Improve log_statement_max_length truncation reporting

log_statement_max_length limits the statement text logged by
log_statement and duration logging. However, the prepared statement
shown in the DETAIL message for EXECUTE was still logged in full,
allowing very large prepared queries to bypass the limit.

Apply the same truncation to the prepared statement text in
errdetail_execute(), making the setting behave consistently across the
main log message and its associated DETAIL output.

Also append an ellipsis to truncated statement text so users can easily
tell when truncation has occurred. With this change, a limit of zero
logs only the ellipsis, indicating that the entire statement text was
truncated.

Finally, avoid scanning the entire query string just to determine
whether truncation is needed. Use strnlen() with sufficient lookahead
for multibyte character handling, then use pg_mbcliplen() to ensure
truncation never splits a multibyte character.

Author: Jim Jones <jim.jones@uni-muenster.de>
Reviewed-by: Fujii Masao <masao.fujii@gmail.com>
Discussion: https://postgr.es/m/CAHGQGwFOV+7nOdfoO=kfVH=-fRA9aQE1YcHHLYty3nfQ9rQ4RA@mail.gmail.com

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index c67130c620e1a7ac3dbf1d2103beb0e2d3619905..0848c18d329e30f6f955a81d99aa64cebe7a6137 100644 (file)
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -8539,8 +8539,10 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         <xref linkend="guc-log-min-duration-statement"/>,
         <xref linkend="guc-log-min-duration-sample"/>, or
         <xref linkend="guc-log-transaction-sample-rate"/>
-        is truncated to at most this many bytes.
-        A value of zero causes statements to be logged with an empty body.
+        has its statement text truncated to at most this many bytes.
+        When a statement is truncated, an ellipsis (<literal>...</literal>)
+        is appended to indicate that truncation has occurred.
+        A value of zero causes statements to be logged as only an ellipsis.
         <literal>-1</literal> (the default) logs statements in full.
         If this value is specified without units, it is taken as bytes.
         This setting does not affect statements logged because of

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index ce18df820cdfbebdf3f3165ceeab132509c6cf91..2d1c22c4fbd01fe29c7691d9f2b9549d2a8a98d4 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -2553,8 +2553,9 @@ check_log_duration(char *msec_str, bool was_logged)
  * truncate_query_log
  *             Truncate query string if needed for logging
  *
- * Returns a palloc'd truncated copy if truncation is needed,
- * or NULL if no truncation is required.
+ * Returns a palloc'd copy of the query truncated for logging, with an
+ * ellipsis appended if truncation occurs, or NULL if no truncation is
+ * required.
  */
 static char *
 truncate_query_log(const char *query)
@@ -2567,7 +2568,9 @@ truncate_query_log(const char *query)
        if (!query || log_statement_max_length < 0)
                return NULL;
 
-       query_len = strlen(query);
+       query_len = strnlen(query,
+                                               (size_t) log_statement_max_length +
+                                               MAX_MULTIBYTE_CHAR_LEN);
 
        /*
         * No need to allocate a truncated copy if the query is shorter than
@@ -2578,9 +2581,10 @@ truncate_query_log(const char *query)
 
        /* Truncate at a multibyte character boundary */
        truncated_len = pg_mbcliplen(query, query_len, log_statement_max_length);
-       truncated_query = (char *) palloc(truncated_len + 1);
+       truncated_query = (char *) palloc(truncated_len + 4);
        memcpy(truncated_query, query, truncated_len);
-       truncated_query[truncated_len] = '\0';
+       memcpy(truncated_query + truncated_len, "...", 3);
+       truncated_query[truncated_len + 3] = '\0';
 
        return truncated_query;
 }
@@ -2608,7 +2612,16 @@ errdetail_execute(List *raw_parsetree_list)
                        pstmt = FetchPreparedStatement(stmt->name, false);
                        if (pstmt)
                        {
-                               errdetail("prepare: %s", pstmt->plansource->query_string);
+                               char       *truncated_stmt =
+                                       truncate_query_log(pstmt->plansource->query_string);
+
+                               errdetail("prepare: %s",
+                                                 truncated_stmt ?
+                                                 truncated_stmt : pstmt->plansource->query_string);
+
+                               if (truncated_stmt != NULL)
+                                       pfree(truncated_stmt);
+
                                return 0;
                        }
                }

diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat
index dd799a5e70f98e90a41372f0308695fe543ccbbe..d421cdbde76daf628777c6721ea644949039591e 100644 (file)
--- a/src/backend/utils/misc/guc_parameters.dat
+++ b/src/backend/utils/misc/guc_parameters.dat
@@ -1876,8 +1876,8 @@
 },
 
 { name => 'log_statement_max_length', type => 'int', context => 'PGC_SUSET', group => 'LOGGING_WHAT',
-  short_desc => 'Sets the maximum length in bytes of logged statements.',
-  long_desc => '-1 means log statement in full; 0 means log an empty statement body.',
+  short_desc => 'Sets the maximum length in bytes of logged statement text.',
+  long_desc => '-1 means log statement in full; 0 means log only an ellipsis.',
   flags => 'GUC_UNIT_BYTE',
   variable => 'log_statement_max_length',
   boot_val => '-1',

diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 47e1221f3c3bafb9ad36d15db089ddd9fdd980ca..7958653077b1676f1c61caea4551bbc158b9198a 100644 (file)
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -676,9 +676,9 @@
                                         # bind-parameter values to N bytes;
                                         # -1 means print in full, 0 disables
 #log_statement = 'none'                 # none, ddl, mod, all
-#log_statement_max_length = -1          # max bytes of logged statements;
+#log_statement_max_length = -1          # max bytes of logged statement text;
                                         # -1 means log statement in full,
-                                        # 0 means log an empty body
+                                        # 0 means log only an ellipsis
 #log_replication_commands = off
 #log_temp_files = -1                    # log temporary files equal or larger
                                         # than the specified size in kilobytes;

diff --git a/src/test/modules/test_misc/t/014_log_statement_max_length.pl b/src/test/modules/test_misc/t/014_log_statement_max_length.pl
index b1ce6068f5d4e27768b8db24e35e37a06b970239..caebc84be3f68071c109f9a634250843c554cb72 100644 (file)
--- a/src/test/modules/test_misc/t/014_log_statement_max_length.pl
+++ b/src/test/modules/test_misc/t/014_log_statement_max_length.pl
@@ -15,14 +15,16 @@ $node->init();
 $node->start;
 
 # Verify ASCII truncation. With log_statement_max_length = 20,
-# a 24-byte query should end at the 20th byte ('C').
+# a 24-byte query should be clipped at the 20th byte ('C') and
+# followed by an ellipsis.
 note "ASCII truncation via log_statement";
 my $log_offset = -s $node->logfile;
 $node->psql(
        'postgres', "
        SET log_statement_max_length TO 20;
        SELECT '123456789ABCDEF';");
-ok($node->log_contains(qr/statement: SELECT '123456789ABC$/m, $log_offset),
+ok( $node->log_contains(
+               qr/statement: SELECT '123456789ABC\.\.\.$/m, $log_offset),
        "ASCII query truncated at 20 bytes");
 
 # Verify -1 logs statement in full (closing quote must be present).
@@ -51,23 +53,23 @@ SKIP:
                SET client_encoding TO 'UTF8';
                SET log_statement_max_length TO 11;
                $mbquery");
-       ok($node->log_contains(qr/statement: SELECT 'AA$/m, $log_offset),
+       ok($node->log_contains(qr/statement: SELECT 'AA\.\.\.$/m, $log_offset),
                "multibyte truncation at character boundary");
 }
 
-# Verify 0 logs an empty statement body.
+# Verify 0 logs only an ellipsis.
 note "Zero length truncation";
 $log_offset = -s $node->logfile;
 $node->psql(
        'postgres', "
        SET log_statement_max_length TO 0;
        SELECT '123456789ABCDEF';");
-ok($node->log_contains(qr/statement:\s*$/m, $log_offset),
-       "0 logs an empty statement body");
+ok($node->log_contains(qr/statement: \.\.\.\s*$/m, $log_offset),
+       "0 logs statement body with only an ellipsis");
 
 # Verify truncation via the extended query protocol (execute message).
-# With log_statement_max_length = 20, a 24-byte query should end
-# at the 20th byte ('C').
+# With log_statement_max_length = 20, a 24-byte query should be clipped
+# at the 20th byte ('C') and followed by an ellipsis.
 note "Extended query protocol (execute) truncation";
 $log_offset = -s $node->logfile;
 $node->psql(
@@ -75,7 +77,7 @@ $node->psql(
        SET log_statement_max_length TO 20;
        SELECT '123456789ABCDEF' \\bind \\g");
 ok( $node->log_contains(
-               qr/execute <unnamed>: SELECT '123456789ABC$/m, $log_offset),
+               qr/execute <unnamed>: SELECT '123456789ABC\.\.\.$/m, $log_offset),
        "extended protocol execute truncated at 20 bytes");
 
 # Verify extended protocol also respects -1 (no truncation; closing quote
@@ -102,14 +104,33 @@ $node->psql(
        SET log_statement_max_length TO 20;
        SELECT '123456789ABCDEF' \\bind \\g");
 ok( $node->log_contains(
-               qr/parse <unnamed>: SELECT '123456789ABC$/m, $log_offset),
+               qr/parse <unnamed>: SELECT '123456789ABC\.\.\.$/m, $log_offset),
        "parse duration entry truncated");
 ok( $node->log_contains(
-               qr/bind <unnamed>: SELECT '123456789ABC$/m, $log_offset),
+               qr/bind <unnamed>: SELECT '123456789ABC\.\.\.$/m, $log_offset),
        "bind duration entry truncated");
 ok( $node->log_contains(
-               qr/execute <unnamed>: SELECT '123456789ABC$/m, $log_offset),
+               qr/execute <unnamed>: SELECT '123456789ABC\.\.\.$/m, $log_offset),
        "execute duration entry truncated");
 
+note "Truncate prepared statement query in DETAIL";
+$log_offset = -s $node->logfile;
+$node->psql(
+       'postgres', "
+       SET log_statement_max_length TO 12;
+       PREPARE stmt AS SELECT * FROM pg_hba_file_rules WHERE address = \$1;
+       EXECUTE stmt('127.0.0.1');");
+ok($node->log_contains(qr/prepare: PREPARE stmt\.\.\.$/m, $log_offset),
+       "Truncate prepared statement query in DETAIL");
+
+note "Truncate prepared statement query in DETAIL (0 length)";
+$log_offset = -s $node->logfile;
+$node->psql(
+       'postgres', "
+       SET log_statement_max_length TO 0;
+       PREPARE stmt AS SELECT * FROM pg_hba_file_rules WHERE address = \$1;
+       EXECUTE stmt('127.0.0.1');");
+ok( $node->log_contains(qr/prepare: \.\.\.$/m, $log_offset),
+       "0 logs the prepared statement body with only an ellipsis");
 $node->stop;
 done_testing();