Gunicorn 19.4.1 : connection closed too early when serving static file #1155

Closed
nMustaki opened this Issue Nov 26, 2015 · 10 comments

Projects

None yet

3 participants

@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
Owner
benoitc commented Nov 26, 2015

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

@benoitc
Owner
benoitc commented Nov 26, 2015

@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
Owner
benoitc commented Nov 26, 2015

@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
Collaborator
tilgovi commented Nov 29, 2015

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 tilgovi closed this in 1f3bddd Nov 29, 2015
@tilgovi
Collaborator
tilgovi commented Nov 29, 2015

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
Collaborator
tilgovi commented Nov 29, 2015

\o/ hurray

@martijnvermaat martijnvermaat added a commit to varda/ansible-role-varda that referenced this issue Jan 5, 2016
@martijnvermaat martijnvermaat Update Gunicorn to 19.4.5
We were bitten by this issue: benoitc/gunicorn#1155
6e33b28
@martijnvermaat martijnvermaat referenced this issue in varda/ansible-role-varda Jan 5, 2016
Merged

Update Gunicorn to 19.4.5 #6

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment