classification
Title: logging midnight rotation
Type: behavior Stage:
Components: Extension Modules Versions: Python 2.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: SanityIO, peter9477, vinay.sajip
Priority: normal Keywords:

Created on 2009-06-10 08:30 by SanityIO, last changed 2010-01-15 17:28 by peter9477. This issue is now closed.

Files
File name Uploaded Description Edit
httpd.py vinay.sajip, 2009-06-10 16:03 Test script which simulates rollover at midnight
httpd.py SanityIO, 2009-06-11 03:52
Messages (5)
msg89191 - (view) Author: Turnaev Evgeny (SanityIO) Date: 2009-06-10 08:30
i have a very basic setup of logging in a long running daemon app..
I use TimedRotatingFileHandler with rotating at midnight.
The bug:
The last open logging file was for 2009-05-25..
app was running without logging anything for about a week or more.
After a week past something happened and daemon started to log messages,
but.. for each new message logging system creates new file.
In other words.. suppose we was idle since 2009-05-25, now it is 
2009-06-10 and we want to log 10 messages.. 
current opened file is for 2009-05-25.. so when a first messages
arrives into logging system current must be closed. and a new file must 
be opened where all 10 messages should be..
but instead logging system will log each subsequent message in files 
2009-05-26, 2009-05-27, 2009-05-28..(in fact it will log in file 
without a date and then when nect message arives rename current to 
2009-05-26, 2009-05-27, 2009-05-28.. but is still the same) and so on, 
one message per file.. i think until it reaches current date.
It is a logic error.


my logging setup looks like this:
---------
import logging
from logging import debug,warning,info,error,critical
from logging.handlers import TimedRotatingFileHandler

log_path = '/var/log/cherry/smsd_reg'
log_level = logging.DEBUG

basic_log_handler = TimedRotatingFileHandler(log_path + "/
app_log_smsd_reg_server",'midnight',1)
basic_log_handler.setLevel(log_level)
basic_log_formatter = logging.Formatter('%(asctime)s pid: %(process)d, 
%(levelname)s %(message)s')
basic_log_handler.setFormatter(basic_log_formatter)
logging.getLogger('').addHandler(basic_log_handler)
logging.getLogger('').setLevel(log_level)

----------------

system info:
Python 2.5.1
FreeBSD 6.2-RELEASE-p7 FreeBSD 6.2-RELEASE-p7
msg89207 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-06-10 16:03
I'm unable to reproduce this problem with Python 2.5.2 on either Windows
XP or Ubuntu Hardy.

I used a test script (httpd.py, attached). This sets up an HTTP server
which you can use to trigger logging events.

I created a time simulator to allow testing in a timely way. This
monkey-patches the binding for the time module in logging and
logging.handlers to return either the real time or the simulated time.
Once you have started the server (just run the script), you can trigger
a logging event by running

wget -o /dev/null http://localhost:9022/

and you can initiate simulated timing by running

wget -o /dev/null http://localhost:9022/s

The simulated time is set to the next midnight, to facilitate rollover.
I then ran

wget -o /dev/null http://localhost:9022/

three times, then

wget -o /dev/null http://localhost:9022/s

once, then

wget -o /dev/null http://localhost:9022/

again three times. The only files created were:

vinay@zeta-hardy:~$ ls -l  httpd.log*
-rw-r--r-- 1 vinay vinay 192 2009-06-10 16:46 httpd.log
-rw-r--r-- 1 vinay vinay 256 2009-06-10 16:46 httpd.log.2009-06-10

which is as expected, and the contents are:

vinay@zeta-hardy:~$ cat httpd.log.2009-06-10 
2009-06-10 16:46:22,999 pid: 512 DEBUG - OK 2009-06-10 16:46:22
2009-06-10 16:46:23,765 pid: 512 DEBUG - OK 2009-06-10 16:46:23
2009-06-10 16:46:24,406 pid: 512 DEBUG - OK 2009-06-10 16:46:24
2009-06-10 16:46:25,974 pid: 512 DEBUG - OK 2009-06-10 16:46:25

and

vinay@zeta-hardy:~$ cat httpd.log
2009-06-11 00:00:01,260 pid: 512 DEBUG - OK 2009-06-11 00:00:01
2009-06-11 00:00:01,923 pid: 512 DEBUG - OK 2009-06-11 00:00:01
2009-06-11 00:00:02,547 pid: 512 DEBUG - OK 2009-06-11 00:00:02

which is again as expected.

Please try out the test script in your environment and feed back the
results you get.
msg89236 - (view) Author: Turnaev Evgeny (SanityIO) Date: 2009-06-11 03:52
I am sorry for my poor english. You must be misunderstood me.
I attached a file try it like this:

wget -o /dev/null http://localhost:9022/

then 5-7 times
wget -o /dev/null http://localhost:9022/s

then 4-5 times 
wget -o /dev/null http://localhost:9022/

i bet this error persists in 3.1
msg89246 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2009-06-11 10:32
Fix checked into trunk, release26-maint and py3k.
msg97828 - (view) Author: Peter Hansen (peter9477) Date: 2010-01-15 17:28
In the NEWS file, this was recorded as fixed using the wrong issue number.  The entry reads "Issue #5262: Fixed bug in next rollover time computation in TimedRotatingFileHandler." rather than "Issue #6252".
History
Date User Action Args
2010-01-15 17:28:05peter9477setnosy: + peter9477
messages: + msg97828
2009-06-11 10:32:09vinay.sajipsetstatus: open -> closed
resolution: works for me -> fixed
messages: + msg89246
2009-06-11 03:52:58SanityIOsetfiles: + httpd.py
status: pending -> open
messages: + msg89236
2009-06-10 16:03:29vinay.sajipsetstatus: open -> pending
files: + httpd.py
resolution: works for me
messages: + msg89207
2009-06-10 10:30:12vinay.sajipsetassignee: vinay.sajip

nosy: + vinay.sajip
title: logging midnigh rotation -> logging midnight rotation
2009-06-10 08:30:54SanityIOcreate