Re: log_truncate_on_rotation=on is not truncating

Hi Chan,

I think this is configuration issue.

This issue is happening because log files will always append when
server is restarted. What I can see from your configuration,
log_rotation_age=1d (1 day) which is greater than daily schedule
shutdown/restart time. So this is the reason why log files are growing.

You can change the log_rotation_age=8h (i.e. any time less than the
schedule shutdown/restart time) as log file name
Is postgreql-%a.log this is sufficient to preserve till last week's log, as
at the time of rotation after 8 hours if the day is not changed then log
file name will be same as previous then truncation will not happen.

 
Thanks & Regards,
Kiran Kumar
   

--------------------------
VISWANATHAM  KIRAN KUMAR
SENIOR TECHNICAL LEADER.
HUAWEI TECHNOLOGIES INDIA PVT. LTD.
EXTN: 7560; LEVEL-7 C & D TOWER
DIAMOND DISTRICT, OLD AIRPORT ROAD
BANGALORE-08
MOBILE: +91-9945115987
 

From: pgsql-bugs-owner(at)postgresql(dot)org
[mailto:pgsql-bugs-owner(at)postgresql(dot)org] On Behalf Of Chan Pham
Sent: Wednesday, June 20, 2012 11:54 PM
To: pgsql-bugs(at)postgresql(dot)org
Subject: [BUGS] log_truncate_on_rotation=on is not truncating

We discovered that on our servers where we do daily shutdown and startup for
a cold backup, the pg_log logs are not truncated when it switches to the new
day, when log_truncation_on_rotation=on. The shutdown/startup of postgresql
happens daily at 16:00 system time. Also observed that only when the
shutdown event happen at 16:00 pm, it is only when the log is rotated for
the current day, and the event message is appended to last week's
postgreql-%a.log. 
On our other servers where there is not a daily shutdown/startup, the
postgresql-%a.log is rotated to the new day at 00:00 hour and is truncated
of all last week's content. We first noticed this only our standby servers
where we do daily cold backup and restart postgresql, and no other
activities. Then I was able to reproduce this issue on a standalone server
by scheduling a daily shutdown/restart.

Here are settings and log details:

Postgresql is shutdown/startup via service:
   /sbin/service postgresql-9.1 stop/start  -- calls pg_ctl

OS versions:
 centos-release-notes-5.5-0
  and
 centos-release-6-2.el6.centos.7.x86_64

PostgreSQL version:
   PostgreSQL 9.1.3 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6
20110731 (Red Hat 4.4.6-3), 64-bit
   and
   PostgreSQL 9.1.4 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6
20110731 (Red Hat 4.4.6-3), 64-bit

Postgresql.conf settings for pg_logs related:
   logging_collector=on
   log_directory='pg_log'
   log_filename='postgresql-%a.log'
   log_truncate_on_rotation=on
   log_rotation_age=1d
   log_rotation_size=0

   timezone = 'UTC'

Service timezone:  
>date
Tue Jun 19 11:25:56 PDT 2012

Content of a postgresql-Tue.log in its entirety. Note this is a standby
slave so there are not much activities other than shutdown/restart performed
for a cold backup. The bold date is just to de-mark the current day where
the entries were appended. The entries of 2012-06-19 was an intentional
syntax error to get the an entry for the current day.

2012-06-12 16:00:02 PDT   23761 4fd67fc4.5cd1 LOG:  received fast shutdown
request
2012-06-12 16:00:02 PDT   23761 4fd67fc4.5cd1 LOG:  aborting any active
transactions
2012-06-12 16:00:02 PDT   23800 4fd67fc8.5cf8 FATAL:  terminating
walreceiver process due to administrator command
2012-06-12 16:00:02 PDT   23765 4fd67fc5.5cd5 LOG:  shutting down
2012-06-12 16:00:02 PDT   23765 4fd67fc5.5cd5 LOG:  database system is shut
down
2012-06-12 16:31:08 PDT   30458 4fd7d13c.76fa LOG:  database system was shut
down in recovery at 2012-06-12 16:00:02 PDT
2012-06-12 16:31:08 PDT   30458 4fd7d13c.76fa LOG:  entering standby mode
2012-06-12 16:31:08 PDT   30458 4fd7d13c.76fa LOG:  redo starts at
6B/D3E1EA70
2012-06-12 16:31:10 PDT   30458 4fd7d13c.76fa LOG:  consistent recovery
state reached at 6B/DB8FDFE8
2012-06-12 16:31:10 PDT   30458 4fd7d13c.76fa LOG:  unexpected pageaddr
69/D68FE000 in log file 107, segment 219, offset 9428992
2012-06-12 16:31:10 PDT   30454 4fd7d13a.76f6 LOG:  database system is ready
to accept read only connections
2012-06-12 16:31:11 PDT   30494 4fd7d13e.771e LOG:  streaming replication
successfully connected to primary
2012-06-19 11:22:04 PDT postgres [local] 30698 4fe0c34c.77ea ERROR:  syntax
error at or near ":" at character 17
2012-06-19 11:22:04 PDT postgres [local] 30698 4fe0c34c.77ea STATEMENT:
 select version():

Listing of pg_log directory. You can see here that the last entry of each
day (file timestamp) is when postgresql is restarted at 16:30. Except June
19, I just force a syntax error to create an entry for today, June 19:

-rw------- 1 postgres postgres 1403 Jun 13 16:30 postgresql-Wed.log
-rw------- 1 postgres postgres 2868 Jun 14 16:31 postgresql-Thu.log
-rw------- 1 postgres postgres 2418 Jun 15 16:31 postgresql-Fri.log
-rw------- 1 postgres postgres 2222 Jun 16 16:31 postgresql-Sat.log
-rw------- 1 postgres postgres 2208 Jun 17 16:30 postgresql-Sun.log
-rw------- 1 postgres postgres 2832 Jun 18 16:31 postgresql-Mon.log
-rw------- 1 postgres postgres 1355 Jun 19 11:22 postgresql-Tue.log

Here's normal behavior on a server that does NOT get restarted daily. The
logs are all rotated and truncated at 00:00 as expected:
$ pwd
/data/postgres/9.1/pg_log
ls -ltr
total 4
-rw------- 1 postgres postgres    0 Jun 13 00:00 postgresql-Wed.log
-rw------- 1 postgres postgres    0 Jun 14 00:00 postgresql-Thu.log
-rw------- 1 postgres postgres 1563 Jun 15 14:12 postgresql-Fri.log
-rw------- 1 postgres postgres    0 Jun 16 00:00 postgresql-Sat.log
-rw------- 1 postgres postgres    0 Jun 17 00:00 postgresql-Sun.log
-rw------- 1 postgres postgres    0 Jun 18 00:00 postgresql-Mon.log
-rw------- 1 postgres postgres    0 Jun 19 00:00 postgresql-Tue.log
--

Chan Pham
Database Administrator

Direct: 503.943.6773
Fax: 503.224.1581 // AIM: ioChanny // Twitter: iovation
www.iovation.com