Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1gKgFA-0007wv-Pz for buildfarm-members@arkaria.postgresql.org; Thu, 08 Nov 2018 09:04:53 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1gKgF9-00031k-5S for buildfarm-members@arkaria.postgresql.org; Thu, 08 Nov 2018 09:04:51 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.89) (envelope-from ) id 1gKgF8-0002yn-P9 for buildfarm-members@lists.postgresql.org; Thu, 08 Nov 2018 09:04:51 +0000 Received: from mail-lf1-x136.google.com ([2a00:1450:4864:20::136]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1gKgF5-00026Q-TP for buildfarm-members@lists.postgresql.org; Thu, 08 Nov 2018 09:04:49 +0000 Received: by mail-lf1-x136.google.com with SMTP id h192so13607510lfg.3 for ; Thu, 08 Nov 2018 01:04:47 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=hagander-net.20150623.gappssmtp.com; s=20150623; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=DqXRMWu9/RUesH8UKuVppFoNjVPxpTqfVFdpwXvLpKk=; b=UvO+99lwXwdkmn29dhG18BR+GslSkXgFHPjzwNi9RzspYKnhVpnA8ZdiT5qFNT6OFO nNi81pB4S9XPrx8/1If4KR3p2jMg8nGO6qEA+HMMbWEukGf8dSAN7tCCfhDDdu/dfCnc H/7EPjlLpsun2IlTHEVEEMDvRjrZNOOdfgLJCCB2Eo1nVmd9sNstiiHgOQGAKn1n3vjD HV3q2/saPu2D+7e2Gw692QMZ1gcVPzCGXQ7kmSOLTREF27S1Ah0HdFiHV6yg+2LTEBqf PFMJI7s/2JSCq7HmbTdvIXp95ZMUkYuLHPf0juCHFRQQK0izZQ1kSYGhjFBRe3OWYTkl VCLg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=DqXRMWu9/RUesH8UKuVppFoNjVPxpTqfVFdpwXvLpKk=; b=dMtiL0nM1E5Witb052iQP3e+XfCT9lj8IP9IFmqY/hff03yEKnbbmPoAFotMh/cagt Is9eSNVneHViuFi7/x0XSHbeToGns3NI78vKv2plDKDFPBBu7i78M0OhP6pE0/ZbEXdl KemW37ZWDXJpec/8eLghWWjMRh7B8Ix2/VOJUXW0NorLBlmFEslflEQjciXHpdxO4k0c t/cwq7HTljZ9JDuLR0sE9U/OCfUrkhrPe1dcv4BIRmb4BEvj7NVQA+I80xbZY686GUe/ RTBv7kAdXOP8E2SebHgldk3OBtVhiwkFegI0o6Q23h98ccyQaZqM5Crw2QnARP/OdjJu A+qQ== X-Gm-Message-State: AGRZ1gK89xpYjPmYqgG1e1SVFmv+OZo98HGPjWNglDRYayVLKMd75YvZ YUvVFSLxRaTRyJwi9eVnyGuGUKCRwb5UTD83UChKHopSMjs= X-Google-Smtp-Source: AJdET5c8vzkh5jFe1He0EmwsZqgrBP+ckUKGGllawkfSvE99TNmU8HYj4Pzy/NDa4Mw7RmlVlRfZYvpEBgdV52bQZWk= X-Received: by 2002:a19:3b9c:: with SMTP id d28mr2354917lfl.30.1541667885703; Thu, 08 Nov 2018 01:04:45 -0800 (PST) MIME-Version: 1.0 References: <428FDD47-5325-4904-9306-F2D6F9D8232D@mac.com> <8832f403-b6ea-e581-b631-a6253731fde6@kaltenbrunner.cc> <85a6c460-108c-875b-4d53-d53c2e4f94b6@kaltenbrunner.cc> In-Reply-To: <85a6c460-108c-875b-4d53-d53c2e4f94b6@kaltenbrunner.cc> From: Magnus Hagander Date: Thu, 8 Nov 2018 10:04:33 +0100 Message-ID: Subject: Re: 503 Backend fetch failed errors To: Stefan Kaltenbrunner Cc: remi_zara@mac.com, buildfarm-members@lists.postgresql.org, sysadmins Content-Type: multipart/alternative; boundary="000000000000b07b3b057a23869b" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk --000000000000b07b3b057a23869b Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Thu, Nov 8, 2018 at 9:42 AM Stefan Kaltenbrunner wrote: > On 11/8/18 9:35 AM, Magnus Hagander wrote: > > > > > > On Thu, Nov 8, 2018 at 9:31 AM Stefan Kaltenbrunner > > wrote: > > > > On 11/8/18 9:19 AM, Magnus Hagander wrote: > > > > > > > > > On Thu, Nov 8, 2018 at 9:01 AM Stefan Kaltenbrunner > > > wrote: > > > > > > On 11/7/18 6:40 PM, R=C3=A9mi Zara wrote: > > > > Hi, > > > > > > Hi R=C3=A9mi! > > > > > > > > > > > I=E2=80=99m getting a lot of these errors with coypu (sev= eral per > > day), > > > but not systematically. > > > > Is this a problem on my end, or is this on the sever end = ? > > > > > > > > Query for: stage=3DOK&animal=3Dcoypu&ts=3D1541573277 > > > > Target: > > > > > > https://buildfarm.postgresql.org/cgi-bin/pgstatus.pl/53b137e7c765b781699b= be73e3aec7751a8c4ab7 > > > > Status Line: 503 Backend fetch failed > > > > Web txn failed with status: 1 > > > > Query for: stage=3DOK&animal=3Dcoypu&ts=3D1541575423 > > > > Target: > > > > > https://buildfarm.postgresql.org/cgi-bin/pgstatus.pl/ > > 1 > > > > Status Line: 503 Backend fetch failed > > > > Web txn failed with status: 1 > > > > > > given the error this is something that is created by the > varnish > > > instance that is in front of the buildfarm. On a quick look = I > > could > > > immediately figure out what the problem is - but it looks > > like you (or > > > somebody else) tried at least to click one of the links abov= e > > using > > > hist > > > desktop browser and got an error about a missing branch > > specification ;) > > > > > > > > > > > > AFAICT: > > > > > > A quick look in the logs indicates that the buildfarm is > responding: > > > - RespHeader Status: 492 bad branch parameter > > > > > > However, 492 is not a valid http status code, so Varnish can't > > handle it > > > and thus returns 503 failure to the client. > > > > I think that is not the actual error that R=C3=A9mi is experiencing= - the > 492 > > case (which is indeed an invalid http error code) only happens when > one > > actually klicks the link in the mail above(which I guess some did a= nd > > you found in the logs) because the actual BF client will add a > > parameter > > to the "Target" URL. > > > > The actual "errors" dont seem to show up in the lighttpd logs afaik= s. > > > > > > Oh, sorry. I was checking the one called "target", I assumed that was > > the URL that failed. > > > > Assuming for the original ones the ts is part of the URL, none of that > > is still in the logs. Or are they post parameters? Do we know exactly > > which URL is actually failing, and when (exactly) this happened? > > well - most of the parameters to each url are in the error report (f.e. > "Query for: stage=3DOK&animal=3Dcoypu&ts=3D1541575423") I dunno whether R= =C3=A9mi > knows which branch that was for? - that one also has a unix timestamp, > though I "think" that is the timestamp from when the build started on > the bf-client and not the ts when the request was made) > > Afaiks the two requests are not at all in the lighly log so only varnish > might have seen them (though its unclear what error it got while > connecting to lighty) > They'll be hard to find in the Varnish log without actually having the URL. There is nothin gin the varnish log with 1541575423 in it at all. And there is nothing with "coypu" and a http 503 in it either. And the log goes back to Nov 6... So my guess is it might be a POST which doesn't actually have the animal name or the timestamp on the URL. I do see some general POSTs returning 503. They all seem to be of the type going to pgstatus.pl like the ones above, so maybe that is the URL after all? If I look at just POSTs there, I see a single one, and it has: - FetchError Resource temporarily unavailable - FetchError straight insufficient bytes "Straight insufficient bytes" means there is a mismatch between Content-Length and the actual amount of data sent/read. And on the backend side: -- FetchError req.body read error: 11 (Resource temporarily unavailable) I believe this means that varnish is actually failing to read the request body from the *client*, in order to pass it on to the server. In that case, it could be that the client sends the wrong length. It does send a content-length header of 4160573 bytes -- perhaps it stops sending data before it gets there. Is that a "reasonable size" package being sent? It's quite a big POST. The error occured 7.25 seconds after Varnish started talking to lighttpd. So it at least did something first. Perhaps if it actually is bigger than 4MB it hit some sort of limit and lighttpd killed the request? --=20 Magnus Hagander Me: https://www.hagander.net/ Work: https://www.redpill-linpro.com/ --000000000000b07b3b057a23869b Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable

On Thu, Nov 8, 2018 at 9:42 AM= Stefan Kaltenbrunner <stefan@kaltenbrunner.cc> wrote:
On 11/8/18 9:35 AM, Magnus Hag= ander wrote:
>
>
> On Thu, Nov 8, 2018 at 9:31 AM Stefan Kaltenbrunner
> <stefan@kaltenbrunner.cc> wrote:
>
>=C2=A0 =C2=A0 =C2=A0On 11/8/18 9:19 AM, Magnus Hagander wrote:
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 > On Thu, Nov 8, 2018 at 9:01 AM Stefan Kaltenb= runner
>=C2=A0 =C2=A0 =C2=A0 > <stefan@kaltenbrunner.cc> wrote:
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0On 11/7/18 6:40 PM, R=C3= =A9mi Zara wrote:
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Hi,
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0Hi R=C3=A9mi!
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > I=E2=80=99m getting = a lot of these errors with coypu (several per
>=C2=A0 =C2=A0 =C2=A0day),
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0but not systematically. >=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Is this a problem on= my end, or is this on the sever end ?
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Query for: stage=3DO= K&animal=3Dcoypu&ts=3D1541573277
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Target:
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0https://buildfarm.postgresql.org/cgi-bin/pgstatus.pl/53b13= 7e7c765b781699bbe73e3aec7751a8c4ab7
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Status Line: 503 Bac= kend fetch failed
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Web txn failed with = status: 1
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Query for: stage=3DO= K&animal=3Dcoypu&ts=3D1541575423
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Target:
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0https://buildfarm.postgresql.org/cgi-bin/pgstatus.pl/1=
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Status Line: 503 Bac= kend fetch failed
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0 > Web txn failed with = status: 1
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0given the error this is so= mething that is created by the varnish
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0instance that is in front = of the buildfarm. On a quick look I
>=C2=A0 =C2=A0 =C2=A0could
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0immediately figure out wha= t the problem is - but it looks
>=C2=A0 =C2=A0 =C2=A0like you (or
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0somebody else) tried at le= ast to click one of the links above
>=C2=A0 =C2=A0 =C2=A0using
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0hist
>=C2=A0 =C2=A0 =C2=A0 >=C2=A0 =C2=A0 =C2=A0desktop browser and got an= error about a missing branch
>=C2=A0 =C2=A0 =C2=A0specification ;)
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 > AFAICT:
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 > A quick look in the logs indicates that the b= uildfarm is responding:
>=C2=A0 =C2=A0 =C2=A0 > -=C2=A0 =C2=A0RespHeader=C2=A0 =C2=A0 =C2=A0S= tatus: 492 bad branch parameter
>=C2=A0 =C2=A0 =C2=A0 >
>=C2=A0 =C2=A0 =C2=A0 > However, 492 is not a valid http status code,= so Varnish can't
>=C2=A0 =C2=A0 =C2=A0handle it
>=C2=A0 =C2=A0 =C2=A0 > and thus returns 503 failure to the client. >
>=C2=A0 =C2=A0 =C2=A0I think that is not the actual error that R=C3=A9mi= is experiencing- the 492
>=C2=A0 =C2=A0 =C2=A0case (which is indeed an invalid http error code) o= nly happens when one
>=C2=A0 =C2=A0 =C2=A0actually klicks the link in the mail above(which I = guess some did and
>=C2=A0 =C2=A0 =C2=A0you found in the logs) because the actual BF client= will add a
>=C2=A0 =C2=A0 =C2=A0parameter
>=C2=A0 =C2=A0 =C2=A0to the "Target" URL.
>
>=C2=A0 =C2=A0 =C2=A0The actual "errors" dont seem to show up = in the lighttpd logs afaiks.
>
>
> Oh, sorry. I was checking the one called "target", I assumed= that was
> the URL that failed.
>
> Assuming for the original ones the ts is part of the URL, none of that=
> is still in the logs. Or are they post parameters? Do we know exactly =
> which URL is actually failing, and when (exactly) this happened?

