Horton
Menu

Thread

Commits

Same data as JSON: GET /api/v1/messages/:b64id/commits the thread's linked commits as JSON, with link sources. API reference →

  1. Fix concurrency issues with WAL segment recycling on Windows

  1. Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-05T10:13:27Z

    Hi!

Postgres 13.1 is installed in windows server. There are about 100 users.

Log files contain huge number of permisson denied error messages in 
every day like :

2021-03-04 01:38:49.818 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 01:48:42.725 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 01:53:22.427 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 01:58:19.623 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 02:03:24.080 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 02:43:17.983 EET [7764] LOG:  invalid length of startup packet
2021-03-04 02:43:21.634 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 02:48:25.048 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 02:53:19.229 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 02:58:19.176 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 03:03:19.136 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 03:29:33.926 EET [2460] FATAL:  expected SASL response, got 
message type 0
2021-03-04 03:36:04.995 EET [4816] LOG:  could not rename temporary 
statistics file "pg_stat_tmp/global.tmp" to "pg_stat_tmp/global.stat": 
Permission denied
2021-03-04 03:36:09.666 EET [10340] LOG:  using stale statistics instead 
of current ones because stats collector is not responding
2021-03-04 03:53:20.036 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied
2021-03-04 04:03:19.001 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000001B": Permission denied

On middle of day where usage is intensive those appear exactly after 
every 10 seconds:

2021-03-05 12:08:40.001 EET [4580] LOG:  could not rename file 
"pg_wal/000000010000000500000078": Permission denied
2021-03-05 12:08:50.059 EET [4580] LOG:  could not rename file 
"pg_wal/00000001000000050000007D": Permission denied
2021-03-05 12:09:00.115 EET [4580] LOG:  could not rename file 
"pg_wal/000000010000000500000082": Permission denied
2021-03-05 12:09:10.171 EET [4580] LOG:  could not rename file 
"pg_wal/000000010000000500000088": Permission denied
2021-03-05 12:09:20.224 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000A4": Permission denied
2021-03-05 12:09:30.281 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000A8": Permission denied
2021-03-05 12:09:40.339 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000B0": Permission denied
2021-03-05 12:09:50.397 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000E7": Permission denied
2021-03-05 12:10:00.456 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000E8": Permission denied
2021-03-05 12:10:10.514 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000E9": Permission denied
2021-03-05 12:10:20.570 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000EB": Permission denied
2021-03-05 12:10:30.626 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000005000000EC": Permission denied

How to fix this ?

It looks like database is working normally, users havent reported any 
issues.

Andrus.

  2. Re: Log files polluted with permission denied error messages after every 10 seconds

    Laurenz Albe <laurenz.albe@cybertec.at> — 2021-03-05T13:50:07Z

    On Fri, 2021-03-05 at 12:13 +0200, Andrus wrote:
> Postgres 13.1 is installed in windows server. There are about 100 users.
> 
> Log files contain huge number of permisson denied error messages in every day like :
> 
> 2021-03-04 01:38:49.818 EET [4580] LOG:  could not rename file "pg_wal/00000001000000050000001B": Permission denied

Windows?

Don't let anti-virus software mess with the data directory.

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

  3. Re: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-05T17:36:37Z

    Hi!

 >Windows? Don't let anti-virus software mess with the data directory.

Windows default Windows Defender is active. I excluded data, pg_wal 
folders and postgres process:


Then turned real-time protection off:

Problem persists. New entry is written after every 10 seconds.

pg_wal also contains files with .deleted extension like

0000000100000005000000B2.deleted

Andrus.

  4. Re: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-06T01:36:39Z

    On Fri, Mar 05, 2021 at 07:36:37PM +0200, Andrus wrote:
> Then turned real-time protection off:
> 
> Problem persists. New entry is written after every 10 seconds.

On which files are those complaints?  It seems to me that you may have
more going on in this system that interacts with your data folder than
you think.

> pg_wal also contains files with .deleted extension like
> 
> 0000000100000005000000B2.deleted

These are generated on Windows when removing a past WAL segment, where
the process involves a rename followed by durable_unlink() that would
generate some LOG entries in the logs if the internal unlink() failed
(see RemoveXlogFile() in xlog.c). 
--
Michael

  5. Re: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-06T08:47:00Z

    Hi!

 > On which files are those complaints?

log contains file names:

...

2021-03-06 10:27:51.468 EET [4580] LOG:  could not rename file 
"pg_wal/000000010000000600000092": Permission denied
2021-03-06 10:28:01.526 EET [4580] LOG:  could not rename file 
"pg_wal/000000010000000600000098": Permission denied
2021-03-06 10:28:11.582 EET [4580] LOG:  could not rename file 
"pg_wal/000000010000000600000099": Permission denied
2021-03-06 10:28:21.637 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000E8": Permission denied
2021-03-06 10:28:31.692 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000EA": Permission denied
2021-03-06 10:28:41.750 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000EB": Permission denied
2021-03-06 10:28:51.807 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000EC": Permission denied
2021-03-06 10:29:01.864 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000ED": Permission denied
2021-03-06 10:29:11.920 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000EE": Permission denied
2021-03-06 10:29:21.976 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000EF": Permission denied
2021-03-06 10:29:32.033 EET [4580] LOG:  could not rename file 
"pg_wal/0000000100000006000000F0": Permission denied

Server was installed some days ago. Numbers in end of file names are 
small. So it looks like almost every wal file in timeline causes entry.

> It seems to me that you may have
> more going on in this system that interacts with your data folder than
> you think.

There is Windows server backup utility client from 
https://www.r1soft.com/  . It looks like it performs block-level 
realtime backup of HDD .

Its about box shows last year 2015 , but Windows Server 2019 is used. 
Maybe it is outdated and causes the issue. It is maintained by by ISP 
and I cannot stop it easily.

I havent found an option in its config to susped or configure it.

Config contains

max_wal_size = 1GB

There are 67 files in pg_wal. Earlier have have similar errors in my app 
if windows temporary directory contains  200000 files by mistake. 
Cleaning temp directory and adding random number to temporary file names 
seems to fix this.

Should max_wal or or other param size decrased or increased to avoid 
file access conflict.


> pg_wal also contains files with .deleted extension like
>> 0000000100000005000000B2.deleted
> These are generated on Windows when removing a past WAL segment, where
> the process involves a rename followed by durable_unlink() that would
> generate some LOG entries in the logs if the internal unlink() failed
> (see RemoveXlogFile() in xlog.c).

.deleted files have dates ealier dates (yesterday and 4th or March). 
Almost all regular wal files have todays date.

There are about 30 .deleted files from totel 67 files in pg_wal. Will 
postgres remove .deleted files automatically or should I create windows 
task which deletes them periodically ?

Andrus.

  6. Re: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-06T17:53:11Z

    Hi!

These are generated on Windows when removing a past WAL segment, where 
the process involves a rename followed by durable_unlink() that would
> generate some LOG entries in the logs if the internal unlink() failed
> (see RemoveXlogFile() in xlog.c).

I changed wal_recycle to off. So checkpointer should no more try to 
rename wal files. Iit still tries to rename files. No idea way it does 
not use this setting:

2021-03-06 19:44:28 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000006000000EB": Permission denied

2021-03-06 19:44:38 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000006000000F0": Permission denied
2021-03-06 19:44:48 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000006000000F7": Permission denied
2021-03-06 19:44:58 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000006000000FB": Permission denied
2021-03-06 19:45:08 EET     postmaster LOG:  received SIGHUP, reloading 
configuration files
2021-03-06 19:45:08 EET     postmaster LOG:  parameter "wal_recycle" 
changed to "off"
2021-03-06 19:45:08 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000006000000FE": Permission denied
2021-03-06 19:45:18 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000006000000FF": Permission denied
2021-03-06 19:45:28 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000700000000": Permission denied
2021-03-06 19:45:38 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000700000002": Permission denied
2021-03-06 19:45:48 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000700000011": Permission denied
2021-03-06 19:45:59 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000700000012": Permission denied

2021-03-06 19:46:09 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000700000015": Permission denied

2021-03-06 19:46:19 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000700000016": Permission denied

Should chekpointer process terminated to force it to use new setting. Is 
it safe to kill it during database usage.

Andrus.

  7. Re: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-07T09:27:57Z

    On Sat, Mar 06, 2021 at 07:53:11PM +0200, Andrus wrote:
> I changed wal_recycle to off. So checkpointer should no more try to rename
> wal files. Iit still tries to rename files. No idea way it does not use this
> setting:

On Windows, RemoveXlogFile() would still rename a given WAL segment
file with a ".deleted" suffix with ou without wal_recycle in the case
where the a recycling of a WAL segment is not necessary, for example
if max_wal_size is already full.  So this has no effect.

> Should chekpointer process terminated to force it to use new setting. Is it
> safe to kill it during database usage.

I don't understand what you mean here.
--
Michael

  8. Re: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-07T09:45:26Z

    Hi!

On Windows, RemoveXlogFile() would still rename a given WAL segment
> file with a ".deleted" suffix with ou without wal_recycle in the case
> where the a recycling of a WAL segment is not necessary, for example
> if max_wal_size is already full.  So this has no effect.

Should files with .deleted extension deleted manually to save disk space 
? May of them have dates before today.

Andrus.

  9. Re: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-07T23:38:02Z

    On Sun, Mar 07, 2021 at 11:45:26AM +0200, Andrus wrote:
> Should files with .deleted extension deleted manually to save disk space ?
> May of them have dates before today.

RemoveOldXlogFiles() would discard any of those .deleted files because
they don't match a legal WAL segment name, so checkpoints are not able
to work on them even in the future.  I would avoid meddling with
anything that a backend may finish to touch while running, but that 
should not really matter here as they are just never chosen for
deletion.  Piling up those files is not a good thing, so while you
still need to figure out what's causing those files to remain around
on your side, perhaps we should improve the situation in the backend
itself.
--
Michael

  10. Re: Log files polluted with permission denied error messages after every 10 seconds

    Thomas Munro <thomas.munro@gmail.com> — 2021-03-08T21:25:59Z

    On Sat, Mar 6, 2021 at 2:36 PM Michael Paquier <michael@paquier.xyz> wrote:
> On Fri, Mar 05, 2021 at 07:36:37PM +0200, Andrus wrote:
> > Then turned real-time protection off:
> >
> > Problem persists. New entry is written after every 10 seconds.
>
> On which files are those complaints?  It seems to me that you may have
> more going on in this system that interacts with your data folder than
> you think.

Suggestion received off-list from my colleague Bevan Arps, when I was
complaining about this general variety of problem: maybe we should
look into using Windows' RestartManager[1][2] API to find out which
processes (at least the pids, maybe also names) currently have a file
open?  Then, if it is indeed a sharing violation that's causing the
problem, we might at least be able to log message that says who's
blocking us once we reach that dreaded retry loop.  There are other
ways to get that information too, I believe, no idea which API would
be best, but this one looks to be the best documented.  I'm unlikely
to work on this myself as a card carrying Unix hacker, so I'm just
passing on this insight in case it's useful...

Another thought: if it's not a sharing violation, I wonder if we
should consider dumping more raw Windows error information in the
messages we log, because, if I recall correctly, we're converting many
Windows error codes into few Unix-style error numbers and thereby
throwing away valuable clues.  It makes it a bit more confusing when
trying to ask a Windows expert what might be happening.

[1] https://docs.microsoft.com/en-us/windows/win32/rstmgr/restart-manager-portal
[2] https://devblogs.microsoft.com/oldnewthing/20120217-00/?p=8283

  11. Re: Log files polluted with permission denied error messages after every 10 seconds

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-03-08T21:58:32Z

    Thomas Munro <thomas.munro@gmail.com> writes:
> Another thought: if it's not a sharing violation, I wonder if we
> should consider dumping more raw Windows error information in the
> messages we log, because, if I recall correctly, we're converting many
> Windows error codes into few Unix-style error numbers and thereby
> throwing away valuable clues.  It makes it a bit more confusing when
> trying to ask a Windows expert what might be happening.

Yeah, I've wondered for some time if the apparent EACCES code is
actually being mapped from something other than ERROR_SHARING_VIOLATION
in (some of?) these reports.  The hard part is to hold onto the
Windows error code alongside errno without massively invasive changes.

			regards, tom lane

  12. Re: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-08T22:01:20Z

    > Another thought: if it's not a sharing violation, I wonder if we
> should consider dumping more raw Windows error information in the
> messages we log, because, if I recall correctly, we're converting many
> Windows error codes into few Unix-style error numbers and thereby
> throwing away valuable clues.  It makes it a bit more confusing when
> trying to ask a Windows expert what might be happening.

Knowing process name holding file and other detailed information would 
be very useful.

In other Win 2019 server/Postgres 13  excluding Postgres drive from 
fprot scan seems to decrease those errors.

However they still occur even if no fprot is active.

There are also regular stat errors in windows servers is size queries  like

ERROR: could not stat file "base/45010/172654232": Permission denied;

in query

SELECT pg_size_pretty(pg_database_size('eeva')::bigint)::char(10) as size

and

ERROR: could not stat file "base/45010/172654232": Permission denied;

in query

     SELECT
pg_catalog.pg_size_pretty(SUM(
         CASE WHEN pg_catalog.has_database_privilege(d.datname, 'CONNECT')
             THEN pg_catalog.pg_database_size(d.datname)
             ELSE 0
         END)::bigint) ::char(50) AS SIZE
     FROM pg_catalog.pg_database d

