FAQ

[PostgreSQL-Hackers] SQLERRD and dump of variables

Joel Jacobson
Apr 25, 2011 at 5:53 pm
I have two separate ideas, but they are kind of connected,


(1) Make the detailed error message available in SPs and not only the short
error message (SQLERRM)

When debugging errors in stored procedures, I often add an exception handler
and print the values of declared variables to the log.

Unfortunately, the original detailed error message is then lost, since the
SQLERRM only contains the short message.

The detailed error message contains valuable information and it would be
good if it could be made accessible within the exception handler code.

Example of detailed error message: "Process 28420 waits for ShareLock on
transaction 1421227628; blocked by process 20718."
The SQLERRM in this case only contains "deadlock detected".

If you would add a "EXCEPTION WHEN deadlock_detected" to catch this error,
it would be nice if this detailed error message could still be written to
the log, in addition to your own customized message, containing the values
of the declared variables you need to view.

The detailed error message is available in edata->detail, while SQLERRM is
in edata->message.

Perhaps we could name it SQLERRD?


(2) New log field showing current values of all declared variables

Instead of using RAISE DEBUG or customizing error messages using exception
handlers, such as,
EXCEPTION WHEN deadlock_detected
RAISE '% var_foo % var_bar %', SQLERRM, var_foo, var_bar USING ERRCODE =
'deadlock_detected';

It would be very convenient if you could enable a log setting to write all
declared variables current values directly to the CSV log, for all errors,
to avoid the need to manually edit stored procedures to write variable
values to the log, which also means you have to wait again for the same
error to occur again, which might never happen if you have unlucky.

Instead of a new CSV log field, perhaps the setting when switch on could
append the info to the already existing "hint" field?
Example: hint: "var_foo=12345 var_bar=67890"

This would be of great help to faster track down errors.

Thoughts?


Best regards,

Joel Jacobson
reply

Search Discussions

