Обсуждение: Log query parameters for terminated execute

Hello all
We already have feature to logging query parameters. If we use log_statement = 'all' we write parameters before
executionand all is fine here. If we use log_min_duration_statement statement is logged obviously after execution, but
currentlywe have no parameters if query was terminated by statement_timeout, lock_timeout or by pg_terminate_backend.
 

I would like have parameters in logs at least for such three cases.

Simple way achieve this is just add errdetail_params to such ereport as in attached patch.
Another way is add something like printing global variable debug_query_string in send_message_to_server_log
(src/backend/utils/error/elog.c).But i have no good idea how print ParamListInfo correctly. We can not use
OidOutputFunctionCallin all cases, right?
 

Another small question is why errdetail_params uses errdetail instead errdetail_log? We assume that the user wants to
gettheir own parameters back (if he set client_min_messages to LOG)?
 

Any feedback is strongly appreciated. Thank you!

regards, Sergei

Hello
Thank you for review!
Well, i can miss some cases. I'm not sure about overall design of this patch. Is acceptable add errdetail_params to
statement_timeoutereport in such way?
 

After shutdown signal we must be in aborted state, so we mustn't call user-defined I/O functions. (quotation from
commentto errdetail_params in src/backend/tcop/postgres.c ). It seems i can not fix it with current design.
 

> ERROR:  canceling statement due to lock timeout at character 13
Hm, "at character"? How can we get this message? I found only "canceling statement due to lock timeout" (without "at
character")ereport in src/backend/tcop/postgres.c
 
Maybe try .. catch in parse state, not in execute?

regards, Sergei

The following review has been posted through the commitfest application:
make installcheck-world:  not tested
Implements feature:       not tested
Spec compliant:           not tested
Documentation:            not tested

Review submitted

The new status of this patch is: Waiting on Author

Hello!

>> After shutdown signal we must be in aborted state, so we mustn't call user-defined I/O functions. (quotation from
commentto errdetail_params in src/backend/tcop/postgres.c ). It seems i can not fix it with current design.
 
>
> No its not about calling the function after abort/shutdown. Just start the server and try to run the program, most of
thetime you will not get params.
 
>
>>> ERROR:  canceling statement due to lock timeout at character 13
>> Hm, "at character"? How can we get this message? I found only "canceling statement due to lock timeout" (without "at
character")ereport in src/backend/tcop/postgres.c
 
>> Maybe try .. catch in parse state, not in execute?
>
> Its really easy to reproduce, just lock the table form another session and run a "c" program to insert row in the
sametable.
 

So, I was right. We can got "canceling statement due to lock timeout at character 13" only in PARSE state. In parse
statewe have completely no parameters, we receive parameters only later in BIND message. I can not log data from
future.
And initially i did change only EXECUTE. Attached patch with similar change in BIND message, if this design is
acceptable.

Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can be
canceledby timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch.
 

regards, Sergei

Sergei Kornilov <sk@zsrv.org> writes:
> Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can
becanceled by timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch. 

This patch scares me to death.  It risks calling user-defined I/O
functions in all sorts of weird places, particularly outside transactions,
or in already-failed transactions, or with no ActiveSnapshot.

Separately from that concern: it appears to result in a substantial
degradation of existing functionality in the places where you did
s/errdetail/errdetail_log/.  What was the reason for that?

            regards, tom lane

Hello

23.07.2018, 17:08, "Tom Lane" <tgl@sss.pgh.pa.us>:
> Sergei Kornilov <sk@zsrv.org> writes:
>>  Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each
canbe canceled by timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch.
 
>
> This patch scares me to death. It risks calling user-defined I/O
> functions in all sorts of weird places, particularly outside transactions,
> or in already-failed transactions, or with no ActiveSnapshot.
This is reason why i start thread with question how do it right way
As i wrote in beginning:
> i have no good idea how print ParamListInfo correctly. We can not use OidOutputFunctionCall in all cases, right?
Attached patch is just simple enough to illustrate one possible way.
I can further work with proper design, but i need idea how it should look.

> Separately from that concern: it appears to result in a substantial
> degradation of existing functionality in the places where you did
> s/errdetail/errdetail_log/. What was the reason for that?
This is my second question at thread beginning. Why used errdetail? We assume that the user wants to get their own
parametersback (if he set client_min_messages to LOG)?
 

regards, Sergei

Changed the status as per last email of Tom Lane.

Hello

> Changed the status as per last email of Tom Lane.
I have no idea what can i change.
I received no feedback how i can print parameters in other cases. Should i mark CF as rejected?

regards, Sergei