502 Gateway Error after reload

[pedroteixeira]

Hello,

I'm using uwsgi in emperor mode, and I always get 502 error after a reload/restart of the service or of the vassal.

Only after the first request, I can see in the logs:

announcing my loyalty to the Emperor...

After this, everything is fine again.

The problem occurs with django+nginx+uwsgi. I've tried the most recent version of uwsgi, and it occurs either by restarting using killproc or by touch-reload.

Is there any workaround for this behaviour? I couldn't find much help in web or in the docs.

Current config of one of the vassals .ini:

[uwsgi]
socket = 127.0.0.1:8001
home = /dir
virtualenv = /dir
pythonpath = /dir
chdir = /dir
env = DJANGO_SETTINGS_MODULE=my.settings
pidfile = /dir/logs/app-uwsgi.pid
touch-reload = /dir/logs/app-uwsgi.pid
mount = /=my.wsgi:application
processes = 4
#threads = 1
#enable-threads
master = true
harakiri = 180
reload-mercy = 8
cpu-affinity = 1
stats = 127.0.0.1:9901
max-requests = 2000
# limit-as = 512
# reload-on-as = 256
# reload-on-rss = 192
uid = intelie
gid = intelie
# no-orphans    = true
#chmod-socket = 777
#chown-socket = nginx
#chmod-socket = 666
logto = /dir/logs/uwsgi.log
logfile-chown = user

Not sure if this is bug.. any help is appreaciated! thanks

[unbit]

From what you describe it could be the emperor is destroying and recreating the instance evrytime. You should paste log messages as they describe what is happening during the reload

[pedroteixeira]

the weird thing is that "announcing my loyalty to the Emperor..." only takes place AFTER I make a HTTP request. I would like the process to be ready right after reloading.

uwsgi.log

*** Starting uWSGI 1.9.13 (64bit) on [Thu Oct 31 23:16:42 2013] ***
compiled with version: 4.4.7 20120313 (Red Hat 4.4.7-3) on 20 July 2013 13:05:30
os: Linux-2.6.32-358.11.1.el6.x86_64 #1 SMP Wed Jun 12 03:34:52 UTC 2013
nodename: pocoweb
machine: x86_64
clock source: unix
detected number of CPU cores: 2
current working directory: /etc/uwsgi/vassals
writing pidfile to /dir/logs/app-uwsgi.pid
detected binary path: /opt/runtime/python27/bin/uwsgi
your processes number limit is 15661
your memory page size is 4096 bytes
 *** WARNING: you have enabled harakiri without post buffering. Slow upload could be rejected on post-unbuffered webservers *** 
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
uwsgi socket 0 bound to TCP address 127.0.0.1:8001 fd 3
Python version: 2.7.3 (default, Jul 20 2013, 13:04:30)  [GCC 4.4.7 20120313 (Red Hat 4.4.7-3)]
Set PythonHome to /dir
*** Python threads support is disabled. You can enable it with --enable-threads ***
Python main interpreter initialized at 0xbb2a60
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 363840 bytes (355 KB) for 4 cores
*** Operational MODE: preforking ***
added /dir to pythonpath.
mounting app.wsgi:application on /
WSGI app 0 (mountpoint='/') ready in 0 seconds on interpreter 0xbb2a60 pid: 20915 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 20915)
spawned uWSGI worker 1 (pid: 20922, cores: 1)
spawned uWSGI worker 2 (pid: 20923, cores: 1)
mapping worker 1 to CPUs: 0
spawned uWSGI worker 3 (pid: 20924, cores: 1)
mapping worker 2 to CPUs: 1
spawned uWSGI worker 4 (pid: 20926, cores: 1)
*** Stats server enabled on 127.0.0.1:9901 fd: 16 ***
mapping worker 4 to CPUs: 1
mapping worker 3 to CPUs: 0

[pid: 703|app: 0|req: 1/1] <IP> () {46 vars in 847 bytes} [Sun Nov  3 20:40:52 2013] GET / => generated 1131 bytes in 545 msecs (HTTP/1.1 500) 4 headers in 147 bytes (1 switches on core 0)
announcing my loyalty to the Emperor...

