[PATCH] Fixed creation of empty .log files during log rotation

On 10/29/24 09:08, Арсений Косицын wrote:

Hi everyone!

A situation has been discovered in which empty .log files are being created.

--Reproduce:

1) You need to set the following parameters in the "postgresql.conf" file:

log_destination = 'csvlog'
logging_collector = on
log_rotation_age = 1min
log_directory = '/home/user/builds/postgresql/log'

2) After starting the server, two files are being created in the
directory with logs:

-rw------- 1 user user  1,4K oct 10 13:29 postgresql-2024-10-10_132907.csv
-rw------- 1 user user  172 oct 10 13:29 postgresql-2024-10-10_132907.log

3) The .log file is created anyway, regardless of the log_destination
parameter.
The following message is displayed in the .log file (due to the fact
that the log_destination
parameter is set = 'csvlog'):
|
|2024-10-10 13:05:52.539 MSK [1629065] LOG:  ending log output to stderr
2024-10-10 13:05:52.539 MSK [1629065] HINT:  Future log output will go
to log destination "csvlog".

Next, the stderr stream is redirected to a .csv file.

4) Now, logs are rotated once a minute (due to the set log_rotation_age
parameter). Moreover, all
open log files are rotated, including the .log file that I wrote about
above. New ones are being created
.csv and .log files. Logs themselves are sent to .csv, and nothing else
is output to .log
and it remains empty:

-rw------- 1 user user 1,4K oct 10 13:29 postgresql-2024-10-10_132907.csv
-rw------- 1 user user  172 oct 10 13:29 postgresql-2024-10-10_132907.log
-rw------- 1 user user 1,4K oct 10 13:30 postgresql-2024-10-10_133000.csv
-rw------- 1 user user    0 oct 10 13:30 postgresql-2024-10-10_133000.log

--Fix:

To correct the situation, you can add a check for the "Log_destination"
parameter in the "logfile_rotate()"
function of the "syslogger.c" module. Then only the logs specified in
this parameter will be rotated.Thisis doneinthe proposedpatch.

Yeah, creating all those files seems rather unnecessary. But wouldn't it
be easier to do the check in logfile_rotate_dest(), instead of for each
call? I think something like this would do the trick:

