[uWSGI] Possible setup race condition between uwsgi-plugin-python and python-flask

Clemens Kolbitsch kolbitsch at lastline.com
Wed Apr 9 17:56:33 CEST 2014


Hi,

thanks for the suggestion! However, seems like all server processes are
ready at this point

## modified wsgi file:

import os
pid = os.getpid()
print "loading stage 1", pid
application = myapp.create_app(CONFIG_FILE, None, log, strict=True)
print "loading stage 2", pid

application.logger.setLevel(logging.DEBUG)
for handler in log.logger().handlers:
    application.logger.addHandler(handler)
print "loading stage 3", pid

## updated logs

...The work of process 17248 is done. Seeya!
...The work of process 17249 is done. Seeya!
worker 1 killed successfully (pid: 17248)
Respawned uWSGI worker 1 (new pid: 17424)
worker 2 killed successfully (pid: 17249)
Respawned uWSGI worker 2 (new pid: 17425)
loading stage 1 17425
loading stage 1 17424
loading stage 2 17424
loading stage 2 17425
loading stage 3 17424
loading stage 3 17425
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2278480 pid:
17424 (default app)
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2278480 pid:
17425 (default app)
...The work of process 17425 is done. Seeya!
...The work of process 17424 is done. Seeya!
worker 1 killed successfully (pid: 17424)
Respawned uWSGI worker 1 (new pid: 17956)
worker 2 killed successfully (pid: 17425)
Respawned uWSGI worker 2 (new pid: 17957)
loading stage 1 17957
loading stage 1 17956
loading stage 2 17956
loading stage 2 17957
loading stage 3 17956
loading stage 3 17957
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2278480 pid:
17956 (default app)
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2278480 pid:
17957 (default app)
[pid: 17956|app: 0|req: 2/3571] 192.168.100.11 () {32 vars in 432 bytes}
[Wed Apr  9 15:48:11 2014] GET /myapp/... => generated 238 bytes in 7 msecs
(HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 1)
[pid: 17956|app: 0|req: 10/3573] 192.168.100.11 () {32 vars in 432 bytes}
[Wed Apr  9 15:48:11 2014] GET /myapp/... => generated 238 bytes in
16 msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 0)
[pid: 17956|app: 0|req: 18/3575] 192.168.100.11 () {32 vars in 432 bytes}
[Wed Apr  9 15:48:11 2014] GET /myapp/... => generated 238 bytes in
24 msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 6)

## FWIW, I decided to do another test to see if new threads are spawned
before the function returns

import os, threading
pid = os.getpid()
print "loading stage 1", pid, threading.active_count()
application = myapp.create_app(CONFIG_FILE, None, log, strict=True)
print "loading stage 2", pid, threading.active_count()

application.logger.setLevel(logging.DEBUG)
for handler in log.logger().handlers:
    application.logger.addHandler(handler)
print "loading stage 3", pid, threading.active_count()


and get


Respawned uWSGI worker 1 (new pid: 23145)
worker 2 killed successfully (pid: 22771)
Respawned uWSGI worker 2 (new pid: 23146)
loading stage 1 23146 1
loading stage 1 23145 1
loading stage 2 23145 1
loading stage 3 23145 1
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2340480 pid:
23145 (default app)
loading stage 2 23146 1
loading stage 3 23146 1
WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2340480 pid:
23146 (default app)
[pid: 23146|app: 0|req: 31/2387] 192.168.100.11 () {32 vars in 432 bytes}
[Wed Apr  9 15:52:38 2014] GET /myapp/... => generated 238 bytes in 26
msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 28)


so, could it be that it's not uwsgi's fault after all? As mentioned
initially, the flask-guys sent me to this mailing list, because they said
it's not flask's fault. But, from all my debug-logs, it seems like the
first thread does the set-up and at the point where all the blueprints have
been set up, there is still only one thread.... but of course I have no
idea of the uwsgi internals (and neither the flask ones) ;)

-Clemens







On Wed, Apr 9, 2014 at 2:40 AM, Roberto De Ioris <roberto at unbit.it> wrote:

