Horton

Thread

Commits

  1. In pgwin32_open, loop after ERROR_ACCESS_DENIED only if we can't stat.

  2. On Windows, wait a little to see if ERROR_ACCESS_DENIED goes away.

  1. BUG #16161: pg_ctl stop fails sometimes (on Windows)

    The Post Office <noreply@postgresql.org> — 2019-12-11T20:00:02Z

    The following bug has been logged on the website:

Bug reference:      16161
Logged by:          Alexander Lakhin
Email address:      exclusion@gmail.com
PostgreSQL version: 12.1
Operating system:   Windows
Description:        

The regression tests on Windows sometimes fail with 'Permission denied'
errors. For example:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dory&dt=2019-12-11%2007%3A45%3A33

============== shutting down postmaster               ==============
pg_ctl: could not open PID file
"c:/pgbuildfarm/pgbuildroot/HEAD/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid":
Permission denied

This error occurs when pg_ctl is trying to open postmaster.pid while this
file is in "delete pending" state
(https://stackoverflow.com/questions/3764072/).

  2. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-11T20:30:01Z

    11.12.2019 23:00, PG Bug reporting form wrote:
> The following bug has been logged on the website:
>
> Bug reference:      16161
> Logged by:          Alexander Lakhin
> Email address:      exclusion@gmail.com
> PostgreSQL version: 12.1
> Operating system:   Windows
> Description:        
>
> The regression tests on Windows sometimes fail with 'Permission denied'
> errors. For example:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dory&dt=2019-12-11%2007%3A45%3A33
>
> ============== shutting down postmaster               ==============
> pg_ctl: could not open PID file
> "c:/pgbuildfarm/pgbuildroot/HEAD/pgsql.build/src/test/regress/./tmp_check/data/postmaster.pid":
> Permission denied
>
> This error occurs when pg_ctl is trying to open postmaster.pid while this
> file is in "delete pending" state
> (https://stackoverflow.com/questions/3764072/).
To reproduce the issue reliably I propose a simple modification to
synchronize unlink() with open() and a simple test
(sync_pid_ops+test.patch).
With the patch applied, `vcregress taptest src/test/restart` fails for
me on iteration 47, 6, 7, 42, 51, 26, ...

I see two ways to fix the issue:
1) Unlink postmaster.pid using rename operation (adopt the solution from
https://stackoverflow.com/questions/3764072/).
2) Ignore such 'Permission denied' error and just try to open the file
once again (attached fix_open_for_unlink.patch implements this).


I'm inclined to the second approach as pgwin32_open() already handles
two transient states (Windows-only), and it could be useful not only for
postmaster.pid, but for some other files.


Best regards,
Alexander

  3. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-15T21:26:40Z

    Alexander Lakhin <exclusion@gmail.com> writes:
>> The regression tests on Windows sometimes fail with 'Permission denied'
>> errors. For example:
>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dory&dt=2019-12-11%2007%3A45%3A33

> I see two ways to fix the issue:
> 1) Unlink postmaster.pid using rename operation (adopt the solution from
> https://stackoverflow.com/questions/3764072/).
> 2) Ignore such 'Permission denied' error and just try to open the file
> once again (attached fix_open_for_unlink.patch implements this).

> I'm inclined to the second approach as pgwin32_open() already handles
> two transient states (Windows-only), and it could be useful not only for
> postmaster.pid, but for some other files.

Agreed that (2) seems like the way to go.  However, I'm not too pleased
with the patch as given, because it is gratuitously different in almost
every possible way from the adjacent code that's doing just about the same
thing for those other transient failures.  Why is the timeout duration
different?  Why is the looping logic not identical?  Why did you make a
different decision about whether logging might be a good idea?  Actually,
why didn't you just extend the existing if-block to also cover this case?
Maybe there's good reasons to be different, but you didn't explain them.

I'm also not that excited about memorializing a stackoverflow discussion
as the reason to do something.  Can we point to something in Microsoft's
official docs?

			regards, tom lane

  4. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-16T05:00:00Z

    Hello Tom,
16.12.2019 0:26, Tom Lane wrote:
> Alexander Lakhin <exclusion@gmail.com> writes:
>>> The regression tests on Windows sometimes fail with 'Permission denied'
>>> errors. For example:
>>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dory&dt=2019-12-11%2007%3A45%3A33
>> I see two ways to fix the issue:
>> 1) Unlink postmaster.pid using rename operation (adopt the solution from
>> https://stackoverflow.com/questions/3764072/).
>> 2) Ignore such 'Permission denied' error and just try to open the file
>> once again (attached fix_open_for_unlink.patch implements this).
>> I'm inclined to the second approach as pgwin32_open() already handles
>> two transient states (Windows-only), and it could be useful not only for
>> postmaster.pid, but for some other files.
> Agreed that (2) seems like the way to go.  However, I'm not too pleased
> with the patch as given, because it is gratuitously different in almost
> every possible way from the adjacent code that's doing just about the same
> thing for those other transient failures.  Why is the timeout duration
> different?  Why is the looping logic not identical?  Why did you make a
> different decision about whether logging might be a good idea?  Actually,
> why didn't you just extend the existing if-block to also cover this case?
> Maybe there's good reasons to be different, but you didn't explain them.
Thanks for your questions. I'll try to add more details.
I didn't want to use the existing code for three reasons.
First, there are too many differences in the parameters: other error
code, other error reason, no need for logging.
Second, I wanted to decrease a delay, as whole unlink operation
(comprising of three kernel calls: CreateFile,
SetDispositionInformationFile, CloseFile) performed for me in 0.0002
seconds (as ProcessMonitor showed for several runs). Assuming even
hundredfold duration seems sufficient. On the other side,
ERROR_ACCESS_DENIED can be caused by a real access restriction and
waiting for 30 seconds before erroring out is too long.
Third, the logic of the existing loop confused me — I haven't seen a
reason to sleep for a last time and then return an error without
rechecking a condition.
And I think that the logging is irrelevant as we want to handle here
just the DELETE_PENDING state. If the "access denied" error state is
disappeared within a second, then we can log only "the file probably was
in a deletion state and now it's not", and if this state is persisting,
we can log "access is really denied", but I believe that the existing
calling code does the same anyway.
> I'm also not that excited about memorializing a stackoverflow discussion
> as the reason to do something.  Can we point to something in Microsoft's
> official docs?
I'm not excited about this too, but I couldn't find something more
appropriate.
For example. there is a similar question on their forums:
https://social.technet.microsoft.com/Forums/office/en-US/58e5c670-f024-44ff-9919-36c44ab11d9c/file-delete-pending-problem?forum=w7itprogeneral
but it left without a reference to their docs.
WebArchive contains their knowledge base article where
STATUS_DELETE_PENDING is mapped to ERROR_ACCESS_DENIED, but today this
information cannot be found on microsoft.com:
https://web.archive.org/web/20150317121919/http://support.microsoft.com/en-us/kb/113996
Maybe they consider this as too low-level implementation details...
I think, they have some internal documentation where this is described
in details, but we can't reference it anyway.
On the other hand, finding a couple of references to stackoverflow in
src/ made me feel that it is not widely accepted, but still accepted (as
an exception).

Best regards.
Alexander

  5. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-16T20:17:13Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> 16.12.2019 0:26, Tom Lane wrote:
