Re: Deadlock bug in logging? Reproducible case

[Brian Tiemann]

Nah, I'm good — but thank you!


On Friday, April 24, 2020 at 8:57:09 AM UTC-4, René Fleschenberg wrote:
>
> 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 
>
>

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/090de7e4-8d00-4432-85cc-95bdd7424988%40googlegroups.com.

Re: Deadlock bug in logging? Reproducible case

[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

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/238fdf4b-fb01-f2b8-bbc1-ef065c0ebd63%40fleschenberg.net.

Re: Deadlock bug in logging? Reproducible case

[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) ...

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/9bab5139-ea38-418e-8b97-c49463be65e3%40googlegroups.com.

Re: Deadlock bug in logging? Reproducible case

[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  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-developers+unsubscr...@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

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CAMyDDM1Ti0inv_5xrc-OSJJSKPWCzvpp0qy7OeB%2B2JpOy1iwBA%40mail.gmail.com.

Re: Deadlock bug in logging? Reproducible case

[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...

-- 
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-developers+unsubscr...@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.

Re: Deadlock bug in logging? Reproducible case

[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.


On Thu, 23 Apr 2020 at 14:25, Brian Tiemann  wrote:

> 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  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!
>
>
> On Thursday, April 23, 2020 at 9:05:20 AM UTC-4, Adam Johnson wrote:
>>
>> 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 0x7cecf000 (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 0x7eed5000 (most recent call first):
>>   File "", line 163 in _get_module_lock
>>   File "", line 148 in __enter__
>>   File "", line 988 in _find_and_load
>>   File "", 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
>> 

Re: Deadlock bug in logging? Reproducible case

[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 
...

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/9b119d25-31fb-4eca-a116-abfd61886777%40googlegroups.com.

Re: Deadlock bug in logging? Reproducible case

[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  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!


On Thursday, April 23, 2020 at 9:05:20 AM UTC-4, Adam Johnson wrote:
>
> 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 0x7cecf000 (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 0x7eed5000 (most recent call first):
>   File "", line 163 in _get_module_lock
>   File "", line 148 in __enter__
>   File "", line 988 in _find_and_load
>   File "", 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 
> 

Re: Deadlock bug in logging? Reproducible case

[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 0x7cecf000 (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 0x7eed5000 (most recent call first):
  File "", line 163 in _get_module_lock
  File "", line 148 in __enter__
  File "", line 988 in _find_and_load
  File "", 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
  

Re: Deadlock bug in logging? Reproducible case

[Brian Tiemann]

It happens with Apache/mod_wsgi in prod.


On Thursday, April 23, 2020 at 7:59:45 AM UTC-4, Tom Forbes wrote:
>
> 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
>
> On 23 Apr 2020, at 12:40, Brian Tiemann > 
> wrote:
>
> 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.
>
>
>
> On Thursday, April 23, 2020 at 7:02:11 AM UTC-4, Brian Tiemann wrote:
>>
>> 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.
>>
>>
>> On Wednesday, April 22, 2020 at 1:23:31 PM UTC-4, Brian Tiemann wrote:
>>>
>>> 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!
>>>
>>>
> -- 
> 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-developers+unsubscr...@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-developers+unsubscr...@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.

Re: Deadlock bug in logging? Reproducible case

[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

> On 23 Apr 2020, at 12:40, Brian Tiemann  wrote:
> 
> 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.
> 
> 
> 
> On Thursday, April 23, 2020 at 7:02:11 AM UTC-4, Brian Tiemann wrote:
> 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.
> 
> 
> On Wednesday, April 22, 2020 at 1:23:31 PM UTC-4, Brian Tiemann wrote:
> 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!
> 
> 
> -- 
> 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-developers+unsubscr...@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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/9B0CF9F5-DB99-4D82-BAFC-4D9E481BCFD7%40tomforb.es.

Re: Deadlock bug in logging? Reproducible case

[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.



On Thursday, April 23, 2020 at 7:02:11 AM UTC-4, Brian Tiemann wrote:
>
> 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.
>
>
> On Wednesday, April 22, 2020 at 1:23:31 PM UTC-4, Brian Tiemann wrote:
>>
>> 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!
>>
>>

-- 
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-developers+unsubscr...@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.

Re: Deadlock bug in logging? Reproducible case

[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.


On Wednesday, April 22, 2020 at 1:23:31 PM UTC-4, Brian Tiemann wrote:
>
> 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!
>
>

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/db88ca65-b8f7-4f29-b156-538ee373b518%40googlegroups.com.

Re: Deadlock bug in logging? Reproducible case

[Adam Johnson]

What version of Python René?

On Thu, 23 Apr 2020 at 10:58, René Fleschenberg 
wrote:

> 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é
>
> --
> 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-developers+unsubscr...@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

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CAMyDDM3cH-FM9Rm8ZLHwXafATPT6G4z4w%2B_M4yu_hQOgFQ%2B%2Bag%40mail.gmail.com.

Re: Deadlock bug in logging? Reproducible case

[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é

-- 
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-developers+unsubscr...@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.

Re: Deadlock bug in logging? Reproducible case

[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  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).
>
>
> On Wednesday, 22 April 2020 18:23:31 UTC+1, Brian Tiemann wrote:
>>
>> 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!
>>
>> --
> 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-developers+unsubscr...@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

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CAMyDDM3dM2B%2BhKTVEgUA458G0FO%2BWhU1%3Dy_VDY5P7e2OTis1mw%40mail.gmail.com.

Re: Deadlock bug in logging? Reproducible case

[Steven Mapes]

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).


On Wednesday, 22 April 2020 18:23:31 UTC+1, Brian Tiemann wrote:
>
> 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!
>
>

-- 
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-developers+unsubscr...@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.

Re: Deadlock bug in logging? Reproducible case

[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


On Wed, 22 Apr 2020 at 18:23, Brian Tiemann  wrote:

> 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!
>
> --
> 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-developers+unsubscr...@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
> 
> .
>

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/CADqmmRxkUyAs3EH%3DggehJTkXb5YM0ENR5wJe19EEHPO8uTF2NQ%40mail.gmail.com.

Re: Deadlock bug in logging? Reproducible case

[Dave Vernon]

FYI 

Sent from my iPhone

> On 22 Apr 2020, at 18:23, Brian Tiemann  wrote:
> 
> 
> 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!
> 
> -- 
> 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-developers+unsubscr...@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.

-- 
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-developers+unsubscr...@googlegroups.com.
To view this discussion on the web visit 
https://groups.google.com/d/msgid/django-developers/6BEF80E7-AC03-46A3-91B0-686146F7C17F%40springbourne-tech.com.

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!

-- 
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-developers+unsubscr...@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.