Date: Tue, 10 Dec 2019 16:33:39 -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: <20191210193339.GA12216@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="9amGYk9869ThD9tj"
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <16839.1575754825@sss.pgh.pa.us>
User-Agent: Mutt/1.10.1 (2018-07-13)
Precedence: bulk


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

On 2019-Dec-07, Tom Lane wrote:

> 0002:

Here's a version of this part with fixes for these comments.  It applies
on top of the stringinfo_mb.c patch sent elsewhere in the thread.

(If we were to add a "log_parameters_on_error_max_length" GUC to decide
the length to log, we would get rid of the remaining magical numbers in
this code).


> Seems like BuildParamLogString's "valueLen" parameter ought to be called
> "maxlen", for consistency with 0001 and because "valueLen" is at best
> misleading about what the parameter means.
> 
> I'd toss the enlargeStringInfo call here too, as it seems overly
> complicated and underly correct or useful.
> 
> Probably doing MemoryContextReset after each parameter (even the last one!)
> is a net loss compared to just letting it go till the end.  Although
> I'd be inclined to use ALLOCSET_DEFAULT_SIZES not SMALL_SIZES if you
> do it like that.
> 
> Please do not throw away the existing comment "/* Free result of encoding
> conversion, if any */" in exec_bind_message.
> 
> As above, this risks generating partial multibyte characters.  You might
> be able to get away with letting appendStringInfoStringQuoted do the
> multibyte-aware truncation, but you probably have to copy more than just
> one more extra byte first.
> 
> I have zero faith in this:
> 
> +    params_errcxt.arg = (void *) &((ParamsErrorCbData)
> +                                   { portal->name, params });
> 
> How do you know where the compiler is putting that value, ie what
> its lifespan is going to be?  Better to use an explicit variable.
> 
> I concur with dropping testlibpq5.
> 
> 			regards, tom lane


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

--9amGYk9869ThD9tj
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v21-0002-Emit-parameter-values-during-query-bind-execute-.patch"

From 45eca917877ea72122478fded75d5722a18d92aa Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvherre@alvh.no-ip.org>
Date: Mon, 2 Dec 2019 16:02:48 -0300
Subject: [PATCH v21 2/2] Emit parameter values during query bind/execute
 errors

---
 doc/src/sgml/config.sgml                      |  23 ++++
 src/backend/nodes/params.c                    | 114 +++++++++++++++++
 src/backend/tcop/postgres.c                   | 118 +++++++++++-------
 src/backend/utils/misc/guc.c                  |  10 ++
 src/backend/utils/misc/postgresql.conf.sample |   1 +
 src/bin/pgbench/t/001_pgbench_with_server.pl  |  35 ++++++
 src/include/nodes/params.h                    |  10 ++
 src/include/utils/guc.h                       |   1 +
 8 files changed, 265 insertions(+), 47 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 53ac14490a..5d1c90282f 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6595,6 +6595,29 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
       </listitem>
      </varlistentry>
 
+     <varlistentry id="guc-log-parameters-on-error" xreflabel="log_parameters_on_error">
+      <term><varname>log_parameters_on_error</varname> (<type>boolean</type>)
+      <indexterm>
+       <primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
+      </indexterm>
+      </term>
+      <listitem>
+       <para>
+        Controls whether bind parameters are logged when a statement is logged
+        as a result of <xref linkend="guc-log-min-error-statement"/>.
+        It adds some overhead, as postgres will compute and store textual
+        representations of parameter values in memory for all statements,
+        even if they eventually do not get logged.
+        This setting has no effect on statements logged due to
+        <xref linkend="guc-log-min-duration-statement"/> or
+        <xref linkend="guc-log-statement"/> settings, as they are always logged
+        with parameters.
+        The default is <literal>off</literal>.
+        Only superusers can change this setting.
+       </para>
+      </listitem>
+     </varlistentry>
+
      <varlistentry id="guc-log-statement" xreflabel="log_statement">
       <term><varname>log_statement</varname> (<type>enum</type>)
       <indexterm>