>> Agreed that (2) seems like the way to go.  However, I'm not too pleased
>> with the patch as given, because it is gratuitously different in almost
>> every possible way from the adjacent code that's doing just about the same
>> thing for those other transient failures.  Why is the timeout duration
>> different?  Why is the looping logic not identical?  Why did you make a
>> different decision about whether logging might be a good idea?  Actually,
>> why didn't you just extend the existing if-block to also cover this case?
>> Maybe there's good reasons to be different, but you didn't explain them.

> Second, I wanted to decrease a delay, as whole unlink operation
> (comprising of three kernel calls: CreateFile,
> SetDispositionInformationFile, CloseFile) performed for me in 0.0002
> seconds (as ProcessMonitor showed for several runs). Assuming even
> hundredfold duration seems sufficient.

Fair enough.  I wonder btw whether the 100ms wait quantum isn't
ridiculously long for modern machines.  We'd have to change it for
both conditions though to avoid odd behavior (or use two separate
wait counters?), so I didn't mess with that for now.

> Third, the logic of the existing loop confused me — I haven't seen a
> reason to sleep for a last time and then return an error without
> rechecking a condition.

That is pretty bogus now that you mention it, but the answer is to fix
it not just avert your eyes.

> And I think that the logging is irrelevant as we want to handle here
> just the DELETE_PENDING state.

True, if we're not going to wait very long then there's little need
to log.

I've pushed this with adjustment of the other loop and some fooling
with the comment --- I still don't see a need to cite stackoverflow
as an authority.

			regards, tom lane

  6. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-17T03:00:00Z

    16.12.2019 23:17, Tom Lane wrote:
>
> I've pushed this with adjustment of the other loop and some fooling
> with the comment --- I still don't see a need to cite stackoverflow
> as an authority.
Thank you! I hope now Windows machines will concede the first place of
the race for failures.

Best regards,
Alexander

  7. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-17T23:50:26Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> 16.12.2019 23:17, Tom Lane wrote:
>> I've pushed this with adjustment of the other loop and some fooling
>> with the comment --- I still don't see a need to cite stackoverflow
>> as an authority.

> Thank you! I hope now Windows machines will concede the first place of
> the race for failures.

Seems like we're not there yet :-(.  Buildfarm members jacana and
fairywren have been failing the recovery tests, in v10 and up,
since this went in.  It looks like we're getting a timeout on
this step in 010_logical_decoding_timelines.pl:

# Should be able to read from slot created before base backup
($ret, $stdout, $stderr) = $node_replica->psql(
	'postgres',
	"SELECT data FROM pg_logical_slot_peek_changes('before_basebackup', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');",
	timeout => 30);

Now, it's mighty suspicious that this has a timeout of 30 sec
which is exactly how long we made pgwin32_open retry for ---
but how is it that this test is causing an ERROR_ACCESS_DENIED
failure?  And if it was, how did we get past that before?

It does look suspiciously like this wait is triggering on these
machines and somehow getting masked in most other test cases.
If you compare the per-step runtimes in jacana's last successful
run,

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2019-12-16%2013%3A01%3A26

with those after this patch went in,

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2019-12-17%2004%3A16%3A40

there's clearly something very wrong.  fairywren likewise.

			regards, tom lane

  8. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-18T03:25:26Z

    At Tue, 17 Dec 2019 18:50:26 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> Alexander Lakhin <exclusion@gmail.com> writes:
> > 16.12.2019 23:17, Tom Lane wrote:
> >> I've pushed this with adjustment of the other loop and some fooling
> >> with the comment --- I still don't see a need to cite stackoverflow
> >> as an authority.
> 
> > Thank you! I hope now Windows machines will concede the first place of
> > the race for failures.
> 
> Seems like we're not there yet :-(.  Buildfarm members jacana and
> fairywren have been failing the recovery tests, in v10 and up,
> since this went in.  It looks like we're getting a timeout on
> this step in 010_logical_decoding_timelines.pl:
> 
> # Should be able to read from slot created before base backup
> ($ret, $stdout, $stderr) = $node_replica->psql(
> 	'postgres',
> 	"SELECT data FROM pg_logical_slot_peek_changes('before_basebackup', NULL, NULL, 'include-xids', '0', 'skip-empty-xacts', '1');",
> 	timeout => 30);
> 
> Now, it's mighty suspicious that this has a timeout of 30 sec
> which is exactly how long we made pgwin32_open retry for ---
> but how is it that this test is causing an ERROR_ACCESS_DENIED
> failure?  And if it was, how did we get past that before?
> 
> It does look suspiciously like this wait is triggering on these
> machines and somehow getting masked in most other test cases.
> If you compare the per-step runtimes in jacana's last successful
> run,
> 
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2019-12-16%2013%3A01%3A26
> 
> with those after this patch went in,
> 
> https://buildfarm.postgresql.org/cgi-bin/shocw_log.pl?nm=jacana&dt=2019-12-17%2004%3A16%3A40
> 
> there's clearly something very wrong.  fairywren likewise.

The immediate cause of the failure seems to be a slowdown of startup
or recovery. It took only 8 minutes in the successful case but 25
minutes even though stopped on the way in the failure case.

In the failure case, it took 30 seconds to move only 26.1MB from
15E8C48 to 30013A0. just around 0.3 seconds for a move of the same
size (15E9C48->3000DE8 (26.1MB)) in the successful case (*1). In the
sucessful case, the time took from archiving 00000002.history to
removing old segments is 0.15 s, but about 3.5 s in the failure case
(*2).

Seemingly the immediate cause of the timeout looks like just an
extreme slowdown of file read, but it took 2 seconds to move within a
page from 3000C18 to 3000C50. So I suspect that 6d7547c219 might slow
down readTimeLineHistory() significantly in the case.

regards.


*1: jacana - WAL reading
Success
2019-12-16 09:01:01.805 EST [5df78e1d.b74:4] 010_logical_decoding_timelines.pl LOG:  starting logical decoding for slot "before_basebackup"
2019-12-16 09:01:01.805 EST [5df78e1d.b74:5] 010_logical_decoding_timelines.pl DETAIL:  Streaming transactions committing after 0/15CC960, reading WAL from 0/15CC928.
...
2019-12-16 09:01:01.836 EST [5df78e1d.b74:34] 010_logical_decoding_timelines.pl DEBUG:  failed to increase restart lsn: proposed 0/3000DE8, after 0/3000DE8, current candidate 0/15E9C48, current after 0/15E9C48, flushed up to 0/15CC960


Fail
2019-12-17 01:35:02.235 EST [5df87716.2ddc:4] 010_logical_decoding_timelines.pl LOG:  starting logical decoding for slot "before_basebackup"
2019-12-17 01:35:02.235 EST [5df87716.2ddc:5] 010_logical_decoding_timelines.pl DETAIL:  Streaming transactions committing after 0/15CC960, reading WAL from 0/15CC928.
...
2019-12-17 01:35:24.195 EST [5df87716.2ddc:33] 010_logical_decoding_timelines.pl DEBUG:  failed to increase restart lsn: proposed 0/3000C18, after 0/3000C18, current candidate 0/15E9C48, current after 0/15E9C48, flushed up to 0/15CC960
2019-12-17 01:35:24.195 EST [5df87716.2ddc:34] 010_logical_decoding_timelines.pl DEBUG:  serializing snapshot to pg_logical/snapshots/0-3000C50.snap
2019-12-17 01:35:26.379 EST [5df87716.2ddc:35] 010_logical_decoding_timelines.pl DEBUG:  failed to increase restart lsn: proposed 0/3000C50, after 0/3000C50, current candidate 0/15E9C48, current after 0/15E9C48, flushed up to 0/15CC960
2019-12-17 01:35:26.379 EST [5df87716.2ddc:36] 010_logical_decoding_timelines.pl DEBUG:  serializing snapshot to pg_logical/snapshots/0-3000D68.snap
2019-12-17 01:35:28.575 EST [5df87716.2ddc:37] 010_logical_decoding_timelines.pl DEBUG:  failed to increase restart lsn: proposed 0/3000D68, after 0/3000D68, current candidate 0/15E9C48, current after 0/15E9C48, flushed up to 0/15CC960
2019-12-17 01:35:28.575 EST [5df87716.2ddc:38] 010_logical_decoding_timelines.pl DEBUG:  serializing snapshot to pg_logical/snapshots/0-30012F0.snap
2019-12-17 01:35:30.775 EST [5df87716.2ddc:39] 010_logical_decoding_timelines.pl DEBUG:  failed to increase restart lsn: proposed 0/30012F0, after 0/30012F0, current candidate 0/15E9C48, current after 0/15E9C48, flushed up to 0/15CC960
2019-12-17 01:35:30.775 EST [5df87716.2ddc:40] 010_logical_decoding_timelines.pl DEBUG:  serializing snapshot to pg_logical/snapshots/0-30013A0.snap


====
*2: jacana - checkpoint
Success
2019-12-16 09:01:01.399 EST [5df78e1d.170c:1] DEBUG:  archived write-ahead log file "00000002.history"
2019-12-16 09:01:01.430 EST [5df78e1d.170c:2] DEBUG:  archived write-ahead log file "000000010000000000000003.partial"
2019-12-16 09:01:01.445 EST [5df78e1b.2f60:4] DEBUG:  attempting to remove WAL segments older than log file 000000000000000000000000
2019

Fail
2019-12-17 01:35:01.950 EST [5df87715.2e0c:1] DEBUG:  archived write-ahead log file "00000002.history"
2019-12-17 01:35:03.080 EST [5df87715.2e0c:2] DEBUG:  archived write-ahead log file "000000010000000000000003.partial"
2019-12-17 01:35:05.389 EST [5df876ed.3370:4] DEBUG:  attempting to remove WAL segments older than log file 000000000000000000000000

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  9. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-18T06:00:00Z

    Hello,
18.12.2019 6:25, Kyotaro Horiguchi wrote:
> At Tue, 17 Dec 2019 18:50:26 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
>>
>> Now, it's mighty suspicious that this has a timeout of 30 sec
>> which is exactly how long we made pgwin32_open retry for ---
>> but how is it that this test is causing an ERROR_ACCESS_DENIED
>> failure?  And if it was, how did we get past that before?
Not exactly, we set timeout for 1 sec. It seems we have this timeout
occurred many times.
>> It does look suspiciously like this wait is triggering on these
>> machines and somehow getting masked in most other test cases.
>> If you compare the per-step runtimes in jacana's last successful
>> run,
>>
>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2019-12-16%2013%3A01%3A26
>>
>> with those after this patch went in,
>>
>> https://buildfarm.postgresql.org/cgi-bin/shocw_log.pl?nm=jacana&dt=2019-12-17%2004%3A16%3A40
>>
>> there's clearly something very wrong.  fairywren likewise.
> The immediate cause of the failure seems to be a slowdown of startup
> or recovery. It took only 8 minutes in the successful case but 25
> minutes even though stopped on the way in the failure case.
>
> In the failure case, it took 30 seconds to move only 26.1MB from
> 15E8C48 to 30013A0. just around 0.3 seconds for a move of the same
> size (15E9C48->3000DE8 (26.1MB)) in the successful case (*1). In the
> sucessful case, the time took from archiving 00000002.history to
> removing old segments is 0.15 s, but about 3.5 s in the failure case
> (*2).
>
> Seemingly the immediate cause of the timeout looks like just an
> extreme slowdown of file read, but it took 2 seconds to move within a
> page from 3000C18 to 3000C50. So I suspect that 6d7547c219 might slow
> down readTimeLineHistory() significantly in the case.
>
> regards.
>
>
Yes, some tests are really slowed down (namely, test-decoding-check,
pg_basebackup-check, ...).
ProcessMonitor shows:

"8:11:57.1428800
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","SUCCESS",...
"8:11:57.1429851
AM","postgres.exe","2640","SetRenameInformationFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state.tmp","SUCCESS",...
"8:11:57.1432041
AM","postgres.exe","2640","CloseFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","SUCCESS",""
"8:11:57.1432964
AM","postgres.exe","2640","CloseFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state","SUCCESS",""
"8:11:57.1435137
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state","SUCCESS",...
"8:11:57.1435709
AM","postgres.exe","2640","CloseFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot\state","SUCCESS",""
"8:11:57.1437251
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.2451100
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.3571077
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.4643527
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.5778052
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.6825679
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.7921704
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:57.9018507
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.0109597
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.1204329
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.2300829
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY",...
"8:11:58.2302124
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.3393345
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.4484310
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.5584079
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.6683586
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.7773396
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.8858091
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:58.9955264
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.1050665
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.2137752
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.3234641
AM","postgres.exe","2640","CreateFile","...\t_006_logical_decoding_master_data\pgdata\pg_replslot","IS
DIRECTORY",...
"8:11:59.3261361
AM","postgres.exe","2640","QueryOpen","C:\Windows\System32\kernel.appcore.dll","FAST
IO DISALLOWED",""

https://web.archive.org/web/20150317121919/http://support.microsoft.com/en-us/kb/113996
tells that STATUS_FILE_IS_A_DIRECTORY is mapped to ERROR_ACCESS_DENIED too.
It seems that the cause of the issue is in fsync_fname_ext:
    fd = OpenTransientFile(fname, flags);

    /*
     * Some OSs don't allow us to open directories at all (Windows returns
     * EACCES), just ignore the error in that case.  If desired also
silently
     * ignoring errors about unreadable files. Log others.
     */
    if (fd < 0 && isdir && (errno == EISDIR || errno == EACCES))
        return 0;
Maybe we need to take isdir into account before calling
OpenTransientFile on Windows...
Please look at the simple patch that makes the recoverycheck test pass.

Best regards,
Alexander

  10. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-18T16:03:11Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> 18.12.2019 6:25, Kyotaro Horiguchi wrote:
>> At Tue, 17 Dec 2019 18:50:26 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
>>> It does look suspiciously like this wait is triggering on these
>>> machines and somehow getting masked in most other test cases.

> https://web.archive.org/web/20150317121919/http://support.microsoft.com/en-us/kb/113996
> tells that STATUS_FILE_IS_A_DIRECTORY is mapped to ERROR_ACCESS_DENIED too.

Ugh.  I wondered if we could really get away with slowing down all
ERROR_ACCESS_DENIED cases.

> It seems that the cause of the issue is in fsync_fname_ext:

I think you're blaming the messenger.  We cannot suddenly impose a
rule that people mustn't try to open() files that might be directories.
Even if fsync_fname_ext() happens to be the only place that does that
today (which I doubt) it's going to bite us on the rear regularly in
the future, because there's no way to enforce it, and most developers
aren't going to notice the problem in testing.

It's possible that we could deal with this specific case by having
pgwin32_open() try to stat the file and see if it's a directory.  But
I think that's messy.  Also, the list of kernel-level conditions that
that webpage says are mapped to ERROR_ACCESS_DENIED is scarily long:

STATUS_THREAD_IS_TERMINATING            ERROR_ACCESS_DENIED
STATUS_PROCESS_IS_TERMINATING           ERROR_ACCESS_DENIED
STATUS_INVALID_LOCK_SEQUENCE            ERROR_ACCESS_DENIED
STATUS_INVALID_VIEW_SIZE                ERROR_ACCESS_DENIED
STATUS_ALREADY_COMMITTED                ERROR_ACCESS_DENIED
STATUS_ACCESS_DENIED                    ERROR_ACCESS_DENIED
STATUS_FILE_IS_A_DIRECTORY              ERROR_ACCESS_DENIED
STATUS_CANNOT_DELETE                    ERROR_ACCESS_DENIED
STATUS_FILE_DELETED                     ERROR_ACCESS_DENIED
STATUS_FILE_RENAMED                     ERROR_ACCESS_DENIED
STATUS_DELETE_PENDING                   ERROR_ACCESS_DENIED
STATUS_PORT_CONNECTION_REFUSED          ERROR_ACCESS_DENIED
...
STATUS_ENCRYPTION_FAILED                ERROR_ACCESS_DENIED
STATUS_DECRYPTION_FAILED                ERROR_ACCESS_DENIED
STATUS_NO_RECOVERY_POLICY               ERROR_ACCESS_DENIED
STATUS_NO_EFS                           ERROR_ACCESS_DENIED
STATUS_WRONG_EFS                        ERROR_ACCESS_DENIED
STATUS_NO_USER_KEYS                     ERROR_ACCESS_DENIED
...
SEC_E_MESSAGE_ALTERED                   ERROR_ACCESS_DENIED   
SEC_E_OUT_OF_SEQUENCE                   ERROR_ACCESS_DENIED   

Maybe most of these can't occur during fopen, but I'd
rather not assume that.

Is there a way to get the original kernel error code?
It'd be a lot better if we could be sure that the condition
is STATUS_DELETE_PENDING before looping.

			regards, tom lane

  11. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-18T19:00:01Z

    18.12.2019 19:03, Tom Lane wrote:
> Alexander Lakhin <exclusion@gmail.com> writes:
>> 18.12.2019 6:25, Kyotaro Horiguchi wrote:
>>> At Tue, 17 Dec 2019 18:50:26 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
>>>> It does look suspiciously like this wait is triggering on these
>>>> machines and somehow getting masked in most other test cases.
>> https://web.archive.org/web/20150317121919/http://support.microsoft.com/en-us/kb/113996
>> tells that STATUS_FILE_IS_A_DIRECTORY is mapped to ERROR_ACCESS_DENIED too.
> Ugh.  I wondered if we could really get away with slowing down all
> ERROR_ACCESS_DENIED cases.
>
>> It seems that the cause of the issue is in fsync_fname_ext:
> I think you're blaming the messenger.  We cannot suddenly impose a
> rule that people mustn't try to open() files that might be directories.
> Even if fsync_fname_ext() happens to be the only place that does that
> today (which I doubt) it's going to bite us on the rear regularly in
> the future, because there's no way to enforce it, and most developers
> aren't going to notice the problem in testing.
Regarding fsync_fname_ext(), I thought that it's OK to avoid performing
a call that is known to fail. And even if someone will try to open() a
directory, he will need to add the same check for EACCES, otherwise the
code will fail on Windows. In fact, I see the same pattern in
pre_sync_fname, fsync_fname in file_utils.c.
> It's possible that we could deal with this specific case by having
> pgwin32_open() try to stat the file and see if it's a directory.  But
> I think that's messy.  Also, the list of kernel-level conditions that
> that webpage says are mapped to ERROR_ACCESS_DENIED is scarily long:
>
> STATUS_THREAD_IS_TERMINATING            ERROR_ACCESS_DENIED
> STATUS_PROCESS_IS_TERMINATING           ERROR_ACCESS_DENIED
> STATUS_INVALID_LOCK_SEQUENCE            ERROR_ACCESS_DENIED
> STATUS_INVALID_VIEW_SIZE                ERROR_ACCESS_DENIED
> STATUS_ALREADY_COMMITTED                ERROR_ACCESS_DENIED
> STATUS_ACCESS_DENIED                    ERROR_ACCESS_DENIED
> STATUS_FILE_IS_A_DIRECTORY              ERROR_ACCESS_DENIED
> STATUS_CANNOT_DELETE                    ERROR_ACCESS_DENIED
> STATUS_FILE_DELETED                     ERROR_ACCESS_DENIED
> STATUS_FILE_RENAMED                     ERROR_ACCESS_DENIED
> STATUS_DELETE_PENDING                   ERROR_ACCESS_DENIED
> STATUS_PORT_CONNECTION_REFUSED          ERROR_ACCESS_DENIED
> ...
> STATUS_ENCRYPTION_FAILED                ERROR_ACCESS_DENIED
> STATUS_DECRYPTION_FAILED                ERROR_ACCESS_DENIED
> STATUS_NO_RECOVERY_POLICY               ERROR_ACCESS_DENIED
> STATUS_NO_EFS                           ERROR_ACCESS_DENIED
> STATUS_WRONG_EFS                        ERROR_ACCESS_DENIED
> STATUS_NO_USER_KEYS                     ERROR_ACCESS_DENIED
> ...
> SEC_E_MESSAGE_ALTERED                   ERROR_ACCESS_DENIED   
> SEC_E_OUT_OF_SEQUENCE                   ERROR_ACCESS_DENIED   
>
> Maybe most of these can't occur during fopen, but I'd
> rather not assume that
I see your point about future uncertainty, but I don't think that
receiving e.g. STATUS_FILE_DELETED or STATUS_NO_EFS error every few
seconds and ignoring it is a normal practice.
> Is there a way to get the original kernel error code?
> It'd be a lot better if we could be sure that the condition
> is STATUS_DELETE_PENDING before looping.
Unfortunately no, there is no known way  to get the kernel error code.
As stated in https://stackoverflow.com/questions/3764072, there is the
GetFileInformationByHandleEx
<http://msdn.microsoft.com/en-us/library/aa364953(v=VS.85).aspx>
function, that can return DeletePending state, but to use it we should
open the file first (to get a file handle).

So I see three ways now:
1) Revert the pgwin32_open change and choose the previously rejected
approach: Unlink postmaster.pid using rename operation (adopt the
solution from https://stackoverflow.com/questions/3764072/).
2) Add a check for directory in pgwin32_open, but I think then we're
getting close to checking there just for postmaster.pid.
3) Find out how often we get ERROR_ACCESS_DENIED during all regression
tests and if such error count is near zero, then add the check for isdir
in fsync_fname_ext and friends, and get done.

I'm still thinking that we shouldn't perform doomed calls, but I'm ready
to change the course.

Best regards,
Alexander

  12. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-18T22:09:15Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> 18.12.2019 19:03, Tom Lane wrote:
>> Even if fsync_fname_ext() happens to be the only place that does that
>> today (which I doubt) it's going to bite us on the rear regularly in
>> the future, because there's no way to enforce it, and most developers
>> aren't going to notice the problem in testing.

