File download results in "110: Connection timed out" on nginx; Download continues until Linux Kernel 'tcp_fin_timeout' reached

Fri Jan 29 17:58:02 UTC 2016

Hello everyone,

when trying to download a static file using curl with a limit rate of
4000 (to simulate slow consumers) the download aborts after a certain
time. A workaround to make that work is to increase the send_timeout
to 3600. Nevertheless I would like to understand the behaviour and
hope that you can help:

- File download starts with via curl with --limit-rate 4000.
- After exactly 60s connection on nginx host goes from ESTABLISHED to
FIN_WAIT_1 (verified with 'ss'). Having nginx on debug gives the
following:

2016/01/29 17:32:19 [debug] 9037#0: *1 http run request: "/8m?"
2016/01/29 17:32:19 [debug] 9037#0: *1 http writer handler: "/8m?"
2016/01/29 17:32:19 [debug] 9037#0: *1 http output filter "/8m?"
2016/01/29 17:32:19 [debug] 9037#0: *1 http copy filter: "/8m?"
2016/01/29 17:32:19 [debug] 9037#0: *1 image filter
2016/01/29 17:32:19 [debug] 9037#0: *1 xslt filter body
2016/01/29 17:32:19 [debug] 9037#0: *1 http postpone filter "/8m?"
0000000000000000
2016/01/29 17:32:19 [debug] 9037#0: *1 write old buf t:0 f:1
0000000000000000, pos 0000000000000000, size: 0 file: 624692, size:
7763916
2016/01/29 17:32:19 [debug] 9037#0: *1 http write filter: l:1 f:0 s:7763916
2016/01/29 17:32:19 [debug] 9037#0: *1 http write filter limit 0
2016/01/29 17:32:19 [debug] 9037#0: *1 sendfile: @624692 7763916
2016/01/29 17:32:19 [debug] 9037#0: *1 sendfile: 777600, @624692 777600:7763916
2016/01/29 17:32:19 [debug] 9037#0: *1 http write filter 00000000024CA578
2016/01/29 17:32:19 [debug] 9037#0: *1 http copy filter: -2 "/8m?"
2016/01/29 17:32:19 [debug] 9037#0: *1 http writer output filter: -2, "/8m?"
2016/01/29 17:32:19 [debug] 9037#0: *1 event timer: 12, old:
1454088799035, new: 1454088799119
2016/01/29 17:33:06 [debug] 9037#0: *1 post event 00000000024FFEF8
2016/01/29 17:33:06 [debug] 9037#0: *1 delete posted event 00000000024FFEF8
2016/01/29 17:33:06 [debug] 9037#0: *1 http run request: "/8m?"
2016/01/29 17:33:06 [debug] 9037#0: *1 http writer handler: "/8m?"
2016/01/29 17:33:06 [debug] 9037#0: *1 http output filter "/8m?"
2016/01/29 17:33:06 [debug] 9037#0: *1 http copy filter: "/8m?"
2016/01/29 17:33:06 [debug] 9037#0: *1 image filter
2016/01/29 17:33:06 [debug] 9037#0: *1 xslt filter body
2016/01/29 17:33:06 [debug] 9037#0: *1 http postpone filter "/8m?"
0000000000000000
2016/01/29 17:33:06 [debug] 9037#0: *1 write old buf t:0 f:1
0000000000000000, pos 0000000000000000, size: 0 file: 1402292, size:
6986316
2016/01/29 17:33:06 [debug] 9037#0: *1 http write filter: l:1 f:0 s:6986316
2016/01/29 17:33:06 [debug] 9037#0: *1 http write filter limit 0
2016/01/29 17:33:06 [debug] 9037#0: *1 sendfile: @1402292 6986316
2016/01/29 17:33:06 [debug] 9037#0: *1 sendfile: 518400, @1402292 518400:6986316
2016/01/29 17:33:06 [debug] 9037#0: *1 http write filter 00000000024CA578
2016/01/29 17:33:06 [debug] 9037#0: *1 http copy filter: -2 "/8m?"
2016/01/29 17:33:06 [debug] 9037#0: *1 http writer output filter: -2, "/8m?"
2016/01/29 17:33:06 [debug] 9037#0: *1 event timer del: 12: 1454088799035
2016/01/29 17:33:06 [debug] 9037#0: *1 event timer add: 12: 60000:1454088846743
2016/01/29 17:34:06 [debug] 9037#0: *1 event timer del: 12: 1454088846743
2016/01/29 17:34:06 [debug] 9037#0: *1 http run request: "/8m?"
2016/01/29 17:34:06 [debug] 9037#0: *1 http writer handler: "/8m?"
2016/01/29 17:34:06 [info] 9037#0: *1 client timed out (110:
Connection timed out) while sending response to client, client:
123.123.123.123, server: localhost, request: "GET /8m HTTP/1.1", host:
"xxx.xxx.xxx"
2016/01/29 17:34:06 [debug] 9037#0: *1 http finalize request: 408,
"/8m?" a:1, c:1
2016/01/29 17:34:06 [debug] 9037#0: *1 http terminate request count:1
2016/01/29 17:34:06 [debug] 9037#0: *1 http terminate cleanup count:1 blk:0
2016/01/29 17:34:06 [debug] 9037#0: *1 http posted request: "/8m?"
2016/01/29 17:34:06 [debug] 9037#0: *1 http terminate handler count:1
2016/01/29 17:34:06 [debug] 9037#0: *1 http request count:1 blk:0
2016/01/29 17:34:06 [debug] 9037#0: *1 http close request
2016/01/29 17:34:06 [debug] 9037#0: *1 http log handler
2016/01/29 17:34:06 [debug] 9037#0: *1 run cleanup: 00000000024D4AD0
2016/01/29 17:34:06 [debug] 9037#0: *1 file cleanup: fd:13
2016/01/29 17:34:06 [debug] 9037#0: *1 free: 00000000024D3B40, unused: 0
2016/01/29 17:34:06 [debug] 9037#0: *1 free: 00000000024CA250, unused: 3145
2016/01/29 17:34:06 [debug] 9037#0: *1 close http connection: 12
2016/01/29 17:34:06 [debug] 9037#0: *1 reusable connection: 0
2016/01/29 17:34:06 [debug] 9037#0: *1 free: 00000000024D3730
2016/01/29 17:34:06 [debug] 9037#0: *1 free: 00000000024C5780, unused: 0
2016/01/29 17:34:06 [debug] 9037#0: *1 free: 00000000024EA910, unused: 128

- Taking a look at the tcpdump file taken on the client side during
the download *NO* FIN has been received.
- Client keeps download and nginx keeps providing data. The tcp
connection on client side remains in ESTABLISHED state.
- After a while: the download still works, the connection on NGINX
host goes from FIN_WAIT_1 to FIN_WAIT_2. After that client side goes
to CLOSE_WAIT.
- Waiting a few minutes and the connection is closed (it seems to me
that this matches with tcp_fin_timeout = 180) and the download is
stopped with an error only on client side. nginx doesn't print
anything in the logs.

*Note*: This only produced the problem when accessing HTTP via the
internet (in a local network everything worked fine).

Thanks a lot for your help in advance!
Markus
---

To reproduce the problem one can do the following (on a linux system):

- Create a file about 8m big e.g.

    dd if=/dev/random of=/tmp/abc bs=1024 count=0 seek=$[1024*8]

and make it available for download via

- curl -# --limit-rate 4000 --verbose -O --trace-ascii trace.out
--trace-time http://PUBLIC-IP/8m

- monitor connections with

    watch -n 2 " ss '( dport = :http or sport = :http )' "

as well as the error log

---

# nginx -V
nginx version: nginx/1.4.6 (Ubuntu)
built by gcc 4.8.2 (Ubuntu 4.8.2-16ubuntu6)
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -fstack-protector
--param=ssp-buffer-size=4 -Wformat -Werror=format-security
-D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions
-Wl,-z,relro' --prefix=/usr/share/nginx
--conf-path=/etc/nginx/nginx.conf
--http-log-path=/var/log/nginx/access.log
--error-log-path=/var/log/nginx/error.log
--lock-path=/var/lock/nginx.lock --pid-path=/run/nginx.pid
--http-client-body-temp-path=/var/lib/nginx/body
--http-fastcgi-temp-path=/var/lib/nginx/fastcgi
--http-proxy-temp-path=/var/lib/nginx/proxy
--http-scgi-temp-path=/var/lib/nginx/scgi
--http-uwsgi-temp-path=/var/lib/nginx/uwsgi --with-debug
--with-pcre-jit --with-ipv6 --with-http_ssl_module
--with-http_stub_status_module --with-http_realip_module
--with-http_addition_module --with-http_dav_module
--with-http_geoip_module --with-http_gzip_static_module
--with-http_image_filter_module --with-http_spdy_module
--with-http_sub_module --with-http_xslt_module --with-mail
--with-mail_ssl_module

# uname -a
Linux 7e355bbce7a7 4.2.0-17-generic #21-Ubuntu SMP Fri Oct 23 19:56:16
UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
-------------- next part --------------
A non-text attachment was scrubbed...
Name: default
Type: application/octet-stream
Size: 2593 bytes
Desc: not available
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20160129/a0d435b4/attachment.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: nginx.conf
Type: application/octet-stream
Size: 1607 bytes
Desc: not available
URL: <http://mailman.nginx.org/pipermail/nginx/attachments/20160129/a0d435b4/attachment-0001.obj>