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
>From 0cfc8ad16edea93ac1de223684e22725d1e86988 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryz...@telsasoft.com>
Date: Fri, 1 Jan 2021 19:38:57 -0600
Subject: [PATCH] report errors in parameter values during BIND
For example:
$ python3.5 -c "import pg,time; db=pg.DB('dbname=postgres host=/var/run/postgresql port=5432 host=/tmp'); q = db.query(\"SET log_parameter_max_length_on_error=-1;\"); db.prepare('p', 'SELECT \$1::smallint'); db.query_prepared('p',66666);"
2021-01-01 19:40:24.777 CST [5330] ERROR: value "66666" is out of range for type smallint
2021-01-01 19:40:24.777 CST [5330] CONTEXT: unnamed portal with parameters: $1 = '66666'
This can be useful to determine which is out of range when there are many bind
params.
See also:
commit ba79cb5dc
commit 0b34e7d30
https://www.postgresql.org/message-id/flat/canfkh5k-6nnt-4csv1vpb80nq2bzczhfvr5o4vznybsx0wz...@mail.gmail.com
Mention column name in error messages
---
src/backend/tcop/postgres.c | 175 ++++++++++++-------
src/bin/pgbench/t/001_pgbench_with_server.pl | 18 ++
2 files changed, 132 insertions(+), 61 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index bb5ccb4578..553b2e30fe 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1759,14 +1759,121 @@ exec_bind_message(StringInfo input_message)
snapshot_set = true;
}
+ /*
+ * Set the error callback so that parameters are logged, as needed.
+ * This has no effect until params->paramValuesStr is set
+ */
+ params_data.portalName = portal->name;
+ params_data.params = NULL;
+ params_errcxt.previous = error_context_stack;
+ params_errcxt.callback = ParamsErrorCallback;
+ params_errcxt.arg = (void *) ¶ms_data;
+ error_context_stack = ¶ms_errcxt;
+
/*
* Fetch parameters, if any, and store in the portal's memory context.
*/
if (numParams > 0)
{
char **knownTextValues = NULL; /* allocate on first use */
+ int32 *plengths;
+ char **pstrings;
+
+ plengths = palloc0(numParams * sizeof(*plengths));
+
+ /* Indexed by paramno, but not used for nulls */
+ pstrings = palloc0(numParams * sizeof(*pstrings));
params = makeParamList(numParams);
+ params_data.params = params;
+
+ /*
+ * Do two loops to allow error reports during BIND;
+ * On the first pass, just save the offset and length of each param;
+ * On the second pass, convert the params to the required type.
+ * If this fails, the params have already been saved for error callack.
+ */
+
+ for (int paramno = 0; paramno < numParams; paramno++)
+ {
+ int32 plength;
+ int16 pformat;
+ char *pstring;
+ MemoryContext oldcxt;
+
+ plength = plengths[paramno] = pq_getmsgint(input_message, 4);
+
+ /* Minimal amount needed for error callback */
+ params->params[paramno].ptype = psrc->param_types[paramno];
+ params->params[paramno].isnull = (plength == -1);
+
+ if (params->params[paramno].isnull)
+ continue;
+
+ pstrings[paramno] = unconstify(char *, pq_getmsgbytes(input_message, plength));
+
+ if (log_parameter_max_length_on_error == 0)
+ continue;
+
+ if (numPFormats > 1)
+ pformat = pformats[paramno];
+ else if (numPFormats > 0)
+ pformat = pformats[0];
+ else
+ pformat = 0; /* default = text */
+
+ if (pformat != 0) /* text mode */
+ continue;
+
+ /*
+ * If we might need to log parameters later, save a copy of
+ * the converted string in MessageContext;
+ * XXX: only supported in text mode ??
+ */
+ pstring = pg_client_to_server(pstrings[paramno], plength);
+ oldcxt = MemoryContextSwitchTo(MessageContext);
+
+ if (knownTextValues == NULL)
+ knownTextValues =
+ palloc0(numParams * sizeof(char *));
+
+ if (log_parameter_max_length_on_error < 0)
+ {
+ knownTextValues[paramno] = pstrdup(pstring);
+ knownTextValues[paramno][plength] = 0;
+ }
+ else
+ {
+ /*
+ * We can trim the saved string, knowing that we
+ * won't print all of it. But we must copy at
+ * least two more full characters than
+ * BuildParamLogString wants to use; otherwise it
+ * might fail to include the trailing ellipsis.
+ */
+ char csave = pstring[plength];
+ pstring[plength] = 0;
+ knownTextValues[paramno] =
+ pnstrdup(pstring,
+ log_parameter_max_length_on_error
+ + 2 * MAX_MULTIBYTE_CHAR_LEN);
+ pstring[plength] = csave;
+ }
+
+ MemoryContextSwitchTo(oldcxt);
+ if (pstring != pstrings[paramno])
+ pfree(pstring);
+ }
+
+ /*
+ * 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,
+ knownTextValues,
+ log_parameter_max_length_on_error);
for (int paramno = 0; paramno < numParams; paramno++)
{
@@ -1778,13 +1885,11 @@ exec_bind_message(StringInfo input_message)
char csave;
int16 pformat;
- plength = pq_getmsgint(input_message, 4);
+ plength = plengths[paramno];
isNull = (plength == -1);
if (!isNull)
{
- const char *pvalue = pq_getmsgbytes(input_message, plength);
-
/*
* Rather than copying data around, we just set up a phony
* StringInfo pointing to the correct portion of the message
@@ -1793,7 +1898,7 @@ exec_bind_message(StringInfo input_message)
* trailing null. This is grotty but is a big win when
* dealing with very large parameter strings.
*/
- pbuf.data = unconstify(char *, pvalue);
+ pbuf.data = pstrings[paramno];
pbuf.maxlen = plength + 1;
pbuf.len = plength;
pbuf.cursor = 0;
@@ -1833,45 +1938,9 @@ exec_bind_message(StringInfo input_message)
pval = OidInputFunctionCall(typinput, pstring, typioparam, -1);
- /*
- * If we might need to log parameters later, save a copy of
- * the converted string in MessageContext; then free the
- * result of encoding conversion, if any was done.
- */
- if (pstring)
- {
- if (log_parameter_max_length_on_error != 0)
- {
- MemoryContext oldcxt;
-
- oldcxt = MemoryContextSwitchTo(MessageContext);
-
- if (knownTextValues == NULL)
- knownTextValues =
- palloc0(numParams * sizeof(char *));
-
- if (log_parameter_max_length_on_error < 0)
- knownTextValues[paramno] = pstrdup(pstring);
- else
- {
- /*
- * We can trim the saved string, knowing that we
- * won't print all of it. But we must copy at
- * least two more full characters than
- * BuildParamLogString wants to use; otherwise it
- * might fail to include the trailing ellipsis.
- */
- knownTextValues[paramno] =
- pnstrdup(pstring,
- log_parameter_max_length_on_error
- + 2 * MAX_MULTIBYTE_CHAR_LEN);
- }
-
- MemoryContextSwitchTo(oldcxt);
- }
- if (pstring != pbuf.data)
- pfree(pstring);
- }
+ /* free the result of encoding conversion, if any was done. */
+ if (pstring && pstring != pbuf.data)
+ pfree(pstring);
}
else if (pformat == 1) /* binary mode */
{
@@ -1922,16 +1991,8 @@ exec_bind_message(StringInfo input_message)
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_parameter_max_length_on_error != 0)
- params->paramValuesStr =
- BuildParamLogString(params,
- knownTextValues,
- log_parameter_max_length_on_error);
+ pfree(plengths);
+ pfree(pstrings);
}
else
params = NULL;
@@ -1939,14 +2000,6 @@ 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 *) ¶ms_data;
- error_context_stack = ¶ms_errcxt;
-
/* Get the result format codes */
numRFormats = pq_getmsgint(input_message, 2);
if (numRFormats > 0)
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index daffc18e52..936ae80f91 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -350,6 +350,7 @@ $node->append_conf('postgresql.conf',
. "log_parameter_max_length = 7\n"
. "log_parameter_max_length_on_error = -1");
$node->reload;
+
pgbench(
'-n -t1 -c1 -M prepared',
2,
@@ -389,6 +390,23 @@ like(
"parameter report truncates");
$log = undef;
+# Check that errors happen during BIND phase, too
+pgbench(
+ '-n -t1 -c1 -M prepared',
+ 2,
+ [],
+ [
+ qr{ERROR: invalid input syntax for type smallint: "1a"},
+ qr{CONTEXT: unnamed portal with parameters: \$1 = '1a'}
+ ],
+ 'server parameter logging',
+ {
+ '001_param_6' => q{select '1a' as value \gset
+select :value::smallint;
+}
+ });
+
+
# Restore default logging config
$node->append_conf('postgresql.conf',
"log_min_duration_statement = -1\n"
--
2.17.0
