Adjust log level of logical decoding messages by context

Commit 21b018e7eab lowered some logical decoding messages from LOG to DEBUG1.
However, per discussion on pgsql-hackers, messages from background activity
(e.g., walsender or slotsync worker) should remain at LOG, as they are less
frequent and more likely to indicate issues that DBAs should notice.

For foreground SQL functions (e.g., pg_logical_slot_peek_binary_changes()),
keep these messages at DEBUG1 to avoid excessive log noise. They can still be
enabled by lowering client_min_messages or log_min_messages for the session.

This commit updates logical decoding to log these messages at LOG for
background activity and at DEBUG1 for foreground execution.

Suggested-by: Robert Haas <robertmhaas@gmail.com>
Author: Fujii Masao <masao.fujii@gmail.com>
Reviewed-by: Amit Kapila <amit.kapila16@gmail.com>
Discussion: https://postgr.es/m/CA+TgmoYsu2+YAo9eLGkDp5VP-pfQ-jOoX382vS4THKHeRTNgew@mail.gmail.com

diff --git a/src/backend/replication/logical/logical.c b/src/backend/replication/logical/logical.c
index d8e02c535582dda72cc6f18d04caebcdfdd92a48..a33a685dcc6d5adc7dd1b066895bedad9184c384 100644 (file)
--- a/src/backend/replication/logical/logical.c
+++ b/src/backend/replication/logical/logical.c
@@ -603,7 +603,7 @@ CreateDecodingContext(XLogRecPtr start_lsn,
 
        ctx->reorder->output_rewrites = ctx->options.receive_rewrites;
 
 
        ctx->reorder->output_rewrites = ctx->options.receive_rewrites;
 

-       ereport(DEBUG1,
+       ereport(LogicalDecodingLogLevel(),

                        (errmsg("starting logical decoding for slot \"%s\"",
                                        NameStr(slot->data.name)),
                         errdetail("Streaming transactions committing after %X/%08X, reading WAL from %X/%08X.",
                        (errmsg("starting logical decoding for slot \"%s\"",
                                        NameStr(slot->data.name)),
                         errdetail("Streaming transactions committing after %X/%08X, reading WAL from %X/%08X.",

diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index ffb4ab2cf2a6c719cd5f941da29113d5d31adddc..c8309b96ed45ce0e86b485d52b9b2732e111e6e9 100644 (file)
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1365,7 +1365,7 @@ SnapBuildFindSnapshot(SnapBuild *builder, XLogRecPtr lsn, xl_running_xacts *runn
                builder->state = SNAPBUILD_CONSISTENT;
                builder->next_phase_at = InvalidTransactionId;
 
                builder->state = SNAPBUILD_CONSISTENT;
                builder->next_phase_at = InvalidTransactionId;
 

-               ereport(DEBUG1,
+               ereport(LogicalDecodingLogLevel(),

                                errmsg("logical decoding found consistent point at %X/%08X",
                                           LSN_FORMAT_ARGS(lsn)),
                                errdetail("There are no running transactions."));
                                errmsg("logical decoding found consistent point at %X/%08X",
                                           LSN_FORMAT_ARGS(lsn)),
                                errdetail("There are no running transactions."));


@@ -1462,7 +1462,7 @@ SnapBuildFindSnapshot(SnapBuild *builder, XLogRecPtr lsn, xl_running_xacts *runn
                builder->state = SNAPBUILD_CONSISTENT;
                builder->next_phase_at = InvalidTransactionId;
 
                builder->state = SNAPBUILD_CONSISTENT;
                builder->next_phase_at = InvalidTransactionId;
 

-               ereport(DEBUG1,
+               ereport(LogicalDecodingLogLevel(),

                                errmsg("logical decoding found consistent point at %X/%08X",
                                           LSN_FORMAT_ARGS(lsn)),
                                errdetail("There are no old transactions anymore."));
                                errmsg("logical decoding found consistent point at %X/%08X",
                                           LSN_FORMAT_ARGS(lsn)),
                                errdetail("There are no old transactions anymore."));


@@ -1972,7 +1972,7 @@ SnapBuildRestore(SnapBuild *builder, XLogRecPtr lsn)
 
        Assert(builder->state == SNAPBUILD_CONSISTENT);
 
 
        Assert(builder->state == SNAPBUILD_CONSISTENT);
 

-       ereport(DEBUG1,
+       ereport(LogicalDecodingLogLevel(),

                        errmsg("logical decoding found consistent point at %X/%08X",
                                   LSN_FORMAT_ARGS(lsn)),
                        errdetail("Logical decoding will begin using saved snapshot."));
                        errmsg("logical decoding found consistent point at %X/%08X",
                                   LSN_FORMAT_ARGS(lsn)),
                        errdetail("Logical decoding will begin using saved snapshot."));

diff --git a/src/include/replication/logical.h b/src/include/replication/logical.h
index bc075b1674175f65d7d12a0ae833e71c782a1ba9..6e0b7628001c85e10c830a5a12e7d3f27cb216ca 100644 (file)
--- a/src/include/replication/logical.h
+++ b/src/include/replication/logical.h
@@ -154,4 +154,25 @@ extern XLogRecPtr LogicalReplicationSlotCheckPendingWal(XLogRecPtr end_of_wal,
 extern XLogRecPtr LogicalSlotAdvanceAndCheckSnapState(XLogRecPtr moveto,
                                                                                                          bool *found_consistent_snapshot);
 
 extern XLogRecPtr LogicalSlotAdvanceAndCheckSnapState(XLogRecPtr moveto,
                                                                                                          bool *found_consistent_snapshot);
 

+
+/*
+ * This macro determines the log level for messages about starting logical
+ * decoding and finding a consistent point.
+ *
+ * When logical decoding is triggered by a foreground SQL function (e.g.,
+ * pg_logical_slot_peek_binary_changes()), these messages are logged at DEBUG1
+ * to avoid excessive log noise. This is acceptable since such issues are
+ * typically less critical, and the messages can still be enabled by lowering
+ * client_min_messages or log_min_messages for the session.
+ *
+ * When the messages originate from background activity (e.g., walsender or
+ * slotsync worker), they are logged at LOG, as these events are less frequent
+ * and more likely to indicate issues that DBAs should notice by default.
+ *
+ * Note that SQL functions executed by the logical walsender are treated as
+ * background activity.
+ */
+#define LogicalDecodingLogLevel() \
+       (AmRegularBackendProcess() ? DEBUG1 : LOG)
+

 #endif
 #endif

diff --git a/src/test/recovery/t/038_save_logical_slots_shutdown.pl b/src/test/recovery/t/038_save_logical_slots_shutdown.pl
index 05aa78b4bc7e8f03fb0b9cd29a22b68b9c12682b..c0392d50460b2804f8318892f2cef7d394536c27 100644 (file)
--- a/src/test/recovery/t/038_save_logical_slots_shutdown.pl
+++ b/src/test/recovery/t/038_save_logical_slots_shutdown.pl
@@ -48,7 +48,6 @@ $node_publisher->append_conf(
        'postgresql.conf', q{
 checkpoint_timeout = 1h
 autovacuum = off
        'postgresql.conf', q{
 checkpoint_timeout = 1h
 autovacuum = off

-log_min_messages = 'debug1'

 });
 $node_publisher->start;
 
 });
 $node_publisher->start;