View Issue Details

IDProjectCategoryView StatusLast Update
0000775Pgpool-IIEnhancementpublic2022-12-26 16:57
Reporterpstef Assigned Topengbo  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionopen 
Product Version4.3.3 
Target Version4.3.4Fixed in Version4.3.4 
Summary0000775: Spammed with "new IPC connection received" from watchdog
DescriptionHello,

I was recently trying to debug an issue unrelated to this email and while doing
so I noticed many entries in the Pgpool log file that looked like this:

2022-11-22 00:02:27.825: watchdog pid 50030: LOG: new IPC connection received
2022-11-22 00:02:37.836: watchdog pid 50030: LOG: new IPC connection received
...

It happens about every ten seconds - so the log file has grown to megabytes of
text now.

Yesterday I set log_min_messages to DEBUG1 (I usually use warning) and
discovered that this is coming from SR checks:

2022-11-22 22:13:30.609: watchdog pid 50030: LOG: new IPC connection received
2022-11-22 22:13:30.609: sr_check_worker pid 50172: DEBUG: watchdog status: 4
2022-11-22 22:13:30.609: sr_check_worker pid 50172: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
...

I've read src/streaming_replication/pool_worker_child.c and it seems this is a
normal mode of operation, because do_worker_child() will periodically call
wd_internal_get_watchdog_local_node_state() (interestingly, its ereport is set
at the DEBUG1 level) which calls issue_command_to_watchdog() and that, down the
call stack, calls connect() (to the watchdog_ipc_address).

I argue that since this connection is expected to happen regularly, it
shouldn't be guaranteed to be logged (LOG), but if the ereport is of any use
then perhaps it should be set to some of the debug levels, like DEBUG1:

diff --git a/src/watchdog/watchdog.c b/src/watchdog/watchdog.c
index d7001df..88046f4 100644
--- a/src/watchdog/watchdog.c
+++ b/src/watchdog/watchdog.c
@@ -3435,7 +3435,7 @@ accept_incoming_connections(fd_set *rmask, int pending_fds_count)
                {
                        MemoryContext oldCxt = MemoryContextSwitchTo(TopMemoryContext);
- ereport(LOG,
+ ereport(DEBUG1,
                                        (errmsg("new IPC connection received")));
                        g_cluster.ipc_command_socks = lappend_int(g_cluster.ipc_command_socks, fd);
                        MemoryContextSwitchTo(oldCxt);

unless I'm mistaken and the spam is caused by a misconfiguration.

Piotr
Additional InformationI have sent this to pgpool-hackers@ but never seen it in the archives or anywhere else.
TagsNo tags attached.

Activities

pengbo

2022-11-30 15:01

developer   ~0004154

Thank you for reporting this issue.

Yes. You are correct. We should change the log level to DEBUG1 because it's a normal message.

> I have sent this to pgpool-hackers@ but never seen it in the archives or anywhere else.

You need to subscribe the mailing list.

administrator

2022-12-03 22:44

administrator   ~0004158

Patch is committed: https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=1114ff000b71ea1c6113341cd10e0d0a2c4297c2

Issue History

Date Modified Username Field Change
2022-11-24 19:39 pstef New Issue
2022-11-28 11:25 pengbo Assigned To => pengbo
2022-11-28 11:25 pengbo Status new => assigned
2022-11-30 15:01 pengbo Note Added: 0004154
2022-11-30 15:01 pengbo Status assigned => feedback
2022-12-03 22:44 administrator Note Added: 0004158
2022-12-03 22:44 administrator Target Version => 4.3.4
2022-12-26 16:57 pengbo Status feedback => closed
2022-12-26 16:57 pengbo Fixed in Version => 4.3.4