Logging in Python/Django not working as expected

Question

I have the following handler configuration for logging:

    "handlers": {
      'system_file': {
        'level': 'DEBUG',
        'class': 'logging.handlers.TimedRotatingFileHandler',
        'filename': os.path.join(LOG_FOLDER, "all.log"),
        'formatter': 'verbose',
        'when': 'midnight',
        'backupCount': '30',
      }
   }

Now based on this configuration my logs should get rotated every midnight, i.e it should create date wise logs.

In the all.log file, everything gets logged properly with correct timestamp, but when the rotation happens, I do not see all the logs in the backup log files (previous day log files).

For example:

Let's say today is 2019-10-29, the all.log file starts storing all the logs from 2019-10-29 00:00:00 to 2019-10-29 23:59:59.

The next day i.e. on 2019-10-30 (when rotation would have happened), when I go and check all.log.2019-10-29, it contains log from 2019-10-30 00:00:00 till 2019-10-30 01:00:00 and the all.log file starts storing logs of 2019-10-30 from 00:00:00 onwards. So basically all my backup files only contain log of the next day from 00:00:00-01:00:00.

all.log as on 2019-10-30

[DEBUG 2019-10-30 00:00:07,463 cron.py:44] .....
[DEBUG 2019-10-30 00:00:11,692 cron.py:44] ....
[DEBUG 2019-10-30 00:00:13,679 cron.py:44] ....
.
.
[DEBUG 2019-10-30 00:00:55,692 cron.py:44] ....
[DEBUG 2019-10-30 00:59:58,679 cron.py:44] ....

SERVER SHUTS DOWN HERE AT 1AM AND STARTS STORING LOGS WHEN IT RESTARTS

[DEBUG 2019-10-30 07:00:02,692 cron.py:44] ....
[DEBUG 2019-10-30 07:00:04,679 cron.py:44] ....
.
.
*Till current time*

all.log.2019-10-29

[DEBUG 2019-10-30 00:00:07,463 cron.py:44] .....
[DEBUG 2019-10-30 00:00:11,692 cron.py:44] ....
[DEBUG 2019-10-30 00:00:13,679 cron.py:44] ....
.
.
.
[DEBUG 2019-10-30 00:00:52,463 cron.py:44] .....
[DEBUG 2019-10-30 00:00:55,692 cron.py:44] ....
[DEBUG 2019-10-30 00:59:58,679 cron.py:44] ....

all.log.2019-10-28

[DEBUG 2019-10-29 00:00:04,463 cron.py:44] .....
[DEBUG 2019-10-29 00:00:09,692 cron.py:44] ....
[DEBUG 2019-10-29 00:00:11,679 cron.py:44] ....
.
.
.
[DEBUG 2019-10-29 00:00:49,463 cron.py:44] .....
[DEBUG 2019-10-29 00:00:52,692 cron.py:44] ....
[DEBUG 2019-10-29 00:59:56,679 cron.py:44] ....

I'm using a server which runs on a schedule, the server shuts down at 1AM and starts up at 7AM. This is the only reason I see why this weird behavior happens at 1AM, but I'm not able to figure out why this will cause a problem

Any help is appreciated.

I'm using Django 1.9.7 and Python 2.7.15

Limeade

Answer 1

As mentioned here and in many other places, you can't use this handler for concurrent logging (and that is the case with Django that runs in few threads).
Potentially, because of concurrency they can override theirself.

To log to a single destination from multiple processes, you can use one of the following approaches:

• Use something like ConcurrentLogHandler
• Use a SysLogHandler (or NTEventLogHandler on Windows)
• Use a SocketHandler which sends the logs to a separate process for writing to file
• Use a QueueHandler with a multiprocessing.Queue, as outlined here.

And if you really need to do this using base on time - you can redefine ConcurrentRotatingFileHandler and _shouldRollover() method with your own condition.
It is not perfect way, but it should work.

Also you can have a look to project on GitHub that is working on solving this issue:

• Preston-Landers/concurrent-log-handler - issue #23: Time based rotation

Anticoagulant

Thanks for the insight, specially because I had no idea that we can't do multiprocessing logging to a same file using the default python handler. I am using celery which runs multiple workers in multiple processes and they all log to the same file. Hence the problem !! Is there any implementation of this which can be used for timerotated logging. ConcurrentLogHandler seems to be an option, but it does not support time rotation. – Limeade

@Limeade I know that this is not perfect way, but you can redefine ConcurrentRotatingFileHandler and _shouldRollover() method with your own condition. – Anticoagulant

@Limeade I found the GitHub issue opened about Time based rotation for this library: github.com/Preston-Landers/concurrent-log-handler/issues/23 But looks like there is no PR yet. But you can subscribe. – Anticoagulant

@Limeade do you have any other questions? As you could see currency there is not ready-made solution. If you want or waiting somebody to develop it - then it is not a part of Stackoverflow, but maybe part of GitHub open-source or some freelance marketplace. – Anticoagulant

It's hard to believe that there's no existing solution for this. There are so many python/Django developers out there. How can no one have come up with a solution for this ! – Limeade

I still didn't get the solution, but at least I now have a heads up. Thanks for it @Anticoagulant – Limeade