Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1vNRCi-002ZBM-2k for pgpool-hackers@arkaria.postgresql.org; Mon, 24 Nov 2025 07:41:45 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.96) (envelope-from ) id 1vNRCh-00H5Ww-1D for pgpool-hackers@arkaria.postgresql.org; Mon, 24 Nov 2025 07:41:43 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1vNRCh-00H5Wo-0M for pgpool-hackers@lists.postgresql.org; Mon, 24 Nov 2025 07:41:43 +0000 Received: from meldrar.postgresql.org ([2a02:c0:301:0:ffff::31]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1vNRCf-001BeR-0U for pgpool-hackers@lists.postgresql.org; Mon, 24 Nov 2025 07:41:43 +0000 DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=postgresql.org; s=20171124; h=Content-Transfer-Encoding:Content-Type: Mime-Version:References:In-Reply-To:From:Subject:Cc:To:Message-Id:Date:Sender :Reply-To:Content-ID:Content-Description; bh=krkDAjqUgUXkDuTrCFyhAJM/HI1HyJjN7ZF7BYPdHgc=; b=ifQhaI1UlGc6ZhxRxookOt9cHJ N32Wdp6rHtAOfOg+hJYG/eK+2cGW125ZsoKG3MOH1o7BxHpD1zwdcAGMWiYraSv2rePwvMeSiFnoL oHrNttcwOr/zvCrD1Iz7k5AiFharQoE16CO1Dg5rKau2QFilcWg6zrZkx8TdyB9btDJBtz87eXNyv 5mz7mfh/lXDwxsoGtEcYSqQzjnbwARMsDTbHEbTWzdBHGIj+bbxplPL9WDv1e0K4X4BW0IqzABzAZ f7zz5t0bhAS4pgDU44TGKQWccg2cUwj5KN9+Iblqy6Yj7bCxP2gG4CkUy9WRLphCIKYJzXRwHJ/vW i199TzoQ==; Received: from [2409:11:4120:300:37a6:ca58:1224:df70] (helo=localhost) by meldrar.postgresql.org with esmtpsa (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.96) (envelope-from ) id 1vNRCb-0030Ad-2X; Mon, 24 Nov 2025 07:41:40 +0000 Date: Mon, 24 Nov 2025 16:41:30 +0900 (JST) Message-Id: <20251124.164130.561276744202086083.ishii@postgresql.org> To: nadav@tailorbrands.com Cc: pgpool-hackers@lists.postgresql.org Subject: Re: Proposal: recent access based routing for primary-replica setups From: Tatsuo Ishii In-Reply-To: References: <20251120.080930.16399896794232732.ishii@postgresql.org> X-Mailer: Mew version 6.8 on Emacs 29.3 Mime-Version: 1.0 Content-Type: Multipart/Mixed; boundary="--Next_Part(Mon_Nov_24_16_41_30_2025_202)--" Content-Transfer-Encoding: 7bit X-Host-Lookup-Failed: Reverse DNS lookup failed for 2409:11:4120:300:37a6:ca58:1224:df70 (failed) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk ----Next_Part(Mon_Nov_24_16_41_30_2025_202)-- Content-Type: Text/Plain; charset=utf-8 Content-Transfer-Encoding: base64 VGhhbmsgeW91IGZvciB1cGRhdGluZyB0aGUgcGF0Y2ghIFRoaXMgdGltZSB0aGUgcGF0Y2ggYXBw bGllcyB3aXRob3V0DQphbnkgaXNzdWUgYW5kIGNvbXBpbGVzIGZpbmUuIFVuZm9ydHVuYXRlbHkg cmVncmVzc2lvbiB0ZXN0IGZhaWxlZC4NCg0KdGVzdGluZyAwNDEuZXh0ZXJuYWxfcmVwbGljYXRp b25fZGVsYXkuLi5mYWlsZWQuDQoNCkZyb20gdGhlIHJlZ3Jlc3Npb24gbG9nLCBpdCBzZWVtcyBU ZXN0NyBmYWlsZWQuDQotLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0NCj09PSBUZXN0NzogQ29tbWFuZCB0 aW1lb3V0IGhhbmRsaW5nID09PQ0Kd2FpdGluZyBmb3Igc2VydmVyIHRvIHN0YXJ0Li4uLjQxMTE4 MSAyMDI1LTExLTI0IDE2OjMxOjA1LjI0NCBKU1QgTE9HOiAgcmVkaXJlY3RpbmcgbG9nIG91dHB1 dCB0byBsb2dnaW5nIGNvbGxlY3RvciBwcm9jZXNzDQo0MTExODEgMjAyNS0xMS0yNCAxNjozMTow NS4yNDQgSlNUIEhJTlQ6ICBGdXR1cmUgbG9nIG91dHB1dCB3aWxsIGFwcGVhciBpbiBkaXJlY3Rv cnkgImxvZyIuDQogZG9uZQ0Kc2VydmVyIHN0YXJ0ZWQNCndhaXRpbmcgZm9yIHNlcnZlciB0byBz dGFydC4uLi40MTExOTYgMjAyNS0xMS0yNCAxNjozMTowNS4zNTIgSlNUIExPRzogIHJlZGlyZWN0 aW5nIGxvZyBvdXRwdXQgdG8gbG9nZ2luZyBjb2xsZWN0b3IgcHJvY2Vzcw0KNDExMTk2IDIwMjUt MTEtMjQgMTY6MzE6MDUuMzUyIEpTVCBISU5UOiAgRnV0dXJlIGxvZyBvdXRwdXQgd2lsbCBhcHBl YXIgaW4gZGlyZWN0b3J5ICJsb2ciLg0KIGRvbmUNCnNlcnZlciBzdGFydGVkDQp3YWl0aW5nIGZv ciBzZXJ2ZXIgdG8gc3RhcnQuLi4uNDExMjEzIDIwMjUtMTEtMjQgMTY6MzE6MDUuNDYxIEpTVCBM T0c6ICByZWRpcmVjdGluZyBsb2cgb3V0cHV0IHRvIGxvZ2dpbmcgY29sbGVjdG9yIHByb2Nlc3MN CjQxMTIxMyAyMDI1LTExLTI0IDE2OjMxOjA1LjQ2MSBKU1QgSElOVDogIEZ1dHVyZSBsb2cgb3V0 cHV0IHdpbGwgYXBwZWFyIGluIGRpcmVjdG9yeSAibG9nIi4NCiBkb25lDQpzZXJ2ZXIgc3RhcnRl ZA0KV2FpdGluZyBmb3IgY29tbWFuZCB0aW1lb3V0Li4uDQpmYWlsOiBjb21tYW5kIHRpbWVvdXQg bm90IGRldGVjdGVkDQotLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0t LS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0NCg0KQXR0YWNoZWQgaXMgdGhlIHBn cG9vbC5sb2cuIElmIHlvdSBuZWVkIG1vcmUgaW5mbywgcGxlYXNlIGxldCBtZSBrbm93Lg0KDQpC ZXN0IHJlZ2FyZHMsDQotLQ0KVGF0c3VvIElzaGlpDQpTUkEgT1NTIEsuSy4NCkVuZ2xpc2g6IGh0 dHA6Ly93d3cuc3Jhb3NzLmNvLmpwL2luZGV4X2VuLw0KSmFwYW5lc2U6aHR0cDovL3d3dy5zcmFv c3MuY28uanANCg0KDQo+IEhpIFRhdHN1bywNCj4gDQo+IFNvcnJ5IGFnYWluLCB0aGlzIHdhcyBk dWUgdG8gdGhlIHNlcGFyYXRpb24gb2YgMiBwYXRjaGVzIGFuZCBpIG9ubHkgc2VudA0KPiB0aGUg b25lLg0KPiANCj4gSSd2ZSBtZXJnZWQgaXQgaW50byAxIGNvbW1pdCBhbmQgMSBwYXRjaCBhbmQg cmViYXNlZCBvdmVyIG1hc3RlciB0byBhdm9pZA0KPiB0aGVzZSBpc3N1ZXMgbW92aW5nIGZvcndh cmQuDQo+IA0KPiBQRkEgbGF0ZXN0IHZlcnNpb24NCj4gDQo+IE9uIFRodSwgTm92IDIwLCAyMDI1 IGF0IDE6MDnigK9BTSBUYXRzdW8gSXNoaWkgPGlzaGlpQHBvc3RncmVzcWwub3JnPiB3cm90ZToN Cj4gDQo+PiBIaSBOYWRhdiwNCj4+DQo+PiBUaGFuayB5b3UgZm9yIG5ldyBwYXRjaC4NCj4+IFVu Zm9ydHVuYXRlbHkgdGhlIHBhdGNoIGRpZCBub3QgYXBwbHkgdG8gY3VycmVudCBtYXN0ZXIuDQo+ Pg0KPj4gJCBnaXQgYXBwbHkNCj4+IH4vMDAwMS1GaXgtbXVsdGlwbGUtaXNzdWVzLWluLWV4dGVy bmFsLXJlcGxpY2F0aW9uLWRlbGF5LWZlLnBhdGNoDQo+PiBlcnJvcjogcGF0Y2ggZmFpbGVkOiBz cmMvc3RyZWFtaW5nX3JlcGxpY2F0aW9uL3Bvb2xfd29ya2VyX2NoaWxkLmM6Njk0DQo+PiBlcnJv cjogc3JjL3N0cmVhbWluZ19yZXBsaWNhdGlvbi9wb29sX3dvcmtlcl9jaGlsZC5jOiBwYXRjaCBk b2VzIG5vdCBhcHBseQ0KPj4NCj4+IE1heWJlIHRoZSBwYXRjaCBpcyBvbiB0b3Agb2YgeW91ciBw cmV2aW91cyBwYXRjaD8NCj4+DQo+PiBBbHNvIEkgc3VnZ2VzdCB0byB1c2UgIi12IiBvcHRpb24g b2YgImdpdCBmb3JtYXQtcGF0Y2giIHRvIGFkZCB0aGUNCj4+IHBhdGNoIHZlcnNpb24gbnVtYmVy IHNvIHRoYXQgd2UgY2FuIGVhc2lseSBrbm93IHdoaWNoIHBhdGNoIGlzIHRoZQ0KPj4gbGF0ZXN0 Lg0KPj4NCj4+IEJlc3QgcmVnYXJkcywNCj4+IC0tDQo+PiBUYXRzdW8gSXNoaWkNCj4+IFNSQSBP U1MgSy5LLg0KPj4gRW5nbGlzaDogaHR0cDovL3d3dy5zcmFvc3MuY28uanAvaW5kZXhfZW4vDQo+ PiBKYXBhbmVzZTpodHRwOi8vd3d3LnNyYW9zcy5jby5qcA0KPj4NCj4+ID4gSGkgVGF0c3VvLA0K Pj4gPg0KPj4gPiBQbGVhc2Ugc2VlIGF0dGFjaGVkIGFuIHVwZGF0ZWQgdmVyc2lvbi4NCj4+ID4N Cj4+ID4gdGhhbmsgeW91DQo+PiA+DQo+PiA+IE9uIEZyaSwgTm92IDcsIDIwMjUgYXQgMjowN+KA r0FNIFRhdHN1byBJc2hpaSA8aXNoaWlAcG9zdGdyZXNxbC5vcmc+DQo+PiB3cm90ZToNCj4+ID4N Cj4+ID4+ID4gU29ycnkgZm9yIHRoYXQgLSB0aGFua3MgZm9yIHRoZSBwYXRjaC4NCj4+ID4+ID4N Cj4+ID4+ID4gUGxlYXNlIGZpbmQgYXR0YWNoZWQgYSBuZXcgdmVyc2lvbg0KPj4gPj4NCj4+ID4+ IFRoYW5rcyBmb3IgdGhlIG5ldyB2ZXJzaW9uLiBVbmZvcnR1bmF0ZWx5IHRoaXMgdGltZSByZWdy ZXNzaW9uIHRlc3QNCj4+ID4+IGZhaWxzIGF0Og0KPj4gPj4NCj4+ID4+ID4gV2FpdGluZyBmb3Ig Y29tbWFuZCB0aW1lb3V0Li4uDQo+PiA+PiA+IGZhaWw6IGNvbW1hbmQgdGltZW91dCBub3QgZGV0 ZWN0ZWQNCj4+ID4+DQo+PiA+PiBBdHRhY2hlZCBpcyB0aGUgcGdwb29sLmxvZy4NCj4+ID4+DQo+ PiA+PiBCZXN0IHJlZ2FyZHMsDQo+PiA+PiAtLQ0KPj4gPj4gVGF0c3VvIElzaGlpDQo+PiA+PiBT UkEgT1NTIEsuSy4NCj4+ID4+IEVuZ2xpc2g6IGh0dHA6Ly93d3cuc3Jhb3NzLmNvLmpwL2luZGV4 X2VuLw0KPj4gPj4gSmFwYW5lc2U6aHR0cDovL3d3dy5zcmFvc3MuY28uanANCj4+ID4+DQo+PiA+ PiA+IE9uIE1vbiwgTm92IDMsIDIwMjUgYXQgOTowNeKAr0FNIFRhdHN1byBJc2hpaSA8aXNoaWlA cG9zdGdyZXNxbC5vcmc+DQo+PiA+PiB3cm90ZToNCj4+ID4+ID4NCj4+ID4+ID4+ID4gdGhhbmtz IGFuZCBzb3JyeSBmb3IgdGhlIGlzc3VlcywgcGxlYXNlIGZpbmQgYXR0YWNoZWQgdXBkYXRlZA0K Pj4gdmVyc2lvbi4NCj4+ID4+ID4+DQo+PiA+PiA+PiBObyBwcm9ibGVtLg0KPj4gPj4gPj4NCj4+ ID4+ID4+IFRoaXMgdGltZSB0aGUgcGF0Y2ggYXBwbGllcyBmaW5lLCBubyBjb21waWxlciB3YXJu aW5ncy4gIEhvd2V2ZXIsDQo+PiA+PiA+PiByZWdyZXNzaW9uIHRlc3QgZGlkIG5vdCBwYXNzZWQg aGVyZSAob24gVWJ1bnR1IDI0IExUUyBpZiB0aGlzDQo+PiA+PiA+PiBtYXR0ZXJzKS4gIFNvIEkg bG9va2VkIGludG8NCj4+ID4+ID4+IHNyYy90ZXN0L3JlZ3Jlc3Npb24vdGVzdHMvMDQxLmV4dGVy bmFsX3JlcGxpY2F0aW9uX2RlbGF5L3Rlc3Quc2ggYQ0KPj4gPj4gPj4gbGl0dGxlIGJpdCBhbmQg YXBwbHkgYXR0YWNoZWQgcGF0Y2ggKHRlc3Quc2gucGF0Y2gpLiBJdCBtb3ZlZCBmb3J3YXJkDQo+ PiA+PiA+PiBwYXJ0aWFsbHkgYnV0IGZhaWxlZCBhdDoNCj4+ID4+ID4+DQo+PiA+PiA+PiBmYWls OiBjb21tYW5kIGV4ZWN1dGlvbiBmYWlsdXJlIG5vdCBkZXRlY3RlZA0KPj4gPj4gPj4NCj4+ID4+ ID4+IFBsZWFzZSBmaW5kIGF0dGFjaGVkDQo+PiA+PiA+Pg0KPj4gPj4NCj4+IHNyYy90ZXN0L3Jl Z3Jlc3Npb24vdGVzdHMvMDQxLmV4dGVybmFsX3JlcGxpY2F0aW9uX2RlbGF5L3Rlc3RkaXIvcGdw b29sLmxvZw0KPj4gPj4gPj4gYW5kIHNyYy90ZXN0L3JlZ3Jlc3Npb24vbG9nLzA0MS5leHRlcm5h bF9yZXBsaWNhdGlvbl9kZWxheS4NCj4+ID4+ID4+DQo+PiA+PiA+PiBCZXN0IHJlZ2FyZHMsDQo+ PiA+PiA+PiAtLQ0KPj4gPj4gPj4gVGF0c3VvIElzaGlpDQo+PiA+PiA+PiBTUkEgT1NTIEsuSy4N Cj4+ID4+ID4+IEVuZ2xpc2g6IGh0dHA6Ly93d3cuc3Jhb3NzLmNvLmpwL2luZGV4X2VuLw0KPj4g Pj4gPj4gSmFwYW5lc2U6aHR0cDovL3d3dy5zcmFvc3MuY28uanANCj4+ID4+ID4+DQo+PiA+PiA+ DQo+PiA+PiA+DQo+PiA+PiA+IC0tDQo+PiA+PiA+IE5hZGF2IFNoYXR6DQo+PiA+PiA+IFRhaWxv ciBCcmFuZHMgfCBDVE8NCj4+ID4+DQo+PiA+DQo+PiA+DQo+PiA+IC0tDQo+PiA+IE5hZGF2IFNo YXR6DQo+PiA+IFRhaWxvciBCcmFuZHMgfCBDVE8NCj4+DQo+IA0KPiANCj4gLS0gDQo+IE5hZGF2 IFNoYXR6DQo+IFRhaWxvciBCcmFuZHMgfCBDVE8NCg== ----Next_Part(Mon_Nov_24_16_41_30_2025_202)-- Content-Type: Text/Plain; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="pgpool.log" 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 ----Next_Part(Mon_Nov_24_16_41_30_2025_202)----