diff --git a/src/backend/nodes/params.c b/src/backend/nodes/params.c
index cf4387e40f..c3320ee1c4 100644
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -15,11 +15,16 @@
 
 #include "postgres.h"
 
+#include "access/xact.h"
+#include "lib/stringinfo.h"
+#include "mb/stringinfo_mb.h"
 #include "nodes/bitmapset.h"
 #include "nodes/params.h"
 #include "storage/shmem.h"
 #include "utils/datum.h"
 #include "utils/lsyscache.h"
+#include "utils/memutils.h"
+#include "utils/portal.h"
 
 
 /*
@@ -44,6 +49,7 @@ makeParamList(int numParams)
 	retval->paramCompileArg = NULL;
 	retval->parserSetup = NULL;
 	retval->parserSetupArg = NULL;
+	retval->paramValuesStr = NULL;
 	retval->numParams = numParams;
 
 	return retval;
@@ -58,6 +64,8 @@ makeParamList(int numParams)
  * set of parameter values.  If dynamic parameter hooks are present, we
  * intentionally do not copy them into the result.  Rather, we forcibly
  * instantiate all available parameter values and copy the datum values.
+ *
+ * paramValuesStr is not copied, either.
  */
 ParamListInfo
 copyParamList(ParamListInfo from)
@@ -158,6 +166,8 @@ EstimateParamListSpace(ParamListInfo paramLI)
  * RestoreParamList can be used to recreate a ParamListInfo based on the
  * serialized representation; this will be a static, self-contained copy
  * just as copyParamList would create.
+ *
+ * paramValuesStr is not included.
  */
 void
 SerializeParamList(ParamListInfo paramLI, char **start_address)
@@ -251,3 +261,107 @@ RestoreParamList(char **start_address)
 
 	return paramLI;
 }