and

ERROR: could not stat file "base/45010/172654232": Permission 
denied;Error while executing the query


     SELECT d.datname::char(15),
          pg_catalog.pg_get_userbyid(d.datdba)::char(18) AS Owner,
         CASE WHEN pg_catalog.has_database_privilege(d.datname, 'CONNECT')
             THEN 
pg_catalog.pg_size_pretty(pg_catalog.pg_database_size(d.datname)::bigint)
             ELSE 'No Access'
         END::char(50) AS SIZE
     FROM pg_catalog.pg_database d
         ORDER BY
         CASE WHEN pg_catalog.has_database_privilege(d.datname, 'CONNECT')
             THEN pg_catalog.pg_database_size(d.datname)
             ELSE NULL
         END DESC -- nulls first

Andrus.

  13. Re: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-08T22:23:37Z

    > Yeah, I've wondered for some time if the apparent EACCES code is
> actually being mapped from something other than ERROR_SHARING_VIOLATION
> in (some of?) these reports.  The hard part is to hold onto the
> Windows error code alongside errno without massively invasive changes.

Permission denied error occur in  Windows. Debian logs doesnt contain it.

In Windows also pg_database_size('mydb')  and similar ones fail 
frequently with permission denied error.

I got information about r1soft idera backup client used. It runs only 
once per night for 16 minutes and compares disk blocks to find changed 
blocks to backup. So it should not cause permission denied errors after 
every 10 seconds.

Andrus.

  14. SV: Log files polluted with permission denied error messages after every 10 seconds

    Niels Jespersen <njn@dst.dk> — 2021-03-09T05:03:19Z

    >
>
>Fra: Andrus <kobruleht2@hot.ee>
>Sendt: 8. marts 2021 23:24
>Emne: Re: Log files polluted with permission denied error messages after every 10 seconds
>
>Permission denied error occur in  Windows. Debian logs doesnt contain it.
>In Windows also pg_database_size('mydb')  and similar ones fail frequently with permission denied error.

Any hints in Windows event viewer? Events occurring at the same time showing up there.

>I got information about r1soft idera backup client used. It runs only once per night for 16 minutes and compares disk blocks to find changed blocks to backup. So it should not cause permission denied errors after every 10 seconds.
>Andrus.
>

  15. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-09T08:43:24Z

    > Any hints in Windows event viewer? Events  occurring at the same time showing up there.

Looked into Administrative Events/Custom views and few others. There are 
no messages about this. Windowsi perfomance monitor and Filemon show 
files opened by process.

How to do reverse: log processes and threads which use files in pg_wal 
directory ?

Is there some utility for this or can restart manager or other API  used 
to create such log?

Andrus.

  16. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Thomas Munro <thomas.munro@gmail.com> — 2021-03-09T10:07:11Z

    On Tue, Mar 9, 2021 at 9:43 PM Andrus <kobruleht2@hot.ee> wrote:
>  > Any hints in Windows event viewer? Events occurring at the same time showing up there.
>
> Looked into Administrative Events/Custom views and few others. There are no messages about this. Windowsi perfomance monitor and Filemon show files opened by process.
>
> How to do reverse: log processes and threads which use files in pg_wal directory ?

Maybe this does the reverse?

https://docs.microsoft.com/en-us/sysinternals/downloads/handle

  17. Re: Log files polluted with permission denied error messages after every 10 seconds

    shammat@gmx.net — 2021-03-09T10:19:22Z

    
Andrus schrieb am 05.03.2021 um 18:36:
> Hi!
>
>>Windows? Don't let anti-virus software mess with the data directory.
>
> Windows default Windows Defender is active. I excluded data, pg_wal folders and postgres process:
>
>
> Then turned real-time protection off:
>
> Problem persists. New entry is written after every 10 seconds.
>
> pg_wal also contains files with .deleted extension like
>
> 0000000100000005000000B2.deleted
>
> Andrus.
>
>
The data directory should not be stored in "C:\Program File"s on Windows.

I wouldn't be surprised if "Program Files" has some additional security settings that come into play here.

%ProgramData% is a better location for the data directory.


Thomas

  18. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-09T16:24:59Z

    Hi!

Maybe this does the reverse?
> https://docs.microsoft.com/en-us/sysinternals/downloads/handle

Examined todays logs in other windows 2019 server with Postgres 13.1

Permission denied occurs single file but permanently . Last entry is 6 
minutes ago:

2021-03-09 00:02:23.915 EET [11328] LOG:  could not rename file 
"pg_wal/000000010000004C00000034": Permission denied

2021-03-09 00:07:24.430 EET [11328] LOG:  could not rename file 
"pg_wal/000000010000004C00000034": Permission denied

2021-03-09 00:12:34.392 EET [11328] LOG:  could not rename file 
"pg_wal/000000010000004C00000034": Permission denied
2021-03-09 00:17:24.270 EET [11328] LOG:  could not rename file 
"pg_wal/000000010000004C00000034": Permission denied
2021-03-09 00:22:23.780 EET [11328] LOG:  could not rename file 
"pg_wal/000000010000004C00000034": Permission denied
..

2021-03-09 17:59:04 EET     checkpointerLOG:  could not rename file 
"pg_wal/000000010000004C00000034": Permission denied

Used Resource Monitor / CPU  / Associated Handles and searched for 
"000000010000004C00000034". Resource Monitor shows that process 11336 is 
using that file

pg_stat_activity shows that this is "background writer"  waiting for 
event BgWriterMain or BgWriterHibernate

Permisson denied exception occurs accoring to log above in process   
11328  which is listed as checkpointer.

So Background writer has locked the file permanently. Checkpointer tries 
to write into it and gets permission denied error all the time.

How to fix this ?

Andrus.

  19. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-10T09:10:14Z

    Today log file contains

2021-03-10 11:01:58 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A0000003B": Permission denied

messages. Resource Manager shows that 000000010000000A0000003B is is 
locked by process 30376


According to pg_stat_activity this is regular postgres process which is 
in idle state and waiting for ClientRead event. It has executed last 
query  an hour ago.

It looks like wal files are not released after usage.

Andrus.

  20. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-10T13:20:47Z

    Hi!

After re-starting postgres service problem persists.

Log file contains permission denied errors exactly after every 10 seconds:

...