> Regarding fsync_fname_ext(), I thought that it's OK to avoid performing
> a call that is known to fail. And even if someone will try to open() a
> directory, he will need to add the same check for EACCES, otherwise the
> code will fail on Windows. In fact, I see the same pattern in
> pre_sync_fname, fsync_fname in file_utils.c.

My point is that it's totally unreasonable to expect callers to always
know, in advance of accessing the filesystem, whether the pathname they
are going to access is a directory or not.  The point of calling a
filesystem access function is to find out that kind of information.
Yes, there are many cases where we can expect that PG can predict
this, but an open() replacement has no business making such a sweeping
assumption about its use-cases.

>> Is there a way to get the original kernel error code?
>> It'd be a lot better if we could be sure that the condition
>> is STATUS_DELETE_PENDING before looping.

> Unfortunately no, there is no known way  to get the kernel error code.

Bleah.  I did a little bit of googling and couldn't find anything
to contradict that, but it's sure annoying.

> So I see three ways now:
> 1) Revert the pgwin32_open change and choose the previously rejected
> approach: Unlink postmaster.pid using rename operation (adopt the
> solution from https://stackoverflow.com/questions/3764072/).
> 2) Add a check for directory in pgwin32_open, but I think then we're
> getting close to checking there just for postmaster.pid.
> 3) Find out how often we get ERROR_ACCESS_DENIED during all regression
> tests and if such error count is near zero, then add the check for isdir
> in fsync_fname_ext and friends, and get done.

I'm not terribly thrilled with (1) because I do not think that
postmaster.pid accesses are the only place where we have this issue.
And (3) is not only not a forward-looking solution, but it imagines
that the speed of the regression tests is the only thing we need to
worry about here.  We generally don't assume that the regression
tests are an accurate model of the performance users will see.

So that leaves us with (2), it seems.

			regards, tom lane

  13. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-19T01:39:48Z

    At Wed, 18 Dec 2019 17:09:15 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> Alexander Lakhin <exclusion@gmail.com> writes:
> > 18.12.2019 19:03, Tom Lane wrote:
> >> Even if fsync_fname_ext() happens to be the only place that does that
> >> today (which I doubt) it's going to bite us on the rear regularly in
> >> the future, because there's no way to enforce it, and most developers
> >> aren't going to notice the problem in testing.
> 
> > Regarding fsync_fname_ext(), I thought that it's OK to avoid performing
> > a call that is known to fail. And even if someone will try to open() a
> > directory, he will need to add the same check for EACCES, otherwise the
> > code will fail on Windows. In fact, I see the same pattern in
> > pre_sync_fname, fsync_fname in file_utils.c.
> 
> My point is that it's totally unreasonable to expect callers to always
> know, in advance of accessing the filesystem, whether the pathname they
> are going to access is a directory or not.  The point of calling a
> filesystem access function is to find out that kind of information.
> Yes, there are many cases where we can expect that PG can predict
> this, but an open() replacement has no business making such a sweeping
> assumption about its use-cases.
> 
> >> Is there a way to get the original kernel error code?
> >> It'd be a lot better if we could be sure that the condition
> >> is STATUS_DELETE_PENDING before looping.
> 
> > Unfortunately no, there is no known way  to get the kernel error code.
> 
> Bleah.  I did a little bit of googling and couldn't find anything
> to contradict that, but it's sure annoying.

The codes seems to be indentifiable only on device driver layer.

> > So I see three ways now:
> > 1) Revert the pgwin32_open change and choose the previously rejected
> > approach: Unlink postmaster.pid using rename operation (adopt the
> > solution from https://stackoverflow.com/questions/3764072/).
> > 2) Add a check for directory in pgwin32_open, but I think then we're
> > getting close to checking there just for postmaster.pid.
> > 3) Find out how often we get ERROR_ACCESS_DENIED during all regression
> > tests and if such error count is near zero, then add the check for isdir
> > in fsync_fname_ext and friends, and get done.
> 
> I'm not terribly thrilled with (1) because I do not think that
> postmaster.pid accesses are the only place where we have this issue.
> And (3) is not only not a forward-looking solution, but it imagines
> that the speed of the regression tests is the only thing we need to
> worry about here.  We generally don't assume that the regression
> tests are an accurate model of the performance users will see.
> 
> So that leaves us with (2), it seems.

Agreed for (2).

I'm not sure about the point of the discussion that stat()'ing is
messy. If it's about performance, does stat()ing only when CreateFile
returned ERROR_ACCESS_DENIED helps? Anyway we wait for a moment in
that case.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  14. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-19T04:00:00Z

    19.12.2019 4:39, Kyotaro Horiguchi wrote:
> At Wed, 18 Dec 2019 17:09:15 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
>> Alexander Lakhin <exclusion@gmail.com> writes:
>>> So I see three ways now:
>>> 1) Revert the pgwin32_open change and choose the previously rejected
>>> approach: Unlink postmaster.pid using rename operation (adopt the
>>> solution from https://stackoverflow.com/questions/3764072/).
>>> 2) Add a check for directory in pgwin32_open, but I think then we're
>>> getting close to checking there just for postmaster.pid.
>>> 3) Find out how often we get ERROR_ACCESS_DENIED during all regression
>>> tests and if such error count is near zero, then add the check for isdir
>>> in fsync_fname_ext and friends, and get done.
>> I'm not terribly thrilled with (1) because I do not think that
>> postmaster.pid accesses are the only place where we have this issue.
>> And (3) is not only not a forward-looking solution, but it imagines
>> that the speed of the regression tests is the only thing we need to
>> worry about here.  We generally don't assume that the regression
>> tests are an accurate model of the performance users will see.
>>
>> So that leaves us with (2), it seems.
> Agreed for (2).
>
> I'm not sure about the point of the discussion that stat()'ing is
> messy. If it's about performance, does stat()ing only when CreateFile
> returned ERROR_ACCESS_DENIED helps? Anyway we wait for a moment in
> that case.
Please look at the patch that implements (2). It makes `vcregress
recoverycheck` pass (and my demo restart test still passes too).
As open(dir) is getting a little more expensive than before, maybe it's
still worthwhile to patch fsync*(..., isdir,...). I can prepare such a
patch if so.

Best regards,
Alexander

  15. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-19T05:11:45Z

    At Thu, 19 Dec 2019 07:00:00 +0300, Alexander Lakhin <exclusion@gmail.com> wrote in 
> 19.12.2019 4:39, Kyotaro Horiguchi wrote:
> > At Wed, 18 Dec 2019 17:09:15 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> >> Alexander Lakhin <exclusion@gmail.com> writes:
> >>> So I see three ways now:
> >>> 1) Revert the pgwin32_open change and choose the previously rejected
> >>> approach: Unlink postmaster.pid using rename operation (adopt the
> >>> solution from https://stackoverflow.com/questions/3764072/).
> >>> 2) Add a check for directory in pgwin32_open, but I think then we're
> >>> getting close to checking there just for postmaster.pid.
> >>> 3) Find out how often we get ERROR_ACCESS_DENIED during all regression
> >>> tests and if such error count is near zero, then add the check for isdir
> >>> in fsync_fname_ext and friends, and get done.
> >> I'm not terribly thrilled with (1) because I do not think that
> >> postmaster.pid accesses are the only place where we have this issue.
> >> And (3) is not only not a forward-looking solution, but it imagines
> >> that the speed of the regression tests is the only thing we need to
> >> worry about here.  We generally don't assume that the regression
> >> tests are an accurate model of the performance users will see.
> >>
> >> So that leaves us with (2), it seems.
> > Agreed for (2).
> >
> > I'm not sure about the point of the discussion that stat()'ing is
> > messy. If it's about performance, does stat()ing only when CreateFile
> > returned ERROR_ACCESS_DENIED helps? Anyway we wait for a moment in
> > that case.
> Please look at the patch that implements (2). It makes `vcregress
> recoverycheck` pass (and my demo restart test still passes too).
> As open(dir) is getting a little more expensive than before, maybe it's
> still worthwhile to patch fsync*(..., isdir,...). I can prepare such a
> patch if so.

