Uwsgi: Sometimes worker hang on respawn (in multi-threaded mode)

Created on 3 Aug 2017 · 29Comments · Source: unbit/uwsgi

Symptoms:

pytrace on worker hangs
uwsgitop shows process as busy in read
log shows no request handled since worker process creation

OS: Linux (3.13.0-63-generic) / Ubuntu 14.04.3 64 bit
Python: 2.7.6 (default, Jun 22 2015, 17:58:13) ( 2.7.6-8ubuntu0.2)
uwsgi: 2.0.13.1 (2.0.15, same behaviour)
App server: Django
uwsgi config (absolute paths cut):

bin/uwsgi  -M -p 5 -C -A 4 -m -b 8192 -s :3031 --max-requests=1000 --reload-on-rss=450  --threads 40 --reload-mercy 600 --listen 200 --harakiri 350 --wsgi-file bin/django.wsgi --pidfile var/run/uwsgi.pid --touch-reload=var/run/reload-uwsgi.touch  --py-tracebacker var/run/pytrace --auto-procname --stats 127.0.0.1:3040

Logs:

...The work of process 5346 is done. Seeya!
worker 3 killed successfully (pid: 5346)
Respawned uWSGI worker 3 (new pid: 14529)
chmod() socket to 666 for lazy and brave users
python tracebacker for worker 3 available on var/run/pytrace3
.... nothing useful, no request handled by this PID
.... manually killed process
DAMN ! worker 3 (pid: 14529) died :( trying respawn ...
Respawned uWSGI worker 3 (new pid: 21516)

Special modules:

memcached
redis / django - rq
raven / sentry

Source

erny

Most helpful comment

I close this bug as "not a uwsgi bug", but a "python stdlib bug (logging module): process my hang with multiple threads on implicit imports.". Thanks.

erny on 8 Nov 2017

👍3

All 29 comments

@erny Please reproduce with latest release

xrmx on 3 Aug 2017

I updated the version to last stable, 2.0.15. The important part of config is:
--master --processes 5 --socket :3031 --sharedarea 4 --memory-report --buffer-size 8192 --chmod --thunder-lock --listen 200 --threads 40 --reload-on-rss 450 --reload-mercy 60

I'm running this config at 2 customers with identical result. I removed harakiri y max requests. pytracer does not respond. strace to this process gives:
Process 22107 attached
futex(0x7fc96f83d000, FUTEX_LOCK_PI, 1

erny on 25 Sep 2017

Here is the strace output of multi-threaded blocked uwsgi process:

[pid 31648] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31647] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31646] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31645] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31644] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31643] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31642] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31641] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31640] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31638] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31639] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31637] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31635] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31632] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31636] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31634] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31633] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31631] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31630] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31629] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31628] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31627] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31625] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31626] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31624] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31623] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31615] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31622] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31621] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31620] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31619] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31618] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31617] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31616] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31614] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31613] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31612] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31611] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31610] 13:16:47 futex(0x7fc950084b60, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 31609] 13:16:47 accept(4,  <unfinished ...>
[pid 31608] 13:16:47 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL^CProcess 31608 detached

It's like we have another futex anywhere. But on reload, the futex is still active, and the process remains locked.

We use beside django:

memcached
redis / django - rq
raven / sentry

Here I have another one:

[pid 29034] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29033] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29032] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29031] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29026] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29030] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29029] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29028] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29027] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29024] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29020] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29019] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29017] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29016] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29013] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29010] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29009] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29008] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29007] 13:17:35 futex(0x7fc950083b40, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29006] 13:17:35 futex(0x7fc950083b40, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29005] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29003] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29002] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29001] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28996] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28995] 13:17:35 accept(4,  
[pid 29025] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29023] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29022] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29021] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29018] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29015] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29014] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29012] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29011] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29004] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 29000] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28999] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28998] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28997] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 28994] 13:17:35 futex(0x13a2b50, FUTEX_WAIT_PRIVATE, 0, NULL^CProcess 28994 detached

erny on 25 Sep 2017

I saw that with Raven we're using the default threaded mode, but we're not using the --enable-threads option (because I read in the docs that this is automatically enabled with we use --threads option). Now, I have disabled async delivery in Raven to see if this changes the erroneous behaviour.

Is there any chance that a uwsgi process which waits on a thread to finish and that reloads itself due to max-requests or reload-on-rss, stays blocked? As I explained in the first comment, the process does not serve any requests after reloading.

erny on 25 Sep 2017

To make the process block (hang), I used ab (Apache Bench) at an URL where a exception in raised. Without raven enabled (empty DSN) the process blocked too.

The most stable config I got (where I was not able to make any uwsgi process block on reload) was using the default backlog (128), --enable-threads, 1 process for each CPU and number of total threads >> backlog:

--master --processes 5 --socket :3031 --sharedarea 4 --memory-report --buffer-size 8192 --chmod --reload-on-rss=450 --py-tracebacker var/run/pytrace --auto-procname --stats 127.0.0.1:3040 --threads 40 --reload-mercy 600 --thunder-lock --enable-threads

erny on 26 Sep 2017

Hi, it would be interesting to understand if the thunder-lock is the futex-locked one. Can you try by removing it ? Thanks

unbit on 28 Sep 2017

Thanks, I'll try to. Before killing I got in strace:

...
[pid 11514] 12:09:26 futex(0x13c0bf0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 11513] 12:09:26 futex(0x7f6b04083b20, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 11511] 12:09:26 futex(0x7f6b04083b20, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 11510] 12:09:26 accept(4,  <unfinished ...>
[pid 11509] 12:09:26 futex(0x13c0bf0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
...

When harakiri is applied, the process is resumed shortly, before it is killed, I see:

[pid 11510] 12:14:35 <... accept resumed> {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, [2]) = 6
[pid 11510] 12:14:35 write(6, "*** uWSGI Python tracebacker out"..., 41) = 41
[pid 11510] 12:14:35 stat("/opt/tangram/tangramdt-cloud/buildout/eggs/Django-1.4.18-py2.7.egg/django/core/handlers/base.py", {st_mode=S_IFREG|0664, st_size=11825, ...}) = 0
[pid 11510] 12:14:35 open("/opt/tangram/tangramdt-cloud/buildout/eggs/Django-1.4.18-py2.7.egg/django/core/handlers/base.py", O_RDONLY) = 96
[pid 11510] 12:14:35 fstat(96, {st_mode=S_IFREG|0664, st_size=11825, ...}) = 0
[pid 11510] 12:14:35 fstat(96, {st_mode=S_IFREG|0664, st_size=11825, ...}) = 0
[pid 11510] 12:14:35 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6b1afba000
[pid 11510] 12:14:35 read(96, "import sys\n\nfrom django import h"..., 8192) = 8192
[pid 11510] 12:14:35 read(96, "    signals.got_request_exceptio"..., 4096) = 3633
[pid 11510] 12:14:35 read(96, "", 4096) = 0
[pid 11510] 12:14:35 close(96)          = 0
[pid 11510] 12:14:35 munmap(0x7f6b1afba000, 4096) = 0
[pid 11510] 12:14:35 stat("/opt/tangram/tangramdt-cloud/buildout/eggs/Django-1.4.18-py2.7.egg/django/core/handlers/wsgi.py", {st_mode=S_IFREG|0664, st_size=8644, ...}) = 0
[pid 11510] 12:14:35 open("/opt/tangram/tangramdt-cloud/buildout/eggs/Django-1.4.18-py2.7.egg/django/core/handlers/wsgi.py", O_RDONLY) = 96
[pid 11510] 12:14:35 fstat(96, {st_mode=S_IFREG|0664, st_size=8644, ...}) = 0
[pid 11510] 12:14:35 fstat(96, {st_mode=S_IFREG|0664, st_size=8644, ...}) = 0
[pid 11510] 12:14:35 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6b1afba000
[pid 11510] 12:14:35 read(96, "import sys\nfrom threading import"..., 8192) = 8192
[pid 11510] 12:14:35 read(96, "text = STATUS_CODE_TEXT[response"..., 4096) = 452
[pid 11510] 12:14:35 read(96, "", 4096) = 0
[pid 11510] 12:14:35 close(96)          = 0
[pid 11510] 12:14:35 munmap(0x7f6b1afba000, 4096) = 0
[pid 11510] 12:14:35 futex(0x13c0bf0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
[pid 11512] 12:14:39 +++ killed by SIGKILL +++
[pid 11531] 12:14:39 +++ killed by SIGKILL +++
[pid 11510] 12:14:39 +++ killed by SIGKILL +++
[pid 11534] 12:14:39 +++ killed by SIGKILL +++
[pid 11541] 12:14:39 +++ killed by SIGKILL +++
...

erny on 28 Sep 2017

After some more testing, I saw (with uwsgitop) that the process is idle and that the first or first two concurrent request make the process block. I'm trying to get a strace capture of this situation. (May be it is a concurrent import module from 2 threads?)

erny on 28 Sep 2017

It seems more like a process-wide lock (like the thunder-lock) is not correctly released while the process is killed. This is why i asked you to check without thunder-lock. If you can confirm it there is a workaround in master (it is generally used for very old kernels)

unbit on 28 Sep 2017

I removed thunder-lock and I still have this issue. I've incremented the memory limit (max-rss), and now the workers reload less often.

erny on 29 Sep 2017

I have a complete strace with the deadlock, but I'm not very sure about how to get the relevant info.

erny on 29 Sep 2017

Well, i just noted you have enabled a sharedarea of 4 pages. How are you using it ?

unbit on 29 Sep 2017

The answer is, I'm not using it. It may come from and old or experimental config.

erny on 29 Sep 2017

the sharedarea allocates a shared lock, can you try by removing it ? Sorry for the iterative tests, but unfortunately debugging threads is a black art :(

unbit on 29 Sep 2017

Thanks, I'll do it and will give feedback. I'm also considering updating psycopg2 (2.4.1) which is a little bit outdated.

erny on 29 Sep 2017

I removed -A (sharedarea) option on a couple of production servers, but it seems that it didn't do the trick. The behaviour is the same.

To work around the issue, is there a way to send 2 consecutive requests to 2 different workers?

On the other side, I'm monitoring the uwsgi process with uwsgitop. This shouldn't introduce new locks, right?

erny on 2 Oct 2017

Today I changes psycopg2 dependency to last stable (2.7.3.1). As far, I got one harakiri (process stuck), with this output (--harakiri-verbose):

Tue Oct  3 09:49:30 2017 - *** HARAKIRI ON WORKER 3 (pid: 29765, try: 1) ***
HARAKIRI: -- syscall> 202 0x2015af0 0x80 0x0 0x0 0x3 0x7ffc8d1c3b00 0x7ffc8d1c3d60 0x7f4568328670
HARAKIRI: -- wchan> futex_wait_queue_me
*** uWSGI Python tracebacker output ***
[nothing here, just empty]

erny on 3 Oct 2017

Things to try:

Use newer kernel: Install hwe stack (https://wiki.ubuntu.com/Kernel/LTSEnablementStack)
User newer python

erny on 4 Oct 2017

Could it be a kernel bug?

https://lists.ubuntu.com/archives/kernel-team/2014-October/048880.html
https://groups.google.com/forum/#!msg/mechanical-sympathy/QbmpZxp6C64/A23zW81OS1EJ

I'll try: update the kernel and alternatively, use semaphores as locking mechanism.

erny on 4 Oct 2017

Perhaps #1149 is related to this? I'll try to get a gdb backtrace. I checked all libs and code, and I couldn't find any other used code creating new threads.

erny on 6 Oct 2017

I switched to use to semaphores, and the problem is still happening. Here is the backtrace:

#0  sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:85
#1  0x00007fd4e591bb78 in PyThread_acquire_lock () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#2  0x00007fd4e593659b in _PyImport_AcquireLock () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#3  0x00007fd4e5936621 in PyImport_ImportModuleLevel () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#4  0x00007fd4e590a85f in ?? () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#5  0x00007fd4e58ad0a3 in PyObject_Call () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#6  0x00007fd4e59405f7 in PyEval_CallObjectWithKeywords () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#7  0x00007fd4e58d46d3 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#8  0x00007fd4e58d6b19 in PyEval_EvalFrameEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#9  0x00007fd4e58d8c3d in PyEval_EvalCodeEx () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#10 0x00007fd4e58d8dd0 in ?? () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#11 0x00007fd4e58ad0a3 in PyObject_Call () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#12 0x00007fd4e5851d6d in ?? () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#13 0x00007fd4e58ad0a3 in PyObject_Call () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#14 0x00007fd4e58b1cf5 in ?? () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#15 0x00007fd4e58ad0a3 in PyObject_Call () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#16 0x00007fd4e59405f7 in PyEval_CallObjectWithKeywords () from /usr/lib/x86_64-linux-gnu/libpython2.7.so.1.0
#17 0x0000000000482841 in python_call ()
#18 0x0000000000484a36 in uwsgi_request_wsgi ()
#19 0x000000000041f602 in wsgi_req_recv ()
#20 0x0000000000467454 in simple_loop_run ()
#21 0x000000000046b744 in uwsgi_ignition ()
#22 0x000000000046ffbd in uwsgi_worker_run ()
#23 0x00000000004705af in uwsgi_run ()
#24 0x000000000041ecbe in main ()

erny on 6 Oct 2017

At this point, can you try with the --no-threads-wait option ?

unbit on 7 Oct 2017

With the semaphore version, I get this in the logs:

ue Oct 10 10:08:09 2017 - *** HARAKIRI ON WORKER 3 (pid: 7481, try: 1) ***
HARAKIRI: -- syscall> 202 0x1225a20 0x80 0x0 0x0 0x3 0x7ffcd0447330 0x7ffcd0447038 0x7fb474978670
HARAKIRI: -- wchan> futex_wait_queue_me
*** uWSGI Python tracebacker output ***

i.e. uwsgi is using semaphores, but I still get a futex lock. This seems to be a Python or a kernel bug.

(I still didn't try no-threads-wait.)

erny on 10 Oct 2017

After all it really seems a concurrent thread import bug (two threads trying to import the same module, but deadlock). I could resolve it adding some code to the django.wsgi script (generated with buildout and djangorecipe) which:

imports my project's urls.py
closes database connection
closes memcached connection
before uwsgi forks.

Should I close the issue?

erny on 14 Oct 2017

I got some more interesting references:

Bug in some version of requests library with implicit imports: https://github.com/requests/requests/issues/2925 (see last comment!)
https://github.com/kobotoolbox/kobocat/issues/377
Python bug in logging module with threads / forks: https://bugs.python.org/issue6721

Recommendation: set disable_existing_loggers to True in LOGGING

erny on 18 Oct 2017

👍3

I close this bug as "not a uwsgi bug", but a "python stdlib bug (logging module): process my hang with multiple threads on implicit imports.". Thanks.

erny on 8 Nov 2017

👍3

I am seeing this too. I am unsure how uwsgi works, but it is never safe to fork from a process that already has multiple threads and continue running.

ztane on 29 Jan 2018

@erny I have the same problem when I run sudo kill -HUP cat /var/run/uwsgi.pid. Then uwsgi can not process any request. My config for disable_existing_loggers is aleady True. Perhaps I use raven transport ThreadedRequestsHTTPTransport to cause this problem?

lxkaka on 30 Nov 2018

May be, but in my case, it was bug due to concurrent imports, i.e., a
global interpreter lock is set before fork, but is removed after fork. This
makes the subprocess hang. Especially sensible is "logging" library, i.e.,
you have to import all needed stuff before uwsgi forks workers.

I just changed the wsgi script to import everything I needed. This has
other advantages:

fork is quicker
lesser overall memory consumption
I assure that nothing is open before ending the script (database, cache
connection, etc.) as most type of connections are not shareable between
main and subprocess.

Best regards

El vie., 30 nov. 2018 a las 7:54, Linxiao Wang (notifications@github.com)
escribió:

@erny https://github.com/erny I have the same problem when I run sudo
kill -HUP cat /var/run/uwsgi.pid. Then uwsgi can not process any request.
My config for disable_existing_loggers is aleady True. Perhaps I use
raven transport ThreadedRequestsHTTPTransport to cause this problem?

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/unbit/uwsgi/issues/1599#issuecomment-443109968, or mute
the thread
https://github.com/notifications/unsubscribe-auth/AAEtcAPsrj7TU9L7Z_jmlPlaPHQcoGBhks5u0NY8gaJpZM4OsPfP
.