2021-03-10 15:15:45 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000030": Permission denied
2021-03-10 15:15:55 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000031": Permission denied
2021-03-10 15:16:06 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000032": Permission denied
2021-03-10 15:16:16 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000033": Permission denied
2021-03-10 15:16:26 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000034": Permission denied
2021-03-10 15:16:36 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000037": Permission denied
2021-03-10 15:16:46 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000038": Permission denied
2021-03-10 15:16:56 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000039": Permission denied
2021-03-10 15:17:06 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A0000003B": Permission denied
2021-03-10 15:17:16 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A0000003E": Permission denied
2021-03-10 15:17:26 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A0000003F": Permission denied
2021-03-10 15:17:36 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000041": Permission denied
2021-03-10 15:17:46 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000044": Permission denied
2021-03-10 15:17:56 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000045": Permission denied
2021-03-10 15:18:06 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000046": Permission denied
2021-03-10 15:18:16 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000047": Permission denied
2021-03-10 15:18:26 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000048": Permission denied
2021-03-10 15:18:36 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A00000049": Permission denied
2021-03-10 15:18:46 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000000A0000004B": Permission denied


Windows Resource manger shows that wal files are used by large number of 
postgres processes:

postgres.exe    22656    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000075
postgres.exe    30788    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000075
postgres.exe    14144    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000074
postgres.exe    20360    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    25356    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    4136    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000075
postgres.exe    7712    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    7020    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    26128    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    13740    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    25660    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    19120    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    30152    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000073
postgres.exe    12140    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    500    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    17616    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    8552    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    23764    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000074
postgres.exe    28400    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    30172    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    28004    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000071
postgres.exe    28236    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000071
postgres.exe    25840    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000072
postgres.exe    20048    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000071
postgres.exe    30156    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000071
postgres.exe    26976    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000071
postgres.exe    26312    File    C:\Program 
Files\PostgreSQL\13\data\pg_wal\000000010000000A00000074

...

Many wal files are used by multiple processes.

Andrus.

  21. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Thomas Munro <thomas.munro@gmail.com> — 2021-03-12T01:27:14Z

    Hi Andrus,

On Thu, Mar 11, 2021 at 2:21 AM Andrus <kobruleht2@hot.ee> wrote:
> Windows Resource manger shows that wal files are used by large number of postgres processes:
>
> postgres.exe    22656    File    C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000000A00000075
> postgres.exe    30788    File    C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000000A00000075
> postgres.exe    14144    File    C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000000A00000074
...

This is normal -- postgres.exe holds open various files it's
interested in, and it's supposed to be OK for them to be renamed or
unlinked at any time by another process because they are opened with
special FILE_SHARE_XXX flags that allow that.  That list doesn't show
the open flags, but it looks like nothing *else* has the files open.
Usually when these types of errors are reported on the mailing list,
it turns out to be due to some other program opening the file without
those flags.

It's also possible that this is a real permissions problem, and not a
sharing violation.  I'd definitely look into this feedback:

On Tue, Mar 9, 2021 at 11:19 PM Thomas Kellerer <shammat@gmx.net> wrote:
> The data directory should not be stored in "C:\Program File"s on Windows.
>
> I wouldn't be surprised if "Program Files" has some additional security settings that come into play here.
>
> %ProgramData% is a better location for the data directory.

  22. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-16T10:26:47Z

    Hi Andrus,

On Wed, Mar 10, 2021 at 03:20:47PM +0200, Andrus wrote:
> After re-starting postgres service problem persists.

Where you getting the Postgres binaries from?  If we provide a patch,
could you test it?  This would require that you do your own build,
unfortunately, but having an environment where this is easily
reproducible is a key thing.
--
Michael

  23. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-16T11:59:07Z

    Hi
> Where you getting the Postgres binaries from?

https://www.enterprisedb.com/downloads/postgres-postgresql-downloads

> If we provide a patch, could you test it?
Yes
> This would require that you do your own build,
> unfortunately, but having an environment where this is easily
> reproducible is a key thing.

I used C last time many years ago. I'm working in C# with Visual Studio 
2019.

I have two Windows 2019 servers. In Intel Xeon Cold 6226R server it 
occurs after every 10 seconds. Last logs:

2021-03-16 13:48:12 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000001100000097": Permission denied
2021-03-16 13:48:22 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000001100000098": Permission denied
2021-03-16 13:48:32 EET     checkpointer LOG:  could not rename file 
"pg_wal/000000010000001100000099": Permission denied
2021-03-16 13:48:42 EET     checkpointer LOG:  could not rename file 
"pg_wal/00000001000000110000009A": Permission denied
2021-03-16 13:48:52 EET     checkpointer LOG:  could not rename file 
"pg_wal/00000001000000110000009D": Permission denied
2021-03-16 13:49:02 EET     checkpointer LOG:  could not rename file 
"pg_wal/0000000100000011000000A0": Permission denied

In AMD Ryzen 3970X Threadripper 32 core processor server in also occurs 
many times per day day but less frequently. Last logs:

2021-03-16 13:45:20 EET     checkpointerLOG:  could not rename file 
"pg_wal/000000010000004E000000FB": Permission denied
2021-03-16 13:50:02 EET     checkpointerLOG:  could not rename file 
"pg_wal/000000010000004E000000FB": Permission denied
2021-03-16 13:50:13 EET     checkpointerLOG:  could not rename file 
"pg_wal/000000010000004F00000082": Permission denied

So It should be probably reproducible in any Windows 2019 server.

Andrus.

  24. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-16T22:18:15Z

    On Tue, Mar 16, 2021 at 01:59:07PM +0200, Andrus wrote:
> I have two Windows 2019 servers. In Intel Xeon Cold 6226R server it occurs
> after every 10 seconds. Last logs:
> 
> 2021-03-16 13:48:12 EET     checkpointer LOG:  could not rename file
> "pg_wal/000000010000001100000097": Permission denied
> 2021-03-16 13:48:22 EET     checkpointer LOG:  could not rename file
> "pg_wal/000000010000001100000098": Permission denied
> 2021-03-16 13:48:32 EET     checkpointer LOG:  could not rename file
> "pg_wal/000000010000001100000099": Permission denied
> 2021-03-16 13:48:42 EET     checkpointer LOG:  could not rename file
> "pg_wal/00000001000000110000009A": Permission denied
> 2021-03-16 13:48:52 EET     checkpointer LOG:  could not rename file
> "pg_wal/00000001000000110000009D": Permission denied
> 2021-03-16 13:49:02 EET     checkpointer LOG:  could not rename file
> "pg_wal/0000000100000011000000A0": Permission denied
> 
> So It should be probably reproducible in any Windows 2019 server.

Those ten seconds are coming from RemoveXlogFile(), where pgrename()
loops 100 times for 100ms before giving up.  So something holding up
the file's handle prevents the removal to happen.  Attached is the
patch that should be tested, based on the suspected commit.  There are
actually two scenarios to worry about:
- Check that the code of 13.2 compiled manually is enough to see the
failure.
- Check that once the patch attached is applied makes the failure go
away.

I am trying on my side to reproduce the problem in a more reliable
way.  One thing I saw breaking in my setup is archive_command, where
it was not able to archive a segment with a simple copy, failing with
the same error as yours.

