503 (Service Unavailable) from Varnish on POST request using Digest Authentication
Sergio Rus
sergio at sergiorus.com
Fri May 11 13:58:46 UTC 2018
I would like to validate my theory over a weird issue I had with Varnish 3.
So we have an endpoint on the server using Digest Authentication and I send
a POST request to that endpoint without including the auth header:
curl --data-urlencode foobar@/home/foo/bar.txt
https://www.example.com/foobar/
Varnish is set up to pass all the requests going to that endpoint. By
default POST requests are passed too, and I didn't change that behaviour.
So we can assume Varnish is not trying to cache anything here.
I would expect to get the response 401 UNAUTHORIZED from the server, but
instead I get a 503 coming from Varnish. This is the log in Varnish for
that request:
SessionOpen c 127.0.0.1 34005 localhost:6081
ReqStart c 127.0.0.1 34005 1873165756
RxRequest c POST
RxURL c /foobar/
RxProtocol c HTTP/1.0
RxHeader c Host: www.example.com
RxHeader c X-Real-IP: 123.123.123.123
RxHeader c X-Forwarded-For: 123.123.123.123
RxHeader c X-Forwarded-Protocol: https
RxHeader c X-SSL-Protocol: TLSv1.2
RxHeader c X-Forwarded-Proto: https
RxHeader c X-Url-Scheme: https
RxHeader c Connection: close
RxHeader c Content-Length: 7811
RxHeader c User-Agent: foobar
RxHeader c Accept: */*
RxHeader c Content-Type: application/x-www-form-urlencoded
VCL_call c recv pass
VCL_call c hash
Hash c /foobar/
Hash c www.example.com
VCL_return c hash
VCL_call c pass pass
Backend c 17 default default
TTL c 1873165756 RFC -1 -1 -1 1526037072 0 1526037072 0 0
VCL_call c fetch
TTL c 1873165756 VCL -1 3600 -1 1526037072 -0
TTL c 1873165756 VCL 120 3600 -1 1526037072 -0
VCL_return c hit_for_pass
ObjProtocol c HTTP/1.1
ObjResponse c UNAUTHORIZED
ObjHeader c Server: foobar
ObjHeader c Date: Fri, 11 May 2018 11:11:12 GMT
ObjHeader c Content-Type: text/html; charset=utf-8
ObjHeader c WWW-Authenticate: Digest
nonce="1526677072.03:1636:cb98ghghgh49495f1174226f25a2f02c79",
realm="foobar", algorithm="MD5",
opaque="9cbc87eb65454ff85bff73b2b38c06c34343e8", qop="auth", stale="false"
ObjHeader c Content-Language: en-us
ObjHeader c Vary: Accept-Encoding, Cookie, User-Agent
VCL_call c error deliver
VCL_call c deliver deliver
TxProtocol c HTTP/1.1
TxStatus c 503
TxResponse c Service Unavailable
TxHeader c Server: Varnish
TxHeader c Content-Type: text/html; charset=utf-8
TxHeader c Retry-After: 5
TxHeader c Content-Length: 419
TxHeader c Accept-Ranges: bytes
TxHeader c Date: Fri, 11 May 2018 11:11:12 GMT
TxHeader c X-Varnish: 1873165756
TxHeader c Age: 0
TxHeader c Via: 1.1 varnish
TxHeader c Connection: close
Length c 419
ReqEnd c 1873165756 1526037072.059784174 1526037072.061955214
0.000038624 0.002078533 0.000092506
But reducing the size of the payload a little bit, it works:
SessionOpen c 127.0.0.1 36019 localhost:6081
ReqStart c 127.0.0.1 36019 1873166315
RxRequest c POST
RxURL c /foobar/
RxProtocol c HTTP/1.0
RxHeader c Host: www.example.com
RxHeader c X-Real-IP: 123.123.123.123
RxHeader c X-Forwarded-For: 123.123.123.123
RxHeader c X-Forwarded-Protocol: https
RxHeader c X-SSL-Protocol: TLSv1.2
RxHeader c X-Forwarded-Proto: https
RxHeader c X-Url-Scheme: https
RxHeader c Connection: close
RxHeader c Content-Length: 7261
RxHeader c User-Agent: foobar
RxHeader c Accept: */*
RxHeader c Content-Type: application/x-www-form-urlencoded
VCL_call c recv pass
VCL_call c hash
Hash c /foobar/
Hash c www.example.com
VCL_return c hash
VCL_call c pass pass
Backend c 17 default default
TTL c 1873166315 RFC -1 -1 -1 1526037112 0 1526037112 0 0
VCL_call c fetch
TTL c 1873166315 VCL -1 3600 -1 1526037112 -0
TTL c 1873166315 VCL 120 3600 -1 1526037112 -0
VCL_return c hit_for_pass
ObjProtocol c HTTP/1.1
ObjResponse c UNAUTHORIZED
ObjHeader c Server: gunicorn/19.0.0
ObjHeader c Date: Fri, 11 May 2018 11:11:52 GMT
ObjHeader c Content-Type: text/html; charset=utf-8
ObjHeader c WWW-Authenticate: Digest
nonce="15260334112.14:3917:d3d558ed34342e8e723d8219bf3b20fc38",
realm="foobar", algorithm="MD5",
opaque="b32cd3f7b82213212397ded88c00ea06f111a29c", qop="auth", stale="false"
ObjHeader c Content-Language: en-us
ObjHeader c Vary: Accept-Encoding, Cookie, User-Agent
VCL_call c deliver deliver
TxProtocol c HTTP/1.1
TxStatus c 401
TxResponse c UNAUTHORIZED
TxHeader c Server: gunicorn/19.0.0
TxHeader c Content-Type: text/html; charset=utf-8
TxHeader c WWW-Authenticate: Digest
nonce="15260334112.14:3917:d3d558ed34342e8e723d8219bf3b20fc38",
realm="foobar", algorithm="MD5",
opaque="b32cd3f7b82213212397ded88c00ea06f111a29c", qop="auth", stale="false"
TxHeader c Content-Language: en-us
TxHeader c Vary: Accept-Encoding, Cookie, User-Agent
TxHeader c Content-Length: 0
TxHeader c Accept-Ranges: bytes
TxHeader c Date: Fri, 11 May 2018 11:11:52 GMT
TxHeader c X-Varnish: 1873166315
TxHeader c Age: 0
TxHeader c Via: 1.1 varnish
TxHeader c Connection: close
Length c 0
ReqEnd c 1873166315 1526037112.192578554 1526037112.194519758
0.000039816 0.001864910 0.000076294
Why is that happening? Well, I have my own theory and this is what I would
like to validate here. I think it's because there is some sort of limit set
in Varnish for the size of the objects to keep in memory, so when the
request size (headers + payload) is bigger than a threshold, and the
request can not be delivered to the backend, it fails with 503. But if the
request is smaller, Varnish keeps the object in memory and just sends to
the client the response from the backend.
Anyone here that could help me understand this weird behaviour?
Thanks!
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20180511/11eabea4/attachment-0001.html>
More information about the varnish-misc
mailing list