Improve logging of bad parameter values in BIND messages.

Since commit ba79cb5dc, values of bind parameters have been logged
during errors in extended query mode.  However, we only did that after
we'd collected and converted all the parameter values, thus failing to
offer any useful localization of invalid-parameter problems.  Add a
separate callback that's used during parameter collection, and have it
print the parameter number, along with the input string if text input
format is used.

Justin Pryzby and Tom Lane

Discussion: https://postgr.es/m/20210104170939[email protected]
Discussion: https://postgr.es/m/CANfkH5k-6nNt-4cSv1vPB80nq2BZCzhFVR5O4VznYbsX0wZmow@mail.gmail.com

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8a0332dde9d9c24ed840b62259ad7ab2f08c06a0..2b1b68109fd67840c49107d69eee37e324074e72 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -102,7 +102,18 @@ int            max_stack_depth = 100;
 /* wait N seconds to allow attach from a debugger */
 int            PostAuthDelay = 0;
 
+/* ----------------
+ *     private typedefs etc
+ * ----------------
+ */
 
+/* type of argument for bind_param_error_callback */
+typedef struct BindParamCbData
+{
+   const char *portalName;
+   int         paramno;        /* zero-based param number, or -1 initially */
+   const char *paramval;       /* textual input string, if available */
+} BindParamCbData;
 
 /* ----------------
  *     private variables
@@ -183,6 +194,7 @@ static int  errdetail_execute(List *raw_parsetree_list);
 static int errdetail_params(ParamListInfo params);
 static int errdetail_abort(void);
 static int errdetail_recovery_conflict(void);
+static void bind_param_error_callback(void *arg);
 static void start_xact_command(void);
 static void finish_xact_command(void);
 static bool IsTransactionExitStmt(Node *parsetree);
@@ -1698,6 +1710,19 @@ exec_bind_message(StringInfo input_message)
    if (numParams > 0)
    {
        char      **knownTextValues = NULL; /* allocate on first use */
+       BindParamCbData one_param_data;
+
+       /*
+        * Set up an error callback so that if there's an error in this phase,
+        * we can report the specific parameter causing the problem.
+        */
+       one_param_data.portalName = portal->name;
+       one_param_data.paramno = -1;
+       one_param_data.paramval = NULL;
+       params_errcxt.previous = error_context_stack;
+       params_errcxt.callback = bind_param_error_callback;
+       params_errcxt.arg = (void *) &one_param_data;
+       error_context_stack = &params_errcxt;
 
        params = makeParamList(numParams);
 
@@ -1711,6 +1736,9 @@ exec_bind_message(StringInfo input_message)
            char        csave;
            int16       pformat;
 
+           one_param_data.paramno = paramno;
+           one_param_data.paramval = NULL;
+
            plength = pq_getmsgint(input_message, 4);
            isNull = (plength == -1);
 
@@ -1764,8 +1792,13 @@ exec_bind_message(StringInfo input_message)
                else
                    pstring = pg_client_to_server(pbuf.data, plength);
 
+               /* Now we can log the input string in case of error */
+               one_param_data.paramval = pstring;
+
                pval = OidInputFunctionCall(typinput, pstring, typioparam, -1);
 
+               one_param_data.paramval = NULL;
+
                /*
                 * If we might need to log parameters later, save a copy of
                 * the converted string in MessageContext; then free the
@@ -1855,10 +1888,13 @@ exec_bind_message(StringInfo input_message)
            params->params[paramno].ptype = ptype;
        }
 
+       /* Pop the per-parameter error callback */
+       error_context_stack = error_context_stack->previous;
+
        /*
         * 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.)
+        * in future 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_parameter_max_length_on_error != 0)
            params->paramValuesStr =
@@ -1872,7 +1908,10 @@ 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  */
+   /*
+    * Set up another error callback so that all the parameters are logged if
+    * we get an error during the rest of the BIND processing.
+    */
    params_data.portalName = portal->name;
    params_data.params = params;
    params_errcxt.previous = error_context_stack;
@@ -2413,6 +2452,55 @@ errdetail_recovery_conflict(void)
    return 0;
 }
 
+/*
+ * bind_param_error_callback
+ *
+ * Error context callback used while parsing parameters in a Bind message
+ */
+static void
+bind_param_error_callback(void *arg)
+{
+   BindParamCbData *data = (BindParamCbData *) arg;
+   StringInfoData buf;
+   char       *quotedval;
+
+   if (data->paramno < 0)
+       return;
+
+   /* If we have a textual value, quote it, and trim if necessary */
+   if (data->paramval)
+   {
+       initStringInfo(&buf);
+       appendStringInfoStringQuoted(&buf, data->paramval,
+                                    log_parameter_max_length_on_error);
+       quotedval = buf.data;
+   }
+   else
+       quotedval = NULL;
+
+   if (data->portalName && data->portalName[0] != '\0')
+   {
+       if (quotedval)
+           errcontext("portal \"%s\" parameter $%d = %s",
+                      data->portalName, data->paramno + 1, quotedval);
+       else
+           errcontext("portal \"%s\" parameter $%d",
+                      data->portalName, data->paramno + 1);
+   }
+   else
+   {
+       if (quotedval)
+           errcontext("unnamed portal parameter $%d = %s",
+                      data->paramno + 1, quotedval);
+       else
+           errcontext("unnamed portal parameter $%d",
+                      data->paramno + 1);
+   }
+
+   if (quotedval)
+       pfree(quotedval);
+}
+
 /*
  * exec_describe_statement_message
  *

diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index d11c4e8c242e0e0772c28d78d24ac5e70b23538b..82a46c72b6af8611459b48e2cbb391fbde00ea7d 100644 (file)
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -389,6 +389,22 @@ like(
    "parameter report truncates");
 $log = undef;
 
+# Check that bad parameters are reported during typinput phase of BIND
+pgbench(
+   '-n -t1 -c1 -M prepared',
+   2,
+   [],
+   [
+       qr{ERROR:  invalid input syntax for type smallint: "1a"},
+       qr{CONTEXT:  unnamed portal parameter \$2 = '1a'}
+   ],
+   'server parameter logging',
+   {
+       '001_param_6' => q{select 42 as value1, '1a' as value2 \gset
+select :value1::smallint, :value2::smallint;
+}
+   });
+
 # Restore default logging config
 $node->append_conf('postgresql.conf',
        "log_min_duration_statement = -1\n"