In one of those servers, do you have in pg_wal/ some files named
xlogtemp.N?  N is an integer that would be the PID of the process that
generated it.
--
Michael

  25. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-16T23:09:24Z

    Hi!

 >Those ten seconds are coming from RemoveXlogFile(), where pgrename()
> loops 100 times for 100ms before giving up.  So something holding up
> the file's handle prevents the removal to happen.

I tried sysinternals

handle pg_wal

It shows that only postgres processes have opened files in pg_wal directory:

postgres.exe       pid: 11800  type: File           CC0: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B7
postgres.exe       pid: 11800  type: File          12B8: C:\Program 
Files\PostgreSQL\13\data\pg_wal
postgres.exe       pid: 23904  type: File          1134: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B5
postgres.exe       pid: 20908  type: File           17C: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B7
postgres.exe       pid: 29892  type: File           C08: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000011000000F4
...
postgres.exe       pid: 34260  type: File           C18: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000011000000FC
postgres.exe       pid: 34484  type: File           C48: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000011000000FC
postgres.exe       pid: 38740  type: File           180: C:\Program 
Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B7


> Attached is the
> patch that should be tested, based on the suspected commit.  There are
> actually two scenarios to worry about:
> - Check that the code of 13.2 compiled manually is enough to see the
> failure.
> - Check that once the patch attached is applied makes the failure go
> away.
>
Intel server has

PostgreSQL 13.1, compiled by Visual C++ build 1914, 64-bit

and AMD server

PostgreSQL 13.2, compiled by Visual C++ build 1914, 64-bit

Should I try install Visual C++ , compile and replace postgres.exe file 
in AMD server.

> I am trying on my side to reproduce the problem in a more reliable
> way.  One thing I saw breaking in my setup is archive_command, where
> it was not able to archive a segment with a simple copy, failing with
> the same error as yours.
wal archiving is not used on those servers.
> In one of those servers, do you have in pg_wal/ some files named
> xlogtemp.N?  N is an integer that would be the PID of the process that
> generated it.

No. Intel server has 4 files with .deleted extension. AMD server has no 
.deleted files. It has probably lower traffic.

Andrus.

  26. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-16T23:41:19Z

    On Wed, Mar 17, 2021 at 01:09:24AM +0200, Andrus wrote:
> Should I try install Visual C++ , compile and replace postgres.exe file in
> AMD server.

Mostly.  That's the annoying part:
https://www.postgresql.org/docs/devel/install-windows-full.html

It is also possible to compile the code on a first machine, then just
zip followed by an unzip it at the same location as your installation.

I am not completely sure which flags your installation has, but
another possibility is that I directly send to you two compiled
builds, one with the patch and one without it that you could directly
test.  I would not send that to the lists as an installation is rather
large, but I could just send you links from where you could download
both of them.  Then you would just need to stop the Postgres service,
do a drop-in deplacement of the binaries, and start again the Postgres
service.
--
Michael

  27. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-17T07:01:02Z

    Hi!

> I am not completely sure which flags your installation has, but
> another possibility is that I directly send to you two compiled
> builds, one with the patch and one without it that you could directly
> test.  I would not send that to the lists as an installation is rather
> large, but I could just send you links from where you could download
> both of them.  Then you would just need to stop the Postgres service,
> do a drop-in deplacement of the binaries, and start again the Postgres
> service.

I can try binaries in Intel server which runs Postgres 13.1. I hope its 
data directory is compatible with them.

Andrus.

  28. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-17T07:25:00Z

    Hi

 >I am not completely sure which flags your installation has, but

pg_config --configure outputs

--enable-thread-safety --enable-nls --with-ldap --with-openssl 
--with-uuid --with-libxml --with-libxslt --with-icu --with-tcl 
--with-perl --with-python

Andrus.

  29. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-17T08:24:34Z

    On Wed, Mar 17, 2021 at 09:25:00AM +0200, Andrus wrote:
> pg_config --configure outputs
> 
> --enable-thread-safety --enable-nls --with-ldap --with-openssl --with-uuid
> --with-libxml --with-libxslt --with-icu --with-tcl --with-perl --with-python

Thanks.  Do you actually use OpenSSL, LDAP, uuid-ossp, xml2, PL/Perl
PL/Python, or the XML datatype for your applications there?  It may be
better if those custom builds have a minimum number of dependencies 
filled, while still being compatible with what you do on those servers
so as they can still have some load applied.
--
Michael

  30. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-17T08:45:28Z

     >On Wed, Mar 17, 2021 at 09:25:00AM +0200, Andrus wrote:
>> pg_config --configure outputs
>>
>> --enable-thread-safety --enable-nls --with-ldap --with-openssl --with-uuid
>> --with-libxml --with-libxslt --with-icu --with-tcl --with-perl --with-python
> Thanks.  Do you actually use OpenSSL,
Not directly. Maybe server uses it for ssl connections but non-ssl 
connections are also allowed.
>   LDAP
no.
> uuid-ossp,
It is used to get guid in few places for compatibility with older servers.
> xml2, PL/Perl PL/Python,
No.
> or the XML datatype

In this server hopefully no. Application code contains xml parsing it 
but probably those queries are never running in this server.

Andrus.

> for your applications there?  It may be
> better if those custom builds have a minimum number of dependencies
> filled, while still being compatible with what you do on those servers
> so as they can still have some load applied.
> --
> Michael

  31. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Laurenz Albe <laurenz.albe@cybertec.at> — 2021-03-17T12:46:28Z

    On Wed, 2021-03-17 at 01:09 +0200, Andrus wrote:
> > Those ten seconds are coming from RemoveXlogFile(), where pgrename() 
> > loops 100 times for 100ms before giving up.  So something holding up
> > the file's handle prevents the removal to happen.  
> 
> I tried sysinternals   
> 
> handle pg_wal 
> 
> It shows that only postgres processes have opened files in pg_wal directory:
> 
> postgres.exe       pid: 11800  type: File           CC0: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B7
> postgres.exe       pid: 11800  type: File          12B8: C:\Program Files\PostgreSQL\13\data\pg_wal
> postgres.exe       pid: 23904  type: File          1134: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B5
> postgres.exe       pid: 20908  type: File           17C: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B7
> postgres.exe       pid: 29892  type: File           C08: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000011000000F4
> ...
> postgres.exe       pid: 34260  type: File           C18: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000011000000FC
> postgres.exe       pid: 34484  type: File           C48: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000011000000FC
> postgres.exe       pid: 38740  type: File           180: C:\Program Files\PostgreSQL\13\data\pg_wal\0000000100000012000000B7

I think what it would be most helpful to run "process monitor", so that you get
a log of the system calls and errors; perhaps that shows some details that
we cannot get from the error message.

Yours,
Laurenz Albe

  32. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-17T13:26:56Z

    Hi!


