Subject: Re: BUG #16678: The ecpg connect/test5 test sometimes fails on
 Windows
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: pgsql-bugs@lists.postgresql.org
References: <16678-253e48d34dc0c376@postgresql.org>
 <434311.1603135136@sss.pgh.pa.us>
 <f558fb39-ce9e-a516-d7c3-fc94fb581711@gmail.com>
 <383222.1603561145@sss.pgh.pa.us>
 <c550c1b0-45e2-9f71-1472-f3f22bbc702a@gmail.com>
 <392145.1603573643@sss.pgh.pa.us>
From: Alexander Lakhin <exclusion@gmail.com>
Message-ID: <b4902d8e-6fdf-4239-60de-b9627f723442@gmail.com>
Date: Sun, 25 Oct 2020 08:00:00 +0300
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.10.0
MIME-Version: 1.0
In-Reply-To: <392145.1603573643@sss.pgh.pa.us>
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit
Content-Language: en-US
Precedence: bulk

25.10.2020 00:07, Tom Lane wrote:
> Alexander Lakhin <exclusion@gmail.com> writes:
>> But I'm inclined to stay on the previous level with "shutdown &&
>> closesocket" as recommended for server side:
>> https://docs.microsoft.com/en-us/windows/win32/winsock/graceful-shutdown-linger-options-and-socket-closure-2
>> Please look at the draft patch.
> If that actually fixes things, I'm okay with it --- do you find
> that it prevents the test failure even with client-side delays?
Yes, the connect/test5 test passes even with 1 sec delay:
C:\src\postgresql\src\tools\msvc>vcregress ecpgcheck
Microsoft (R) Build Engine version 16.6.0+5ff7b0c9e for .NET Framework
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 10/25/2020 7:58:25 AM.
...
============== running regression test queries        ==============
test compat_informix/dec_test     ... ok           27 ms
test compat_informix/charfuncs    ... ok           14 ms
test compat_informix/rfmtdate     ... ok           12 ms
test compat_informix/rfmtlong     ... ok           12 ms
test compat_informix/rnull        ... ok        23337 ms
test compat_informix/sqlda        ... ok        56734 ms
test compat_informix/describe     ... ok        35485 ms
test compat_informix/test_informix ... ok        41592 ms
test compat_informix/test_informix2 ... ok        21336 ms
test compat_oracle/char_array     ... ok        39457 ms
test connect/test2                ... ok        18274 ms
test connect/test3                ... ok        15276 ms
test connect/test4                ... ok         3073 ms
test connect/test5                ... ok        45866 ms
test pgtypeslib/dt_test           ... ok        15200 ms
test pgtypeslib/dt_test2          ... ok           12 ms
test pgtypeslib/num_test          ... ok        11188 ms
...
test sql/prepareas                ... ok       148876 ms
test thread/thread                ... ok        90417 ms
test thread/thread_implicit       ... ok        91290 ms
test thread/prep                  ... ok       258438 ms
test thread/alloc                 ... ok       150070 ms
test thread/descriptor            ... ok           79 ms
============== shutting down postmaster               ==============
============== removing temporary instance            ==============

======================
 All 60 tests passed.
======================

And regarding the src/test/recovery test failure with a 10 ms delay
added... I've increased a log level and get probably the same behaviour
as described in
https://www.postgresql.org/message-id/flat/OFCA523F90.7499E22F-ON4325828E.005573C4-4325828E.0055B412%40iba.by
The primary node can't finish smart shutdown and logs of the primary and
the standby are filling with the following messages:
2020-10-25 07:37:39.830 MSK [1065932] standby_1 DEBUG:  sending
replication keepalive
2020-10-25 07:37:39.840 MSK [1065932] standby_1 DEBUG:  write 0/30000A0
flush 0/3000000 apply 0/3000000 reply_time 2020-10-25 07:37:39.840277+03
2020-10-25 07:37:39.840 MSK [1065932] standby_1 DEBUG:  sending
replication keepalive
2020-10-25 07:37:39.850 MSK [1065932] standby_1 DEBUG:  write 0/30000A0
flush 0/3000000 apply 0/3000000 reply_time 2020-10-25 07:37:39.850389+03
2020-10-25 07:37:39.850 MSK [1065932] standby_1 DEBUG:  sending
replication keepalive
2020-10-25 07:37:39.860 MSK [1065932] standby_1 DEBUG:  write 0/30000A0
flush 0/3000000 apply 0/3000000 reply_time 2020-10-25 07:37:39.860486+03
...

2020-10-25 07:37:39.830 MSK [1065931] DEBUG:  sending write 0/30000A0
flush 0/3000000 apply 0/3000000
2020-10-25 07:37:39.840 MSK [1065931] DEBUG:  sendtime 2020-10-25
07:37:39.83022+03 receipttime 2020-10-25 07:37:39.840262+03 replication
apply delay 0 ms transfer latency 10 ms
2020-10-25 07:37:39.840 MSK [1065931] DEBUG:  sending write 0/30000A0
flush 0/3000000 apply 0/3000000
2020-10-25 07:37:39.850 MSK [1065931] DEBUG:  sendtime 2020-10-25
07:37:39.840331+03 receipttime 2020-10-25 07:37:39.850364+03 replication
apply delay 0 ms transfer latency 10 ms
2020-10-25 07:37:39.850 MSK [1065931] DEBUG:  sending write 0/30000A0
flush 0/3000000 apply 0/3000000
2020-10-25 07:37:39.860 MSK [1065931] DEBUG:  sendtime 2020-10-25
07:37:39.850438+03 receipttime 2020-10-25 07:37:39.860468+03 replication
apply delay 0 ms transfer latency 10 ms
...
 
Though the patch proposed by Kyotaro Horiguchi doesn't help. It this
looks like an issue that should be fixed, I can investigate it further.

Best regards,
Alexander