Uwsgi: Listen queue reported full and all requests failing immediately after graceful reload

[SuneKjaergaard]

This morning we had a weird incident when we deployed an update.
immediately after reloading, the uwsgi server started reporting that the listening queue was full and served no requests. I tried doing another graceful reload to no avail. Restarting nginx helped, but what happened in the first place?

The other servers reloaded without problems, and there was next to no incomming traffic.

Log:

...gracefully killing workers...
Gracefully killing worker 2 (pid: 10332)...
Gracefully killing worker 19 (pid: 16519)...
Gracefully killing worker 1 (pid: 10331)...
Gracefully killing worker 8 (pid: 10338)...
Gracefully killing worker 3 (pid: 10333)...
Gracefully killing worker 16 (pid: 10346)...
Gracefully killing worker 11 (pid: 10341)...
Gracefully killing worker 4 (pid: 10334)...
Gracefully killing worker 10 (pid: 10340)...
Gracefully killing worker 12 (pid: 10342)...
Gracefully killing worker 5 (pid: 10335)...
Gracefully killing worker 9 (pid: 10339)...
Gracefully killing worker 20 (pid: 15669)...
Gracefully killing worker 13 (pid: 10343)...
Gracefully killing worker 6 (pid: 10336)...
Gracefully killing worker 18 (pid: 10348)...
Gracefully killing worker 17 (pid: 15051)...
Gracefully killing worker 7 (pid: 10337)...
Gracefully killing worker 14 (pid: 10344)...
Gracefully killing worker 15 (pid: 10345)...
worker 1 buried after 4 seconds
worker 2 buried after 4 seconds
worker 3 buried after 4 seconds
worker 4 buried after 4 seconds
worker 5 buried after 4 seconds
worker 6 buried after 4 seconds
worker 7 buried after 4 seconds
worker 8 buried after 4 seconds
worker 9 buried after 4 seconds
worker 10 buried after 4 seconds
worker 11 buried after 4 seconds
worker 12 buried after 4 seconds
worker 13 buried after 4 seconds
worker 14 buried after 4 seconds
worker 15 buried after 4 seconds
worker 16 buried after 4 seconds
worker 18 buried after 4 seconds
worker 17 buried after 4 seconds
worker 20 buried after 4 seconds
worker 19 buried after 4 seconds
binary reloading uWSGI...
chdir() to /
closing all non-uwsgi socket fds > 2 (max_fd = 1024)...
found fd 6 mapped to socket 0 (0.0.0.0:9099)
running /home/myuser/.virtualenvs/env/bin/uwsgi
[uWSGI] getting INI configuration from /hostroot/conf/uwsgi/ENV/myapp.ini
open("./logsocket_plugin.so"): No such file or directory [core/utils.c line 3684]
!!! UNABLE to load uWSGI plugin: ./logsocket_plugin.so: cannot open shared object file: No such file or directory !!!
*** Starting uWSGI 2.0.12 (64bit) on [Thu Sep 29 08:11:48 2016] ***
compiled with version: 4.4.7 20120313 (Red Hat 4.4.7-4) on 22 March 2016 08:31:17
os: Linux-2.6.32-358.23.2.el6.x86_64 #1 SMP Wed Oct 16 18:37:12 UTC 2013
nodename: web1.myhost.env
machine: x86_64
clock source: unix
detected number of CPU cores: 4
current working directory: /
detected binary path: /home/myuser/.virtualenvs/env/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 77038
limiting address space of processes...
your process address space limit is 1048576000 bytes (1000 MB)
your memory page size is 4096 bytes
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 inherited INET address 0.0.0.0:9099 fd 6

