public inbox for [email protected]
help / color / mirror / Atom feedFrom: Jim Jones <[email protected]>
To: Fujii Masao <[email protected]>
Cc: Maxym Kharchenko <[email protected]>
Cc: Kirill Reshke <[email protected]>
Cc: Álvaro Herrera <[email protected]>
Cc: Fujii Masao <[email protected]>
Cc: Kirill Gavrilov <[email protected]>
Cc: Andrey M. Borodin <[email protected]>
Cc: Euler Taveira <[email protected]>
Cc: [email protected]
Subject: Re: Truncate logs by max_log_size
Date: Thu, 9 Jul 2026 09:41:57 +0200
Message-ID: <[email protected]> (raw)
In-Reply-To: <CAHGQGwEQgFn9UF3wG+LXszM=HMLm6nkEv-Jg2uX7M9M5VLKYkQ@mail.gmail.com>
References: <[email protected]>
<CAHGQGwEc5Dn5KFU04sDp0Kyai2Te5yTuni3QW7pc2a3=343tJQ@mail.gmail.com>
<[email protected]>
<CAHGQGwGVxV1YbtLCT+q1yHejBKjLz7L+8r3WJMW=72SDJFW27g@mail.gmail.com>
<CACsxBjB5+HLw6jJ17qR5vSg+kBb2G5ACSbd_ytZ0HvvD22JqkQ@mail.gmail.com>
<CAHGQGwFYxCVmL4Bvm61bUW+WUi+YXFHzXo9hFEoSgYT1=fU-+w@mail.gmail.com>
<[email protected]>
<[email protected]>
<[email protected]>
<CAHGQGwHJHCi=4zEyMc4GJWPC9-oQZHj+9kncxS2442V9PXGgoQ@mail.gmail.com>
<[email protected]>
<CAHGQGwFOV+7nOdfoO=kfVH=-fRA9aQE1YcHHLYty3nfQ9rQ4RA@mail.gmail.com>
<[email protected]>
<CAHGQGwHhtcMH2YY9bo=qkZWLDkN7DBiHJ0g2Xja8eb6OfVkVUA@mail.gmail.com>
<[email protected]>
<CAHGQGwEQgFn9UF3wG+LXszM=HMLm6nkEv-Jg2uX7M9M5VLKYkQ@mail.gmail.com>
Thanks for the thorough review!
On 09/07/2026 06:03, Fujii Masao wrote:
> - 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);
>
> Shouldn't truncated_stmt be freed with pfree() (when non-NULL)
> immediately after errdetail()?
Yes, I missed that one.
Fixed.
> - is truncated to at most this many bytes.
> + is truncated to at most this many bytes. When a statement is
> + truncated, an ellipsis (<literal>...</literal>) is appended to
> + indicate that truncation has occurred.
>
> Since an ellipsis is appended, the logged output can exceed the configured
> limit by three bytes. Wouldn't it be clearer to say something like
> "has its statement text truncated to at most this many bytes"?
> That makes it clear the limit applies to the statement text, not the entire
> logged message.
Agreed.
I added your suggestion.
> -ok($node->log_contains(qr/statement: SELECT '123456789ABC$/m, $log_offset),
> +ok($node->log_contains(qr/statement: SELECT '123456789ABC...$/m, $log_offset),
>
> Shouldn't the dots be escaped? As written, "..." matches any three characters.
> I think it should be "\.\.\.".
At first I also thought so, as in this context ... could mean any three
arbitrary characters, but the tests results showed a different picture,
so I thought it was not necessary. Anyway, I escaped them now in v2.
> # a 24-byte query should end at the 20th byte ('C').
>
> Since an ellipsis is now appended, isn't it better to replace this
> with "a 24-byte query should be clipped at the 20th byte ('C')
> and followed by an ellipsis."?
>
>
> # With log_statement_max_length = 20, a 24-byte query should end
> # at the 20th byte ('C').
>
> Similarly, isn't it better to replace this with
> "With log_statement_max_length = 20, a 24-byte query should be clipped
> at the 20th byte ('C'). and followed by an ellipsis."?
>> * appending ellipsis to the query to indicate truncation (docs and tests
>> also updated accordingly). A side effect of this change is that setting
>> the parameter to 0 logs an ellipsis, which is not zero in length, but is
>> arguably correct, as it indicates that the whole query has been
>> truncated - just noting.
> So, should we update the docs and comments accordingly? For example:
>
> --------------------------------------------
> - A value of zero causes statements to be logged with an empty body.
> + 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.
>
> { 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.',
>
> - #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
>
> -# Verify 0 logs an empty statement body.
> +# Verify 0 logs only an ellipsis.
> note "Zero length truncation";
>
> ok($node->log_contains(qr/statement: \.\.\.\s*$/m, $log_offset),
> - "0 logs statement body with ellipsis");
> + "0 logs only an ellipsis");
> --------------------------------------------
Comments and docs updated.
>> BTW, should I open a new CF entry for this?
> Yes, I think that's a good idea so these follow-up patches don't get forgotten.
Done: https://commitfest.postgresql.org/patch/6998/
Best, Jim
Attachments:
[text/x-patch] v2-0001-Improve-log_statement_max_length-truncation.patch (9.1K, ../[email protected]/2-v2-0001-Improve-log_statement_max_length-truncation.patch)
download | inline diff:
From 39072fa5bff8e23d4c56604d45635f835a0c78ad Mon Sep 17 00:00:00 2001
From: Jim Jones <[email protected]>
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 <[email protected]>
Co-authored-by: Fujii Masao <[email protected]>
---
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 '
<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 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 <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 +103,35 @@ $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();
--
2.55.0
[text/x-patch] v2-0002-Simplify-callers-of-truncate_query_log.patch (3.2K, ../[email protected]/3-v2-0002-Simplify-callers-of-truncate_query_log.patch)
download | inline diff:
From 4c1fb8acd321dea4830b96d1518b1ffd4474b164 Mon Sep 17 00:00:00 2001
From: Jim Jones <[email protected]>
Date: Wed, 8 Jul 2026 18:31:27 +0200
Subject: [PATCH v2 2/2] Simplify callers of truncate_query_log()
truncate_query_log() already returns NULL when query logging is disabled
or when no truncation is needed. Callers therefore do not need to check
log_statement_max_length before invoking it.
Remove the redundant checks and rely on truncate_query_log() to decide
whether a truncated copy should be returned. This is purely a code
cleanup with no behavioral change.
Author: Jim Jones <[email protected]>
---
src/backend/tcop/postgres.c | 30 ++++++------------------------
1 file changed, 6 insertions(+), 24 deletions(-)
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 019e4ab42fe..b966cb242b7 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -1085,10 +1085,7 @@ exec_simple_query(const char *query_string)
/* Log immediately if dictated by log_statement */
if (check_log_statement(parsetree_list))
{
- char *truncated_stmt = NULL;
-
- if (log_statement_max_length >= 0)
- truncated_stmt = truncate_query_log(query_string);
+ char *truncated_stmt = truncate_query_log(query_string);
ereport(LOG,
(errmsg("statement: %s",
@@ -1392,10 +1389,7 @@ exec_simple_query(const char *query_string)
break;
case 2:
{
- char *truncated_stmt = NULL;
-
- if (log_statement_max_length >= 0)
- truncated_stmt = truncate_query_log(query_string);
+ char *truncated_stmt = truncate_query_log(query_string);
ereport(LOG,
(errmsg("duration: %s ms statement: %s",
@@ -1638,10 +1632,7 @@ exec_parse_message(const char *query_string, /* string to execute */
break;
case 2:
{
- char *truncated_stmt = NULL;
-
- if (log_statement_max_length >= 0)
- truncated_stmt = truncate_query_log(query_string);
+ char *truncated_stmt = truncate_query_log(query_string);
ereport(LOG,
(errmsg("duration: %s ms parse %s: %s",
@@ -2125,10 +2116,7 @@ exec_bind_message(StringInfo input_message)
break;
case 2:
{
- char *truncated_stmt = NULL;
-
- if (log_statement_max_length >= 0)
- truncated_stmt = truncate_query_log(psrc->query_string);
+ char *truncated_stmt = truncate_query_log(psrc->query_string);
ereport(LOG,
(errmsg("duration: %s ms bind %s%s%s: %s",
@@ -2282,10 +2270,7 @@ exec_execute_message(const char *portal_name, long max_rows)
/* Log immediately if dictated by log_statement */
if (check_log_statement(portal->stmts))
{
- char *truncated_source = NULL;
-
- if (log_statement_max_length >= 0)
- truncated_source = truncate_query_log(sourceText);
+ char *truncated_source = truncate_query_log(sourceText);
ereport(LOG,
(errmsg("%s %s%s%s: %s",
@@ -2414,10 +2399,7 @@ exec_execute_message(const char *portal_name, long max_rows)
break;
case 2:
{
- char *truncated_source = NULL;
-
- if (log_statement_max_length >= 0)
- truncated_source = truncate_query_log(sourceText);
+ char *truncated_source = truncate_query_log(sourceText);
ereport(LOG,
(errmsg("duration: %s ms %s %s%s%s: %s",
--
2.55.0
view thread (15+ messages)
reply
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: [email protected]
Cc: [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected], [email protected]
Subject: Re: Truncate logs by max_log_size
In-Reply-To: <[email protected]>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox