upstream/postgresql
1
0
Fork 0
mirror of https://github.com/postgres/postgres.git synced 2026-07-15 20:52:53 -04:00
Code Issues Projects Releases Packages Wiki Activity Actions

Improve log_statement_max_length truncation reporting

Browse source 
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
This commit is contained in:
Fujii Masao 2026-07-10 08:36:46 +09:00
parent 21e958c303
commit 999a8412bb
5 changed files with 60 additions and 24 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
doc/src/sgml/config.sgml
View file

@ -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

25
src/backend/tcop/postgres.c
View file

@ -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;
}
}

4
src/backend/utils/misc/guc_parameters.dat
View file

@ -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',

4
src/backend/utils/misc/postgresql.conf.sample
View file

@ -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;

45
src/test/modules/test_misc/t/014_log_statement_max_length.pl
View file

@ -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();