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: Thu, 06 Nov 2025 18:24:19 +0900 (JST)
Message-ID: <[email protected]> (raw)
In-Reply-To: <CACeKOO2Xeg5nGGhwj-JUa7wgFekZtfGeCkMKLbdG1EoY4N5YSA@mail.gmail.com>
References: <CACeKOO25iz+fik4_JqZeE8VbLe=TPCCocMABQQgzcJYioaWhHA@mail.gmail.com>
<[email protected]>
<CACeKOO2Xeg5nGGhwj-JUa7wgFekZtfGeCkMKLbdG1EoY4N5YSA@mail.gmail.com>
> 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
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: num_backends: 3 total_weight: 1.000000
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: backend 0 weight: 0.000000 flag: 0000
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: backend 1 weight: 2147483647.000000 flag: 0000
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: backend 2 weight: 0.000000 flag: 0000
2025-11-06 18:19:45.737: main pid 87757: 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-06 18:19:45.737: main pid 87757: DEBUG: BackendDesc: 113672 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: 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-06 18:19:45.737: main pid 87757: DEBUG: ProcessInfo: num_init_children (4) * sizeof(ProcessInfo) (2152) = 8608 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: UserSignalSlot: 24 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: POOL_REQUEST_INFO: 5272 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: stat_shared_memory_size: 9216 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-06 18:19:45.737: main pid 87757: DEBUG: SI_ManageInfo: 24 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: memcache blocks :64
2025-11-06 18:19:45.737: main pid 87757: DEBUG: shared_memory_cache_size: 67108864
2025-11-06 18:19:45.737: main pid 87757: DEBUG: shared_memory_fsmm_size: 64
2025-11-06 18:19:45.737: main pid 87757: DEBUG: pool_hash_size: 67108880
2025-11-06 18:19:45.737: main pid 87757: DEBUG: POOL_QUERY_CACHE_STATS: 24 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: LOG: allocating shared memory segment of size: 134793216
2025-11-06 18:19:45.803: main pid 87757: 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-06 18:19:45.803: main pid 87757: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-06 18:19:45.803: main pid 87757: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-06 18:19:45.803: main pid 87757: DEBUG: memcache blocks :64
2025-11-06 18:19:45.803: main pid 87757: DEBUG: shared_memory_cache_size: 67108864
2025-11-06 18:19:45.803: main pid 87757: DEBUG: memory cache request size : 67108864
2025-11-06 18:19:45.803: main pid 87757: DEBUG: shared_memory_fsmm_size: 64
2025-11-06 18:19:45.805: main pid 87757: LOG: pool_discard_oid_maps: discarded memqcache oid maps
2025-11-06 18:19:45.812: main pid 87757: LOG: create socket files[0]: /tmp/.s.PGSQL.11000
2025-11-06 18:19:45.812: main pid 87757: LOG: listen address[0]: *
2025-11-06 18:19:45.813: main pid 87757: LOG: Setting up socket for 0.0.0.0:11000
2025-11-06 18:19:45.813: main pid 87757: LOG: Setting up socket for :::11000
2025-11-06 18:19:45.813: main pid 87757: DEBUG: Spawning 4 child processes
2025-11-06 18:19:45.813: child pid 87764: DEBUG: initializing backend status
2025-11-06 18:19:45.813: child pid 87765: DEBUG: initializing backend status
2025-11-06 18:19:45.814: main pid 87757: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2025-11-06 18:19:45.814: child pid 87766: DEBUG: initializing backend status
2025-11-06 18:19:45.814: child pid 87767: DEBUG: initializing backend status
2025-11-06 18:19:45.819: main pid 87757: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.819: main pid 87757: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.819: main pid 87757: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.823: main pid 87757: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.823: main pid 87757: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.823: main pid 87757: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.826: main pid 87757: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.826: main pid 87757: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.826: main pid 87757: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.826: main pid 87757: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-06 18:19:45.826: main pid 87757: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-06 18:19:45.826: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:45.826: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-06 18:19:45.826: main pid 87757: DEBUG: get_server_version: backend 0 server version: 180000
2025-11-06 18:19:45.826: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: get_server_version: backend 1 server version: 180000
2025-11-06 18:19:45.827: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: get_server_version: backend 2 server version: 180000
2025-11-06 18:19:45.827: main pid 87757: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-06 18:19:45.827: main pid 87757: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-06 18:19:45.827: main pid 87757: DEBUG: pool_release_follow_primary_lock called
2025-11-06 18:19:45.827: main pid 87757: LOG: find_primary_node: primary node is 0
2025-11-06 18:19:45.827: main pid 87757: LOG: find_primary_node: standby node is 1
2025-11-06 18:19:45.827: main pid 87757: LOG: find_primary_node: standby node is 2
2025-11-06 18:19:45.827: main pid 87757: LOG: create socket files[0]: /tmp/.s.PGSQL.11001
2025-11-06 18:19:45.827: main pid 87757: LOG: listen address[0]: localhost
2025-11-06 18:19:45.827: main pid 87757: LOG: Setting up socket for 127.0.0.1:11001
2025-11-06 18:19:45.827: pcp_main pid 87771: DEBUG: I am PCP child with pid:87771
2025-11-06 18:19:45.828: pcp_main pid 87771: LOG: PCP process: 87771 started
2025-11-06 18:19:45.828: sr_check_worker pid 87772: LOG: process started
2025-11-06 18:19:45.828: sr_check_worker pid 87772: DEBUG: I am 87772
2025-11-06 18:19:45.828: sr_check_worker pid 87772: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-06 18:19:45.828: sr_check_worker pid 87772: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-06 18:19:45.828: health_check pid 87773: LOG: process started
2025-11-06 18:19:45.828: health_check0 pid 87773: DEBUG: I am health check process pid:87773 DB node id:0
2025-11-06 18:19:45.828: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.828: health_check pid 87774: LOG: process started
2025-11-06 18:19:45.828: health_check1 pid 87774: DEBUG: I am health check process pid:87774 DB node id:1
2025-11-06 18:19:45.828: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.828: health_check pid 87775: LOG: process started
2025-11-06 18:19:45.828: health_check2 pid 87775: DEBUG: I am health check process pid:87775 DB node id:2
2025-11-06 18:19:45.828: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.829: health_check1 pid 87774: 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-06 18:19:45.829: health_check1 pid 87774: DETAIL: No such file or directory
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check0 pid 87773: 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-06 18:19:45.830: health_check0 pid 87773: DETAIL: No such file or directory
2025-11-06 18:19:45.830: sr_check_worker pid 87772: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.830: sr_check_worker pid 87772: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.830: sr_check_worker pid 87772: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check2 pid 87775: 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-06 18:19:45.830: health_check2 pid 87775: DETAIL: No such file or directory
2025-11-06 18:19:45.831: sr_check_worker pid 87772: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.831: sr_check_worker pid 87772: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.831: sr_check_worker pid 87772: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: executing replication delay command: ./delay_cmd_slow.sh localhost:11003 localhost:11004
2025-11-06 18:19:45.832: sr_check_worker pid 87772: CONTEXT: while checking replication time lag
2025-11-06 18:19:45.834: main pid 87757: LOG: pgpool-II successfully started. version 4.7devel (tasukiboshi)
2025-11-06 18:19:45.835: main pid 87757: LOG: node status[0]: 1
2025-11-06 18:19:45.835: main pid 87757: LOG: node status[1]: 2
2025-11-06 18:19:45.835: main pid 87757: LOG: node status[2]: 2
2025-11-06 18:19:46.735: child pid 87766: DEBUG: I am 87766 accept fd 7
2025-11-06 18:19:46.735: child pid 87766: DEBUG: reading startup packet
2025-11-06 18:19:46.735: child pid 87766: DETAIL: application_name: psql
2025-11-06 18:19:46.735: child pid 87766: DEBUG: reading startup packet
2025-11-06 18:19:46.735: child pid 87766: DETAIL: Protocol Major: 3 Minor: 0 database: test user: t-ishii
2025-11-06 18:19:46.735: child pid 87766: DEBUG: creating new connection to backend
2025-11-06 18:19:46.735: child pid 87766: DETAIL: connecting 0 backend
2025-11-06 18:19:46.735: child pid 87766: DEBUG: creating new connection to backend
2025-11-06 18:19:46.735: child pid 87766: DETAIL: connecting 1 backend
2025-11-06 18:19:46.735: child pid 87766: DEBUG: creating new connection to backend
2025-11-06 18:19:46.735: child pid 87766: DETAIL: connecting 2 backend
2025-11-06 18:19:46.751: child pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.751: child pid 87766: DETAIL: auth kind:0
2025-11-06 18:19:46.751: child pid 87766: DEBUG: reading message length
2025-11-06 18:19:46.751: child pid 87766: DETAIL: message length (22) in slot 1 does not match with slot 0(23)
2025-11-06 18:19:46.751: child pid 87766: DEBUG: reading message length
2025-11-06 18:19:46.751: child pid 87766: DETAIL: message length (22) in slot 2 does not match with slot 0(23)
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"in_hot_standby" value:"off"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:1 name:"in_hot_standby" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:2 name:"in_hot_standby" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"integer_datetimes" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:1 name:"integer_datetimes" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:2 name:"integer_datetimes" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"TimeZone" value:"Asia/Tokyo"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:1 name:"TimeZone" value:"Asia/Tokyo"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:2 name:"TimeZone" value:"Asia/Tokyo"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"IntervalStyle" value:"postgres"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:1 name:"IntervalStyle" value:"postgres"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:2 name:"IntervalStyle" value:"postgres"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:0 name:"search_path" value:""$user", public"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:1 name:"search_path" value:""$user", public"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:2 name:"search_path" value:""$user", public"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:0 name:"is_superuser" value:"on"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:1 name:"is_superuser" value:"on"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:2 name:"is_superuser" value:"on"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:0 name:"application_name" value:"psql"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"application_name" value:"psql"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"application_name" value:"psql"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"default_transaction_read_only" value:"off"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"default_transaction_read_only" value:"off"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"default_transaction_read_only" value:"off"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"scram_iterations" value:"4096"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"scram_iterations" value:"4096"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"scram_iterations" value:"4096"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"DateStyle" value:"ISO, MDY"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"DateStyle" value:"ISO, MDY"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"DateStyle" value:"ISO, MDY"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"standard_conforming_strings" value:"on"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"standard_conforming_strings" value:"on"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"standard_conforming_strings" value:"on"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"session_authorization" value:"t-ishii"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"session_authorization" value:"t-ishii"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"session_authorization" value:"t-ishii"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"client_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"client_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"client_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"server_version" value:"18.0"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"server_version" value:"18.0"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"server_version" value:"18.0"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"server_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"server_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"server_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: cancel key length: 4
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: cp->info[i]:0x726410677c08 pid:87787
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: cp->info[i]:0x726410677da8 pid:87786
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: cp->info[i]:0x726410677f48 pid:87788
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: sending backend key data
2025-11-06 18:19:46.755: psql pid 87766: DEBUG: selecting load balance node
2025-11-06 18:19:46.755: psql pid 87766: DETAIL: selected backend id is 1
2025-11-06 18:19:46.756: psql pid 87766: LOG: DB node id: 0 backend pid: 87787 statement: SELECT pg_catalog.version()
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: username: "t-ishii" database_name: "test"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: fetching from cache storage
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: search key "c8645f9bdf015b6b5ee4667cb578f1b3"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: fetching from cache storage
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: cache not found on shared memory
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: not hit local relation cache and query cache
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: query:SELECT pg_catalog.version()
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.version()"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: committing relation cache to cache storage
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: Query="SELECT pg_catalog.version()"
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: username: "t-ishii" database_name: "test"
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: committing relation cache to cache storage
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: memqcache_expire = 0
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.758: psql pid 87766: DEBUG: memcache adding item
2025-11-06 18:19:46.758: psql pid 87766: DETAIL: new item inserted. blockid: 0 itemid:0
2025-11-06 18:19:46.758: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.758: psql pid 87766: DEBUG: memcache adding item
2025-11-06 18:19:46.758: psql pid 87766: DETAIL: block: 0 item: 0
2025-11-06 18:19:46.758: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.758: psql pid 87766: DEBUG: SimpleQuery
2025-11-06 18:19:46.758: psql pid 87766: DETAIL: nodes reporting
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: authenticate kind = 0
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: authenticate backend: key data received
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: authenticate kind = 0
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: authenticate backend: key data received
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: authenticate kind = 0
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: authenticate backend: key data received
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: decide where to send the query
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: destination = 3 for query= "DISCARD ALL"
2025-11-06 18:19:46.768: psql pid 87766: LOG: DB node id: 0 backend pid: 87787 statement: DISCARD ALL
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: waiting for query response
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: waiting for backend:0 to complete the query
2025-11-06 18:19:46.768: psql pid 87766: LOG: DB node id: 1 backend pid: 87786 statement: DISCARD ALL
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: waiting for query response
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: waiting for backend:1 to complete the query
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: setting backend connection close timer
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: close time 1762420786
2025-11-06 18:19:55.830: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.830: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.830: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: authenticate kind = 0
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: authenticate backend: key data received
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check1 pid 87774: 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-06 18:19:55.831: health_check1 pid 87774: DETAIL: No such file or directory
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: authenticate kind = 0
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: authenticate backend: key data received
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.832: health_check0 pid 87773: 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-06 18:19:55.832: health_check0 pid 87773: DETAIL: No such file or directory
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: authenticate kind = 0
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: authenticate backend: key data received
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.832: health_check2 pid 87775: 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-06 18:19:55.832: health_check2 pid 87775: DETAIL: No such file or directory
2025-11-06 18:20:00.835: sr_check_worker pid 87772: LOG: Replication of node: 1 is behind 0.025 second(s) from the primary server (node: 0) [external command]
2025-11-06 18:20:00.835: sr_check_worker pid 87772: CONTEXT: while checking replication time lag
2025-11-06 18:20:00.835: sr_check_worker pid 87772: LOG: Replication of node: 2 is behind 0.050 second(s) from the primary server (node: 0) [external command]
2025-11-06 18:20:00.835: sr_check_worker pid 87772: CONTEXT: while checking replication time lag
2025-11-06 18:20:00.835: sr_check_worker pid 87772: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:20:00.835: sr_check_worker pid 87772: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: node status[0]: 1
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: node status[1]: 2
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: node status[2]: 2
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: pool_release_follow_primary_lock called
2025-11-06 18:20:01.810: main pid 87757: LOG: exit handler called (signal: 2)
2025-11-06 18:20:01.810: main pid 87757: LOG: shutting down by signal 2
2025-11-06 18:20:01.810: main pid 87757: LOG: terminating all child processes
2025-11-06 18:20:01.813: main pid 87757: LOG: Pgpool-II system is shutdown
Attachments:
[text/plain] pgpool.log (31.6K, 2-pgpool.log)
download | inline:
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: num_backends: 3 total_weight: 1.000000
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: backend 0 weight: 0.000000 flag: 0000
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: backend 1 weight: 2147483647.000000 flag: 0000
2025-11-06 18:19:45.730: main pid 87757: DEBUG: initializing pool configuration
2025-11-06 18:19:45.730: main pid 87757: DETAIL: backend 2 weight: 0.000000 flag: 0000
2025-11-06 18:19:45.737: main pid 87757: 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-06 18:19:45.737: main pid 87757: DEBUG: BackendDesc: 113672 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: 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-06 18:19:45.737: main pid 87757: DEBUG: ProcessInfo: num_init_children (4) * sizeof(ProcessInfo) (2152) = 8608 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: UserSignalSlot: 24 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: POOL_REQUEST_INFO: 5272 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: stat_shared_memory_size: 9216 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-06 18:19:45.737: main pid 87757: DEBUG: SI_ManageInfo: 24 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: DEBUG: memcache blocks :64
2025-11-06 18:19:45.737: main pid 87757: DEBUG: shared_memory_cache_size: 67108864
2025-11-06 18:19:45.737: main pid 87757: DEBUG: shared_memory_fsmm_size: 64
2025-11-06 18:19:45.737: main pid 87757: DEBUG: pool_hash_size: 67108880
2025-11-06 18:19:45.737: main pid 87757: DEBUG: POOL_QUERY_CACHE_STATS: 24 bytes requested for shared memory
2025-11-06 18:19:45.737: main pid 87757: LOG: allocating shared memory segment of size: 134793216
2025-11-06 18:19:45.803: main pid 87757: 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-06 18:19:45.803: main pid 87757: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-06 18:19:45.803: main pid 87757: DEBUG: health_check_stats_shared_memory_size: requested size: 12288
2025-11-06 18:19:45.803: main pid 87757: DEBUG: memcache blocks :64
2025-11-06 18:19:45.803: main pid 87757: DEBUG: shared_memory_cache_size: 67108864
2025-11-06 18:19:45.803: main pid 87757: DEBUG: memory cache request size : 67108864
2025-11-06 18:19:45.803: main pid 87757: DEBUG: shared_memory_fsmm_size: 64
2025-11-06 18:19:45.805: main pid 87757: LOG: pool_discard_oid_maps: discarded memqcache oid maps
2025-11-06 18:19:45.812: main pid 87757: LOG: create socket files[0]: /tmp/.s.PGSQL.11000
2025-11-06 18:19:45.812: main pid 87757: LOG: listen address[0]: *
2025-11-06 18:19:45.813: main pid 87757: LOG: Setting up socket for 0.0.0.0:11000
2025-11-06 18:19:45.813: main pid 87757: LOG: Setting up socket for :::11000
2025-11-06 18:19:45.813: main pid 87757: DEBUG: Spawning 4 child processes
2025-11-06 18:19:45.813: child pid 87764: DEBUG: initializing backend status
2025-11-06 18:19:45.813: child pid 87765: DEBUG: initializing backend status
2025-11-06 18:19:45.814: main pid 87757: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2025-11-06 18:19:45.814: child pid 87766: DEBUG: initializing backend status
2025-11-06 18:19:45.814: child pid 87767: DEBUG: initializing backend status
2025-11-06 18:19:45.819: main pid 87757: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.819: main pid 87757: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.819: main pid 87757: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.823: main pid 87757: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.823: main pid 87757: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.823: main pid 87757: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.826: main pid 87757: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.826: main pid 87757: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.826: main pid 87757: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.826: main pid 87757: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-06 18:19:45.826: main pid 87757: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-06 18:19:45.826: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:45.826: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-06 18:19:45.826: main pid 87757: DEBUG: get_server_version: backend 0 server version: 180000
2025-11-06 18:19:45.826: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: get_server_version: backend 1 server version: 180000
2025-11-06 18:19:45.827: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-06 18:19:45.827: main pid 87757: DEBUG: get_server_version: backend 2 server version: 180000
2025-11-06 18:19:45.827: main pid 87757: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-06 18:19:45.827: main pid 87757: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-06 18:19:45.827: main pid 87757: DEBUG: pool_release_follow_primary_lock called
2025-11-06 18:19:45.827: main pid 87757: LOG: find_primary_node: primary node is 0
2025-11-06 18:19:45.827: main pid 87757: LOG: find_primary_node: standby node is 1
2025-11-06 18:19:45.827: main pid 87757: LOG: find_primary_node: standby node is 2
2025-11-06 18:19:45.827: main pid 87757: LOG: create socket files[0]: /tmp/.s.PGSQL.11001
2025-11-06 18:19:45.827: main pid 87757: LOG: listen address[0]: localhost
2025-11-06 18:19:45.827: main pid 87757: LOG: Setting up socket for 127.0.0.1:11001
2025-11-06 18:19:45.827: pcp_main pid 87771: DEBUG: I am PCP child with pid:87771
2025-11-06 18:19:45.828: pcp_main pid 87771: LOG: PCP process: 87771 started
2025-11-06 18:19:45.828: sr_check_worker pid 87772: LOG: process started
2025-11-06 18:19:45.828: sr_check_worker pid 87772: DEBUG: I am 87772
2025-11-06 18:19:45.828: sr_check_worker pid 87772: DEBUG: pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-06 18:19:45.828: sr_check_worker pid 87772: DEBUG: pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-06 18:19:45.828: health_check pid 87773: LOG: process started
2025-11-06 18:19:45.828: health_check0 pid 87773: DEBUG: I am health check process pid:87773 DB node id:0
2025-11-06 18:19:45.828: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.828: health_check pid 87774: LOG: process started
2025-11-06 18:19:45.828: health_check1 pid 87774: DEBUG: I am health check process pid:87774 DB node id:1
2025-11-06 18:19:45.828: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.828: health_check pid 87775: LOG: process started
2025-11-06 18:19:45.828: health_check2 pid 87775: DEBUG: I am health check process pid:87775 DB node id:2
2025-11-06 18:19:45.828: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.829: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.829: health_check1 pid 87774: 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-06 18:19:45.829: health_check1 pid 87774: DETAIL: No such file or directory
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check0 pid 87773: 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-06 18:19:45.830: health_check0 pid 87773: DETAIL: No such file or directory
2025-11-06 18:19:45.830: sr_check_worker pid 87772: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.830: sr_check_worker pid 87772: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.830: sr_check_worker pid 87772: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:45.830: health_check2 pid 87775: 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-06 18:19:45.830: health_check2 pid 87775: DETAIL: No such file or directory
2025-11-06 18:19:45.831: sr_check_worker pid 87772: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.831: sr_check_worker pid 87772: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.831: sr_check_worker pid 87772: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: authenticate kind = 0
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: authenticate backend: key data received
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:45.832: sr_check_worker pid 87772: DEBUG: executing replication delay command: ./delay_cmd_slow.sh localhost:11003 localhost:11004
2025-11-06 18:19:45.832: sr_check_worker pid 87772: CONTEXT: while checking replication time lag
2025-11-06 18:19:45.834: main pid 87757: LOG: pgpool-II successfully started. version 4.7devel (tasukiboshi)
2025-11-06 18:19:45.835: main pid 87757: LOG: node status[0]: 1
2025-11-06 18:19:45.835: main pid 87757: LOG: node status[1]: 2
2025-11-06 18:19:45.835: main pid 87757: LOG: node status[2]: 2
2025-11-06 18:19:46.735: child pid 87766: DEBUG: I am 87766 accept fd 7
2025-11-06 18:19:46.735: child pid 87766: DEBUG: reading startup packet
2025-11-06 18:19:46.735: child pid 87766: DETAIL: application_name: psql
2025-11-06 18:19:46.735: child pid 87766: DEBUG: reading startup packet
2025-11-06 18:19:46.735: child pid 87766: DETAIL: Protocol Major: 3 Minor: 0 database: test user: t-ishii
2025-11-06 18:19:46.735: child pid 87766: DEBUG: creating new connection to backend
2025-11-06 18:19:46.735: child pid 87766: DETAIL: connecting 0 backend
2025-11-06 18:19:46.735: child pid 87766: DEBUG: creating new connection to backend
2025-11-06 18:19:46.735: child pid 87766: DETAIL: connecting 1 backend
2025-11-06 18:19:46.735: child pid 87766: DEBUG: creating new connection to backend
2025-11-06 18:19:46.735: child pid 87766: DETAIL: connecting 2 backend
2025-11-06 18:19:46.751: child pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.751: child pid 87766: DETAIL: auth kind:0
2025-11-06 18:19:46.751: child pid 87766: DEBUG: reading message length
2025-11-06 18:19:46.751: child pid 87766: DETAIL: message length (22) in slot 1 does not match with slot 0(23)
2025-11-06 18:19:46.751: child pid 87766: DEBUG: reading message length
2025-11-06 18:19:46.751: child pid 87766: DETAIL: message length (22) in slot 2 does not match with slot 0(23)
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"in_hot_standby" value:"off"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:1 name:"in_hot_standby" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:2 name:"in_hot_standby" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"integer_datetimes" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:1 name:"integer_datetimes" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:2 name:"integer_datetimes" value:"on"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"TimeZone" value:"Asia/Tokyo"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:1 name:"TimeZone" value:"Asia/Tokyo"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:2 name:"TimeZone" value:"Asia/Tokyo"
2025-11-06 18:19:46.751: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.751: child pid 87766: DETAIL: backend:0 name:"IntervalStyle" value:"postgres"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:1 name:"IntervalStyle" value:"postgres"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:2 name:"IntervalStyle" value:"postgres"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:0 name:"search_path" value:""$user", public"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:1 name:"search_path" value:""$user", public"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:2 name:"search_path" value:""$user", public"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:0 name:"is_superuser" value:"on"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:1 name:"is_superuser" value:"on"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:2 name:"is_superuser" value:"on"
2025-11-06 18:19:46.752: child pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: child pid 87766: DETAIL: backend:0 name:"application_name" value:"psql"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"application_name" value:"psql"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"application_name" value:"psql"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"default_transaction_read_only" value:"off"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"default_transaction_read_only" value:"off"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"default_transaction_read_only" value:"off"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"scram_iterations" value:"4096"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"scram_iterations" value:"4096"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"scram_iterations" value:"4096"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"DateStyle" value:"ISO, MDY"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"DateStyle" value:"ISO, MDY"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"DateStyle" value:"ISO, MDY"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"standard_conforming_strings" value:"on"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"standard_conforming_strings" value:"on"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"standard_conforming_strings" value:"on"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"session_authorization" value:"t-ishii"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"session_authorization" value:"t-ishii"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"session_authorization" value:"t-ishii"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"client_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"client_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"client_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"server_version" value:"18.0"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"server_version" value:"18.0"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"server_version" value:"18.0"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:0 name:"server_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:1 name:"server_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: process parameter status
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: backend:2 name:"server_encoding" value:"UTF8"
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: cancel key length: 4
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: cp->info[i]:0x726410677c08 pid:87787
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: cp->info[i]:0x726410677da8 pid:87786
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: authentication backend
2025-11-06 18:19:46.752: psql pid 87766: DETAIL: cp->info[i]:0x726410677f48 pid:87788
2025-11-06 18:19:46.752: psql pid 87766: DEBUG: sending backend key data
2025-11-06 18:19:46.755: psql pid 87766: DEBUG: selecting load balance node
2025-11-06 18:19:46.755: psql pid 87766: DETAIL: selected backend id is 1
2025-11-06 18:19:46.756: psql pid 87766: LOG: DB node id: 0 backend pid: 87787 statement: SELECT pg_catalog.version()
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: username: "t-ishii" database_name: "test"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: fetching from cache storage
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: search key "c8645f9bdf015b6b5ee4667cb578f1b3"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: fetching from cache storage
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: cache not found on shared memory
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: not hit local relation cache and query cache
2025-11-06 18:19:46.756: psql pid 87766: DETAIL: query:SELECT pg_catalog.version()
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.756: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.version()"
2025-11-06 18:19:46.756: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: committing relation cache to cache storage
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: Query="SELECT pg_catalog.version()"
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: username: "t-ishii" database_name: "test"
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: query: "SELECT pg_catalog.version()"
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: memcache encode key
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.757: psql pid 87766: DEBUG: committing relation cache to cache storage
2025-11-06 18:19:46.757: psql pid 87766: DETAIL: memqcache_expire = 0
2025-11-06 18:19:46.757: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.758: psql pid 87766: DEBUG: memcache adding item
2025-11-06 18:19:46.758: psql pid 87766: DETAIL: new item inserted. blockid: 0 itemid:0
2025-11-06 18:19:46.758: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.758: psql pid 87766: DEBUG: memcache adding item
2025-11-06 18:19:46.758: psql pid 87766: DETAIL: block: 0 item: 0
2025-11-06 18:19:46.758: psql pid 87766: CONTEXT: while searching system catalog, When relcache is missed
2025-11-06 18:19:46.758: psql pid 87766: DEBUG: SimpleQuery
2025-11-06 18:19:46.758: psql pid 87766: DETAIL: nodes reporting
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: authenticate kind = 0
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: authenticate backend: key data received
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:46.761: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: authenticate kind = 0
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: authenticate backend: key data received
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:46.765: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: authenticate kind = 0
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: authenticate backend: key data received
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: decide where to send the query
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: destination = 3 for query= "DISCARD ALL"
2025-11-06 18:19:46.768: psql pid 87766: LOG: DB node id: 0 backend pid: 87787 statement: DISCARD ALL
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: waiting for query response
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: waiting for backend:0 to complete the query
2025-11-06 18:19:46.768: psql pid 87766: LOG: DB node id: 1 backend pid: 87786 statement: DISCARD ALL
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: waiting for query response
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: waiting for backend:1 to complete the query
2025-11-06 18:19:46.768: psql pid 87766: DEBUG: setting backend connection close timer
2025-11-06 18:19:46.768: psql pid 87766: DETAIL: close time 1762420786
2025-11-06 18:19:55.830: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.830: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.830: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: authenticate kind = 0
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: authenticate backend: key data received
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check1 pid 87774: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check1 pid 87774: 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-06 18:19:55.831: health_check1 pid 87774: DETAIL: No such file or directory
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: authenticate kind = 0
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: authenticate backend: key data received
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.831: health_check0 pid 87773: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.832: health_check0 pid 87773: 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-06 18:19:55.832: health_check0 pid 87773: DETAIL: No such file or directory
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: authenticate kind = 0
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: authenticate backend: key data received
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: authenticate backend: transaction state: I
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.832: health_check2 pid 87775: DEBUG: health check: clearing alarm
2025-11-06 18:19:55.832: health_check2 pid 87775: 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-06 18:19:55.832: health_check2 pid 87775: DETAIL: No such file or directory
2025-11-06 18:20:00.835: sr_check_worker pid 87772: LOG: Replication of node: 1 is behind 0.025 second(s) from the primary server (node: 0) [external command]
2025-11-06 18:20:00.835: sr_check_worker pid 87772: CONTEXT: while checking replication time lag
2025-11-06 18:20:00.835: sr_check_worker pid 87772: LOG: Replication of node: 2 is behind 0.050 second(s) from the primary server (node: 0) [external command]
2025-11-06 18:20:00.835: sr_check_worker pid 87772: CONTEXT: while checking replication time lag
2025-11-06 18:20:00.835: sr_check_worker pid 87772: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:20:00.835: sr_check_worker pid 87772: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: verify_backend_node_status: multiple standbys: 2
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: node status[0]: 1
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: node status[1]: 2
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: node status[2]: 2
2025-11-06 18:20:00.836: sr_check_worker pid 87772: DEBUG: pool_release_follow_primary_lock called
2025-11-06 18:20:01.810: main pid 87757: LOG: exit handler called (signal: 2)
2025-11-06 18:20:01.810: main pid 87757: LOG: shutting down by signal 2
2025-11-06 18:20:01.810: main pid 87757: LOG: terminating all child processes
2025-11-06 18:20:01.813: main pid 87757: 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