Re: log bind parameter values on error

Hello Anders and Peter,

Thanks for your messages.
Please see the new patch version attached.

> Have you analyzed how invasive it'd be to delay that till we actually
> can safely start a [sub]transaction to do that logging? Probably too
> expensive, but it seems like something that ought to be analyzed.

The fundamental problem here is that the output functions for the types
of the values to be logged may be present only in the transaction
that has just been aborted.

Also I don't like the idea of doing complex operations in the error handler,
as it increases the chances of cascading errors.

I thought of pre-calculating types' output functions instead of their
results,
but that would work for certain built-in types only.

>> + <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
>> + <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
>> + <indexterm>
>> + <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
>> + </indexterm>
>> + </term>
>> + <listitem>
>> + <para>
>> + Controls whether the statement is logged with bind parameter values.
>> + It adds some overhead, as postgres will cache textual
>> + representations of parameter values in memory for all statements,
>> + even if they eventually do not get logged. The default is
>> + <literal>off</literal>. Only superusers can change this setting.
>> + </para>
>> + </listitem>
>> + </varlistentry>
> This needs a bit of language polishing.

I would appreciate if you had any suggestions, as my English isn't great.

>> @@ -31,6 +31,8 @@
>> * set of parameter values. If dynamic parameter hooks are present, we
>> * intentionally do not copy them into the result. Rather, we forcibly
>> * instantiate all available parameter values and copy the datum values.
>> + *
>> + * We don't copy textual representations here.
>> */
> That probably needs to be expanded on. Including a comment about what
> guarantees that there are no memory lifetime issues.

What kind of memory lifetime issues do you mean?
We're not copying textual representations, so the worst can happen
is they don't get logged when appropriate. Luckily, we never use this
function when copying to a portal we use for logging, I added this to
the comment. Do you think it's any better?

>
> So the parameters we log here haven't actually gone through the output
> function? Isn't that an issue? I mean that'll cause the contents to
> differ from the non-error case, no? And differs from the binary protocol
> case?
I don't think it's much of a problem. Text input and output functions are
meant to match, but the CREATE TYPE spec isn't too specific about what
it means.
Of course it does not mean that typoutput(typinput(foo)) is always
exactly foo.
However, I really hope that at least typinput(typoutput(foo)) = foo,
where "=" is the correspondent operator registered in postgres.

If a cheeky client passes '007' as a numeric value I don't mind it being
sometimes logged as '007' and sometimes as '7', depending on the settings.
It anyway denotes the same number, and we'll know what to pass to
reproduce the problem.
For binary protocol it'll be '7' as well, as it'll undergo the typrecv
and then typoutput procedures.

>> else
>> {
>> + /*
>> + * We do it for non-xact commands only, as an xact command
>> + * 1) shouldn't have any parameters to log;
>> + * 2) may have the portal dropped early.
>> + */
>> + Assert(current_top_portal == NULL);
>> + current_top_portal = portal;
>> + portalParams = NULL;
>> +
> "it"? ISTM the comment doesn't really stand on its own?
Thanks, I fixed the comment and some code around it.

>> +/*
>> + * get_portal_bind_parameters
>> + * Get the string containing parameters data, is used for logging.
>> + *
>> + * Can return NULL if there are no parameters in the portal
>> + * or the portal is not valid, or the text representations of the parameters are
>> + * not available. If returning a non-NULL value, it allocates memory
>> + * for the returned string in the current context, and it's the caller's
>> + * responsibility to pfree() it if needed.
>> + */
>> +char *
>> +get_portal_bind_parameters(ParamListInfo params)
>> +{
>> + StringInfoData param_str;
>> +
>> + /* No parameters to format */
>> + if (!params || params->numParams == 0)
>> + return NULL;
>> +
>> + elog(WARNING, "params->hasTextValues=%d, IsAbortedTransactionBlockState()=%d",
>> + params->hasTextValues && IsAbortedTransactionBlockState());
> Err, huh?
This was some debugging, I threw it away now.

Best,
 Alex