3 responses

  • Pavel Stehule at Apr 25, 2011 at 8:10 pm
    Hello

    2011/4/25 Joel Jacobson <joel@gluefinance.com>:
    I have two separate ideas, but they are kind of connected,

    (1) Make the detailed error message available in SPs and not only the short
    error message (SQLERRM)
    When debugging errors in stored procedures, I often add an exception handler
    and print the values of declared variables to the log.
    Unfortunately, the original detailed error message is then lost, since the
    SQLERRM only contains the short message.
    The detailed error message contains valuable information and it would be
    good if it could be made accessible within the exception handler code.
    Example of detailed error message: "Process 28420 waits for ShareLock on
    transaction 1421227628; blocked by process 20718."
    The SQLERRM in this case only contains "deadlock detected".
    If you would add a "EXCEPTION WHEN deadlock_detected" to catch this error,
    it would be nice if this detailed error message could still be written to
    the log, in addition to your own customized message, containing the values
    of the declared variables you need to view.
    The detailed error message is available in edata->detail, while SQLERRM is
    in edata->message.
    Perhaps we could name it SQLERRD?
    A magic variables like SQLERRM or SQLSTATE are little bit expensive -
    and isn't important if this variables are used or not.

    In this moment I am thinking so best methotd is enhancing GET
    DIAGNOSTICS statement - you can access to more informations than
    detail - hint, line,
    (2) New log field showing current values of all declared variables
    Instead of using RAISE DEBUG or customizing error messages using exception
    handlers, such as,
    EXCEPTION WHEN deadlock_detected
    RAISE '% var_foo % var_bar %', SQLERRM, var_foo, var_bar USING ERRCODE =
    'deadlock_detected';
    It would be very convenient if you could enable a log setting to write all
    declared variables current values directly to the CSV log, for all errors,
    to avoid the need to manually edit stored procedures to write variable
    values to the log, which also means you have to wait again for the same
    error to occur again, which might never happen if you have unlucky.
    Instead of a new CSV log field, perhaps the setting when switch on could
    append the info to the already existing "hint" field?
    Example: hint: "var_foo=12345 var_bar=67890"
    This would be of great help to faster track down errors.
    I realised similar tool in PSM0

    https://github.com/okbob/plpsm0

    see on executor.c

    It is little bit more harder then is looking - inside unrollbacked
    exception you can't access to system directories, and you can't to
    search a out functions. I found a workaround, but it is little bit
    strange. I am for this feature - just add note - inside executor is
    zero infrastructure for this.

    Regards

    Pavel Stehule

    Thoughts?

    Best regards,
    Joel Jacobson
  • Noah Misch at Apr 28, 2011 at 9:54 pm
    Joel,
    On Mon, Apr 25, 2011 at 07:45:13PM +0200, Joel Jacobson wrote:
    (1) Make the detailed error message available in SPs and not only the short
    error message (SQLERRM)
    Agreed. Really, all the information available via PQresultErrorField should
    also be exposed in PL error handling facilities. Just exposing DETAIL as a
    start seems fine, but I suggest designing with that broader goal in mind.
    When debugging errors in stored procedures, I often add an exception handler
    and print the values of declared variables to the log.

    Unfortunately, the original detailed error message is then lost, since the
    SQLERRM only contains the short message.
    (2) New log field showing current values of all declared variables

    Instead of using RAISE DEBUG or customizing error messages using exception
    handlers, such as,
    EXCEPTION WHEN deadlock_detected
    RAISE '% var_foo % var_bar %', SQLERRM, var_foo, var_bar USING ERRCODE =
    'deadlock_detected';
    In the mean time, have you considered doing something like this instead?

    EXCEPTION WHEN deadlock_detected
    RAISE NOTICE '% var_foo % var_bar', var_foo, var_bar;
    RAISE;

    The information isn't as nicely aggregated, but you don't lose any details.
    It would be very convenient if you could enable a log setting to write all
    declared variables current values directly to the CSV log, for all errors,
    to avoid the need to manually edit stored procedures to write variable
    values to the log, which also means you have to wait again for the same
    error to occur again, which might never happen if you have unlucky.
    If you go for a distinct CSV field, I think it should have a tightly-specified,
    machine-friendly format that all PLs populating that field must observe. If the
    format is going to be ad-hoc, I'd lean toward storing it as extra material in a
    CONTEXT field. Machine-friendly formatting wouldn't be a priority for me
    personally, but perhaps you or others would value it.

    Also keep in mind that you may have several PL/pgSQL functions in your call
    stack, and you'll want to capture the local variables at each level.
    Instead of a new CSV log field, perhaps the setting when switch on could
    append the info to the already existing "hint" field?
    Example: hint: "var_foo=12345 var_bar=67890"
    It would belong in CONTEXT or possibly DETAIL, not HINT. HINT is for
    generally-applicable suggestions about the parent message, not additional facts
    needed to fully characterize what happened.
    This would be of great help to faster track down errors.
    It does sound useful. I'd envision this as plpgsql_exec_error_callback checking
    a GUC and, when set, emitting the local variable values. Features like this do
    usually live in a debugger facility, not in the basic error reporting
    infrastructure of the language. Still, if it were in core, I'd surely use it.

    Consider the potential need to avoid logging very-large variable values. The
    GUC could perhaps be a size limit (0 disables the feature entirely), not a
    boolean.

    Thanks,
    nm
  • Joel Jacobson at Apr 29, 2011 at 8:28 am
    2011/4/28 Noah Misch <noah@leadboat.com>
    In the mean time, have you considered doing something like this instead?

    EXCEPTION WHEN deadlock_detected
    RAISE NOTICE '% var_foo % var_bar', var_foo, var_bar;
    RAISE;

    The information isn't as nicely aggregated, but you don't lose any details.
    Thank you, very useful! This solved my problem. I wrote a comment at
    http://www.postgresql.org/docs/9.0/interactive/plpgsql-errors-and-messages.html
    .


    Also keep in mind that you may have several PL/pgSQL functions in your call
    stack, and you'll want to capture the local variables at each level.
    Yes, the format of the string written to the log must support multi-level
    data strucutres, perhaps JSON would be a good choice.


    Consider the potential need to avoid logging very-large variable values.
    The
    GUC could perhaps be a size limit (0 disables the feature entirely), not a
    boolean.
    Yes, for very large values, it's okay if they are truncated or perhaps
    truncated+a simple MD5-hash of the value, so you can check if it is equal to
    the excepted value. You are usually not interested in these anyway, since
    what you are looking for are probably things like ID-numbers, usernames,
    etc.

Related Discussions

Discussion Navigation
viewthread | post