Varnish 503ing on ~1/100 POSTs

Stewart Robinson stewsnooze at gmail.com
Tue Mar 8 23:11:39 CET 2011


On 8 Mar 2011, at 16:07, Ben Dodd <B.Dodd at comicrelief.com> wrote:

Hello,

This is only to add we've been experiencing exactly the same issue and are
desperately searching for a solution. Can anyone help?

 Thanks, Ben

 On 8 Mar 2011, at 21:55, <varnish-misc-request at varnish-cache.org> <
varnish-misc-request at varnish-cache.org> wrote:

-----Original Message-----
From: varnish-misc-bounces at varnish-cache.org
[mailto:varnish-misc-bounces at varnish-cache.org] On Behalf Of Ronan
Mullally
Sent: March-08-11 3:38 PM
To: varnish-misc at varnish-cache.org
Subject: Varnish 503ing on ~1/100 POSTs

I'm seeing intermittant 503s on POSTs to a fairly busy VBulletin
website.
The current load is light (up to a couple of thousand active sessions,
peak is around five thousand).  Varnish has a fairly simple config with
a director consisting of two Apache backends:

backend backend1 {
        .host = "1.2.3.4";
        .port = "80";
        .connect_timeout = 5s;
        .first_byte_timeout = 90s;
        .between_bytes_timeout = 90s;
        .probe = {
                .timeout = 5s;
                .interval = 5s;
                .window = 5;
                .threshold = 3;
                .request =
                        "HEAD /favicon.ico HTTP/1.0"
                        "X-Forwarded-For: 1.2.3.4"
                        "Connection: close";
        }
}

backend backend2 {
        .host = "5.6.7.8";
        .port = "80";
        .connect_timeout = 5s;
        .first_byte_timeout = 90s;
        .between_bytes_timeout = 90s;
        .probe = {
                .timeout = 5s;
                .interval = 5s;
                .window = 5;
                .threshold = 3;
                .request =
                        "HEAD /favicon.ico HTTP/1.0"
                        "X-Forwarded-For: 5.6.7.8"
                        "Connection: close";
        }
}

The numbers are modest, but significant - about 1 POST in a hundred
fails.
I've upped the backend timeouts to 90 seconds (first_byte /
between_bytes)
and I'm pretty confident they're responding in well under that time.

varnishlog does not show any backend health changes.  A typical event
looks like:

Varnish:
a.b.c.d - - [08/Mar/2011:14:48:03 +0000] "POST
http://www.sitename.net/newreply.php?do=postreply&t=285227 HTTP/1.1" 503
2623

Backend:
a.b.c.d - - [08/Mar/2011:14:48:03 +0000] "POST
/newreply.php?do=postreply&t=285227 HTTP/1.1" 200 2686

The POST appears to work fine on the backend but the user gets a 503
from
Varnish.  It's not unusual to see users getting the error several times
in
a row (presumably re-submitting the post):

a.b.c.d - - [08/Mar/2011:18:21:23 +0000] "POST
http://www.sitename.net/editpost.php?do=updatepost&p=9405408 HTTP/1.1"
503 2623
a.b.c.d - - [08/Mar/2011:18:21:36 +0000] "POST
http://www.sitename.net/editpost.php?do=updatepost&p=9405408 HTTP/1.1"
503 2623
a.b.c.d - - [08/Mar/2011:18:21:50 +0000] "POST
http://www.sitename.net/editpost.php?do=updatepost&p=9405408 HTTP/1.1"
503 2623

A typical request is below.  The first attempt fails with:

 33 FetchError   c http first read error: -1 0 (Success)

there is presumably a restart and the second attempt (sometimes to
backend1, sometimes backend2) fails with:

 33 FetchError   c backend write error: 11 (Resource temporarily
unavailable)

This pattern has been the same on the few transactions I've examined in
detail.  The full log output of a typical request is below.

I'm stumped.  Has anybody got any ideas what might be causing this?


-Ronan


  33 RxRequest    c POST
  33 RxURL        c /ajax.php
  33 RxProtocol   c HTTP/1.1
  33 RxHeader     c Accept: */*
  33 RxHeader     c Accept-Language: nl-be
  33 RxHeader     c Referer: http://www.redcafe.net/
  33 RxHeader     c x-requested-with: XMLHttpRequest
  33 RxHeader     c Content-Type: application/x-www-form-urlencoded;
charset=UTF-8
  33 RxHeader     c Accept-Encoding: gzip, deflate
  33 RxHeader     c User-Agent: Mozilla/4.0 (compatible; ...)
  33 RxHeader     c Host: www.sitename.net
  33 RxHeader     c Content-Length: 82
  33 RxHeader     c Connection: Keep-Alive
  33 RxHeader     c Cache-Control: no-cache
  33 RxHeader     c Cookie: ...
  33 VCL_call     c recv
  33 VCL_return   c pass
  33 VCL_call     c hash
  33 VCL_return   c hash
  33 VCL_call     c pass
  33 VCL_return   c pass
  33 Backend      c 44 backend backend1
  44 TxRequest    b POST
  44 TxURL        b /ajax.php
  44 TxProtocol   b HTTP/1.1
  44 TxHeader     b Accept: */*
  44 TxHeader     b Accept-Language: nl-be
  44 TxHeader     b Referer: http://www.sitename.net/
  44 TxHeader     b x-requested-with: XMLHttpRequest
  44 TxHeader     b Content-Type: application/x-www-form-urlencoded;