> I think what it would be most helpful to run "process monitor", so that you get
> a log of the system calls and errors; perhaps that shows some details that
> we cannot get from the error message.
>
Process monitor shows huge number of DELETE PENDING results from 
CreateFile operation:

15:22:35,1708187    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE 
PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a

15:22:35,2713856    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE 
PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a

15:22:35,3719483    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE 
PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a

15:22:35,4723624    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE 
PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a

Andrus.

  33. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Laurenz Albe <laurenz.albe@cybertec.at> — 2021-03-17T14:48:42Z

    On Wed, 2021-03-17 at 15:26 +0200, Andrus wrote:
> > I think what it would be most helpful to run "process monitor", so that you get
> > a log of the system calls and errors; perhaps that shows some details that
> > we cannot get from the error message.
> > 
> 
> Process monitor shows huge number of DELETE PENDING results from CreateFile operation:
> 
> 15:22:35,1708187    postgres.exe    11800    CreateFile    C:\Program Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE PENDING    Desired Access: Read Attributes, Delete,
> Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
> 15:22:35,2713856    postgres.exe    11800    CreateFile    C:\Program Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE PENDING    Desired Access: Read Attributes, Delete,
> Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
> 
> 15:22:35,3719483    postgres.exe    11800    CreateFile    C:\Program Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE PENDING    Desired Access: Read Attributes, Delete,
> Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a
> 
> 15:22:35,4723624    postgres.exe    11800    CreateFile    C:\Program Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE PENDING    Desired Access: Read Attributes, Delete,
> Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a

Doesn't look like these are error messages.

There should be error messages that correspond to the error messages you see in the PostgreSQL log.

Yours,
Laurenz Albe
-- 
Cybertec | https://www.cybertec-postgresql.com

  34. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-17T15:16:16Z

    Hi!
> Doesn't look like these are error messages.
>
> There should be error messages that correspond to the error messages you see in the PostgreSQL log.

I excluded SUCCESS and DELETE PENDING results and included pg_wal path 
and postgres.exe process.

Log file contains only few entries, BUFFER OVERFLOW and NAME NOT FOUND

17:07:09,9618758    postgres.exe    11800 QueryAllInformationFile    
C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000001300000021    
BUFFER OVERFLOW    CreationTime: 16.03.2021 20:04:57, LastAccessTime: 
17.03.2021 16:58:43, LastWriteTime: 17.03.2021 16:58:43, ChangeTime: 
17.03.2021 16:58:43, FileAttributes: A, AllocationSize: 16 777 216, 
EndOfFile: 16 777 216, NumberOfLinks: 1, DeletePending: False, 
Directory: False, IndexNumber: 0x38100000009ffb4, EaSize: 0, Access: 
Read Attributes, Synchronize, Position: 0, Mode: Synchronous IO 
Non-Alert, AlignmentRequirement: Byte
17:07:09,9624993    postgres.exe    11800 QueryAllInformationFile    
C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000001300000023    
BUFFER OVERFLOW    CreationTime: 16.03.2021 20:04:57, LastAccessTime: 
17.03.2021 17:07:09, LastWriteTime: 17.03.2021 17:07:09, ChangeTime: 
17.03.2021 17:07:09, FileAttributes: A, AllocationSize: 16 777 216, 
EndOfFile: 16 777 216, NumberOfLinks: 1, DeletePending: False, 
Directory: False, IndexNumber: 0x20000000a010c, EaSize: 0, Access: Read 
Attributes, Synchronize, Position: 0, Mode: Synchronous IO Non-Alert, 
AlignmentRequirement: Byte
17:07:09,9630741    postgres.exe    11800 QueryAllInformationFile    
C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000001300000024    
BUFFER OVERFLOW    CreationTime: 16.03.2021 20:04:57, LastAccessTime: 
16.03.2021 20:05:12, LastWriteTime: 16.03.2021 20:05:12, ChangeTime: 
16.03.2021 20:15:24, FileAttributes: A, AllocationSize: 16 777 216, 
EndOfFile: 16 777 216, NumberOfLinks: 1, DeletePending: False, 
Directory: False, IndexNumber: 0x20000000a010d, EaSize: 0, Access: Read 
Attributes, Synchronize, Position: 0, Mode: Synchronous IO Non-Alert, 
AlignmentRequirement: Byte
17:07:09,9636100    postgres.exe    11800 QueryAllInformationFile    
C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000001300000025    
BUFFER OVERFLOW    CreationTime: 16.03.2021 20:04:57, LastAccessTime: 
16.03.2021 20:05:12, LastWriteTime: 16.03.2021 20:05:12, ChangeTime: 
16.03.2021 20:15:24, FileAttributes: A, AllocationSize: 16 777 216, 
EndOfFile: 16 777 216, NumberOfLinks: 1, DeletePending: False, 
Directory: False, IndexNumber: 0x20000000a010e, EaSize: 0, Access: Read 
Attributes, Synchronize, Position: 0, Mode: Synchronous IO Non-Alert, 
AlignmentRequirement: Byte
17:07:09,9641594    postgres.exe    11800 QueryAllInformationFile    
C:\Program Files\PostgreSQL\13\data\pg_wal\000000010000001300000026    
BUFFER OVERFLOW    CreationTime: 16.03.2021 20:04:57, LastAccessTime: 
16.03.2021 20:05:13, LastWriteTime: 16.03.2021 20:05:13, ChangeTime: 
16.03.2021 20:15:24, FileAttributes: A, AllocationSize: 16 777 216, 
EndOfFile: 16 777 216, NumberOfLinks: 1, DeletePending: False, 
Directory: False, IndexNumber: 0x20000000a010f, EaSize: 0, Access: Read 
Attributes, Synchronize, Position: 0, Mode: Synchronous IO Non-Alert, 
AlignmentRequirement: Byte
17:07:09,9659048    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal    IS DIRECTORY Desired Access: Generic 
Read, Disposition: Open, Options: Synchronous IO Non-Alert, 
Non-Directory File, Attributes: N, ShareMode: Read, Write, Delete, 
AllocationSize: n/a
17:07:09,9661026    postgres.exe    11800 QueryAllInformationFile    
C:\Program Files\PostgreSQL\13\data\pg_wal    BUFFER OVERFLOW 
CreationTime: 10.02.2021 14:07:18, LastAccessTime: 17.03.2021 17:07:09, 
LastWriteTime: 17.03.2021 17:07:09, ChangeTime: 17.03.2021 17:07:09, 
FileAttributes: D, AllocationSize: 196 608, EndOfFile: 196 608, 
NumberOfLinks: 1, DeletePending: False, Directory: True, IndexNumber: 
0x1000000055e2b, EaSize: 0, Access: Read Attributes, Synchronize, 
Position: 0, Mode: Synchronous IO Non-Alert, AlignmentRequirement: Byte
17:07:09,9666396    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal\archive_status\000000010000001300000021.done 
NAME NOT FOUND    Desired Access: Read Attributes, Delete, Disposition: 
Open, Options: Non-Directory File, Open Reparse Point, Attributes: n/a, 
ShareMode: Read, Write, Delete, AllocationSize: n/a
17:07:09,9667813    postgres.exe    11800    CreateFile C:\Program 
Files\PostgreSQL\13\data\pg_wal\archive_status\000000010000001300000021.ready 
NAME NOT FOUND    Desired Access: Read Attributes, Delete, Disposition: 
Open, Options: Non-Directory File, Open Reparse Point, Attributes: n/a, 
ShareMode: Read, Write, Delete, AllocationSize: n/a
17:07:09,9668956    postgres.exe    11800    QueryDirectory C:\Program 
Files\PostgreSQL\13\data\pg_wal    NO MORE FILES FileInformationClass: 
FileBothDirectoryInformation