Sorry, I hadn't looked it.

+#ifdef WIN32
+	/* Windows doesn't allow us to open directories at all.
+	*/
+	if (isdir)
+		return 0;
+#endif

Doesn't it need to handle ENOENT or anything that can happen if
OpenTransientFile() were called?

And.. how do we regard about the crash-safetiness on Windows?  After
some googling it seems that not only CreateFile but also fsync on
directories cannot be performed on Windows at all.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  16. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-19T15:44:08Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> Please look at the patch that implements (2). It makes `vcregress
> recoverycheck` pass (and my demo restart test still passes too).

I think we could be a little smarter here.  If the problem is
STATUS_DELETE_PENDING, doesn't that affect stat() as well?  That is,
if stat() succeeds, we needn't wait, independently of whether it
says S_ISDIR or not?  This seems like a noticeable improvement if
true, because it would mean that ordinary file-permission failures
also need not wait.  We'd still get confused if we get a permission
failure on a containing directory rather than the file itself, but
that I'm prepared to dismiss as an uncommon case.

Entirely-untested patch along this line attached.

BTW ... it's likely that stat() here is actually going to invoke
pgwin32_safestat(), which has its own opinions about this, and
indeed seems to think we'll get ERROR_DELETE_PENDING.  I think
that's harmless here, but it makes me wonder if we should use
a native Windows API instead of going through stat().

> As open(dir) is getting a little more expensive than before, maybe it's
> still worthwhile to patch fsync*(..., isdir,...). I can prepare such a
> patch if so.

I think we should leave that for later, so that the buildfarm can
actually test whatever logic we put in here.

			regards, tom lane

  17. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-19T20:00:00Z

    19.12.2019 18:44, Tom Lane wrote:
> Alexander Lakhin <exclusion@gmail.com> writes:
>> Please look at the patch that implements (2). It makes `vcregress
>> recoverycheck` pass (and my demo restart test still passes too).
> I think we could be a little smarter here.  If the problem is
> STATUS_DELETE_PENDING, doesn't that affect stat() as well?  That is,
> if stat() succeeds, we needn't wait, independently of whether it
> says S_ISDIR or not?  This seems like a noticeable improvement if
> true, because it would mean that ordinary file-permission failures
> also need not wait.  We'd still get confused if we get a permission
> failure on a containing directory rather than the file itself, but
> that I'm prepared to dismiss as an uncommon case.
>
> Entirely-untested patch along this line attached.
I have tested it with my demo restart test and it works. Yes, stat() is
resulted in the CreateFile() call too, so it should fail the same way. 
I haven't managed to catch both CreateFile() and stat() failing with
STATUS_DELETE_PENDING (CreateFile() failed for me 37 times per 1000
loops), but I believe that sleep() will work correctly in this case.
`vcregress recoverytest` is passed too.
The DELETE_PENDING conflict now looks like this:
1 "8:50:44.9928200
PM","postgres.exe","2792","CreateFile","...\pgdata\postmaster.pid","SUCCESS","Desired
Access: Read Attributes, Delete, ..."
2 "8:50:44.9928951
PM","postgres.exe","2792","QueryAttributeTagFile","...\pgdata\postmaster.pid","SUCCESS",...
3 "8:50:44.9929114
PM","pg_ctl.exe","2996","CreateFile","...\pgdata\postmaster.pid","DELETE
PENDING","Desired Access: Generic Read, Disposition: Open, ..."
4 "8:50:44.9929162
PM","postgres.exe","2792","SetDispositionInformationFile","...\pgdata\postmaster.pid","SUCCESS","Delete:
True"
5 "8:50:44.9929377
PM","postgres.exe","2792","CloseFile","...\pgdata\postmaster.pid","SUCCESS",""
6 "8:50:44.9932617
PM","pg_ctl.exe","2996","CreateFile","...\pgdata\postmaster.pid","NAME
NOT FOUND","Desired Access: Read Attributes, ..."
7 "8:50:45.1042027
PM","pg_ctl.exe","2996","CreateFile","...\pgdata\postmaster.pid","NAME
NOT FOUND","Desired Access: Generic Read, ..."
8 "8:50:45.9926445
PM","pg_ctl.exe","2396","CreateFile","...\pgdata\postmaster.pid","NAME
NOT FOUND","Desired Access: Generic Read ..."
Here 1, 2, 4, 5 are calls behind unlink() in postmaster, 3 is
CreateFile() in pgwin32_open(), 6 is stat() in pgwin32_safestat(), then
we have sleep for 0.1 sec, 7 is CreateFile() in pgwin32_open() again,
and 8 is CreateFile() performed by a new pg_ctl instance.

Maybe we should change the condition to 'if (stat(fileName, &st) != 0 &&
(err = GetLastError()) == ERROR_ACCESS_DENIED)' to avoid unnecessary
sleep with a loop iteration...
With this change the same conflict looks like this:
1 "10:23:12.9940793
PM","postgres.exe","1908","CreateFile","...\pgdata\postmaster.pid","SUCCESS","Desired
Access: Read Attributes, ..."
2 "10:23:12.9941500
PM","postgres.exe","1908","QueryAttributeTagFile","...\pgdata\postmaster.pid","SUCCESS",
...
3 "10:23:12.9941713
PM","postgres.exe","1908","SetDispositionInformationFile","...\pgdata\postmaster.pid","SUCCESS","Delete:
True"
4 "10:23:12.9941766
PM","pg_ctl.exe","2420","CreateFile","...\pgdata\postmaster.pid","DELETE
PENDING","Desired Access: Generic Read ..."
5 "10:23:12.9941936
PM","postgres.exe","1908","CloseFile","...\pgdata\postmaster.pid","SUCCESS",""
6 "10:23:12.9945254
PM","pg_ctl.exe","2420","CreateFile","...\pgdata\postmaster.pid","NAME
NOT FOUND","Desired Access: Read Attributes, ..."
7 "10:23:13.9940261
PM","pg_ctl.exe","1676","CreateFile","...\pgdata\postmaster.pid","NAME
NOT FOUND","Desired Access: Generic Read, ..."
Here 1, 2, 3, 5 are calls behind unlink() in postmaster, 4 is
CreateFile() in pgwin32_open(), 6 is stat() in pgwin32_safestat(), 7 is
CreateFile() performed by a new pg_ctl instance.
`vcregress recoverytest` is passed.
The log of access to the logical decoding slot now looks like this:
1 "10:37:22.9496662
PM","postgres.exe","2956","CreateFile","...\pgdata\pg_replslot\otherdb_slot","IS
DIRECTORY","Desired Access: Generic Read, ..."
2 "10:37:22.9498061
PM","postgres.exe","2956","CreateFile","...\pgdata\pg_replslot\otherdb_slot","SUCCESS","Desired
Access: Read Attributes, ..."
3 "10:37:22.9498478
PM","postgres.exe","2956","QueryInformationVolume","...\pgdata\pg_replslot\otherdb_slot","SUCCESS","VolumeCreationTime:
... "
4 "10:37:22.9498634
PM","postgres.exe","2956","QueryAllInformationFile","...\pgdata\pg_replslot\otherdb_slot","BUFFER
OVERFLOW","CreationTime: ..."
5 "10:37:22.9498860
PM","postgres.exe","2956","CloseFile","...\pgdata\pg_replslot\otherdb_slot","SUCCESS",""
6 "10:37:22.9499936
PM","postgres.exe","2956","QueryOpen","...\pgdata\pg_replslot\otherdb_slot","FAST
IO DISALLOWED",""
7 "10:37:22.9500733
PM","postgres.exe","2956","CreateFile","...\pgdata\pg_replslot\otherdb_slot","SUCCESS","Desired
Access: ..."
8 "10:37:22.9500973
PM","postgres.exe","2956","QueryNetworkOpenInformationFile","...\pgdata\pg_replslot\otherdb_slot","SUCCESS","CreationTime:..."
9 "10:37:22.9501108
PM","postgres.exe","2956","CloseFile","...\pgdata\pg_replslot\otherdb_slot","SUCCESS",""

