rdelaage
/
postgresql
mirror of https://git.postgresql.org/git/postgresql.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Improve user control over truncation of logged bind-parameter values. 

This patch replaces the boolean GUC log_parameters_on_error introduced
by commit ba79cb5dc with an integer log_parameter_max_length_on_error,
adding the ability to specify how many bytes to trim each logged
parameter value to.  (The previous coding hard-wired that choice at
64 bytes.)

In addition, add a new parameter log_parameter_max_length that provides
similar control over truncation of query parameters that are logged in
response to statement-logging options, as opposed to errors.  Previous
releases always logged such parameters in full, possibly causing log
bloat.

For backwards compatibility with prior releases,
log_parameter_max_length defaults to -1 (log in full), while
log_parameter_max_length_on_error defaults to 0 (no logging).

Per discussion, log_parameter_max_length is SUSET since the DBA should
control routine logging behavior, but log_parameter_max_length_on_error
is USERSET because it also affects errcontext data sent back to the
client.

Alexey Bashtanov, editorialized a little by me

Discussion: https://postgr.es/m/b10493cc-a399-a03a-67c7-068f2791ee50@imap.cc
This commit is contained in:
Tom Lane 2020-04-02 15:04:51 -04:00
parent 2c220ca46f
commit 0b34e7d307
9 changed files with 207 additions and 63 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -2243,7 +2243,7 @@ include_dir 'conf.d'
</para>
</listitem>
</varlistentry>
<varlistentry id="guc-max-worker-processes" xreflabel="max_worker_processes">
<term><varname>max_worker_processes</varname> (<type>integer</type>)
<indexterm>
@ -4167,7 +4167,7 @@ ANY <replaceable class="parameter">num_sync</replaceable> ( <replaceable class="
Specifies whether the WAL receiver process should create a temporary replication
slot on the remote instance when no permanent replication slot to use
has been configured (using <xref linkend="guc-primary-slot-name"/>).
The default is off. This parameter can only be set in the
The default is off. This parameter can only be set in the
<filename>postgresql.conf</filename> file or on the server command line.
If this parameter is changed while the WAL receiver process is running,
that process is signalled to shut down and expected to restart with
@ -6685,26 +6685,58 @@ 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>)
<varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
<term><varname>log_parameter_max_length</varname> (<type>integer</type>)
<indexterm>
<primary><varname>log_parameters_on_error</varname> configuration parameter</primary>
<primary><varname>log_parameter_max_length</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 <productname>PostgreSQL</productname> 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>.
If greater than zero, each bind parameter value reported in
non-error statement-logging messages is trimmed to this many bytes.
Zero disables logging bind parameters with statements.
<literal>-1</literal> (the default) allows bind parameters to be
logged in full.
If this value is specified without units, it is taken as bytes.
Only superusers can change this setting.
</para>
<para>
This setting only affects log messages printed as a result of
<xref linkend="guc-log-statement"/>,
<xref linkend="guc-log-duration"/>, and related settings. Non-zero
values of this setting add some overhead, particularly if parameters
are sent in binary form, since then conversion to text is required.
</para>
</listitem>
</varlistentry>
<varlistentry id="guc-log-parameter-max-length-on-error" xreflabel="log_parameter_max_length_on_error">
<term><varname>log_parameter_max_length_on_error</varname> (<type>integer</type>)
<indexterm>
<primary><varname>log_parameter_max_length_on_error</varname> configuration parameter</primary>
</indexterm>
</term>
<listitem>
<para>
If greater than zero, each bind parameter value reported in error
messages is trimmed to this many bytes.
Zero (the default) disables including bind parameters in error
messages.
<literal>-1</literal> allows bind parameters to be printed in full.
If this value is specified without units, it is taken as bytes.
</para>
<para>
Non-zero values of this setting add overhead, as
<productname>PostgreSQL</productname> will need to store textual
representations of parameter values in memory at the start of each
statement, whether or not an error eventually occurs. The overhead
is greater when bind parameters are sent in binary form than when
they are sent as text, since the former case requires data
conversion while the latter only requires copying the string.
</para>
</listitem>
</varlistentry>

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

@ -269,7 +269,7 @@ RestoreParamList(char **start_address)
* 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 bytes of any one
* If maxlen is >= 0, that's the maximum number of bytes of any one
* parameter value to be printed; an ellipsis is added if the string is
* longer. (Added quotes are not considered in this calculation.)
*/

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

