Uwsgi: Deadlock when multiple workers die at the same time

Created on 3 Jul 2017 · 5Comments · Source: unbit/uwsgi

Hi @unbit,

I am running into the following deadlock which seems to occur after two workers harakiri at the same time. Eventually as the remaining workers are recycled, they also become caught in the same deadlock.

Mon Jul  3 03:55:12 2017 - *** HARAKIRI ON WORKER 1 (pid: 17511, try: 1) ***
Mon Jul  3 03:55:12 2017 - HARAKIRI !!! worker 1 status !!!
Mon Jul  3 03:55:12 2017 - HARAKIRI [core 0] ... - POST ... since 1499050249
Mon Jul  3 03:55:12 2017 - HARAKIRI [core 1] ... - POST ... since 1499050250
Mon Jul  3 03:55:12 2017 - HARAKIRI [core 2] ... - POST ... since 1499050251
Mon Jul  3 03:55:12 2017 - HARAKIRI [core 3] ... - POST ... since 1499050249
Mon Jul  3 03:55:12 2017 - HARAKIRI !!! end of worker 1 status !!!
Mon Jul  3 03:55:13 2017 - DAMN ! worker 1 (pid: 17511) died, killed by signal 9 :( trying respawn ...
Mon Jul  3 03:55:13 2017 - Respawned uWSGI worker 1 (new pid: 17584)
Mon Jul  3 03:55:13 2017 - mapping worker 1 to CPUs: 0 1 2 3
Mon Jul  3 03:55:13 2017 - *** no app loaded. going in full dynamic mode ***
Mon Jul  3 03:55:13 2017 - subprocess 17585 exited with code 0
Mon Jul  3 02:55:14 2017 - WSGI app 0 (mountpoint='...|') ready in 0 seconds on interpreter 0x960f6d0 pid: 17584
Mon Jul  3 03:56:14 2017 - *** HARAKIRI ON WORKER 4 (pid: 17527, try: 1) ***
Mon Jul  3 03:56:14 2017 - HARAKIRI !!! worker 4 status !!!
Mon Jul  3 03:56:14 2017 - HARAKIRI [core 0] ... - POST ... since 1499050438
Mon Jul  3 03:56:14 2017 - HARAKIRI [core 1] ... - GET ... 1499050443
Mon Jul  3 03:56:14 2017 - HARAKIRI [core 2] ... - POST ... since 1499050439
Mon Jul  3 03:56:14 2017 - HARAKIRI [core 3] ... - POST ... since 1499050438
Mon Jul  3 03:56:14 2017 - HARAKIRI !!! end of worker 4 status !!!
Mon Jul  3 02:56:14 2017 - [deadlock-detector] a process holding a robust mutex died. recovering...
Mon Jul  3 02:56:14 2017 - ...The work of process 17355 is done. Seeya!
Mon Jul  3 03:56:15 2017 - worker 3 killed successfully (pid: 17355)
Mon Jul  3 03:56:15 2017 - Respawned uWSGI worker 3 (new pid: 17594)
Mon Jul  3 03:56:15 2017 - DAMN ! worker 4 (pid: 17527) died, killed by signal 9 :( trying respawn ...
Mon Jul  3 03:56:15 2017 - Respawned uWSGI worker 4 (new pid: 17595)
Mon Jul  3 03:56:15 2017 - mapping worker 3 to CPUs: 0 1 2 3
Mon Jul  3 03:56:15 2017 - mapping worker 4 to CPUs: 0 1 2 3
Mon Jul  3 03:56:15 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:56:15 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:56:15 2017 - DAMN ! worker 3 (pid: 17594) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:56:15 2017 - Respawned uWSGI worker 3 (new pid: 17606)
Mon Jul  3 03:56:15 2017 - mapping worker 3 to CPUs: 0 1 2 3
Mon Jul  3 03:56:15 2017 - DAMN ! worker 4 (pid: 17595) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:56:15 2017 - Respawned uWSGI worker 4 (new pid: 17607)
Mon Jul  3 03:56:15 2017 - mapping worker 4 to CPUs: 0 1 2 3
Mon Jul  3 03:56:15 2017 - *** no app loaded. going in full dynamic mode ***
Mon Jul  3 03:56:15 2017 - subprocess 17596 exited with code 0
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:56:15 2017 - *** no app loaded. going in full dynamic mode ***
Mon Jul  3 03:56:15 2017 - DAMN ! worker 3 (pid: 17606) died, killed by signal 6 :( trying respawn ...
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:56:15 2017 - Respawned uWSGI worker 3 (new pid: 17616)
Mon Jul  3 03:56:15 2017 - mapping worker 3 to CPUs: 0 1 2 3
Mon Jul  3 03:56:15 2017 - DAMN ! worker 4 (pid: 17607) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:56:15 2017 - worker respawning too fast !!! i have to sleep a bit (2 seconds)...
Mon Jul  3 03:56:15 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:56:17 2017 - Respawned uWSGI worker 4 (new pid: 17620)
Mon Jul  3 03:56:17 2017 - DAMN ! worker 3 (pid: 17616) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:56:17 2017 - Respawned uWSGI worker 3 (new pid: 17621)
Mon Jul  3 03:56:17 2017 - mapping worker 4 to CPUs: 0 1 2 3
Mon Jul  3 03:56:17 2017 - mapping worker 3 to CPUs: 0 1 2 3
Mon Jul  3 03:56:17 2017 - *** no app loaded. going in full dynamic mode ***
Mon Jul  3 03:56:17 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
...
Mon Jul  3 03:57:10 2017 - *** HARAKIRI ON WORKER 2 (pid: 17570, try: 1) ***
Mon Jul  3 03:57:10 2017 - HARAKIRI !!! worker 2 status !!!
Mon Jul  3 03:57:10 2017 - HARAKIRI [core 0] ... - POST ... since 1499050497
Mon Jul  3 03:57:10 2017 - HARAKIRI [core 1] ... - GET ... since 149905049
Mon Jul  3 03:57:10 2017 - HARAKIRI [core 2] ... - GET ... since 1499050498
Mon Jul  3 03:57:10 2017 - HARAKIRI [core 3] ... - POST ... since 1499050497
Mon Jul  3 03:57:10 2017 - HARAKIRI !!! end of worker 2 status !!!
Mon Jul  3 03:57:10 2017 - mapping worker 4 to CPUs: 0 1 2 3
Mon Jul  3 03:57:10 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:57:10 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:57:11 2017 - DAMN ! worker 2 (pid: 17570) died, killed by signal 9 :( trying respawn ...
Mon Jul  3 03:57:11 2017 - Respawned uWSGI worker 2 (new pid: 17927)
Mon Jul  3 03:57:11 2017 - DAMN ! worker 3 (pid: 17919) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:57:11 2017 - Respawned uWSGI worker 3 (new pid: 17928)
Mon Jul  3 03:57:11 2017 - DAMN ! worker 4 (pid: 17920) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:57:11 2017 - mapping worker 2 to CPUs: 0 1 2 3
Mon Jul  3 03:57:11 2017 - mapping worker 3 to CPUs: 0 1 2 3
Mon Jul  3 03:57:11 2017 - Respawned uWSGI worker 4 (new pid: 17929)
Mon Jul  3 03:57:11 2017 - mapping worker 4 to CPUs: 0 1 2 3
Mon Jul  3 03:57:11 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:57:11 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:57:11 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
...
Mon Jul  3 03:57:25 2017 - *** HARAKIRI ON WORKER 1 (pid: 17584, try: 1) ***
Mon Jul  3 03:57:25 2017 - HARAKIRI !!! worker 1 status !!!
Mon Jul  3 03:57:25 2017 - HARAKIRI [core 0] ... - POST ... since 1499050514
Mon Jul  3 03:57:25 2017 - HARAKIRI [core 1] ... - GET ... since 1499050514
Mon Jul  3 03:57:25 2017 - HARAKIRI [core 2] ... - GET ... since 1499050514
Mon Jul  3 03:57:25 2017 - HARAKIRI [core 3] ... - POST ... since 1499050514
Mon Jul  3 03:57:25 2017 - HARAKIRI !!! end of worker 1 status !!!
Mon Jul  3 03:57:25 2017 - mapping worker 3 to CPUs: 0 1 2 3
Mon Jul  3 03:57:25 2017 - *** no app loaded. going in full dynamic mode ***
Mon Jul  3 03:57:25 2017 - *** no app loaded. going in full dynamic mode ***
Mon Jul  3 03:57:25 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:57:26 2017 - DAMN ! worker 1 (pid: 17584) died, killed by signal 9 :( trying respawn ...
Mon Jul  3 03:57:26 2017 - Respawned uWSGI worker 1 (new pid: 18035)
Mon Jul  3 03:57:26 2017 - DAMN ! worker 4 (pid: 18023) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:57:26 2017 - mapping worker 1 to CPUs: 0 1 2 3
Mon Jul  3 03:57:26 2017 - Respawned uWSGI worker 4 (new pid: 18036)
Mon Jul  3 03:57:26 2017 - DAMN ! worker 2 (pid: 18024) died, killed by signal 6 :( trying respawn ...
Mon Jul  3 03:57:26 2017 - worker respawning too fast !!! i have to sleep a bit (2 seconds)...
Mon Jul  3 03:57:26 2017 - mapping worker 4 to CPUs: 0 1 2 3
Mon Jul  3 03:57:26 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
Mon Jul  3 03:57:26 2017 - *** no app loaded. going in full dynamic mode ***
uwsgi: pthread_mutex_lock.c:312: __pthread_mutex_lock_full: Assertion `(-(e)) != 3 || !robust' failed.
...

Configuration is as follows:

[uwsgi]
strict = true
socket = ...
stats = ...
master = true
no-orphans = true
reload-os-env = true
logto = ...
logdate = true
processes = 4
threads = 4
harakiri = 130
post-buffering = 4096
vhost = true
vhost-host = true
no-site = true
chmod-socket = 600
uid = www-data
gid = www-data
pidfile = ...
max-requests = 500
max-worker-lifetime = 86400
reload-mercy = 20
reload-on-as = 512
reload-on-rss = 256
listen = 1024
env = LANG=en_GB.UTF-8
env = LC_ALL=en_GB.UTF-8
buffer-size = 8192
single-interpreter = true
thunder-lock = true
enable-threads = true
cpu-affinity = 4
lazy-apps = true
vacuum = true
alarm = mail cmd:fqdn=`hostname --fqdn`; mail -s "[uwsgi] alarm triggered on ${fqdn}" -a "From: uwsgi@${fqdn}" [email protected]
alarm-backlog = mail
alarm-log = mail HARAKIRI ON WORKER
alarm-segfault = mail
ignore-sigpipe = true

Looking into the uwsgi code, I found the commit https://github.com/unbit/uwsgi/commit/0e08c0211ce65982edc708f951bee36bbb275b1d and it sounds as though it is trying to address something similar to what I am experiencing. Is there a reason this cannot be part of a normal release (or at least behind a configuration option)?

Thanks,

Nick

Source

ngnpope

All 5 comments

You forgot to mention your uwsgi version, and your environment (distribution and kernel version)

xrmx on 3 Jul 2017

You are quite right - I meant to and forgot.

Ubuntu 10.04 Lucid Lynx (32-bit)
Linux 2.6.32-6-pve
libc6 2.11.1-0ubuntu7.20
uWSGI 2.0.15

I realise that this is a rather old environment, but I'm stuck with it for a few months. I used to manually restart uWSGI to workaround this issue as it was relatively infrequent, but an increase in traffic has made it occur more often and typically overnight due to with increased workloads.

ngnpope on 4 Jul 2017

@xrmx: did you see my response above?

ngnpope on 6 Sep 2017

@pope1ni yes, pardon me if I don't want to spend my free time researching your issues, I ask questions to make it possible for others willing to do so to have all the relevant information.

xrmx on 6 Sep 2017

👎19

@pope1ni hi, i think that workaround (now that unbit kernels are all been moved to more recent versions) can be moved to a public option. Would you like to make a pull request for it ? (just remove the #ifdef and place it into an option)