> BTW ... it's likely that stat() here is actually going to invoke
> pgwin32_safestat(), which has its own opinions about this, and
> indeed seems to think we'll get ERROR_DELETE_PENDING.  I think
> that's harmless here, but it makes me wonder if we should use
> a native Windows API instead of going through stat().
Yes, I would call native stat(), as we don't need to perform an
excessive call to get file size (for directories).
It seems that the check for ERROR_DELETE_PENDING was added to
pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com

>> As open(dir) is getting a little more expensive than before, maybe it's
>> still worthwhile to patch fsync*(..., isdir,...). I can prepare such a
>> patch if so.
> I think we should leave that for later, so that the buildfarm can
> actually test whatever logic we put in here.
Agreed. It doesn't directly affect this bug and should be done separately.

Best regards,
Alexander

  18. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-19T20:09:45Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> Maybe we should change the condition to 'if (stat(fileName, &st) != 0 &&
> (err = GetLastError()) == ERROR_ACCESS_DENIED)' to avoid unnecessary
> sleep with a loop iteration...

Well, we have to loop back on file-not-found too ...

> It seems that the check for ERROR_DELETE_PENDING was added to
> pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
> https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com

Hmm, makes one wonder whether that's actually live code.

			regards, tom lane

  19. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Juan José Santamaría Flecha <juanjo.santamaria@gmail.com> — 2019-12-19T20:49:54Z

    On Thu, Dec 19, 2019 at 9:09 PM Tom Lane <tgl@sss.pgh.pa.us> wrote:

>
> > It seems that the check for ERROR_DELETE_PENDING was added to
> > pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
> >
> https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com
>
> Hmm, makes one wonder whether that's actually live code.
>
>
Part of what the patch "Windows could not stat file - over 4GB" [1] does is
proposing an alternative using native functions.

[1] https://commitfest.postgresql.org/26/2189/

Regards,

Juan José Santamaría Flecha

  20. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-20T02:40:00Z

    19.12.2019 23:09, Tom Lane wrote:
> Alexander Lakhin <exclusion@gmail.com> writes:
>> Maybe we should change the condition to 'if (stat(fileName, &st) != 0 &&
>> (err = GetLastError()) == ERROR_ACCESS_DENIED)' to avoid unnecessary
>> sleep with a loop iteration...
> Well, we have to loop back on file-not-found too ...
I think, if the file is not found on stat() we can safely return the
updated err (set errno with _dosmapper(err), to be exact). If we'll loop
back, we'll get the same err = GetLastError() after next CreateFile().
>> It seems that the check for ERROR_DELETE_PENDING was added to
>> pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
>> https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com
> Hmm, makes one wonder whether that's actually live code.
I'll try to research this matter meantime.

Best regards,
Alexander

  21. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-20T03:16:32Z

    At Thu, 19 Dec 2019 15:09:45 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> Alexander Lakhin <exclusion@gmail.com> writes:
> > Maybe we should change the condition to 'if (stat(fileName, &st) != 0 &&
> > (err = GetLastError()) == ERROR_ACCESS_DENIED)' to avoid unnecessary
> > sleep with a loop iteration...
> 
> Well, we have to loop back on file-not-found too ...

Agreed. But no need for a sleep in the case and even no need to loop
back when we are opening an existing file, if CreateFile would return
ERROR_ACCESS_DENIED on opening an existing file.

> > It seems that the check for ERROR_DELETE_PENDING was added to
> > pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
> > https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com
> 
> Hmm, makes one wonder whether that's actually live code.

Even if it is actually dead code, it seems reasonable as it stands
since it is intending to read status of an existing file and the
caller is assumed not to be knowing of ERROR_ACCESS_DENIED. In our
case, pgwin32_open should be conscious of the state so I think calling
pgwin32_safestat does not fit. (Or pgwin32_open and pgwin32_safestat
are on the same level of API.)

Maybe we could just loop back without extra stat'ing. With the
following change, fopen(pidfile, 'r') immediately returns if the file
is being deleted. Postmaster waits for the file gone (it would be
already gone at the first try in most cases). The sleep on
ERROR_ACCESS_DENEID moves from pg_ctl to postmaster in that case,
but I think it doesn't matter.

