Gunicorn 19.4.1 : connection closed too early when serving static file

[nMustaki]

Hi,

first thanks for Gunicorn !
I updated Gunicorn from 19.3.0 to 19.4.1 yesterday evening and serving static js files stopped working because the connection was closed before the file was entirely downloaded. Reverting to 19.3.0, with exactly the same configuration fixed the issue.
The js static file weights 1Mo, but the only the first 5000 lines or so were downloaded.

Some info :

• The OS is a x64 Debian Wheezy with 3.2 kernel.
• I use gevent workers, version 1.0.1
• Gunicorn is started with this command as an initscript:

start-stop-daemon 
--start -d /path/to/repo 
--exec /path/to/venv/bin/gunicorn -- 
run_production:new_app 
--workers 5 
--bind 127.0.0.1:18004 
-k gevent 
--worker-connections 100 
-D 
--timeout 30 
--pid /tmp/project.pid 
--name project 
--access-logfile /var/log/project_access.log 
--error-logfile /var/log/project_error.log 
--log-file /var/log/project_access.log 
--log-level info --access-logformat {"remote": "%(h)s", "date": "%(t)s", "method": "%(m)s", "status": "%(s)s", "url": "%(U)s", "query": "%(q)s", "referer" :%(f)s", "user-agent" : "%(a)s", "request_time" : "%(L)s"}

Here are the Gunicorn log file in debug mode

[2015-11-26 03:11:40 +0000] [57088] [INFO] Starting gunicorn 19.4.1
[2015-11-26 03:11:40 +0000] [57088] [DEBUG] Arbiter booted
[2015-11-26 03:11:40 +0000] [57088] [INFO] Listening at: http://127.0.0.1:18004 (57088)
[2015-11-26 03:11:40 +0000] [57088] [INFO] Using worker: gevent
[2015-11-26 03:11:40 +0000] [57094] [INFO] Booting worker with pid: 57094
[2015-11-26 03:11:40 +0000] [57095] [INFO] Booting worker with pid: 57095
[2015-11-26 03:11:40 +0000] [57096] [INFO] Booting worker with pid: 57096
[2015-11-26 03:11:40 +0000] [57097] [INFO] Booting worker with pid: 57097
[2015-11-26 03:11:40 +0000] [57110] [INFO] Booting worker with pid: 57110
[2015-11-26 03:11:40 +0000] [57088] [DEBUG] 5 workers
[2015-11-26 02:11:55 +0000] [57094] [DEBUG] GET /static/react/main.js
{"remote": "127.0.0.1", "date": "[26/Nov/2015:03:11:55 +0100]", "method": "GET", "status": "200", "url": "/static/react/main.js", "query": "", "referer" :-", "user-agent" : "Wget/1.15 (linux-gnu)", "request_time" : "0.009241"}
[2015-11-26 02:11:55 +0000] [57094] [DEBUG] Closing connection. 
[2015-11-26 02:12:01 +0000] [57096] [DEBUG] GET /static/react/main.js

Which were created with this shell call :

#wget https://www.domain.com/project/static/react/main.js                                                                                                                                                                         8 ↵
--2015-11-26 03:11:55--  https://www.domain.com/project/static/react/main.js
Resolving www.domain.com (www.domain.com)... 195.154.188.2
Connecting to www.domain.com (www.domain.com)|195.154.188.2|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2047243 (2.0M) [application/javascript]
Saving to: ‘main.js.3’

11% [=====================>                                                                                                                                                                               ] 229,376     44.1KB/s   in 5.1s   

2015-11-26 03:12:00 (44.1 KB/s) - Connection closed at byte 229376. Retrying.

--2015-11-26 03:12:01--  (try: 2)  https://www.domain.com/project/static/react/main.js
Connecting to www.domain.com (www.domain.com)|195.154.188.2|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2047243 (2.0M) [application/javascript]
Saving to: ‘main.js.3’

11% [=====================>                                                                                                                                                                               ] 229,376     44.1KB/s   in 5.1s   

2015-11-26 03:12:07 (44.1 KB/s) - Connection closed at byte 229376. Retrying.

--2015-11-26 03:12:09--  (try: 3)  https://www.domain.com/project/static/react/main.js
Connecting to www.domain.com (www.domain.com)|195.154.188.2|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 2047243 (2.0M) [application/javascript]
Saving to: ‘main.js.3’

 9% [=================>                                                                                                                                                                                   ] 196,608     38.1KB/s   in 5.0s   

2015-11-26 03:12:14 (38.1 KB/s) - Connection closed at byte 229376. Retrying.

^C

Thanks you !

[benoitc]

it may be due to #1094 can you try to revert that fix and let me know? ping @tilgovi

[benoitc]

@nMustaki also are you giving a content-length to your response? Does it correspond to the file length?

[nMustaki]

I didn't check the content-length, the file is served with Flask static system so I figured it should be ok.
I'll check that try to revert tonight (10/15 hours from now) and I'll let you know.

[benoitc]

@nMustaki thanks!

[nMustaki]

Hi, sorry for the lag...

So I reverted the commit (git revert 6b92575e004da36deed0a952cf342a2eb8d -m 1) and the issue is solved like magic.
What can I do to help you go further ?

Thanks again

[tilgovi]

Thanks for reporting this. My apologies for the regression. Very much appreciate having this tested live now. I'll see what I can do.

@benoitc if you want to revert and make a patch release I can revisit and we can try again with more testing.

[nMustaki]

No problem for the regression, you do a really great job so it's fine by me.

I added some custom logging, and here what I got :

[2015-11-29 16:08:17 +0000] [56592] [DEBUG] GET /static/react/main.js
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:369 response_length=1079593
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:381 self.sendfile nbytes=1079593
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:381 self.sendfile BLKSIZE=1073741823
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:382 self.sendfile for count=1079593
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:385 self.sendfile total sent 229376
{"remote": "127.0.0.1", "date": "[29/Nov/2015:17:08:17 +0100]", "method": "GET", "status": "200", "url": "/static/react/main.js", "query": "", "referer" :-", "user-agent" : "Wget/1.15 (linux-gnu)", "request_time" : "0.010926"}
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:229 self.must_close=False
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] wsgi.py:229 self.req.should_close()=True
[2015-11-29 16:08:17 +0000] [56592] [DEBUG] Closing connection.

So the libc.sendfile in _sendfile.py is not sending everything in one shot as expected by the current loop :

for m in range(0, nbytes, BLKSIZE):
            count = min(nbytes - sent, BLKSIZE)
            sent += sendfile(sockno, fileno, offset + sent, count)

[tilgovi]

I think this should be fixed now on master. The old code before #1155 did not trust sendfile to send the requested count, but my change left that out.

If you get a chance to test, please report back that it is confirmed fixed.

[nMustaki]

It's fixed, many thanks !

[tilgovi]

\o/ hurray