Thread

Commits

Improve logging of bad parameter values in BIND messages.
- 1ea396362be1 14.0 landed

[PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Justin Pryzby <pryzby@telsasoft.com> — 2021-01-04T17:09:39Z

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.

-- 
Justin

Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Justin Pryzby <pryzby@telsasoft.com> — 2021-02-22T05:05:26Z

On Mon, Jan 04, 2021 at 11:09:39AM -0600, Justin Pryzby wrote:
> 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(),(),()...

This fixes a crash when there are zero bind params, and the error context was
popped after not being pushed.

-- 
Justin

Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Justin Pryzby <pryzby@telsasoft.com> — 2021-02-22T17:15:25Z

On Sun, Feb 21, 2021 at 11:05:26PM -0600, Justin Pryzby wrote:
> On Mon, Jan 04, 2021 at 11:09:39AM -0600, Justin Pryzby wrote:
> > 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(),(),()...
> 
> This fixes a crash when there are zero bind params, and the error context was
> popped after not being pushed.

The previous patch was dysfynctional due to params_data.params = NULL.
This also fixes an issue with string termination.
And added a new test case.

I didn't understand how the existing pgbench test was working; apparently the
first of these queries generates parameter value CONTEXT messages in v13, but
(without my patch) not the 2nd.

| select column1::smallint from (values ($1)) as q;
| select $1::smallint

In the first case, it looks like:

        postgres: pryzbyj postgres [local] BIND(int2in+0x11) [0x55a57addd461]
        postgres: pryzbyj postgres [local] BIND(evaluate_expr+0x94) [0x55a57acba634]
        postgres: pryzbyj postgres [local] BIND(expression_tree_mutator+0x99) [0x55a57ac5a839]
        postgres: pryzbyj postgres [local] BIND(expression_tree_mutator+0x31e) [0x55a57ac5aabe]
        postgres: pryzbyj postgres [local] BIND(eval_const_expressions+0x53) [0x55a57acbbc73]
        postgres: pryzbyj postgres [local] BIND(subquery_planner+0x5a9) [0x55a57aca7159]
        postgres: pryzbyj postgres [local] BIND(standard_planner+0x113) [0x55a57aca8a63]
        postgres: pryzbyj postgres [local] BIND(pg_plan_query+0x4c) [0x55a57ad7cbfc]
        postgres: pryzbyj postgres [local] BIND(pg_plan_queries+0x41) [0x55a57ad7ccf1]
        postgres: pryzbyj postgres [local] BIND(GetCachedPlan+0x7d) [0x55a57ae87b9d]
        postgres: pryzbyj postgres [local] BIND(PostgresMain+0xe82) [0x55a57ad7e352]

In the 2nd case:

        postgres: pryzbyj postgres [local] BIND(int2in+0x11) [0x55a57addd461]
        postgres: pryzbyj postgres [local] BIND(InputFunctionCall+0x7f) [0x55a57aea19df]
        postgres: pryzbyj postgres [local] BIND(OidInputFunctionCall+0x4d) [0x55a57aea1bad]
        postgres: pryzbyj postgres [local] BIND(PostgresMain+0x1754) [0x55a57ad7ec24]

This could be considered a bugfix to v13, since ba79cb5dc says:
"Emit parameter values during query bind/execute errors"

-- 
Justin

Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Justin Pryzby <pryzby@telsasoft.com> — 2021-02-23T16:03:18Z

On Mon, Feb 22, 2021 at 11:15:25AM -0600, Justin Pryzby wrote:
> On Sun, Feb 21, 2021 at 11:05:26PM -0600, Justin Pryzby wrote:
> > On Mon, Jan 04, 2021 at 11:09:39AM -0600, Justin Pryzby wrote:
> > > 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(),(),()...
> > 
> > This fixes a crash when there are zero bind params, and the error context was
> > popped after not being pushed.
> 
> The previous patch was dysfynctional due to params_data.params = NULL.
> This also fixes an issue with string termination.
> And added a new test case.

I noticed that this would crash with binary mode parameter input from
PQexecParams, if typinput failed.

So this patch allows reporting of bind params on errors in typinput if all the
params are sent in text mode (which is typical).

But if they're sent in binary mode, we can't provide error output before
they're processed by the typinput function.

I added ecpg tests to exercize the binary mode cases.

-- 
Justin

Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Tom Lane <tgl@sss.pgh.pa.us> — 2021-03-15T22:45:49Z

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

Justin Pryzby <pryzby@telsasoft.com> — 2021-03-15T22:49:45Z

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

Tom Lane <tgl@sss.pgh.pa.us> — 2021-03-16T00:30:18Z

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

Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Justin Pryzby <pryzby@telsasoft.com> — 2021-03-16T01:18:59Z

On Mon, Mar 15, 2021 at 08:30:18PM -0400, Tom Lane wrote:
> +               /* 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,
>                  * so that they'll appear when the query is executed later.)
>                  */
>                 if (log_parameter_max_length_on_error != 0)
>                         params->paramValuesStr =
>                                 BuildParamLogString(params,
...

I think it's somewhat confusing that there's two callbacks.
The first one applies only during typinput/typreceive.
I guess the 2nd one should say that they're printed "in *future errors".

> +# Check that errors are reported during BIND phase, too

Actually, the v13 log_parameter_max_length_on_error feature works during BIND
too, but only after typinput of *all* params.

For example, this shows params when failing in GetCachedPlan().

| python3.5 -c "import pg,time; db=pg.DB('dbname=postgres host=/var/run/postgresql port=5432 host=/tmp'); q = db.query(\"SET backtrace_functions=pg_strtoint16; SET log_parameter_max_length_on_error=-1;\"); db.prepare('p', 'SELECT a::smallint from (select \$1 a)a'); db.query_prepared('p',66666);"

So my own description of the patch evolved from "show errors during BIND" to
"show errors during typinput of text params".

Thanks,
-- 
Justin

Re: [PATCH]: Allow errors in parameter values to be reported during the BIND phase itself..

Tom Lane <tgl@sss.pgh.pa.us> — 2021-03-16T15:18:57Z

Justin Pryzby <pryzby@telsasoft.com> writes:
> I think it's somewhat confusing that there's two callbacks.
> The first one applies only during typinput/typreceive.
> I guess the 2nd one should say that they're printed "in *future errors".

I adjusted the comments to make this a bit clearer, and pushed it.

			regards, tom lane