Python version: 2.7.3 (default, Oct 15 2014, 15:24:57)  [GCC 4.4.7 20120313 (Red Hat 4.4.7-4)]
Set PythonHome to /home/myuser/.virtualenvs/env/
Python main interpreter initialized at 0xaa5690
python threads support enabled
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 1958208 bytes (1912 KB) for 20 cores
*** Operational MODE: preforking ***
added /home/myuser/otherapp/ to pythonpath.
added /home/myuser/myapp/ to pythonpath.
added /home/myuser/otherapp/dir/ to pythonpath.
WSGI app 0 (mountpoint='') ready in 5 seconds on interpreter 0xaa5690 pid: 15112 (default app)
gracefully (RE)spawned uWSGI master process (pid: 15112)
spawned uWSGI worker 1 (pid: 16772, cores: 1)
spawned uWSGI worker 2 (pid: 16773, cores: 1)
spawned uWSGI worker 3 (pid: 16774, cores: 1)
spawned uWSGI worker 4 (pid: 16775, cores: 1)
spawned uWSGI worker 5 (pid: 16776, cores: 1)
spawned uWSGI worker 6 (pid: 16777, cores: 1)
spawned uWSGI worker 7 (pid: 16778, cores: 1)
spawned uWSGI worker 8 (pid: 16779, cores: 1)
spawned uWSGI worker 9 (pid: 16780, cores: 1)
spawned uWSGI worker 10 (pid: 16781, cores: 1)
spawned uWSGI worker 11 (pid: 16782, cores: 1)
spawned uWSGI worker 12 (pid: 16783, cores: 1)
spawned uWSGI worker 13 (pid: 16784, cores: 1)
spawned uWSGI worker 14 (pid: 16785, cores: 1)
spawned uWSGI worker 15 (pid: 16786, cores: 1)
spawned uWSGI worker 16 (pid: 16787, cores: 1)
spawned uWSGI worker 17 (pid: 16788, cores: 1)
spawned uWSGI worker 18 (pid: 16789, cores: 1)
spawned uWSGI worker 19 (pid: 16790, cores: 1)
spawned uWSGI worker 20 (pid: 16791, cores: 1)
*** Stats server enabled on /tmp/api-stats.socket fd: 101 ***
Thu Sep 29 08:36:32 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:33 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:34 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:35 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:36 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:37 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:38 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:39 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:40 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:41 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:42 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:43 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:44 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:45 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:46 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:47 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:48 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:49 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:50 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:51 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:52 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:53 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:54 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:55 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:56 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:57 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:58 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:36:59 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:37:00 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:37:01 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:37:02 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:37:03 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:37:04 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***
Thu Sep 29 08:37:05 2016 - *** uWSGI listen queue of socket "0.0.0.0:9099" (fd: 6) full !!! (101/100) ***

[emilyzzz]

We had the same issue recently. After investigation we found the root cause: upstream database had global read lock due to database backup script running. So uwsgi processes were waiting for locking, eventually caused "listen queue...full" error. After killing some processes on database side and restarting our uwsgi app, it's all running well now. Just FYI.

[SuneKjaergaard]

Hey @emilyzzz

Thanks for commenting. We have seen similar scenarios to the original one a few times more, however we have multiple servers running, and this only happened on one of them, so a database lock can't be the culprit in our case. But thanks anyway!

[perrohunter]

@SuneKjaergaard Did you found a solution to this problem?

[SuneKjaergaard]

Unfortunately we have not been able to neither identify a root cause, nor find a fix that guaranteed prevents this from happening again. However we haven't seen it in a long time.

[SuneKjaergaard]

The thing is, that this is not a question of load. There is no load on the server, so the listen queue fills up, or uwsgi thinks it's full for no apparent reason. I know there is no load on the server, because I have multiple other servers running, all behind a load balancer, and they are trotting along happily with few or no requests

[jordotech]

@SuneKjaergaard I am having the same issue you are describing. Single server with zero traffic behind a load balancer, backlog was getting filled. Our load balancer (digitalocean) had a health check configured every 3s which I think was contributing to the queue backlog, maybe you have something like that going on?

Our uwsgi logs were filled with these:

uwsgi_response_writev_headers_and_body_do(): Connection reset by peer [core/writer.c line 296] during GET

