Opened 7 years ago

Closed 7 years ago

#1550 closed defect (invalid)

Slice module closes connection unexpectedly

Reported by: Xin Liu Owned by:
Priority: minor Milestone:
Component: nginx-module Version: 1.13.x
Keywords: ngx_http_slice_module Cc:
uname -a: Linux bionic 4.15.0-20-generic #21-Ubuntu SMP Tue Apr 24 06:16:15 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.14.0 (Ubuntu)
built with OpenSSL 1.1.0g 2 Nov 2017
TLS SNI support enabled
configure arguments: --with-cc-opt='-g -O2 -fdebug-prefix-map=/build/nginx-mcUg8N/nginx-1.14.0=. -fstack-protector-strong -Wformat -Werror=format-security -fPIC -Wdate-time -D_FORTIFY_SOURCE=2' --with-ld-opt='-Wl,-Bsymbolic-functions -Wl,-z,relro -Wl,-z,now -fPIC' --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 --modules-path=/usr/lib/nginx/modules --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-http_ssl_module --with-http_stub_status_module --with-http_realip_module --with-http_auth_request_module --with-http_v2_module --with-http_dav_module --with-http_slice_module --with-threads --with-http_addition_module --with-http_flv_module --with-http_geoip_module=dynamic --with-http_gunzip_module --with-http_gzip_static_module --with-http_image_filter_module=dynamic --with-http_mp4_module --with-http_perl_module=dynamic --with-http_random_index_module --with-http_secure_link_module --with-http_sub_module --with-http_xslt_module=dynamic --with-mail=dynamic --with-mail_ssl_module --with-stream=dynamic --with-stream_ssl_module --with-stream_ssl_preread_module --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-headers-more-filter --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-auth-pam --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-cache-purge --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-dav-ext --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-ndk --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-echo --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-fancyindex --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/nchan --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-lua --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/rtmp --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-uploadprogress --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-upstream-fair --add-dynamic-module=/build/nginx-mcUg8N/nginx-1.14.0/debian/modules/http-subs-filter

Description

With slice module enabled, this curl command can always trigger the problem:

curl -v -o /dev/null -H "Host: demo.ogslb.com" -H "Range: bytes=4000001-5000000" http://10.1.0.108/sample.mp4

curl output:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   
  Trying 10.1.0.108...
* TCP_NODELAY set
* Connected to 10.1.0.108 (10.1.0.108) port 80 (#0)
> GET /sample.mp4 HTTP/1.1
> Host: demo.ogslb.com
> User-Agent: curl/7.54.0
> Accept: */*
> Range: bytes=4000001-5000000
>
< HTTP/1.1 206 Partial Content
< Server: nginx/1.14.0 (Ubuntu)
< Date: Thu, 10 May 2018 07:12:14 GMT
< Content-Type: video/mp4
< Content-Length: 1000000
< Connection: keep-alive
< Last-Modified: Sun, 28 Feb 2016 19:56:29 GMT
< ETag: "56d350ed-3208b07"
< Expires: Thu, 07 Jun 2018 07:12:14 GMT
< Cache-Control: max-age=2419200
< X-Cache: HIT from bionic
< Content-Range: bytes 4000001-5000000/52464391
<
{ [8297 bytes data]
* transfer closed with 855591 bytes remaining to read
* stopped the pause stream!
 14  976k   14  141k    0     0  5817k      0 --:--:-- --:--:-- --:--:-- 5876k
* Closing connection 0
curl: (18) transfer closed with 855591 bytes remaining to read

When this problem occurs, this can be observed in the debug error log:

2018/05/10 07:12:14 [debug] 13724#13724: *32 http slice response range: 0-4194304/52464391
2018/05/10 07:12:14 [error] 13724#13724: *32 unexpected range in slice response: 0-4194304, client: 10.1.0.45, server: demo.ogslb.com, request: "GET /sample.mp4 HTTP/1.1", subrequest: "/sample.mp4", host: "demo.ogslb.com"

While the error log above stated "0-4194304", the actual Content-Range from upstream is 1 byte fewer, also can be observed earlier in the debug error log:

2018/05/10 07:12:14 [debug] 13724#13724: *32 http proxy header: "Content-Range: bytes 0-4194303/52464391"

The full debug error log regarding this one request is attached.

NGINX config for this server:

proxy_cache_path /data/demo levels=1:2 keys_zone=demo:64m max_size=8g inactive=14d;

upstream demo_backend {
    server 192.254.90.134:80 max_fails=0 fail_timeout=0;
    keepalive 4;
}

server {
    listen 80;

    server_name demo.ogslb.com;

    access_log /var/log/nginx/demo.access.log;
    error_log /var/log/nginx/demo.error.log debug;

    location / {
        slice 4m;

        proxy_set_header Range $slice_range;

        proxy_http_version 1.1;

        proxy_set_header Connection "";

        proxy_set_header Host "demo.ogslb.com";

        proxy_cache demo;

        proxy_cache_revalidate off;

        set $demo_cache_key $scheme://demo.ogslb.com$uri$is_args$args$slice_range;

        proxy_cache_valid 200 206 2419200s;
        expires 2419200s;
        proxy_cache_valid 301 302 2419200s;

        proxy_cache_key $demo_cache_key;

        proxy_cache_min_uses 1;

        proxy_cache_valid 403 404 500 0s;

        add_header X-Cache "$upstream_cache_status from $hostname";

        proxy_pass http://demo_backend;
    }
}

Attachments (1)

demo.error.log (11.8 KB ) - added by Xin Liu 7 years ago.
debug error log

Download all attachments as: .zip

Change History (4)

by Xin Liu, 7 years ago

Attachment: demo.error.log added

debug error log

comment:1 by Roman Arutyunyan, 7 years ago

This line

set $demo_cache_key $scheme://demo.ogslb.com$uri$is_args$args$slice_range;

is evaluated only once - at main request's rewrite phase. Slice subrequests retain the old value of this key with the initial $slice_range equal to bytes=0-4194303. That's why for the second slice in fact the first slice is fetched again, which causes the error.

To fix the issue, eliminate the variable and set proxy_cache_key directly.

in reply to:  1 comment:2 by Xin Liu, 7 years ago

Thanks a lot. I will change my config to set the cache key directly.

comment:3 by Roman Arutyunyan, 7 years ago

Resolution: invalid
Status: newclosed
Note: See TracTickets for help on using tickets.