Thread: BUG #7890: wrong behaviour using pg_rotate_logfile() with parameter log_truncate_on_rotation = on

The following bug has been logged on the website:

Bug reference:      7890
Logged by:          Sari Thiele
Email address:      sari.thiele@usit.uio.no
PostgreSQL version: 9.1.8
Operating system:   Red Hat Enterprise Linux Server release 6.3
Description:        =


Hi,

I am trying to use the function pg_rotate_logfile() to force a truncate of
the current log file by setting the parameter "log_truncate_on_rotation =3D
on".
But it looks like that this does not work, like I expected. =


System info:
Red Hat Enterprise Linux Server release 6.3 (Santiago)

select version();
                                                  version                   =

                                =

---------------------------------------------------------------------------=
-----------------------------------
 PostgreSQL 9.1.8 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6
20120305 (Red Hat 4.4.6-4), 64-bit


Parameter set-up:

log_filename =3D 'postgresql-%F_%H.log'
logging_collector =3D on
log_truncate_on_rotation =3D on
log_rotation_age =3D 1h
log_rotation_size =3D 0 =


SELECT pg_rotate_logfile();

After the function call, the file is still filled with the previous data.
After my understanding the log file should be emptied (truncated).
 =

-----------
To check if there is something wrong with my set-up, I did some other tests,
too.

1.
log_filename =3D 'postgresql-%F_%T.log'
logging_collector =3D on
log_truncate_on_rotation =3D on
log_rotation_age =3D 1h
log_rotation_size =3D 0 =


SELECT pg_rotate_logfile();

After the function call a new file is generated, because of the logfilename
string (HH:MM:ss).
This is correct.

-------------------------
2.
log_filename =3D 'postgresql-%M.log'
logging_collector =3D on
log_truncate_on_rotation =3D on
log_rotation_age =3D 10min  =

log_rotation_size =3D 0

Here is the file automatically truncated after an hour, because of the file
name. So that works also correct.

----

We checked the source code and it looks like the problem could be here:

src/backend/postmaster/syslogger.c


