Обсуждение: SQLERRD and dump of variables

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
>

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_detectedRAISE 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