[prev in list] [next in list] [prev in thread] [next in thread]
List: uwsgi
Subject: Re: [uWSGI] Possible setup race condition between uwsgi-plugin-python and python-flask
From: Clemens Kolbitsch <kolbitsch () lastline ! com>
Date: 2014-04-09 15:56:33
Message-ID: CAN+VXVOKo6HNkDd7XnfztmNzHG9-nK5Q4ZO4S=BiP+A3mJ_7Ug () mail ! gmail ! com
[Download RAW message or body]
[Attachment #2 (multipart/alternative)]
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@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@lists.unbit.it
> http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi
>
--
Clemens Kolbitsch
Security Researcher
kolbitsch@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
[Attachment #5 (text/html)]
<div dir="ltr"><div>Hi,</div><div><br></div><div>thanks for the suggestion! However, \
seems like all server processes are ready at this point</div><div><br></div><div>## \
modified wsgi file:</div><div><br></div><div>import os</div>
<div>pid = os.getpid()</div><div>print "loading stage 1", \
pid</div><div>application = myapp.create_app(CONFIG_FILE, None, log, \
strict=True)</div><div>print "loading stage 2", \
pid</div><div><br></div><div>
application.logger.setLevel(logging.DEBUG)</div><div>for handler in \
log.logger().handlers:</div><div> \
application.logger.addHandler(handler)</div><div>print "loading stage 3", \
pid</div><div><br></div><div>## updated logs</div>
<div><br></div><div><div>...The work of process 17248 is done. \
Seeya!</div><div>...The work of process 17249 is done. Seeya!</div><div>worker 1 \
killed successfully (pid: 17248)</div><div>Respawned uWSGI worker 1 (new pid: \
17424)</div>
<div>worker 2 killed successfully (pid: 17249)</div><div>Respawned uWSGI worker 2 \
(new pid: 17425)</div><div>loading stage 1 17425</div><div>loading stage 1 \
17424</div><div>loading stage 2 17424</div><div>loading stage 2 17425</div>
<div>loading stage 3 17424</div><div>loading stage 3 17425</div><div>WSGI app 0 \
(mountpoint='') ready in 1 seconds on interpreter 0x2278480 pid: 17424 \
(default app)</div><div>WSGI app 0 (mountpoint='') ready in 1 seconds on \
interpreter 0x2278480 pid: 17425 (default app)</div>
<div>...The work of process 17425 is done. Seeya!</div><div>...The work of process \
17424 is done. Seeya!</div><div>worker 1 killed successfully (pid: \
17424)</div><div>Respawned uWSGI worker 1 (new pid: 17956)</div><div>worker 2 killed \
successfully (pid: 17425)</div>
<div>Respawned uWSGI worker 2 (new pid: 17957)</div><div>loading stage 1 \
17957</div><div>loading stage 1 17956</div><div>loading stage 2 \
17956</div><div>loading stage 2 17957</div><div>loading stage 3 \
17956</div><div>loading stage 3 17957</div>
<div>WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x2278480 \
pid: 17956 (default app)</div><div>WSGI app 0 (mountpoint='') ready in 1 \
seconds on interpreter 0x2278480 pid: 17957 (default app)</div>
<div>[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)</div>
<div>[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)</div>
<div>[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)</div>
</div><div><br></div><div>## FWIW, I decided to do another test to see if new threads \
are spawned before the function returns</div><div><br></div><div><div>import os, \
threading</div><div>pid = os.getpid()</div><div>print "loading stage 1", \
pid, threading.active_count()</div>
<div>application = myapp.create_app(CONFIG_FILE, None, log, \
strict=True)</div><div>print "loading stage 2", pid, \
threading.active_count()</div><div><br></div><div>application.logger.setLevel(logging.DEBUG)</div>
<div>for handler in log.logger().handlers:</div><div> \
application.logger.addHandler(handler)</div><div>print "loading stage 3", \
pid, threading.active_count()</div></div><div><br></div><div><br></div><div>and \
get</div>
<div><br></div><div><br></div><div><div>Respawned uWSGI worker 1 (new pid: \
23145)</div><div>worker 2 killed successfully (pid: 22771)</div><div>Respawned uWSGI \
worker 2 (new pid: 23146)</div><div>loading stage 1 23146 1</div>
<div>loading stage 1 23145 1</div><div>loading stage 2 23145 1</div><div>loading \
stage 3 23145 1</div><div>WSGI app 0 (mountpoint='') ready in 1 seconds on \
interpreter 0x2340480 pid: 23145 (default app)</div><div>
loading stage 2 23146 1</div><div>loading stage 3 23146 1</div><div>WSGI app 0 \
(mountpoint='') ready in 1 seconds on interpreter 0x2340480 pid: 23146 \
(default app)</div><div>[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)</div>
</div><div><br></div><div><br></div><div>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) ;)</div>
<div><br></div><div>-Clemens</div><div><br></div><div><br></div><div><br></div><div><br></div><div><br></div></div><div \
class="gmail_extra"><br><br><div class="gmail_quote">On Wed, Apr 9, 2014 at 2:40 AM, \
Roberto De Ioris <span dir="ltr"><<a href="mailto:roberto@unbit.it" \
target="_blank">roberto@unbit.it</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc \
solid;padding-left:1ex"><div class="HOEnZb"><div class="h5"><br> > I modified the \
code as follows:<br> ><br>
> [...]<br>
> print "loading stage 1"<br>
> application = myapp.create_app(CONFIG_FILE, None, log, strict=True)<br>
> print "loading stage 2"<br>
> application.logger.setLevel(logging.DEBUG)<br>
> for handler in log.logger().handlers:<br>
> application.logger.addHandler(handler)<br>
> print "loading stage 3"<br>
><br>
> and get the following logs<br>
><br>
> /usr/bin/uwsgi --ini /etc/uwsgi/apps-enabled/myapp.ini 2>&1 | grep -v<br>
> HTTP.....200<br>
> [uWSGI] getting INI configuration from /etc/uwsgi/apps-enabled/myapp.ini<br>
> *** Starting uWSGI 2.0.3 (64bit) on [Tue Apr 8 18:16:20 2014] ***<br>
> compiled with version: 4.6.3 on 08 April 2014 02:43:31<br>
> os: Linux-3.2.0-60-generic #91-Ubuntu SMP Wed Feb 19 03:54:44 UTC 2014<br>
> nodename: mynode<br>
> machine: x86_64<br>
> clock source: unix<br>
> detected number of CPU cores: 8<br>
> current working directory: /var/log<br>
> detected binary path: /usr/local/bin/uwsgi<br>
> !!! no internal routing support, rebuild with pcre support !!!<br>
> setgid() to 1010<br>
> setuid() to 1002<br>
> your processes number limit is 128020<br>
> your memory page size is 4096 bytes<br>
> detected max file descriptor number: 1024<br>
> lock engine: pthread robust mutexes<br>
> thunder lock: disabled (you can enable it with --thunder-lock)<br>
> uwsgi socket 0 bound to TCP address <a href="http://127.0.0.1:4003" \
target="_blank">127.0.0.1:4003</a> fd 3<br> > Python version: 2.7.3 (default, Feb \
27 2014, 20:09:21) [GCC 4.6.3]<br> > Python main interpreter initialized at \
0x1d5d480<br> > python threads support enabled<br>
> your server socket listen backlog is limited to 100 connections<br>
> your mercy for graceful operations on workers is 60 seconds<br>
> mapped 2503992 bytes (2445 KB) for 150 cores<br>
> *** Operational MODE: preforking+threaded ***<br>
> *** uWSGI is running in multiple interpreter mode ***<br>
> spawned uWSGI master process (pid: 19627)<br>
> spawned uWSGI worker 1 (pid: 19629, cores: 75)<br>
> spawned uWSGI worker 2 (pid: 19630, cores: 75)<br>
> loading stage 1<br>
> loading stage 1<br>
> loading stage 2<br>
> loading stage 2<br>
> loading stage 3<br>
> loading stage 3<br>
><br>
> [...]<br>
><br>
> worker 2 killed successfully (pid: 22063)<br>
> Respawned uWSGI worker 2 (new pid: 22494)<br>
> worker 1 killed successfully (pid: 22064)<br>
> Respawned uWSGI worker 1 (new pid: 22495)<br>
> loading stage 1<br>
> loading stage 1<br>
> loading stage 2<br>
> loading stage 3<br>
> loading stage 2<br>
> WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter \
0x1d5d480<br> > pid:<br>
> 22494 (default app)<br>
> loading stage 3<br>
> WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter \
0x1d5d480<br> > pid:<br>
> 22495 (default app)<br>
><br>
> [...]<br>
><br>
> ...The work of process 22494 is done. Seeya!<br>
> ...The work of process 22495 is done. Seeya!<br>
> worker 2 killed successfully (pid: 22494)<br>
> Respawned uWSGI worker 2 (new pid: 22685)<br>
> worker 1 killed successfully (pid: 22495)<br>
> Respawned uWSGI worker 1 (new pid: 22686)<br>
> loading stage 1<br>
> loading stage 1<br>
> loading stage 2<br>
> loading stage 2<br>
> loading stage 3<br>
> WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter \
0x1d5d480<br> > pid:<br>
> 22686 (default app)<br>
> loading stage 3<br>
> WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter \
0x1d5d480<br> > pid:<br>
> 22685 (default app)<br>
> [pid: 22685|app: 0|req: 3/4660] 192.168.100.11 () {32 vars in 432 bytes}<br>
> [Tue Apr 8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 6<br>
> msecs<br>
> (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 0)<br>
> [pid: 22686|app: 0|req: 16/4665] 192.168.100.11 () {32 vars in 432 bytes}<br>
> [Tue Apr 8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 26<br>
> msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 5)<br>
> [pid: 22686|app: 0|req: 54/4677] 192.168.100.11 () {32 vars in 432 bytes}<br>
> [Tue Apr 8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 56<br>
> msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 7)<br>
> [pid: 22686|app: 0|req: 54/4678] 192.168.100.11 () {32 vars in 432 bytes}<br>
> [Tue Apr 8 18:18:07 2014] GET /myapp/... => generated 238 bytes in 58<br>
> msecs (HTTP/1.1 404) 2 headers in 72 bytes (1 switches on core 1)<br>
><br>
> after this, the logs are empty again - that is, no more 404s for a while<br>
> (note that I grep out the HTTP-200s before and after)<br>
><br>
> thanks!<br>
> -Clemens<br>
><br>
><br>
<br>
</div></div>can you repeat the test printing the process pid (os.getpid()) at \
each<br> line ? in this way we can see if all the stages are executed before the<br>
"readyness" announce<br>
<br>
Thanks<br>
<div class="HOEnZb"><div class="h5"><br>
--<br>
Roberto De Ioris<br>
<a href="http://unbit.it" target="_blank">http://unbit.it</a><br>
_______________________________________________<br>
uWSGI mailing list<br>
<a href="mailto:uWSGI@lists.unbit.it">uWSGI@lists.unbit.it</a><br>
<a href="http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi" \
target="_blank">http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi</a><br> \
</div></div></blockquote></div><br><br clear="all"><div><br></div>-- <br><div \
dir="ltr"><div>Clemens Kolbitsch</div><div>Security Researcher</div><div><a \
href="mailto:kolbitsch@lastline.com" target="_blank">kolbitsch@lastline.com</a></div>
<div>Mobile +1 (206) 356-7745</div><div>Land +1 (805) \
456-7076<br></div><div><br></div><div>Lastline, Inc.</div><div>6950 Hollister Avenue, \
Suite 101</div><div>Goleta, CA 93117</div><div><br></div><div><a \
href="http://www.lastline.com" target="_blank">www.lastline.com</a></div>
</div>
</div>
_______________________________________________
uWSGI mailing list
uWSGI@lists.unbit.it
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic