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