Deadlock bug in logging? Reproducible case

[Brian Tiemann]

Hi all,

I was directed here after getting corroboration on #django and elsewhere.

I have what appears to be a bug in which a Django app can deadlock if you hit it with a lot (>3) of AJAX requests within a short time (i.e. all triggered in parallel from a single HTML page). I have a reproducible case here:

https://github.com/data-graham/wedge

I'd really appreciate it if someone could take a look and let me know whether I'm doing something wrong, or if there's something systemic going on. Thanks much!

[Dave Vernon]

FYI 

Sent from my iPhone

On 22 Apr 2020, at 18:23, Brian Tiemann <greeni...@gmail.com> wrote:



--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/7fa1a28d-8f54-48cd-9c34-5d1c111ef136%40googlegroups.com.

[Dave Vernon]

Sorry - that message was sent as a 'reply' in error - my colleague uses ajax with Django a lot and I was trying to forward this to him.

Kind Regards,

Dave

[Adam Johnson]

Brian - You didn't describe the exact symptoms you're seeing. "Deadlock" has a particular technical meaning around multiple processes requesting locks mutually off each other, and normally ends in one process being terminated. But I presume you're experiencing more of a "standstill" and future requests no longer work?

Additionally you don't describe your Python version. Since logging is part of the Python standard library (and you're not using any extensions) any logging issues you're seeing are part of Python, and may be fixed on later versions. Minor versions contain lots of such fixes and Django only officially supports the latest in each series.

Steven has managed to test with 1000's of requests and I think that's an indicator it could be a Python bug.

Also Steven is right, writing to disk is expensive and something to avoid in production (at scale). In production I've previously used two high quality setups:

1. Logging to stdout/stderr, running the server under systemd, and letting it capture stdout logs into journald
2. Logging directly into a running fluentd process

Both logging agents - journald and fluentd - provide in-memory buffering before disk, discarding of extreme bursts, etc. Journald is easier to get started with since it's included in most linuxes, fluentd is more flexible and easy to configure. There are many others out there too!

And if you use a PaaS like Heroku, they normally capture your stdout/stderr into such a logging agent already.

Hope that helps,

Adam

On Wed, 22 Apr 2020 at 19:47, Steven Mapes <st...@jigsawtech.co.uk> wrote:

This is more an issue at the file system level and the hardware not being able to keep up rather than anything Django is doing.  It's the same fundamental principal for why you may turn off webserver logging to increase performance, writing to disk is expensive and so when dealing with high throughout you probably want to question why.

I've just run that on my laptop and hit your 1000 requests fine. I actually them bumped it up to run 6 requests per iteration and still was fine writing to disk. I started to have network resource issues when I bumped it up further but that was more limitations within chrome

In the real world if you were writing logs like this for information or debugging you would be best served to defer them by writing to a message queue of sort some, probably FIFO based as its logging, and then have as many subscribers as you want dealing with reading and processing those queued messages. This could be as few as one so that you never hit a deadlock or it could be a few, again it depends on the performance of the underlying hardware, what you are writing and where (database, disk, memory).

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/1445d05d-eefc-43b1-8913-79d6e55de216%40googlegroups.com.

--

Adam

[René Fleschenberg]

Hi,

On 4/23/20 9:40 AM, Adam Johnson wrote:
> Brian - You didn't describe the exact symptoms you're seeing. "Deadlock"
> has a particular technical meaning around multiple processes requesting
> locks mutually off each other, and normally ends in one process being
> terminated. But I presume you're experiencing more of a "standstill" and
> future requests no longer work?

I was able to reproduce this. It leads to a standstill, further requests
are not getting processed. I can reproduce it when logging to the
console, so I don't think disk I/O is the problem. It might still be a
problem in the Python stdlib, of course.

--
René

[Adam Johnson]

What version of Python René?

--
You received this message because you are subscribed to the Google Groups "Django developers  (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/1b14cc08-4abf-9a97-8e02-a16931c0bf28%40fleschenberg.net.

--

Adam

[Brian Tiemann]

Hi — Thanks for looking into this. Adam, I skipped over details like the Python version because I noted them in the readme on my gitlab demo. But I was using Python 3.7.2 for the record.

I used "deadlock" because my digging into this had previously turned up https://bugs.python.org/issue6721 , suggesting this was to do with thread locking. But I'm not qualified to make that call for sure, so I don't want to throw red herrings into the mix. If "standstill" is a better term for this that's what I'll use.

Thanks again.

[Brian Tiemann]

It also happens in 3.6.9, which is my prod environment.

FWIW, by way of background context, this is not a heavily used app, not enough so to warrant logging to a custom buffered consumer or remote agent. It's just a small office using it. But the main home view's UI has 5 AJAX calls that cause the site to lock up on a regular basis, such that I have to have a watchdog in place to bounce Apache whenever it happens.

