A few weeks ago I found myself scratching my head about missing records on the log files of a Flask application running with Gunicorn. I knew that the requests had been performed and should have been logged, but they were nowhere to be found.

While investigating, I noticed that the rotated log files had way less records than what I expected. Something was going on. After some online surfing, I found out the following crucial pieces of information:

• Python's standard library logging is thread safe but not process safe.
• Gunicorn logs are written by the worker processes, not by the master process.

I figured out that because I was using TimedRotatingFileHandler to rotate the log files daily, I was running into a situation where each worker was not only trying to write to the same file, but each worker also tried to handle the file rotation. I'm not sure how all these pieces interacted (when was data flushed to disk, if a worker was overwriting other workers' output, etc.), but definitely there was a conflict that was resulting on data being lost.

And I was not alone on being confused about rotating Gunicorn logs. A sample:

• Gunicorn GitHub issue: [Design Question] How do gunicorn workers log correctly?
• Gunicorn GitHub issue: (forum) logging from each worker
• Loguru GitHub issue: Issues with rotate
• Uvicorn GitHub issue: Gunicorn+UvicornWorker,access log not working after logrotate access log file.

So, I ended taking a pragmatic approach to see by myself how different configurations would work out. I created an environment where I had Gunicorn running a Flask application with 10 Sync workers. I used k6 to generate 1000 requests per minute during 3 minutes, which should generate 3000 log records. I recreated this setup with 3 different configurations, but always with a rotation set to 1 minute (or to 500KBs per file, which seemed to be the amount of records generated per minute):

1. Python/Gunicorn handling the rotation with TimedRotatingFileHandler: at the end of the test I had less than 200 log records among the 3 rotated files. Lots of records lost!

2. Python/Gunicorn writing to a single file with the default FileHandler, and logrotate handling the rotation: all the log records kept being written to the first file even after being rotated. So I ended with the most recent non-rotated file with 0 entries and a rotated file with 3000 records.

3. Python/Gunicorn writing to a single file with the WatchedFileHandler, and logrotate handling the rotation: the log records were distributed evenly among the different rotated log files, for a total of 3000 records! Success!

If you found yourself with the same issue, this is the winning configuration:

gunicorn_logging.conf

; ...

[handler_json_log_file]
class=logging.handlers.WatchedFileHandler
formatter=json
; filename, mode='a', encoding=None, delay=True, errors=None
args=('/path/to/my/log_file.log', 'a', None, True, None)
  
;... 

logrotate.conf

/path/to/my/log_file.log {
    daily
    rotate 100
    create
    missingok
    notifempty
}

Happy logging!