Slice module closes connection unexpectedly

[Xin Liu]

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;
    }
}

[Xin Liu]

debug error log

[Roman Arutyunyan]

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.

[Xin Liu]

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