Skip to content

Django dev server hangs at startup due to deadlock between LogtailHandler.flush() and flusher/uploader #42

Description

@Mr0grog

This seems really similar to #35, although that issue was closed and I’m experiencing this today. I’m not clear on whether that issue was actually solved since there was no feedback at the end of the discussion.

If the root logger in a Django project is handled by LogtailHandler, the Django dev server (python manage.py runserver) deadlocks when starting unless --noreload is specified as an option.

To Reproduce

Using:

  • logtail-python v0.4.0
  • django v6.0.7
  • CPython 3.13.15 (but looking at CPython’s source, I think this would happen in 3.14 and 3.15)

Given a settings file with logging configured:

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'logtail': {
            'class': 'logtail.LogtailHandler',
            'source_token': LOGTAIL_TOKEN,
            'host': LOGTAIL_HOST,
        },
    },
    'loggers': {
        '': {
            'level': 'INFO',
            'handlers': ['logtail'],
        }
    },
}

Running the the dev server outputs the following and then hangs:

> python manage.py runserver 0.0.0.0:8000
Watching for file changes with StatReloader
Performing system checks...

System check identified no issues (0 silenced).

The server doesn’t fully initialize and doesn’t respond to HTTP requests. If everything went fine, you normally see the above followed by something like:

September 05, 2026 - 02:54:50
Django version 6.0.7, using settings 'config.settings.dev'
Starting development server at http://0.0.0.0:8000/
Quit the server with CONTROL-C.

WARNING: This is a development server. Do not use it in a production setting. Use a production WSGI or ASGI server instead.
For more information on production servers see: https://docs.djangoproject.com/en/6.0/howto/deployment/

Simpler Reproduction (No Django)

That said, the actual problem here is just a deadlock when reconfiguring loggers while there are logs left to be flushed. You can reproduce it more simply without Django using the following script:

import logging
import logging.config
from os import getenv


logger = logging.getLogger('example_logger')


LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'handlers': {
        'logtail': {
            'class': 'logtail.LogtailHandler',
            'source_token': getenv('LOGTAIL_TOKEN'),
            'host': getenv('LOGTAIL_HOST'),
        },
    },
    'loggers': {
        '': {
            'level': 'INFO',
            'handlers': ['logtail'],
        }
    },
}

logging.config.dictConfig(LOGGING)

print('=== Logs configured. ===')

logger.info('Hello!')

print('=== Logged one message. ===')

logging.config.dictConfig(LOGGING)

print('=== Logging reconfigured. ===')

logger.info('Goodbye!')

print('=== Logged second message. ===')

That should print:

=== Logs configured. ===
=== Logged one message. ===
=== Logged reconfigured. ===
=== Logged second message. ===

But instead it just prints the following and then hangs:

=== Logs configured. ===
=== Logged one message. ===

Cause

The previous issue (#35) identified the hang as an infinite loop in FlushWorker.flush() (which is called by LogtailHandler.flush()):

def flush(self):
self._flushing = True
while not self._clean or not self.pipe.empty():
time.sleep(self.check_interval)
self._flushing = False

In my case, the infinite loop here is actually because the log flushing/HTTP thread is deadlocked (so self._clean never gets set to True). Django’s main thread (where the loggers are being reconfigured and flush() is called) is holding a lock that the flushing thread needs in order to finish flushing.

Specifically, the following happens:

  1. logging.dictConfig() (or any other config method) takes the logging._lock lock.

  2. The configuration method de-registers all the handlers (they are still attached to individual loggers in some_logger.handlers, so they still work; they just can’t be looked up by name).

  3. The configuration method calls flush() on all the handlers.

  4. LogtailHandler.flush() calls FlushWorker.flush(), which waits on another thread to do the actual sending of logs.

  5. On the thread that is buffering and sending logs, FlushWorker.step() buffers up the logs and then sends them via the uploader.

  6. The uploader calls requests.Session.post(), which tries to log a message about the HTTP request. That logging call deadlocks.

    Various methods in logging.Logger and logging.Handler instances try to take the logging._lock lock, which is already held by the main thread that is reconfiguring loggers, and won’t be released until flushing is done, which can’t be done until after these logging calls in the HTTP library.

    (The main method I’m observing causing the deadlock here is Logger.isEnabledFor(), which takes the lock if it has not yet cached information about what level it is set at. So if all the loggers down in requests and urllib3 have already been used, you might avoid the deadlock. But there are other places the lock is used that might also cause problems.)

In the context of the Django dev server, the following happens when reloading is turned on (the default behavior):

  1. Django loads settings (which configures loggers) before starting the runserver command.
  2. The runserver command logs "Watching for file changes with StatReloader".
  3. The runserver command (re)starts the actual WSGI app (which reloads settings, which reconfigures loggers, which hits the above issue).

If you don’t have reloading enabled (e.g. you call python manage.py runserver --noreload), it doesn’t try to log a message before starting the Django app, and avoids the deadlock (since there is nothing to send when the handlers flush).

Fixes

This is a little thorny! As far as I can tell, this should work fine if the logging happens on the thread where loggers are being reconfigured (since the lock is an RLock, it can be reacquired recursively by the same thread). So the main thing to do here is make sure the actual sending of logs happens on the same thread where flush() is called.

My naive thought here is that the whole handler/flush worker needs a bit of re-architecting. Instead of using a queue to buffer up log records, the handler could probably just have a list that is protected by a lock. When the buffer is full, it could be sliced off and dropped onto a queue as a single bundle for a sending thread to handle. Calls to flush() would just bypass the queue and call the sending method directly. Another thread could serve as a heartbeat to flush the queue on a schedule (this could be the same as the thread that is reading off the queue, but is easier to conceptualize as two threads).

There might be easier ways to do this that fit better with the current code. I spent more time on identifying the deadlock than thinking through an ideal solution so far. 😉

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions