Emit parameter values during query bind/execute errors

This makes such log entries more useful, since the cause of the error
can be dependent on the parameter values.

Author: Alexey Bashtanov, Álvaro Herrera
Discussion: https://postgr.es/m/0146a67b-a22a-0519-9082-bc29756b93a2@imap.cc
Reviewed-by: Peter Eisentraut, Andres Freund, Tom Lane

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 53ac14490a1932a4b8d42d263e2ea950b448878c..5d1c90282f949e229f9318a90f5a3a19e72b938b 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6595,6 +6595,29 @@ log_line_prefix = '%m [%p] %q%u@%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 bind parameters are logged when a statement is logged
+        as a result of <xref linkend="guc-log-min-error-statement"/>.
+        It adds some overhead, as postgres will compute and store textual
+        representations of parameter values in memory for all statements,
+        even if they eventually do not get logged.
+        This setting has no effect on statements logged due to
+        <xref linkend="guc-log-min-duration-statement"/> or
+        <xref linkend="guc-log-statement"/> settings, as they are always logged
+        with parameters.
+        The default is <literal>off</literal>.
+        Only superusers can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-log-statement" xreflabel="log_statement">
       <term><varname>log_statement</varname> (<type>enum</type>)
       <indexterm>

diff --git a/src/backend/nodes/params.c b/src/backend/nodes/params.c
index cf4387e40f0034a1b6d3355be43be4836b4a5838..a9a7aca5334ed4785215aac6290ea367c3ddfe9b 100644 (file)
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -15,11 +15,14 @@
 
 #include "postgres.h"
 
+#include "access/xact.h"
+#include "mb/stringinfo_mb.h"
 #include "nodes/bitmapset.h"
 #include "nodes/params.h"
 #include "storage/shmem.h"
 #include "utils/datum.h"
 #include "utils/lsyscache.h"
+#include "utils/memutils.h"
 
 
 /*
@@ -44,6 +47,7 @@ makeParamList(int numParams)
        retval->paramCompileArg = NULL;
        retval->parserSetup = NULL;
        retval->parserSetupArg = NULL;
+       retval->paramValuesStr = NULL;
        retval->numParams = numParams;
 
        return retval;
@@ -58,6 +62,8 @@ makeParamList(int numParams)
  * 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.
+ *
+ * paramValuesStr is not copied, either.
  */
 ParamListInfo
 copyParamList(ParamListInfo from)
@@ -158,6 +164,8 @@ EstimateParamListSpace(ParamListInfo paramLI)
  * RestoreParamList can be used to recreate a ParamListInfo based on the
  * serialized representation; this will be a static, self-contained copy
  * just as copyParamList would create.
+ *
+ * paramValuesStr is not included.
  */
 void
 SerializeParamList(ParamListInfo paramLI, char **start_address)
@@ -251,3 +259,105 @@ RestoreParamList(char **start_address)
 
        return paramLI;
 }
+
+/*
+ * BuildParamLogString
+ *             Return a string that represent the parameter list, for logging.
+ *
+ * If caller already knows textual representations for some parameters, it can
+ * pass an array of exactly params->numParams values as knownTextValues, which
+ * can contain NULLs for any unknown individual values.  NULL can be given if
+ * no parameters are known.
+ *
+ * If maxlen is not zero, that's the maximum number of characters of the
+ * input string printed; an ellipsis is added if more characters exist.
+ * (Added quotes are not considered.)
+ */
+char *
+BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen)
+{
+       MemoryContext tmpCxt,
+                               oldCxt;
+       StringInfoData buf;
+
+       /*
+        * NB: think not of returning params->paramValuesStr!  It may have been
+        * generated with a different maxlen, and so unsuitable.
+        */
+
+       /*
+        * No work if the param fetch hook is in use.  Also, it's not possible to
+        * do this in an aborted transaction.  (It might be possible to improve on
+        * this last point when some knownTextValues exist, but it seems tricky.)
+        */
+       if (params->paramFetch != NULL ||
+               IsAbortedTransactionBlockState())
+               return NULL;
+
+       /* Initialize the output stringinfo, in caller's memory context */
+       initStringInfo(&buf);
+
+       /* Use a temporary context to call output functions, just in case */
+       tmpCxt = AllocSetContextCreate(CurrentMemoryContext,
+                                                                  "BuildParamLogString",
+                                                                  ALLOCSET_DEFAULT_SIZES);
+       oldCxt = MemoryContextSwitchTo(tmpCxt);
+
+       for (int paramno = 0; paramno < params->numParams; paramno++)
+       {
+               ParamExternData *param = &params->params[paramno];
+
+               appendStringInfo(&buf,
+                                                "%s$%d = ",
+                                                paramno > 0 ? ", " : "",
+                                                paramno + 1);
+
+               if (param->isnull || !OidIsValid(param->ptype))
+                       appendStringInfoString(&buf, "NULL");
+               else
+               {
+                       if (knownTextValues != NULL && knownTextValues[paramno] != NULL)
+                               appendStringInfoStringQuoted(&buf, knownTextValues[paramno],
+                                                                                        maxlen);
+                       else
+                       {
+                               Oid                     typoutput;
+                               bool            typisvarlena;
+                               char       *pstring;
+
+                               getTypeOutputInfo(param->ptype, &typoutput, &typisvarlena);
+                               pstring = OidOutputFunctionCall(typoutput, param->value);
+                               appendStringInfoStringQuoted(&buf, pstring, maxlen);
+                       }
+               }
+       }
+
+       MemoryContextSwitchTo(oldCxt);
+       MemoryContextDelete(tmpCxt);
+
+       return buf.data;
+}
+
+/*
+ * ParamsErrorCallback - callback for printing parameters in error context
+ *
+ * Note that this is a no-op unless BuildParamLogString has been called
+ * beforehand.
+ */
+void
+ParamsErrorCallback(void *arg)
+{
+       ParamsErrorCbData *data = (ParamsErrorCbData *) arg;
+
+       if (data == NULL ||
+               data->params == NULL ||
+               data->params->paramValuesStr == NULL)
+               return;
+
+       if (data->portalName && data->portalName[0] != '\0')
+               errcontext("extended query \"%s\" with parameters: %s",
+                                  data->portalName, data->params->paramValuesStr);
+       else
+               errcontext("extended query with parameters: %s",
+                                  data->params->paramValuesStr);
+}

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 512209a38c40bb2a90711e5fdaa6eadb86466eae..0b7bc1fd0307988109c777d186e7e08ab854cff2 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1614,6 +1614,8 @@ exec_bind_message(StringInfo input_message)
        bool            save_log_statement_stats = log_statement_stats;
        bool            snapshot_set = false;
        char            msec_str[32];
+       ParamsErrorCbData params_data;
+       ErrorContextCallback params_errcxt;
 
        /* Get the fixed part of the message */
        portal_name = pq_getmsgstring(input_message);
@@ -1753,6 +1755,8 @@ exec_bind_message(StringInfo input_message)
         */
        if (numParams > 0)
        {
+               char      **knownTextValues = NULL;     /* allocate on first use */
+
                params = makeParamList(numParams);
 
                for (int paramno = 0; paramno < numParams; paramno++)
@@ -1820,9 +1824,32 @@ exec_bind_message(StringInfo input_message)
 
                                pval = OidInputFunctionCall(typinput, pstring, typioparam, -1);
 
-                               /* Free result of encoding conversion, if any */
-                               if (pstring && pstring != pbuf.data)
-                                       pfree(pstring);
+                               /*
+                                * Free result of encoding conversion, if any, and save a copy
+                                * for later when logging parameters.
+                                */
+                               if (pstring)
+                               {
+                                       if (log_parameters_on_error)
+                                       {
+                                               MemoryContext   oldcxt;
+
+                                               oldcxt = MemoryContextSwitchTo(MessageContext);
+                                               if (knownTextValues == NULL)
+                                                       knownTextValues =
+                                                               palloc0(numParams * sizeof(char *));
+                                               /*
+                                                * Note: must copy at least two more full characters
+                                                * than BuildParamLogString wants to see; otherwise it
+                                                * might fail to include the ellipsis.
+                                                */
+                                               knownTextValues[paramno] =
+                                                       pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+                                               MemoryContextSwitchTo(oldcxt);
+                                       }
+                                       if (pstring != pbuf.data)
+                                               pfree(pstring);
+                               }
                        }
                        else if (pformat == 1)  /* binary mode */
                        {
@@ -1872,6 +1899,15 @@ exec_bind_message(StringInfo input_message)
                        params->params[paramno].pflags = PARAM_FLAG_CONST;
                        params->params[paramno].ptype = ptype;
                }
+
+               /*
+                * Once all parameters have been received, prepare for printing them in
+                * errors, if configured to do so.  (This is saved in the portal, so
+                * that they'll appear when the query is executed later.)
+                */
+               if (log_parameters_on_error)
+                       params->paramValuesStr =
+                               BuildParamLogString(params, knownTextValues, 64);
        }
        else
                params = NULL;
@@ -1879,6 +1915,14 @@ exec_bind_message(StringInfo input_message)
        /* Done storing stuff in portal's context */
        MemoryContextSwitchTo(oldContext);
 
+       /* Set the error callback so that parameters are logged, as needed  */
+       params_data.portalName = portal->name;
+       params_data.params = params;
+       params_errcxt.previous = error_context_stack;
+       params_errcxt.callback = ParamsErrorCallback;
+       params_errcxt.arg = (void *) &params_data;
+       error_context_stack = &params_errcxt;
+
        /* Get the result format codes */
        numRFormats = pq_getmsgint(input_message, 2);
        if (numRFormats > 0)
@@ -1924,6 +1968,12 @@ exec_bind_message(StringInfo input_message)
         */
        PortalSetResultFormat(portal, numRFormats, rformats);
 
+       /*
+        * Done binding; remove the parameters error callback.  Entries emitted
+        * later determine independently whether to log the parameters or not.
+        */
+       error_context_stack = error_context_stack->previous;
+
        /*
         * Send BindComplete.
         */
@@ -1980,6 +2030,8 @@ exec_execute_message(const char *portal_name, long max_rows)
        bool            execute_is_fetch;
        bool            was_logged = false;
        char            msec_str[32];
+       ParamsErrorCbData params_data;
+       ErrorContextCallback params_errcxt;
 
        /* Adjust destination to tell printtup.c what to do */
        dest = whereToSendOutput;
@@ -2104,8 +2156,16 @@ exec_execute_message(const char *portal_name, long max_rows)
        CHECK_FOR_INTERRUPTS();
 
        /*
-        * Okay to run the portal.
+        * Okay to run the portal.  Set the error callback so that parameters are
+        * logged.  The parameters must have been saved during the bind phase.
         */
+       params_data.portalName = portal->name;
+       params_data.params = portalParams;
+       params_errcxt.previous = error_context_stack;
+       params_errcxt.callback = ParamsErrorCallback;
+       params_errcxt.arg = (void *) &params_data;
+       error_context_stack = &params_errcxt;
+
        if (max_rows <= 0)
                max_rows = FETCH_ALL;
 
@@ -2119,6 +2179,9 @@ exec_execute_message(const char *portal_name, long max_rows)
 
        receiver->rDestroy(receiver);
 
+       /* Done executing; remove the params error callback */
+       error_context_stack = error_context_stack->previous;
+
        if (completed)
        {
                if (is_xact_command)
@@ -2329,51 +2392,13 @@ errdetail_execute(List *raw_parsetree_list)
 static int
 errdetail_params(ParamListInfo params)
 {
-       /* We mustn't call user-defined I/O functions when in an aborted xact */
-       if (params && params->numParams > 0 && !IsAbortedTransactionBlockState())
+       if (params && params->numParams > 0)
        {
-               StringInfoData param_str;
-               MemoryContext oldcontext;
+               char   *str;
 
-               /* This code doesn't support dynamic param lists */
-               Assert(params->paramFetch == NULL);
-
-               /* Make sure any trash is generated in MessageContext */
-               oldcontext = MemoryContextSwitchTo(MessageContext);
-
-               initStringInfo(&param_str);
-
-               for (int paramno = 0; paramno < params->numParams; paramno++)
-               {
-                       ParamExternData *prm = &params->params[paramno];
-                       Oid                     typoutput;
-                       bool            typisvarlena;
-                       char       *pstring;
-
-                       appendStringInfo(&param_str, "%s$%d = ",
-                                                        paramno > 0 ? ", " : "",
-                                                        paramno + 1);
-
-                       if (prm->isnull || !OidIsValid(prm->ptype))
-                       {
-                               appendStringInfoString(&param_str, "NULL");
-                               continue;
-                       }
-
-                       getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena);
-
-                       pstring = OidOutputFunctionCall(typoutput, prm->value);
-
-                       appendStringInfoStringQuoted(&param_str, pstring, 0);
-
-                       pfree(pstring);
-               }
-
-               errdetail("parameters: %s", param_str.data);
-
-               pfree(param_str.data);
-
-               MemoryContextSwitchTo(oldcontext);
+               str = BuildParamLogString(params, NULL, 0);
+               if (str && str[0] != '\0')
+                       errdetail("parameters: %s", str);
        }
 
        return 0;

diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index ba74bf9f7dc25ccd2a929a5c7917f549f35b4c46..8d951ce404cbb2183bb886c9ad3c44fb92f88e58 100644 (file)
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -486,6 +486,7 @@ extern const struct config_enum_entry dynamic_shared_memory_options[];
  * GUC option variables that are exported from this module
  */
 bool           log_duration = false;
+bool           log_parameters_on_error = false;
 bool           Debug_print_plan = false;
 bool           Debug_print_parse = false;
 bool           Debug_print_rewritten = false;
@@ -1300,6 +1301,15 @@ static struct config_bool ConfigureNamesBool[] =
                false,
                NULL, NULL, NULL
        },
+       {
+               {"log_parameters_on_error", PGC_SUSET, LOGGING_WHAT,
+                       gettext_noop("Logs bind parameters of the logged statements where possible."),
+                       NULL
+               },
+               &log_parameters_on_error,
+               false,
+               NULL, NULL, NULL
+       },
        {
                {"debug_print_parse", PGC_USERSET, LOGGING_WHAT,
                        gettext_noop("Logs each query's parse tree."),

diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 9541879c1facb958f3ba01c62c847d308a8ac8d6..087190ce6383fc349423acd4f039d02c3084e646 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -544,6 +544,7 @@
                                        # e.g. '<%u%%%d> '
 #log_lock_waits = off                  # log lock waits >= deadlock_timeout
 #log_statement = 'none'                        # none, ddl, mod, all
+#log_parameters_on_error = off # on error log statements with bind parameters
 #log_replication_commands = off
 #log_temp_files = -1                   # log temporary files equal or larger
                                        # than the specified size in kilobytes;

diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 18458690168cb5a3d940d3d6077112724369b985..b91f491b40f08b189f549ec5a5a51292a8435d96 100644 (file)
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -270,6 +270,50 @@ COMMIT;
 }
        });
 
+# Verify server logging of parameters.
+$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
+$node->reload;
+pgbench(
+               '-n -t1 -c1 -M prepared',
+               2,
+               [],
+               [
+               qr{ERROR:  division by zero},
+               qr{CONTEXT:  extended query with parameters: \$1 = '1', \$2 = NULL}
+               ],
+               'server parameter logging',
+               {
+                       '001_param_1' => q{select '1' as one \gset
+SELECT 1 / (random() / 2)::int, :one::int, :two::int;
+}
+       });
+
+$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
+$node->reload;
+pgbench(
+               '-n -t1 -c1 -M prepared',
+               2,
+               [],
+               [
+               qr{ERROR:  invalid input syntax for type json},
+               qr[CONTEXT:  JSON data, line 1: \{ invalid\.\.\.
+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que ...'$]m
+               ],
+               'server parameter logging',
+               {
+                       '001_param_2' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+       });
+my $log = TestLib::slurp_file($node->logfile);
+like($log, qr[DETAIL:  parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?'''],
+        "parameter report does not truncate");
+$log = undef;
+
+$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
+$node->reload;
+
 # test expressions
 # command 1..3 and 23 depend on random seed which is used to call srandom.
 pgbench(

diff --git a/src/include/nodes/params.h b/src/include/nodes/params.h
index fd9046619cccd0ea6df29ed095abe92393c4a26f..c6310b892f2107437c92249b9938029d309ddc4f 100644 (file)
--- a/src/include/nodes/params.h
+++ b/src/include/nodes/params.h
@@ -115,6 +115,7 @@ typedef struct ParamListInfoData
        void       *paramCompileArg;
        ParserSetupHook parserSetup;    /* parser setup hook */
        void       *parserSetupArg;
+       char       *paramValuesStr;             /* params as a single string for errors */
        int                     numParams;              /* nominal/maximum # of Params represented */
 
        /*
@@ -149,6 +150,12 @@ typedef struct ParamExecData
        bool            isnull;
 } ParamExecData;
 
+/* type of argument for ParamsErrorCallback */
+typedef struct ParamsErrorCbData
+{
+       const char       *portalName;
+       ParamListInfo params;
+} ParamsErrorCbData;
 
 /* Functions found in src/backend/nodes/params.c */
 extern ParamListInfo makeParamList(int numParams);
@@ -156,5 +163,8 @@ extern ParamListInfo copyParamList(ParamListInfo from);
 extern Size EstimateParamListSpace(ParamListInfo paramLI);
 extern void SerializeParamList(ParamListInfo paramLI, char **start_address);
 extern ParamListInfo RestoreParamList(char **start_address);
+extern char *BuildParamLogString(ParamListInfo params, char **paramTextValues,
+                                                               int valueLen);
+extern void ParamsErrorCallback(void *arg);
 
 #endif                                                 /* PARAMS_H */

diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index 50098e63feab3f440b1370ff33e88488927d551a..41d5e1d14ae1d3046dc9eccc83ef406b1e52ff1c 100644 (file)
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -234,6 +234,7 @@ typedef enum
 
 /* GUC vars that are actually declared in guc.c, rather than elsewhere */
 extern bool log_duration;
+extern bool log_parameters_on_error;
 extern bool Debug_print_plan;
 extern bool Debug_print_parse;
 extern bool Debug_print_rewritten;