It's not the logging itself that's the issue; none of the AJAX views log anything. The app only actually logs maybe 100 lines per day. My investigation however turned up that if I commented out LOGGING altogether, it worked fine. Further trimming down of the codebase showed that I could remove all the loggers and it would still happen as long as any handlers were defined. So that's how I set up the demo. The logging itself isn't important, in other words; it's that the whole app is wedging just because I happen to have a vanilla LOGGING setup configured.

[Tom Forbes]

Just to confirm - are you running into this issue while using the Django development server in production, or does this occur with Gunicorn/uwsgi as well?

Tom

-- 
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/9a5bc078-66b9-4e09-97c2-8340b8882c02%40googlegroups.com.

[Brian Tiemann]

It happens with Apache/mod_wsgi in prod.

Tom

To unsubscribe from this group and stop receiving emails from it, send an email to django-developers+unsub...@googlegroups.com.

[Adam Johnson]

I ran it on Python 3.7.6 and Python 3.8.2 and found the deadlock issue on both.

I then adjusted the settings to *only* have the console logger, and added these lines at the end of the settings file:

import faulthandler
faulthandler.enable()
print(os.getpid())

faulthandler allows getting a stacktrace in dire situations such as hangs like this: https://docs.python.org/3/library/faulthandler.html

Then used `runserver`, ran until the deadlock, and killed the *second* printed PID with `kill -ABRT` . This kills the actual Django server process, rather than the outer "watch & restart" process.

This ended with a traceback with lots of threads all trying to acquire a lock. Some are trying to log at the end of the request:

Thread 0x000070000cecf000 (most recent call first):
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/logging/__init__.py", line 221 in _acquireLock
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/logging/__init__.py", line 1687 in isEnabledFor
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/logging/__init__.py", line 1433 in info
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/servers/basehttp.py", line 157 in log_message
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/http/server.py", line 544 in log_request
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/wsgiref/simple_server.py", line 34 in close
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/servers/basehttp.py", line 114 in close
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/wsgiref/handlers.py", line 196 in finish_response
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/wsgiref/handlers.py", line 138 in run
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/servers/basehttp.py", line 197 in handle_one_request
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/servers/basehttp.py", line 174 in handle
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/socketserver.py", line 720 in __init__
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/socketserver.py", line 360 in finish_request
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/socketserver.py", line 650 in process_request_thread
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/threading.py", line 870 in run
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/threading.py", line 932 in _bootstrap_inner
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/threading.py", line 890 in _bootstrap

One stood out to me as trying to reconfigure logging through wsgi.py:

Thread 0x000070000eed5000 (most recent call first):
  File "<frozen importlib._bootstrap>", line 163 in _get_module_lock
  File "<frozen importlib._bootstrap>", line 148 in __enter__
  File "<frozen importlib._bootstrap>", line 988 in _find_and_load
  File "<frozen importlib._bootstrap>", line 1014 in _gcd_import
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/importlib/__init__.py", line 127 in import_module
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/utils/module_loading.py", line 17 in import_string
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/utils/log.py", line 89 in __init__
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/logging/config.py", line 744 in configure_handler
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/logging/config.py", line 563 in configure
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/logging/config.py", line 808 in dictConfig
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/utils/log.py", line 71 in configure_logging
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/__init__.py", line 19 in setup
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/wsgi.py", line 12 in get_wsgi_application
  File "/Users/chainz/Documents/Projects/wedge/wedge/wsgi.py", line 6 in application
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/contrib/staticfiles/handlers.py", line 68 in __call__
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/wsgiref/handlers.py", line 137 in run
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/servers/basehttp.py", line 197 in handle_one_request
  File "/Users/chainz/Documents/Projects/wedge/venv38/lib/python3.8/site-packages/django/core/servers/basehttp.py", line 174 in handle
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/socketserver.py", line 720 in __init__
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/socketserver.py", line 360 in finish_request
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/socketserver.py", line 650 in process_request_thread
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/threading.py", line 870 in run
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/threading.py", line 932 in _bootstrap_inner
  File "/Users/chainz/.pyenv/versions/3.8.2/lib/python3.8/threading.py", line 890 in _bootstrap

This stood out to me. I checked your wsgi.py , it contained:

def application(environ, start_response):
    return get_wsgi_application()(environ, start_response)

This means "create a new wsgi application for each request." During creation of a WSGI application, Django sets itself up, including configuring logging. This is why logging was trying to acquire that lock.

I changed it to use the standard definition from the startproject template:

application = get_wsgi_application()

(The outrer "def application" was previously a no-op, so gone)

Then I stopped experiencing the logging issue. This is your solution.

So it seems there *may* be a python logging lock issue if you reconfigure logging whilst logs are being sent in other threads. But I'm not sure if that is intended to be supported.

Tom

