Lost connection after reading 2147479552 bytes with sendfile

[Mathias Andre]

Hi!

I've bumped into a strange problem lately, and though I've found a
workaround I thought I'd post here to try and understand what the
underlying issue can be in case it affects anyone else.


The short version is:
Running Nginx 1.9.2 on Scientific Linux 6 with a
2.6.32-504.8.1.el6.x86_64 kernel, nginx is configured to serve a large
file (4GB) with sendfile enabled, the file download hangs exactly after
2147479552 bytes, after ~ 60s the connection is dropped (presumably
because of the default send_timeout).

Setting sendfile_max_chunk to 1G fixes the problem


Longer version:

# Create a random 4G file:
mkdir /tmp/test
dd if=/dev/urandom of=/tmp/test/bigfile bs=1M count=4096 

# Basic NGINX configuration /tmp/nginx.conf:
worker_processes  1;
daemon off;

events {
    worker_connections 768;
}

http {
    sendfile on;

    access_log /tmp/access.log;
    error_log /tmp/error.log debug;

    server {
        listen 8080 default_server;
        location / {
            root /tmp/test/;
        }
    }
}

# Nginx 1.9.2 was compiled by hand:
nginx -V
nginx version: nginx/1.9.2
built by gcc 4.4.7 20120313 (Red Hat 4.4.7-4) (GCC) 
built with OpenSSL 1.0.1e-fips 11 Feb 2013
TLS SNI support enabled
configure arguments: --prefix=/tmp/opt --conf-path=/etc/nginx/nginx.conf --error-log-path=/tmp/error.log --http-log-path=/tmp/access.log --pid-path=/tmp/nginx.pid --http-client-body-temp-path=/var/cache/nginx/client_temp --http-proxy-temp-path=/var/cache/nginx/proxy_temp --http-fastcgi-temp-path=/var/cache/nginx/fastcgi_temp --http-uwsgi-temp-path=/var/cache/nginx/uwsgi_temp --http-scgi-temp-path=/var/cache/nginx/scgi_temp --user=nginx --group=nginx --with-http_ssl_module --with-http_realip_module --with-http_addition_module --with-http_sub_module --with-http_dav_module --with-http_flv_module --with-http_mp4_module --with-http_gunzip_module --with-http_gzip_static_module --with-http_random_index_module --with-http_secure_link_module --with-http_stub_status_module --with-http_auth_request_module --with-mail --with-mail_ssl_module --with-file-aio --with-ipv6 --with-cc-opt='-O2 -g -pipe -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic' --without-pcre --without-http_rewrite_module --with-debug


# Run nginx with the above configuration (non-root user, hence all the
# /tmp/ stuff above)
nginx -c /tmp/nginx.conf 


# On the same machine run a wget (auto-retry disabled):
$ wget http://localhost:8080/bigfile -O /dev/null -t 1
--2015-07-10 17:02:22--  http://localhost:8080/bigfile
Resolving localhost... 127.0.0.1, ::1
Connecting to localhost|127.0.0.1|:8080... connected.
HTTP request sent, awaiting response... 200 OK
Length: 4294967296 (4.0G) [text/plain]
Saving to: “/dev/null”

49% [===================================================================================>                                                                                     ] 2,147,479,552 --.-K/s   in 96s     

2015-07-10 17:03:58 (21.4 MB/s) - Connection closed at byte 2147479552. Giving up.

# The error logs is visible at:
# https://gist.githubusercontent.com/mathiasuk/9022d3458ef373db1775/raw/e483a69aae10805558fefc4eefb381e34bbbeaf9/error-sc6.5.log




I tried the same thing on an Ubuntu 14.04.2 without problem, however, in
this case the sendfile system call always reads much fewer bytes at a
time https://gist.githubusercontent.com/mathiasuk/018e0462d8788288d0d3/raw/error-ubuntu-14.04.02.log :

$ grep sendfile /tmp/error-ubuntu-14.04.02.log|head
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: @0 2147479552
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: 3557719 of 2147479552 @0
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: @3557719 2147481257
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: 7792477 of 2147481257 @3557719
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: @11350196 2147483468
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: 1833524 of 2147483468 @11350196
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: @13183720 2147480856
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: 1899007 of 2147480856 @13183720
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: @15082727 2147482393
2015/07/10 17:08:51 [debug] 15680#0: *1 sendfile: 1964490 of 2147482393 @15082727


Whereas on the SL6 box sendfile tries to read 2147479552 in one go and
nginx then seems to stop there:

$ grep sendfile /tmp/error-sc6.5.log 
2015/07/10 17:02:22 [debug] 22749#0: *1 sendfile: @0 2147479552
2015/07/10 17:02:22 [debug] 22749#0: *1 sendfile: 2147479552 of 2147479552 @0


I'm not sure if this is the right place to post this, please point me in
the right direction if not :)

Let me know if I can provide more information or details.

Cheers,
Mathias

-- 
  *    Mathias Andre                   Web & Advanced Projects Coordinator
*E S*  European Southern Observatory   ESO Education & Public Outreach Department
  O    Karl Schwarzschildstr. 2        
  *    D-85748 Garching                Phone : +49 (0)89 3200 6760
       Germany                         Office 246
"For every problem, there is a solution that is simple, neat, and wrong."
H. L. Mencken