logging midnight rotation

[9fec6ef2-64d7-411a-8b4e-64a182db81ed]

BPO	6252
Nosy	@vsajip
Files	httpd.py: Test script which simulates rollover at midnight httpd.py

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields: ```python assignee = 'https://github.com/vsajip' closed_at = created_at = labels = ['extension-modules', 'type-bug'] title = 'logging midnight rotation' updated_at = user = 'https://bugs.python.org/SanityIO' ``` bugs.python.org fields: ```python activity = actor = 'peter9477' assignee = 'vinay.sajip' closed = True closed_date = closer = 'vinay.sajip' components = ['Extension Modules'] creation = creator = 'SanityIO' dependencies = [] files = ['14258', '14263'] hgrepos = [] issue_num = 6252 keywords = [] message_count = 5.0 messages = ['89191', '89207', '89236', '89246', '97828'] nosy_count = 3.0 nosy_names = ['vinay.sajip', 'SanityIO', 'peter9477'] pr_nums = [] priority = 'normal' resolution = 'fixed' stage = None status = 'closed' superseder = None type = 'behavior' url = 'https://bugs.python.org/issue6252' versions = ['Python 2.5'] ```

[9fec6ef2-64d7-411a-8b4e-64a182db81ed]

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

[vsajip]

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.

[9fec6ef2-64d7-411a-8b4e-64a182db81ed]

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

[vsajip]

Fix checked into trunk, release26-maint and py3k.

[9622be6b-560e-49e8-bfda-ea89f3bd1b5d]

In the NEWS file, this was recorded as fixed using the wrong issue number. The entry reads "Issue bpo-5262: Fixed bug in next rollover time computation in TimedRotatingFileHandler." rather than "Issue bpo-6252".