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

Answer 1

正如此处和许多其他地方所提到的，您不能将此处理程序用于并发日志记录（在少数线程中运行的 Django 就是这种情况）。
潜在地，由于并发性，它们可以覆盖自己。

要从多个进程登录到单个目标，您可以使用以下方法之一：

• 使用类似的东西 ConcurrentLogHandler
• 使用SysLogHandler（或NTEventLogHandler在 Windows 上）
• 使用 aSocketHandler将日志发送到单独的进程以写入文件
• 使用QueueHandler带multiprocessing.Queue，所概述这里。

如果您确实需要使用基于时间的方法来执行此操作 - 您可以根据自己的条件重新定义ConcurrentRotatingFileHandler和_shouldRollover()方法。
这不是完美的方式，但它应该有效。

您也可以在 GitHub 上查看正在解决此问题的项目：

• Preston-Landers/concurrent-log-handler - 问题 #23：基于时间的轮换