I turned on thunder-lock (which I don't fully understand yet) and spaced out the health checks to 20s intervals and now all those are gone from the log and it seems to be working nicely so far.

Is there a way to check how many incomplete requests are currently in the backlog?

[SuneKjaergaard]

Interesting, I haven't seen this particular message in our uwsgi logs. However we do have a load balancer that does health checks.
In general this is very hard to debug, it happens only a few times a year, and when it does happen, it is in need of instant fixing.

Btw I wrote a small shell script to check the log for those warnings and then restart the uwsgi server when it happens

[KIVagant]

Got the same today.

Btw I wrote a small shell script to check the log for those warnings and then restart the uwsgi server when it happens

@SuneKjaergaard , could you share the script?

[SuneKjaergaard]

Of course :-)

https://gist.github.com/SuneKjaergaard/c686ee5fb2564685148ad03fc87ba219

[nrlakin]

I had the same issue last week. By dumb luck, I reproduced it today. I haven't solved the problem (I don't even have a plausible explanation for why it happens) but I'm posting here on the off chance a smarter engineer finds it.

uWSGI version: 2.0.14
Ubuntu 16.04, running in a Docker container

First event: I left a shell connection to the container open (docker exec -it container /bin/bash). Seems farfetched that this could be related, but only unusual thing about the event.

Second event: During Redis cluster reboot, requests from my web server to Redis were timing out. This error started appearing after the first timeout. The server did not recover when the Redis server came back online.

Best guess right now is that any sort of long blocking process on the web server can trigger this issue. I'm trying to reproduce it now by running a simple flask app with a single endpoint:

@app.route('/suicide', methods=['GET'])
def suicide():
    requests.get('https://www.google.com:81')
    return "never gets here", 200

So far this isn't working.

[SuneKjaergaard]

This happened for us again yesterday, this time in a kubernetes environment. The server went from working perfect to reporting listen queue full in an instant.

[thenewguy]

Anyone ever figure this out?

[SuneKjaergaard]

We are seeing it from time to time, however I have now setup a liveness probe in kubernetes that handles it.
We run uWSGI with the following parameter:

alarm=removefile cmd:rm /tmp/listen_queue_healthy

And then in my deployment specification I have the following as liveness probe:

livenessProbe: exec: command: - test - -f - /tmp/listen_queue_healthy

Which basically tests if the file is still there. Of course you need to make sure the file exists in the first place, uWSGI doesnt create it. So we create it as part of the docker specification:

RUN touch /tmp/listen_queue_healthy && chown www-data:www-data /tmp/listen_queue_healthy

Funny thing is, that we run multiple applications with uWSGI but we've only seen the issue on one of them (which is based on the web.py framework)

DISCLAIMER: if the listen queue is filled up because of actual traffic, this will still restart the pods, so it can be dangerous

[anmolghosh]

We faced the issue recently.

We are using uwsgi to deploy our django app. We are using the preforking configuration of uwsgi, with 3 workers and a master. As we know under this configuration, the loading cycles is as follows:

• uwsgi initialize Django app in the master thread
• Post initialization, the master is forked to create workers

For details on this please read: https://uwsgi-docs.readthedocs.io/en/latest/articles/TheArtOfGracefulReloading.html#preforking-vs-lazy-apps-vs-lazy

As a part of recent code change, we added a “logger.error()” into the code which was called at the time of django app initialization/loading. Since we also had sentry configured, the “logger.error()” trigger a request to send an entry to the sentry.

The simultaneous execution of sentry called in the master thread and the uwsgi thread fork process was sometimes leading to a deadlock situation due to the following python bugs:

• https://bugs.python.org/issue6721
• https://bugs.python.org/issue25668
  Please read the reproduction steps in the first link to better understand the issue.

This was an intermittent issue as this required the logging call and uwsgi os forks to occur at the exact same time. When this occurs, it creates a deadlock for all the uwsgi worker making them unable to serve any request and hence leading to the listen queue being overloaded

We resolved the issue by removing the sentry call from the django app loading/initializing process.

[jgoclawski]

@anmolghosh Thank you for sharing your detailed story. We believe that a very similar thing was randomly occurring in our case (it was about double-configuring loggers, which emitted a log during app startup). Your comment helped us a lot, thanks!