[uWSGI] When the backlog is full, is uwsgi supposed to accept connections?

[Francois Gaudin]

Hi,

we ran into an issue a few weeks ago and I don't know if it's an expected
behavior or not.

Short version: uwsgi still accepts connections even when the backlog is
full. Is it normal? If it is, is there a way to refuse connection once it's
full?

Long version: we have several instances on Heroku serving our python app
with uwsgi. Their load-balancer has the following routing algorithm:


1. Accept a new request for the app
2. Look up the list of web dynos (instance name on Heroku) for the app
3. Randomly select a dyno from that list
4. Attempt to open a connection to that dyno's IP and port
5. If the connection was successful, proxy the request to the dyno, and
proxy the response back to the client
6. If it takes more than 30 seconds, the request is killed.


If a wsgi worker get stale, the backlog quickly fills up and then it
shouldn't accept the connection to let the router know that it should route
the requests to another dyno. The problem is that it doesn't and all the
traffic going to a stale dyno/worker will get killed eventually.

I've managed to reproduce the behavior locally.

Thanks

[Roberto De Ioris]

Post by Francois Gaudin
Hi,
we ran into an issue a few weeks ago and I don't know if it's an expected
behavior or not.
Short version: uwsgi still accepts connections even when the backlog is
full. Is it normal? If it is, is there a way to refuse connection once it's
full?
Long version: we have several instances on Heroku serving our python app
1. Accept a new request for the app
2. Look up the list of web dynos (instance name on Heroku) for the app
3. Randomly select a dyno from that list
4. Attempt to open a connection to that dyno's IP and port
5. If the connection was successful, proxy the request to the dyno, and
proxy the response back to the client
6. If it takes more than 30 seconds, the request is killed.
If a wsgi worker get stale, the backlog quickly fills up and then it
shouldn't accept the connection to let the router know that it should route
the requests to another dyno. The problem is that it doesn't and all the
traffic going to a stale dyno/worker will get killed eventually.
I've managed to reproduce the behavior locally.
Thanks

It is hard to say, but if the check is only an open/close connection
without sending data, the deferred accept
(http://www.techrepublic.com/article/take-advantage-of-tcp-ip-options-to-optimize-data-transmission/)
could fake the proxy:

--no-defer-accept

will disable it

On the other side if you are using --http instead of --http-socket (it is
a common error) the http proxy is able to accept tons more connections
than workers, so again this could cause the problem.

[Francois Gaudin]

Thanks Roberto,

I've checked, we already use --http-socket.

I've just tried the --no-defer-accept option locally, it doesn't change
anything.

What I do to test:

$ uwsgi --http :9090 --wsgi-file test.py --single-interpreter --master
--die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri 28 -l 3
--no-defer-accept

test.py:

import time

def application(env, start_response):
start_response('200 OK', [('Content-Type','text/html')])
time.sleep(25)
return ["Hello World"]

Then I do a bunch of curl:

$ curl localhost:9090 -v

And I get the expected:

Tue Aug 19 10:57:31 2014 - *** uWSGI listen queue of socket "127.0.0.1:43920"
(fd: 3) full !!! (4/3) ***

And to be sure that curl is not doing weird things (like auto retrying the
tcp connection), I test with telnet to see if I'm rejected right away:

$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1

Connection closed by foreign host.

real 1m7.567s
user 0m0.005s
sys 0m0.003s

The load-balancer would expect to be rejected right away at that point.

Thus, what is the backlog for if uwsgi still accepts connections once it's
full? Just a warning?

Also, I've seen an email from you mentioning that using sleep() in a test
wasn't faking the right behavior, so I'm not sure in my case if it's the
right way to fill the backlog.

Cheers

Post by Roberto De Ioris

Post by Francois Gaudin
Hi,
we ran into an issue a few weeks ago and I don't know if it's an expected
behavior or not.
Short version: uwsgi still accepts connections even when the backlog is
full. Is it normal? If it is, is there a way to refuse connection once it's
full?
Long version: we have several instances on Heroku serving our python app
1. Accept a new request for the app
2. Look up the list of web dynos (instance name on Heroku) for the app
3. Randomly select a dyno from that list
4. Attempt to open a connection to that dyno's IP and port
5. If the connection was successful, proxy the request to the dyno,

and

Post by Francois Gaudin
proxy the response back to the client
6. If it takes more than 30 seconds, the request is killed.
If a wsgi worker get stale, the backlog quickly fills up and then it
shouldn't accept the connection to let the router know that it should route
the requests to another dyno. The problem is that it doesn't and all the
traffic going to a stale dyno/worker will get killed eventually.
I've managed to reproduce the behavior locally.
Thanks

It is hard to say, but if the check is only an open/close connection
without sending data, the deferred accept
(
http://www.techrepublic.com/article/take-advantage-of-tcp-ip-options-to-optimize-data-transmission/
)
--no-defer-accept
will disable it
On the other side if you are using --http instead of --http-socket (it is
a common error) the http proxy is able to accept tons more connections
than workers, so again this could cause the problem.
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
Thanks Roberto,
I've checked, we already use --http-socket.
I've just tried the --no-defer-accept option locally, it doesn't change
anything.
$ uwsgi --http :9090 --wsgi-file test.py --single-interpreter --master
--die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri 28 -l 3
--no-defer-accept

i have told you that http-socket is different from http, and here you test
with http :)

http is a non-blocking proxy, it will continue to accept until it has free
file descriptors.

You need to test with --http-socket with and without --no-defer-accept

[Francois Gaudin]

My bad, we use http-socket in prod and for some reason I put http locally
and checked only our prod settings.

Try again...

With no-defer-accept:

$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3 --no-defer-accept

$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1

HTTP/1.1 200 OK
Content-Type: text/html

Hello WorldConnection closed by foreign host.

real 2m22.434s
user 0m0.003s
sys 0m0.006s

All requests responded (waiting as long as necessary) except one which
ended with:

curl: (56) Recv failure: Connection reset by peer

after 1min46


Without --no-defer-accept:

$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3

$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1

Connection closed by foreign host.

real 1m17.867s
user 0m0.000s
sys 0m0.008s

and worked another time:

$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1

HTTP/1.1 200 OK
Content-Type: text/html

Hello WorldConnection closed by foreign host.

real 1m59.701s
user 0m0.000s
sys 0m0.004s


So either way, uwsgi still accepts the connection.

Post by Roberto De Ioris

Post by Francois Gaudin
Thanks Roberto,
I've checked, we already use --http-socket.
I've just tried the --no-defer-accept option locally, it doesn't change
anything.
$ uwsgi --http :9090 --wsgi-file test.py --single-interpreter --master
--die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri 28 -l 3
--no-defer-accept

i have told you that http-socket is different from http, and here you test
with http :)
http is a non-blocking proxy, it will continue to accept until it has free
file descriptors.
You need to test with --http-socket with and without --no-defer-accept
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
My bad, we use http-socket in prod and for some reason I put http locally
and checked only our prod settings.
Try again...
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3 --no-defer-accept
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 2m22.434s
user 0m0.003s
sys 0m0.006s
All requests responded (waiting as long as necessary) except one which
curl: (56) Recv failure: Connection reset by peer
after 1min46
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
Connection closed by foreign host.
real 1m17.867s
user 0m0.000s
sys 0m0.008s
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 1m59.701s
user 0m0.000s
sys 0m0.004s
So either way, uwsgi still accepts the connection.

