Uwsgi: RuntimeError at startup in Python 3.7.1+ when using `--py-call-osafterfork` option and logging module

[joshuahlang]

It appears that the fix for this issue, which was released in CPython 3.7.1, introduced this error. This change relies on PyOS_BeforeFork(), PyOS_AfterFork_Parent() and PyOS_AfterFork_Child() being called, but uWSGI only calls PyOS_AfterFork_Child(). The change in the Python logging module in 3.7.1 relies on PyOS_BeforeFork() being called to acquire a lock in the logging module pre-fork, and then will release it in PyOS_AfterFork_Parent() and PyOS_AfterFork_Child().

Given that the Python logging module now relies on this behavior, one could argue that py-call-osafterfork = true should be the default.

Here is an example of the full error, with the necessary code to reproduce it following:

*** Starting uWSGI 2.0.18 (64bit) on [Fri Feb 15 17:57:06 2019] ***
compiled with version: 6.3.0 20170516 on 15 February 2019 00:09:04
os: Linux-4.15.0-45-generic #48-Ubuntu SMP Tue Jan 29 16:28:13 UTC 2019
nodename: e8911a8df958
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 8
current working directory: /
detected binary path: /usr/local/bin/uwsgi
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
your memory page size is 4096 bytes
detected max file descriptor number: 1048576
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uWSGI http bound on 8080 fd 4
uwsgi socket 0 bound to TCP address 127.0.0.1:33015 (port auto-assigned) fd 3
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
Python version: 3.7.2 (default, Jan 23 2019, 02:31:57)  [GCC 6.3.0 20170516]
*** Python threads support is disabled. You can enable it with --enable-threads ***
Python main interpreter initialized at 0x55f1ab045130
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145840 bytes (142 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x55f1ab045130 pid: 1 (default app)
uWSGI running as root, you can use --uid/--gid/--chroot options
*** WARNING: you are running uWSGI as root !!! (use the --uid flag) *** 
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 1)
spawned uWSGI worker 1 (pid: 7, cores: 1)
spawned uWSGI http 1 (pid: 8)
Exception ignored in: <function _releaseLock at 0x7fa8eb20b9d8>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/logging/__init__.py", line 226, in _releaseLock
    _lock.release()
RuntimeError: cannot release un-acquired lock
Ignoring exception from logging atfork Exception ignored in: <function _after_at_fork_weak_calls at 0x7fa8eb20bc80>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/logging/__init__.py", line 269, in _after_at_fork_weak_calls
    _at_fork_weak_calls('release')
  File "/usr/local/lib/python3.7/logging/__init__.py", line 261, in _at_fork_weak_calls
    method_name, "method:", err, file=sys.stderr)
  File "/usr/local/lib/python3.7/logging/__init__.py", line 1066, in __repr__
    name += ' '
TypeError: unsupported operand type(s) for +=: 'int' and 'str'

This is simple to reproduce in Docker using:

FROM python:3.7
RUN pip install uwsgi==2.0.18
COPY application.py .
EXPOSE 8080
CMD ["uwsgi", "--master", "--http=8080", "--wsgi-file", "application.py", "--py-call-osafterfork"]

and the example application from the uWSGI documentation:

import logging # <-- this is necessary

def application(env, start_response):
    start_response('200 OK', [('Content-Type','text/html')])
    return [b"Hello World"]

[xrmx]

@joshuahlang Don't know if --py-call-osafterfork should default to true but if one uses it we should probably call the other python functions as you noted. Reproduced with python 3.7.2

[joshuahlang]

I suggested it be the default because the fix for an issue in Python's logging module relies on the fork hooks being called (as of 3.7.1). Likely most users won't hit the logging issue, but by not calling the hooks it does break Python 3.7+'s os.register_at_fork function.

[nickwilliams-eventbrite]

Note that the fix for this new CPython bug (https://github.com/python/cpython/pull/11908) makes half of the error go away. It is now:

Exception ignored in: <function _releaseLock at 0x7fd64dc69ea0>
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/logging/__init__.py", line 226, in _releaseLock
spawned uWSGI worker 2 (pid: 19, cores: 1)
    _lock.release()
RuntimeError: cannot release un-acquired lock
Ignoring exception from logging atfork <_StderrHandler 2 (WARNING)> release method: cannot release un-acquired lock

Repeated once for every worker uWSGI spins up.

What are the consequences of disabling py-call-osafterfork? Will it cause problems? Or will it have no affect because these errors indicate it's already not working?

Is there any Python code that I can locally put in place as a work-around to get this working?

[nickwilliams-eventbrite]

Interesting: Based on my reading of the documentation for fork.register_at_fork and the fact that it's being relied upon in CPython, I believe that, as of 3.7, any C extension which does not call all three of PyOS_BeforeFork(), PyOS_AfterFork_Parent(), and PyOS_AfterFork_Child() at fork time is misbehaving. As such, I believe the correct course of action is to leave py-call-osafterfork = false the default in Python 3.6 and older, but deprecate that setting completely for Python 3.7 and newer and hardwire it to always call all three regardless of the setting.

[xrmx]

@nickwilliams-eventbrite yeah the python PR is kinda unrelated to the uwsgi issue. Agree with your analysis but am not sure I'll have time in the foreseeable future to take a look at this myself though.

[nickwilliams-eventbrite]

@xrmx: Thanks for the quick reply. Given your inability to address it quickly and the fact that this is causing startup errors in Python 3.7 (and that those errors indicate incorrect behavior), I have put together a pull request (#1995) that addresses this issue and that I hope will meet your requirements. I tried to keep it as simple as possible, but unfortunately it required adding another plugin function, as there was simply no other post-fork plugin function run on the master (only on the children).

I learned something interesting along the way. Other than changing the log output, it appears enable-threads=true vs enable-threads=false //has essentially no affect// in the Python plugin. I traced this down because I had to read some CPython source code in order to fix this bug, and I noticed that any attempt to access the Global Interpreter Lock will call PyEval_InitThreads if Python threads have not already been enabled. As such, even if you specify enable-threads=false, Python threads still get enabled. There's simply no way to avoid that in newer Python (perhaps there was in Python 2; I don't know). This may warrant some future cleanup of the Python plugin to ignore the enable-threads setting, but this did not affect my changes and was outside the scope of them.

[nickwilliams-eventbrite]

[bump] Could I get some 👀 on that above pull request, please? Thanks!

[tylerecouture]

Still an issue in Python 3.8
https://stackoverflow.com/questions/62250160/uwsgi-runtimeerror-cannot-release-un-acquired-lock