I get a 500 error for my first request after uwsgi reload:

nginx.error.log

2013/11/03 20:39:56 [error] 29232#0: *123 upstream prematurely closed connection while reading response header from upstream, client: <IP>, server: <URL>, request: "GET /favicon.ico HTTP/1.1", upstream: "uwsgi://127.0.0.1:8001", host: "<URL>"

nginx.acess.log

<IP> - - [03/Nov/2013:20:40:53 -0200] "GET / HTTP/1.1" 500 1131 "-" "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.114 Safari/537.36"

Does it anyone know a configuration param that would help in this case, to avoid first requests not being served correctly?

thanks.

[unbit]

Loyalty happens at the first successfull request, as it is a flag to consider a vassal "healthy". (It is only a flag, there is no difference in the way requests are managed). By the way the logs you pasted shows a completely restarted vassal not a reloaded one. You should report the whole logs before the reloading is issued, because it looks like reloading fails and your instance is completely restarted (that means no graceful reloading as the sockets are closed)

[pedroteixeira]

I used touch to reload, and the first requests still fail. I'm considering triggering some "curl" after reload o restart to warm up.. not sure if there's a better strategy.

Mon Nov  4 10:22:44 2013 - *** /dir/logs/app-uwsgi.pid has been touched... grace them all !!! ***
...gracefully killing workers...
Gracefully killing worker 2 (pid: 2438)...
Gracefully killing worker 1 (pid: 2436)...
Gracefully killing worker 3 (pid: 2439)...
Gracefully killing worker 4 (pid: 2440)...
worker 1 buried after 1 seconds
worker 2 buried after 1 seconds
worker 3 buried after 1 seconds
worker 4 buried after 1 seconds
binary reloading uWSGI...
chdir() to /etc/uwsgi/vassals
closing all non-uwsgi socket fds > 2 (max_fd = 1024)...
found fd 3 mapped to socket 0 (127.0.0.1:8001)
running /opt/runtime/python27/bin/uwsgi
*** has_emperor mode detected (fd: 7) ***
[uWSGI] getting INI configuration from app.ini
*** Starting uWSGI 1.9.13 (64bit) on [Mon Nov  4 10:22:45 2013] ***
compiled with version: 4.4.7 20120313 (Red Hat 4.4.7-3) on 20 July 2013 13:05:30
os: Linux-2.6.32-358.11.1.el6.x86_64 #1 SMP Wed Jun 12 03:34:52 UTC 2013
nodename: pocoweb
machine: x86_64
clock source: unix
detected number of CPU cores: 2
current working directory: /etc/uwsgi/vassals
detected binary path: /opt/runtime/python27/bin/uwsgi
your processes number limit is 15661
your memory page size is 4096 bytes
 *** WARNING: you have enabled harakiri without post buffering. Slow upload could be rejected on post-unbuffered webservers *** 
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
uwsgi socket 0 inherited INET address 127.0.0.1:8001 fd 3
Python version: 2.7.3 (default, Jul 20 2013, 13:04:30)  [GCC 4.4.7 20120313 (Red Hat 4.4.7-3)]
Set PythonHome to /dir
*** Python threads support is disabled. You can enable it with --enable-threads ***
Python main interpreter initialized at 0x1b5dae0
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 363840 bytes (355 KB) for 4 cores
*** Operational MODE: preforking ***
added /dir/ to pythonpath.
mounting app.wsgi:application on /
WSGI app 0 (mountpoint='/') ready in 0 seconds on interpreter 0x1b5dae0 pid: 2433 (default app)
*** uWSGI is running in multiple interpreter mode ***
gracefully (RE)spawned uWSGI master process (pid: 2433)
spawned uWSGI worker 1 (pid: 2465, cores: 1)
mapping worker 1 to CPUs: 0
spawned uWSGI worker 2 (pid: 2466, cores: 1)
mapping worker 2 to CPUs: 1
spawned uWSGI worker 3 (pid: 2467, cores: 1)
spawned uWSGI worker 4 (pid: 2468, cores: 1)
mapping worker 4 to CPUs: 1
mapping worker 3 to CPUs: 0
*** Stats server enabled on 127.0.0.1:9901 fd: 16 ***

