Improve user control over truncation of logged bind-parameter values.
authorTom Lane <tgl@sss.pgh.pa.us>
Thu, 2 Apr 2020 19:04:51 +0000 (15:04 -0400)
committerTom Lane <tgl@sss.pgh.pa.us>
Thu, 2 Apr 2020 19:04:51 +0000 (15:04 -0400)
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

doc/src/sgml/config.sgml
src/backend/nodes/params.c
src/backend/tcop/postgres.c
src/backend/utils/mb/stringinfo_mb.c
src/backend/utils/misc/guc.c
src/backend/utils/misc/postgresql.conf.sample
src/bin/pgbench/t/001_pgbench_with_server.pl
src/include/utils/guc.h
src/pl/plpgsql/src/pl_exec.c

index 243d0198689f508d5137efb5cc1f6229b6bd864b..c4d6ed4bbcd5d6c65d0de24b59c695c0ccbe767a 100644 (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>
 
index a57f9eea768fb7bb5f9702ec69571866b1c79f34..ed2ee6a975a0e5655b7799bb5dddbf118fa74314 100644 (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.)
  */
index 5b677863b9c4de661b4bb67ff755e76b014201d1..8958ec8103ef2bc91331200e42b87c0dfe4837e0 100644 (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);
        }
index d7cf3751aa30f81b29f77844dc9053f4c3bff2db..5f51f538c1803b736fafffa00c46935e1eaa76e3 100644 (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;
index 79bc7ac8cac4a7a8c80da6aad8a987f91798c853..64dc9fbd1386eefba020465b9ed70b436f4c8c0c 100644 (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."),
index 7de4adc2ff19cb39d9935922744b9f2e5d8dfab6..e904fa7300fad36d3f4034ae997b1ae2822a43dd 100644 (file)
                                        #   %% = '%'
                                        # 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;
index 25ea17f7d1125f6d555fa87a24ab36f681eec315..b85a3ac32dd3b6b52ccc77874c34ca509b30670b 100644 (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,13 +314,10 @@ 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;
 }
        });
-
-$node->append_conf('postgresql.conf', "log_min_duration_statement = 0");
-$node->reload;
 pgbench(
                '-n -t1 -c1 -M prepared',
                2,
@@ -300,17 +328,64 @@ pgbench(
                ],
                'server parameter logging',
                {
-                       '001_param_2' => q[select '{ invalid ' as value \gset
+                       '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;
 ]
        });
-my $log = TestLib::slurp_file($node->logfile);
+$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");
+# 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;
+}
+       });
+
+$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\.\.\.[\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_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;
+]
+       });
+$log = TestLib::slurp_file($node->logfile);
+like($log, qr[DETAIL:  parameters: \$1 = '\{ inval\.\.\.', \$2 = '''Valame\.\.\.'],
+        "parameter report truncates");
+$log = undef;
+
+# 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
index ce93ace76c00cb3fa76bcf001e4bcc81dba30cae..2819282181678b30fdaea676f07a5c7a78249b15 100644 (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;
index 1c40709b3c90234f530732f3aa6f609f07cc310f..aeb6c8fefc2f2e30e7c86df066722d4d6bf6f8b5 100644 (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);