On 08/22/2018 04:32 AM, Willy Tarreau wrote:
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.
Here is a reg testing file for this bug.
>From f0ea3bb95bf6bb54a40e62953531019e7f602134 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Fr=C3=A9d=C3=A9ric=20L=C3=A9caille?= <flecai...@haproxy.com>
Date: Fri, 24 Aug 2018 16:14:28 +0200
Subject: [PATCH] REGTEST/MINOR: Add a reg testing file for b406b87 commit.
---
reg-tests/connection/b00000.vtc | 61 +++++++++++++++++++++++++++++++++++++++++
reg-tests/connection/common.pem | 1 +
2 files changed, 62 insertions(+)
create mode 100644 reg-tests/connection/b00000.vtc
create mode 120000 reg-tests/connection/common.pem
diff --git a/reg-tests/connection/b00000.vtc b/reg-tests/connection/b00000.vtc
new file mode 100644
index 00000000..3a873848
--- /dev/null
+++ b/reg-tests/connection/b00000.vtc
@@ -0,0 +1,61 @@
+#commit b406b87
+# BUG/MEDIUM: connection: don't store recv() result into trash.data
+#
+# Cyril Bonté discovered that the proxy protocol randomly fails since
+# commit 843b7cb ("MEDIUM: chunks: make the chunk struct's fields match
+# the buffer struct"). This is because we used to store recv()'s return
+# code into trash.data which is now unsigned, so it never compares as
+# negative against 0. Let's clean this up and test the result itself
+# without storing it first.
+
+varnishtest "PROXY protocol random failures"
+
+feature ignore_unknown_macro
+
+syslog Slog_1 -repeat 8 -level info {
+ recv
+ expect ~ "Connect from .* to ${h1_ssl_addr}:${h1_ssl_port}"
+ recv
+ expect ~ "ssl-offload-http/http .* \"POST /[1-8] HTTP/1\\.1\""
+} -start
+
+haproxy h1 -conf {
+ global
+ nbproc 4
+ nbthread 4
+ tune.ssl.default-dh-param 2048
+ stats bind-process 1
+ log ${Slog_1_addr}:${Slog_1_port} len 2048 local0 debug err
+
+ defaults
+ mode http
+ timeout client 1s
+ timeout server 1s
+ timeout connect 1s
+ log global
+
+ listen http
+ bind-process 1
+ bind abns@http accept-proxy name ssl-offload-http
+ option forwardfor
+
+ listen ssl-offload-http
+ option httplog
+ bind-process 2-4
+ bind "fd@${ssl}" ssl crt ${testdir}/common.pem ssl no-sslv3 alpn h2,http/1.1
+ server http abns@http send-proxy
+} -start
+
+
+shell {
+ HOST=${h1_ssl_addr}
+ if [ "$HOST" = "::1" ] ; then
+ HOST="\[::1\]"
+ fi
+ for i in 1 2 3 4 5 6 7 8 ; do
+ urls="$urls https://$HOST:${h1_ssl_port}/$i";
+ done
+ curl -i -k -d 'x=x' $urls & wait $!
+}
+
+syslog Slog_1 -wait
diff --git a/reg-tests/connection/common.pem b/reg-tests/connection/common.pem
new file mode 120000
index 00000000..a4433d56
--- /dev/null
+++ b/reg-tests/connection/common.pem
@@ -0,0 +1 @@
+../ssl/common.pem
\ No newline at end of file
--
2.11.0
