frequent 504's on VCL

Tim Dunphy bluethundr at gmail.com
Tue Jul 28 17:50:38 CEST 2015


>
> > It's pretty odd how inconsistent this VCL is behaving.
>
> Varnish does not produce 504 responses.
>
> If you see 504, they are coming through from your backend.


Yeah that makes sense.


>
>
>
> > On one load of the page where the graphics are broken I'm seeing this
> error
> > in the logs:
> >    10 TxHeader     c Connection: close
> >    10 TxHeader     c X-Cache: MISS
> >    10 Debug        c Write error, retval = -1, len = 602, errno =
> > Connection reset by peer
> >    10 ReqEnd       c 241437586 1438049428.763690233 1438049435.868994236
> > 0.000110626 7.105183125 0.000120878
>
> Client or backend closed the connection (went away) after 7 seconds.
>
>
> [..]
> > And on 504 errors I'm seeing this result in the logs:
> > 10 TxHeader     c Via: 1.1 varnish
> >    10 TxHeader     c Connection: close
> >    10 TxHeader     c X-Cache: MISS
> >    10 Length       c 316
> >    10 ReqEnd       c 241437672 1438049679.750560999 1438049679.750730276
> > 0.000099182 0.000094652 0.000074625
> >    10 SessionClose c error
> >    10 StatSess     c 54.86.143.49 49821 0 1 1 0 0 0 285 316
> > I'm running 3 back ends using apache 2.4 on Centos 7. I'm running two
> > Varnish nodes at version 3.0.5.
>


When I'm tailing the logs for both apache and varnish at the same time,
this is what I see happening in both logs when the 504 errors occur:

Varnish:

   10 Debug        c Write error, retval = -1, len = 613, errno =
Connection reset by peer
   10 ReqEnd       c 822463677 1438097028.730667830 1438097034.047527790
0.000082970 5.316770077 0.000089884
   10 StatSess     c 54.86.143.49 42935 5 1 1 0 0 1 613 0
    0 CLI          - Rd ping


Apache:

[Tue Jul 28 15:16:11.614501 2015] [authz_core:debug] [pid 6407]
mod_authz_core.c(809): [client 162.243.86.41:55114] AH01626: authorization
result of <RequireAny>: denied (no authenticated user yet)
[Tue Jul 28 15:16:11.614763 2015] [authz_core:debug] [pid 6407]
mod_authz_core.c(809): [client 162.243.86.41:55114] AH01626: authorization
result of Require valid-user : granted
[Tue Jul 28 15:16:11.614767 2015] [authz_core:debug] [pid 6407]
mod_authz_core.c(809): [client 162.243.86.41:55114] AH01626: authorization
result of <RequireAny>: granted
[Tue Jul 28 15:16:11.614841 2015] [authz_core:debug] [pid 6407]
mod_authz_core.c(809): [client 162.243.86.41:55114] AH01626: authorization
result of Require valid-user : denied (no authenticated user yet)

And as you can see from my VCL I am performing some apache basic
authentication, and then passing it through to the back end. And as you can
see my health check also passes authentication headers to the health check
file (healthcheck.php)

Now I could be wrong. But what I think is happening is that varnish is
passing the request to on back end, and authenticating, and then sends
another request to a different host without authentication being passed to
it.

If my theory is correct, this could be fixed by added session persistence
to my varnish VCL. How can I add sticky sessions to varnish? I think that
might do the trick.

Thanks
Tim



>
> Please note that Varnish 3 is end of life.
>
> In the 4.0 release timestamp logging is vastly improved. It would tell
> you if it was the client or backend that went away above, for example.
>
> Another sweet feature in 4.0 is that just-expired content will be served
> while a background fetch is initiated.
>
> > backend web1 {
> >   .host = “10.10.10.25”;
> >   .port = "80";
> >   .connect_timeout = 45s;
> >   .first_byte_timeout = 45s;
> >   .between_bytes_timeout = 45s;
> [probe section]
> >    .timeout = 60s;
>
> These timeouts are way too long.  What client sits around for 45s waiting
> for a web page? Isn't it better to produce clean 503s to the client that
> can be looked for in varnishlog, rather than not responding?


-- 
GPG me!!

gpg --keyserver pool.sks-keyservers.net --recv-keys F186197B


On Tue, Jul 28, 2015 at 7:31 AM, Lasse Karstensen <
lkarsten at varnish-software.com> wrote:

> On Mon, Jul 27, 2015 at 10:24:21PM -0400, Tim Dunphy wrote:
> [cut]
> > It's pretty odd how inconsistent this VCL is behaving.
>
> Varnish does not produce 504 responses.
>
> If you see 504, they are coming through from your backend.
>
>
> > On one load of the page where the graphics are broken I'm seeing this
> error
> > in the logs:
> >    10 TxHeader     c Connection: close
> >    10 TxHeader     c X-Cache: MISS
> >    10 Debug        c Write error, retval = -1, len = 602, errno =
> > Connection reset by peer
> >    10 ReqEnd       c 241437586 1438049428.763690233 1438049435.868994236
> > 0.000110626 7.105183125 0.000120878
>
> Client or backend closed the connection (went away) after 7 seconds.
>
>
> [..]
> > And on 504 errors I'm seeing this result in the logs:
> > 10 TxHeader     c Via: 1.1 varnish
> >    10 TxHeader     c Connection: close
> >    10 TxHeader     c X-Cache: MISS
> >    10 Length       c 316
> >    10 ReqEnd       c 241437672 1438049679.750560999 1438049679.750730276
> > 0.000099182 0.000094652 0.000074625
> >    10 SessionClose c error
> >    10 StatSess     c 54.86.143.49 49821 0 1 1 0 0 0 285 316
> > I'm running 3 back ends using apache 2.4 on Centos 7. I'm running two
> > Varnish nodes at version 3.0.5.
>
> Please note that Varnish 3 is end of life.
>
> In the 4.0 release timestamp logging is vastly improved. It would tell
> you if it was the client or backend that went away above, for example.
>
> Another sweet feature in 4.0 is that just-expired content will be served
> while a background fetch is initiated.
>
> > backend web1 {
> >   .host = “10.10.10.25”;
> >   .port = "80";
> >   .connect_timeout = 45s;
> >   .first_byte_timeout = 45s;
> >   .between_bytes_timeout = 45s;
> [probe section]
> >    .timeout = 60s;
>
> These timeouts are way too long.  What client sits around for 45s waiting
> for a web page? Isn't it better to produce clean 503s to the client that
> can be looked for in varnishlog, rather than not responding?
>
>
> --
> Lasse Karstensen
> Varnish Software AS
>



-- 
GPG me!!

gpg --keyserver pool.sks-keyservers.net --recv-keys F186197B
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20150728/93d3bdd9/attachment-0001.html>


More information about the varnish-misc mailing list