mirrors
/
postgres
mirror of https://github.com/postgres/postgres
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Emit parameter values during query bind/execute errors 

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-bc29756b93a2@imap.cc
Reviewed-by: Peter Eisentraut, Andres Freund, Tom Lane
This commit is contained in:
Alvaro Herrera 2019-12-11 18:03:35 -03:00
parent 16114f2ea0
commit ba79cb5dc8
8 changed files with 271 additions and 47 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

23
doc/src/sgml/config.sgml
View File

@ -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>

110
src/backend/nodes/params.c
View File

@ -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,105 @@ 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 any unknown individual values. 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;
/*
* NB: think not of returning params->paramValuesStr! It may have been
* generated with a different maxlen, and so unsuitable.
*/
/*
* 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 = &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);
}
}
}
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);
}

119
src/backend/tcop/postgres.c
View File

@ -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 *) &params_data;
error_context_stack = &params_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 *) &params_data;
error_context_stack = &params_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(&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);
str = BuildParamLogString(params, NULL, 0);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}
return 0;

10
src/backend/utils/misc/guc.c
View File

@ -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."),

1
src/backend/utils/misc/postgresql.conf.sample
View File

@ -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;

44
src/bin/pgbench/t/001_pgbench_with_server.pl
View File

@ -270,6 +270,50 @@ 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;
}
});
$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
$node->reload;
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;
]
});
my $log = TestLib::slurp_file($node->logfile);
like($log, qr[DETAIL: parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?'''],
"parameter report does not truncate");
$log = undef;
$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
$node->reload;
# test expressions
# command 1..3 and 23 depend on random seed which is used to call srandom.
pgbench(

10
src/include/nodes/params.h
View File

@ -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 */

1
src/include/utils/guc.h
View File

@ -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;