Andrus.

  35. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-17T15:24:42Z

    Hi!

BUFFER OVERFLOW result stack trace is

"Frame","Module","Location","Address","Path"
"0","FLTMGR.SYS","FltDecodeParameters + 
0x1c5d","0xfffff8019f72555d","C:\Windows\System32\drivers\FLTMGR.SYS"
"1","FLTMGR.SYS","FltDecodeParameters + 
0x17bc","0xfffff8019f7250bc","C:\Windows\System32\drivers\FLTMGR.SYS"
"2","FLTMGR.SYS","FltDecodeParameters + 
0x1328","0xfffff8019f724c28","C:\Windows\System32\drivers\FLTMGR.SYS"
"3","FLTMGR.SYS","FltDecodeParameters + 
0x111e","0xfffff8019f724a1e","C:\Windows\System32\drivers\FLTMGR.SYS"
"4","ntoskrnl.exe","IofCallDriver + 
0x59","0xfffff80051856109","C:\Windows\system32\ntoskrnl.exe"
"5","ntoskrnl.exe","KeIsAttachedProcess + 
0xf3","0xfffff80051929343","C:\Windows\system32\ntoskrnl.exe"
"6","ntoskrnl.exe","NtQueryInformationFile + 
0x492","0xfffff80051e8b5c2","C:\Windows\system32\ntoskrnl.exe"
"7","ntoskrnl.exe","setjmpex + 
0x7905","0xfffff800519e6705","C:\Windows\system32\ntoskrnl.exe"
"8","<unknown>","0x7ffc7a17f9e4","0x7ffc7a17f9e4",""
"9","<unknown>","0x7ffc7639af04","0x7ffc7639af04",""
"10","<unknown>","0x7ffc7728fe86","0x7ffc7728fe86",""
"11","<unknown>","0x7ffc7728f622","0x7ffc7728f622",""
"12","<unknown>","0x7ffc77290a46","0x7ffc77290a46",""
"13","<unknown>","0x14048ccca","0x14048ccca",""
"14","<unknown>","0x14009463b","0x14009463b",""
"15","<unknown>","0x140094365","0x140094365",""
"16","<unknown>","0x14008e541","0x14008e541",""
"17","<unknown>","0x140286f46","0x140286f46",""
"18","<unknown>","0x1400a17ca","0x1400a17ca",""
"19","<unknown>","0x1402923cb","0x1402923cb",""
"20","<unknown>","0x1401b95c0","0x1401b95c0",""
"21","<unknown>","0x14049f304","0x14049f304",""
"22","<unknown>","0x7ffc77bb7974","0x7ffc77bb7974",""
"23","<unknown>","0x7ffc7a13a2d1","0x7ffc7a13a2d1",""

It looks like too small buffer is passed to NtQueryInformationFile .

Andrus.

  36. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-03-17T15:44:48Z

    Andrus <kobruleht2@hot.ee> writes:
> It looks like too small buffer is passed to NtQueryInformationFile .

Oh!  That's an interesting theory; it'd explain why this broke recently,
because we didn't use to use that function.  But how do you draw that
conclusion from this stack trace?

Anyway, if you've diagnosed this correctly, I bet the fault is in
this bit in win32stat.c:

#if _WIN32_WINNT < 0x0600
	IO_STATUS_BLOCK ioStatus;
	FILE_STANDARD_INFORMATION standardInfo;
#else
	FILE_STANDARD_INFO standardInfo;
#endif

Maybe the version cutoff is wrong?  Maybe we have to do this with
a run-time version check, instead of statically compiling it?

			regards, tom lane

  37. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-17T21:00:03Z

    On Wed, Mar 17, 2021 at 11:44:48AM -0400, Tom Lane wrote:
> Oh!  That's an interesting theory; it'd explain why this broke recently,
> because we didn't use to use that function.  But how do you draw that
> conclusion from this stack trace?
> 
> Anyway, if you've diagnosed this correctly, I bet the fault is in
> this bit in win32stat.c:
> 
> #if _WIN32_WINNT < 0x0600
> 	IO_STATUS_BLOCK ioStatus;
> 	FILE_STANDARD_INFORMATION standardInfo;
> #else
> 	FILE_STANDARD_INFO standardInfo;
> #endif
> 
> Maybe the version cutoff is wrong?  Maybe we have to do this with
> a run-time version check, instead of statically compiling it?

All the reports received are on 13.1 and 13.2.  This code is new as of
bed9075, no?
--
Michael

  38. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Tom Lane <tgl@sss.pgh.pa.us> — 2021-03-17T21:07:11Z

    Michael Paquier <michael@paquier.xyz> writes:
> On Wed, Mar 17, 2021 at 11:44:48AM -0400, Tom Lane wrote:
>> Oh!  That's an interesting theory; it'd explain why this broke recently,
>> because we didn't use to use that function.  But how do you draw that
>> conclusion from this stack trace?

> All the reports received are on 13.1 and 13.2.  This code is new as of
> bed9075, no?

