Content-Type: multipart/mixed; boundary="------------xRCtqnQ9zSEtj9rahcNyp4mY"
Message-ID: <5ea25e4d-1ee2-b9bf-7806-119ffa658826@gmail.com>
Date: Wed, 28 Aug 2024 21:00:00 +0300
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.4.2
Subject: Re: [EXTERNAL] Re: Add non-blocking version of PQcancel
Content-Language: en-US
To: Alvaro Herrera <alvherre@alvh.no-ip.org>
Cc: Jelte Fennema-Nio <postgres@jeltef.nl>, Noah Misch <noah@leadboat.com>,
 Tom Lane <tgl@sss.pgh.pa.us>,
 Jacob Champion <jacob.champion@enterprisedb.com>,
 Denis Laxalde <denis.laxalde@dalibo.com>, vignesh C <vignesh21@gmail.com>,
 Thomas Munro <thomas.munro@gmail.com>, Greg Stark <stark@mit.edu>,
 "Gregory Stark (as CFM)" <stark.cfm@gmail.com>,
 Jelte Fennema <Jelte.Fennema@microsoft.com>,
 Daniel Gustafsson <daniel@yesql.se>, Peter Eisentraut
 <peter@eisentraut.org>, Andres Freund <andres@anarazel.de>,
 Justin Pryzby <pryzby@telsasoft.com>, Robert Haas <robertmhaas@gmail.com>,
 pgsql-hackers@lists.postgresql.org, Etsuro Fujita <etsuro.fujita@gmail.com>
References: <202407221126.vyw5q3h4nyoh@alvherre.pgsql>
From: Alexander Lakhin <exclusion@gmail.com>
In-Reply-To: <202407221126.vyw5q3h4nyoh@alvherre.pgsql>
Archived-At: 
 <https://www.postgresql.org/message-id/5ea25e4d-1ee2-b9bf-7806-119ffa658826%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------xRCtqnQ9zSEtj9rahcNyp4mY
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

Hello Alvaro,

Let me show you another related anomaly, which drongo kindly discovered
recently: [1]. That test failed with:
  SELECT dblink_cancel_query('dtest1');
- dblink_cancel_query
----------------------
- OK
+   dblink_cancel_query
+--------------------------
+ cancel request timed out
  (1 row)

I've managed to reproduce this when running 20 dblink tests in parallel,
and with extra logging added (see attached) I've got:
...
2024-08-28 10:17:12.949 PDT [8236:204] pg_regress/dblink LOG: statement: SELECT dblink_cancel_query('dtest1');
!!!PQcancelPoll|8236| conn->status: 2
!!!PQcancelPoll|8236| conn->status: 3
!!!PQconnectPoll|8236| before pqPacketSend(..., &cancelpacket, ...)
!!!pqPacketSend|8236| before pqFlush
!!!pqsecure_raw_write|8236| could not send data to server: Socket is not connected (0x00002749/10057)
!!!pqPacketSend|8236| after pqFlush, STATUS_OK
!!!PQconnectPoll|8236| after pqPacketSend, STATUS_OK
2024-08-28 10:17:12.950 PDT [5548:7] pg_regress LOG:  statement: select * from foo where f1 < 3
2024-08-28 10:17:12.951 PDT [8692:157] DEBUG:  forked new backend, pid=4644 socket=5160
2024-08-28 10:17:12.973 PDT [4644:1] [unknown] LOG:  connection received: host=::1 port=55073
2024-08-28 10:17:12.973 PDT [4644:2] [unknown] LOG: !!!BackendInitialize| before ProcessSSLStartup()
!!!PQcancelPoll|8236| conn->status: 4
!!!PQcancelPoll|8236| conn->status: 4
2024-08-28 10:17:24.060 PDT [1436:1] DEBUG:  snapshot of 0+0 running transaction ids (lsn 0/194C4E0 oldest xid 780 
latest complete 779 next xid 780)
!!!PQcancelPoll|8236| conn->status: 4
2024-08-28 10:17:42.951 PDT [4644:3] [unknown] LOG: !!!BackendInitialize| ProcessSSLStartup() returned -1
2024-08-28 10:17:42.951 PDT [4644:4] [unknown] DEBUG: shmem_exit(0): 0 before_shmem_exit callbacks to make
...

