Please find the rebased patch attached.
Tested like the following.
Provided you're in the postgres checkout and you've run make in
src/test/examples/ and connected to db=postgres:
CREATE SCHEMA testlibpq3;
SET search_path = testlibpq3;
CREATE TABLE test1_(i int4, t text, b bytea);
INSERT INTO test1_ VALUES(0, '', '');
CREATE VIEW test1 AS SELECT 1/i i, t, b FROM test1_;
-- will log only statement
\! ./src/test/examples/testlibpq3
ALTER SYSTEM SET log_parameters_on_error TO on;
SELECT pg_reload_conf();
-- will log statement with parameters
\! ./src/test/examples/testlibpq3
Best regards,
Alexey
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c91e3e1550..9f2e9bae33 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6423,6 +6423,23 @@ 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 the statement is logged with bind parameter values.
+ It adds some overhead, as postgres will cache textual
+ representations of parameter values in memory for all statements,
+ even if they eventually do not get logged. 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 f5d56138ee..5e5ccf1a4f 100644
--- a/src/backend/nodes/params.c
+++ b/src/backend/nodes/params.c
@@ -45,6 +45,7 @@ makeParamList(int numParams)
retval->parserSetup = NULL;
retval->parserSetupArg = NULL;
retval->numParams = numParams;
+ retval->hasTextValues = false;
return retval;
}
@@ -58,6 +59,10 @@ 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.
+ *
+ * Since this function is never used for copying parameters into a top portal,
+ * we don't copy textual representations. Neither we set the hasTextValues
+ * flag, so noone will access them.
*/
ParamListInfo
copyParamList(ParamListInfo from)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 44a59e1d4f..3559163ac3 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -86,6 +86,12 @@
*/
const char *debug_query_string; /* client-supplied query string */
+/*
+ * The top-level portal that the client is immediately working with:
+ * creating, binding, executing, or all at one using simple protocol
+ */
+Portal current_top_portal = NULL;
+
/* Note: whereToSendOutput is initialized for the bootstrap/standalone case */
CommandDest whereToSendOutput = DestDebug;
@@ -1694,6 +1700,9 @@ exec_bind_message(StringInfo input_message)
else
portal = CreatePortal(portal_name, false, false);
+ Assert(current_top_portal == NULL);
+ current_top_portal = portal;
+
/*
* Prepare to copy stuff into the portal's memory context. We do all this
* copying first, because it could possibly fail (out-of-memory) and we
@@ -1731,6 +1740,9 @@ exec_bind_message(StringInfo input_message)
*/
if (numParams > 0)
{
+ /* GUC value can change, so we remember its state to be consistent */
+ bool need_text_values = log_parameters_on_error;
+
params = makeParamList(numParams);
for (int paramno = 0; paramno < numParams; paramno++)
@@ -1798,9 +1810,31 @@ 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);
+ if (pstring)
+ {
+ if (need_text_values)
+ {
+ if (pstring == pbuf.data)
+ {
+ /*
+ * Copy textual representation to portal context.
+ */
+ params->params[paramno].textValue =
+ pstrdup(pstring);
+ }
+ else
+ {
+ /* Reuse the result of encoding conversion for it */
+ params->params[paramno].textValue = pstring;
+ }
+ }
+ else
+ {
+ /* Free result of encoding conversion */
+ if (pstring != pbuf.data)
+ pfree(pstring);
+ }
+ }
}
else if (pformat == 1) /* binary mode */
{
@@ -1826,6 +1860,22 @@ exec_bind_message(StringInfo input_message)
(errcode(ERRCODE_INVALID_BINARY_REPRESENTATION),
errmsg("incorrect binary data format in bind parameter %d",
paramno + 1)));
+
+ /*
+ * Compute textual representation for further logging. We waste
+ * some time and memory here, maybe one day we could skip
+ * certain types like built-in primitives, which are safe to get
+ * it calculated later in an aborted xact.
+ */
+ if (!isNull && need_text_values)
+ {
+ Oid typoutput;
+ bool typisvarlena;
+
+ getTypeOutputInfo(ptype, &typoutput, &typisvarlena);
+ params->params[paramno].textValue =
+ OidOutputFunctionCall(typoutput, pval);
+ }
}
else
{
@@ -1850,10 +1900,22 @@ exec_bind_message(StringInfo input_message)
params->params[paramno].pflags = PARAM_FLAG_CONST;
params->params[paramno].ptype = ptype;
}
+
+ /*
+ * only now we can safely set it, as we have textValue populated
+ * for all non-null parameters
+ */
+ params->hasTextValues = need_text_values;
}
else
params = NULL;
+ /*
+ * Set portal parameters early for them to get logged if an error happens
+ * on planning stage
+ */
+ portal->portalParams = params;
+
/* Done storing stuff in portal's context */
MemoryContextSwitchTo(oldContext);
@@ -1934,6 +1996,7 @@ exec_bind_message(StringInfo input_message)
if (save_log_statement_stats)
ShowUsage("BIND MESSAGE STATISTICS");
+ current_top_portal = NULL;
debug_query_string = NULL;
}
@@ -1969,7 +2032,6 @@ exec_execute_message(const char *portal_name, long max_rows)
ereport(ERROR,
(errcode(ERRCODE_UNDEFINED_CURSOR),
errmsg("portal \"%s\" does not exist", portal_name)));
-
/*
* If the original query was a null string, just return
* EmptyQueryResponse.
@@ -1984,32 +2046,49 @@ exec_execute_message(const char *portal_name, long max_rows)
/* Does the portal contain a transaction command? */
is_xact_command = IsTransactionStmtList(portal->stmts);
- /*
- * We must copy the sourceText and prepStmtName into MessageContext in
- * case the portal is destroyed during finish_xact_command. Can avoid the
- * copy if it's not an xact command, though.
- */
if (is_xact_command)
{
+ /*
+ * We must copy the sourceText and prepStmtName into MessageContext in
+ * case the portal is destroyed during finish_xact_command.
+ */
sourceText = pstrdup(portal->sourceText);
if (portal->prepStmtName)
prepStmtName = pstrdup(portal->prepStmtName);
else
prepStmtName = "<unnamed>";
-
/*
* An xact command shouldn't have any parameters, which is a good
* thing because they wouldn't be around after finish_xact_command.
*/
portalParams = NULL;
+
+ /*
+ * We don't set current top portal for xact cmds, as
+ * 1) the portal may be destroyed earlier than the error happens
+ * 2) it anyway has no parameters in it to log
+ */
+ Assert(current_top_portal == NULL);
}
else
{
+ /*
+ * The portal will remain there until we leave the function, so it's
+ * safe avoid copying and just to refer to the data in its memory
+ * context instead
+ */
sourceText = portal->sourceText;
if (portal->prepStmtName)
prepStmtName = portal->prepStmtName;
else
prepStmtName = "<unnamed>";
+
+ /*
+ * For non-xact commands, we remember the current portal and its bind
+ * parameters for further use in logging
+ */
+ Assert(current_top_portal == NULL);
+ current_top_portal = portal;
portalParams = portal->portalParams;
}
@@ -2158,6 +2237,7 @@ exec_execute_message(const char *portal_name, long max_rows)
if (save_log_statement_stats)
ShowUsage("EXECUTE MESSAGE STATISTICS");
+ current_top_portal = NULL;
debug_query_string = NULL;
}
@@ -2299,61 +2379,18 @@ 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())
- {
- StringInfoData param_str;
- MemoryContext oldcontext;
-
- /* 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;
- char *p;
-
- 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);
-
- appendStringInfoCharMacro(¶m_str, '\'');
- for (p = pstring; *p; p++)
- {
- if (*p == '\'') /* double single quotes */
- appendStringInfoCharMacro(¶m_str, *p);
- appendStringInfoCharMacro(¶m_str, *p);
- }
- appendStringInfoCharMacro(¶m_str, '\'');
-
- pfree(pstring);
- }
-
- errdetail("parameters: %s", param_str.data);
+ /* Make sure any trash is generated in MessageContext */
+ MemoryContext oldcontext = MemoryContextSwitchTo(MessageContext);
+ char *params_message = get_portal_bind_parameters(params);
- pfree(param_str.data);
-
- MemoryContextSwitchTo(oldcontext);
+ if (params_message)
+ {
+ errdetail("parameters: %s", params_message);
+ pfree(params_message);
}
+ MemoryContextSwitchTo(oldcontext);
+
return 0;
}
@@ -2671,6 +2708,87 @@ drop_unnamed_stmt(void)
}
}
+/*
+ * get_portal_bind_parameters
+ * Get the string containing parameters data, is used for logging.
+ *
+ * Can return NULL if there are no parameters in the portal
+ * or the portal is not valid, or the text representations of the parameters are
+ * not available. If returning a non-NULL value, it allocates memory
+ * for the returned string in the current context, and it's the caller's
+ * responsibility to pfree() it if needed.
+ */
+char *
+get_portal_bind_parameters(ParamListInfo params)
+{
+ StringInfoData param_str;
+
+ /* No parameters to format */
+ if (!params || params->numParams == 0)
+ return NULL;
+
+ /*
+ * We either need textual representation of parameters pre-calcualted,
+ * or call potentially user-defined I/O functions to convert internal
+ * representation into text, which cannot be done in an aborted xact
+ */
+ if (!params->hasTextValues && IsAbortedTransactionBlockState())
+ return NULL;
+
+ initStringInfo(¶m_str);
+
+ /* This code doesn't support dynamic param lists */
+ Assert(params->paramFetch == NULL);
+
+ for (int paramno = 0; paramno < params->numParams; paramno++)
+ {
+ ParamExternData *prm = ¶ms->params[paramno];
+ char *pstring;
+ char *p;
+
+ appendStringInfo(¶m_str, "%s$%d = ",
+ paramno > 0 ? ", " : "",
+ paramno + 1);
+
+ if (prm->isnull)
+ {
+ appendStringInfoString(¶m_str, "NULL");
+ continue;
+ }
+
+ if (params->hasTextValues)
+ pstring = prm->textValue;
+ else
+ {
+ Oid typoutput;
+ bool typisvarlena;
+
+ if (!OidIsValid(prm->ptype))
+ {
+ appendStringInfoString(¶m_str, "UNKNOWN TYPE");
+ continue;
+ }
+
+ getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena);
+ 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, '\'');
+
+ if (!params->hasTextValues)
+ pfree(pstring);
+ }
+
+ return param_str.data;
+}
+
/* --------------------------------
* signal handler routines used in PostgresMain()
@@ -4024,10 +4142,11 @@ PostgresMain(int argc, char *argv[],
EmitErrorReport();
/*
- * Make sure debug_query_string gets reset before we possibly clobber
- * the storage it points at.
+ * Make sure these get reset before we possibly clobber
+ * the storages they point at.
*/
debug_query_string = NULL;
+ current_top_portal = NULL;
/*
* Abort the current transaction in order to recover.
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 8b4720ef3a..e18d9e59c8 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -76,6 +76,7 @@
#include "tcop/tcopprot.h"
#include "utils/guc.h"
#include "utils/memutils.h"
+#include "utils/portal.h"
#include "utils/ps_status.h"
@@ -344,6 +345,7 @@ errstart(int elevel, const char *filename, int lineno,
{
error_context_stack = NULL;
debug_query_string = NULL;
+ current_top_portal = NULL;
}
}
if (++errordata_stack_depth >= ERRORDATA_STACK_SIZE)
@@ -2788,6 +2790,18 @@ write_csvlog(ErrorData *edata)
if (print_stmt && edata->cursorpos > 0)
appendStringInfo(&buf, "%d", edata->cursorpos);
appendStringInfoChar(&buf, ',');
+ if (print_stmt && log_parameters_on_error
+ && PortalIsValid(current_top_portal))
+ {
+ char *param_values =
+ get_portal_bind_parameters(current_top_portal->portalParams);
+ if (param_values != NULL)
+ {
+ appendCSVLiteral(&buf, param_values);
+ pfree(param_values);
+ }
+ }
+ appendStringInfoChar(&buf, ',');
/* file error location */
if (Log_error_verbosity >= PGERROR_VERBOSE)
@@ -2944,6 +2958,18 @@ send_message_to_server_log(ErrorData *edata)
appendStringInfoString(&buf, _("STATEMENT: "));
append_with_tabs(&buf, debug_query_string);
appendStringInfoChar(&buf, '\n');
+
+ if (log_parameters_on_error && PortalIsValid(current_top_portal))
+ {
+ char *param_values =
+ get_portal_bind_parameters(current_top_portal->portalParams);
+ if (param_values != NULL)
+ {
+ log_line_prefix(&buf, edata);
+ appendStringInfo(&buf, _("PARAMETERS: %s\n"), param_values);
+ pfree(param_values);
+ }
+ }
}
#ifdef HAVE_SYSLOG
diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c
index 631f16f5fe..2e0b265f4b 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -483,6 +483,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;
@@ -1294,6 +1295,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 cfad86c02a..02e60b3bd2 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -536,6 +536,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/include/nodes/params.h b/src/include/nodes/params.h
index fd9046619c..316d3a2888 100644
--- a/src/include/nodes/params.h
+++ b/src/include/nodes/params.h
@@ -93,6 +93,7 @@ typedef struct ParamExternData
bool isnull; /* is it NULL? */
uint16 pflags; /* flag bits, see above */
Oid ptype; /* parameter's datatype, or 0 */
+ char *textValue; /* textual representation for debug purposes */
} ParamExternData;
typedef struct ParamListInfoData *ParamListInfo;
@@ -116,6 +117,8 @@ typedef struct ParamListInfoData
ParserSetupHook parserSetup; /* parser setup hook */
void *parserSetupArg;
int numParams; /* nominal/maximum # of Params represented */
+ bool hasTextValues; /* whether textValue for all non-null
+ params is populated */
/*
* params[] may be of length zero if paramFetch is supplied; otherwise it
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index ec21f7e45c..ecd6a93e2c 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -19,6 +19,7 @@
#include "nodes/plannodes.h"
#include "storage/procsignal.h"
#include "utils/guc.h"
+#include "utils/portal.h"
#include "utils/queryenvironment.h"
@@ -27,6 +28,8 @@
extern CommandDest whereToSendOutput;
extern PGDLLIMPORT const char *debug_query_string;
+extern PGDLLIMPORT Portal current_top_portal;
+
extern int max_stack_depth;
extern int PostAuthDelay;
@@ -78,6 +81,7 @@ extern long get_stack_depth_rlimit(void);
extern void ResetUsage(void);
extern void ShowUsage(const char *title);
extern int check_log_duration(char *msec_str, bool was_logged);
+extern char *get_portal_bind_parameters(ParamListInfo params);
extern void set_debug_options(int debug_flag,
GucContext context, GucSource source);
extern bool set_plan_disabling_options(const char *arg,
diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h
index e709177c37..125dc13a31 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/testlibpq3.c b/src/test/examples/testlibpq3.c
index c3b524cfdf..3b76d66e7d 100644
--- a/src/test/examples/testlibpq3.c
+++ b/src/test/examples/testlibpq3.c
@@ -42,7 +42,6 @@
#include <netinet/in.h>
#include <arpa/inet.h>
-
static void
exit_nicely(PGconn *conn)
{
@@ -116,9 +115,9 @@ main(int argc, char **argv)
const char *conninfo;
PGconn *conn;
PGresult *res;
- const char *paramValues[1];
- int paramLengths[1];
- int paramFormats[1];
+ const char *paramValues[2];
+ int paramLengths[2];
+ int paramFormats[2];
uint32_t binaryIntVal;
/*
@@ -224,6 +223,52 @@ main(int argc, char **argv)
PQclear(res);
+ /*
+ * In the third example we transmit parameters in different forms, make
+ * a statement fail and check how logging parameters on error works.
+ */
+ /* Set always-secure search path, so malicious users can't take control. */
+
+ 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);
+
+ 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 */
+ res = PQexecParams(conn,
+ /*
+ * always divide by zero,
+ * but deduce it only when executing
+ */
+ "SELECT 1 / (random() / 2)::int + $1::int + $2::int",
+ 2, /* two 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");
+ PQclear(res);
+ exit_nicely(conn);
+ }
+ PQclear(res);
+ printf("Division by zero expected, got an error message from server: %s"
+ "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);
