Thread: Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..
Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..
From
Tom Lane
Date:
Justin Pryzby <pryzby@telsasoft.com> writes:
> For example:
> $ python3.5 -c "import pg; db=pg.DB(); q = db.query(\"SET log_parameter_max_length_on_error=-1;\"); db.prepare('p',
'SELECT\$1::smallint'); db.query_prepared('p',66666);"
> 2021-01-03 02:21:04.547 CST [20157] ERROR: value "66666" is out of range for type smallint
> 2021-01-03 02:21:04.547 CST [20157] CONTEXT: unnamed portal with parameters: $1 = '66666'
> 2021-01-03 02:21:04.547 CST [20157] STATEMENT: SELECT $1::smallint
> When there are many bind params, this can be useful to determine which is out
> of range. Think 900 int/smallint columns, or less-wide tables being inserted
> multiple rows at a time with VALUES(),(),()...
> Of course, this isn't as good as showing the column name, so I might pursue
> Tom's suggestion for that at some point.
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?
regards, tom lane
Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..
From
Justin Pryzby
Date:
On Mon, Mar 15, 2021 at 06:45:49PM -0400, Tom Lane wrote:
> Justin Pryzby <pryzby@telsasoft.com> writes:
> > For example:
> > $ python3.5 -c "import pg; db=pg.DB(); q = db.query(\"SET log_parameter_max_length_on_error=-1;\"); db.prepare('p',
'SELECT\$1::smallint'); db.query_prepared('p',66666);"
> > 2021-01-03 02:21:04.547 CST [20157] ERROR: value "66666" is out of range for type smallint
> > 2021-01-03 02:21:04.547 CST [20157] CONTEXT: unnamed portal with parameters: $1 = '66666'
> > 2021-01-03 02:21:04.547 CST [20157] STATEMENT: SELECT $1::smallint
>
> > When there are many bind params, this can be useful to determine which is out
> > of range. Think 900 int/smallint columns, or less-wide tables being inserted
> > multiple rows at a time with VALUES(),(),()...
>
> > Of course, this isn't as good as showing the column name, so I might pursue
> > Tom's suggestion for that at some point.
>
> 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
Also, I looked through the original thread, and found this was discussed at the
time:
https://www.postgresql.org/message-id/b1b68453-9756-bd92-306e-a29fc5ad7cd7%402ndquadrant.com
> >> ERROR: value "62812" is out of range for type smallint
> >> STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;
> >>
> >> (In this case the error message contains the parameter value, so it's
> >> not a very practical case, but it should work, it seems.)
> > I guess this error occurred /while/ binding, so the parameters probably
> > weren't yet all bound by the time of error reporting.
> > That's why the error message came without parameters.
>
> I see. But I think that could be fixed. Change exec_bind_message() to
> loop over the parameters twice: once to save them away, once to actually
> process them. I think the case of a faulty input value is probably very
> common, so it would be confusing if that didn't work.
https://www.postgresql.org/message-id/resend/20191205231550.GA28677%40alvherre.pgsql
> One problem I noticed is that we don't log parameters when
> exec_bind_message fetches the parameter values. So the very first
> example problem in testlibpq5 fails to print the values of any
> parameters previously seen. I don't think this is a real problem in
> practice. You still get the unparseable value in the error message from
> the input function, so not having the errdetail() does not seem very
> important.
I see that as a deficiency (as Peter did), so I'm requesting to improve that
now. It's not a bugfix, though.
--
Justin
Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..
From
Tom Lane
Date:
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"