/*
 * Decide whether to overwrite or append.  We can overwrite if (a)
 * Log_truncate_on_rotation is set, (b) the rotation was triggered by
 * elapsed time and not something else, and (c) the computed file name is
 * different from what we were previously logging into.
 *
 * Note: last_file_name should never be NULL here, but if it is, append.
 */
 if (time_based_rotation || (size_rotation_for &LOG_DESTINATION_STDERR))
    {
     if (Log_truncate_on_rotation && time_based_rotation &&
         last_file_name !=3D NULL &&
         strcmp(filename, last_file_name) !=3D 0) =3D=3D> *
        fh =3D logfile_open(filename, "w", true);
     else
        fh =3D logfile_open(filename, "a", true);

 =

=3D=3D> * this checks if the new file name is different from the old one.
In my case it is still the same name and so the new log lines will be
appended to the current file, not truncated like I expected.
I think this is the wrong behaviour, what do you think?

Cheers,

Sari Thiele
 Center for Information Technology
 University of Oslo, Norway

On Monday, February 18, 2013 5:42 PM sari thiele wrote:
> The following bug has been logged on the website:
>=20
> Bug reference:      7890
> Logged by:          Sari Thiele
> Email address:      sari.thiele@usit.uio.no
> PostgreSQL version: 9.1.8
> Operating system:   Red Hat Enterprise Linux Server release 6.3
> Description:
>=20
> Hi,
>=20
> I am trying to use the function pg_rotate_logfile() to force a =
truncate
> of
> the current log file by setting the parameter =
"log_truncate_on_rotation
> =3D
> on".
> But it looks like that this does not work, like I expected.
>=20
> System info:
> Red Hat Enterprise Linux Server release 6.3 (Santiago)
>=20
> select version();
>                                                   version
>=20
> =
-----------------------------------------------------------------------
> ---------------------------------------
>  PostgreSQL 9.1.8 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
> 4.4.6
> 20120305 (Red Hat 4.4.6-4), 64-bit
>=20
>=20
> Parameter set-up:
>=20
> log_filename =3D 'postgresql-%F_%H.log'
> logging_collector =3D on
> log_truncate_on_rotation =3D on
> log_rotation_age =3D 1h
> log_rotation_size =3D 0
>=20
> SELECT pg_rotate_logfile();
>=20
> After the function call, the file is still filled with the previous
> data.
> After my understanding the log file should be emptied (truncated).
>=20
> -----------
> To check if there is something wrong with my set-up, I did some other
> tests,
> too.
>=20
> 1.
> log_filename =3D 'postgresql-%F_%T.log'
> logging_collector =3D on
> log_truncate_on_rotation =3D on
> log_rotation_age =3D 1h
> log_rotation_size =3D 0
>=20
> SELECT pg_rotate_logfile();
>=20
> After the function call a new file is generated, because of the
> logfilename
> string (HH:MM:ss).
> This is correct.
>=20
> -------------------------
> 2.
> log_filename =3D 'postgresql-%M.log'
> logging_collector =3D on
> log_truncate_on_rotation =3D on
> log_rotation_age =3D 10min
> log_rotation_size =3D 0
>=20
> Here is the file automatically truncated after an hour, because of the
> file
> name. So that works also correct.
>=20
> ----
>=20
> We checked the source code and it looks like the problem could be =
here:
>=20
> src/backend/postmaster/syslogger.c
>=20
>=20
> /*
>  * Decide whether to overwrite or append.  We can overwrite if (a)
>  * Log_truncate_on_rotation is set, (b) the rotation was triggered by
>  * elapsed time and not something else, and (c) the computed file name
> is
>  * different from what we were previously logging into.
>  *
>  * Note: last_file_name should never be NULL here, but if it is,
> append.
>  */
>  if (time_based_rotation || (size_rotation_for
> &LOG_DESTINATION_STDERR))
>     {
>      if (Log_truncate_on_rotation && time_based_rotation &&
>          last_file_name !=3D NULL &&
>          strcmp(filename, last_file_name) !=3D 0) =3D=3D> *
>         fh =3D logfile_open(filename, "w", true);
>      else
>         fh =3D logfile_open(filename, "a", true);
>=20
>=20
> =3D=3D> * this checks if the new file name is different from the old =
one.
> In my case it is still the same name and so the new log lines will be
> appended to the current file, not truncated like I expected.
> I think this is the wrong behaviour, what do you think?

The only reason is you have used pg_rotate_logfile() to perform the =
action, otherwise if it would have been done
based on time, it should have truncated the file.
Why you think this is wrong behavior, do you expect any time you call =
pg_rotate_logfile(), it should truncate the file if
log_truncate_on_rotation is on?
I think if you are expecting such behavior, it might not be right =
expectation, because it considers the the time and log_filename format =
as well.=20

With Regards,
Amit Kapila.

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 02/18/2013 03:41 PM, Amit Kapila wrote:
[...........]
> Why you think this is wrong behavior, do you expect any time you
> call pg_rotate_logfile(), it should truncate the file if
> log_truncate_on_rotation is on? I think if you are expecting such
> behavior, it might not be right expectation, because it considers
> the the time and log_filename format as well.
>

Hello

I agree with Sari in this report.

If you call pg_rotate_logfile() AND log_truncate_on_rotation is on,
the logfile should be truncated. This should happen even if the
logfile name does not change during rotation, and even if
log_rotation_age / log_rotation_size are defined.

According to the documentation:

"log_truncate_on_rotation ... When logging_collector is enabled, this
parameter will cause PostgreSQL to truncate (overwrite), rather than
append to, any existing log file of the same name ..."

"... pg_rotate_logfile signals the log-file manager to switch to a new
output file immediately"

regards,
- --
 Rafael Martinez Guerrero
 Center for Information Technology
 University of Oslo, Norway

 PGP Public Key: http://folk.uio.no/rafael/
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.14 (GNU/Linux)

iEYEARECAAYFAlEiQX8ACgkQBhuKQurGihRJLwCeIrZFkLDuAIOK21k5Ez4jIV2x
WgcAnAxJYJkfH2+uzb778AH8QL1qGRjq
=a4kS
-----END PGP SIGNATURE-----

On Monday, February 18, 2013 8:28 PM Rafael Martinez wrote:
> On 02/18/2013 03:41 PM, Amit Kapila wrote:
> [...........]
> > Why you think this is wrong behavior, do you expect any time you
> > call pg_rotate_logfile(), it should truncate the file if
> > log_truncate_on_rotation is on? I think if you are expecting such
> > behavior, it might not be right expectation, because it considers
> > the the time and log_filename format as well.
> >
>=20
> Hello
>=20
> I agree with Sari in this report.
>=20
> If you call pg_rotate_logfile() AND log_truncate_on_rotation is on,
> the logfile should be truncated. This should happen even if the
> logfile name does not change during rotation, and even if
> log_rotation_age / log_rotation_size are defined.
>=20
> According to the documentation:
>=20
> "log_truncate_on_rotation ... When logging_collector is enabled, this
> parameter will cause PostgreSQL to truncate (overwrite), rather than
> append to, any existing log file of the same name ..."

Further description for log_truncate_on_rotation is as follows:

However, truncation will occur only when a new file is being opened due =
to time-based rotation, not during server startup or size-based =
rotation.

For example, using this setting in combination with a log_filename like =
postgresql-%H.log would result in generating twenty-four hourly log =
files and then cyclically overwriting them. This parameter can only be =
set in the postgresql.conf file or on the server command line.=20

Example: To keep 7 days of logs, one log file per day named =
server_log.Mon, server_log.Tue, etc, and automatically overwrite last =
week's log with this week's log, set log_filename to server_log.%a, =
log_truncate_on_rotation to on, and log_rotation_age to 1440.

In the examples, it is clearly shown that, truncation will not happen =
only on based of log_truncate_on_rotation.


> "... pg_rotate_logfile signals the log-file manager to switch to a new
> output file immediately"

By reading the description of pg_rotate_logfile, it can mean that this =
is function to achieve what you are saying.
But as per code, it is not so.

By the way, why you want this function to behave in such a way, that it =
can override the meaning of other log parameters?

With Regards,
Amit Kapila.

sari.thiele@usit.uio.no writes:
> ==> * this checks if the new file name is different from the old one.
> In my case it is still the same name and so the new log lines will be
> appended to the current file, not truncated like I expected.
> I think this is the wrong behaviour, what do you think?

No, that behavior is intentional.  Otherwise you'd lose log data
earlier than the configuration specifies.

            regards, tom lane

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 02/19/2013 10:54 AM, Tom Lane wrote:
> sari.thiele@usit.uio.no writes:
>> ==> * this checks if the new file name is different from the old
>> one. In my case it is still the same name and so the new log
>> lines will be appended to the current file, not truncated like I
>> expected. I think this is the wrong behaviour, what do you
>> think?
>
> No, that behavior is intentional.  Otherwise you'd lose log data
> earlier than the configuration specifies.
>
> regards, tom lane
>
>

Hei Tom

Well, the "problem" is there even with log_rotation_age = 0 and
log_rotation_size = 0.

If the behavior we are talking about is intentional, why do be have
pg_rotate_logfile() if we can not manually override with this function
log_rotation_age and log_rotation_size?

When rotating log files you can control 3 things, and they define or
should define different aspects of the rotation:

1) When to rotate
- -------------------

When to rotate the log file can be defined to happen automatically by
log_rotation_age and/or log_rotation_size, or it can be done manually by
pg_rotate_logfile().


2) Name of the log file
- ------------------------

The name of the log file can be:

- - always the same
- - always different
- - can be defined so it will be recycled after a while.


3) Use truncation or not when creating a log file.
- --------------------------------------------------

This is or should be independent of 1) and 2). It only defines if the
log file we are going to start using will start from scratch or not if
it already exists regardless of the log file name.

This is how we see log rotation in a logical way.


Actual behavior
- ---------------

The actual behavior of log rotation in postgreSQL does not follow this
logic and in our humble opinion it is inconsistent and not clear.

Truncation only works if:

- - The old and new log file names are different.
- - A new file is being opened due to time-based rotation, not during
size-based rotation.

Log rotation is in general done so the active log file does not grow
indefinitely.

PostgreSQL is versatile enough to allow you to activate or not
truncation. If truncation is activated, it should work independently
of when we rotate, how we activate the rotation and the name of the
log file.

We are almost there, the actual behavior can be fixed without a lot of
work.

Think about this usercase.

You are using a log file name that does not change  over time (i.e.
postgreSQL.log) and you want to rotate this file so it does not grow
indefinitely (you activate log_truncate_on_rotation).

Then you can provoke the rotation with log_rotation_age,
log_rotation_size or pg_rotate_logfile().

This does not work nowadays. The only way of rotating in this case
will be to stop postgres, delete/rename the log file and start
postgres again.

What you do with an old file after a rotation is another question.
Here PostgreSQL is versatile enough to let you define the name of the
log file in many ways so you can control if the number of "old" files
grow indefinitely or not.

Thanks for your time.

regards,
- --
 Rafael Martinez Guerrero
 Center for Information Technology
 University of Oslo, Norway

 PGP Public Key: http://folk.uio.no/rafael/
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.14 (GNU/Linux)

iEYEARECAAYFAlEjUNkACgkQBhuKQurGihQh5gCfcAmF6h1WAfcicvHx5jCeEdWO
zpIAn3Vjf1DLdAY4jaaZWqyOCBxKmll/
=5dRj
-----END PGP SIGNATURE-----

Rafael Martinez <r.m.guerrero@usit.uio.no> writes:
> If the behavior we are talking about is intentional, why do be have
> pg_rotate_logfile() if we can not manually override with this function
> log_rotation_age and log_rotation_size?

It works fine as long as the filename pattern is such that a new file
would be selected.

If we didn't have this filter, then a rotation operation would wipe out
*current* log entries, even those that were made a millisecond ago.
That can't possibly be a good idea.  Any rotation scheme ought to
provide for recent entries to survive at least until you've rotated
through whichever other log files you have.

            regards, tom lane

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 02/19/2013 11:21 AM, Tom Lane wrote:
> Rafael Martinez <r.m.guerrero@usit.uio.no> writes:
>> If the behavior we are talking about is intentional, why do be
>> have pg_rotate_logfile() if we can not manually override with
>> this function log_rotation_age and log_rotation_size?
>
> It works fine as long as the filename pattern is such that a new
> file would be selected.
>
> If we didn't have this filter, then a rotation operation would wipe
> out *current* log entries, even those that were made a millisecond
> ago. That can't possibly be a good idea.  Any rotation scheme ought
> to provide for recent entries to survive at least until you've
> rotated through whichever other log files you have.
>
> regards, tom lane

Well, postgreSQL is versatile enough to allow you to decide many
aspects of log rotation. It should be the user who decide what will
happen with log data after and during a rotation.

I agree that using a filename pattern such that a new file would be
selected is a god idea, but it is not the only way of doing this and
it should not be the only way.

What if the user wants to use the same log file name all the time, not
archive old data and not to have a log file that grows indefinitely?
This should be a valid option because it is a valid and used scenario
when administrating databases.

What if we want/need to truncate the log file before postgres has to
change the file name according to the log_filename definition?

If the alternative to not lose some log entries while we are rotating
the log file, it is to stop postgres, truncate the log file manually
and start postgres again, I prefer to lose some log entries.

This should not be a problem as long as this is documented and the
user decides to do it this way. And you still have the option of not
losing any entries and archive the old file if you want. But one thing
should not prevent the other.

regards,
- --
 Rafael Martinez Guerrero
 Center for Information Technology
 University of Oslo, Norway

 PGP Public Key: http://folk.uio.no/rafael/
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.14 (GNU/Linux)

iEYEARECAAYFAlEjWt4ACgkQBhuKQurGihTIpQCeJcOmKfnFDMqYllW2YUsywKVl
BxgAoIF+R14GNlvNLNSgxR0lUDDQN23M
=zrAw
-----END PGP SIGNATURE-----

Rafael Martinez <r.m.guerrero@usit.uio.no> writes:
> Well, postgreSQL is versatile enough to allow you to decide many
> aspects of log rotation. It should be the user who decide what will
> happen with log data after and during a rotation.

TBH, I don't think the rotation configuration options need to cater for
stupid choices, and what you're describing sounds like a stupid choice.
Why wouldn't you configure, say, a finite set of daily- or hourly-named
files?  Even just ping-ponging between two log files would be enough to
prevent the scenario where you lose the freshest log entries.

If you don't care about keeping even the latest entries, then you don't
need a log at all, much less rotation --- just pipe it to /dev/null.

            regards, tom lane

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 02/19/2013 12:12 PM, Tom Lane wrote:

> TBH, I don't think the rotation configuration options need to cater
> for stupid choices, and what you're describing sounds like a stupid
> choice. Why wouldn't you configure, say, a finite set of daily- or
> hourly-named files?  Even just ping-ponging between two log files
> would be enough to prevent the scenario where you lose the freshest
> log entries.
>
> If you don't care about keeping even the latest entries, then you
> don't need a log at all, much less rotation --- just pipe it to
> /dev/null.
>
> regards, tom lane


Tom, I think we are talking past each other here.

The point here is that if you need to run pg_rotate_logfile() manually
is because something has happened in your system and you have taken
the decision of running manually a log rotation that truncates the log
file.

Think about this usercase from real live:

log_filename= 'postgres_%m.log'
log_truncate_on_rotation = on
log_rotation_age = 0
log_rotation_size = 0

We run pg_rotate_logfile() from cron every first day of the month at
00:00:01. This will give us 12 files that contain the logdata for the
month defined in the file name and they will we recycled after one
year because of the truncate parameter.

Think now that because an error in an application, or because we have
activated full logs for a period of time for debug purpouses, the size
of the active log file has grown to a point where we have to take
accion to avoid other problems (diskspace, parsing time, etc).

We should be able to run pg_rotate_logfile() i.e. in the middle of the
month and get the active logfile truncated if we are using
log_truncate_on_rotation = on. Don't you think?

In the way pg_rotate_logfile() and log_truncate_on_rotation = on work
today, we have to stop postgres to truncate the log file if an
unexpected situation happens and this is not always possible in a
production system.

If we need to run pg_rotate_logfile() manually in the middle of the
month and we don't want to lose the data in the file that is going to
be truncated, we will have to take a manual copy of it before running
pg_rotate_logfile().

This is a real life administration problem that I have seen many times
in different systems. We want and need logdata and to pipe it to
/dev/null is not an option to us.

truncate_on_rotation for us outside the development world of postgres,
means that, the file will get truncated on rotation independently of
the filename schema used.

Thanks for your time.

regards,
- --
 Rafael Martinez Guerrero
 Center for Information Technology
 University of Oslo, Norway

 PGP Public Key: http://folk.uio.no/rafael/
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.14 (GNU/Linux)

iEYEARECAAYFAlEjcLcACgkQBhuKQurGihRXAQCghoRbIbWVWqb7vhAXY1nDcLEQ
n1QAn0e3me49/jWclcQ8iLKn2uL0A/mM
=NShe
-----END PGP SIGNATURE-----

On 19.02.2013 14:31, Rafael Martinez wrote:
> In the way pg_rotate_logfile() and log_truncate_on_rotation = on work
> today, we have to stop postgres to truncate the log file if an
> unexpected situation happens and this is not always possible in a
> production system.
>
> If we need to run pg_rotate_logfile() manually in the middle of the
> month and we don't want to lose the data in the file that is going to
> be truncated, we will have to take a manual copy of it before running
> pg_rotate_logfile().

You can rm the log file, then do pg_rotate_logfile(). No need to stop
the system.

- Heikki