Mailing List Archive: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication

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

May 11, 2018, 6:58 AM

Post #1 of 8 (1269 views)

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!

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

dridi at varni

May 11, 2018, 7:15 AM

Post #2 of 8 (1269 views)

Permalink

On Fri, May 11, 2018 at 3:58 PM, Sergio Rus <sergio@sergiorus.com> wrote:
> 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
> 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

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

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
_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

sergio at sergiorus

May 11, 2018, 7:38 AM

Post #3 of 8 (1269 views)

Permalink

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

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

guillaume at varnish-software

May 14, 2018, 2:13 AM

Post #4 of 8 (1264 views)

Permalink

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

On Fri, May 11, 2018 at 4:38 PM, Sergio Rus <sergio@sergiorus.com> wrote:

> 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
> varnish-misc@varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

sergio at sergiorus

May 14, 2018, 2:50 AM

Post #5 of 8 (1264 views)

Permalink

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

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

guillaume at varnish-software

May 14, 2018, 2:54 AM

Post #6 of 8 (1264 views)

Permalink

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

--
Guillaume Quintard

On Mon, May 14, 2018 at 11:50 AM, Sergio Rus <sergio@sergiorus.com> wrote:

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

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

dridi at varni

May 14, 2018, 8:44 AM

Post #7 of 8 (1257 views)

Permalink

On Fri, May 11, 2018 at 4:38 PM, Sergio Rus <sergio@sergiorus.com> wrote:
> 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).

> 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).

> 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
_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc

Re: 503 (Service Unavailable) from Varnish on POST request using Digest Authentication [ In reply to ]

sergio at sergiorus

May 14, 2018, 9:51 AM

Post #8 of 8 (1257 views)

Permalink

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

_______________________________________________
varnish-misc mailing list
varnish-misc@varnish-cache.org
https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc