Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself.. - Mailing list pgsql-hackers

Justin Pryzby <pryzby@telsasoft.com> writes:
> On Mon, Mar 15, 2021 at 06:45:49PM -0400, Tom Lane wrote:
>> I started to look at this, and immediately began to wonder where is the
>> previous discussion you're evidently referring to.  Can you dig up an
>> archives link?

> I think I was referring to this (from the commit message).
> https://www.postgresql.org/message-id/flat/CANfkH5k-6nNt-4cSv1vPB80nq2BZCzhFVR5O4VznYbsX0wZmow@mail.gmail.com

Got it, thanks.

After studying the patch it seems like there's a better way to do it:
we should just log the single parameter that's at fault.  That saves
the user from having to dig through a bunch of parameters to figure
out which one we're complaining about, plus we can usefully identify
the parameter (by number) even if it was sent in binary.

This is a little bit more net code addition than what you had,
but only by ten lines or so.  On the plus side, it doesn't
require rearranging any existing code.

            regards, tom lane

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 8a0332dde9..b9ac6b8f76 100644
--- 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,16 @@ exec_bind_message(StringInfo input_message)
     if (numParams > 0)
     {
         char      **knownTextValues = NULL; /* allocate on first use */
+        BindParamCbData one_param_data;
+
+        /* Set the error callback so that parameters are logged for errors */
+        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 = ¶ms_errcxt;

         params = makeParamList(numParams);

@@ -1711,6 +1733,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 +1789,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,6 +1885,9 @@ exec_bind_message(StringInfo input_message)
             params->params[paramno].ptype = ptype;
         }

+        /* Pop the 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,
@@ -2413,6 +2446,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 d11c4e8c24..b66e564802 100644
--- 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 errors are reported during BIND phase, too
+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"