Alexey: I would appreciate it if you give this patch a spin. Let me know if it does what you wanted it to do.
On 2019-Dec-10, Alvaro Herrera wrote: > Here's a curious thing that happens with this patch. If you have > log_duration set so that parameters are logged during the bind phase, > and then an error occurs during the execution phase but you don't have > log_parameters_on_error set true, the second error will log the > parameters nonetheless ... because they were saved in the ParamListInfo > struct by the errdetail_params() call in the check_log_durations block > during bind. AFAICS this has a simple solution, which is to stop saving the parameter string in BuildParamLogString; instead, just *return* the string. Caller can then assign it into params->paramValuesStr if appropriate (which, in the case of errdetail_params(), it is not.) v22 does it like that. There is still a much smaller issue that if you have both log_durations set to log the params during bind, and log_parameters_on_error to true, the parameters will appear twice. But I think that's correct by definition. -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
>From 57546105624ac5184a356dc227f0820240e61b62 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 v22] Emit parameter values during query bind/execute errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This makes such log entries more useful, since the cause of the error can be dependent on the parameter values. Author: Alexey Bashtanov, Álvaro Herrera Discussion: https://postgr.es/m/0146a67b-a22a-0519-9082-bc29756b9...@imap.cc Reviewed-by: Peter Eisentraut, Andres Freund, Tom Lane --- doc/src/sgml/config.sgml | 23 ++++ src/backend/nodes/params.c | 105 ++++++++++++++++ src/backend/tcop/postgres.c | 119 +++++++++++------- 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, 257 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..907da0e7cf 100644 --- a/src/backend/nodes/params.c +++ b/src/backend/nodes/params.c @@ -15,11 +15,14 @@ #include "postgres.h" +#include "access/xact.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" /* @@ -44,6 +47,7 @@ makeParamList(int numParams) retval->paramCompileArg = NULL; retval->parserSetup = NULL; retval->parserSetupArg = NULL; + retval->paramValuesStr = NULL; retval->numParams = numParams; return retval; @@ -58,6 +62,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 +164,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 +259,100 @@ RestoreParamList(char **start_address) return paramLI; } + +/* + * BuildParamLogString + * Return a string that represent the parameter list, for logging. + * + * 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.) + */ +char * +BuildParamLogString(ParamListInfo params, char **knownTextValues, int maxlen) +{ + MemoryContext tmpCxt, + oldCxt; + StringInfoData buf; + + /* + * No work if the param fetch hook is in use. Also, it's not possible to + * do this in an aborted transaction. (It might be possible to improve on + * this last point when some knownTextValues exist, but it seems tricky.) + */ + if (params->paramFetch != NULL || + IsAbortedTransactionBlockState()) + return NULL; + + /* 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 = ¶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], + maxlen); + else + { + Oid typoutput; + bool typisvarlena; + char *pstring; + + getTypeOutputInfo(param->ptype, &typoutput, &typisvarlena); + pstring = OidOutputFunctionCall(typoutput, param->value); + appendStringInfoStringQuoted(&buf, pstring, maxlen); + } + } + } + + MemoryContextSwitchTo(oldCxt); + MemoryContextDelete(tmpCxt); + + return buf.data; +} + +/* + * 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..0b7bc1fd03 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,15 @@ exec_bind_message(StringInfo input_message) params->params[paramno].pflags = PARAM_FLAG_CONST; params->params[paramno].ptype = ptype; } + + /* + * Once all parameters have been received, prepare for printing them in + * errors, 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) + params->paramValuesStr = + BuildParamLogString(params, knownTextValues, 64); } else params = NULL; @@ -1879,6 +1915,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_data.portalName = portal->name; + params_data.params = params; + params_errcxt.previous = error_context_stack; + params_errcxt.callback = ParamsErrorCallback; + params_errcxt.arg = (void *) ¶ms_data; + error_context_stack = ¶ms_errcxt; + /* Get the result format codes */ numRFormats = pq_getmsgint(input_message, 2); if (numRFormats > 0) @@ -1924,6 +1968,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 +2030,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 +2156,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_data.portalName = portal->name; + params_data.params = portalParams; + params_errcxt.previous = error_context_stack; + params_errcxt.callback = ParamsErrorCallback; + params_errcxt.arg = (void *) ¶ms_data; + error_context_stack = ¶ms_errcxt; + if (max_rows <= 0) max_rows = FETCH_ALL; @@ -2119,6 +2179,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 +2392,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; + char *str; - /* 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); + str = BuildParamLogString(params, NULL, 0); + if (str && str[0] != '\0') + errdetail("parameters: %s", str); } 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..c6310b892f 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 char *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
