Error stack function now (12.2) includes backtrace information!

The DBMS_UTILITY has long (since 10.2) offered three functions that are very handy when either tracing execution or logging errors:
  • FORMAT_CALL_STACK - answering the question "How did I get here?"
  • FORMAT_ERROR_STACK - answering the question "What was the error?" (or a stack of errors, depending on the situation)
  • FORMAT_ERROR_BACKTRACE - answering the question "On what line was my error raised?"
Therefore (and prior to 12.2), if you wanted to get the error information + the line number on which the error was raised, you would need to call both of the "*ERROR*" as in:

CREATE OR REPLACE PROCEDURE p3
   AUTHID DEFINER
IS
BEGIN
   p2;
EXCEPTION
   WHEN OTHERS
   THEN
      DBMS_OUTPUT.put_line (DBMS_UTILITY.format_error_stack);
      DBMS_OUTPUT.put_line (DBMS_UTILITY.format_error_backtrace);
      RAISE;
END;

Of course, in the real world, you would not display the text on the screen. You would write them to a log table via an autonomous transaction procedure, as I show in this simple error logging package.

When I run the above procedure on a version of Oracle Database through 12.1, I might see output like this:

ORA-06501: PL/SQL: program error

ORA-06512: at "STEVEN.P1", line 4
ORA-06512: at "STEVEN.PKG", line 6
ORA-06512: at "STEVEN.P2", line 5
ORA-06512: at "STEVEN.P3", line 5

In other words: the error stack shows just the error message, and the backtrace shows just the backtrace.

But as of 12.2, the error stack function has been enhanced to also include backtrace information (more details available in this My Oracle Support note). So the output run on 12.2, 18.1 or higher shows:

ORA-06501: PL/SQL: program error
ORA-06512: at "STEVEN.P1", line 4
ORA-06512: at "STEVEN.PKG", line 6
ORA-06512: at "STEVEN.P2", line 5

ORA-06512: at "STEVEN.P1", line 4
ORA-06512: at "STEVEN.PKG", line 6
ORA-06512: at "STEVEN.P2", line 5
ORA-06512: at "STEVEN.P3", line 5

Nice stuff!