@@ -1292,6 +1292,9 @@ logfile_rotate_dest(bool time_based_rotation, int
size_rotation_for,
if (!time_based_rotation && (size_rotation_for & target_dest) == 0)
return true;

+    if ((Log_destination & target_dest) == 0)
+        return true;
+
     /* file extension depends on the destination type */
     if (target_dest == LOG_DESTINATION_STDERR)
         logFileExt = NULL;

In fact, isn't it wrong to do the check outside? logfile_rotate_dest()
is responsible for closing the log files too, and with the check outside
we keep the first .log file open forever (lsof shows that).

FWIW my fix has the same issue, but IMO that just means the logic needs
to be more complex, but still in logfile_rotate_dest().

regards

--
Tomas Vondra

Hi, Tomas.

08.12.2024 01:06, Tomas Vondra wrote:

Yeah, creating all those files seems rather unnecessary. But wouldn't it
be easier to do the check in logfile_rotate_dest(), instead of for each
call? I think something like this would do the trick:

@@ -1292,6 +1292,9 @@ logfile_rotate_dest(bool time_based_rotation, int
size_rotation_for,
      if (!time_based_rotation && (size_rotation_for & target_dest) == 0)
          return true;

+    if ((Log_destination & target_dest) == 0)
+        return true;
+
      /* file extension depends on the destination type */
      if (target_dest == LOG_DESTINATION_STDERR)
          logFileExt = NULL;

Thanks for the comments, I agree that it is better to move the check to
logfile_rotate_dest().

In fact, isn't it wrong to do the check outside? logfile_rotate_dest()
is responsible for closing the log files too, and with the check outside
we keep the first .log file open forever (lsof shows that).

FWIW my fix has the same issue, but IMO that just means the logic needs
to be more complex, but still in logfile_rotate_dest().

You can close the first file if you remove the second part of the
condition in
if (because it is stderr). I checked it in lsof and the first log file is
closing:

@@ -1274,8 +1274,7 @@ logfile_rotate_dest(bool time_based_rotation, int
size_rotation_for,
       * is assumed to be always opened even if stderr is disabled in
       * log_destination.
       */
-    if ((Log_destination & target_dest) == 0 &&
-        target_dest != LOG_DESTINATION_STDERR)
+    if ((Log_destination & target_dest) == 0)
   {
     if (*logFile != NULL)
       fclose(*logFile);

But the comment above says that stderr should always remain open, even if
disabled in log_destination. Is it really necessary to do more complex
logic
in order to close this file? I'm sorry if I misunderstood something.

What do you think about this?

Best regards,
Arseny Kositsin.

On Fri, Dec 13, 2024 at 02:21:45PM +0300, Arseny Kositsin wrote:

08.12.2024 01:06, Tomas Vondra wrote:

In fact, isn't it wrong to do the check outside? logfile_rotate_dest()
is responsible for closing the log files too, and with the check outside
we keep the first .log file open forever (lsof shows that).

FWIW my fix has the same issue, but IMO that just means the logic needs
to be more complex, but still in logfile_rotate_dest().

Yep. All destination checks should be inside logfile_rotate_dest().
That's way cleaner to isolate which files to close and/or open when
the destinations switch.

You can close the first file if you remove the second part of the condition
in if (because it is stderr). I checked it in lsof and the first log file is
closing:

@@ -1274,8 +1274,7 @@ logfile_rotate_dest(bool time_based_rotation, int
size_rotation_for,
      * is assumed to be always opened even if stderr is disabled in
      * log_destination.
      */
-    if ((Log_destination & target_dest) == 0 &&
-        target_dest != LOG_DESTINATION_STDERR)
+    if ((Log_destination & target_dest) == 0)
  {
    if (*logFile != NULL)
      fclose(*logFile);

But the comment above says that stderr should always remain open, even if
disabled in log_destination. Is it really necessary to do more complex logic
in order to close this file? I'm sorry if I misunderstood something.

If you do that the stderr log file would be closed when the stderr
destination is disabled.

What do you think about this?

The comment you are pointed to has been added in 5c6e33f07153 (in
15~), but keeping the logfile fd for stderr opened all the time is
something historically much older than that so as, AFAIK, it can act
as a backup destination even if the syslogger is not started yet for
the postmaster or some of the other destination file could not be
opened. See also bff84a547d71, that has added a second comment in
write_syslogger_file() telling a few more details about the reason
why. The bug fixed by this commit is not "that" old, so you cannot do
what you are suggesting.

It's true that some of these files are useless to keep around when
there is an aggressive rotation, but does it really matter? I am
sure that there are many external tools that browse the contents of
the log directory and perform a cleanup of past files based on their
timestamp and the file name formats (like daily cleanups, etc). So
there is the argument that not rotating the stderr files would cause
harm as some files to actually keep would be removed by such tools.
--
Michael

On Tue, 29 Oct 2024 at 13:38, Арсений Косицын <a.kositsyn@postgrespro.ru> wrote:

Hi everyone!

A situation has been discovered in which empty .log files are being created.

--Reproduce:

1) You need to set the following parameters in the "postgresql.conf" file:

log_destination = 'csvlog'
logging_collector = on
log_rotation_age = 1min
log_directory = '/home/user/builds/postgresql/log'

2) After starting the server, two files are being created in the directory with logs:

-rw------- 1 user user 1,4K oct 10 13:29 postgresql-2024-10-10_132907.csv
-rw------- 1 user user 172 oct 10 13:29 postgresql-2024-10-10_132907.log

3) The .log file is created anyway, regardless of the log_destination parameter.
The following message is displayed in the .log file (due to the fact that the log_destination
parameter is set = 'csvlog'):

2024-10-10 13:05:52.539 MSK [1629065] LOG: ending log output to stderr
2024-10-10 13:05:52.539 MSK [1629065] HINT: Future log output will go to log destination "csvlog".

Next, the stderr stream is redirected to a .csv file.

4) Now, logs are rotated once a minute (due to the set log_rotation_age parameter). Moreover, all
open log files are rotated, including the .log file that I wrote about above. New ones are being created
.csv and .log files. Logs themselves are sent to .csv, and nothing else is output to .log
and it remains empty:

-rw------- 1 user user 1,4K oct 10 13:29 postgresql-2024-10-10_132907.csv
-rw------- 1 user user 172 oct 10 13:29 postgresql-2024-10-10_132907.log
-rw------- 1 user user 1,4K oct 10 13:30 postgresql-2024-10-10_133000.csv
-rw------- 1 user user 0 oct 10 13:30 postgresql-2024-10-10_133000.log

--Fix:

To correct the situation, you can add a check for the "Log_destination" parameter in the "logfile_rotate()"
function of the "syslogger.c" module. Then only the logs specified in this parameter will be rotated. This is done in the proposed patch.

Some agreed-upon comments from [1]/messages/by-id/4dc16c9a-a546-48a6-a8df-ab7441a008a6@postgrespro.ru need to be addressed. I'm changing
the status to "Waiting on Author." Please resolve the comments, submit
a V2 patch, and update the status back to "Needs Review."
[1]: /messages/by-id/4dc16c9a-a546-48a6-a8df-ab7441a008a6@postgrespro.ru

Regards,
Vignesh

On Tue, 2024-10-29 at 11:08 +0300, Арсений Косицын wrote:

 log_destination = 'csvlog'
 logging_collector = on
 log_rotation_age = 1min
 log_directory = '/home/user/builds/postgresql/log'

 2) After starting the server, two files are being created in the directory with logs:

 -rw------- 1 user user  1,4K oct 10 13:29 postgresql-2024-10-10_132907.csv
 -rw------- 1 user user  172 oct 10 13:29 postgresql-2024-10-10_132907.log

 3) The .log file is created anyway, regardless of the log_destination parameter.
 [...]

 Next, the stderr stream is redirected to a .csv file.

 4) Now, logs are rotated once a minute (due to the set log_rotation_age parameter). Moreover, all
 open log files are rotated, including the .log file that I wrote about above. New ones are being created
 .csv and .log files. Logs themselves are sent to .csv, and nothing else is output to .log
 and it remains empty:

 --Fix:

 To correct the situation, you can add a check for the "Log_destination" parameter in the "logfile_rotate()"
 function of the "syslogger.c" module. Then only the logs specified in this parameter will be rotated.
