[pgpool-general: 8572] Re: received degenerate backend request for node_id: 0 from pid [$pid]

[Giuseppe Sacco]

Hello,
I finally managed to collect a complete log with at debug5 level.

Il giorno mer, 30/11/2022 alle 14.56 +0900, Bo Peng ha scritto:
[...]
> I couldn't find any logs that causes the degeneration.
> If it's possible, could you change the log devel to debug5 
> and share your debug logs and pgpool.conf?

Here it is:

pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  do_query: received COMMAND COMPLETE ('C')
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_process_query.c:2173
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  do_query: kind: 'Z'
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_process_query.c:2081
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  do_query: received READY FOR QUERY ('Z')
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_process_query.c:2162
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  verify_backend_node_status: multiple standbys: 1
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pgpool_main.c:3092
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  verify_backend_node_status: detach_false_primary is off and no additional checking is performed
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pgpool_main.c:3097
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  node status[0]: 1
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_worker_child.c:215
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  node status[1]: 2
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_worker_child.c:215
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  pool_write: to backend: 0 kind:X
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_stream.c:467
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  pool_flush_it: flush size: 5
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_stream.c:650
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  pool_write: to backend: 1 kind:X
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_stream.c:467
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  pool_flush_it: flush size: 5
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pool_stream.c:650
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: DEBUG:  pool_release_follow_primary_lock called
pgpool[92410]: 2023-01-26 15:30:16.017: sr_check_worker pid 92410: LOCATION:  pgpool_main.c:4586
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: DEBUG:  pool_read: read -1 bytes from backend 0
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: LOCATION:  pool_stream.c:199
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: LOG:  received degenerate backend request for node_id: 0 from pid [134337]
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: LOCATION:  pool_internal_comms.c:145
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: LOG:  signal_user1_to_parent_with_reason(0)
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: LOCATION:  pgpool_main.c:611
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: DEBUG:  sending signal:10 to the parent process with PID:88381
pgpool[134337]: 2023-01-26 15:30:16.735: [unknown] pid 134337: LOCATION:  pool_signal.c:179
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: LOG:  Pgpool-II parent process received SIGUSR1
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: LOCATION:  pgpool_main.c:1292
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: LOG:  Pgpool-II parent process has received failover request
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: LOCATION:  pgpool_main.c:1357
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: DEBUG:  failover handler called
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: LOCATION:  pgpool_main.c:1415
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: DEBUG:  failover handler
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: DETAIL:  kind: 1 flags: 1 node_count: 1 index:2
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: LOCATION:  pgpool_main.c:1487
pgpool[88381]: 2023-01-26 15:30:16.735: main pid 88381: DEBUG:  failover handler

Of course, this is only a small excerpt. If you need more data, I should
have about 200 lines above and below this excerpt.

Thank you very much,
Giuseppe