Problem with Python logging RotatingFileHandler in Django website

Question

I've a django powered website, and I use standard logging module to track web activity.

The log is done via RotatingFileHandler which is configured with 10 log files, 1000000 byte each. The log system works, but this are the log files I get:

-rw-r--r-- 1 apache      apache          83 Jul 23 13:30 hr.log
-rw-r--r-- 1 apache      apache      446276 Jul 23 13:03 hr.log.1
-rw-r--r-- 1 apache      apache      999910 Jul 23 06:00 hr.log.10
-rw-r--r-- 1 apache      apache         415 Jul 23 16:24 hr.log.2
-rw-r--r-- 1 apache      apache      479636 Jul 23 16:03 hr.log.3
-rw-r--r-- 1 apache      apache         710 Jul 23 15:30 hr.log.4
-rw-r--r-- 1 apache      apache      892179 Jul 23 15:03 hr.log.5
-rw-r--r-- 1 apache      apache         166 Jul 23 14:30 hr.log.6
-rw-r--r-- 1 apache      apache      890769 Jul 23 14:03 hr.log.7
-rw-r--r-- 1 apache      apache      999977 Jul 23 12:30 hr.log.8
-rw-r--r-- 1 apache      apache      999961 Jul 23 08:01 hr.log.9

As you can see it is a mess. Last log has been written to file hr.log.2 (Jul 23 16:24) instead of hr.log, and logging documentation states that:

[...]For example, with a backupCount of 5 and a base file name of app.log, you would get app.log, app.log.1, app.log.2, up to app.log.5. The file being written to is always app.log. When this file is filled, it is closed and renamed to app.log.1, and if files app.log.1, app.log.2, etc. exist, then they are renamed to app.log.2, app.log.3 etc. respectively.

What am I doing wrong?

---

My logging configuration file is:

logger.conf:

[loggers]
keys=root

[handlers]
keys=fileHandler

[formatters]
keys=simple

#--------------------------------------------------------------------
# Formatters
[formatter_simple]
format=%(asctime)s - %(name)s - %(levelname)s - %(message)s

#--------------------------------------------------------------------
# Handlers
[handler_fileHandler]
class=handlers.RotatingFileHandler
level=DEBUG
formatter=simple
args=("/data/django/hr/hr.log",'a',1000000,10)

#--------------------------------------------------------------------
# Loggers
[logger_root]
level=DEBUG
handlers=fileHandler

and my python module to set up the log system is:

logger.py

import os, logging

# Load config file
logger_config_file = \
    os.path.join(os.path.abspath(os.path.dirname(__file__)), 'logger.conf')
logging.config.fileConfig(logger_config_file)

# Create logger
logger = logging.getLogger('hr_Logger')

# Log start message
logger.info("Logging system started")

then, at the top of my views.py I have:

import logging
from hr import logger

log = logging.getLogger('hr.views')
log.info('Load hr.views')

[...]

Answer 1

I've found this behavior when there are multiple precesses are running with your code.

Unfortunatelly no perfect option exists.

Some ideas, you can incorporate are:

• use WatchedFileHandler (new in 2.6) and rotate with external programs as logrotate
• use syslog or other log aggregating server
• use python log aggregation sentry - this is especially useful with django as you can log not only log messages, but exceptions with full stacktrace and 404s.

Answer 2

Also perhaps this is worth considering http://pypi.python.org/pypi/ConcurrentLogHandler/0.8.3