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