Comments

  1. Hello Steven,

    I have observed this weird behavior on LiveSQL, and, if I remember it correctly, this was the behavior on LiveSQL still before migrating to 12.2.

    Since this is still the only environment that I can access, I sent you a small sample
    for testing this in a different (or "normal") environment.

    Also, unfortunately, the support documents are only accessible for customers who have a paid license for Oracle support :(

    So, it would be great if you could post the content of that support document on this blog,
    ( or, maybe elsewhere on Devgym, as a resource ), for allowing also "the poor" ones to see it.

    Without this post, and even in spite of it, I am still not sure that this new "behavior" is indeed an intended one, and not a bug or side-effect of some other software change.

    I would also underline that the sample presented in the 18c documentation for DBMS_UTILITY.FORMAT_ERROR_BACKTRACE is still the same as in the older versions, and, in light of the change you specified in this post, its presented output might be wrong.

    I am not sure that making such a deliberate change is definitely a right decision, since it might break existing logic of applications that use these functions for their error logging.


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete
    Replies
    1. Iudith,

      Here is the key text from the MOS note (the code examples reflect what I show above). It is an enhancement not a bug or side effect.

      The exception handling behavior of the function DBMS_UTILITY.FORMAT_ERROR_STACK has been changed in 12.2. The PL/SQL error back trace is now enhanced to add an ORA-6512 whenever an exception handler or a PL/SQL unit is left looking for a handler unlike it's behavior in the previous releases. The ORA-6512 are cleared only when their corresponding exception is cleared, thus preserving the back trace on re-raise and for multiple exceptions.

      I will notify the doc team about the need to upgrade the description of the format error stack function (backtrace is not affected).

      I suppose it is possible that this change will affect applications, but it seems like a very small probability. Can you think of "existing logic" that someone might write that would then be broken by this change?

      Delete
  2. Hello Steven,

    Here is an example of what happens when two exceptions are put successively on the stack:

    CREATE OR REPLACE PROCEDURE plch_proc1
    IS
    BEGIN
    RAISE NO_DATA_FOUND; --> initial exception
    END plch_proc1;
    /

    -- Procedure created.


    CREATE OR REPLACE PROCEDURE plch_proc2
    IS
    BEGIN
    plch_proc1;
    EXCEPTION
    WHEN OTHERS
    THEN
    RAISE VALUE_ERROR; --> raise a different exception
    END plch_proc2;
    /

    -- Procedure created.


    CREATE OR REPLACE PROCEDURE plch_proc3
    IS
    BEGIN
    plch_proc2;
    /*RERAISE*/
    EXCEPTION
    WHEN OTHERS
    THEN
    DBMS_OUTPUT.put_line('----- BEFORE RAISE; -----');
    DBMS_OUTPUT.put_line('----- ERROR -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_stack);
    DBMS_OUTPUT.put_line('----- BACKTRACE -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_backtrace);

    RAISE; --> reraise same exception
    END plch_proc3;
    /

    -- Procedure created.


    -- the test
    BEGIN
    plch_proc3;
    EXCEPTION
    WHEN OTHERS
    THEN
    DBMS_OUTPUT.put_line('----- AFTER RAISE; -----');
    DBMS_OUTPUT.put_line('----- ERROR -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_stack);
    DBMS_OUTPUT.put_line('----- BACKTRACE -----');
    DBMS_OUTPUT.put_line(DBMS_UTILITY.format_error_backtrace);
    END;
    /

    ----- BEFORE RAISE; -----
    ----- ERROR -----
    ORA-06502: PL/SQL: numeric or value error
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-01403: no data found
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4

    ----- BACKTRACE -----
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 4

    ----- AFTER RAISE; -----
    ----- ERROR -----
    ORA-06502: PL/SQL: numeric or value error
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 15
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-01403: no data found
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 4

    ----- BACKTRACE -----
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 15
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 8
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC1", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC2", line 4
    ORA-06512: at "SQL_MZQKSCWZIRDTGKWQVBJVOZMTD.PLCH_PROC3", line 4
    ORA-06512: at line 2

    ( will be continued, because if size limitation ... )

    ReplyDelete
  3. ( continued ... )

    From here, it looks like not only the FORMAT_ERROR_STACK was changed by having the ORA-06512 lines added, but the FORMAT_ERROR_BACKTRACE also has some duplicate lines ...

    In my opinion, this output is very unreadable.

    Regardless of any exceptions that were raised, each procedure was called only once.

    However, the FORMAT_ERROR_STACK shows PLCH_PROC2 twice (in each of BEFORE/AFTER RAISE sections), and also PLCH_PROC3 twice in the AFTER RAISE sections.

    The same duplicates also appear in FORMAT_ERROR_BACKTRACE.

    As by my understanding, the meaning of "preserving the back trace on re-raise and for multiple exceptions" in the MOS document was supposed to be that the FORMAT_ERROR_BACKTRACE does not "stop" on the closest RAISE statement when looking backwards, but instead it goes all the way up to the line where the original exception was raised.

    In our case, this would mean that not only PLCH_PROC3 will appear in the backtrace, but also PLCH_PROC2 and PLCH_PROC1, but each of them should still appear once only.

    Or, in case that the same procedure does appears twice because once it is considered a caller of another procedure (like PLCH_PROC2 calling PLCH_PROC1) and a second time because of a RAISE statement that it executes explicitly (like PLCH_PROC2 raising VALUE_ERROR),
    then these two occurrences should better be adjacent in the output.


    Also, the sentence "The PL/SQL error back trace is now enhanced to add an ORA-6512 whenever an exception handler or a PL/SQL unit is left looking for a handler" sounds a little unclear about what exactly will be added to FORMAT_ERROR_STACK.

    The first impression might be that, if we examine both these functions at the same point in the code, then FORMAT_ERROR_STACK will in fact contain all the information in FORMAT_ERROR_BACKTRACE, in addition to the errors themselves.

    And, in the example above, this is indeed so for the AFTER RAISE section, but not for the BEFORE RAISE section, where backtrace does have an additional line for PLCH_PROC3.

    From the information shown above, with all the duplicates, and without "knowing" the code,
    I find it quite difficult to deduct the exact order and place where the exceptions were raised.


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete
    Replies
    1. I agree with Iudith.
      >From the information shown above, with all the duplicates, and without "knowing" the code,
      >I find it quite difficult to deduct the exact order and place where the exceptions were raised.

      The problem is even worse. it seems to me that the ORA-06512 is added in different positions in the backtrace stack (and therefor also in the error stack), depending on whether added by a RAISE in the when others section, or if there was no exception handler.

      Delete
    2. Issues like these get the most attention when our customers submit SRs that include descriptions of how the problem adversely affects their applications. If one of you could do this, and include the examples shown above, that would be fantastic!

      Delete
    3. I plan to do that. But since I know how tedious it is to raise an SR, it will probably be after Kscope18 until I find time to do it.

      Delete
    4. Thanks and....sigh.....ah, to be able to right all the wrongs in the world!

      Delete
  4. Hello All,

    I am very content that Sven does agree with me :)

    Maybe saying that such a change does "adversely affect" an application would mean "
    going too far", because these functions are more targeted to the use of developers,
    rather than to that of application users.

    Steven, as I know you, you always did afford a much heavier importance to the use of an organized and consistent way of handling errors ... surely a much heavier one than I ever did.

    Unfortunately, now I am only a "private customer" ... so I cannot perform such "privileged"
    actions like opening SR's and other similar :(

    Anyway, I guess that this "enhancement" introduced in 12.2 is a result of some other request,
    or maybe some complaint about FORMAT_ERROR_STACK not containing "enough information" ...
    so it would be nice to hear (from inside) where does this change originate from.

    The only thing that I myself would have thought to add would be the "extension" of the
    FORMAT_ERROR_BACKTRACE to continue past the closest RAISE statement,
    and still leaving the FORMAT_ERROR_STACK as it was.


    Thanks a lot & Best Regards,
    Iudith

    ReplyDelete

Post a Comment

Popular posts from this blog

Table Functions, Part 1: Introduction and Exploration

Quick Guide to User-Defined Types in Oracle PL/SQL

Recommendations for unit testing PL/SQL programs