Re: Log query parameters for terminated execute

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