Re: 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 execution and all is fine here. If we use log_min_duration_statement statement is logged obviously after execution, but currently we 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 OidOutputFunctionCall in all cases, right?

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

Any feedback is strongly appreciated. Thank you!

regards, Sergei

2018-06-23 21:54 GMT+02:00 Sergei Kornilov <sk(at)zsrv(dot)org>:

> Hello all
> We already have feature to logging query parameters. If we use
> log_statement = 'all' we write parameters before execution and all is fine
> here. If we use log_min_duration_statement statement is logged obviously
> after execution, but currently we 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.
>

It is good idea - more times I would to see these values

Regards

Pavel

> 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 OidOutputFunctionCall in all cases,
> right?
>
> Another small question is why errdetail_params uses errdetail instead
> errdetail_log? We assume that the user wants to get their own parameters
> back (if he set client_min_messages to LOG)?
>
> Any feedback is strongly appreciated. Thank you!
>
> regards, Sergei

On Sun, Jun 24, 2018 at 1:08 AM, Pavel Stehule <pavel(dot)stehule(at)gmail(dot)com>
wrote:

>
>
> 2018-06-23 21:54 GMT+02:00 Sergei Kornilov <sk(at)zsrv(dot)org>:
>
>> Hello all
>> We already have feature to logging query parameters. If we use
>> log_statement = 'all' we write parameters before execution and all is fine
>> here. If we use log_min_duration_statement statement is logged obviously
>> after execution, but currently we 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.
>>
>
> It is good idea - more times I would to see these values
>
> Regards
>
> Pavel
>
>
>> 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 OidOutputFunctionCall in all cases,
>> right?
>>
>> Another small question is why errdetail_params uses errdetail instead
>> errdetail_log? We assume that the user wants to get their own parameters
>> back (if he set client_min_messages to LOG)?
>>
>> Any feedback is strongly appreciated. Thank you!
>>
>> regards, Sergei
>
>
>
I have reviewed and tested the patch here are my findings about the patch.

Patch applied successfully on master branch
"04269320aed30d3e37c10ae77775954eae234d45". There is no compilation issue
with the patch.

statement_timeout: For this I wrote a simple LibPq program to insert into
table. The results are random, some times it logs the param and some time
does not; with the same program. After digging a bit I found that if you
execute just after starting the server it does not log the param and start
logging after subsequent calls. Here is the log

2018-07-23 14:12:13.530 PKT [29165] ERROR: canceling statement due to
statement timeout

2018-07-23 14:12:13.530 PKT [29165] DETAIL: parameters: $1 = '16777216',
$2 = 'Foobar'

2018-07-23 14:12:13.530 PKT [29165] STATEMENT: INSERT INTO tbl_libpq_test
(id, name) VALUES ($1::integer, $2::varchar)

...

2018-07-23 14:13:38.483 PKT [29169] LOG: shutting down

...

2018-07-23 14:13:38.616 PKT [29901] LOG: database system is ready to
accept connections

2018-07-23 14:13:39.848 PKT [29910] ERROR: canceling statement due to
statement timeout

2018-07-23 14:13:39.848 PKT [29910] STATEMENT: INSERT INTO tbl_libpq_test
(id, name) VALUES ($1::integer, $2::varchar)

lock_timeout: For this I a use the same program to insert into table. I
lock the table in other session and try to execute the program. It does not
log any params at all here is the log.

2018-07-23 14:21:19.165 PKT [30006] ERROR: canceling statement due to lock
timeout at character 13

2018-07-23 14:21:19.165 PKT [30006] STATEMENT: INSERT INTO tbl_libpq_test
(id, name) VALUES ($1::integer, $2::varchar)

--
Ibrar Ahmed

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_timeout ereport in such way?

After shutdown signal we must be in aborted state, so we mustn't call user-defined I/O functions. (quotation from comment to 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

On Mon, Jul 23, 2018 at 3:05 PM, Sergei Kornilov <sk(at)zsrv(dot)org> wrote:

> 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_timeout ereport in
> such way?
>
> After shutdown signal we must be in aborted state, so we mustn't call
> user-defined I/O functions. (quotation from comment to 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 the time 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 same table.

>
> regards, Sergei
>

--
Ibrar Ahmed

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 comment to 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 the time 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 same table.

So, I was right. We can got "canceling statement due to lock timeout at character 13" only in PARSE state. In parse state we 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 canceled by timeout. But here is completely no parameters in PARSE and i did not change BIND in first patch.

regards, Sergei

Sergei Kornilov <sk(at)zsrv(dot)org> writes:
> Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can be 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.

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(at)sss(dot)pgh(dot)pa(dot)us>:
> Sergei Kornilov <sk(at)zsrv(dot)org> writes:
>>  Please test with logging command tag %i in log_line_prefix. Extended protocol has three different messages, each can be 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 parameters back (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