I fear you are testing in the wrong way. What you describe is basically
impossible, event with defer-accept the amount of manageable connections
is always limited (by the kernel memory).

With defer-accept you tell the kernel to pass the request to the socket
until a packet arrives, without defer-accept the connection (if there are
slots in the listen queue) the request is passed to the socket and first
free worker accept() it.

Best way, would be attaching a strace to the worker before running the
test (in uWSGI only workers accept() requests, there is no arbitrer or
similar, unless you add a proxy)

You should:

spawn a single worker with --http-socket and listen queue of 2 and strace
it, open at least 10 curl requests (the listen queue size is not precise
for various reasons, there are generally a couple more slots allocated) to
the app (the should generate a loop). Open a telnet session, without
defer-accept the connection should timeout or close (based on kernel
settings)

[Francois Gaudin]

Thanks for taking the time to help.

Except the strace and the listen queue size, I don't see the difference
with what I'm doing so I don't understand what I'm doing wrong.

But basically, are you saying that whatever I do, I won't get a connection
refused when the queue is full? Or it may depend on the kernel settings,
which will either make it timeout after a while or close it right away, or
just succeed sometimes as my test shows it?

So here is the new test pretty close to what I was doing:

$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2

startup logs:

*** Starting uWSGI 2.0.6 (64bit) on [Tue Aug 19 14:14:15 2014] ***
compiled with version: 4.8.1 on 18 August 2014 15:19:17
os: Linux-3.11.0-20-generic #35-Ubuntu SMP Fri May 2 21:32:49 UTC 2014
nodename: ptfga
machine: x86_64
clock source: unix
detected number of CPU cores: 4
current working directory: /home/fga/tmp
detected binary path: /home/fga/tmp/testenv/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 30632
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
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :9090 fd 3
Python version: 2.7.5+ (default, Feb 27 2014, 19:40:54) [GCC 4.8.1]
Set PythonHome to /home/fga/tmp/testenv
*** Python threads support is disabled. You can enable it with
--enable-threads ***
Python main interpreter initialized at 0x1641f80
your server socket listen backlog is limited to 2 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145536 bytes (142 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1641f80 pid:
21370 (default app)
spawned uWSGI master process (pid: 21370)
spawned uWSGI worker 1 (pid: 21371, cores: 1)

before launching the test, it loops as you said:

$ sudo strace -s 2000 -p 21370 -p 21371
Process 21370 attached
Process 21371 attached
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0x\v=\7\0\0\0\0x\v=\7x\v=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0`\17=\7\0\0\0\0`\17=\7`\17=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0H\23=\7\0\0\0\0H\23=\7H\23=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0

my test script is now:

import time, random

def application(env, start_response):
thread_id = random.randint(1, 1000)
start_response('200 OK', [('Content-Type','text/html')])
for i in range(10):
print 'sleeping (%d)' % (thread_id)
time.sleep(5)
return ["Hello World (%d)" % (thread_id)]

Launching 11 curl requests in parallel, logs show:

sleeping (302)
Tue Aug 19 14:21:30 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:31 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:32 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:33 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:34 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:35 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:36 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:37 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:38 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:39 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:40 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:41 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:42 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[ ... ]
Tue Aug 19 14:22:15 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:16 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:17 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[pid: 21371|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 247 bytes} [Tue Aug
19 14:21:28 2014] GET / => generated 17 bytes in 50047 msecs (HTTP/1.1 200)
1 headers in 44 bytes (1 switches on core 0)
sleeping (63)
Tue Aug 19 14:22:18 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:19 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:20 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:21 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:22 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
sleeping (63)
Tue Aug 19 14:22:23 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:24 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***


*When I do the telnet, I don't notice anything:*

pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\375J\7\0\0\0\0T\375J\7T\375J\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:19 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0<\1K\7\0\0\0\0<\1K\7<\1K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:20 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0$\5K\7\0\0\0\0$\5K\7$\5K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:21 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\tK\7\0\0\0\0\20\tK\7\20\tK\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:22 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\370\fK\7\0\0\0\0\370\fK\7\370\fK\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:23 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\340\20K\7\0\0\0\0\340\20K\7\340\20K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:24 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\310\24K\7\0\0\0\0\310\24K\7\310\24K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:25 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\264\30K\7\0\0\0\0\264\30K\7\264\30K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:26 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\234\34K\7\0\0\0\0\234\34K\7\234\34K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:27 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0

*Then at some point, it accepts the telnet connection:*

[pid 21371] epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
[pid 21371] accept4(3, {sa_family=AF_INET, sin_port=htons(59113),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
[pid 21371] read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
[pid 21371] write(1, "sleeping (43)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\270\206M\7\0\0\0\0\270\206M\7\270\206M\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0


*Eventually, the telnet request returned, successfully this time:*

time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1

HTTP/1.1 200 OK
Content-Type: text/html

Hello World (43)Connection closed by foreign host.

real 3m49.293s
user 0m0.002s
sys 0m0.003s


[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0dFN\7\0\0\0\0dFN\7dFN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type:
text/html\r\n\r\n", 44}, {"Hello World (43)", 16}], 2) = 60
[pid 21371] close(6) = 0
[pid 21371] writev(2, [{"[pid: 21371|app: 0|req: 9/9] 127.0.0.1 () {18 vars
in 180 bytes} [Tue Aug 19 14:37:04 2014] GET /test => generated 16 bytes in
50032 msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
199}], 1) = 199
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0PJN\7\0\0\0\0PJN\7PJN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
"\n\0\0\0\0\0\0\***@B\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0008NN\7\0\0\0\0008NN\0078NN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0

Post by Roberto De Ioris

Post by Francois Gaudin
My bad, we use http-socket in prod and for some reason I put http locally
and checked only our prod settings.
Try again...
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3 --no-defer-accept
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 2m22.434s
user 0m0.003s
sys 0m0.006s
All requests responded (waiting as long as necessary) except one which
curl: (56) Recv failure: Connection reset by peer
after 1min46
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
Connection closed by foreign host.
real 1m17.867s
user 0m0.000s
sys 0m0.008s
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 1m59.701s
user 0m0.000s
sys 0m0.004s
So either way, uwsgi still accepts the connection.

I fear you are testing in the wrong way. What you describe is basically
impossible, event with defer-accept the amount of manageable connections
is always limited (by the kernel memory).
With defer-accept you tell the kernel to pass the request to the socket
until a packet arrives, without defer-accept the connection (if there are
slots in the listen queue) the request is passed to the socket and first
free worker accept() it.
Best way, would be attaching a strace to the worker before running the
test (in uWSGI only workers accept() requests, there is no arbitrer or
similar, unless you add a proxy)
spawn a single worker with --http-socket and listen queue of 2 and strace
it, open at least 10 curl requests (the listen queue size is not precise
for various reasons, there are generally a couple more slots allocated) to
the app (the should generate a loop). Open a telnet session, without
defer-accept the connection should timeout or close (based on kernel
settings)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[INADA Naoki]

What is the TCP status for telnet while waiting connection?
If SYN_SENT, telnet has very long connection timeout.
If ESTABLISHED, uWSGI sent ACK for SYN.

Post by Francois Gaudin
Thanks for taking the time to help.
Except the strace and the listen queue size, I don't see the difference with
what I'm doing so I don't understand what I'm doing wrong.
But basically, are you saying that whatever I do, I won't get a connection
refused when the queue is full? Or it may depend on the kernel settings,
which will either make it timeout after a while or close it right away, or
just succeed sometimes as my test shows it?
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2
*** Starting uWSGI 2.0.6 (64bit) on [Tue Aug 19 14:14:15 2014] ***
compiled with version: 4.8.1 on 18 August 2014 15:19:17
os: Linux-3.11.0-20-generic #35-Ubuntu SMP Fri May 2 21:32:49 UTC 2014
nodename: ptfga
machine: x86_64
clock source: unix
detected number of CPU cores: 4
current working directory: /home/fga/tmp
detected binary path: /home/fga/tmp/testenv/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 30632
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
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :9090 fd 3
Python version: 2.7.5+ (default, Feb 27 2014, 19:40:54) [GCC 4.8.1]
Set PythonHome to /home/fga/tmp/testenv
*** Python threads support is disabled. You can enable it with
--enable-threads ***
Python main interpreter initialized at 0x1641f80
your server socket listen backlog is limited to 2 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145536 bytes (142 KB) for 1 cores
*** Operational MODE: single process ***
21370 (default app)
spawned uWSGI master process (pid: 21370)
spawned uWSGI worker 1 (pid: 21371, cores: 1)
$ sudo strace -s 2000 -p 21370 -p 21371
Process 21370 attached
Process 21371 attached
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
import time, random
thread_id = random.randint(1, 1000)
start_response('200 OK', [('Content-Type','text/html')])
print 'sleeping (%d)' % (thread_id)
time.sleep(5)
return ["Hello World (%d)" % (thread_id)]
sleeping (302)
Tue Aug 19 14:21:30 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:31 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:32 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:33 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:34 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:35 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:36 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:37 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:38 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:39 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:40 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:41 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:42 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[ ... ]
Tue Aug 19 14:22:15 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:16 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:17 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[pid: 21371|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 247 bytes} [Tue Aug 19
14:21:28 2014] GET / => generated 17 bytes in 50047 msecs (HTTP/1.1 200) 1
headers in 44 bytes (1 switches on core 0)
sleeping (63)
Tue Aug 19 14:22:18 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:19 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:20 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:21 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:22 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
sleeping (63)
Tue Aug 19 14:22:23 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:24 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:19 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:20 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:21 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:22 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:23 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:24 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:25 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:26 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:27 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21371] epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
[pid 21371] accept4(3, {sa_family=AF_INET, sin_port=htons(59113),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
[pid 21371] read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
[pid 21371] write(1, "sleeping (43)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello World (43)Connection closed by foreign host.
real 3m49.293s
user 0m0.002s
sys 0m0.003s
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
text/html\r\n\r\n", 44}, {"Hello World (43)", 16}], 2) = 60
[pid 21371] close(6) = 0
[pid 21371] writev(2, [{"[pid: 21371|app: 0|req: 9/9] 127.0.0.1 () {18 vars
in 180 bytes} [Tue Aug 19 14:37:04 2014] GET /test => generated 16 bytes in
50032 msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
199}], 1) = 199
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0

Post by Roberto De Ioris

Post by Francois Gaudin
My bad, we use http-socket in prod and for some reason I put http locally
and checked only our prod settings.
Try again...
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3 --no-defer-accept
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 2m22.434s
user 0m0.003s
sys 0m0.006s
All requests responded (waiting as long as necessary) except one which
curl: (56) Recv failure: Connection reset by peer
after 1min46
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
Connection closed by foreign host.
real 1m17.867s
user 0m0.000s
sys 0m0.008s
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 1m59.701s
user 0m0.000s
sys 0m0.004s
So either way, uwsgi still accepts the connection.

I fear you are testing in the wrong way. What you describe is basically
impossible, event with defer-accept the amount of manageable connections
is always limited (by the kernel memory).
With defer-accept you tell the kernel to pass the request to the socket
until a packet arrives, without defer-accept the connection (if there are
slots in the listen queue) the request is passed to the socket and first
free worker accept() it.
Best way, would be attaching a strace to the worker before running the
test (in uWSGI only workers accept() requests, there is no arbitrer or
similar, unless you add a proxy)
spawn a single worker with --http-socket and listen queue of 2 and strace
it, open at least 10 curl requests (the listen queue size is not precise
for various reasons, there are generally a couple more slots allocated) to
the app (the should generate a loop). Open a telnet session, without
defer-accept the connection should timeout or close (based on kernel
settings)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

--
Francois
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Francois Gaudin]

tcp 0 0 localhost:33839 localhost:9090
ESTABLISHED fga 1833136 28433/telnet

Post by INADA Naoki
What is the TCP status for telnet while waiting connection?
If SYN_SENT, telnet has very long connection timeout.
If ESTABLISHED, uWSGI sent ACK for SYN.

Post by Francois Gaudin
Thanks for taking the time to help.
Except the strace and the listen queue size, I don't see the difference

with

Post by Francois Gaudin
what I'm doing so I don't understand what I'm doing wrong.
But basically, are you saying that whatever I do, I won't get a

connection

Post by Francois Gaudin
refused when the queue is full? Or it may depend on the kernel settings,
which will either make it timeout after a while or close it right away,

or

Post by Francois Gaudin
just succeed sometimes as my test shows it?
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2
*** Starting uWSGI 2.0.6 (64bit) on [Tue Aug 19 14:14:15 2014] ***
compiled with version: 4.8.1 on 18 August 2014 15:19:17
os: Linux-3.11.0-20-generic #35-Ubuntu SMP Fri May 2 21:32:49 UTC 2014
nodename: ptfga
machine: x86_64
clock source: unix
detected number of CPU cores: 4
current working directory: /home/fga/tmp
detected binary path: /home/fga/tmp/testenv/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 30632
your memory page size is 4096 bytes
*** WARNING: you have enabled harakiri without post buffering. Slow

upload

Post by Francois Gaudin
could be rejected on post-unbuffered webservers ***
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 :9090 fd 3
Python version: 2.7.5+ (default, Feb 27 2014, 19:40:54) [GCC 4.8.1]
Set PythonHome to /home/fga/tmp/testenv
*** Python threads support is disabled. You can enable it with
--enable-threads ***
Python main interpreter initialized at 0x1641f80
your server socket listen backlog is limited to 2 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145536 bytes (142 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x1641f80
21370 (default app)
spawned uWSGI master process (pid: 21370)
spawned uWSGI worker 1 (pid: 21371, cores: 1)
$ sudo strace -s 2000 -p 21370 -p 21371
Process 21370 attached
Process 21371 attached
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0x\v=\7\0\0\0\0x\v=\7x\v=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0`\17=\7\0\0\0\0`\17=\7`\17=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0H\23=\7\0\0\0\0H\23=\7H\23=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
import time, random
thread_id = random.randint(1, 1000)
start_response('200 OK', [('Content-Type','text/html')])
print 'sleeping (%d)' % (thread_id)
time.sleep(5)
return ["Hello World (%d)" % (thread_id)]
sleeping (302)

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***
sleeping (302)

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***
sleeping (302)

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***
[ ... ]

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***

3)

