Re: log bind parameter values on error

Hi,

tiny scroll-through review.

On 2019-01-28 00:15:51 +0000, Alexey Bashtanov wrote:
> diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
> index b6f5822..997e6e8 100644
> --- a/doc/src/sgml/config.sgml
> +++ b/doc/src/sgml/config.sgml
> @@ -6274,6 +6274,23 @@ log_line_prefix = '%m [%p] %q%u(at)%d/%a '
> </listitem>
> </varlistentry>
>
> + <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.

> @@ -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.

> - /* Free result of encoding conversion, if any */
> - if (pstring && pstring != pbuf.data)
> - pfree(pstring);
> + if (pstring)
> + {
> + if (need_text_values)
> + {
> + if (pstring == pbuf.data)
> + {
> + /*
> + * Copy textual representation to portal context.
> + */
> + params->params[paramno].textValue =
> + pstrdup(pstring);
> + }
> + else
> + {
> + /* Reuse the result of encoding conversion for it */
> + params->params[paramno].textValue = pstring;
> + }
> + }
> + else
> + {
> + /* Free result of encoding conversion */
> + if (pstring != pbuf.data)
> + pfree(pstring);
> + }
> + }

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?
> 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?

> +/*
> + * 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?

Greetings,

Andres Freund