Ah, right.  But then this theory must be nonsense, because we did
not use NtQueryInformationFile() in v13.

			regards, tom lane

  39. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Guy Burgess <guy@burgess.co.nz> — 2021-03-17T23:25:45Z

    FWIW, this looks the same issue I am getting (reported last month: 
https://www.postgresql.org/message-id/f444a84e-2d29-55f9-51a6-a5dcea3bc253%40burgess.co.nz)

I get the same Process Monitor output, including BUFFER OVERFLOW 
entries.  No sign of any process other than postgres.exe touching the 
WAL files.

Regards,

Guy


On 18/03/2021 2:26 am, Andrus wrote:
>
> Hi!
>
>
>> I think what it would be most helpful to run "process monitor", so that you get
>> a log of the system calls and errors; perhaps that shows some details that
>> we cannot get from the error message.
>>
> Process monitor shows huge number of DELETE PENDING results from 
> CreateFile operation:
>
> 15:22:35,1708187    postgres.exe    11800    CreateFile C:\Program 
> Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B    DELETE 
> PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
> Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
> Point, Attributes: n/a, ShareMode: Read, Write, Delete, 
> AllocationSize: n/a
>
> 15:22:35,2713856    postgres.exe    11800    CreateFile C:\Program 
> Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B DELETE 
> PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
> Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
> Point, Attributes: n/a, ShareMode: Read, Write, Delete, 
> AllocationSize: n/a
>
> 15:22:35,3719483    postgres.exe    11800    CreateFile C:\Program 
> Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B DELETE 
> PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
> Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
> Point, Attributes: n/a, ShareMode: Read, Write, Delete, 
> AllocationSize: n/a
>
> 15:22:35,4723624    postgres.exe    11800    CreateFile C:\Program 
> Files\PostgreSQL\13\data\pg_wal\00000001000000110000003B DELETE 
> PENDING    Desired Access: Read Attributes, Delete, Synchronize, 
> Disposition: Open, Options: Synchronous IO Non-Alert, Open Reparse 
> Point, Attributes: n/a, ShareMode: Read, Write, Delete, 
> AllocationSize: n/a
>
> Andrus.
>
>

  40. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-17T23:53:29Z

    On Wed, Mar 17, 2021 at 10:45:28AM +0200, Andrus wrote:
> In this server hopefully no. Application code contains xml parsing it but
> probably those queries are never running in this server.

Okay, cool.  I am going to send you privately two links to the builds
I am going to produce, 13.2 unpatched and 13.2 patched.
--
Michael

  41. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-18T00:08:31Z

    On Thu, Mar 18, 2021 at 12:25:45PM +1300, Guy Burgess wrote:
> FWIW, this looks the same issue I am getting (reported last month:
> https://www.postgresql.org/message-id/f444a84e-2d29-55f9-51a6-a5dcea3bc253%40burgess.co.nz)

Yep.

> I get the same Process Monitor output, including BUFFER OVERFLOW entries.
> No sign of any process other than postgres.exe touching the WAL files.

Guy, do you have an environment where this is still happening and
where you could test a potential fix?  We are not sure yet what's
causing that, but one code path has changed in this area, involving
CreateHardLinkA()+_unlink() instead of a single rename when attempting
to recycle a segment.  And I am just in a mood to build things by
myself and send some links to people to be able to download and test
that, so one more is fine..
--
Michael

  42. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Guy Burgess <guy@burgess.co.nz> — 2021-03-18T00:19:54Z

    Thanks - yes pleas send me a private link and I will try to reproduce it 
in a test environment and then test the patch.

Regards,

Guy


On 18/03/2021 1:08 pm, Michael Paquier wrote:
> On Thu, Mar 18, 2021 at 12:25:45PM +1300, Guy Burgess wrote:
>> FWIW, this looks the same issue I am getting (reported last month:
>> https://www.postgresql.org/message-id/f444a84e-2d29-55f9-51a6-a5dcea3bc253%40burgess.co.nz)
> Yep.
>
>> I get the same Process Monitor output, including BUFFER OVERFLOW entries.
>> No sign of any process other than postgres.exe touching the WAL files.
> Guy, do you have an environment where this is still happening and
> where you could test a potential fix?  We are not sure yet what's
> causing that, but one code path has changed in this area, involving
> CreateHardLinkA()+_unlink() instead of a single rename when attempting
> to recycle a segment.  And I am just in a mood to build things by
> myself and send some links to people to be able to download and test
> that, so one more is fine..
> --
> Michael

  43. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-19T07:00:10Z

    Hi!


> Okay, cool.  I am going to send you privately two links to the builds
> I am going to produce, 13.2 unpatched and 13.2 patched.

I replaced files in 13.1 server with ones from your patched version. 
There are no errors in log file now for 8 hours.

Andrus.

  44. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-19T07:06:34Z

    On Fri, Mar 19, 2021 at 09:00:10AM +0200, Andrus wrote:
> I replaced files in 13.1 server with ones from your patched version. There
> are no errors in log file now for 8 hours.

Yippee.  Thanks.

Have you tested the unpatched builds?  And did you see some errors
with them?
--
Michael

  45. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-19T07:56:15Z

    Hi!


> Have you tested the unpatched builds?

No.

Andrus.

  46. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-20T21:38:59Z

    Hi!

Today got 2 errors in patched version:

2021-03-20 20:31:27 EET     stats collector LOG:  could not rename 
temporary statistics file "pg_stat_tmp/global.tmp" to 
"pg_stat_tmp/global.stat": Permission denied

2021-03-20 20:51:25 EET     stats collector LOG:  could not rename 
temporary statistics file "pg_stat_tmp/global.tmp" to 
"pg_stat_tmp/global.stat": Permission denied

Andrus.

  47. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Andrus <kobruleht2@hot.ee> — 2021-03-22T07:25:26Z

    Hi!

Errors in pg_wal directory seems not to occur in patched version. Errors 
in pg_stat_tmp still occur. Yesterdays log introduces new error message

using stale statistics instead of current ones because stats collector 
is not responding

2021-03-21 03:02:23 EET     stats collector LOG:  could not rename 
temporary statistics file "pg_stat_tmp/global.tmp" to 
"pg_stat_tmp/global.stat": Permission denied
2021-03-21 13:31:00 EET     stats collector LOG:  could not rename 
temporary statistics file "pg_stat_tmp/global.tmp" to 
"pg_stat_tmp/global.stat": Permission denied
2021-03-21 15:15:52 EET     stats collector LOG:  could not rename 
temporary statistics file "pg_stat_tmp/global.tmp" to 
"pg_stat_tmp/global.stat": Permission denied
2021-03-21 23:51:20 EET     stats collector LOG:  could not rename 
temporary statistics file "pg_stat_tmp/global.tmp" to 
"pg_stat_tmp/global.stat": Permission denied
2021-03-21 23:51:25 EET     autovacuum worker LOG:  using stale 
statistics instead of current ones because stats collector is not responding

Andrus.

  48. Re: SV: Log files polluted with permission denied error messages after every 10 seconds

    Michael Paquier <michael@paquier.xyz> — 2021-03-22T07:44:52Z

    On Mon, Mar 22, 2021 at 09:25:26AM +0200, Andrus wrote:
> Errors in pg_wal directory seems not to occur in patched version. Errors in
> pg_stat_tmp still occur. Yesterdays log introduces new error message
> 
> using stale statistics instead of current ones because stats collector is
> not responding
> 
> 2021-03-21 23:51:25 EET     autovacuum worker LOG:  using stale statistics
> instead of current ones because stats collector is not responding

The renaming of stats files involves just pgrename(), which is a
completely separate code path than the one of the WAL segments.  This
requires a separate investigation.
--
Michael