Thus, pqsecure_raw_write(), called via PQcancelPoll() -> PQconnectPoll() ->
pqPacketSend() -> pqFlush) -> pqSendSome() -> pqsecure_write(), returned
the WSAENOTCONN error, but it wasn't noticed at upper levels.
Consequently, the cancelling backend waited for the cancel packet that was
never sent.

The first commit, that I could reproduce this test failure on, is 2466d6654.

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-08-26%2021%3A35%3A04

Best regards,
Alexander
--------------xRCtqnQ9zSEtj9rahcNyp4mY
Content-Type: text/x-patch; charset=UTF-8;
 name="libpqsrv_cancel-debugging.patch"
Content-Disposition: attachment; filename="libpqsrv_cancel-debugging.patch"
Content-Transfer-Encoding: base64

ZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL3Rjb3AvYmFja2VuZF9zdGFydHVwLmMgYi9zcmMv
YmFja2VuZC90Y29wL2JhY2tlbmRfc3RhcnR1cC5jCmluZGV4IGNmYTI3NTUxOTYuLmZjOWFi
YmZlNTMgMTAwNjQ0Ci0tLSBhL3NyYy9iYWNrZW5kL3Rjb3AvYmFja2VuZF9zdGFydHVwLmMK
KysrIGIvc3JjL2JhY2tlbmQvdGNvcC9iYWNrZW5kX3N0YXJ0dXAuYwpAQCAtMjUyLDggKzI1
MiwxMCBAQCBCYWNrZW5kSW5pdGlhbGl6ZShDbGllbnRTb2NrZXQgKmNsaWVudF9zb2NrLCBD
QUNfc3RhdGUgY2FjKQogCVJlZ2lzdGVyVGltZW91dChTVEFSVFVQX1BBQ0tFVF9USU1FT1VU
LCBTdGFydHVwUGFja2V0VGltZW91dEhhbmRsZXIpOwogCWVuYWJsZV90aW1lb3V0X2FmdGVy
KFNUQVJUVVBfUEFDS0VUX1RJTUVPVVQsIEF1dGhlbnRpY2F0aW9uVGltZW91dCAqIDEwMDAp
OwogCitlbG9nKExPRywgIiEhIUJhY2tlbmRJbml0aWFsaXplfCBiZWZvcmUgUHJvY2Vzc1NT
TFN0YXJ0dXAoKSIsIHN0YXR1cyk7CiAJLyogSGFuZGxlIGRpcmVjdCBTU0wgaGFuZHNoYWtl
ICovCiAJc3RhdHVzID0gUHJvY2Vzc1NTTFN0YXJ0dXAocG9ydCk7CitlbG9nKExPRywgIiEh
IUJhY2tlbmRJbml0aWFsaXplfCBQcm9jZXNzU1NMU3RhcnR1cCgpIHJldHVybmVkICVkIiwg
c3RhdHVzKTsKIAogCS8qCiAJICogUmVjZWl2ZSB0aGUgc3RhcnR1cCBwYWNrZXQgKHdoaWNo
IG1pZ2h0IHR1cm4gb3V0IHRvIGJlIGEgY2FuY2VsIHJlcXVlc3QKZGlmZiAtLWdpdCBhL3Ny
Yy9pbnRlcmZhY2VzL2xpYnBxL2ZlLWNhbmNlbC5jIGIvc3JjL2ludGVyZmFjZXMvbGlicHEv
ZmUtY2FuY2VsLmMKaW5kZXggMjEzYTZmNDNjMi4uODQ4MmRmYTNlOCAxMDA2NDQKLS0tIGEv
c3JjL2ludGVyZmFjZXMvbGlicHEvZmUtY2FuY2VsLmMKKysrIGIvc3JjL2ludGVyZmFjZXMv
bGlicHEvZmUtY2FuY2VsLmMKQEAgLTIwOSw2ICsyMDksNyBAQCBQUWNhbmNlbFBvbGwoUEdj
YW5jZWxDb25uICpjYW5jZWxDb25uKQogCVBHY29ubgkgICAqY29ubiA9ICZjYW5jZWxDb25u
LT5jb25uOwogCWludAkJCW47CiAKK2ZwcmludGYoc3RkZXJyLCAiISEhUFFjYW5jZWxQb2xs
fCVkfCBjb25uLT5zdGF0dXM6ICVkXG4iLCBnZXRwaWQoKSwgY29ubi0+c3RhdHVzKTsKIAkv
KgogCSAqIFdlIGxlYXZlIG1vc3Qgb2YgdGhlIGNvbm5lY3Rpb24gZXN0YWJsaXNobWVudCB0
byBQUWNvbm5lY3RQb2xsLCBzaW5jZQogCSAqIGl0J3MgdmVyeSBzaW1pbGFyIHRvIG5vcm1h
bCBjb25uZWN0aW9uIGVzdGFibGlzaG1lbnQuIEJ1dCBvbmNlIHdlIGdldApkaWZmIC0tZ2l0
IGEvc3JjL2ludGVyZmFjZXMvbGlicHEvZmUtY29ubmVjdC5jIGIvc3JjL2ludGVyZmFjZXMv
bGlicHEvZmUtY29ubmVjdC5jCmluZGV4IDM2MGQ5YTQ1NDcuLjcyYTMxZDI5ZWQgMTAwNjQ0
Ci0tLSBhL3NyYy9pbnRlcmZhY2VzL2xpYnBxL2ZlLWNvbm5lY3QuYworKysgYi9zcmMvaW50
ZXJmYWNlcy9saWJwcS9mZS1jb25uZWN0LmMKQEAgLTM0MDcsMTIgKzM0MDcsMTQgQEAga2Vl
cF9nb2luZzoJCQkJCQkvKiBXZSB3aWxsIGNvbWUgYmFjayB0byBoZXJlIHVudGlsIHRoZXJl
IGlzCiAJCQkJCWNhbmNlbHBhY2tldC5jYW5jZWxSZXF1ZXN0Q29kZSA9IChNc2dUeXBlKSBw
Z19odG9uMzIoQ0FOQ0VMX1JFUVVFU1RfQ09ERSk7CiAJCQkJCWNhbmNlbHBhY2tldC5iYWNr
ZW5kUElEID0gcGdfaHRvbjMyKGNvbm4tPmJlX3BpZCk7CiAJCQkJCWNhbmNlbHBhY2tldC5j
YW5jZWxBdXRoQ29kZSA9IHBnX2h0b24zMihjb25uLT5iZV9rZXkpOworZnByaW50ZihzdGRl
cnIsICIhISFQUWNvbm5lY3RQb2xsfCVkfCBiZWZvcmUgcHFQYWNrZXRTZW5kKC4uLiwgJmNh
bmNlbHBhY2tldCwgLi4uKVxuIiwgZ2V0cGlkKCkpOwogCQkJCQlpZiAocHFQYWNrZXRTZW5k
KGNvbm4sIDAsICZjYW5jZWxwYWNrZXQsIHBhY2tldGxlbikgIT0gU1RBVFVTX09LKQogCQkJ
CQl7CiAJCQkJCQlsaWJwcV9hcHBlbmRfY29ubl9lcnJvcihjb25uLCAiY291bGQgbm90IHNl
bmQgY2FuY2VsIHBhY2tldDogJXMiLAogCQkJCQkJCQkJCQkJU09DS19TVFJFUlJPUihTT0NL
X0VSUk5PLCBzZWJ1Ziwgc2l6ZW9mKHNlYnVmKSkpOwogCQkJCQkJZ290byBlcnJvcl9yZXR1
cm47CiAJCQkJCX0KK2ZwcmludGYoc3RkZXJyLCAiISEhUFFjb25uZWN0UG9sbHwlZHwgYWZ0
ZXIgcHFQYWNrZXRTZW5kLCBTVEFUVVNfT0tcbiIsIGdldHBpZCgpKTsKIAkJCQkJY29ubi0+
c3RhdHVzID0gQ09OTkVDVElPTl9BV0FJVElOR19SRVNQT05TRTsKIAkJCQkJcmV0dXJuIFBH
UkVTX1BPTExJTkdfUkVBRElORzsKIAkJCQl9CkBAIC01MDEyLDkgKzUwMTQsMTMgQEAgcHFQ
YWNrZXRTZW5kKFBHY29ubiAqY29ubiwgY2hhciBwYWNrX3R5cGUsCiAJaWYgKHBxUHV0TXNn
RW5kKGNvbm4pKQogCQlyZXR1cm4gU1RBVFVTX0VSUk9SOwogCitpZiAoYnVmX2xlbiA9PSAx
MikKK2ZwcmludGYoc3RkZXJyLCAiISEhcHFQYWNrZXRTZW5kfCVkfCBiZWZvcmUgcHFGbHVz
aFxuIiwgZ2V0cGlkKCkpOwogCS8qIEZsdXNoIHRvIGVuc3VyZSBiYWNrZW5kIGdldHMgaXQu
ICovCiAJaWYgKHBxRmx1c2goY29ubikpCiAJCXJldHVybiBTVEFUVVNfRVJST1I7CitpZiAo
YnVmX2xlbiA9PSAxMikKK2ZwcmludGYoc3RkZXJyLCAiISEhcHFQYWNrZXRTZW5kfCVkfCBh
ZnRlciBwcUZsdXNoLCBTVEFUVVNfT0tcbiIsIGdldHBpZCgpKTsKIAogCXJldHVybiBTVEFU
VVNfT0s7CiB9CmRpZmYgLS1naXQgYS9zcmMvaW50ZXJmYWNlcy9saWJwcS9mZS1zZWN1cmUu
YyBiL3NyYy9pbnRlcmZhY2VzL2xpYnBxL2ZlLXNlY3VyZS5jCmluZGV4IGY2MjgwODIzMzcu
LjFhODVkOWE0MGYgMTAwNjQ0Ci0tLSBhL3NyYy9pbnRlcmZhY2VzL2xpYnBxL2ZlLXNlY3Vy
ZS5jCisrKyBiL3NyYy9pbnRlcmZhY2VzL2xpYnBxL2ZlLXNlY3VyZS5jCkBAIC00MjEsNiAr
NDIxLDcgQEAgcmV0cnlfbWFza2VkOgogCQkJCQkJCQkJICAgc2VidWYsIHNpemVvZihzZWJ1
ZikpKTsKIAkJCQkvKiBrZWVwIG5ld2xpbmUgb3V0IG9mIHRyYW5zbGF0ZWQgc3RyaW5nICov
CiAJCQkJc3RybGNhdChtc2didWYsICJcbiIsIHNpemVvZihtc2didWYpKTsKK2ZwcmludGYo
c3RkZXJyLCAiISEhcHFzZWN1cmVfcmF3X3dyaXRlfCVkfCAlcyIsIGdldHBpZCgpLCBtc2di
dWYpOwogCQkJCWNvbm4tPndyaXRlX2Vycl9tc2cgPSBzdHJkdXAobXNnYnVmKTsKIAkJCQkv
KiBOb3cgY2xhaW0gdGhlIHdyaXRlIHN1Y2NlZWRlZCAqLwogCQkJCW4gPSBsZW47Cg==

--------------xRCtqnQ9zSEtj9rahcNyp4mY--