public inbox for [email protected]
help / color / mirror / Atom feedFrom: Tatsuo Ishii <[email protected]>
To: [email protected]
Cc: [email protected]
Subject: Re: Proposal: recent access based routing for primary-replica setups
Date: Mon, 24 Nov 2025 16:41:30 +0900 (JST)
Message-ID: <[email protected]> (raw)
In-Reply-To: <CACeKOO17CEiuBoV-V-ZzLPPW4yEMt6+m3y+9Ys6Ky_=fEAJZLg@mail.gmail.com>
References: <CACeKOO3kSTnAsjQMmuYFAFDG513W4KeAX=vZ7NVaFafMy9KFXQ@mail.gmail.com>
<[email protected]>
<CACeKOO17CEiuBoV-V-ZzLPPW4yEMt6+m3y+9Ys6Ky_=fEAJZLg@mail.gmail.com>
Thank you for updating the patch! This time the patch applies without
any issue and compiles fine. Unfortunately regression test failed.
testing 041.external_replication_delay...failed.
From the regression log, it seems Test7 failed.
------------------------------------------------------------------------------
=== Test7: Command timeout handling ===
waiting for server to start....411181 2025-11-24 16:31:05.244 JST LOG: redirecting log output to logging collector process
411181 2025-11-24 16:31:05.244 JST HINT: Future log output will appear in directory "log".
done
server started
waiting for server to start....411196 2025-11-24 16:31:05.352 JST LOG: redirecting log output to logging collector process
411196 2025-11-24 16:31:05.352 JST HINT: Future log output will appear in directory "log".
done
server started
waiting for server to start....411213 2025-11-24 16:31:05.461 JST LOG: redirecting log output to logging collector process
411213 2025-11-24 16:31:05.461 JST HINT: Future log output will appear in directory "log".
done
server started
Waiting for command timeout...
fail: command timeout not detected
------------------------------------------------------------------------------
Attached is the pgpool.log. If you need more info, please let me know.
Best regards,
--
Tatsuo Ishii
SRA OSS K.K.
English: http://www.sraoss.co.jp/index_en/
Japanese:http://www.sraoss.co.jp
> Hi Tatsuo,
>
> Sorry again, this was due to the separation of 2 patches and i only sent
> the one.
>
> I've merged it into 1 commit and 1 patch and rebased over master to avoid
> these issues moving forward.
>
> PFA latest version
>
> On Thu, Nov 20, 2025 at 1:09 AM Tatsuo Ishii <[email protected]> wrote:
>
>> Hi Nadav,
>>
>> Thank you for new patch.
>> Unfortunately the patch did not apply to current master.
>>
>> $ git apply
>> ~/0001-Fix-multiple-issues-in-external-replication-delay-fe.patch
>> error: patch failed: src/streaming_replication/pool_worker_child.c:694
>> error: src/streaming_replication/pool_worker_child.c: patch does not apply
>>
>> Maybe the patch is on top of your previous patch?
>>
>> Also I suggest to use "-v" option of "git format-patch" to add the
>> patch version number so that we can easily know which patch is the
>> latest.
>>
>> Best regards,
>> --
>> Tatsuo Ishii
>> SRA OSS K.K.
>> English: http://www.sraoss.co.jp/index_en/
>> Japanese:http://www.sraoss.co.jp
>>
>> > Hi Tatsuo,
>> >
>> > Please see attached an updated version.
>> >
>> > thank you
>> >
>> > On Fri, Nov 7, 2025 at 2:07 AM Tatsuo Ishii <[email protected]>
>> wrote:
>> >
>> >> > Sorry for that - thanks for the patch.
>> >> >
>> >> > Please find attached a new version
>> >>
>> >> Thanks for the new version. Unfortunately this time regression test
>> >> fails at:
>> >>
>> >> > Waiting for command timeout...
>> >> > fail: command timeout not detected
>> >>
>> >> Attached is the pgpool.log.
>> >>
>> >> Best regards,
>> >> --
>> >> Tatsuo Ishii
>> >> SRA OSS K.K.
>> >> English: http://www.sraoss.co.jp/index_en/
>> >> Japanese:http://www.sraoss.co.jp
>> >>
>> >> > On Mon, Nov 3, 2025 at 9:05 AM Tatsuo Ishii <[email protected]>
>> >> wrote:
>> >> >
>> >> >> > thanks and sorry for the issues, please find attached updated
>> version.
>> >> >>
>> >> >> No problem.
>> >> >>
>> >> >> This time the patch applies fine, no compiler warnings. However,
>> >> >> regression test did not passed here (on Ubuntu 24 LTS if this
>> >> >> matters). So I looked into
>> >> >> src/test/regression/tests/041.external_replication_delay/test.sh a
>> >> >> little bit and apply attached patch (test.sh.patch). It moved forward
>> >> >> partially but failed at:
>> >> >>
>> >> >> fail: command execution failure not detected
>> >> >>
>> >> >> Please find attached
>> >> >>
>> >>
>> src/test/regression/tests/041.external_replication_delay/testdir/pgpool.log
>> >> >> and src/test/regression/log/041.external_replication_delay.
>> >> >>
>> >> >> Best regards,
>> >> >> --
>> >> >> Tatsuo Ishii
>> >> >> SRA OSS K.K.
>> >> >> English: http://www.sraoss.co.jp/index_en/
>> >> >> Japanese:http://www.sraoss.co.jp
>> >> >>
>> >> >
>> >> >
>> >> > --
>> >> > Nadav Shatz
>> >> > Tailor Brands | CTO
>> >>
>> >
>> >
>> > --
>> > Nadav Shatz
>> > Tailor Brands | CTO
>>
>
>
> --
> Nadav Shatz
> Tailor Brands | CTO
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: num_backends: 3 total_weight: 1.000000
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: backend 0 weight: 0.000000 flag: 0000
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: backend 1 weight: 2147483647.000000 flag: 0000
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: backend 2 weight: 0.000000 flag: 0000
2025-11-24 16:31:05.543: main pid 411227: LOG: Backend status file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/pgpool_status discarded
2025-11-24 16:31:05.543: main pid 411227: DEBUG: BackendDesc: 113672 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: pool_coninfo_size: num_init_children (4) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (416) = 425984 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: ProcessInfo: num_init_children (4) * sizeof(ProcessInfo) (2152) = 8608 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: UserSignalSlot: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: POOL_REQUEST_INFO: 5272 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: stat_shared_memory_size: 9216 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.543: main pid 411227: DEBUG: SI_ManageInfo: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: memcache blocks :64
2025-11-24 16:31:05.543: main pid 411227: DEBUG: shared_memory_cache_size: 67108864
2025-11-24 16:31:05.543: main pid 411227: DEBUG: shared_memory_fsmm_size: 64
2025-11-24 16:31:05.543: main pid 411227: DEBUG: pool_hash_size: 67108880
2025-11-24 16:31:05.543: main pid 411227: DEBUG: POOL_QUERY_CACHE_STATS: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: LOG: allocating shared memory segment of size: 134793216
2025-11-24 16:31:05.668: main pid 411227: DEBUG: pool_coninfo_size: num_init_children (4) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (416) = 425984 bytes requested for shared memory
2025-11-24 16:31:05.668: main pid 411227: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.668: main pid 411227: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.668: main pid 411227: DEBUG: memcache blocks :64
2025-11-24 16:31:05.668: main pid 411227: DEBUG: shared_memory_cache_size: 67108864
2025-11-24 16:31:05.668: main pid 411227: DEBUG: memory cache request size : 67108864
2025-11-24 16:31:05.668: main pid 411227: DEBUG: shared_memory_fsmm_size: 64
2025-11-24 16:31:05.671: main pid 411227: LOG: pool_discard_oid_maps: discarded memqcache oid maps
2025-11-24 16:31:05.686: main pid 411227: LOG: create socket files[0]: /tmp/.s.PGSQL.11000
2025-11-24 16:31:05.686: main pid 411227: LOG: listen address[0]: *
2025-11-24 16:31:05.687: main pid 411227: LOG: Setting up socket for 0.0.0.0:11000
2025-11-24 16:31:05.687: main pid 411227: LOG: Setting up socket for :::11000
2025-11-24 16:31:05.687: main pid 411227: DEBUG: Spawning 4 child processes
2025-11-24 16:31:05.688: child pid 411234: DEBUG: initializing backend status
2025-11-24 16:31:05.688: child pid 411235: DEBUG: initializing backend status
2025-11-24 16:31:05.688: child pid 411236: DEBUG: initializing backend status
2025-11-24 16:31:05.688: main pid 411227: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2025-11-24 16:31:05.689: child pid 411237: DEBUG: initializing backend status
2025-11-24 16:31:05.696: main pid 411227: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.696: main pid 411227: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.696: main pid 411227: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.705: main pid 411227: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.705: main pid 411227: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.705: main pid 411227: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.714: main pid 411227: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.714: main pid 411227: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.714: main pid 411227: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.714: main pid 411227: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-24 16:31:05.714: main pid 411227: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-24 16:31:05.714: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.715: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.716: main pid 411227: DEBUG: get_server_version: backend 0 server version: 180000
2025-11-24 16:31:05.716: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.716: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.717: main pid 411227: DEBUG: get_server_version: backend 1 server version: 180000
2025-11-24 16:31:05.717: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.717: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.717: main pid 411227: DEBUG: get_server_version: backend 2 server version: 180000
2025-11-24 16:31:05.717: main pid 411227: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-24 16:31:05.717: main pid 411227: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-24 16:31:05.717: main pid 411227: DEBUG: pool_release_follow_primary_lock called
2025-11-24 16:31:05.718: main pid 411227: LOG: find_primary_node: primary node is 0
2025-11-24 16:31:05.718: main pid 411227: LOG: find_primary_node: standby node is 1
2025-11-24 16:31:05.718: main pid 411227: LOG: find_primary_node: standby node is 2
2025-11-24 16:31:05.718: main pid 411227: LOG: create socket files[0]: /tmp/.s.PGSQL.11001
2025-11-24 16:31:05.718: main pid 411227: LOG: listen address[0]: localhost
2025-11-24 16:31:05.718: main pid 411227: LOG: Setting up socket for 127.0.0.1:11001
2025-11-24 16:31:05.718: pcp_main pid 411241: DEBUG: I am PCP child with pid:411241
2025-11-24 16:31:05.719: pcp_main pid 411241: LOG: PCP process: 411241 started
2025-11-24 16:31:05.719: sr_check_worker pid 411242: LOG: process started
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG: I am 411242
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-24 16:31:05.719: health_check pid 411243: LOG: process started
2025-11-24 16:31:05.719: health_check0 pid 411243: DEBUG: I am health check process pid:411243 DB node id:0
2025-11-24 16:31:05.719: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.719: health_check pid 411244: LOG: process started
2025-11-24 16:31:05.719: health_check1 pid 411244: DEBUG: I am health check process pid:411244 DB node id:1
2025-11-24 16:31:05.719: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.719: health_check pid 411245: LOG: process started
2025-11-24 16:31:05.720: health_check2 pid 411245: DEBUG: I am health check process pid:411245 DB node id:2
2025-11-24 16:31:05.720: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check1 pid 411244: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.723: health_check1 pid 411244: DETAIL: No such file or directory
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check2 pid 411245: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.723: health_check2 pid 411245: DETAIL: No such file or directory
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.724: health_check0 pid 411243: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.724: health_check0 pid 411243: DETAIL: No such file or directory
2025-11-24 16:31:05.727: main pid 411227: LOG: pgpool-II successfully started. version 4.8devel (mitsukakeboshi)
2025-11-24 16:31:05.727: main pid 411227: LOG: node status[0]: 1
2025-11-24 16:31:05.727: main pid 411227: LOG: node status[1]: 2
2025-11-24 16:31:05.727: main pid 411227: LOG: node status[2]: 2
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: executing replication delay command: ./delay_cmd_slow.sh localhost:11003 localhost:11004
2025-11-24 16:31:05.732: sr_check_worker pid 411242: CONTEXT: while checking replication time lag
2025-11-24 16:31:06.548: child pid 411237: DEBUG: I am 411237 accept fd 7
2025-11-24 16:31:06.549: child pid 411237: DEBUG: reading startup packet
2025-11-24 16:31:06.549: child pid 411237: DETAIL: application_name: psql
2025-11-24 16:31:06.549: child pid 411237: DEBUG: reading startup packet
2025-11-24 16:31:06.549: child pid 411237: DETAIL: Protocol Major: 3 Minor: 0 database: test user: t-ishii
2025-11-24 16:31:06.549: child pid 411237: DEBUG: creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL: connecting 0 backend
2025-11-24 16:31:06.549: child pid 411237: DEBUG: creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL: connecting 1 backend
2025-11-24 16:31:06.549: child pid 411237: DEBUG: creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL: connecting 2 backend
2025-11-24 16:31:06.567: child pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: child pid 411237: DETAIL: auth kind:0
2025-11-24 16:31:06.567: child pid 411237: DEBUG: reading message length
2025-11-24 16:31:06.567: child pid 411237: DETAIL: message length (22) in slot 1 does not match with slot 0(23)
2025-11-24 16:31:06.567: child pid 411237: DEBUG: reading message length
2025-11-24 16:31:06.567: child pid 411237: DETAIL: message length (22) in slot 2 does not match with slot 0(23)
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"in_hot_standby" value:"off"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"in_hot_standby" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"in_hot_standby" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: cancel key length: 4
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: cp->info[i]:0x7e3902ddfc08 pid:411256
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: cp->info[i]:0x7e3902ddfda8 pid:411257
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: cp->info[i]:0x7e3902ddff48 pid:411258
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: sending backend key data
2025-11-24 16:31:06.570: psql pid 411237: DEBUG: selecting load balance node
2025-11-24 16:31:06.570: psql pid 411237: DETAIL: selected backend id is 1
2025-11-24 16:31:06.571: psql pid 411237: LOG: DB node id: 0 backend pid: 411256 statement: SELECT pg_catalog.version()
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: username: "t-ishii" database_name: "test"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: fetching from cache storage
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: search key "c8645f9bdf015b6b5ee4667cb578f1b3"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: fetching from cache storage
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: cache not found on shared memory
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: not hit local relation cache and query cache
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: query:SELECT pg_catalog.version()
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.version()"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.572: psql pid 411237: DEBUG: committing relation cache to cache storage
2025-11-24 16:31:06.572: psql pid 411237: DETAIL: Query="SELECT pg_catalog.version()"
2025-11-24 16:31:06.572: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.572: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.572: psql pid 411237: DETAIL: username: "t-ishii" database_name: "test"
2025-11-24 16:31:06.572: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: committing relation cache to cache storage
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: memqcache_expire = 0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache adding item
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: new item inserted. blockid: 0 itemid:0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache adding item
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: block: 0 item: 0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: SimpleQuery
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: nodes reporting
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: authenticate kind = 0
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: authenticate backend: key data received
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: authenticate kind = 0
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: authenticate backend: key data received
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: authenticate kind = 0
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: authenticate backend: key data received
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.599: psql pid 411237: DEBUG: decide where to send the query
2025-11-24 16:31:06.599: psql pid 411237: DETAIL: destination = 3 for query= "DISCARD ALL"
2025-11-24 16:31:06.599: psql pid 411237: LOG: DB node id: 0 backend pid: 411256 statement: DISCARD ALL
2025-11-24 16:31:06.599: psql pid 411237: DEBUG: waiting for query response
2025-11-24 16:31:06.599: psql pid 411237: DETAIL: waiting for backend:0 to complete the query
2025-11-24 16:31:06.600: psql pid 411237: LOG: DB node id: 1 backend pid: 411257 statement: DISCARD ALL
2025-11-24 16:31:06.600: psql pid 411237: DEBUG: waiting for query response
2025-11-24 16:31:06.600: psql pid 411237: DETAIL: waiting for backend:1 to complete the query
2025-11-24 16:31:06.600: psql pid 411237: DEBUG: setting backend connection close timer
2025-11-24 16:31:06.600: psql pid 411237: DETAIL: close time 1763969466
2025-11-24 16:31:15.724: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.724: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.724: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: authenticate kind = 0
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: authenticate backend: key data received
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check2 pid 411245: DETAIL: No such file or directory
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: authenticate kind = 0
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: authenticate backend: key data received
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: authenticate kind = 0
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: authenticate backend: key data received
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check0 pid 411243: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check0 pid 411243: DETAIL: No such file or directory
2025-11-24 16:31:15.729: health_check1 pid 411244: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check1 pid 411244: DETAIL: No such file or directory
2025-11-24 16:31:20.738: sr_check_worker pid 411242: LOG: Replication of node: 1 is behind 0.025 second(s) from the primary server (node: 0) [external command]
2025-11-24 16:31:20.738: sr_check_worker pid 411242: CONTEXT: while checking replication time lag
2025-11-24 16:31:20.738: sr_check_worker pid 411242: LOG: Replication of node: 2 is behind 0.050 second(s) from the primary server (node: 0) [external command]
2025-11-24 16:31:20.738: sr_check_worker pid 411242: CONTEXT: while checking replication time lag
2025-11-24 16:31:20.738: sr_check_worker pid 411242: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.740: sr_check_worker pid 411242: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.741: sr_check_worker pid 411242: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: node status[0]: 1
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: node status[1]: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: node status[2]: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: pool_release_follow_primary_lock called
2025-11-24 16:31:21.696: main pid 411227: LOG: exit handler called (signal: 2)
2025-11-24 16:31:21.696: main pid 411227: LOG: shutting down by signal 2
2025-11-24 16:31:21.696: main pid 411227: LOG: terminating all child processes
2025-11-24 16:31:21.699: main pid 411227: LOG: Pgpool-II system is shutdown
Attachments:
[text/plain] pgpool.log (32.0K, 2-pgpool.log)
download | inline:
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: num_backends: 3 total_weight: 1.000000
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: backend 0 weight: 0.000000 flag: 0000
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: backend 1 weight: 2147483647.000000 flag: 0000
2025-11-24 16:31:05.537: main pid 411227: DEBUG: initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL: backend 2 weight: 0.000000 flag: 0000
2025-11-24 16:31:05.543: main pid 411227: LOG: Backend status file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/pgpool_status discarded
2025-11-24 16:31:05.543: main pid 411227: DEBUG: BackendDesc: 113672 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: pool_coninfo_size: num_init_children (4) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (416) = 425984 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: ProcessInfo: num_init_children (4) * sizeof(ProcessInfo) (2152) = 8608 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: UserSignalSlot: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: POOL_REQUEST_INFO: 5272 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: stat_shared_memory_size: 9216 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.543: main pid 411227: DEBUG: SI_ManageInfo: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG: memcache blocks :64
2025-11-24 16:31:05.543: main pid 411227: DEBUG: shared_memory_cache_size: 67108864
2025-11-24 16:31:05.543: main pid 411227: DEBUG: shared_memory_fsmm_size: 64
2025-11-24 16:31:05.543: main pid 411227: DEBUG: pool_hash_size: 67108880
2025-11-24 16:31:05.543: main pid 411227: DEBUG: POOL_QUERY_CACHE_STATS: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: LOG: allocating shared memory segment of size: 134793216
2025-11-24 16:31:05.668: main pid 411227: DEBUG: pool_coninfo_size: num_init_children (4) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (416) = 425984 bytes requested for shared memory
2025-11-24 16:31:05.668: main pid 411227: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.668: main pid 411227: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.668: main pid 411227: DEBUG: memcache blocks :64
2025-11-24 16:31:05.668: main pid 411227: DEBUG: shared_memory_cache_size: 67108864
2025-11-24 16:31:05.668: main pid 411227: DEBUG: memory cache request size : 67108864
2025-11-24 16:31:05.668: main pid 411227: DEBUG: shared_memory_fsmm_size: 64
2025-11-24 16:31:05.671: main pid 411227: LOG: pool_discard_oid_maps: discarded memqcache oid maps
2025-11-24 16:31:05.686: main pid 411227: LOG: create socket files[0]: /tmp/.s.PGSQL.11000
2025-11-24 16:31:05.686: main pid 411227: LOG: listen address[0]: *
2025-11-24 16:31:05.687: main pid 411227: LOG: Setting up socket for 0.0.0.0:11000
2025-11-24 16:31:05.687: main pid 411227: LOG: Setting up socket for :::11000
2025-11-24 16:31:05.687: main pid 411227: DEBUG: Spawning 4 child processes
2025-11-24 16:31:05.688: child pid 411234: DEBUG: initializing backend status
2025-11-24 16:31:05.688: child pid 411235: DEBUG: initializing backend status
2025-11-24 16:31:05.688: child pid 411236: DEBUG: initializing backend status
2025-11-24 16:31:05.688: main pid 411227: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2025-11-24 16:31:05.689: child pid 411237: DEBUG: initializing backend status
2025-11-24 16:31:05.696: main pid 411227: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.696: main pid 411227: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.696: main pid 411227: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.705: main pid 411227: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.705: main pid 411227: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.705: main pid 411227: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.714: main pid 411227: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.714: main pid 411227: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.714: main pid 411227: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.714: main pid 411227: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-24 16:31:05.714: main pid 411227: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-24 16:31:05.714: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.715: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.716: main pid 411227: DEBUG: get_server_version: backend 0 server version: 180000
2025-11-24 16:31:05.716: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.716: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.717: main pid 411227: DEBUG: get_server_version: backend 1 server version: 180000
2025-11-24 16:31:05.717: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.717: main pid 411227: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.717: main pid 411227: DEBUG: get_server_version: backend 2 server version: 180000
2025-11-24 16:31:05.717: main pid 411227: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-24 16:31:05.717: main pid 411227: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-24 16:31:05.717: main pid 411227: DEBUG: pool_release_follow_primary_lock called
2025-11-24 16:31:05.718: main pid 411227: LOG: find_primary_node: primary node is 0
2025-11-24 16:31:05.718: main pid 411227: LOG: find_primary_node: standby node is 1
2025-11-24 16:31:05.718: main pid 411227: LOG: find_primary_node: standby node is 2
2025-11-24 16:31:05.718: main pid 411227: LOG: create socket files[0]: /tmp/.s.PGSQL.11001
2025-11-24 16:31:05.718: main pid 411227: LOG: listen address[0]: localhost
2025-11-24 16:31:05.718: main pid 411227: LOG: Setting up socket for 127.0.0.1:11001
2025-11-24 16:31:05.718: pcp_main pid 411241: DEBUG: I am PCP child with pid:411241
2025-11-24 16:31:05.719: pcp_main pid 411241: LOG: PCP process: 411241 started
2025-11-24 16:31:05.719: sr_check_worker pid 411242: LOG: process started
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG: I am 411242
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-24 16:31:05.719: health_check pid 411243: LOG: process started
2025-11-24 16:31:05.719: health_check0 pid 411243: DEBUG: I am health check process pid:411243 DB node id:0
2025-11-24 16:31:05.719: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.719: health_check pid 411244: LOG: process started
2025-11-24 16:31:05.719: health_check1 pid 411244: DEBUG: I am health check process pid:411244 DB node id:1
2025-11-24 16:31:05.719: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.719: health_check pid 411245: LOG: process started
2025-11-24 16:31:05.720: health_check2 pid 411245: DEBUG: I am health check process pid:411245 DB node id:2
2025-11-24 16:31:05.720: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check1 pid 411244: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.723: health_check1 pid 411244: DETAIL: No such file or directory
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.723: health_check2 pid 411245: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.723: health_check2 pid 411245: DETAIL: No such file or directory
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:05.724: health_check0 pid 411243: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.724: health_check0 pid 411243: DETAIL: No such file or directory
2025-11-24 16:31:05.727: main pid 411227: LOG: pgpool-II successfully started. version 4.8devel (mitsukakeboshi)
2025-11-24 16:31:05.727: main pid 411227: LOG: node status[0]: 1
2025-11-24 16:31:05.727: main pid 411227: LOG: node status[1]: 2
2025-11-24 16:31:05.727: main pid 411227: LOG: node status[2]: 2
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: authenticate kind = 0
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: authenticate backend: key data received
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG: executing replication delay command: ./delay_cmd_slow.sh localhost:11003 localhost:11004
2025-11-24 16:31:05.732: sr_check_worker pid 411242: CONTEXT: while checking replication time lag
2025-11-24 16:31:06.548: child pid 411237: DEBUG: I am 411237 accept fd 7
2025-11-24 16:31:06.549: child pid 411237: DEBUG: reading startup packet
2025-11-24 16:31:06.549: child pid 411237: DETAIL: application_name: psql
2025-11-24 16:31:06.549: child pid 411237: DEBUG: reading startup packet
2025-11-24 16:31:06.549: child pid 411237: DETAIL: Protocol Major: 3 Minor: 0 database: test user: t-ishii
2025-11-24 16:31:06.549: child pid 411237: DEBUG: creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL: connecting 0 backend
2025-11-24 16:31:06.549: child pid 411237: DEBUG: creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL: connecting 1 backend
2025-11-24 16:31:06.549: child pid 411237: DEBUG: creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL: connecting 2 backend
2025-11-24 16:31:06.567: child pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: child pid 411237: DETAIL: auth kind:0
2025-11-24 16:31:06.567: child pid 411237: DEBUG: reading message length
2025-11-24 16:31:06.567: child pid 411237: DETAIL: message length (22) in slot 1 does not match with slot 0(23)
2025-11-24 16:31:06.567: child pid 411237: DEBUG: reading message length
2025-11-24 16:31:06.567: child pid 411237: DETAIL: message length (22) in slot 2 does not match with slot 0(23)
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"in_hot_standby" value:"off"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"in_hot_standby" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"in_hot_standby" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:1 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:2 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL: backend:0 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:0 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:1 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: backend:2 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: cancel key length: 4
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: cp->info[i]:0x7e3902ddfc08 pid:411256
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: cp->info[i]:0x7e3902ddfda8 pid:411257
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL: cp->info[i]:0x7e3902ddff48 pid:411258
2025-11-24 16:31:06.567: psql pid 411237: DEBUG: sending backend key data
2025-11-24 16:31:06.570: psql pid 411237: DEBUG: selecting load balance node
2025-11-24 16:31:06.570: psql pid 411237: DETAIL: selected backend id is 1
2025-11-24 16:31:06.571: psql pid 411237: LOG: DB node id: 0 backend pid: 411256 statement: SELECT pg_catalog.version()
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: username: "t-ishii" database_name: "test"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: fetching from cache storage
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: search key "c8645f9bdf015b6b5ee4667cb578f1b3"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: fetching from cache storage
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: cache not found on shared memory
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: not hit local relation cache and query cache
2025-11-24 16:31:06.571: psql pid 411237: DETAIL: query:SELECT pg_catalog.version()
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.version()"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.572: psql pid 411237: DEBUG: committing relation cache to cache storage
2025-11-24 16:31:06.572: psql pid 411237: DETAIL: Query="SELECT pg_catalog.version()"
2025-11-24 16:31:06.572: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.572: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.572: psql pid 411237: DETAIL: username: "t-ishii" database_name: "test"
2025-11-24 16:31:06.572: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache encode key
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: committing relation cache to cache storage
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: memqcache_expire = 0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache adding item
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: new item inserted. blockid: 0 itemid:0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: memcache adding item
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: block: 0 item: 0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT: while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG: SimpleQuery
2025-11-24 16:31:06.573: psql pid 411237: DETAIL: nodes reporting
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: authenticate kind = 0
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: authenticate backend: key data received
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:06.582: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: authenticate kind = 0
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: authenticate backend: key data received
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:06.591: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: authenticate kind = 0
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: authenticate backend: key data received
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:06.598: psql pid 411237: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.599: psql pid 411237: DEBUG: decide where to send the query
2025-11-24 16:31:06.599: psql pid 411237: DETAIL: destination = 3 for query= "DISCARD ALL"
2025-11-24 16:31:06.599: psql pid 411237: LOG: DB node id: 0 backend pid: 411256 statement: DISCARD ALL
2025-11-24 16:31:06.599: psql pid 411237: DEBUG: waiting for query response
2025-11-24 16:31:06.599: psql pid 411237: DETAIL: waiting for backend:0 to complete the query
2025-11-24 16:31:06.600: psql pid 411237: LOG: DB node id: 1 backend pid: 411257 statement: DISCARD ALL
2025-11-24 16:31:06.600: psql pid 411237: DEBUG: waiting for query response
2025-11-24 16:31:06.600: psql pid 411237: DETAIL: waiting for backend:1 to complete the query
2025-11-24 16:31:06.600: psql pid 411237: DEBUG: setting backend connection close timer
2025-11-24 16:31:06.600: psql pid 411237: DETAIL: close time 1763969466
2025-11-24 16:31:15.724: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.724: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.724: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: authenticate kind = 0
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: authenticate backend: key data received
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check2 pid 411245: DETAIL: No such file or directory
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: authenticate kind = 0
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: authenticate backend: key data received
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: authenticate kind = 0
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: authenticate backend: key data received
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG: health check: clearing alarm
2025-11-24 16:31:15.729: health_check0 pid 411243: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check0 pid 411243: DETAIL: No such file or directory
2025-11-24 16:31:15.729: health_check1 pid 411244: WARNING: check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check1 pid 411244: DETAIL: No such file or directory
2025-11-24 16:31:20.738: sr_check_worker pid 411242: LOG: Replication of node: 1 is behind 0.025 second(s) from the primary server (node: 0) [external command]
2025-11-24 16:31:20.738: sr_check_worker pid 411242: CONTEXT: while checking replication time lag
2025-11-24 16:31:20.738: sr_check_worker pid 411242: LOG: Replication of node: 2 is behind 0.050 second(s) from the primary server (node: 0) [external command]
2025-11-24 16:31:20.738: sr_check_worker pid 411242: CONTEXT: while checking replication time lag
2025-11-24 16:31:20.738: sr_check_worker pid 411242: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.740: sr_check_worker pid 411242: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.741: sr_check_worker pid 411242: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: node status[0]: 1
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: node status[1]: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: node status[2]: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG: pool_release_follow_primary_lock called
2025-11-24 16:31:21.696: main pid 411227: LOG: exit handler called (signal: 2)
2025-11-24 16:31:21.696: main pid 411227: LOG: shutting down by signal 2
2025-11-24 16:31:21.696: main pid 411227: LOG: terminating all child processes
2025-11-24 16:31:21.699: main pid 411227: LOG: Pgpool-II system is shutdown
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]
Subject: Re: Proposal: recent access based routing for primary-replica setups
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