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

Clemens Kolbitsch kolbitsch at lastline.com
Tue Apr 8 05:01:34 CEST 2014


Hi,

ok, some more tests later, I can still reproduce the problem :( To me it
*feels* like it happens less frequently, but it still happens. More
information about the setup:

# uwsgi --version
2.0.3

# /usr/bin/uwsgi --ini /etc/uwsgi/apps-enabled/myapp.ini
[uWSGI] getting INI configuration from /etc/uwsgi/apps-enabled/myapp.ini
*** Starting uWSGI 2.0.3 (64bit) on [Tue Apr  8 02:54:48 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 0xa4b480
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: 16816)
spawned uWSGI worker 1 (pid: 16828, cores: 75)
spawned uWSGI worker 2 (pid: 16829, cores: 75)
WSGI app 0 (mountpoint='') ready in 2 seconds on interpreter 0xa4b480 pid:
16829 (default app)
WSGI app 0 (mountpoint='') ready in 2 seconds on interpreter 0xa4b480 pid:
16828 (default app)

My config:

[uwsgi]
master      = 1
workers     = 2
threads     = 75
max-requests = 100
listen = 100
socket      = 127.0.0.1:4003
file        = /usr/bin/myapp.wsgi
callable    = application
chdir       = /var/lib/myapp/
uid         = myapp
gid         = myapp_group
lazy        = 1

As a reminder: I am using uwsgi behind nginx (which terminates SSL
connections and does some routing-magic, but other than this) it just
forwards to uwsgi using the following config:

  location /myapp/ {
    include uwsgi_params;
    uwsgi_pass 127.0.0.1:4003;
    uwsgi_read_timeout 150;
  }

In my test-setup, I am using myapp which has multiple Flask endpoints and I
am stress-testing uwsgi with many concurrent requests using

for x in {1..99}; do curl -s -k https://<myip>/myapp/somefunction & done

(as you can see, it's just a parallel curl)

After running it 2-3 times (sequentially - so I don't max out the maximum
listening sockets), I get a 404 instead of an HTTP 200

I'd be happy to provide more details if it helps. Thanks guys!

-Clemens







On Tue, Apr 1, 2014 at 3:17 PM, Roberto De Ioris <roberto at unbit.it> wrote:

>
> > Hi guys,
> >
> > I've been struggling with a weird situation (I have to assume a bug) and
> > cannot find any references to this on the Internet. If you could chime in
> > with some advice, that'd be wonderful :)
> >
> > Please note that this whole situation is related to python-flask, and I
> > have contacted their mailing list to see if anyone has seen this behavior
> > before. They didn't and suggested to see if you guys know more :-/
> >
> > The problem is that I'm not sure at what point uwsgi-plugin-python starts
> > spawning new threads for handling requests. Maybe it's too early and
> > python-flask does some optimizations that result in a bug.
> >
> > Here is the situation: We host a web-service through nginx, serving
> > requests to uwsgi-plugin-python (version 1.0.3+dfsg-1ubuntu0.1) to our
> > nice
> > Python (2.7.3) flask app. Since we had garbage-collection issues with
> many
> > small objects on the heap in the past, we decided to respawn the uwsgi
> > service every few k requests and use multiple processes to avoid a
> > down-time in the respawn phase (and every process has multiple threads of
> > course).
> >
> > Another important note is that we use the "lazy" option, because we use
> > MySQL connections which cannot be forked after Python initialization
> > (because all DB connections would share the same connection ID, which is
> > not supported by the MySQL client).
> >
> > Now, it seems like each time the Python process respawns, that flask sets
> > up our blueprints (mappings between Python handlers and URLs in case
> > you're
> > not familiar with flask) and then starts accepting requests, but
> > *sometimes* responds with a 404 to clients early during this phase. This
> > happens very rarely, but since there is considerable load on the server,
> > it
> > actually starts adding up so that we need to something about it.
> >
> > I have spent quite some time debugging the flask blueprints, and my
> > findings - so far - show that at app creation time, only one thread is
> > running in Python *after* the blueprints have been registered. However,
> > when I add code to log details about the blueprints / URL-rules when the
> > 404 happens, then the blueprints are not all/fully loaded yet.
> >
> > It seems to me like new threads are created and start accepting
> > connections
> > before all blueprints/rules have been fully registered. Here is some code
> > to show what I mean:
> >
> > def create_app(...):
> >     app = flask.Flask(__name__)
> >     [...]
> >
> >     @app.after_request
> >     def after_request(response):
> >         if response.status_code == 404:
> >             # DBG2
> >             print 'dbg', response.status_code, request.base_url
> >             print threading.active_count(), "active threads"
> >             print app.url_map.__dict__.get('foo/mytesturl')
> >         return response
> >
> >     app.register_blueprint(mymodel, url_prefix="/foo")
> >     # DBG1
> >     print 'done loading', app.url_map.__dict__
> >     print threading.active_count(), "active threads"
> >     return app
> >
> > While the DBG1 code shows everything correctly, the DBG2 code shows a
> > sub-set of my URL-handlers (which is why the 404 gets executed).
> >
> > BTW, at DBG1 point, the logs usually show "1 active threads", while at
> > DBG2
> > many more threads are loaded, making me assume there is some sort of
> > lazy/on-demand loading of the rules within flask.
> >
> > Again, the code works, it's just that there is this race where I get
> 404s.
> >
> > Is this a known bug in uwsgi / uwsgi-plugin-python? If so, it'd be worth
> > investigating on a newer version, or is there a specific way to tell
> flask
> > to fully load all blueprints/rules before accepting connections?
> >
> > Sorry for the overly long email, I wanted to get all the details right :)
> >
> > Thanks!
> > -Clemens
> >
> > --
> > 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
> >
> >
>
> Hi Clemens, sorry but uWSGI 1.0 is unsupported since 2012 and know to be
> broken (as well as 1.2). Only 1.4.x and 2.0.x are supported and actively
> maintained.
>
> Upgrade to a stable version, and if you still have problems feel free to
> repost.
>
>
> --
> 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/20140407/676b334a/attachment.html>


More information about the uWSGI mailing list