python-loggingdjango-logging

Logging in Django runserver with rotating files - file access error on rotation


Setup and desired behavior:

  1. Logging-configuration defined outside of settings.py
  2. Want to still have logging with runserver

1.

# custom_logging.py
def set_logger(logger):
    # add formatters and handlers for the supplied logger
def init():
    # call set_logger on the desired loggers

2.

# apps.py
import sys
    [...]
    def ready():
        is_manage_py = any(arg.casefold().endswith("manage.py") for arg in sys.argv)
        is_runserver = any(arg.casefold() == "runserver" for arg in sys.argv)
        is_shell     = any(arg.casefold() == "shell" for arg in sys.argv)

        if is_manage_py and (is_runserver or is_shell):
            custom_logging.init()

All well and dandy ... until you need your logs to rotate (logging.handlers.RotatingFileHandler for instance):

--- Logging error ---
Traceback (most recent call last):
  File "\Lib\logging\handlers.py", line 74, in emit
    self.doRollover()
  File "\Lib\logging\handlers.py", line 185, in doRollover
    self.rotate(self.baseFilename, dfn)
  File "\Lib\logging\handlers.py", line 116, in rotate
    os.rename(source, dest)
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: '\logs\main.log' -> '\logs\main.log.1'

Inspecting the file handle will reveal that Django is the only process holding a lock. So what gives? Restarting the IDE does nothing, restarting the PC does nothing, there are no duplicate processes.

Setting up an instance through gunicorn or similar doesn't suffer this issue so the problem is likely not in the logging configuration itself, but rather with how/when/etc. the logging configuration gets called.

By way of print-debugging, I can see that the init() method gets run twice before the server has completely started but upon auto-reload it only gets run once.


Solution

  • In the case of runserver, the "main process" will import all packages first and then the auto-reloader appears to import all packages immediately after. This runs the log-init twice, which as far as I can tell causes Django to hold two locks for all the mentioned logs, and only the lock belonging to the auto-reloader gets released (until you terminate the main process).

    This is how we can selectively make the import only happen in either the main process or in the auto-reloader's process:

    # apps.py
        [...]
        if is_manage_py and (is_runserver or is_shell) and os.environ.get('RUN_MAIN') == 'true':
    

    If this feels hacky, the primary recommendation is to break with requirement #1 and move logging configuration into settings.py.