Hi Colin,
On Tue, Oct 21, 2014 at 04:36:25PM -0500, Colin Ingarfield wrote:
> On 10/21/2014 03:59 PM, Cyril Bonté wrote:
> >Hi Colin,
> >
> >Le 21/10/2014 22:05, Colin Ingarfield a écrit :
> >>Hello,
> >>
> >>Please help me understand this output in the haproxy log file:
> >>
> >>Oct 21 14:53:17 host haproxy[4526]: 206.x.x.x:56480
> >>[21/Oct/2014:14:53:16.560] http-in~ servers/server1 60/0/0/527/587 200
> >>243 - - LRVN 12/12/1/2/0 0/0 "POST /ctx/cometd/connect HTTP/1.1"
> >>
> >>The first two letters of the termination state are confusing me.
> >>"L" indicates the session was processed by haproxy and not sent to a
> >>server
> >>"R" proxy was waiting for a complete request from the client
> >>
> >>It also shows a status code of 200.
> >>
> >>What circumstances could cause this? I'm testing haproxy now and it
> >>(and the 2 servers behind it) are under no real load. So far I have
> >>only observed this with Chrome Version 38.0.2125.104 (64-bit) linux. I
> >>do not see any errors in the Chrome Network panel and the application
> >>appears to work correctly.
> >>
> >>Any insight greatly appreciated.
> >
> >From a quick test I made, I think you have some redirect rules in your
> >haroxy configuration.
> >And it appears that flags are not reset on a keep-alived connection.
> >
> >Please check in your logs if a previous request already used port
> >56480 with a 302 status.
> >
> >This is maybe a bug, but I won't have time tonight to investigate more.
> >
> >
> >To reproduce it, I used this minimal configuration :
> >listen testflag :9000
> > mode http
> > option httplog
> > log /dev/log local7 debug err
> >
> > http-request redirect location /redirected if { path / }
> >
> > server s localhost:80
> >
> >$ curl -L http://localhost:9000/
> >Oct 21 22:53:40 asus haproxy[11282]: 127.0.0.1:33985
> >[21/Oct/2014:22:53:40.094] testflag testflag/<NOSRV> 0/-1/-1/-1/0 302
> >89 - - LR-- 1/1/0/0/3 0/0 "GET / HTTP/1.1"
> >Oct 21 22:53:40 asus haproxy[11282]: 127.0.0.1:33985
> >[21/Oct/2014:22:53:40.094] testflag testflag/s 0/0/1/2/3 404 550 - -
> >LR-- 1/1/0/1/0 0/0 "GET /redirected HTTP/1.1"
> >
> >Here, the second request inherits LR from the first one.
> >
> >The same test with curl using HTTP/1.0 :
> >
> >$ curl -0 -L http://localhost:9000/
> >Oct 21 22:55:26 asus haproxy[11282]: 127.0.0.1:33997
> >[21/Oct/2014:22:55:26.272] testflag testflag/<NOSRV> 0/-1/-1/-1/0 302
> >108 - - LR-- 0/0/0/0/3 0/0 "GET / HTTP/1.0"
> >Oct 21 22:55:26 asus haproxy[11282]: 127.0.0.1:33999
> >[21/Oct/2014:22:55:26.272] testflag testflag/s 0/0/0/2/2 404 529 - -
> >---- 0/0/0/0/0 0/0 "GET /redirected HTTP/1.0"
> >
> >Here, it's OK.
> >
> >
> >
>
> Thank you for the quick reply.
>
> I searched the log and did not find any request from port 56480 with a
> 302 status. I do not have any explicit redirect rules in my config, but
> perhaps some rules can cause a redirect. I'm quite new to haproxy.
Indeed redirects can emit such status codes, and stats can do that as well.
Since you have a stats page in your config, we could imagine that it would
come from there but I don't see how your request could match the stats URI.
Also, you have a server mentionned on this log line, which indicates that
the request was sent to a server. Thus I'm puzzled, I don't see how it is
possible that a request is forwarded to a server and still logs "LR" since
"R" means "while processing the request", and we're way past this (at least
the connection was established).
Oct 21 14:53:17 host haproxy[4526]: 206.x.x.x:56480
[21/Oct/2014:14:53:16.560] http-in~ servers/server1 60/0/0/527/587 200
243 - - LRVN 12/12/1/2/0 0/0 "POST /ctx/cometd/connect HTTP/1.1"
Could you please check in your log if you find other requests from the
same IP:port ? I'm wondering if we can't have something like this in the
case of keep-alive when a prior request was sent to stats for example (in
which case we'd have to fix it of course).
> I've attached my cleaned config file. If you could take a look I'd
> really appreciate it. And the haproxy version:
I'm not seeing anything wrong here.
Could you please check if all requests giving this are all POST ?
The request state could come from the fact that the full body was
not completely received (eventhough in this config extract I'm not
seeing anything waiting for some body). And that will not explain the
local flag either.
Thus I have no idea for now. If you could find other such logs, it could
possibly help getting a clue.
Regards,
Willy