>
> > I modified the code as follows:
> >
> > [...]
> > print "loading stage 1"
> > application = myapp.create_app(CONFIG_FILE, None, log, strict=True)
> > print "loading stage 2"
> > application.logger.setLevel(logging.DEBUG)
> > for handler in log.logger().handlers:
> >     application.logger.addHandler(handler)
> > print "loading stage 3"
> >
> > and get the following logs
> >
> > /usr/bin/uwsgi --ini /etc/uwsgi/apps-enabled/myapp.ini 2>&1 | grep -v
> > HTTP.....200
> > [uWSGI] getting INI configuration from /etc/uwsgi/apps-enabled/myapp.ini
> > *** Starting uWSGI 2.0.3 (64bit) on [Tue Apr  8 18:16:20 2014] ***
> > compiled with version: 4.6.3 on 08 April 2014 02:43:31
> > os: Linux-3.2.0-60-generic #91-Ubuntu SMP Wed Feb 19 03:54:44 UTC 2014
> > nodename: mynode
> > machine: x86_64
> > clock source: unix
> > detected number of CPU cores: 8
> > current working directory: /var/log
> > detected binary path: /usr/local/bin/uwsgi
> > !!! no internal routing support, rebuild with pcre support !!!
> > setgid() to 1010
> > setuid() to 1002
> > your processes number limit is 128020
> > 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 bound to TCP address 127.0.0.1:4003 fd 3
> > Python version: 2.7.3 (default, Feb 27 2014, 20:09:21)  [GCC 4.6.3]
> > Python main interpreter initialized at 0x1d5d480
> > 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 2503992 bytes (2445 KB) for 150 cores
> > *** Operational MODE: preforking+threaded ***
> > *** uWSGI is running in multiple interpreter mode ***
> > spawned uWSGI master process (pid: 19627)
> > spawned uWSGI worker 1 (pid: 19629, cores: 75)
> > spawned uWSGI worker 2 (pid: 19630, cores: 75)
> > loading stage 1
> > loading stage 1
> > loading stage 2
> > loading stage 2
> > loading stage 3
> > loading stage 3
> >
> > [...]
> >
> > worker 2 killed successfully (pid: 22063)
> > Respawned uWSGI worker 2 (new pid: 22494)
> > worker 1 killed successfully (pid: 22064)
> > Respawned uWSGI worker 1 (new pid: 22495)
> > loading stage 1
> > loading stage 1
> > loading stage 2
> > loading stage 3
> > loading stage 2
> > WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1d5d480
> > pid:
> > 22494 (default app)
> > loading stage 3
> > WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1d5d480
> > pid:
> > 22495 (default app)
> >
> > [...]
> >
> > ...The work of process 22494 is done. Seeya!
> > ...The work of process 22495 is done. Seeya!
> > worker 2 killed successfully (pid: 22494)
> > Respawned uWSGI worker 2 (new pid: 22685)
> > worker 1 killed successfully (pid: 22495)
> > Respawned uWSGI worker 1 (new pid: 22686)
> > loading stage 1
> > loading stage 1
> > loading stage 2
> > loading stage 2
> > loading stage 3
> > WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1d5d480
> > pid:
> > 22686 (default app)
> > loading stage 3
> > WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1d5d480
> > pid:
> > 22685 (default app)
> > [pid: 22685|app: 0|req: 3/4660] 192.168.100.11 () {32 vars in 432 bytes}
> > [Tue Apr  8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 6
> > msecs
> > (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 0)
> > [pid: 22686|app: 0|req: 16/4665] 192.168.100.11 () {32 vars in 432 bytes}
> > [Tue Apr  8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 26
> > msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 5)
> > [pid: 22686|app: 0|req: 54/4677] 192.168.100.11 () {32 vars in 432 bytes}
> > [Tue Apr  8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 56
> > msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 7)
> > [pid: 22686|app: 0|req: 54/4678] 192.168.100.11 () {32 vars in 432 bytes}
> > [Tue Apr  8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 58
> > msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 1)
> >
> > after this, the logs are empty again - that is, no more 404s for a while
> > (note that I grep out the HTTP-200s before and after)
> >
> > thanks!
> > -Clemens
> >
> >
>
> can you repeat the test printing the process pid (os.getpid()) at each
> line ? in this way we can see if all the stages are executed before the
> "readyness" announce
>
> Thanks
>
> --
> Roberto De Ioris
> http://unbit.it
> _______________________________________________
> uWSGI mailing list
> uWSGI at lists.unbit.it
> http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi
>



-- 
Clemens Kolbitsch
Security Researcher
kolbitsch at lastline.com
Mobile +1 (206) 356-7745
Land +1 (805) 456-7076

Lastline, Inc.
6950 Hollister Avenue, Suite 101
Goleta, CA 93117

www.lastline.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.unbit.it/pipermail/uwsgi/attachments/20140409/93d8cbb6/attachment.html>


More information about the uWSGI mailing list