To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/9a5bc078-66b9-4e09-97c2-8340b8882c02%40googlegroups.com.

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.

To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/aa37f782-50bb-42a9-b4ed-45516e3751e5%40googlegroups.com.

--

Adam

[Brian Tiemann]

Ah, interesting. Let me show you what my non-trimmed-down wsgi.py looked like --

import os, sys

from django.core.wsgi import get_wsgi_application

env_variables_to_pass = [

    'SECRET_KEY',

    ... other env vars ...

]

def application(environ, start_response):

    # pass the WSGI environment variables on through to os.environ

    for var in env_variables_to_pass:

        os.environ[var] = environ.get(var, '')

    return get_wsgi_application()(environ, start_response)

That's why I had it set up that way. This was how someone once told me env vars should be passed in via the Apache config. Is there a better way to do that? Like I want to define an env var in the Apache <VirtualHost> block, but I want it to then be available to the app via os.environ. Is there a best-practices way to make that happen?

Thank you for digging into this!

Tom

To unsubscribe from this group and stop receiving emails from it, send an email to django-developers+unsub...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/9a5bc078-66b9-4e09-97c2-8340b8882c02%40googlegroups.com.

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.

To unsubscribe from this group and stop receiving emails from it, send an email to django-d...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/aa37f782-50bb-42a9-b4ed-45516e3751e5%40googlegroups.com.

--

Adam

[Brian Tiemann]

FYI, here's where that approach came from -- http://ericplumb.com/blog/passing-apache-environment-variables-to-django-via-mod_wsgi.html

It's the top hit for "django apache environment variable" Which is literally an old friend of mine from grade school. Maybe that's a red flag ...

[Adam Johnson]

https://adamj.eu/tech/2019/05/27/the-simplest-wsgi-middleware/

django_application = get_wsgi_application()

def application(environ, start_response):

    # pass the WSGI environment variables on through to os.environ

    for var in env_variables_to_pass:

        os.environ[var] = environ.get(var, '')

    return django_applicationenviron, start_response)

But I think it's questionable to push some environment variables into wsgi environ, you can read the environment variables elsewhere.

Tom

To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/9a5bc078-66b9-4e09-97c2-8340b8882c02%40googlegroups.com.

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-d...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/aa37f782-50bb-42a9-b4ed-45516e3751e5%40googlegroups.com.

--

Adam

--

You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.

To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/3d950ac3-348f-44fc-9d32-2b26f6109de2%40googlegroups.com.

--

Adam

[Brian Tiemann]

Beautiful. That does the trick. Thank you!

And I certainly can see there's plenty of other approaches such as envparse or django-environ that I could be using, that keeps the vars out of my Apache config. Quick fix and a slighly longer better fix. This'll change how I do all my new projects from now on, plus retroactively for all the ones I used this approach with...

[Adam Johnson]

Actually that might not work entirely, since your settings file will be imported before the environment variables are copied over.

Instead you can lazily construct the django application on the first request:

django_application = None

def application(environ, start_response):
    global django_application
   
    if django_application is None:

        # pass the WSGI environment variables on through to os.environ
        for var in env_variables_to_pass:
            os.environ[var] = environ.get(var, '')

        django_application = get_wsgi_application()
   
    return django_application(environ, start_response)

And yes, using a real environment variable solution is better. You can only use WSGI environment for configuration during requests - not during background processes such as management commands or background task queues like Celery.

On Thu, 23 Apr 2020 at 15:00, Brian Tiemann <greeni...@gmail.com> wrote:

Beautiful. That does the trick. Thank you!

And I certainly can see there's plenty of other approaches such as envparse or django-environ that I could be using, that keeps the vars out of my Apache config. Quick fix and a slighly longer better fix. This'll change how I do all my new projects from now on, plus retroactively for all the ones I used this approach with...

--
You received this message because you are subscribed to the Google Groups "Django developers (Contributions to Django itself)" group.
To unsubscribe from this group and stop receiving emails from it, send an email to django-develop...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/django-developers/97ea9ad1-7f9d-4648-8eb5-c3b8a42f479b%40googlegroups.com.

--

Adam

[Brian Tiemann]

True, I did notice it needed some more tweaking. I've got a long evening of rewriting years' worth of wsgi.py's and Apache configs ahead of me. I'll probably just jump straight to the envparse approach because (as you noted) my celery env var handling was making the WSGI approach moot anyway.

Now if there were only a way to avoid having to put os.environ["DJANGO_SETTINGS_MODULE"] = "myapp.settings" into wsgi.py (since I'm sharing lots of vhosts in one Apache) ...

[René Fleschenberg]

Hi,

On 4/23/20 12:20 PM, Adam Johnson wrote:
> What version of Python René?

I tested with 3.6.7. I can test with other versions, if that helps.

Regards,
René



--
René Fleschenberg

[Brian Tiemann]

Nah, I'm good — but thank you!