varnishcache
503 Invalid content-range header on partial response with start-end/*
Context:
- A client makes a partial request against Varnish:
Range: bytes=10-19. - Varnish is configured to
passthe request - The server responds with
Content-Range: bytes 10-19/*(andTransfer-Encoding: chunked, but not sure if that's necessary to reproduce)
Expected behavior:
- Varnish passes the partial response through (because
Content-Range: bytes 10-19/*appears to be correct?)
Current behavior:
- Varnish responds with a 503; varnishlog shows
Invalid content-range header
After delving deeper, this happens in cache_http.c at http_GetContentRange: lo gets set to 10, hi to 19, cl to -1, as expected; but then if (*lo >= cl || *hi >= cl) return (-2); returns -2 and fails the request, because 10 >= -1.
https://github.com/varnishcache/varnish-cache/blob/8f2c3648b82a6e527ef86c1d6f228b94583b9e0a/bin/varnishd/cache/cache_http.c#L954
Not sure I fully understand the function, but should the condition be closer to if (*hi - *lo < cl) return (-2); ?
Here's a MWE VTC. Feel free to reuse.
varnishtest "Content-Range failure reproducer"
server s1 {
rxreq
txresp -status 206 -hdr "Transfer-Encoding: chunked" -hdr "content-range: bytes 10-19/*"
chunkedlen 10
chunkedlen 0
} -start
varnish v1 -vcl+backend {
sub vcl_recv {
return (pass);
}
} -start
client c1 {
txreq -hdr "range: bytes=10-19"
rxresp
expect resp.status != 503
} -run
Can you please give https://github.com/varnishcache/varnish-cache/pull/4091 a try?
Thanks for the quick fix.
Testing with #4091, the issue looks partially fixed (no more 503 Invalid content-range header); but I'm seeing a very strange behavior. Varnish is sometimes responding with 416 "Requested Range Not Satisfiable" (just after it logs Filters range). When I keep making the same request, it sometimes responds with 416 and sometimes with 206. I can't reproduce it in varnishtest (always 206).
My cURL (repeated many times): curl -v 'http://varnish/file.mp4' -H 'Range: bytes=52364-92712' -H 'Cache-Control: no-cache'
varnishlog (censored) for 206:
* << BeReq >> 427600
- Begin bereq 427599 pass
- VCL_use boot
- Timestamp Start: 1711550661.644483 0.000000 0.000000
- BereqMethod GET
- BereqURL /file.mp4
- BereqProtocol HTTP/1.1
- BereqHeader Host: varnish
- BereqHeader User-Agent: curl/8.6.0
- BereqHeader Accept: */*
- BereqHeader Range: bytes=52364-92712
- BereqHeader Cache-Control: no-cache
- BereqHeader X-Varnish: 427600
- VCL_call BACKEND_FETCH
- BereqURL /file.mp4
- BereqUnset Via: 1.1 varnish (Varnish/7.4)
- BereqUnset Host: varnish
- VCL_return fetch
- Timestamp Fetch: 1711550661.644500 0.000016 0.000016
- BereqHeader Host: source
- Timestamp Connected: 1711550661.644511 0.000028 0.000011
- BackendOpen 32 source source 80 x 34718 reuse
- Timestamp Bereq: 1711550661.644561 0.000077 0.000049
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Wed, 27 Mar 2024 14:44:21 GMT
- BerespHeader Accept-ranges: bytes
- BerespHeader Content-Range: bytes 52364-92712/*
- BerespHeader Transfer-Encoding: chunked
- BerespHeader Content-Type: video/mp4
- Timestamp Beresp: 1711550661.655290 0.010806 0.010728
- VCL_call BACKEND_RESPONSE
- TTL VCL 60 0 0 1711550662 uncacheable
- VCL_return deliver
- Timestamp Process: 1711550661.655341 0.010857 0.000051
- Filters
- Storage malloc Transient
- Fetch_Body 2 chunked stream
- BackendClose 32 source recycle
- Timestamp BerespBody: 1711550661.655469 0.010985 0.000128
- Length 40349
- BereqAcct 444 0 444 310 40349 40659
- End
* << Request >> 427599
- Begin req 427598 rxreq
- Timestamp Start: 1711550661.644366 0.000000 0.000000
- Timestamp Req: 1711550661.644366 0.000000 0.000000
- VCL_use boot
- ReqStart x 57136 http
- ReqMethod GET
- ReqURL /file.mp4
- ReqProtocol HTTP/1.1
- ReqHeader Host: varnish
- ReqHeader User-Agent: curl/8.6.0
- ReqHeader Accept: */*
- ReqHeader Range: bytes=52364-92712
- ReqHeader Cache-Control: no-cache
- VCL_call RECV
- ReqURL /file.mp4
- VCL_return pass
- VCL_call HASH
- VCL_return lookup
- VCL_call PASS
- VCL_Log action:miss
- VCL_return fetch
- Link bereq 427600 pass
- Timestamp Fetch: 1711550661.655399 0.011033 0.011033
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 27 Mar 2024 14:44:21 GMT
- RespHeader Accept-ranges: bytes
- RespHeader Content-Range: bytes 52364-92712/*
- RespHeader Content-Type: video/mp4
- RespHeader X-Varnish: 427599
- RespHeader Age: 0
- VCL_call DELIVER
- RespUnset X-Varnish: 427599
- VCL_return deliver
- Timestamp Process: 1711550661.655452 0.011086 0.000052
- Filters range
- RespHeader Content-Range: bytes 52364-92712/*
- RespProtocol HTTP/1.1
- RespStatus 206
- RespReason Partial Content
- RespHeader Connection: keep-alive
- RespHeader Transfer-Encoding: chunked
- Timestamp Resp: 1711550661.655493 0.011126 0.000040
- ReqAcct 246 0 246 446 0 446
- End
varnishlog (censored) for 416:
* << BeReq >> 165189
- Begin bereq 165188 pass
- VCL_use boot
- Timestamp Start: 1711550661.048146 0.000000 0.000000
- BereqMethod GET
- BereqURL /file.mp4
- BereqProtocol HTTP/1.1
- BereqHeader Host: varnish
- BereqHeader User-Agent: curl/8.6.0
- BereqHeader Accept: */*
- BereqHeader Range: bytes=52364-92712
- BereqHeader Cache-Control: no-cache
- BereqHeader X-Varnish: 165189
- VCL_call BACKEND_FETCH
- BereqURL /file.mp4
- BereqUnset Via: 1.1 varnish (Varnish/7.4)
- BereqUnset Host: varnish
- VCL_return fetch
- Timestamp Fetch: 1711550661.048198 0.000051 0.000051
- BereqHeader Host: source
- Timestamp Connected: 1711550661.048211 0.000065 0.000013
- BackendOpen 32 source source 80 x 34718 reuse
- Timestamp Bereq: 1711550661.048265 0.000118 0.000053
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Wed, 27 Mar 2024 14:44:21 GMT
- BerespHeader Accept-ranges: bytes
- BerespHeader Content-Range: bytes 52364-92712/*
- BerespHeader Transfer-Encoding: chunked
- BerespHeader Content-Type: video/mp4
- Timestamp Beresp: 1711550661.053141 0.004994 0.004876
- VCL_call BACKEND_RESPONSE
- TTL VCL 60 0 0 1711550661 uncacheable
- VCL_return deliver
- Timestamp Process: 1711550661.053237 0.005091 0.000096
- Filters
- Storage malloc Transient
- Fetch_Body 2 chunked stream
- BackendClose 32 source recycle
- Timestamp BerespBody: 1711550661.053336 0.005190 0.000098
- Length 40349
- BereqAcct 444 0 444 310 40349 40659
- End
* << Request >> 165188
- Begin req 165187 rxreq
- Timestamp Start: 1711550661.047969 0.000000 0.000000
- Timestamp Req: 1711550661.047969 0.000000 0.000000
- VCL_use boot
- ReqStart x 57134 http
- ReqMethod GET
- ReqURL /file.mp4
- ReqProtocol HTTP/1.1
- ReqHeader Host: varnish
- ReqHeader User-Agent: curl/8.6.0
- ReqHeader Accept: */*
- ReqHeader Range: bytes=52364-92712
- ReqHeader Cache-Control: no-cache
- VCL_call RECV
- ReqURL /file.mp4
- VCL_return pass
- VCL_call HASH
- VCL_return lookup
- VCL_call PASS
- VCL_Log action:miss
- VCL_return fetch
- Link bereq 165189 pass
- Timestamp Fetch: 1711550661.053407 0.005437 0.005437
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Wed, 27 Mar 2024 14:44:21 GMT
- RespHeader Accept-ranges: bytes
- RespHeader Content-Range: bytes 52364-92712/*
- RespHeader Content-Type: video/mp4
- RespHeader X-Varnish: 165188
- RespHeader Age: 0
- VCL_call DELIVER
- RespUnset X-Varnish: 165188
- VCL_return deliver
- Timestamp Process: 1711550661.053432 0.005462 0.000024
- Filters range
- RespHeader Content-Range: bytes */40349
- RespProtocol HTTP/1.1
- RespStatus 416
- RespReason Requested Range Not Satisfiable
- RespHeader Content-Length: 0
- RespHeader Connection: keep-alive
- Timestamp Resp: 1711550661.053485 0.005515 0.000052
- ReqAcct 246 0 246 447 0 447
- End
The varnishlogs are exactly the same (except for stamps and ids), except after the range filter, where in one case Varnish responds with 206, and in the other case it replies with 416. Repeating the cURL varies between the two responses, seemingly randomly.
Edit: Managed to enable the Debug logs and got RANGE_FAIL low range beyond object on 416.
This happens in http_GetRange:
https://github.com/varnishcache/varnish-cache/blob/master/bin/varnishd/cache/cache_http.c#L1010-L1024
if (len <= 0)
return (NULL); // Allow 200 response
if (*lo < 0) {
assert(*hi > 0);
*lo = len - *hi;
if (*lo < 0)
*lo = 0;
*hi = len - 1;
} else if (len >= 0 && (*hi >= len || *hi < 0)) {
*hi = len - 1;
}
if (*lo >= len)
return ("low range beyond object");
In both cases, *lo = 33318; *hi=16769 (at the time of return). However in the 206 case, len = -1, so this returns early, and in the 416 case, len = 16770.
Looks like some race condition?
Edit: Looks like some race condition because adding a sleep in vcl_deliver makes it 406 almost 100% instead of 10%:
sub vcl_deliver {
C{
usleep(100000);
}C
return (deliver);
}
Sadly I still cannot reproduce this in varnishtest.
@dridi I would think that, with streaming enabled, we would need to add ObjWaitExtend(..., lo, ...).
I started seeing this after doing an upgrade from Varnish 6 to 7. Only happening with one of my backends that runs Backrop CMS
After some searching, I was able to 'make it work' by adding this to my VCL according to https://varnish-cache.org/docs/7.4/whats-new/upgrading-7.0.html. I'm not exactly sure if this is the correct way to fix it.
sub vcl_backend_response {
if (!bereq.http.range) {
unset beresp.http.content-range;
}
}
Happy to provide more information if needed:
* << Request >> 589975
- Begin req 589974 rxreq
- Timestamp Start: 1730958334.756315 0.000000 0.000000
- Timestamp Req: 1730958334.756315 0.000000 0.000000
- VCL_use boot
- ReqStart 63.247.147.163 5246 a0
- ReqMethod GET
- ReqURL /unibianet/
- ReqProtocol HTTP/1.1
- ReqHeader Host: www.unibia.com
- ReqHeader User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:132.0) Gecko/20100101 Firefox/132.0
- ReqHeader Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
- ReqHeader Accept-Language: en-US,en;q=0.5
- ReqHeader Accept-Encoding: gzip, deflate
- ReqHeader Connection: keep-alive
- ReqHeader Cookie: _ga=GA1.2.1909873704.1721884095
- ReqHeader Upgrade-Insecure-Requests: 1
- ReqHeader Priority: u=0, i
- ReqHeader X-Forwarded-For: 63.247.147.163
- ReqHeader Via: 1.1 cache.fl.pacyworld.com (Varnish/7.5)
- VCL_call RECV
- VCL_return pass
- VCL_call HASH
- VCL_return lookup
- VCL_call PASS
- VCL_return fetch
- Link bereq 589976 pass
- Timestamp Fetch: 1730958334.771505 0.015189 0.015189
- RespProtocol HTTP/1.1
- RespStatus 503
- RespReason Backend fetch failed
- RespHeader Date: Thu, 07 Nov 2024 05:45:34 GMT
- RespHeader Server: Varnish
- RespHeader Content-Type: text/html; charset=utf-8
- RespHeader Retry-After: 5
- RespHeader X-Varnish: 589975
- RespHeader Age: 0
- RespHeader Via: 1.1 cache.fl.pacyworld.com (Varnish/7.5)
- VCL_call DELIVER
- VCL_return deliver
- Timestamp Process: 1730958334.771520 0.015204 0.000014
- Filters
- RespHeader Content-Length: 283
- RespHeader Connection: keep-alive
- Timestamp Resp: 1730958334.771547 0.015231 0.000026
- ReqAcct 395 0 395 266 283 549
- End
** << BeReq >> 589976
-- Begin bereq 589975 pass
-- VCL_use boot
-- Timestamp Start: 1730958334.756391 0.000000 0.000000
-- BereqMethod GET
-- BereqURL /unibianet/
-- BereqProtocol HTTP/1.1
-- BereqHeader Host: www.unibia.com
-- BereqHeader User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:132.0) Gecko/20100101 Firefox/132.0
-- BereqHeader Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
-- BereqHeader Accept-Language: en-US,en;q=0.5
-- BereqHeader Accept-Encoding: gzip, deflate
-- BereqHeader Cookie: _ga=GA1.2.1909873704.1721884095
-- BereqHeader Upgrade-Insecure-Requests: 1
-- BereqHeader Priority: u=0, i
-- BereqHeader X-Forwarded-For: 63.247.147.163
-- BereqHeader Via: 1.1 cache.fl.pacyworld.com (Varnish/7.5)
-- BereqHeader X-Varnish: 589976
-- VCL_call BACKEND_FETCH
-- VCL_return fetch
-- Timestamp Fetch: 1730958334.756414 0.000022 0.000022
-- Timestamp Connected: 1730958334.756484 0.000092 0.000069
-- BackendOpen 27 default 127.0.0.1 8080 127.0.0.1 58985 connect
-- Timestamp Bereq: 1730958334.756550 0.000158 0.000066
-- BerespProtocol HTTP/1.1
-- BerespStatus 200
-- BerespReason OK
-- BerespHeader cache-control: public, max-age=600
-- BerespHeader content-language: en
-- BerespHeader content-length: 32271
-- BerespHeader content-range: 0-32270/32271
-- BerespHeader content-type: text/html; charset=utf-8
-- BerespHeader date: Thu, 07 Nov 2024 05:45:34 GMT
-- BerespHeader etag: "1730958317"
-- BerespHeader expires: Fri, 16 Jan 2015 07:50:00 GMT
-- BerespHeader last-modified: Thu, 07 Nov 2024 05:45:17 +0000
-- BerespHeader server: Apache/2.4.62 (FreeBSD) PHP/8.3.12
-- BerespHeader vary: Cookie
-- BerespHeader x-backdrop-cache: HIT
-- BerespHeader x-content-type-options: nosniff
-- BerespHeader x-frame-options: SAMEORIGIN
-- BerespHeader x-generator: Backdrop CMS 1 (https://backdropcms.org)
-- BerespHeader x-powered-by: PHP/8.3.12
-- BerespHeader x-pacyworld-cache: Naples, FL
-- Timestamp Beresp: 1730958334.771291 0.014899 0.014741
-- VCL_call BACKEND_RESPONSE
-- VCL_return deliver
-- Error Invalid content-range header
-- BackendClose 27 default close null
-- Timestamp Error: 1730958334.771328 0.014936 0.000036
-- BerespProtocol HTTP/1.1
-- BerespStatus 503
-- BerespReason Backend fetch failed
-- BerespHeader Date: Thu, 07 Nov 2024 05:45:34 GMT
-- BerespHeader Server: Varnish
-- VCL_call BACKEND_ERROR
-- BerespHeader Content-Type: text/html; charset=utf-8
-- BerespHeader Retry-After: 5
-- VCL_return deliver
-- Storage malloc Transient
-- Length 283
-- BereqAcct 498 0 498 570 0 570
-- End
