Re: log bind parameter values on error

On 05/04/2019 12:23, Peter Eisentraut wrote:
> On 2019-03-29 15:55, Alexey Bashtanov wrote:
>>> ERROR: value "62812" is out of range for type smallint
>>> STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;
>>>
>>> (In this case the error message contains the parameter value, so it's
>>> not a very practical case, but it should work, it seems.)
>> I guess this error occurred /while/ binding, so the parameters probably
>> weren't yet all bound by the time of error reporting.
>> That's why the error message came without parameters.
> I see. But I think that could be fixed. Change exec_bind_message() to
> loop over the parameters twice: once to save them away, once to actually
> process them. I think the case of a faulty input value is probably very
> common, so it would be confusing if that didn't work.
I understand this may sound lazy of me, however let me take this risk
and try to explain why I think logging them here in the same fashion
would be inconsistent.

The original feature is intended to log textual representations of
the bind parameter values, whereas the problem suggested to be solved
together with it is verbose logging of the part of the bind message that
failed to get converted to a Datum.

These are equivalent only under the following conditions:
1) the rest of the message was correctly formatted, so we can extract
something for each of the parameter values
2) the values have been passed in text mode
(all of them, not only the one failed to process)
3) the values have been passed in the server encoding

I think it would be a bit of inconsistent to log the parts of the message
only when we are lucky to satisfy the 3 conditions above.

If we are to log bind parameters message parsing and processing problems
more verbosely, what do you think of rather wrapping calls to
OidInputFunctionCall, OidReceiveFunctionCall and pg_client_to_server
into PG_TRY blocks and logging their arguments individually?

In case it doesn't work for any reason, I have an alternative idea on
how to log half-processed parameters.
Instead of hasTextValues store the number of parameters having
their textual representations successfully saved.
This way we will be able, in case of text mode,
save the original value and increment the counter
before the call to OidInputFunctionCall. When logging and not having values
for some parameters, we can print an ellipsis in the log to indicate there's
some more of them missing.

> I think this patch needs some tests. Manually testing it is cumbersome,
> and as we are seeing now, it is not quite clear which cases it is
> supposed to cover. There are also additional cases for binary
> parameters, and there are additions to the CSV output format. We need
> tests for all that so the behavior explains itself and doesn't have to
> be rediscovered every time someone wants to look at this again.
>

I have added a section into src/test/examples/testlibpq3.c,
please see attached.

As far as I could see these tests never run on "make check" or "make
installcheck",
hence the README change. Please correct me if I'm wrong.

I also failed to find an automatic way to test what actually gets logged
to the server log, at least not in the installcheck case.
I would appreciate if you had any suggestions about it.

Best regards,
  Alex