+
+/*
+ * BuildParamLogString
+ *		Prepare for reporting parameter values.
+ *
+ * Create a string to represent parameters list for logging and save it to
+ * params->paramValuesStr. If caller already knows textual representations for
+ * some parameters, it can pass an array of exactly params->numParams values
+ * as knownTextValues, which can contain NULLs for the individual values not
+ * known.  NULL can be given if no parameters are known.
+ *
+ * If maxlen is not zero, that's the maximum number of characters of the
+ * input string printed; an ellipsis is added if more characters exist.
+ * (Added quotes are not considered.)
+ *
+ * This should only be called if log_parameters_on_error is set, or caller
+ * wants to report the query parameters for other reasons.
+ */
+void
+BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen)
+{
+	MemoryContext tmpCxt,
+				oldCxt;
+	StringInfoData buf;
+
+	/*
+	 * Nothing to do if it's is already set; also, no work if the param fetch
+	 * hook is in use.  (Mostly because it's unimplemented ... but that's
+	 * because it doesn't seem a case worth pursuing.)  Also, avoid calling
+	 * user-defined I/O functions when in an aborted transaction.  It might
+	 * be possible to improve on this when some knownTextValues exist.
+	 */
+	if (params->paramValuesStr != NULL ||
+		params->paramFetch != NULL ||
+		IsAbortedTransactionBlockState())
+		return;
+
+	/* Initialize the output stringinfo, in caller's memory context */
+	initStringInfo(&buf);
+
+	/* Use a temporary context to call output functions, just in case */
+	tmpCxt = AllocSetContextCreate(CurrentMemoryContext,
+								   "BuildParamLogString",
+								   ALLOCSET_DEFAULT_SIZES);
+	oldCxt = MemoryContextSwitchTo(tmpCxt);
+
+	for (int paramno = 0; paramno < params->numParams; paramno++)
+	{
+		ParamExternData *param = &params->params[paramno];
+
+		appendStringInfo(&buf,
+						 "%s$%d = ",
+						 paramno > 0 ? ", " : "",
+						 paramno + 1);
+
+		if (param->isnull || !OidIsValid(param->ptype))
+			appendStringInfoString(&buf, "NULL");
+		else
+		{
+			if (knownTextValues != NULL && knownTextValues[paramno] != NULL)
+				appendStringInfoStringQuoted(&buf, knownTextValues[paramno],
+											 maxlen);
+			else
+			{
+				Oid			typoutput;
+				bool		typisvarlena;
+				char	   *pstring;
+
+				getTypeOutputInfo(param->ptype, &typoutput, &typisvarlena);
+				pstring = OidOutputFunctionCall(typoutput, param->value);
+				appendStringInfoStringQuoted(&buf, pstring, maxlen);
+			}
+		}
+	}
+
+	params->paramValuesStr = buf.data;
+
+	MemoryContextSwitchTo(oldCxt);
+	MemoryContextDelete(tmpCxt);
+}
+
+/*
+ * ParamsErrorCallback - callback for printing parameters in error context
+ *
+ * Note that this is a no-op unless BuildParamLogString has been called
+ * beforehand.
+ */
+void
+ParamsErrorCallback(void *arg)
+{
+	ParamsErrorCbData *data = (ParamsErrorCbData *) arg;
+
+	if (data == NULL ||
+		data->params == NULL ||
+		data->params->paramValuesStr == NULL)
+		return;
+
+	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 512209a38c..5eef1ae41c 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1614,6 +1614,8 @@ exec_bind_message(StringInfo input_message)
 	bool		save_log_statement_stats = log_statement_stats;
 	bool		snapshot_set = false;
 	char		msec_str[32];
+	ParamsErrorCbData params_data;
+	ErrorContextCallback params_errcxt;
 
 	/* Get the fixed part of the message */
 	portal_name = pq_getmsgstring(input_message);
@@ -1753,6 +1755,8 @@ exec_bind_message(StringInfo input_message)
 	 */
 	if (numParams > 0)
 	{
+		char	  **knownTextValues = NULL;	/* allocate on first use */
+
 		params = makeParamList(numParams);
 
 		for (int paramno = 0; paramno < numParams; paramno++)
@@ -1820,9 +1824,32 @@ exec_bind_message(StringInfo input_message)
 
 				pval = OidInputFunctionCall(typinput, pstring, typioparam, -1);
 
-				/* Free result of encoding conversion, if any */
-				if (pstring && pstring != pbuf.data)
-					pfree(pstring);
+				/*
+				 * Free result of encoding conversion, if any, and save a copy
+				 * for later when logging parameters.
+				 */
+				if (pstring)
+				{
+					if (log_parameters_on_error)
+					{
+						MemoryContext	oldcxt;
+
+						oldcxt = MemoryContextSwitchTo(MessageContext);
+						if (knownTextValues == NULL)
+							knownTextValues =
+								palloc0(numParams * sizeof(char *));
+						/*
+						 * Note: must copy at least two more full characters
+						 * than BuildParamLogString wants to see; otherwise it
+						 * might fail to include the ellipsis.
+						 */
+						knownTextValues[paramno] =
+							pnstrdup(pstring, 64 + 2 * MAX_MULTIBYTE_CHAR_LEN);
+						MemoryContextSwitchTo(oldcxt);
+					}
+					if (pstring != pbuf.data)
+						pfree(pstring);
+				}
 			}
 			else if (pformat == 1)	/* binary mode */
 			{
@@ -1872,6 +1899,14 @@ exec_bind_message(StringInfo input_message)
 			params->params[paramno].pflags = PARAM_FLAG_CONST;
 			params->params[paramno].ptype = ptype;
 		}
+
+		/*
+		 * Prepare for printing parameters, if configured to do so.  (This is
+		 * saved in the portal, so that they'll appear when the query is
+		 * executed later.)
+		 */
+		if (log_parameters_on_error)
+			BuildParamLogString(params, knownTextValues, 64);
 	}
 	else
 		params = NULL;
@@ -1879,6 +1914,14 @@ 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_errcxt.previous = error_context_stack;
+	params_errcxt.callback = ParamsErrorCallback;
+	params_data.portalName = portal->name;
+	params_data.params = params;
+	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)
@@ -1924,6 +1967,12 @@ exec_bind_message(StringInfo input_message)
 	 */
 	PortalSetResultFormat(portal, numRFormats, rformats);
 
+	/*
+	 * Done binding; remove the parameters error callback.  Entries emitted
+	 * later determine independently whether to log the parameters or not.
+	 */
+	error_context_stack = error_context_stack->previous;
+
 	/*
 	 * Send BindComplete.
 	 */
@@ -1980,6 +2029,8 @@ exec_execute_message(const char *portal_name, long max_rows)
 	bool		execute_is_fetch;
 	bool		was_logged = false;
 	char		msec_str[32];
+	ParamsErrorCbData params_data;
+	ErrorContextCallback params_errcxt;
 
 	/* Adjust destination to tell printtup.c what to do */
 	dest = whereToSendOutput;
@@ -2104,8 +2155,16 @@ exec_execute_message(const char *portal_name, long max_rows)
 	CHECK_FOR_INTERRUPTS();
 
 	/*
-	 * Okay to run the portal.
+	 * Okay to run the portal.  Set the error callback so that parameters are
+	 * logged.  The parameters must have been saved during the bind phase.
 	 */
+	params_errcxt.previous = error_context_stack;
+	params_errcxt.callback = ParamsErrorCallback;
+	params_data.portalName = portal->name;
+	params_data.params = portalParams;
+	params_errcxt.arg = (void *) &params_data;
+	error_context_stack = &params_errcxt;
+
 	if (max_rows <= 0)
 		max_rows = FETCH_ALL;
 
@@ -2119,6 +2178,9 @@ exec_execute_message(const char *portal_name, long max_rows)
 
 	receiver->rDestroy(receiver);
 
+	/* Done executing; remove the params error callback */
+	error_context_stack = error_context_stack->previous;
+
 	if (completed)
 	{
 		if (is_xact_command)
@@ -2329,51 +2391,13 @@ errdetail_execute(List *raw_parsetree_list)
 static int
 errdetail_params(ParamListInfo params)
 {
-	/* We mustn't call user-defined I/O functions when in an aborted xact */
-	if (params && params->numParams > 0 && !IsAbortedTransactionBlockState())
+	if (params && params->numParams > 0)
 	{
-		StringInfoData param_str;
-		MemoryContext oldcontext;
+		BuildParamLogString(params, NULL, 0);
 
-		/* This code doesn't support dynamic param lists */
-		Assert(params->paramFetch == NULL);
-
-		/* Make sure any trash is generated in MessageContext */
-		oldcontext = MemoryContextSwitchTo(MessageContext);
-
-		initStringInfo(&param_str);
-
-		for (int paramno = 0; paramno < params->numParams; paramno++)
-		{
-			ParamExternData *prm = &params->params[paramno];
-			Oid			typoutput;
-			bool		typisvarlena;
-			char	   *pstring;
-
-			appendStringInfo(&param_str, "%s$%d = ",
-							 paramno > 0 ? ", " : "",
-							 paramno + 1);
-
-			if (prm->isnull || !OidIsValid(prm->ptype))
-			{
-				appendStringInfoString(&param_str, "NULL");
-				continue;
-			}
-
-			getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena);
-
-			pstring = OidOutputFunctionCall(typoutput, prm->value);
-
-			appendStringInfoStringQuoted(&param_str, pstring, 0);
-
-			pfree(pstring);
-		}
-
-		errdetail("parameters: %s", param_str.data);
-
-		pfree(param_str.data);
-
-		MemoryContextSwitchTo(oldcontext);
+		if (params->paramValuesStr &&
+			params->paramValuesStr[0] != '\0')
+			errdetail("parameters: %s", params->paramValuesStr);
 	}
 
 	return 0;
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index ba74bf9f7d..8d951ce404 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -486,6 +486,7 @@ extern const struct config_enum_entry dynamic_shared_memory_options[];
  * GUC option variables that are exported from this module
  */
 bool		log_duration = false;
+bool		log_parameters_on_error = false;
 bool		Debug_print_plan = false;
 bool		Debug_print_parse = false;
 bool		Debug_print_rewritten = false;
@@ -1300,6 +1301,15 @@ static struct config_bool ConfigureNamesBool[] =
 		false,
 		NULL, NULL, NULL
 	},
