503 (Service Unavailable) from Varnish on POST request using Digest Authentication

[Dridi Boukelmoune]

I would like to validate my theory over a weird issue I had with Varnish 3.

It's reached EOL for a long while now, we aren't supporting Varnish 3...

So we have an endpoint on the server using Digest Authentication and I send
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
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

According to this log record you could have a return(error) in your
VCL, could it be that your larger object triggers some condition in
your VCL that leads to a return(error) statement?

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
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?

If it's the size of the response, only headers count, not the body. In
which case you do have knobs to allow larger HTTP responses:

https://varnish-cache.org/docs/3.0/reference/varnishd.html#run-time-parameters

See http_resp_size and http_resp_hdr_len for respectively the size of
the whole set of response headers and the size of individual headers.

Dridi

[Sergio Rus]

Varnish 3 is quite old, I know. But it's still supported by Ubuntu 14 LTS.
That's why I'm still using it. I will move to a recent version soon.

In regards to the issue, I don't have any return(error) in the VCL I wrote.
So maybe it's coming from somewhere in the default VCL?

I read about those parameters you mentioned already, and even increased
them just for testing, but didn't work at that time, testing bigger files.
So in any case that would be a partial solution, because it would fail at
some point with larger payloads. I'm currently using the default values for
those parameters, 8K, which is very close to the threshold I manually found
in the logs I posted. If you see the payload size, it's nearly 8K. Only
adding or removing a few bytes in the payload changes the behaviour in
Varnish. But the headers size in any case is the same, so that's why I
don't understand what's happening. The payload size seems to be affecting
here.

Cheers

[Guillaume Quintard]

Hi,

Could it simply be your backend complaining? Notably, I'm pretty sure
that WWW-Authenticate
header doesn't come from Varnish, but I may be wrong.

Cheers,
--
Guillaume Quintard

Post by Sergio Rus
Varnish 3 is quite old, I know. But it's still supported by Ubuntu 14 LTS.
That's why I'm still using it. I will move to a recent version soon.
In regards to the issue, I don't have any return(error) in the VCL I
wrote. So maybe it's coming from somewhere in the default VCL?
I read about those parameters you mentioned already, and even increased
them just for testing, but didn't work at that time, testing bigger files.
So in any case that would be a partial solution, because it would fail at
some point with larger payloads. I'm currently using the default values for
those parameters, 8K, which is very close to the threshold I manually found
in the logs I posted. If you see the payload size, it's nearly 8K. Only
adding or removing a few bytes in the payload changes the behaviour in
Varnish. But the headers size in any case is the same, so that's why I
don't understand what's happening. The payload size seems to be affecting
here.
Cheers
_______________________________________________
varnish-misc mailing list
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

[Sergio Rus]

Well, this issue is not really about the authentication process itself. As
I said, the endpoint was using Digest Authentication, but I was
intentionally not including the auth header, so I was expecting to get in
the client a 401 UNAUTHORIZED response, but instead I was getting a 503
coming from Varnish. Everything works fine without Varnish: the client gets
the 401 UNAUTHORIZED in every case, using any payload size. So I just
wanted to understand why Varnish was failing with a 503, and after several
tests I found that reducing the payload size a little bit, keeping it
around 7K-8K, it worked. A few bytes bigger, close to 8K, it failed (503).
To me, it looks like Varnish has some sort of size limit for the objects
that can keep in memory that is not only applied for the headers size, but
also for the payload in POST requests. Unfortunately I couldn't find in the
documentation any parameter related to this. But as I said, increasing a
parameter wouldn't be the right solution, because at some point it would
fail again with bigger payloads.

Cheers

[Guillaume Quintard]

Duh, right, I got really confused with the old log format. Sorry for the
noise
--
Guillaume Quintard

Post by Sergio Rus
Well, this issue is not really about the authentication process itself. As
I said, the endpoint was using Digest Authentication, but I was
intentionally not including the auth header, so I was expecting to get in
the client a 401 UNAUTHORIZED response, but instead I was getting a 503
coming from Varnish. Everything works fine without Varnish: the client gets
the 401 UNAUTHORIZED in every case, using any payload size. So I just
wanted to understand why Varnish was failing with a 503, and after several
tests I found that reducing the payload size a little bit, keeping it
around 7K-8K, it worked. A few bytes bigger, close to 8K, it failed (503).
To me, it looks like Varnish has some sort of size limit for the objects
that can keep in memory that is not only applied for the headers size, but
also for the payload in POST requests. Unfortunately I couldn't find in the
documentation any parameter related to this. But as I said, increasing a
parameter wouldn't be the right solution, because at some point it would
fail again with bigger payloads.
Cheers

[Dridi Boukelmoune]

Post by Sergio Rus
Varnish 3 is quite old, I know. But it's still supported by Ubuntu 14 LTS.
That's why I'm still using it. I will move to a recent version soon.

I don't think Ubuntu supports Varnish in any way. In my book that
would mean you could open a ticket to them and have the package
maintainer track down the bug and provide a fix (especially since _we_
won't do that considering it's EOL).

Post by Sergio Rus
In regards to the issue, I don't have any return(error) in the VCL I wrote.
So maybe it's coming from somewhere in the default VCL?

I don't think so, looking closer I don't see any hint at that (and
don't remember any return(error) in the built-in off the top of my
head).

Post by Sergio Rus
I read about those parameters you mentioned already, and even increased them
just for testing, but didn't work at that time, testing bigger files. So in
any case that would be a partial solution, because it would fail at some
point with larger payloads. I'm currently using the default values for those
parameters, 8K, which is very close to the threshold I manually found in the
logs I posted. If you see the payload size, it's nearly 8K. Only adding or
removing a few bytes in the payload changes the behaviour in Varnish. But
the headers size in any case is the same, so that's why I don't understand
what's happening. The payload size seems to be affecting here.

Very puzzling but sorry, I dipped my toes and don't feel like diving :(

Dridi

[Sergio Rus]

Ok don't mind. I guess it's quite a corner case. Or maybe not so
unusual... Hope it's fixed (if needed) in recent versions of Varnish.
I will test it when I make the move.

Thanks