@ -1763,7 +1763,7 @@ exec_bind_message(StringInfo input_message)
*/
if (numParams > 0)
{
char **knownTextValues = NULL; /* allocate on first use */
char **knownTextValues = NULL; /* allocate on first use */
params = makeParamList(numParams);
@ -1833,26 +1833,39 @@ exec_bind_message(StringInfo input_message)
pval = OidInputFunctionCall(typinput, pstring, typioparam, -1);
/*
* Free result of encoding conversion, if any, and save a copy
* for later when logging parameters.
* If we might need to log parameters later, save a copy of
* the converted string in MessageContext; then free the
* result of encoding conversion, if any was done.
*/
if (pstring)
{
if (log_parameters_on_error)
if (log_parameter_max_length_on_error != 0)
{
MemoryContext oldcxt;
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);
if (log_parameter_max_length_on_error < 0)
knownTextValues[paramno] = pstrdup(pstring);
else
{
/*
* We can trim the saved string, knowing that we
* won't print all of it. But we must copy at
* least two more full characters than
* BuildParamLogString wants to use; otherwise it
* might fail to include the trailing ellipsis.
*/
knownTextValues[paramno] =
pnstrdup(pstring,
log_parameter_max_length_on_error
+ 2 * MAX_MULTIBYTE_CHAR_LEN);
}
MemoryContextSwitchTo(oldcxt);
}
if (pstring != pbuf.data)
@ -1909,13 +1922,15 @@ exec_bind_message(StringInfo input_message)
}
/*
* 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.)
* 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)
if (log_parameter_max_length_on_error != 0)
params->paramValuesStr =
BuildParamLogString(params, knownTextValues, 64);
BuildParamLogString(params,
knownTextValues,
log_parameter_max_length_on_error);
}
else
params = NULL;
@ -2396,15 +2411,17 @@ errdetail_execute(List *raw_parsetree_list)
* errdetail_params
*
* Add an errdetail() line showing bind-parameter data, if available.
* Note that this is only used for statement logging, so it is controlled
* by log_parameter_max_length not log_parameter_max_length_on_error.
*/
static int
errdetail_params(ParamListInfo params)
{
if (params && params->numParams > 0)
if (params && params->numParams > 0 && log_parameter_max_length != 0)
{
char *str;
char *str;
str = BuildParamLogString(params, NULL, 0);
str = BuildParamLogString(params, NULL, log_parameter_max_length);
if (str && str[0] != '\0')
errdetail("parameters: %s", str);
}

6
src/backend/utils/mb/stringinfo_mb.c
View File

@ -27,7 +27,7 @@
* appendStringInfoStringQuoted
*
* Append up to maxlen bytes from s to str, or the whole input string if
* maxlen <= 0, adding single quotes around it and doubling all single quotes.
* maxlen < 0, adding single quotes around it and doubling all single quotes.
* Add an ellipsis if the copy is incomplete.
*/
void
@ -43,9 +43,9 @@ appendStringInfoStringQuoted(StringInfo str, const char *s, int maxlen)
Assert(str != NULL);
slen = strlen(s);
if (maxlen > 0 && maxlen < slen)
if (maxlen >= 0 && maxlen < slen)
{
int finallen = pg_mbcliplen(s, slen, maxlen);
int finallen = pg_mbcliplen(s, slen, maxlen);
copy = pnstrdup(s, finallen);
chunk_search_start = copy;

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

@ -515,7 +515,6 @@ 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;
@ -544,6 +543,8 @@ int log_min_messages = WARNING;
int client_min_messages = NOTICE;
int log_min_duration_sample = -1;
int log_min_duration_statement = -1;
int log_parameter_max_length = -1;
int log_parameter_max_length_on_error = 0;
int log_temp_files = -1;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
@ -1381,15 +1382,6 @@ 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."),
@ -2855,6 +2847,28 @@ static struct config_int ConfigureNamesInt[] =
NULL, NULL, NULL
},
{
{"log_parameter_max_length", PGC_SUSET, LOGGING_WHAT,
gettext_noop("When logging statements, limit logged parameter values to first N bytes."),
gettext_noop("-1 to print values in full."),
GUC_UNIT_BYTE
},
&log_parameter_max_length,
-1, -1, INT_MAX / 2,
NULL, NULL, NULL
},
{
{"log_parameter_max_length_on_error", PGC_USERSET, LOGGING_WHAT,
gettext_noop("When reporting an error, limit logged parameter values to first N bytes."),
gettext_noop("-1 to print values in full."),
GUC_UNIT_BYTE
},
&log_parameter_max_length_on_error,
0, -1, INT_MAX / 2,
NULL, NULL, NULL
},
{
{"bgwriter_delay", PGC_SIGHUP, RESOURCES_BGWRITER,
gettext_noop("Background writer sleep time between rounds."),

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

@ -545,8 +545,13 @@
# %% = '%'
# e.g. '<%u%%%d> '
#log_lock_waits = off # log lock waits >= deadlock_timeout
#log_parameter_max_length = -1 # when logging statements, limit logged
# bind-parameter values to N bytes;
# -1 means print in full, 0 disables
#log_parameter_max_length_on_error = 0 # when logging an error, limit logged
# bind-parameter values to N bytes;
# -1 means print in full, 0 disables
#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;

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

@ -270,8 +270,39 @@ COMMIT;
}
});
# Verify server logging of parameters.
$node->append_conf('postgresql.conf', "log_parameters_on_error = true");
# Verify server logging of query parameters.
# (This doesn't really belong here, but pgbench is a convenient way
# to issue commands using extended query mode with parameters.)
# 1. Logging neither with errors nor with statements
$node->append_conf('postgresql.conf',
"log_min_duration_statement = 0\n" .
"log_parameter_max_length = 0\n" .
"log_parameter_max_length_on_error = 0");
$node->reload;
pgbench(
'-n -t1 -c1 -M prepared',
2,
[],
[
qr{ERROR: invalid input syntax for type json},
qr{(?!extended query with parameters)}
],
'server parameter logging',
{
'001_param_1' => 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);
unlike($log, qr[DETAIL: parameters: \$1 = '\{ invalid ',], "no parameters logged");
$log = undef;
# 2. Logging truncated parameters on error, full with statements
$node->append_conf('postgresql.conf',
"log_parameter_max_length = -1\n" .
"log_parameter_max_length_on_error = 64");
$node->reload;
pgbench(
'-n -t1 -c1 -M prepared',
@ -283,7 +314,47 @@ pgbench(
],
'server parameter logging',
{
'001_param_1' => q{select '1' as one \gset
'001_param_2' => 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\.\.\.[\r\n]+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_3' => 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;
]
});
$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;
# 3. Logging full parameters on error, truncated with statements
$node->append_conf('postgresql.conf',
"log_min_duration_statement = -1\n" .
"log_parameter_max_length = 7\n" .
"log_parameter_max_length_on_error = -1");
$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_4' => q{select '1' as one \gset
SELECT 1 / (random() / 2)::int, :one::int, :two::int;
}
});
@ -296,21 +367,25 @@ pgbench(
[],
[
qr{ERROR: invalid input syntax for type json},
qr[CONTEXT: JSON data, line 1: \{ invalid\.\.\.[\r\n]+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que \.\.\.']m
qr[CONTEXT: JSON data, line 1: \{ invalid\.\.\.[\r\n]+extended query with parameters: \$1 = '\{ invalid ', \$2 = '''Valame Dios!'' dijo Sancho; ''no le dije yo a vuestra merced que mirase bien lo que hacia\?']m
],
'server parameter logging',
{
'001_param_2' => q[select '{ invalid ' as value \gset
'001_param_5' => 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 = TestLib::slurp_file($node->logfile);
like($log, qr[DETAIL: parameters: \$1 = '\{ inval\.\.\.', \$2 = '''Valame\.\.\.'],
"parameter report truncates");
$log = undef;
$node->append_conf('postgresql.conf', "log_min_duration_statement = -1");
# Restore default logging config
$node->append_conf('postgresql.conf',
"log_min_duration_statement = -1\n" .
"log_parameter_max_length_on_error = 0\n" .
"log_parameter_max_length = -1");
$node->reload;
# test expressions

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

@ -233,8 +233,6 @@ 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;
@ -249,6 +247,9 @@ extern bool log_btree_build_stats;
extern PGDLLIMPORT bool check_function_bodies;
extern bool session_auth_is_superuser;
extern bool log_duration;
extern int log_parameter_max_length;
extern int log_parameter_max_length_on_error;
extern int log_min_error_statement;
extern PGDLLIMPORT int log_min_messages;
extern PGDLLIMPORT int client_min_messages;

4
src/pl/plpgsql/src/pl_exec.c
View File

@ -8771,7 +8771,7 @@ format_expr_params(PLpgSQL_execstate *estate,
convert_value_to_string(estate,
paramdatum,
paramtypeid),
0);
-1);
paramno++;
}
@ -8813,7 +8813,7 @@ format_preparedparamsdata(PLpgSQL_execstate *estate,
convert_value_to_string(estate,
ppd->values[paramno],
ppd->types[paramno]),
0);
-1);
}
MemoryContextSwitchTo(oldcontext);