+	{
+		{"log_parameters_on_error", PGC_SUSET, LOGGING_WHAT,
+			gettext_noop("Logs bind parameters of the logged statements where possible."),
+			NULL
+		},
+		&log_parameters_on_error,
+		false,
+		NULL, NULL, NULL
+	},
 	{
 		{"debug_print_parse", PGC_USERSET, LOGGING_WHAT,
 			gettext_noop("Logs each query's parse tree."),
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 9541879c1f..087190ce63 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -544,6 +544,7 @@
 					# e.g. '<%u%%%d> '
 #log_lock_waits = off			# log lock waits >= deadlock_timeout
 #log_statement = 'none'			# none, ddl, mod, all
+#log_parameters_on_error = off	# on error log statements with bind parameters
 #log_replication_commands = off
 #log_temp_files = -1			# log temporary files equal or larger
 					# than the specified size in kilobytes;
diff --git a/src/bin/pgbench/t/001_pgbench_with_server.pl b/src/bin/pgbench/t/001_pgbench_with_server.pl
index 1845869016..021d7a1826 100644
--- a/src/bin/pgbench/t/001_pgbench_with_server.pl
+++ b/src/bin/pgbench/t/001_pgbench_with_server.pl
@@ -270,6 +270,41 @@ COMMIT;
 }
 	});
 
+# Verify server logging of parameters
+$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
+$node->reload;
+pgbench(
+		'-n -t1 -c1 -M prepared',
+		2,
+		[],
+		[
+		qr{ERROR:  division by zero},
+		qr{CONTEXT:  extended query with parameters: \$1 = '1', \$2 = NULL}
+		],
+		'server parameter logging',
+		{
+			'001_param_1' => q{select '1' as one \gset
+SELECT 1 / (random() / 2)::int, :one::int, :two::int;
+}
+	});
+
+pgbench(
+		'-n -t1 -c1 -M prepared',
+		2,
+		[],
+		[
+		qr{ERROR:  invalid input syntax for type json},
+		qr[CONTEXT:  JSON data, line 1: \{ invalid\.\.\.
+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que ...'$]m
+		],
+		'server parameter logging',
+		{
+			'001_param_2' => q[select '{ invalid ' as value \gset
+select $$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$$ as long \gset
+select column1::jsonb from (values (:value), (:long)) as q;
+]
+	});
+
 # test expressions
 # command 1..3 and 23 depend on random seed which is used to call srandom.
 pgbench(
diff --git a/src/include/nodes/params.h b/src/include/nodes/params.h
index fd9046619c..d7a7e1f191 100644
--- a/src/include/nodes/params.h
+++ b/src/include/nodes/params.h
@@ -115,6 +115,7 @@ typedef struct ParamListInfoData
 	void	   *paramCompileArg;
 	ParserSetupHook parserSetup;	/* parser setup hook */
 	void	   *parserSetupArg;
+	char	   *paramValuesStr;		/* params as a single string for errors */
 	int			numParams;		/* nominal/maximum # of Params represented */
 
 	/*
@@ -149,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);
@@ -156,5 +163,8 @@ extern ParamListInfo copyParamList(ParamListInfo from);
 extern Size EstimateParamListSpace(ParamListInfo paramLI);
 extern void SerializeParamList(ParamListInfo paramLI, char **start_address);
 extern ParamListInfo RestoreParamList(char **start_address);
+extern void BuildParamLogString(ParamListInfo params, char **paramTextValues,
+								int valueLen);
+extern void ParamsErrorCallback(void *arg);
 
 #endif							/* PARAMS_H */
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index 50098e63fe..41d5e1d14a 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -234,6 +234,7 @@ typedef enum
 
 /* GUC vars that are actually declared in guc.c, rather than elsewhere */
 extern bool log_duration;
+extern bool log_parameters_on_error;
 extern bool Debug_print_plan;
 extern bool Debug_print_parse;
 extern bool Debug_print_rewritten;
-- 
2.20.1


--9amGYk9869ThD9tj--