while (CreateFile())
{
  ...
  if (err == ERROR_ACCESS_DENIED)
  {
    if ((fileFlags & O_CREAT) == 0)
	  <retun with ENOENT>

    pg_usleep(...);
    loops++;
	continue;

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  22. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-20T03:29:28Z

    At Fri, 20 Dec 2019 12:16:32 +0900 (JST), Kyotaro Horiguchi <horikyota.ntt@gmail.com> wrote in 
> At Thu, 19 Dec 2019 15:09:45 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> > Alexander Lakhin <exclusion@gmail.com> writes:
> > > It seems that the check for ERROR_DELETE_PENDING was added to
> > > pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
> > > https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com
> > 
> > Hmm, makes one wonder whether that's actually live code.
> 
> Even if it is actually dead code, it seems reasonable as it stands
> since it is intending to read status of an existing file and the
> caller is assumed not to be knowing of ERROR_ACCESS_DENIED. In our
> case, pgwin32_open should be conscious of the state so I think calling
> pgwin32_safestat does not fit. (Or pgwin32_open and pgwin32_safestat
> are on the same level of API.)
> 
> Maybe we could just loop back without extra stat'ing. With the
> following change, fopen(pidfile, 'r') immediately returns if the file
> is being deleted. Postmaster waits for the file gone (it would be
> already gone at the first try in most cases). The sleep on
> ERROR_ACCESS_DENEID moves from pg_ctl to postmaster in that case,
> but I think it doesn't matter.

It is wrong. It hides real "access denied".. Sorry for the noise.

> while (CreateFile())
> {
>   ...
>   if (err == ERROR_ACCESS_DENIED)
>   {
>     if ((fileFlags & O_CREAT) == 0)
> 	  <retun with ENOENT>
> 
>     pg_usleep(...);
>     loops++;
> 	continue;

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  23. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-20T03:32:37Z

    At Fri, 20 Dec 2019 05:40:00 +0300, Alexander Lakhin <exclusion@gmail.com> wrote in 
> 19.12.2019 23:09, Tom Lane wrote:
> > Alexander Lakhin <exclusion@gmail.com> writes:
> >> Maybe we should change the condition to 'if (stat(fileName, &st) != 0 &&
> >> (err = GetLastError()) == ERROR_ACCESS_DENIED)' to avoid unnecessary
> >> sleep with a loop iteration...
> > Well, we have to loop back on file-not-found too ...
> I think, if the file is not found on stat() we can safely return the
> updated err (set errno with _dosmapper(err), to be exact). If we'll loop
> back, we'll get the same err = GetLastError() after next CreateFile().

I think Tom is mentinoing for O_CREAT case. If CreateFile returned
ERROR_ACCESS_DENIED, then stat() returns ERROR_FILE_NOT_FOUND, it
means the next CreateFile can success.

> >> It seems that the check for ERROR_DELETE_PENDING was added to
> >> pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
> >> https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com
> > Hmm, makes one wonder whether that's actually live code.
> I'll try to research this matter meantime.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  24. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-20T04:22:52Z

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> writes:
> At Thu, 19 Dec 2019 15:09:45 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
>> Alexander Lakhin <exclusion@gmail.com> writes:
>>> It seems that the check for ERROR_DELETE_PENDING was added to
>>> pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
>>> https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com

>> Hmm, makes one wonder whether that's actually live code.

> Even if it is actually dead code, it seems reasonable as it stands
> since it is intending to read status of an existing file and the
> caller is assumed not to be knowing of ERROR_ACCESS_DENIED.

What I was wondering about was how come, if stat() can see the specific
error code ERROR_DELETE_PENDING, we don't get to see that from CreateFile.
The whole reason we have a problem here is that CreateFile won't return
that code :-( ... so it seems possible that the code in pgwin32_safestat
is just wrong because the case never happens.

			regards, tom lane

  25. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Alexander Law <exclusion@gmail.com> — 2019-12-20T04:40:00Z

    20.12.2019 6:32, Kyotaro Horiguchi wrote:
> At Fri, 20 Dec 2019 05:40:00 +0300, Alexander Lakhin <exclusion@gmail.com> wrote in 
>> 19.12.2019 23:09, Tom Lane wrote:
>>> Alexander Lakhin <exclusion@gmail.com> writes:
>>>> Maybe we should change the condition to 'if (stat(fileName, &st) != 0 &&
>>>> (err = GetLastError()) == ERROR_ACCESS_DENIED)' to avoid unnecessary
>>>> sleep with a loop iteration...
>>> Well, we have to loop back on file-not-found too ...
>> I think, if the file is not found on stat() we can safely return the
>> updated err (set errno with _dosmapper(err), to be exact). If we'll loop
>> back, we'll get the same err = GetLastError() after next CreateFile().
> I think Tom is mentinoing for O_CREAT case. If CreateFile returned
> ERROR_ACCESS_DENIED, then stat() returns ERROR_FILE_NOT_FOUND, it
> means the next CreateFile can success.
It seems this is a new corner case and we just failed in this case
previously (yes, with ERROR_ACCESS_DENIED instead of
ERROR_FILE_NOT_FOUND, but nonetheless). If we restrict ourselves to
solving the initial problem with 'pt_ctl stop' (and pg_ctl opens pidfile
without O_CREAT), I wouldn't develop more powerful open() now.
But if we want it, the following code passes my tests (restart &
recoverycheck) too:
                if (stat(fileName, &st) != 0 &&
                    ((err = GetLastError()) == ERROR_ACCESS_DENIED) ||
                     ((err == ERROR_FILE_NOT_FOUND) && (fileFlags &
O_CREAT)))
                {
                    pg_usleep(100000);
                    loops++;
                    continue;
                }
Maybe we still need a practical case where it's useful, to test it for sure.

Best regards,
Alexander

  26. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2019-12-20T04:55:42Z

    Whaaaaat!!

At Thu, 19 Dec 2019 23:22:52 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> Kyotaro Horiguchi <horikyota.ntt@gmail.com> writes:
> > At Thu, 19 Dec 2019 15:09:45 -0500, Tom Lane <tgl@sss.pgh.pa.us> wrote in 
> >> Alexander Lakhin <exclusion@gmail.com> writes:
> >>> It seems that the check for ERROR_DELETE_PENDING was added to
> >>> pgwin32_safestat() blindly, the issue wasn't reproduced at that time:
> >>> https://www.postgresql.org/message-id/CAB7nPqRJV6trFta-Qzgi6j2feuYR2ZC%2BKHvWdHnbpDG2scTrxw%40mail.gmail.com
> 
> >> Hmm, makes one wonder whether that's actually live code.
> 
> > Even if it is actually dead code, it seems reasonable as it stands
> > since it is intending to read status of an existing file and the
> > caller is assumed not to be knowing of ERROR_ACCESS_DENIED.
> 
> What I was wondering about was how come, if stat() can see the specific
> error code ERROR_DELETE_PENDING, we don't get to see that from CreateFile.
> The whole reason we have a problem here is that CreateFile won't return
> that code :-( ... so it seems possible that the code in pgwin32_safestat
> is just wrong because the case never happens.

Ugggh! My eyes automatically converted it to
ERROR_ACCESS_DENIED.. Yes, the condition never be true.

Even if we use ERROR_ACCESS_DENIED instaed, pgwin32_safestat cannot
tell STATUS_ACCESS_DENIED from STATUS_DELETE_PENDING. A possible
compromise would be the same looping with pgwin32_open, but I'm not
sure if it doesn't harm callers.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  27. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Michael Paquier <michael@paquier.xyz> — 2019-12-21T02:26:32Z

    On Thu, Dec 19, 2019 at 09:49:54PM +0100, Juan José Santamaría Flecha wrote:
> Part of what the patch "Windows could not stat file - over 4GB" [1] does is
> proposing an alternative using native functions.
> 
> [1] https://commitfest.postgresql.org/26/2189/

Yeah, we are likely going to need something like that at the end..
--
Michael

  28. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-21T02:41:52Z

    Michael Paquier <michael@paquier.xyz> writes:
> On Thu, Dec 19, 2019 at 09:49:54PM +0100, Juan José Santamaría Flecha wrote:
>> Part of what the patch "Windows could not stat file - over 4GB" [1] does is
>> proposing an alternative using native functions.
>> [1] https://commitfest.postgresql.org/26/2189/

> Yeah, we are likely going to need something like that at the end..

Yeah, I was wondering if we shouldn't investigate that issue alongside
this one.  I've not had the time to look closely though (and besides,
I'm the wrong guy to be taking point on a Windows issue).

			regards, tom lane

  29. Re: BUG #16161: pg_ctl stop fails sometimes (on Windows)

    Tom Lane <tgl@sss.pgh.pa.us> — 2019-12-21T22:41:52Z

    Alexander Lakhin <exclusion@gmail.com> writes:
> 19.12.2019 18:44, Tom Lane wrote:
>> Entirely-untested patch along this line attached.

> I have tested it with my demo restart test and it works. Yes, stat() is
> resulted in the CreateFile() call too, so it should fail the same way.

Since this patch seems to fix the problem, I went ahead and pushed it.
We can still consider whether it can be improved, but I was getting
antsy about leaving the buildfarm broken.

			regards, tom lane