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

<http://www.iovation.com/eml-msg/>
*