From: Fujii Masao Date: Thu, 9 Jul 2026 23:36:46 +0000 (+0900) Subject: Improve log_statement_max_length truncation reporting X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=999a8412bbabec4811195fee7e315c282c97f694;p=thirdparty%2Fpostgresql.git 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 Reviewed-by: Fujii Masao 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 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..2d1c22c4fbd 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,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 dd799a5e70f..d421cdbde76 100644 --- 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 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..caebc84be3f 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,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 : 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 +104,33 @@ $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();