503 Invalid content-range header on partial response with start-end/* #4089

delthas · 2024-03-22T12:19:49Z

Context:

A client makes a partial request against Varnish: Range: bytes=10-19.
Varnish is configured to pass the request
The server responds with Content-Range: bytes 10-19/* (and Transfer-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.

varnish-cache/bin/varnishd/cache/cache_http.c

Line 954 in 8f2c364

if (*lo >= cl || *hi >= cl)

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

The text was updated successfully, but these errors were encountered:

This function returns the content length and puts range indices in lo and hi arguments. A content length of -1 used to be interpreted as something to ignore, but there is a case where the content length may be unknown. Since we can't represent a zero-length range, because both bounds are inclusive, zero now denotes the lack of content-range header. Unknown range units are treated as errors as they wouldn't pass the busyobj check for the range header, even for pass transactions. The only way to use "extension" range units is to turn http_range_support off. The calling convention for http_GetContentRange() remains otherwise the same, and for good measure http_GetContentLength() received a similar description. Fixes varnishcache#4089

dridi · 2024-03-27T09:37:15Z

Can you please give #4091 a try?

delthas · 2024-03-27T15:01:59Z

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.

nigoroll · 2024-05-24T12:17:06Z

@dridi I would think that, with streaming enabled, we would need to add ObjWaitExtend(..., lo, ...).

nigoroll assigned dridi Mar 25, 2024

dridi linked a pull request Mar 27, 2024 that will close this issue

range: New http_GetContentRange() semantics #4091

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

503 Invalid content-range header on partial response with start-end/* #4089

503 Invalid content-range header on partial response with start-end/* #4089

delthas commented Mar 22, 2024 •

edited

dridi commented Mar 27, 2024

delthas commented Mar 27, 2024 •

edited

nigoroll commented May 24, 2024

503 Invalid content-range header on partial response with start-end/* #4089

503 Invalid content-range header on partial response with start-end/* #4089

Comments

delthas commented Mar 22, 2024 • edited

dridi commented Mar 27, 2024

delthas commented Mar 27, 2024 • edited

nigoroll commented May 24, 2024

delthas commented Mar 22, 2024 •

edited

delthas commented Mar 27, 2024 •

edited