[pid: 2465|app: 0|req: 1/1] 189.122.20.197 () {46 vars in 847 bytes} [Mon Nov  4 10:23:03 2013] GET / => generated 1131 bytes in 551 msecs (HTTP/1.1 500) 4 headers in 147 bytes (1 switches on core 0)
announcing my loyalty to the Emperor...

[unbit]

oh, i was sure you mean that uWSGI does not respond to request, but you are effectively saying that your django app returns an unexpected 500. Unfortunately there is nothing from the uWSGI side to fix, it. Have you enabled sending of django exceptions via mail ? maybe you will find the error

[pedroteixeira]

hm.. ok, will try to further investigate on the Django side. But it only happens after uWSGI reload/restart. And it does not happen with gUnicorn for example (but only tested on a different OS)

[prymitive]

maybe your database requires fixing after forking?

http://uwsgi-docs.readthedocs.org/en/latest/PythonDecorators.html#uwsgidecorators.postfork

[unbit]

generally django activation is lazy so there is no need to fix databases connections. Debugging that 500 should give more useful infos

[pedroteixeira]

indeed, it was a weird error in the django/app side, sorry about that :) [ImportError due to some sort of cyclic imports]

[fletchowns]

I'm also running into the same issue - first request after a touch to reload results in a 502 error. Subsequent requests work fine - how'd you track down the source of your error pedroteixeira? I'm not finding anything useful in the logs.

[fletchowns]

Nevermind, I was looking in the wrong log file. Looks like it was an issue with my logging configuration:

ValueError: Unable to configure handler 'file': [Errno 13] Permission denied: '/var/log/django/www.myawesomesite.com.log'

[zsluedem]

i meet this problem after i reload the uwsgi

Gracefully killing worker 1 (pid: 28636)...
Gracefully killing worker 4 (pid: 28642)...
Gracefully killing worker 2 (pid: 28638)...
worker 1 buried after 3 seconds
worker 2 buried after 3 seconds
worker 3 buried after 3 seconds
worker 4 buried after 3 seconds
binary reloading uWSGI...
chdir() to /home/xx
closing all non-uwsgi socket fds > 2 (max_fd = 165535)...
found fd 3 mapped to socket 0 (127.0.0.1:7788)
running /home/xx
[uWSGI] getting INI configuration from uwsgi.ini
*** Starting uWSGI 2.0.15 (64bit) on [Thu Sep  7 14:57:58 2017] ***
compiled with version: 4.8.5 20150623 (Red Hat 4.8.5-11) on 24 August 2017 09:25:44
os: Linux-3.10.0-514.26.2.el7.x86_64 #1 SMP Tue Jul 4 15:04:05 UTC 2017
nodename: cdh1
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 4
current working directory: /home/xx
detected binary path: /home/xx
chdir() to /home/xx
your processes number limit is 4096
your memory page size is 4096 bytes
detected max file descriptor number: 165535
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 inherited INET address 127.0.0.1:7788 fd 3
Python version: 3.4.5 (default, May 29 2017, 15:17:55)  [GCC 4.8.5 20150623 (Red Hat 4.8.5-11)]
Python main interpreter initialized at 0x26ded50
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 415360 bytes (405 KB) for 8 cores
*** Operational MODE: preforking+threaded ***
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x26ded50 pid: 5341 (default app)
*** uWSGI is running in multiple interpreter mode ***
gracefully (RE)spawned uWSGI master process (pid: 5341)
spawned uWSGI worker 1 (pid: 28946, cores: 2)
spawned uWSGI worker 2 (pid: 28947, cores: 2)
spawned uWSGI worker 3 (pid: 28948, cores: 2)
spawned uWSGI worker 4 (pid: 28949, cores: 2)

it is a timeout error