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

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

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.

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

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.

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.

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

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.

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

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]https://docs.microsoft.com/en-us/windows/win32/rstmgr/restart-manager-portal[2]https://devblogs.microsoft.com/oldnewthing/20120217-00/?p=8283 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

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

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.

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.

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.

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.

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

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

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.

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.

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.