Post by Francois Gaudin
full !!! (3/2) ***
[pid: 21371|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 247 bytes} [Tue

Aug 19

Post by Francois Gaudin
14:21:28 2014] GET / => generated 17 bytes in 50047 msecs (HTTP/1.1 200)

1

Post by Francois Gaudin
headers in 44 bytes (1 switches on core 0)
sleeping (63)

3)

Post by Francois Gaudin
full !!! (2/2) ***

3)

Post by Francois Gaudin
full !!! (2/2) ***

3)

Post by Francois Gaudin
full !!! (2/2) ***

3)

Post by Francois Gaudin
full !!! (2/2) ***

3)

Post by Francois Gaudin
full !!! (2/2) ***
sleeping (63)

3)

Post by Francois Gaudin
full !!! (2/2) ***

3)

Post by Francois Gaudin
full !!! (2/2) ***
pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\375J\7\0\0\0\0T\375J\7T\375J\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:19 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0<\1K\7\0\0\0\0<\1K\7<\1K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:20 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0$\5K\7\0\0\0\0$\5K\7$\5K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:21 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\tK\7\0\0\0\0\20\tK\7\20\tK\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:22 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\370\fK\7\0\0\0\0\370\fK\7\370\fK\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:23 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\340\20K\7\0\0\0\0\340\20K\7\340\20K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:24 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\310\24K\7\0\0\0\0\310\24K\7\310\24K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:25 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\264\30K\7\0\0\0\0\264\30K\7\264\30K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:26 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\234\34K\7\0\0\0\0\234\34K\7\234\34K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:27 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21371] epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
[pid 21371] accept4(3, {sa_family=AF_INET, sin_port=htons(59113),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
[pid 21371] read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
[pid 21371] write(1, "sleeping (43)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\270\206M\7\0\0\0\0\270\206M\7\270\206M\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello World (43)Connection closed by foreign host.
real 3m49.293s
user 0m0.002s
sys 0m0.003s
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0dFN\7\0\0\0\0dFN\7dFN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
text/html\r\n\r\n", 44}, {"Hello World (43)", 16}], 2) = 60
[pid 21371] close(6) = 0
[pid 21371] writev(2, [{"[pid: 21371|app: 0|req: 9/9] 127.0.0.1 () {18

vars

Post by Francois Gaudin
in 180 bytes} [Tue Aug 19 14:37:04 2014] GET /test => generated 16 bytes

in

Post by Francois Gaudin
50032 msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core

0)\n",

Post by Francois Gaudin
199}], 1) = 199
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0PJN\7\0\0\0\0PJN\7PJN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0008NN\7\0\0\0\0008NN\0078NN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0

Post by Roberto De Ioris

Post by Francois Gaudin
My bad, we use http-socket in prod and for some reason I put http locally
and checked only our prod settings.
Try again...
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3 --no-defer-accept
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 2m22.434s
user 0m0.003s
sys 0m0.006s
All requests responded (waiting as long as necessary) except one which
curl: (56) Recv failure: Connection reset by peer
after 1min46
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --enable-threads --pyhome ~/tmp/testenv --harakiri
28 -l 3
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
Connection closed by foreign host.
real 1m17.867s
user 0m0.000s
sys 0m0.008s
$ time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello WorldConnection closed by foreign host.
real 1m59.701s
user 0m0.000s
sys 0m0.004s
So either way, uwsgi still accepts the connection.

I fear you are testing in the wrong way. What you describe is basically
impossible, event with defer-accept the amount of manageable connections
is always limited (by the kernel memory).
With defer-accept you tell the kernel to pass the request to the socket
until a packet arrives, without defer-accept the connection (if there

are

Post by Francois Gaudin

Post by Roberto De Ioris
slots in the listen queue) the request is passed to the socket and first
free worker accept() it.
Best way, would be attaching a strace to the worker before running the
test (in uWSGI only workers accept() requests, there is no arbitrer or
similar, unless you add a proxy)
spawn a single worker with --http-socket and listen queue of 2 and

strace

Post by Francois Gaudin

Post by Roberto De Ioris
it, open at least 10 curl requests (the listen queue size is not precise
for various reasons, there are generally a couple more slots allocated)

to

Post by Francois Gaudin

Post by Roberto De Ioris
the app (the should generate a loop). Open a telnet session, without
defer-accept the connection should timeout or close (based on kernel
settings)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

--
Francois
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

--
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
Thanks for taking the time to help.
Except the strace and the listen queue size, I don't see the difference
with what I'm doing so I don't understand what I'm doing wrong.
But basically, are you saying that whatever I do, I won't get a connection
refused when the queue is full? Or it may depend on the kernel settings,
which will either make it timeout after a while or close it right away, or
just succeed sometimes as my test shows it?
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2
*** Starting uWSGI 2.0.6 (64bit) on [Tue Aug 19 14:14:15 2014] ***
compiled with version: 4.8.1 on 18 August 2014 15:19:17
os: Linux-3.11.0-20-generic #35-Ubuntu SMP Fri May 2 21:32:49 UTC 2014
nodename: ptfga
machine: x86_64
clock source: unix
detected number of CPU cores: 4
current working directory: /home/fga/tmp
detected binary path: /home/fga/tmp/testenv/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 30632
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
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :9090 fd 3
Python version: 2.7.5+ (default, Feb 27 2014, 19:40:54) [GCC 4.8.1]
Set PythonHome to /home/fga/tmp/testenv
*** Python threads support is disabled. You can enable it with
--enable-threads ***
Python main interpreter initialized at 0x1641f80
your server socket listen backlog is limited to 2 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145536 bytes (142 KB) for 1 cores
*** Operational MODE: single process ***
21370 (default app)
spawned uWSGI master process (pid: 21370)
spawned uWSGI worker 1 (pid: 21371, cores: 1)
$ sudo strace -s 2000 -p 21370 -p 21371
Process 21370 attached
Process 21371 attached
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
import time, random
thread_id = random.randint(1, 1000)
start_response('200 OK', [('Content-Type','text/html')])
print 'sleeping (%d)' % (thread_id)
time.sleep(5)
return ["Hello World (%d)" % (thread_id)]
sleeping (302)
Tue Aug 19 14:21:30 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:31 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:32 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:33 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:34 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:35 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:36 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:37 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:38 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:39 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:40 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:41 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:42 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[ ... ]
Tue Aug 19 14:22:15 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:16 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:17 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[pid: 21371|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 247 bytes} [Tue Aug
19 14:21:28 2014] GET / => generated 17 bytes in 50047 msecs (HTTP/1.1 200)
1 headers in 44 bytes (1 switches on core 0)
sleeping (63)
Tue Aug 19 14:22:18 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:19 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:20 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:21 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:22 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
sleeping (63)
Tue Aug 19 14:22:23 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:24 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
*When I do the telnet, I don't notice anything:*
pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:19 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:20 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:21 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:22 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:23 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:24 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:25 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:26 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:27 2014 - *** uWSGI listen queue of
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
*Then at some point, it accepts the telnet connection:*
[pid 21371] epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
[pid 21371] accept4(3, {sa_family=AF_INET, sin_port=htons(59113),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
[pid 21371] read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
[pid 21371] write(1, "sleeping (43)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
*Eventually, the telnet request returned, successfully this time:*
time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello World (43)Connection closed by foreign host.
real 3m49.293s
user 0m0.002s
sys 0m0.003s
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
text/html\r\n\r\n", 44}, {"Hello World (43)", 16}], 2) = 60
[pid 21371] close(6) = 0
[pid 21371] writev(2, [{"[pid: 21371|app: 0|req: 9/9] 127.0.0.1 () {18 vars
in 180 bytes} [Tue Aug 19 14:37:04 2014] GET /test => generated 16 bytes in
50032 msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
199}], 1) = 199
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0

this is teh strace of the master, you have to strace the worker, as it is
the one calling accept()

[Francois Gaudin]

Sometimes it works, like the following trace, and I get the accept(),
sometimes I get "Connection closed by foreign host."

Last one is the telnet

epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34071),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
read(6, "GET / HTTP/1.1\r\nUser-Agent: curl/7.32.0\r\nHost:
localhost:9090\r\nAccept: */*\r\n\r\n", 4096) = 78
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (314)", 17}], 2) = 61
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 14/14] 127.0.0.1 () {24 vars in 247
bytes} [Tue Aug 19 23:31:17 2014] GET / => generated 17 bytes in 30027
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
197}], 1) = 197
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34072),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
read(6, "GET / HTTP/1.1\r\nUser-Agent: curl/7.32.0\r\nHost:
localhost:9090\r\nAccept: */*\r\n\r\n", 4096) = 78
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (74)", 16}], 2) = 60
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 15/15] 127.0.0.1 () {24 vars in 247
bytes} [Tue Aug 19 23:31:48 2014] GET / => generated 16 bytes in 30022
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
197}], 1) = 197
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34080),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (79)", 16}], 2) = 60
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 16/16] 127.0.0.1 () {18 vars in 180
bytes} [Tue Aug 19 23:32:18 2014] GET /test => generated 16 bytes in 30031
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
201}], 1) = 201
epoll_wait(4,

Post by Francois Gaudin

Post by Francois Gaudin
Thanks for taking the time to help.
Except the strace and the listen queue size, I don't see the difference
with what I'm doing so I don't understand what I'm doing wrong.
But basically, are you saying that whatever I do, I won't get a

connection

Post by Francois Gaudin
refused when the queue is full? Or it may depend on the kernel settings,
which will either make it timeout after a while or close it right away,

or

Post by Francois Gaudin
just succeed sometimes as my test shows it?
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2
*** Starting uWSGI 2.0.6 (64bit) on [Tue Aug 19 14:14:15 2014] ***
compiled with version: 4.8.1 on 18 August 2014 15:19:17
os: Linux-3.11.0-20-generic #35-Ubuntu SMP Fri May 2 21:32:49 UTC 2014
nodename: ptfga
machine: x86_64
clock source: unix
detected number of CPU cores: 4
current working directory: /home/fga/tmp
detected binary path: /home/fga/tmp/testenv/bin/uwsgi
!!! no internal routing support, rebuild with pcre support !!!
your processes number limit is 30632
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
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :9090 fd 3
Python version: 2.7.5+ (default, Feb 27 2014, 19:40:54) [GCC 4.8.1]
Set PythonHome to /home/fga/tmp/testenv
*** Python threads support is disabled. You can enable it with
--enable-threads ***
Python main interpreter initialized at 0x1641f80
your server socket listen backlog is limited to 2 connections
your mercy for graceful operations on workers is 60 seconds
mapped 145536 bytes (142 KB) for 1 cores
*** Operational MODE: single process ***
21370 (default app)
spawned uWSGI master process (pid: 21370)
spawned uWSGI worker 1 (pid: 21371, cores: 1)
$ sudo strace -s 2000 -p 21370 -p 21371
Process 21370 attached
Process 21371 attached
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0x\v=\7\0\0\0\0x\v=\7x\v=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0`\17=\7\0\0\0\0`\17=\7`\17=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0H\23=\7\0\0\0\0H\23=\7H\23=\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
import time, random
thread_id = random.randint(1, 1000)
start_response('200 OK', [('Content-Type','text/html')])
print 'sleeping (%d)' % (thread_id)
time.sleep(5)
return ["Hello World (%d)" % (thread_id)]
sleeping (302)
Tue Aug 19 14:21:30 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:31 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:32 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:33 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:34 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:35 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:36 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:37 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
sleeping (302)
Tue Aug 19 14:21:38 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:39 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:40 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:41 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:21:42 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[ ... ]
Tue Aug 19 14:22:15 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:16 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
Tue Aug 19 14:22:17 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (3/2) ***
[pid: 21371|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 247 bytes} [Tue Aug
19 14:21:28 2014] GET / => generated 17 bytes in 50047 msecs (HTTP/1.1 200)
1 headers in 44 bytes (1 switches on core 0)
sleeping (63)
Tue Aug 19 14:22:18 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:19 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:20 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:21 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:22 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
sleeping (63)
Tue Aug 19 14:22:23 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
Tue Aug 19 14:22:24 2014 - *** uWSGI listen queue of socket ":9090" (fd: 3)
full !!! (2/2) ***
*When I do the telnet, I don't notice anything:*
pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\375J\7\0\0\0\0T\375J\7T\375J\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:19 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0<\1K\7\0\0\0\0<\1K\7<\1K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:20 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0$\5K\7\0\0\0\0$\5K\7$\5K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:21 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\20\tK\7\0\0\0\0\20\tK\7\20\tK\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:22 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\370\fK\7\0\0\0\0\370\fK\7\370\fK\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:23 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\340\20K\7\0\0\0\0\340\20K\7\340\20K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:24 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
[pid 21371] write(1, "sleeping (14)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\310\24K\7\0\0\0\0\310\24K\7\310\24K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:25 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\264\30K\7\0\0\0\0\264\30K\7\264\30K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:26 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\3\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\234\34K\7\0\0\0\0\234\34K\7\234\34K\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] write(2, "Tue Aug 19 14:34:27 2014 - *** uWSGI listen queue

of

Post by Francois Gaudin
socket \":9090\" (fd: 3) full !!! (3/2) ***\n", 95) = 95
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
*Then at some point, it accepts the telnet connection:*
[pid 21371] epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
[pid 21371] accept4(3, {sa_family=AF_INET, sin_port=htons(59113),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
[pid 21371] read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
[pid 21371] write(1, "sleeping (43)\n", 14) = 14
[pid 21371] select(0, NULL, NULL, NULL, {5, 0} <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\270\206M\7\0\0\0\0\270\206M\7\270\206M\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
*Eventually, the telnet request returned, successfully this time:*
time telnet localhost 9090
Trying 127.0.0.1...
Connected to localhost.
Escape character is '^]'.
GET /test HTTP/1.1
HTTP/1.1 200 OK
Content-Type: text/html
Hello World (43)Connection closed by foreign host.
real 3m49.293s
user 0m0.002s
sys 0m0.003s
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0dFN\7\0\0\0\0dFN\7dFN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, <unfinished ...>
[pid 21371] <... select resumed> ) = 0 (Timeout)
text/html\r\n\r\n", 44}, {"Hello World (43)", 16}], 2) = 60
[pid 21371] close(6) = 0
[pid 21371] writev(2, [{"[pid: 21371|app: 0|req: 9/9] 127.0.0.1 () {18 vars
in 180 bytes} [Tue Aug 19 14:37:04 2014] GET /test => generated 16 bytes in
50032 msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
199}], 1) = 199
[pid 21371] epoll_wait(4, <unfinished ...>
[pid 21370] <... epoll_wait resumed> {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0PJN\7\0\0\0\0PJN\7PJN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0
[pid 21370] epoll_wait(8, {}, 1, 1000) = 0
[pid 21370] getsockopt(3, SOL_TCP, TCP_INFO,

\17\0\0\0\0\0\30\2\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0008NN\7\0\0\0\0008NN\0078NN\7\0\0\0\0\0\0\0\0\0\0\0\0\220\320\3\0\377\377\377\177\n\0\0\0\0\0\0\0\3\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0",

Post by Francois Gaudin
[104]) = 0
[pid 21370] wait4(-1, 0x7fff65fbd868, WNOHANG, NULL) = 0

this is teh strace of the master, you have to strace the worker, as it is
the one calling accept()
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
Sometimes it works, like the following trace, and I get the accept(),
sometimes I get "Connection closed by foreign host."
Last one is the telnet
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34071),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
localhost:9090\r\nAccept: */*\r\n\r\n", 4096) = 78
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (314)", 17}], 2) = 61
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 14/14] 127.0.0.1 () {24 vars in 247
bytes} [Tue Aug 19 23:31:17 2014] GET / => generated 17 bytes in 30027
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
197}], 1) = 197
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34072),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
localhost:9090\r\nAccept: */*\r\n\r\n", 4096) = 78
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (74)", 16}], 2) = 60
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 15/15] 127.0.0.1 () {24 vars in 247
bytes} [Tue Aug 19 23:31:48 2014] GET / => generated 16 bytes in 30022
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
197}], 1) = 197
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34080),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (79)", 16}], 2) = 60
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 16/16] 127.0.0.1 () {18 vars in 180
bytes} [Tue Aug 19 23:32:18 2014] GET /test => generated 16 bytes in 30031
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
201}], 1) = 201
epoll_wait(4,

It is the expected behaviour: the epoll_wait is never wake up as there are
no more free slots.

Maybe there is an important point you are missing: when you see accept()
in your process strace it means the previous requests has ended. There is
no other way for uWSGI to accept() in single process mode.

[Francois Gaudin]

I understand that it accepts because the other requests are finished.

What I don't understand is the role of the queue size. I can put 2 or 100,
I'll have the same behavior. The connection will be accepted and the client
will sit there waiting

Post by Roberto De Ioris

Post by Francois Gaudin
Sometimes it works, like the following trace, and I get the accept(),
sometimes I get "Connection closed by foreign host."
Last one is the telnet
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34071),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
localhost:9090\r\nAccept: */*\r\n\r\n", 4096) = 78
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (314)", 17}], 2) = 61
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 14/14] 127.0.0.1 () {24 vars in 247
bytes} [Tue Aug 19 23:31:17 2014] GET / => generated 17 bytes in 30027
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
197}], 1) = 197
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34072),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
localhost:9090\r\nAccept: */*\r\n\r\n", 4096) = 78
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (74)", 16}], 2) = 60
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 15/15] 127.0.0.1 () {24 vars in 247
bytes} [Tue Aug 19 23:31:48 2014] GET / => generated 16 bytes in 30022
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
197}], 1) = 197
epoll_wait(4, {{EPOLLIN, {u32=3, u64=3}}}, 1, -1) = 1
accept4(3, {sa_family=AF_INET, sin_port=htons(34080),
sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_NONBLOCK) = 6
read(6, "GET /test HTTP/1.1\r\n\r\n", 4096) = 22
select(0, NULL, NULL, NULL, {30, 0}) = 0 (Timeout)
writev(6, [{"HTTP/1.1 200 OK\r\nContent-Type: text/html\r\n\r\n", 44},
{"Hello World (79)", 16}], 2) = 60
close(6) = 0
writev(2, [{"[pid: 29752|app: 0|req: 16/16] 127.0.0.1 () {18 vars in 180
bytes} [Tue Aug 19 23:32:18 2014] GET /test => generated 16 bytes in

30031

Post by Francois Gaudin
msecs (HTTP/1.1 200) 1 headers in 44 bytes (1 switches on core 0)\n",
201}], 1) = 201
epoll_wait(4,

It is the expected behaviour: the epoll_wait is never wake up as there are
no more free slots.
Maybe there is an important point you are missing: when you see accept()
in your process strace it means the previous requests has ended. There is
no other way for uWSGI to accept() in single process mode.
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
I understand that it accepts because the other requests are finished.
What I don't understand is the role of the queue size. I can put 2 or 100,
I'll have the same behavior. The connection will be accepted and the client
will sit there waiting

This can happens only if tcp_defer_accept is enabled (or you have some
proxy before uWSGI accepting requests), otherwise you can enqueue upto
listen_queue + X requests.

You could strace telnet too, to better check, and eventually you can check
the sockets status with the 'ss' command (if i rememebr correctly it is
part of the iproute2 suite)

[Francois Gaudin]

Can X be greater than 10? See my new test, I can definitely send at least
12 requests.

To be sure curl is not doing weird things, I've switched to a telnet only
test. My script uses expect:

#!/usr/bin/expect

set timeout 3
spawn telnet localhost 9090
expect "^]'."
send "GET /test HTTP/1.1\r\r"
set timeout 300
expect eof

*uwsgi is running with --no-defer-accept*

$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2
--no-defer-accept

*And all connections are established:*

$ ss -p | grep telnet
tcp ESTAB 0 0 127.0.0.1:38508 127.0.0.1:9090
users:(("telnet",8654,3))
tcp ESTAB 0 22 127.0.0.1:38528 127.0.0.1:9090
users:(("telnet",8684,3))
tcp ESTAB 0 22 127.0.0.1:38532 127.0.0.1:9090
users:(("telnet",8704,3))
tcp ESTAB 0 22 127.0.0.1:38530 127.0.0.1:9090
users:(("telnet",8694,3))
tcp ESTAB 0 22 127.0.0.1:38531 127.0.0.1:9090
users:(("telnet",8699,3))
tcp ESTAB 0 0 127.0.0.1:38519 127.0.0.1:9090
users:(("telnet",8659,3))
tcp ESTAB 0 0 127.0.0.1:38505 127.0.0.1:9090
users:(("telnet",8649,3))
tcp ESTAB 0 22 127.0.0.1:38527 127.0.0.1:9090
users:(("telnet",8679,3))
tcp ESTAB 0 0 127.0.0.1:38524 127.0.0.1:9090
users:(("telnet",8664,3))
tcp ESTAB 0 22 127.0.0.1:38526 127.0.0.1:9090
users:(("telnet",8674,3))
tcp ESTAB 0 22 127.0.0.1:38525 127.0.0.1:9090
users:(("telnet",8669,3))
tcp ESTAB 0 22 127.0.0.1:38529 127.0.0.1:9090
users:(("telnet",8689,3))

$ sudo strace -s 2000 -p 8659
Process 8659 attached
select(4, [0 3], [], [3], NULL

Post by Roberto De Ioris

Post by Francois Gaudin
I understand that it accepts because the other requests are finished.
What I don't understand is the role of the queue size. I can put 2 or

100,

Post by Francois Gaudin
I'll have the same behavior. The connection will be accepted and the client
will sit there waiting

This can happens only if tcp_defer_accept is enabled (or you have some
proxy before uWSGI accepting requests), otherwise you can enqueue upto
listen_queue + X requests.
You could strace telnet too, to better check, and eventually you can check
the sockets status with the 'ss' command (if i rememebr correctly it is
part of the iproute2 suite)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Francois Gaudin]

Hi

Can anyone reproduce this behavior?

Post by Francois Gaudin
Can X be greater than 10? See my new test, I can definitely send at least
12 requests.
To be sure curl is not doing weird things, I've switched to a telnet only
#!/usr/bin/expect
set timeout 3
spawn telnet localhost 9090
expect "^]'."
send "GET /test HTTP/1.1\r\r"
set timeout 300
expect eof
*uwsgi is running with --no-defer-accept*
$ uwsgi --http-socket :9090 --wsgi-file test.py --single-interpreter
--master --die-on-term --pyhome ~/tmp/testenv --harakiri 55 -l 2
--no-defer-accept
*And all connections are established:*
$ ss -p | grep telnet
tcp ESTAB 0 0 127.0.0.1:38508
127.0.0.1:9090 users:(("telnet",8654,3))
tcp ESTAB 0 22 127.0.0.1:38528
127.0.0.1:9090 users:(("telnet",8684,3))
tcp ESTAB 0 22 127.0.0.1:38532
127.0.0.1:9090 users:(("telnet",8704,3))
tcp ESTAB 0 22 127.0.0.1:38530
127.0.0.1:9090 users:(("telnet",8694,3))
tcp ESTAB 0 22 127.0.0.1:38531
127.0.0.1:9090 users:(("telnet",8699,3))
tcp ESTAB 0 0 127.0.0.1:38519
127.0.0.1:9090 users:(("telnet",8659,3))
tcp ESTAB 0 0 127.0.0.1:38505
127.0.0.1:9090 users:(("telnet",8649,3))
tcp ESTAB 0 22 127.0.0.1:38527
127.0.0.1:9090 users:(("telnet",8679,3))
tcp ESTAB 0 0 127.0.0.1:38524
127.0.0.1:9090 users:(("telnet",8664,3))
tcp ESTAB 0 22 127.0.0.1:38526
127.0.0.1:9090 users:(("telnet",8674,3))
tcp ESTAB 0 22 127.0.0.1:38525
127.0.0.1:9090 users:(("telnet",8669,3))
tcp ESTAB 0 22 127.0.0.1:38529
127.0.0.1:9090 users:(("telnet",8689,3))
$ sudo strace -s 2000 -p 8659
Process 8659 attached
select(4, [0 3], [], [3], NULL

Post by Roberto De Ioris

Post by Francois Gaudin
I understand that it accepts because the other requests are finished.
What I don't understand is the role of the queue size. I can put 2 or

100,

Post by Francois Gaudin
I'll have the same behavior. The connection will be accepted and the client
will sit there waiting

This can happens only if tcp_defer_accept is enabled (or you have some
proxy before uWSGI accepting requests), otherwise you can enqueue upto
listen_queue + X requests.
You could strace telnet too, to better check, and eventually you can check
the sockets status with the 'ss' command (if i rememebr correctly it is
part of the iproute2 suite)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

--
Francois

[Roberto De Ioris]

Post by Francois Gaudin
Hi
Can anyone reproduce this behavior?

Sorry, complete forgot to answer :)

Yes, this is the expected behaviour for linux, the minimal size of the
listen queue is always forced to 8 (in BSD to 5).

[Francois Gaudin]

Ok, so if I run the same test with like 20 telnet, they should start being
rejected? I'll tell you in a bit ;)

Thanks for the answer

Post by Roberto De Ioris

Post by Francois Gaudin
Hi
Can anyone reproduce this behavior?

Sorry, complete forgot to answer :)
Yes, this is the expected behaviour for linux, the minimal size of the
listen queue is always forced to 8 (in BSD to 5).
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
Ok, so if I run the same test with like 20 telnet, they should start being
rejected? I'll tell you in a bit ;)
Thanks for the answer

Based on your configuration, it could requires a bit of time in SYN_SENT
state before being rejected (this is the default on osx as an example)

[Francois Gaudin]

but it shouldn't reach the ESTABLISHED state right? I'm on Ubuntu, we'll see

Post by Roberto De Ioris

Post by Francois Gaudin
Ok, so if I run the same test with like 20 telnet, they should start

being

Post by Francois Gaudin
rejected? I'll tell you in a bit ;)
Thanks for the answer

Based on your configuration, it could requires a bit of time in SYN_SENT
state before being rejected (this is the default on osx as an example)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Francois Gaudin]

:'(

tcp ESTAB 0 22 127.0.0.1:49107 127.0.0.1:9090
users:(("telnet",7844,3))
tcp ESTAB 0 0 127.0.0.1:49102 127.0.0.1:9090
users:(("telnet",7820,3))
tcp ESTAB 0 0 127.0.0.1:49105 127.0.0.1:9090
users:(("telnet",7834,3))
tcp ESTAB 0 22 127.0.0.1:49113 127.0.0.1:9090
users:(("telnet",7884,3))
tcp ESTAB 0 0 127.0.0.1:49106 127.0.0.1:9090
users:(("telnet",7839,3))
tcp ESTAB 0 22 127.0.0.1:49120 127.0.0.1:9090
users:(("telnet",7927,3))
tcp ESTAB 0 22 127.0.0.1:49118 127.0.0.1:9090
users:(("telnet",7913,3))
tcp ESTAB 0 22 127.0.0.1:49116 127.0.0.1:9090
users:(("telnet",7903,3))
tcp ESTAB 0 22 127.0.0.1:49112 127.0.0.1:9090
users:(("telnet",7879,3))
tcp ESTAB 0 22 127.0.0.1:49111 127.0.0.1:9090
users:(("telnet",7870,3))
tcp ESTAB 0 22 127.0.0.1:49115 127.0.0.1:9090
users:(("telnet",7894,3))
tcp ESTAB 0 22 127.0.0.1:49110 127.0.0.1:9090
users:(("telnet",7865,3))
tcp ESTAB 0 22 127.0.0.1:49119 127.0.0.1:9090
users:(("telnet",7918,3))
tcp ESTAB 0 22 127.0.0.1:49122 127.0.0.1:9090
users:(("telnet",7937,3))
tcp ESTAB 0 22 127.0.0.1:49109 127.0.0.1:9090
users:(("telnet",7860,3))
tcp ESTAB 0 22 127.0.0.1:49117 127.0.0.1:9090
users:(("telnet",7908,3))
tcp ESTAB 0 22 127.0.0.1:49121 127.0.0.1:9090
users:(("telnet",7932,3))
tcp ESTAB 0 0 127.0.0.1:49104 127.0.0.1:9090
users:(("telnet",7825,3))
tcp ESTAB 0 22 127.0.0.1:49114 127.0.0.1:9090
users:(("telnet",7889,3))
tcp ESTAB 0 22 127.0.0.1:49108 127.0.0.1:9090
users:(("telnet",7851,3))

Post by Francois Gaudin
but it shouldn't reach the ESTABLISHED state right? I'm on Ubuntu, we'll see

Post by Roberto De Ioris

Post by Francois Gaudin
Ok, so if I run the same test with like 20 telnet, they should start

being

Post by Francois Gaudin
rejected? I'll tell you in a bit ;)
Thanks for the answer

Based on your configuration, it could requires a bit of time in SYN_SENT
state before being rejected (this is the default on osx as an example)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

--
Francois

[Roberto De Ioris]

Post by Francois Gaudin
:'(
tcp ESTAB 0 22 127.0.0.1:49107
127.0.0.1:9090
users:(("telnet",7844,3))
tcp ESTAB 0 0 127.0.0.1:49102
127.0.0.1:9090
users:(("telnet",7820,3))
tcp ESTAB 0 0 127.0.0.1:49105
127.0.0.1:9090
users:(("telnet",7834,3))
tcp ESTAB 0 22 127.0.0.1:49113
127.0.0.1:9090
users:(("telnet",7884,3))
tcp ESTAB 0 0 127.0.0.1:49106
127.0.0.1:9090
users:(("telnet",7839,3))
tcp ESTAB 0 22 127.0.0.1:49120
127.0.0.1:9090
users:(("telnet",7927,3))
tcp ESTAB 0 22 127.0.0.1:49118
127.0.0.1:9090
users:(("telnet",7913,3))
tcp ESTAB 0 22 127.0.0.1:49116
127.0.0.1:9090
users:(("telnet",7903,3))
tcp ESTAB 0 22 127.0.0.1:49112
127.0.0.1:9090
users:(("telnet",7879,3))
tcp ESTAB 0 22 127.0.0.1:49111
127.0.0.1:9090
users:(("telnet",7870,3))
tcp ESTAB 0 22 127.0.0.1:49115
127.0.0.1:9090
users:(("telnet",7894,3))
tcp ESTAB 0 22 127.0.0.1:49110
127.0.0.1:9090
users:(("telnet",7865,3))
tcp ESTAB 0 22 127.0.0.1:49119
127.0.0.1:9090
users:(("telnet",7918,3))
tcp ESTAB 0 22 127.0.0.1:49122
127.0.0.1:9090
users:(("telnet",7937,3))
tcp ESTAB 0 22 127.0.0.1:49109
127.0.0.1:9090
users:(("telnet",7860,3))
tcp ESTAB 0 22 127.0.0.1:49117
127.0.0.1:9090
users:(("telnet",7908,3))
tcp ESTAB 0 22 127.0.0.1:49121
127.0.0.1:9090
users:(("telnet",7932,3))
tcp ESTAB 0 0 127.0.0.1:49104
127.0.0.1:9090
users:(("telnet",7825,3))
tcp ESTAB 0 22 127.0.0.1:49114
127.0.0.1:9090
users:(("telnet",7889,3))
tcp ESTAB 0 22 127.0.0.1:49108
127.0.0.1:9090
users:(("telnet",7851,3))

I realized now that you are checking netstat for checking accept()'ed
connection, but ESTABLISHED in modern kernels (at least on Linux and BSDs)
does not mean a process has called accept().

Syncookies, max_syn_backlog, the minimal queue length. all changes the
"old" behaviour (in the name of security, first of all)

The client behaviour (telnet, curl...) is getting connect() in write-ready
state up to the amount of the listen queue (minimal 8 or 16 on Linux),
after this limit the connect() will block until the timeout. But at kernel
level, lot more connections can be in ESTABLISHED state.

You can play with your kernel tcp tunings, but just for fun :)

[Francois Gaudin]

So it seems I won't be able to get the behavior I need from uwsgi directly
if I understand what you're saying.

Thanks you anyway for all your answers! You refreshed my knowledge about
sockets.

Post by Roberto De Ioris

Post by Francois Gaudin
:'(
tcp ESTAB 0 22 127.0.0.1:49107
127.0.0.1:9090
users:(("telnet",7844,3))
tcp ESTAB 0 0 127.0.0.1:49102
127.0.0.1:9090
users:(("telnet",7820,3))
tcp ESTAB 0 0 127.0.0.1:49105
127.0.0.1:9090
users:(("telnet",7834,3))
tcp ESTAB 0 22 127.0.0.1:49113
127.0.0.1:9090
users:(("telnet",7884,3))
tcp ESTAB 0 0 127.0.0.1:49106
127.0.0.1:9090
users:(("telnet",7839,3))
tcp ESTAB 0 22 127.0.0.1:49120
127.0.0.1:9090
users:(("telnet",7927,3))
tcp ESTAB 0 22 127.0.0.1:49118
127.0.0.1:9090
users:(("telnet",7913,3))
tcp ESTAB 0 22 127.0.0.1:49116
127.0.0.1:9090
users:(("telnet",7903,3))
tcp ESTAB 0 22 127.0.0.1:49112
127.0.0.1:9090
users:(("telnet",7879,3))
tcp ESTAB 0 22 127.0.0.1:49111
127.0.0.1:9090
users:(("telnet",7870,3))
tcp ESTAB 0 22 127.0.0.1:49115
127.0.0.1:9090
users:(("telnet",7894,3))
tcp ESTAB 0 22 127.0.0.1:49110
127.0.0.1:9090
users:(("telnet",7865,3))
tcp ESTAB 0 22 127.0.0.1:49119
127.0.0.1:9090
users:(("telnet",7918,3))
tcp ESTAB 0 22 127.0.0.1:49122
127.0.0.1:9090
users:(("telnet",7937,3))
tcp ESTAB 0 22 127.0.0.1:49109
127.0.0.1:9090
users:(("telnet",7860,3))
tcp ESTAB 0 22 127.0.0.1:49117
127.0.0.1:9090
users:(("telnet",7908,3))
tcp ESTAB 0 22 127.0.0.1:49121
127.0.0.1:9090
users:(("telnet",7932,3))
tcp ESTAB 0 0 127.0.0.1:49104
127.0.0.1:9090
users:(("telnet",7825,3))
tcp ESTAB 0 22 127.0.0.1:49114
127.0.0.1:9090
users:(("telnet",7889,3))
tcp ESTAB 0 22 127.0.0.1:49108
127.0.0.1:9090
users:(("telnet",7851,3))

I realized now that you are checking netstat for checking accept()'ed
connection, but ESTABLISHED in modern kernels (at least on Linux and BSDs)
does not mean a process has called accept().
Syncookies, max_syn_backlog, the minimal queue length. all changes the
"old" behaviour (in the name of security, first of all)
The client behaviour (telnet, curl...) is getting connect() in write-ready
state up to the amount of the listen queue (minimal 8 or 16 on Linux),
after this limit the connect() will block until the timeout. But at kernel
level, lot more connections can be in ESTABLISHED state.
You can play with your kernel tcp tunings, but just for fun :)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi

[Roberto De Ioris]

Post by Francois Gaudin
So it seems I won't be able to get the behavior I need from uwsgi directly
if I understand what you're saying.

Yes, all of this things happens before uWSGI (or whatever process) can do
something. (unless we want to make something extreme like shutting down
the instance when the listen queue is full)

By the way i do not think it would be much of a problem for the heroku
"ping" (once you disable deferred accept) as i suppose they have set a
pretty tiny timeout (eventually ask them about some more detail)

[Francois Gaudin]

yes, I'll ask them and try to do the same test on an Heroku app to see how
it behave in real conditions.

Thank you again!

Post by Francois Gaudin

Post by Francois Gaudin
So it seems I won't be able to get the behavior I need from uwsgi

directly

Post by Francois Gaudin
if I understand what you're saying.

Yes, all of this things happens before uWSGI (or whatever process) can do
something. (unless we want to make something extreme like shutting down
the instance when the listen queue is full)
By the way i do not think it would be much of a problem for the heroku
"ping" (once you disable deferred accept) as i suppose they have set a
pretty tiny timeout (eventually ask them about some more detail)
--
Roberto De Ioris
http://unbit.it
_______________________________________________
uWSGI mailing list
http://lists.unbit.it/cgi-bin/mailman/listinfo/uwsgi