Hello and sorry for weeks of silence.
Hello Anders and Peter,
Thanks for your messages.
Please see the new patch version attached.
In my testing, I couldn't get this patch to do anything. Could you
please share your testing steps?
Sure. Provided you're in the postgres checkout and you've run make in
src/test/examples/ this should work
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
I did
postgres -D data --log-parameters-on-error=on
pgbench -i bench
alter table pgbench_accounts alter column aid type smallint;
pgbench -M extended -S -T 10 bench
This will then error out on type overflows, but I don't see any
parameters being logged:
ERROR: value "62812" is out of range for type smallint
STATEMENT: SELECT abalance FROM pgbench_accounts WHERE aid = $1;
(In this case the error message contains the parameter value, so it's
not a very practical case, but it should work, it seems.)
I guess this error occurred /while/ binding, so the parameters probably
weren't yet all bound by the time of error reporting.
That's why the error message came without parameters.
Meanwhile, I have committed a patch that refactors the ParamListInfo
initialization a bit, so you don't have to initialize hasTextValues in a
bunch of places unrelated to your core code. So please rebase your
patch on that.
Please find rebased patch attached.
I apologize for no reply before: I first thought my patch was really
faulty and knew I wouldn't have time to fix it these days, but it seems
to me it actually works.
Anyway, I don't suppose you manage to review it within the remaining few
days, so I'll rebase it again in the beginning of the next CF.
Best regards,
Alexey
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index d383de2..1442f30 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6330,6 +6330,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 f5d5613..5e5ccf1 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 f9ce3d8..e097ce8 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;
}
@@ -2297,61 +2377,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;
}
@@ -2669,6 +2706,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()
@@ -4022,10 +4140,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 8b4720e..e18d9e5 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 aa564d1..acd4f1e 100644
--- a/src/backend/utils/misc/guc.c
+++ b/src/backend/utils/misc/guc.c
@@ -481,6 +481,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;
@@ -1254,6 +1255,15 @@ static struct config_bool ConfigureNamesBool[] =
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."),
NULL
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index cccb5f1..61ec41a 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -528,6 +528,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 fd90466..316d3a2 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 b367838..2cfa2ac 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -24,6 +24,7 @@
#include "nodes/plannodes.h"
#include "storage/procsignal.h"
#include "utils/guc.h"
+#include "utils/portal.h"
#include "utils/queryenvironment.h"
@@ -32,6 +33,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;
@@ -83,6 +86,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 2712a77..563dcea 100644
--- a/src/include/utils/guc.h
+++ b/src/include/utils/guc.h
@@ -232,6 +232,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;
