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).
--
Cyril Bonté