This is done in the proposed patch.

I see your point, but I am having doubts.

You say that the stderr stream is redirected to the CSV file, but that is not true.
Anything that a PostgreSQL process writes to stderr will still end up in the *.log file.
For example, any error message from the archive_command will end up there, not in the
CSV log.

I think that that is pretty useful.

Where do such messages end up with your patch? I didn't test, but I guess they'll
just be written to the console and get lost.
The empty (or almost empty) *.log files are not pretty, but are they a problem
to solve at the price of losing potentially interesting information?

Yours,
Laurenz Albe

Laurenz Albe <laurenz.albe@cybertec.at> writes:

You say that the stderr stream is redirected to the CSV file, but that is not true.
Anything that a PostgreSQL process writes to stderr will still end up in the *.log file.
For example, any error message from the archive_command will end up there, not in the
CSV log.

Yes. An important point here is that we must not assume that all
stderr output from a Postgres server process goes through elog.c.
It's possible to have random other stuff loaded, such as Python
modules invoked via PL/Python, and there's no guarantee that such
code won't write valuable information to stderr. Another example
that doesn't require any extension at all is that if glibc detects
corruption of malloc'd memory, it will complain about that on
stderr.

So the argument that these .log files won't contain any useful
data is false.

A conceivable improvement is to make the logger unlink a log file if
it's still empty after we stop using it. Even that would need a
switch IMO, since it might break somebody's log-archiving script.
But I'm doubtful that it's worth the trouble.

regards, tom lane

On Tue, Nov 18, 2025 at 06:31:19PM -0500, Tom Lane wrote:

So the argument that these .log files won't contain any useful
data is false.

A conceivable improvement is to make the logger unlink a log file if
it's still empty after we stop using it. Even that would need a
switch IMO, since it might break somebody's log-archiving script.
But I'm doubtful that it's worth the trouble.

FWIW, after reading again the thread and the arguments in place, I am
still not convinced that there is something to do here.
--
Michael

On Mon, Nov 24, 2025 at 07:49:11PM +0900, Michael Paquier wrote:

FWIW, after reading again the thread and the arguments in place, I am
still not convinced that there is something to do here.

I have been reminded about this one while doing some CF maintenance
cleanup for what's classified as a bug fix, because we still need to
track all of these... And, while this is not a bug, I still see
nothing that we need to do. So I have switched the category of the CF
entry, and marked the entry as rejected.
--
Michael