I added some tests to the pgbench suite in the attached. I also finally
put it the business to limit the length of parameters reported.
I'd probably drop testlibpq5.c, since it seems a bit pointless now ...
--
Álvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>From 6e0a777cb51bcb17e15977fbc729fef6b80b3aa8 Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvhe...@alvh.no-ip.org>
Date: Tue, 3 Dec 2019 10:08:35 -0300
Subject: [PATCH v17 1/2] Add appendStringInfoStringQuoted
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
Simplifies some coding that prints parameters, as well as optimize to do
it per non-quote chunks instead of per byte.
Author: Alexey Bashtanov and Álvaro Herrera, after a suggestion from Andres Freund
Discussion: https://postgr.es/m/20190920203905.xkv5udsd5dxfs...@alap3.anarazel.de
---
src/backend/tcop/postgres.c | 10 +---
src/common/stringinfo.c | 67 +++++++++++++++++++++++++++
src/include/lib/stringinfo.h | 8 ++++
src/pl/plpgsql/src/pl_exec.c | 36 ++++----------
src/test/regress/expected/plpgsql.out | 14 ++++++
src/test/regress/sql/plpgsql.sql | 13 ++++++
6 files changed, 113 insertions(+), 35 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 3b85e48333..3d3172e83d 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2348,7 +2348,6 @@ errdetail_params(ParamListInfo params)
Oid typoutput;
bool typisvarlena;
char *pstring;
- char *p;
appendStringInfo(¶m_str, "%s$%d = ",
paramno > 0 ? ", " : "",
@@ -2364,14 +2363,7 @@ errdetail_params(ParamListInfo params)
pstring = OidOutputFunctionCall(typoutput, prm->value);
- appendStringInfoCharMacro(¶m_str, '\'');
- for (p = pstring; *p; p++)
- {
- if (*p == '\'') /* double single quotes */
- appendStringInfoCharMacro(¶m_str, *p);
- appendStringInfoCharMacro(¶m_str, *p);
- }
- appendStringInfoCharMacro(¶m_str, '\'');
+ appendStringInfoStringQuoted(¶m_str, pstring, 0);
pfree(pstring);
}
diff --git a/src/common/stringinfo.c b/src/common/stringinfo.c
index a50e587da9..6f7555ef96 100644
--- a/src/common/stringinfo.c
+++ b/src/common/stringinfo.c
@@ -178,6 +178,73 @@ appendStringInfoString(StringInfo str, const char *s)
appendBinaryStringInfo(str, s, strlen(s));
}
+/*
+ * appendStringInfoStringQuoted
+ *
+ * Append a null-terminated string to str, adding single quotes around it
+ * and doubling all single quotes.
+ */
+void
+appendStringInfoStringQuoted(StringInfo str, const char *s, int maxlen)
+{
+ char *copy = NULL;
+ const char *chunk_search_start,
+ *chunk_copy_start,
+ *chunk_end;
+ bool ellipsis;
+
+ Assert(str != NULL);
+
+ if (maxlen > 0)
+ {
+ copy = pnstrdup(s, maxlen);
+ chunk_search_start = copy;
+ chunk_copy_start = copy;
+
+ ellipsis = strnlen(s, maxlen + 1) > maxlen;
+ /* enlarge while we can do so cheaply */
+ enlargeStringInfo(str, maxlen);
+ }
+ else
+ {
+ chunk_search_start = s;
+ chunk_copy_start = s;
+
+ ellipsis = false;
+ }
+
+ appendStringInfoCharMacro(str, '\'');
+
+ while ((chunk_end = strchr(chunk_search_start, '\'')) != NULL)
+ {
+ /* copy including the found delimiting ' */
+ appendBinaryStringInfoNT(str,
+ chunk_copy_start,
+ chunk_end - chunk_copy_start + 1);
+
+ /* in order to double it, include this ' into the next chunk as well */
+ chunk_copy_start = chunk_end;
+ chunk_search_start = chunk_end + 1;
+ }
+
+ /* copy the last chunk and terminate */
+ if (ellipsis)
+ appendStringInfo(str, "%s...'", chunk_copy_start);
+ else
+ {
+ int len = strlen(chunk_copy_start);
+
+ /* ensure sufficient space for terminators */
+ enlargeStringInfo(str, len + 2);
+ appendBinaryStringInfoNT(str, chunk_copy_start, len);
+ appendStringInfoCharMacro(str, '\'');
+ str->data[str->len] = '\0';
+ }
+
+ if (copy)
+ pfree(copy);
+}
+
/*
* appendStringInfoChar
*
diff --git a/src/include/lib/stringinfo.h b/src/include/lib/stringinfo.h
index e27942728e..956ccbba45 100644
--- a/src/include/lib/stringinfo.h
+++ b/src/include/lib/stringinfo.h
@@ -113,6 +113,14 @@ extern int appendStringInfoVA(StringInfo str, const char *fmt, va_list args) pg_
*/
extern void appendStringInfoString(StringInfo str, const char *s);
+/*------------------------
+ * appendStringInfoStringQuoted
+ * Append a null-terminated string to str, adding single quotes around it
+ * and doubling all single quotes.
+ */
+extern void appendStringInfoStringQuoted(StringInfo str, const char *s,
+ int maxlen);
+
/*------------------------
* appendStringInfoChar
* Append a single byte to str.
diff --git a/src/pl/plpgsql/src/pl_exec.c b/src/pl/plpgsql/src/pl_exec.c
index 4f0de7a811..c3ae409f39 100644
--- a/src/pl/plpgsql/src/pl_exec.c
+++ b/src/pl/plpgsql/src/pl_exec.c
@@ -8611,19 +8611,11 @@ format_expr_params(PLpgSQL_execstate *estate,
if (paramisnull)
appendStringInfoString(¶mstr, "NULL");
else
- {
- char *value = convert_value_to_string(estate, paramdatum, paramtypeid);
- char *p;
-
- appendStringInfoCharMacro(¶mstr, '\'');
- for (p = value; *p; p++)
- {
- if (*p == '\'') /* double single quotes */
- appendStringInfoCharMacro(¶mstr, *p);
- appendStringInfoCharMacro(¶mstr, *p);
- }
- appendStringInfoCharMacro(¶mstr, '\'');
- }
+ appendStringInfoStringQuoted(¶mstr,
+ convert_value_to_string(estate,
+ paramdatum,
+ paramtypeid),
+ 0);
paramno++;
}
@@ -8661,19 +8653,11 @@ format_preparedparamsdata(PLpgSQL_execstate *estate,
if (ppd->nulls[paramno] == 'n')
appendStringInfoString(¶mstr, "NULL");
else
- {
- char *value = convert_value_to_string(estate, ppd->values[paramno], ppd->types[paramno]);
- char *p;
-
- appendStringInfoCharMacro(¶mstr, '\'');
- for (p = value; *p; p++)
- {
- if (*p == '\'') /* double single quotes */
- appendStringInfoCharMacro(¶mstr, *p);
- appendStringInfoCharMacro(¶mstr, *p);
- }
- appendStringInfoCharMacro(¶mstr, '\'');
- }
+ appendStringInfoStringQuoted(¶mstr,
+ convert_value_to_string(estate,
+ ppd->values[paramno],
+ ppd->types[paramno]),
+ 0);
}
MemoryContextSwitchTo(oldcontext);
diff --git a/src/test/regress/expected/plpgsql.out b/src/test/regress/expected/plpgsql.out
index e85b29455e..cd2c79f4d5 100644
--- a/src/test/regress/expected/plpgsql.out
+++ b/src/test/regress/expected/plpgsql.out
@@ -2656,6 +2656,20 @@ create or replace function stricttest() returns void as $$
declare
x record;
p1 int := 2;
+p3 text := $a$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$a$;
+begin
+ -- no rows
+ select * from foo where f1 = p1 and f1::text = p3 into strict x;
+ raise notice 'x.f1 = %, x.f2 = %', x.f1, x.f2;
+end$$ language plpgsql;
+select stricttest();
+ERROR: query returned no rows
+DETAIL: parameters: p1 = '2', p3 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia?'''
+CONTEXT: PL/pgSQL function stricttest() line 8 at SQL statement
+create or replace function stricttest() returns void as $$
+declare
+x record;
+p1 int := 2;
p3 text := 'foo';
begin
-- too many rows
diff --git a/src/test/regress/sql/plpgsql.sql b/src/test/regress/sql/plpgsql.sql
index 70deadfbea..d841d8c0f9 100644
--- a/src/test/regress/sql/plpgsql.sql
+++ b/src/test/regress/sql/plpgsql.sql
@@ -2280,6 +2280,19 @@ end$$ language plpgsql;
select stricttest();
+create or replace function stricttest() returns void as $$
+declare
+x record;
+p1 int := 2;
+p3 text := $a$'Valame Dios!' dijo Sancho; 'no le dije yo a vuestra merced que mirase bien lo que hacia?'$a$;
+begin
+ -- no rows
+ select * from foo where f1 = p1 and f1::text = p3 into strict x;
+ raise notice 'x.f1 = %, x.f2 = %', x.f1, x.f2;
+end$$ language plpgsql;
+
+select stricttest();
+
create or replace function stricttest() returns void as $$
declare
x record;
--
2.20.1
>From a898bbfb4aefa98325cdd2af9a1b0627c5e7f745 Mon Sep 17 00:00:00 2001
From: Alvaro Herrera <alvhe...@alvh.no-ip.org>
Date: Mon, 2 Dec 2019 16:02:48 -0300
Subject: [PATCH v17 2/2] Emit parameter values during query bind/execute
errors
---
doc/src/sgml/config.sgml | 23 +++
src/backend/nodes/params.c | 130 ++++++++++++
src/backend/tcop/postgres.c | 110 +++++-----
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 +
src/test/README | 3 +-
src/test/examples/.gitignore | 1 +
src/test/examples/Makefile | 2 +-
src/test/examples/testlibpq5.c | 193 ++++++++++++++++++
12 files changed, 469 insertions(+), 50 deletions(-)
create mode 100644 src/test/examples/testlibpq5.c
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..cbdaec9b7c 100644
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -15,11 +15,15 @@
#include "postgres.h"
+#include "access/xact.h"
+#include "lib/stringinfo.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 +48,7 @@ makeParamList(int numParams)
retval->paramCompileArg = NULL;
retval->parserSetup = NULL;
retval->parserSetupArg = NULL;
+ retval->paramValuesStr = NULL;
retval->numParams = numParams;
return retval;
@@ -58,6 +63,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 +165,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 +260,124 @@ 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. If caller already knows textual representations for some or all
+ * parameters, it can pass an array of exactly params->numParams values as
+ * knownTextValues. It can contain NULLs for the individual values not known,
+ * or, if no text text values known at all the caller may pass NULL pointer.
+ *
+ * If valueLen 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 valueLen)
+{
+ 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 the callers memory context.
+ *
+ * To avoid repeated stringinfo enlargement, we assume 64 bytes per param
+ * for the first 128 params, then 16 bytes for each until completing 1024.
+ * Add zero bytes for parameters beyond 1024, since things are difficult
+ * to anticipate at that point. Note that because stringinfo initial size
+ * is 1024, we don't have to do anything with 8 parameters or less.
+ *
+ * (It doesn't seem worth the time or code complication to strlen() each
+ * parameter individually.)
+ */
+ initStringInfo(&buf);
+ if (params->numParams > 8)
+ enlargeStringInfo(&buf,
+ 64 * Min(params->numParams, 128) +
+ 16 * Min(Max(0, params->numParams - 128), 1024 - 128));
+
+ /* Use a temporary context to call output functions, just in case */
+ tmpCxt = AllocSetContextCreate(CurrentMemoryContext,
+ "BuildParamLogString",
+ ALLOCSET_SMALL_SIZES);
+ oldCxt = MemoryContextSwitchTo(tmpCxt);
+
+ for (int paramno = 0; paramno < params->numParams; paramno++)
+ {
+ ParamExternData *param = ¶ms->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],
+ valueLen);
+ else
+ {
+ Oid typoutput;
+ bool typisvarlena;
+ char *pstring;
+
+ getTypeOutputInfo(param->ptype, &typoutput, &typisvarlena);
+ pstring = OidOutputFunctionCall(typoutput, param->value);
+ appendStringInfoStringQuoted(&buf, pstring, valueLen);
+ }
+ }
+
+ MemoryContextReset(tmpCxt);
+ }
+
+ 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 3d3172e83d..1d23ec7746 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1613,6 +1613,7 @@ exec_bind_message(StringInfo input_message)
bool save_log_statement_stats = log_statement_stats;
bool snapshot_set = false;
char msec_str[32];
+ ErrorContextCallback params_errcxt;
/* Get the fixed part of the message */
portal_name = pq_getmsgstring(input_message);
@@ -1752,6 +1753,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++)
@@ -1819,9 +1822,28 @@ 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);
+ /* When logging params, save a copy for later */
+ 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 one more byte than
+ * BuildParamLogString wants to see; otherwise it'll
+ * fail to include the ellipsis ...
+ */
+ knownTextValues[paramno] = pnstrdup(pstring, 65);
+ MemoryContextSwitchTo(oldcxt);
+ }
+ if (pstring != pbuf.data)
+ pfree(pstring);
+ }
}
else if (pformat == 1) /* binary mode */
{
@@ -1871,6 +1893,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;
@@ -1878,6 +1908,13 @@ 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_errcxt.arg = (void *) &((ParamsErrorCbData)
+ { portal->name, params });
+ error_context_stack = ¶ms_errcxt;
+
/* Get the result format codes */
numRFormats = pq_getmsgint(input_message, 2);
if (numRFormats > 0)
@@ -1923,6 +1960,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.
*/
@@ -1979,6 +2022,7 @@ exec_execute_message(const char *portal_name, long max_rows)
bool execute_is_fetch;
bool was_logged = false;
char msec_str[32];
+ ErrorContextCallback params_errcxt;
/* Adjust destination to tell printtup.c what to do */
dest = whereToSendOutput;
@@ -2103,8 +2147,15 @@ 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_errcxt.arg = (void *) &((ParamsErrorCbData)
+ { portal->name, portalParams });
+ error_context_stack = ¶ms_errcxt;
+
if (max_rows <= 0)
max_rows = FETCH_ALL;
@@ -2118,6 +2169,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)
@@ -2328,51 +2382,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(¶m_str);
-
- for (int paramno = 0; paramno < params->numParams; paramno++)
- {
- ParamExternData *prm = ¶ms->params[paramno];
- Oid typoutput;
- bool typisvarlena;
- char *pstring;
-
- appendStringInfo(¶m_str, "%s$%d = ",
- paramno > 0 ? ", " : "",
- paramno + 1);
-
- if (prm->isnull || !OidIsValid(prm->ptype))
- {
- appendStringInfoString(¶m_str, "NULL");
- continue;
- }
-
- getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena);
-
- pstring = OidOutputFunctionCall(typoutput, prm->value);
-
- appendStringInfoStringQuoted(¶m_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;
diff --git a/src/test/README b/src/test/README
index b5ccfc0cf6..22e624d8ba 100644
--- a/src/test/README
+++ b/src/test/README
@@ -12,8 +12,7 @@ authentication/
Tests for authentication
examples/
- Demonstration programs for libpq that double as regression tests via
- "make check"
+ Demonstration programs for libpq that double as regression tests
isolation/
Tests for concurrent behavior at the SQL level
diff --git a/src/test/examples/.gitignore b/src/test/examples/.gitignore
index 1957ec198f..007aaee590 100644
--- a/src/test/examples/.gitignore
+++ b/src/test/examples/.gitignore
@@ -2,5 +2,6 @@
/testlibpq2
/testlibpq3
/testlibpq4
+/testlibpq5
/testlo
/testlo64
diff --git a/src/test/examples/Makefile b/src/test/examples/Makefile
index a67f456904..0407ca60bc 100644
--- a/src/test/examples/Makefile
+++ b/src/test/examples/Makefile
@@ -14,7 +14,7 @@ override CPPFLAGS := -I$(libpq_srcdir) $(CPPFLAGS)
LDFLAGS_INTERNAL += $(libpq_pgport)
-PROGS = testlibpq testlibpq2 testlibpq3 testlibpq4 testlo testlo64
+PROGS = testlibpq testlibpq2 testlibpq3 testlibpq4 testlibpq5 testlo testlo64
all: $(PROGS)
diff --git a/src/test/examples/testlibpq5.c b/src/test/examples/testlibpq5.c
new file mode 100644
index 0000000000..47a5e31335
--- /dev/null
+++ b/src/test/examples/testlibpq5.c
@@ -0,0 +1,193 @@
+/*
+ * src/test/examples/testlibpq5.c
+ *
+ * testlibpq5.c
+ * Test logging of statement parameters in case of errors.
+ */
+
+#ifdef WIN32
+#include <windows.h>
+#endif
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <stdint.h>
+#include <string.h>
+#include <sys/types.h>
+#include "libpq-fe.h"
+
+static void
+exit_nicely(PGconn *conn)
+{
+ PQfinish(conn);
+ exit(1);
+}
+
+int
+main(int argc, char **argv)
+{
+ const char *conninfo;
+ PGconn *conn;
+ PGresult *res;
+ const char *paramValues[3];
+ int paramLengths[3];
+ int paramFormats[3];
+ uint32_t binaryIntVal;
+
+ /*
+ * If the user supplies a parameter on the command line, use it as the
+ * conninfo string; otherwise default to setting dbname=postgres and using
+ * environment variables or defaults for all other connection parameters.
+ */
+ if (argc > 1)
+ conninfo = argv[1];
+ else
+ conninfo = "dbname = postgres";
+
+ /* Make a connection to the database */
+ conn = PQconnectdb(conninfo);
+
+ /* Check to see that the backend connection was successfully made */
+ if (PQstatus(conn) != CONNECTION_OK)
+ {
+ fprintf(stderr, "Connection to database failed: %s",
+ PQerrorMessage(conn));
+ exit_nicely(conn);
+ }
+
+ /* Set always-secure search path, so malicious users can't take control. */
+ res = PQexec(conn,
+ "SELECT pg_catalog.set_config('search_path', '', false)");
+ if (PQresultStatus(res) != PGRES_TUPLES_OK)
+ {
+ fprintf(stderr, "SET failed: %s", PQerrorMessage(conn));
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+
+ /*
+ * Transmit parameters in different forms and make a statement fail. User
+ * can then verify the server log.
+ */
+ res = PQexec(conn, "SET log_parameters_on_error = on");
+ if (PQresultStatus(res) != PGRES_COMMAND_OK)
+ {
+ fprintf(stderr, "SET failed: %s", PQerrorMessage(conn));
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+
+ /* emit error on parse stage */
+ paramValues[0] = (char *) "non-number -- parse";
+ paramLengths[0] = strlen(paramValues[2]) + 1;
+ paramFormats[0] = 0; /* text */
+ res = PQexecParams(conn,
+ "SELECT $1::int",
+ 1, /* # params */
+ NULL, /* let the backend deduce param type */
+ paramValues,
+ paramLengths,
+ paramFormats,
+ 1); /* ask for binary results */
+
+ if (PQresultStatus(res) != PGRES_FATAL_ERROR)
+ {
+ fprintf(stderr, "SELECT succeeded but was supposed to fail\n");
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+ printf("text->int conversion error expected on parse stage, "
+ "got an error message from server: %s\n",
+ PQerrorMessage(conn));
+
+ /* emit error on bind stage */
+ paramValues[0] = (char *) "{malformed json -- bind :-{";
+ paramLengths[0] = strlen(paramValues[2]) + 1;
+ paramFormats[0] = 0; /* text */
+ res = PQexecParams(conn,
+ "SELECT (' ' || $1::text || ' ')::json",
+ 1, /* # params */
+ NULL, /* let the backend deduce param type */
+ paramValues,
+ paramLengths,
+ paramFormats,
+ 1); /* ask for binary results */
+
+ if (PQresultStatus(res) != PGRES_FATAL_ERROR)
+ {
+ fprintf(stderr, "SELECT succeeded but was supposed to fail\n");
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+ printf("Json parsing error expected on bind stage, "
+ "got an error message from server: %s\n"
+ "Please make sure it has been logged "
+ "with bind parameters in server log\n",
+ PQerrorMessage(conn));
+
+ /* divide by zero -- but server won't realize until execution; 0 params */
+ res = PQexecParams(conn,
+ "SELECT 1 / (random() / 2)::int /*exec*/",
+ 0, /* # params */
+ NULL, /* let the backend deduce param type */
+ NULL,
+ NULL,
+ NULL,
+ 1); /* ask for binary results */
+
+ if (PQresultStatus(res) != PGRES_FATAL_ERROR)
+ {
+ fprintf(stderr, "SELECT succeeded but was supposed to fail\n");
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+ printf("Division by zero on execution expected, "
+ "got an error message from server: %s\n"
+ "Please make sure it has been logged "
+ "with bind parameters in server log\n",
+ PQerrorMessage(conn));
+
+ /* divide by zero -- but server won't realize until execution; 3 params */
+ paramValues[0] = (char *) &binaryIntVal;
+ paramLengths[0] = sizeof(binaryIntVal);
+ paramFormats[0] = 1; /* binary */
+ paramValues[1] = "2";
+ paramLengths[1] = strlen(paramValues[1]) + 1;
+ paramFormats[1] = 0; /* text */
+ paramValues[2] = (char *) "everyone's little $$ in \"dollar\"";
+ paramLengths[2] = strlen(paramValues[2]) + 1;
+ paramFormats[2] = 0; /* text */
+ res = PQexecParams(
+ conn,
+ "SELECT 1 / (random() / 2)::int + $1::int + $2::int, $3::text /*exec*/",
+ 3, /* # params */
+ NULL, /* let the backend deduce param type */
+ paramValues,
+ paramLengths,
+ paramFormats,
+ 1 /* ask for binary results */
+ );
+
+ if (PQresultStatus(res) != PGRES_FATAL_ERROR)
+ {
+ fprintf(stderr, "SELECT succeeded but was supposed to fail\n");
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+ printf("Division by zero on execution expected, "
+ "got an error message from server: %s\n"
+ "Please make sure it has been logged "
+ "with bind parameters in server log\n",
+ PQerrorMessage(conn));
+
+ /* close the connection to the database and cleanup */
+ PQfinish(conn);
+
+ return 0;
+}
--
2.20.1
