From 39072fa5bff8e23d4c56604d45635f835a0c78ad Mon Sep 17 00:00:00 2001 From: Jim Jones Date: Thu, 9 Jul 2026 09:25:32 +0200 Subject: [PATCH v2 1/2] Improve log_statement_max_length truncation Apply log_statement_max_length consistently when logging prepared statements. Previously, the prepared query emitted in the DETAIL message for EXECUTE was not truncated, even though the corresponding statement logged by log_statement was. Also append an ellipsis to truncated statements, so it is immediately apparent when a statement has been truncated. This also avoid scanning the entire query string when determining if truncation is needed by using strnlen() instead of strlen() in truncate_query_log(). Author: Jim Jones Co-authored-by: Fujii Masao --- doc/src/sgml/config.sgml | 6 ++- src/backend/tcop/postgres.c | 20 +++++--- src/backend/utils/misc/postgresql.conf.sample | 4 +- .../t/014_log_statement_max_length.pl | 46 ++++++++++++++----- 4 files changed, 54 insertions(+), 22 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index c67130c620e..0848c18d329 100644 --- 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 ' , , or - 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 (...) + is appended to indicate that truncation has occurred. + A value of zero causes statements to be logged as only an ellipsis. -1 (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 ce18df820cd..019e4ab42fe 100644 --- 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,7 @@ 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 +2579,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 +2610,13 @@ 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/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index 47e1221f3c3..7958653077b 100644 --- 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 b1ce6068f5d..b879566ef54 100644 --- 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,15 @@ $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 +52,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 +76,7 @@ $node->psql( SET log_statement_max_length TO 20; SELECT '123456789ABCDEF' \\bind \\g"); ok( $node->log_contains( - qr/execute : SELECT '123456789ABC$/m, $log_offset), + qr/execute : SELECT '123456789ABC\.\.\.$/m, $log_offset), "extended protocol execute truncated at 20 bytes"); # Verify extended protocol also respects -1 (no truncation; closing quote @@ -102,14 +103,35 @@ $node->psql( SET log_statement_max_length TO 20; SELECT '123456789ABCDEF' \\bind \\g"); ok( $node->log_contains( - qr/parse : SELECT '123456789ABC$/m, $log_offset), + qr/parse : SELECT '123456789ABC\.\.\.$/m, $log_offset), "parse duration entry truncated"); ok( $node->log_contains( - qr/bind : SELECT '123456789ABC$/m, $log_offset), + qr/bind : SELECT '123456789ABC\.\.\.$/m, $log_offset), "bind duration entry truncated"); ok( $node->log_contains( - qr/execute : SELECT '123456789ABC$/m, $log_offset), + qr/execute : 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(); -- 2.55.0