charset=UTF-8
  44 TxHeader     b User-Agent: Mozilla/4.0 (compatible; ...)
  44 TxHeader     b Host: www.sitename.net
  44 TxHeader     b Content-Length: 82
  44 TxHeader     b Cache-Control: no-cache
  44 TxHeader     b Cookie: ...
  44 TxHeader     b Accept-Encoding: gzip
  44 TxHeader     b X-Forwarded-For: a.b.c.d
  44 TxHeader     b X-Varnish: 657185708
* 33 FetchError   c http first read error: -1 0 (Success)
  44 BackendClose b backend1
  33 Backend      c 47 backend backend2
  47 TxRequest    b POST
  47 TxURL        b /ajax.php
  47 TxProtocol   b HTTP/1.1
  47 TxHeader     b Accept: */*
  47 TxHeader     b Accept-Language: nl-be
  47 TxHeader     b Referer: http://www.sitename.net/
  47 TxHeader     b x-requested-with: XMLHttpRequest
  47 TxHeader     b Content-Type: application/x-www-form-urlencoded;
charset=UTF-8
  47 TxHeader     b User-Agent: Mozilla/4.0 (compatible; ...)
  47 TxHeader     b Host: www.sitename.net
  47 TxHeader     b Content-Length: 82
  47 TxHeader     b Cache-Control: no-cache
  47 TxHeader     b Cookie: ...
  47 TxHeader     b Accept-Encoding: gzip
  47 TxHeader     b X-Forwarded-For: a.b.c.d
  47 TxHeader     b X-Varnish: 657185708
* 33 FetchError   c backend write error: 11 (Resource temporarily
unavailable)
  47 BackendClose b backend2
  33 VCL_call     c error
  33 VCL_return   c deliver
  33 VCL_call     c deliver
  33 VCL_return   c deliver
  33 TxProtocol   c HTTP/1.1
  33 TxStatus     c 503
  33 TxResponse   c Service Unavailable
  33 TxHeader     c Server: Varnish
  33 TxHeader     c Retry-After: 0
  33 TxHeader     c Content-Type: text/html; charset=utf-8
  33 TxHeader     c Content-Length: 2623
  33 TxHeader     c Date: Tue, 08 Mar 2011 17:08:33 GMT
  33 TxHeader     c X-Varnish: 657185708
  33 TxHeader     c Age: 3
  33 TxHeader     c Via: 1.1 varnish
  33 TxHeader     c Connection: close
  33 Length       c 2623
  33 ReqEnd       c 657185708 1299604110.559967279 1299604113.447372913
0.000037670 2.887368441 0.000037193
  33 SessionClose c error
  33 StatSess     c a.b.c.d 50044 3 1 1 0 1 0 235 2623



------------------------------
Comic Relief 1st Floor 89 Albert Embankment London SE1 7TP Tel: 020 7820
2000 Fax: 020 7820 2222 red at comicrelief.com www.comicrelief.com

Comic Relief is the operating name of Charity Projects, a company limited by
guarantee and registered in England no. 1806414; registered charity 326568
(England & Wales) and SC039730 (Scotland). Comic Relief Ltd is a subsidiary
of Charity Projects and registered in England no. 1967154. Registered
offices: Hanover House, 14 Hanover Square, London W1S 1HP. VAT no.
773865187.

This email (and any attachment) may contain confidential and/or privileged
information. If you are not the intended addressee, you must not use,
disclose, copy or rely on anything in this email and should contact the
sender and delete it immediately. The views of the author are not
necessarily those of Comic Relief. We cannot guarantee that this email (and
any attachment) is virus free or has not been intercepted and amended, so do
not accept liability for any damage resulting from software viruses. You
should carry out your own virus checks.

_______________________________________________
varnish-misc mailing list
varnish-misc at varnish-cache.org
http://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc


Whilst this may not be a fix to a possible bug in varnish have you tried
switching posts to pipe instead of pass?

Stew
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20110308/1dd9e251/attachment-0003.html>


More information about the varnish-misc mailing list