Date: Mon, 22 Feb 2021 11:15:25 -0600
From: Justin Pryzby <pryzby@telsasoft.com>
To: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Alexey Bashtanov <bashtanov@imap.cc>, Franck Verrot <franck@verrot.fr>,
	pgsql-hackers@postgresql.org
Subject: Re: [PATCH]: Allow errors in parameter values to be reported during
 the BIND phase itself..
Message-ID: <20210222171525.GU14772@telsasoft.com>
References: <20210104170939.GH9712@telsasoft.com>
 <20210222050526.GA11347@telsasoft.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="xQmOcGOVkeO43v2v"
Content-Disposition: inline
In-Reply-To: <20210222050526.GA11347@telsasoft.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk


--xQmOcGOVkeO43v2v
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

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

--xQmOcGOVkeO43v2v
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="0001-report-errors-in-parameter-values-during-BIND.patch"

From 0cfc8ad16edea93ac1de223684e22725d1e86988 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@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-4cSv1vPB80nq2BZCzhFVR5O4VznYbsX0wZmow@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 *) &params_data;
+	error_context_stack = &params_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 *) &params_data;
-	error_context_stack = &params_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


--xQmOcGOVkeO43v2v--