On Wed, Aug 22, 2018 at 12:46:47AM +0200, Cyril Bonté wrote:
> Le 22/08/2018 à 00:40, Cyril Bonté a écrit :
> > Hi again Willy,
> >
> > Le 21/08/2018 à 22:55, Cyril Bonté a écrit :
> > > > Thanks for the diag. I don't remember changing anything around the proxy
> > > > protocol, but it's possible that something subtle changed. Also it's not
> > > > on the regular send/receive path so maybe I overlooked certain parts and
> > > > broke it by accident when changing the buffers.
> > > >
> > > > Same here, if you have a small reproducer it will really help.
> > >
> > > I try to find a configuration that could help identify the issue,
> > > but currently I fail (timings seems to have a role). I let you know
> > > once I have a good reproducer.
> >
> > OK, I have a small reproducer that triggers the issue quite often on my
> > laptop:
> > global
> > log /dev/log len 2048 local7 debug err
> >
> > nbproc 4
> >
> > defaults
> > mode http
> > log global
> > option log-health-checks
> >
> > listen ssl-offload-http
> > bind :4443 ssl crt localhost.pem ssl no-sslv3 alpn h2,http/1.1
> > bind-process 2-4
> >
> > server http abns@http send-proxy
> >
> > listen http
> > bind-process 1
> > bind abns@http accept-proxy name ssl-offload-http
> >
> > option forwardfor
> >
> > then execute several H2 requests on the same connection, for example:
> > $ curl -k -d 'x=x' $(printf 'https://localhost:4443/%s ' {1..8})
> > <html><body><h1>503 Service Unavailable</h1>
> > No server is available to handle this request.
> > </body></html>
> > <html><body><h1>503 Service Unavailable</h1>
> > No server is available to handle this request.
> > </body></html>
> > <html><body><h1>503 Service Unavailable</h1>
> > No server is available to handle this request.
> > </body></html>
> > curl: (16) Error in the HTTP2 framing layer
> > <html><body><h1>503 Service Unavailable</h1>
> > No server is available to handle this request.
> > </body></html>
> > curl: (16) Error in the HTTP2 framing layer
> > curl: (16) Error in the HTTP2 framing layer
> > <html><body><h1>503 Service Unavailable</h1>
> > No server is available to handle this request.
> > </body></html>
> >
> > In the logs, I can see:
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.459] http http/<NOSRV> 0/-1/-1/-1/0 503 212 - -
> > SC-- 1/1/0/0/0 0/0 "POST /1 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12625]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.458] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/0/0 503 212 - - ---- 1/1/0/0/0 0/0 "POST /1 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.459] http http/<NOSRV> 0/-1/-1/-1/0 503 212 - -
> > SC-- 1/1/0/0/0 0/0 "POST /2 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12625]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.459] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/0/0 503 212 - - ---- 1/1/0/0/0 0/0 "POST /2 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.460] http http/<NOSRV> 0/-1/-1/-1/0 503 212 - -
> > SC-- 1/1/0/0/0 0/0 "POST /3 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12625]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.459] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/0/0 503 212 - - ---- 1/1/0/0/0 0/0 "POST /3 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: PROXY SIG ERROR
> > X-Forwarded-For: 127.0.0.1
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: unix:1
> > [22/Aug/2018:00:34:19.460] http/ssl-offload-http: Received something
> > which does not look like a PROXY protocol header
> > Aug 22 00:34:19 asus-wifi haproxy[12625]: 127.0.0.1:37538
> > [22/Aug/2018:00:34:19.459] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/-1/0 -1 0 - - SD-- 1/1/0/0/0 0/0 "POST /4 HTTP/1.1"
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: PROXY SIG ERROR unix:1
> > [22/Aug/2018:00:34:19.460] http/ssl-offload-http
> > Aug 22 00:34:19 asus-wifi haproxy[12623]: unix:1
> > [22/Aug/2018:00:34:19.461] http/ssl-offload-http: Received something
> > which does not look like a PROXY protocol header
> > Aug 22 00:34:20 asus-wifi haproxy[12623]: 127.0.0.1:37542
> > [22/Aug/2018:00:34:20.462] http http/<NOSRV> 0/-1/-1/-1/0 503 212 - -
> > SC-- 1/1/0/0/0 0/0 "POST /5 HTTP/1.1"
> > Aug 22 00:34:20 asus-wifi haproxy[12625]: 127.0.0.1:37542
> > [22/Aug/2018:00:34:19.460] ssl-offload-http~ ssl-offload-http/http
> > 0/0/1002/0/1002 503 212 - - ---- 1/1/0/0/1 0/0 "POST /5 HTTP/1.1"
> > Aug 22 00:34:20 asus-wifi haproxy[12623]: PROXY SIG ERROR
> > X-Forwarded-For: 127.0.0.1
> > Aug 22 00:34:20 asus-wifi haproxy[12623]: unix:1
> > [22/Aug/2018:00:34:20.463] http/ssl-offload-http: Received something
> > which does not look like a PROXY protocol header
> > Aug 22 00:34:20 asus-wifi haproxy[12625]: 127.0.0.1:37542
> > [22/Aug/2018:00:34:20.463] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/-1/0 -1 0 - - SD-- 1/1/0/0/0 0/0 "POST /6 HTTP/1.1"
> > Aug 22 00:34:20 asus-wifi haproxy[12623]: PROXY SIG ERROR unix:1
> > [22/Aug/2018:00:34:20.463] http/ssl-offload-http
> > Aug 22 00:34:20 asus-wifi haproxy[12623]: unix:1
> > [22/Aug/2018:00:34:20.469] http/ssl-offload-http: Received something
> > which does not look like a PROXY protocol header
> > Aug 22 00:34:20 asus-wifi haproxy[12625]: 127.0.0.1:37546
> > [22/Aug/2018:00:34:20.469] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/-1/0 -1 0 - - SD-- 1/1/0/0/0 0/0 "POST /7 HTTP/1.1"
> > Aug 22 00:34:20 asus-wifi haproxy[12623]: 127.0.0.1:37550
> > [22/Aug/2018:00:34:20.472] http http/<NOSRV> 0/-1/-1/-1/0 503 212 - -
> > SC-- 1/1/0/0/0 0/0 "POST /8 HTTP/1.1"
> > Aug 22 00:34:20 asus-wifi haproxy[12625]: 127.0.0.1:37550
> > [22/Aug/2018:00:34:20.471] ssl-offload-http~ ssl-offload-http/http
> > 0/0/0/0/0 503 212 - - SD-- 1/1/0/0/0 0/0 "POST /8 HTTP/1.1"
> >
> > Note that "PROXY SIG ERROR" messages are debug logs I've added to see
> > what's in the trash when it fails... and that's embarrassing, we can
> > find header manipulation, or sometimes healthchecks messages, log
> > prefixes, ...
> > diff --git a/src/connection.c b/src/connection.c
> > index ee80e616f..4535f4168 100644
> > --- a/src/connection.c
> > +++ b/src/connection.c
> > @@ -593,6 +593,9 @@ int conn_recv_proxy(struct connection *conn, int flag)
> >
> > if (memcmp(hdr_v2->sig, v2sig, PP2_SIGNATURE_LEN) != 0 ||
> > (hdr_v2->ver_cmd & PP2_VERSION_MASK) != PP2_VERSION) {
> > + char *sig = strdup(hdr_v2->sig);
> > + ha_alert("PROXY SIG ERROR %s\n", sig);
> > + send_log(((struct session *)conn->owner)->fe, LOG_ERR, "PROXY
> > SIG ERROR %s\n", sig);
> > conn->err_code = CO_ER_PRX_NOT_HDR;
> > goto fail;
> > }
>
> Oh, and now I can reproduce it with a simple config, I can see this is not
> related to H2, I can observe the same with HTTP/1.1 (http or https).
Excellent, I think I found it :
trash.data = recv(conn->handle.fd, trash.area, trash.size,
MSG_PEEK);
if (trash.data < 0) {
if (errno == EINTR)
continue;
if (errno == EAGAIN) {
fd_cant_recv(conn->handle.fd);
return 0;
}
...
trash.data is a size_t now so it cannot be negative. Thus it's believed
that recv() never fails. This it's clearly related to the buffer changes.
I'm seeing a few other such places that require using an intermediate
variable for the test. After all it's not that bad because we've inherited
such assignments from a good decade, and it's time to clean this up as well.
Willy