well - most of the parameters to each url are in the error report (f.e. "Query for: stage=3DOK&animal=3Dcoypu&ts=3D1541575423") I= dunno whether R=C3=A9mi
knows which branch that was for? - that one also has a unix timestamp,
though I "think" that is the timestamp from when the build starte= d on
the bf-client and not the ts when the request was made)

Afaiks the two requests are not at all in the lighly log so only varnish might have seen them (though its unclear what error it got while
connecting to lighty)

They'll be ha= rd to find in the Varnish log without actually having the URL. There is not= hin gin the varnish log with 1541575423 in it at all. And there is nothing = with "coypu" and a http 503 in it either. And the log goes back t= o Nov 6...

So my guess is it might be a POST which= doesn't actually have the animal name or the timestamp on the URL.



=
--=C2=A0 FetchError=C2=A0 =C2=A0 =C2=A0req.body read error: 11 (R= esource temporarily unavailable)

I believe t= his means that varnish is actually failing to read the request body from th= e *client*, in order to pass it on to the server. In that case, it could be= that the client sends the wrong length. It does send a content-length head= er of=C2=A04160573 bytes -- perhaps it stops sending data before it gets th= ere. Is that a "reasonable size" package being sent? It's qui= te a big POST.

The error occured 7.25 seconds afte= r Varnish started talking to lighttpd. So it at least did something first. = Perhaps if it actually is bigger than 4MB it hit some sort of limit and lig= httpd killed the request?

--
<= /div>
--000000000000b07b3b057a23869b--