2025-11-24 16:31:05.537: main pid 411227: DEBUG:  initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL:  num_backends: 3 total_weight: 1.000000
2025-11-24 16:31:05.537: main pid 411227: DEBUG:  initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL:  backend 0 weight: 0.000000 flag: 0000
2025-11-24 16:31:05.537: main pid 411227: DEBUG:  initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL:  backend 1 weight: 2147483647.000000 flag: 0000
2025-11-24 16:31:05.537: main pid 411227: DEBUG:  initializing pool configuration
2025-11-24 16:31:05.537: main pid 411227: DETAIL:  backend 2 weight: 0.000000 flag: 0000
2025-11-24 16:31:05.543: main pid 411227: LOG:  Backend status file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/pgpool_status discarded
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  BackendDesc: 113672 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  pool_coninfo_size: num_init_children (4) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (416) = 425984 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  ProcessInfo: num_init_children (4) * sizeof(ProcessInfo) (2152) = 8608 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  UserSignalSlot: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  POOL_REQUEST_INFO: 5272 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  stat_shared_memory_size: 9216 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  SI_ManageInfo: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  memcache blocks :64
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  shared_memory_cache_size: 67108864
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  shared_memory_fsmm_size: 64
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  pool_hash_size: 67108880
2025-11-24 16:31:05.543: main pid 411227: DEBUG:  POOL_QUERY_CACHE_STATS: 24 bytes requested for shared memory
2025-11-24 16:31:05.543: main pid 411227: LOG:  allocating shared memory segment of size: 134793216 
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  pool_coninfo_size: num_init_children (4) * max_pool (2) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (416) = 425984 bytes requested for shared memory
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  health_check_stats_shared_memory_size: requested size: 12288
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  memcache blocks :64
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  shared_memory_cache_size: 67108864
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  memory cache request size : 67108864
2025-11-24 16:31:05.668: main pid 411227: DEBUG:  shared_memory_fsmm_size: 64
2025-11-24 16:31:05.671: main pid 411227: LOG:  pool_discard_oid_maps: discarded memqcache oid maps
2025-11-24 16:31:05.686: main pid 411227: LOG:  create socket files[0]: /tmp/.s.PGSQL.11000
2025-11-24 16:31:05.686: main pid 411227: LOG:  listen address[0]: *
2025-11-24 16:31:05.687: main pid 411227: LOG:  Setting up socket for 0.0.0.0:11000
2025-11-24 16:31:05.687: main pid 411227: LOG:  Setting up socket for :::11000
2025-11-24 16:31:05.687: main pid 411227: DEBUG:  Spawning 4 child processes
2025-11-24 16:31:05.688: child pid 411234: DEBUG:  initializing backend status
2025-11-24 16:31:05.688: child pid 411235: DEBUG:  initializing backend status
2025-11-24 16:31:05.688: child pid 411236: DEBUG:  initializing backend status
2025-11-24 16:31:05.688: main pid 411227: LOG:  find_primary_node_repeatedly: waiting for finding a primary node
2025-11-24 16:31:05.689: child pid 411237: DEBUG:  initializing backend status
2025-11-24 16:31:05.696: main pid 411227: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.696: main pid 411227: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.696: main pid 411227: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.705: main pid 411227: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.705: main pid 411227: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.705: main pid 411227: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.714: main pid 411227: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.714: main pid 411227: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.714: main pid 411227: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.714: main pid 411227: DEBUG:  pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-24 16:31:05.714: main pid 411227: DEBUG:  pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-24 16:31:05.714: main pid 411227: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.715: main pid 411227: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.716: main pid 411227: DEBUG:  get_server_version: backend 0 server version: 180000
2025-11-24 16:31:05.716: main pid 411227: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.716: main pid 411227: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  get_server_version: backend 1 server version: 180000
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.current_setting('server_version_num')"
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  get_server_version: backend 2 server version: 180000
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  verify_backend_node_status: multiple standbys: 2
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-24 16:31:05.717: main pid 411227: DEBUG:  pool_release_follow_primary_lock called
2025-11-24 16:31:05.718: main pid 411227: LOG:  find_primary_node: primary node is 0
2025-11-24 16:31:05.718: main pid 411227: LOG:  find_primary_node: standby node is 1
2025-11-24 16:31:05.718: main pid 411227: LOG:  find_primary_node: standby node is 2
2025-11-24 16:31:05.718: main pid 411227: LOG:  create socket files[0]: /tmp/.s.PGSQL.11001
2025-11-24 16:31:05.718: main pid 411227: LOG:  listen address[0]: localhost
2025-11-24 16:31:05.718: main pid 411227: LOG:  Setting up socket for 127.0.0.1:11001
2025-11-24 16:31:05.718: pcp_main pid 411241: DEBUG:  I am PCP child with pid:411241
2025-11-24 16:31:05.719: pcp_main pid 411241: LOG:  PCP process: 411241 started
2025-11-24 16:31:05.719: sr_check_worker pid 411242: LOG:  process started
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG:  I am 411242
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG:  pool_acquire_follow_primary_lock: lock was not held by anyone
2025-11-24 16:31:05.719: sr_check_worker pid 411242: DEBUG:  pool_acquire_follow_primary_lock: succeeded in acquiring lock
2025-11-24 16:31:05.719: health_check pid 411243: LOG:  process started
2025-11-24 16:31:05.719: health_check0 pid 411243: DEBUG:  I am health check process pid:411243 DB node id:0
2025-11-24 16:31:05.719: health_check0 pid 411243: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.719: health_check pid 411244: LOG:  process started
2025-11-24 16:31:05.719: health_check1 pid 411244: DEBUG:  I am health check process pid:411244 DB node id:1
2025-11-24 16:31:05.719: health_check1 pid 411244: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.719: health_check pid 411245: LOG:  process started
2025-11-24 16:31:05.720: health_check2 pid 411245: DEBUG:  I am health check process pid:411245 DB node id:2
2025-11-24 16:31:05.720: health_check2 pid 411245: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.723: sr_check_worker pid 411242: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.723: health_check1 pid 411244: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.723: health_check1 pid 411244: WARNING:  check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.723: health_check1 pid 411244: DETAIL:  No such file or directory
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.723: health_check2 pid 411245: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.723: health_check2 pid 411245: WARNING:  check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.723: health_check2 pid 411245: DETAIL:  No such file or directory
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.724: health_check0 pid 411243: DEBUG:  health check: clearing alarm
2025-11-24 16:31:05.724: health_check0 pid 411243: WARNING:  check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:05.724: health_check0 pid 411243: DETAIL:  No such file or directory
2025-11-24 16:31:05.727: main pid 411227: LOG:  pgpool-II successfully started. version 4.8devel (mitsukakeboshi)
2025-11-24 16:31:05.727: main pid 411227: LOG:  node status[0]: 1
2025-11-24 16:31:05.727: main pid 411227: LOG:  node status[1]: 2
2025-11-24 16:31:05.727: main pid 411227: LOG:  node status[2]: 2
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.728: sr_check_worker pid 411242: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG:  authenticate kind = 0
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:05.732: sr_check_worker pid 411242: DEBUG:  executing replication delay command: ./delay_cmd_slow.sh localhost:11003 localhost:11004
2025-11-24 16:31:05.732: sr_check_worker pid 411242: CONTEXT:  while checking replication time lag
2025-11-24 16:31:06.548: child pid 411237: DEBUG:  I am 411237 accept fd 7
2025-11-24 16:31:06.549: child pid 411237: DEBUG:  reading startup packet
2025-11-24 16:31:06.549: child pid 411237: DETAIL:  application_name: psql
2025-11-24 16:31:06.549: child pid 411237: DEBUG:  reading startup packet
2025-11-24 16:31:06.549: child pid 411237: DETAIL:  Protocol Major: 3 Minor: 0 database: test user: t-ishii
2025-11-24 16:31:06.549: child pid 411237: DEBUG:  creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL:  connecting 0 backend
2025-11-24 16:31:06.549: child pid 411237: DEBUG:  creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL:  connecting 1 backend
2025-11-24 16:31:06.549: child pid 411237: DEBUG:  creating new connection to backend
2025-11-24 16:31:06.549: child pid 411237: DETAIL:  connecting 2 backend
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  authentication backend
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  auth kind:0
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  reading message length
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  message length (22) in slot 1 does not match with slot 0(23)
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  reading message length
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  message length (22) in slot 2 does not match with slot 0(23)
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"in_hot_standby" value:"off"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:1 name:"in_hot_standby" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:2 name:"in_hot_standby" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:1 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:2 name:"integer_datetimes" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:1 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:2 name:"TimeZone" value:"Asia/Tokyo"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:1 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:2 name:"IntervalStyle" value:"postgres"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:1 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:2 name:"search_path" value:""$user", public"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:1 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:2 name:"is_superuser" value:"on"
2025-11-24 16:31:06.567: child pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: child pid 411237: DETAIL:  backend:0 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"application_name" value:"psql"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"default_transaction_read_only" value:"off"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"scram_iterations" value:"4096"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"DateStyle" value:"ISO, MDY"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"standard_conforming_strings" value:"on"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"session_authorization" value:"t-ishii"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"client_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"server_version" value:"18.0"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:0 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:1 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  process parameter status
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  backend:2 name:"server_encoding" value:"UTF8"
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  cancel key length: 4
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  cp->info[i]:0x7e3902ddfc08 pid:411256
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  cp->info[i]:0x7e3902ddfda8 pid:411257
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  authentication backend
2025-11-24 16:31:06.567: psql pid 411237: DETAIL:  cp->info[i]:0x7e3902ddff48 pid:411258
2025-11-24 16:31:06.567: psql pid 411237: DEBUG:  sending backend key data
2025-11-24 16:31:06.570: psql pid 411237: DEBUG:  selecting load balance node
2025-11-24 16:31:06.570: psql pid 411237: DETAIL:  selected backend id is 1
2025-11-24 16:31:06.571: psql pid 411237: LOG:  DB node id: 0 backend pid: 411256 statement: SELECT pg_catalog.version()
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL:  username: "t-ishii" database_name: "test"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL:  query: "SELECT pg_catalog.version()"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  memcache encode key
2025-11-24 16:31:06.571: psql pid 411237: DETAIL:  `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  fetching from cache storage
2025-11-24 16:31:06.571: psql pid 411237: DETAIL:  search key "c8645f9bdf015b6b5ee4667cb578f1b3"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  fetching from cache storage
2025-11-24 16:31:06.571: psql pid 411237: DETAIL:  cache not found on shared memory
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  not hit local relation cache and query cache
2025-11-24 16:31:06.571: psql pid 411237: DETAIL:  query:SELECT pg_catalog.version()
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.571: psql pid 411237: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.version()"
2025-11-24 16:31:06.571: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.572: psql pid 411237: DEBUG:  committing relation cache to cache storage
2025-11-24 16:31:06.572: psql pid 411237: DETAIL:  Query="SELECT pg_catalog.version()"
2025-11-24 16:31:06.572: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.572: psql pid 411237: DEBUG:  memcache encode key
2025-11-24 16:31:06.572: psql pid 411237: DETAIL:  username: "t-ishii" database_name: "test"
2025-11-24 16:31:06.572: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG:  memcache encode key
2025-11-24 16:31:06.573: psql pid 411237: DETAIL:  query: "SELECT pg_catalog.version()"
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG:  memcache encode key
2025-11-24 16:31:06.573: psql pid 411237: DETAIL:  `t-ishiiSELECT pg_catalog.version()test' -> `c8645f9bdf015b6b5ee4667cb578f1b3'
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG:  committing relation cache to cache storage
2025-11-24 16:31:06.573: psql pid 411237: DETAIL:  memqcache_expire = 0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG:  memcache adding item
2025-11-24 16:31:06.573: psql pid 411237: DETAIL:  new item inserted. blockid: 0 itemid:0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG:  memcache adding item
2025-11-24 16:31:06.573: psql pid 411237: DETAIL:  block: 0 item: 0
2025-11-24 16:31:06.573: psql pid 411237: CONTEXT:  while searching system catalog, When relcache is missed
2025-11-24 16:31:06.573: psql pid 411237: DEBUG:  SimpleQuery
2025-11-24 16:31:06.573: psql pid 411237: DETAIL:  nodes reporting
2025-11-24 16:31:06.582: psql pid 411237: DEBUG:  authenticate kind = 0
2025-11-24 16:31:06.582: psql pid 411237: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:06.582: psql pid 411237: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:06.582: psql pid 411237: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.591: psql pid 411237: DEBUG:  authenticate kind = 0
2025-11-24 16:31:06.591: psql pid 411237: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:06.591: psql pid 411237: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:06.591: psql pid 411237: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.598: psql pid 411237: DEBUG:  authenticate kind = 0
2025-11-24 16:31:06.598: psql pid 411237: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:06.598: psql pid 411237: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:06.598: psql pid 411237: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:06.599: psql pid 411237: DEBUG:  decide where to send the query
2025-11-24 16:31:06.599: psql pid 411237: DETAIL:  destination = 3 for query= "DISCARD ALL"
2025-11-24 16:31:06.599: psql pid 411237: LOG:  DB node id: 0 backend pid: 411256 statement: DISCARD ALL
2025-11-24 16:31:06.599: psql pid 411237: DEBUG:  waiting for query response
2025-11-24 16:31:06.599: psql pid 411237: DETAIL:  waiting for backend:0 to complete the query
2025-11-24 16:31:06.600: psql pid 411237: LOG:  DB node id: 1 backend pid: 411257 statement: DISCARD ALL
2025-11-24 16:31:06.600: psql pid 411237: DEBUG:  waiting for query response
2025-11-24 16:31:06.600: psql pid 411237: DETAIL:  waiting for backend:1 to complete the query
2025-11-24 16:31:06.600: psql pid 411237: DEBUG:  setting backend connection close timer
2025-11-24 16:31:06.600: psql pid 411237: DETAIL:  close time 1763969466
2025-11-24 16:31:15.724: health_check2 pid 411245: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.724: health_check1 pid 411244: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.724: health_check0 pid 411243: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG:  authenticate kind = 0
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check2 pid 411245: WARNING:  check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check2 pid 411245: DETAIL:  No such file or directory
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG:  authenticate kind = 0
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check0 pid 411243: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG:  authenticate kind = 0
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG:  authenticate backend: key data received
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG:  authenticate backend: transaction state: I
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check1 pid 411244: DEBUG:  health check: clearing alarm
2025-11-24 16:31:15.729: health_check0 pid 411243: WARNING:  check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check0 pid 411243: DETAIL:  No such file or directory
2025-11-24 16:31:15.729: health_check1 pid 411244: WARNING:  check_backend_down_request: failed to open file /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/041.external_replication_delay/testdir/log/backend_down_request
2025-11-24 16:31:15.729: health_check1 pid 411244: DETAIL:  No such file or directory
2025-11-24 16:31:20.738: sr_check_worker pid 411242: LOG:  Replication of node: 1 is behind 0.025 second(s) from the primary server (node: 0) [external command]
2025-11-24 16:31:20.738: sr_check_worker pid 411242: CONTEXT:  while checking replication time lag
2025-11-24 16:31:20.738: sr_check_worker pid 411242: LOG:  Replication of node: 2 is behind 0.050 second(s) from the primary server (node: 0) [external command]
2025-11-24 16:31:20.738: sr_check_worker pid 411242: CONTEXT:  while checking replication time lag
2025-11-24 16:31:20.738: sr_check_worker pid 411242: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.740: sr_check_worker pid 411242: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.741: sr_check_worker pid 411242: DEBUG:  do_query: extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG:  verify_backend_node_status: multiple standbys: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG:  verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG:  node status[0]: 1
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG:  node status[1]: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG:  node status[2]: 2
2025-11-24 16:31:20.742: sr_check_worker pid 411242: DEBUG:  pool_release_follow_primary_lock called
2025-11-24 16:31:21.696: main pid 411227: LOG:  exit handler called (signal: 2)
2025-11-24 16:31:21.696: main pid 411227: LOG:  shutting down by signal 2
2025-11-24 16:31:21.696: main pid 411227: LOG:  terminating all child processes
2025-11-24 16:31:21.699: main pid 411227: LOG:  Pgpool-II system is shutdown