Date: Fri, 6 Dec 2019 14:57:19 -0300
From: Alvaro Herrera <alvherre@2ndquadrant.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Andres Freund <andres@anarazel.de>,
	Alexey Bashtanov <bashtanov@imap.cc>,
	Peter Eisentraut <peter.eisentraut@2ndquadrant.com>,
	PostgreSQL Hackers <pgsql-hackers@postgresql.org>
Subject: Re: log bind parameter values on error
Message-ID: <20191206175719.GA15456@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="VbJkn9YxBvnuCH5J"
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <27177.1575591206@sss.pgh.pa.us>
User-Agent: Mutt/1.10.1 (2018-07-13)
Precedence: bulk


--VbJkn9YxBvnuCH5J
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit

On 2019-Dec-05, Tom Lane wrote:

> Possibly a workable compromise is to emit the info as an error
> context line, appending it to whatever context exists today.
> The result might look like, say,
> 
> ERROR:  whatever
> CONTEXT: SQL function "foo"
> extended query with parameters x, y, ...

This is easy to accomodate -- just change the errdetail() to errcontext.
That makes the params be reported different than in the non-error case
(for duration).

> For extra credit maybe we could include the query's statement or
> portal name?
> 
> 	errcontext("extended query \"%s\" with parameters %s", ...);

Sure.  Done in the attached.

> An independent point: it seems like just wishful thinking to imagine that
> src/test/examples/ can serve as a regression test for this.  Nor is the
> proposed program very useful as an example.  I'd drop that and find a
> way to have an actual, routinely-exercised-by-check-world regression
> test.  If memory serves, pgbench can be cajoled into executing stuff
> in extended query mode --- maybe we could create a test case using
> that?

I tried

pgbench -c1 -t1 -n -M prepared -f errparameters.bnch
with this file

  select '{ invalid ' as value \gset
  select column1::jsonb from (values (:value)) as q;

and got these lines:

2019-12-06 13:49:36.388 -03 [31028] ERROR:  invalid input syntax for type json
2019-12-06 13:49:36.388 -03 [31028] DETAIL:  Token "invalid" is invalid.
2019-12-06 13:49:36.388 -03 [31028] CONTEXT:  JSON data, line 1: { invalid...
        extended query with parameters: $1 = '{ invalid '
2019-12-06 13:49:36.388 -03 [31028] STATEMENT:  select column1::jsonb from (values ($1)) as q;

With this file,
  select '1' as one \gset
  SELECT 1 / (random() / 2)::int, :one::int, :two::int;

using the same pgbench invocation as above, I get this in the log:

2019-12-06 14:50:59.181 -03 [6187] ERROR:  division by zero
2019-12-06 14:50:59.181 -03 [6187] CONTEXT:  extended query with parameters: $1 = '1', $2 = NULL
2019-12-06 14:50:59.181 -03 [6187] STATEMENT:  SELECT 1 / (random() / 2)::int, $1::int, $2::int;

(While testing this I noticed that failing to strdup the text repr of
the datum when it's given as a text-format parameter results in bogus
output.  So I added a pstrdup there.)

(It seems a bit weird that if I assign NULL to :two pgbench stores the
empty string, instead of the NULL that I get as in the above which is
what happens when the variable is not defined at all.  That's probably a
bug in \gset ...)

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--VbJkn9YxBvnuCH5J
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="errcontext.patch"

diff --git a/src/backend/nodes/params.c b/src/backend/nodes/params.c
index 13d90f6551..a881df578e 100644
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -23,6 +23,7 @@
 #include "utils/datum.h"
 #include "utils/lsyscache.h"
 #include "utils/memutils.h"
+#include "utils/portal.h"
 
 
 /*
@@ -361,14 +362,17 @@ BuildParamLogString(ParamListInfo params, char **knownTextValues)
 void
 ParamsErrorCallback(void *arg)
 {
-	ParamListInfo params = (ParamListInfo) arg;
+	ParamsErrorCbData *data = (ParamsErrorCbData *) arg;
 
-	if (params == NULL || params->paramValuesStr == NULL)
+	if (data == NULL ||
+		data->params == NULL ||
+		data->params->paramValuesStr == NULL)
 		return;
 
-	/*
-	 * XXX this clobbers any other DETAIL line that the error callsite could
-	 * have had.  Do we care?
-	 */
-	errdetail("parameters: %s", params->paramValuesStr);
+	if (data->portalName && data->portalName[0] != '\0')
+		errcontext("extended query \"%s\" with parameters: %s",
+				   data->portalName, data->params->paramValuesStr);
+	else
+		errcontext("extended query with parameters: %s",
+				   data->params->paramValuesStr);
 }
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 9a009a5a9b..05a03ae924 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1753,7 +1753,7 @@ exec_bind_message(StringInfo input_message)
 	 */
 	if (numParams > 0)
 	{
-		char	  **knownTextValues = NULL;
+		char	  **knownTextValues = NULL;	/* allocate on first use */
 
 		params = makeParamList(numParams);
 
@@ -1822,22 +1822,19 @@ exec_bind_message(StringInfo input_message)
 
 				pval = OidInputFunctionCall(typinput, pstring, typioparam, -1);
 
-				/*
-				 * Save the parameter string if we need it; otherwise free it.
-				 */
+				/* When logging params, save a copy for later. */
 				if (pstring)
 				{
 					if (log_parameters_on_error)
 					{
-						/*
-						 * Allocate this on first use, making sure to put it
-						 * in a short-lived context.
-						 */
 						if (knownTextValues == NULL)
 							knownTextValues =
 								MemoryContextAllocZero(MessageContext,
 													   numParams * sizeof(char *));
-						knownTextValues[paramno] = pstring;
+						knownTextValues[paramno] =
+							pstring == pbuf.data ?
+							MemoryContextStrdup(MessageContext, pstring) :
+							pstring;
 					}
 					else if (pstring != pbuf.data)
 						pfree(pstring);
@@ -1905,7 +1902,8 @@ exec_bind_message(StringInfo input_message)
 	/* Set the error callback so that parameters are logged, as needed  */
 	params_errcxt.previous = error_context_stack;
 	params_errcxt.callback = ParamsErrorCallback;
-	params_errcxt.arg = (void *) params;
+	params_errcxt.arg = (void *) &((ParamsErrorCbData)
+								   { portal->name, params });
 	error_context_stack = &params_errcxt;
 
 	/* Get the result format codes */
@@ -2145,7 +2143,8 @@ exec_execute_message(const char *portal_name, long max_rows)
 	 */
 	params_errcxt.previous = error_context_stack;
 	params_errcxt.callback = ParamsErrorCallback;
-	params_errcxt.arg = (void *) portalParams;
+	params_errcxt.arg = (void *) &((ParamsErrorCbData)
+								   { portal->name, portalParams });
 	error_context_stack = &params_errcxt;
 
 	if (max_rows <= 0)
diff --git a/src/include/nodes/params.h b/src/include/nodes/params.h
index ba51dfe5e0..1e557ca7fd 100644
--- a/src/include/nodes/params.h
+++ b/src/include/nodes/params.h
@@ -150,6 +150,12 @@ typedef struct ParamExecData
 	bool		isnull;
 } ParamExecData;
 
+/* type of argument for ParamsErrorCallback */
+typedef struct ParamsErrorCbData
+{
+	const char	 *portalName;
+	ParamListInfo params;
+} ParamsErrorCbData;
 
 /* Functions found in src/backend/nodes/params.c */
 extern ParamListInfo makeParamList(int numParams);

--VbJkn9YxBvnuCH5J--