400 Bad request when enabling HTTP/2

Hi all,
Basically I want to enable http/2 protocol on my HAproxy. I successfully upgraded from v1.7.5 to v1.8.28 and as per examples added alpn h2,http/1.1 to my bind where ssl crt already was like so

bind 2.2.2.2:443 ssl crt cert.pem alpn h2,http/1.1

After reloading config and trying to access my page, it shows 400 Bad request error from HAproxy and in logs it shows this with CH flag
frontend~ backend/backend-server 0/0/1/-1/2 400 188 - - CH-- 2/2/0/0/0 0/0 "GET / HTTP/1.1"

Everything works fine if I dont add alpn h2,http/1.1 to config.
Also I noticed that if I bypass nginx on my backend, it also works. For example I am running Rancher behind HAproxy for my apps and if I set backend to not use Rancher nginx ingress, but connect straight to dedicated port, it works.
Also it works bypassing HAproxy itself, setting Rancher nginx ingress in hosts file and accessing my app, in chrome dev tools I see that it loads using h2 protocol just fine.

Any idea what might cause the 400 bad request?
Regards

The entire configuration is needed.

Actually what helped was upgrading haproxy to v2.0 and everything worked fine, page is serving with h2 protocol.

1 Like

It could’ve been a number of things, like a non-default http mode (If I recall correctly, h2 didn’t work with http close mode).

Hi @lukastribus ,

Actually after upgrading to v2.0 I have noticed a lot of CR termination status codes together with on few requests. I tried to increase maxconn setting but it does not help. Do you maybe have an idea where I could begin by debugging this issue? I am starting to think maybe to upgrade to newer version or downgrade to 1.9 instead.

To troubleshoot, use show errors on the admin socket.

To possibly workaround an invalid request (which 1.8 may not yet detect), use the option accept-invalid-http-request option. However this doesn’t work for all invalid requests.

Also make sure you are using the latest bugfix version, that would be 2.0.20 at this point, or, for 2.2 it would be 2.2.10.

This is when trying to run show errors on admin socket

root@boost-2:/etc/haproxy# echo "show errors" | socat stdio /run/haproxy/admin.sock
Total events captured on [12/Mar/2021:15:21:26.992] : 0

root@boost-2:/etc/haproxy# echo "show errors -1" | socat stdio /run/haproxy/admin.sock
Total events captured on [12/Mar/2021:15:21:32.969] : 0

root@boost-2:/etc/haproxy# echo "show errors -1 response" | socat stdio /run/haproxy/admin.sock
Total events captured on [12/Mar/2021:15:21:38.826] : 0

root@boost-2:/etc/haproxy# echo "show errors -1 request" | socat stdio /run/haproxy/admin.sock
Total events captured on [12/Mar/2021:15:21:43.786] : 0

and the CR logs look like this -

Mar 12 15:20:56 boost-2 haproxy[1147]: 195.122.4.119:63621 [12/Mar/2021:15:20:56.011] front-http~ backend/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 1632/577/17/0/3 0/0 "GET /t/2021/02/27/32890/470x275.jpg HTTP/2.0"
Mar 12 15:20:56 boost-2 haproxy[1147]: 195.122.4.119:63621 [12/Mar/2021:15:20:56.038] front-http~ backend/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 1637/578/18/0/3 0/0 "GET /t/2016/11/08/6/110x110.jpg HTTP/2.0"
Mar 12 15:20:56 boost-2 haproxy[1147]: 195.122.4.119:63621 [12/Mar/2021:15:20:56.051] front-http~ backend/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 1639/578/17/0/3 0/0 "GET /t/2016/11/08/28/110x110.jpg HTTP/2.0"
Mar 12 15:21:05 boost-2 haproxy[1147]: 81.198.64.171:52737 [12/Mar/2021:15:21:05.364] front-http~ backend/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 1689/579/3/0/3 0/0 "GET /v5/img/icons/app-store-badge.svg HTTP/2.0"

Also I am using 2.0.20 version -

root@boost-2:/etc/haproxy# haproxy -vv
HA-Proxy version 2.0.20-1~bpo9+1 2021/01/12 - https://haproxy.org/
Build options :
  TARGET  = linux-glibc
  CPU     = generic
  CC      = gcc
  CFLAGS  = -O2 -g -O2 -fdebug-prefix-map=/build/haproxy-2.0.20=. -fstack-protector-strong -Wformat -Werror=format-security -Wdate-time -D_FORTIFY_SOURCE=2 -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -Wno-unused-label -Wno-sign-compare -Wno-unused-parameter -Wno-old-style-declaration -Wno-ignored-qualifiers -Wno-clobbered -Wno-missing-field-initializers -Wtype-limits -Wshift-negative-value -Wshift-overflow=2 -Wduplicated-cond -Wnull-dereference
  OPTIONS = USE_PCRE2=1 USE_PCRE2_JIT=1 USE_REGPARM=1 USE_OPENSSL=1 USE_LUA=1 USE_ZLIB=1 USE_SYSTEMD=1

Feature list : +EPOLL -KQUEUE -MY_EPOLL -MY_SPLICE +NETFILTER -PCRE -PCRE_JIT +PCRE2 +PCRE2_JIT +POLL -PRIVATE_CACHE +THREAD -PTHREAD_PSHARED +REGPARM -STATIC_PCRE -STATIC_PCRE2 +TPROXY +LINUX_TPROXY +LINUX_SPLICE +LIBCRYPT +CRYPT_H -VSYSCALL +GETADDRINFO +OPENSSL +LUA +FUTEX +ACCEPT4 -CLOSEFROM -MY_ACCEPT4 +ZLIB -SLZ +CPU_AFFINITY +TFO +NS +DL +RT -DEVICEATLAS -51DEGREES -WURFL +SYSTEMD -OBSOLETE_LINKER +PRCTL +THREAD_DUMP -EVPORTS

Default settings :
  bufsize = 16384, maxrewrite = 1024, maxpollevents = 200

Built with multi-threading support (MAX_THREADS=64, default=8).
Built with OpenSSL version : OpenSSL 1.1.0l  10 Sep 2019
Running on OpenSSL version : OpenSSL 1.1.0j  20 Nov 2018
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2
Built with Lua version : Lua 5.3.3
Built with network namespace support.
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with zlib version : 1.2.8
Running on zlib version : 1.2.8
Compression algorithms supported : identity("identity"), deflate("deflate"), raw-deflate("deflate"), gzip("gzip")
Built with PCRE2 version : 10.22 2016-07-29
PCRE2 library supports JIT : yes
Encrypted password support via crypt(3): yes
Built with the Prometheus exporter as a service

Available polling systems :
      epoll : pref=300,  test result OK
       poll : pref=200,  test result OK
     select : pref=150,  test result OK
Total: 3 (3 usable), will use epoll.

Available multiplexer protocols :
(protocols marked as <default> cannot be specified using 'proto' keyword)
              h2 : mode=HTX        side=FE|BE     mux=H2
              h2 : mode=HTTP       side=FE        mux=H2
       <default> : mode=HTX        side=FE|BE     mux=H1
       <default> : mode=TCP|HTTP   side=FE|BE     mux=PASS

Available services :
	prometheus-exporter

Available filters :
	[SPOE] spoe
	[COMP] compression
	[CACHE] cache
	[TRACE] trace

Also trying to set option accept-invalid-http-request looks like did not make any change, still getting those CR in logs, max req rate is 345/s as pet stats page and this is the config from stats page -

**pid =** 1147 (process #1, nbproc = 1, nbthread = 8)
**uptime =** 0d 0h09m47s
**system limits:** memmax = unlimited; ulimit-n = 20079
**maxsock =** 20079; **maxconn =** 10000; **maxpipes =** 0
current conns = 1673; current pipes = 0/0; conn rate = 107/sec; bit rate = 62.665 Mbps
Running tasks: 1/2138; idle = 93 %

This started to happen on v2.0 as previously using the same config (except for alpn h2,http/1.1) on v1.7 there were no CR errors.

Actually looks like the CR is caused by the alpn h2,http/1.1 setting, as removing it I can not see anything related to CR in my log now, but I can see that show errors is increasing like crazy

root@boost-2:/etc/haproxy# echo "show errors -1 request" | socat stdio /run/haproxy/admin.sock
Total events captured on [12/Mar/2021:15:51:16.397] : 3620

[12/Mar/2021:15:51:16.263] frontend frontend-http (#2): invalid request
  backend <NONE> (#-1), server <NONE> (#-1), event #3619, src 80.89.72.155:2574
  buffer starts at 0 (including 0 out), 16188 free,
  len 196, wraps at 16336, error at position 0
  H1 connection flags 0x00000000, H1 stream flags 0x00000012
  H1 msg state MSG_RQBEFORE(0), H1 msg flags 0x00001400
  H1 chunk len 0 bytes, H1 body len 0 bytes :

  00000  \x16\x03\x01\x00\xBF\x01\x00\x00\xBB\x03\x036\xEC\xBDcj\xFD\x1E\xB9
  00019+ \x0F\xD4\xACR\xCBU=\x01\xFC2j\x83\x1E\xCBgEz\x83\x9E\xC2G\xFAu\x85\x00
  00044+ \x00\x1E\xC0+\xC0/\xCC\xA9\xCC\xA8\xC0,\xC00\xC0\n
  00060  \xC0\t\xC0\x13\xC0\x14\x003\x009\x00/\x005\x00\n
  00076  \x01\x00\x00t\x00\x00\x00\x14\x00\x12\x00\x00\x0Fmy.domain.com\x00
  00105+ \x17\x00\x00\xFF\x01\x00\x01\x00\x00\n
  00115  \x00\n
  00117  \x00\x08\x00\x1D\x00\x17\x00\x18\x00\x19\x00\x0B\x00\x02\x01\x00\x00#
  00135+ \x00\x00\x00\x10\x00\x0E\x00\x0C\x02h2\x08http/1.1\x00\x05\x00\x05\x01
  00160+ \x00\x00\x00\x00\xFF\x03\x00\x00\x00\r\x00\x18\x00\x16\x04\x03\x05\x03
  00178+ \x06\x03\x08\x04\x08\x05\x08\x06\x04\x01\x05\x01\x06\x01\x02\x03\x02
  00195+ \x01

With alpn h2 it did not increase like that, but there were lots of CR in logs but right now there is none without alpn h2 setting.

But this disables HTTP/2 protocol on my server which was the main idea to use HAproxy v2.0

EDIT: to keep in mind, there are hundreds of reuqests coming in per second on this haproxy, but those CR errors pop out a few per 5 seconds for example.

And regarding this one, I just tried to downgrade to v1.8 on my test server and you are right, 400 bad request is caused by option httpclose on backend when using alpn h2,http/1.1
No idea why on v2.0 it still works with option httpclose but I am pretty sure this is waht causes my issues with CR in logs.
Can you suggest please what value I might try to use to replace option httpclose ?

EDIT: I just tried to remove option httpclose from backend so default keep-alive would be used and unfortunately it still throws CR error in logs using v2.0 version.

1 Like

Right, I confused CR (which is a timeout) with a bad request, so my suggestion doesn’t make sense.

You’d have to share the entire configuration, as I have absolutely no context on what you are actually doing.

But CR requers to HTTP parser to actually detect some HTTP; which doesn’t seem to be the case here. So it’s definitely not an improvement.

Hi @lukastribus

I tried to trim my config as much as possible to exclude unnecessary ACL rules and backends as most of them are similar to the ones I have here in example. IP addresses and domains have been changed for example ones.

global
    maxconn 10000
	log /dev/log	local0
	log /dev/log	local1 notice
	chroot /var/lib/haproxy
	stats socket /run/haproxy/admin.sock mode 660 level admin
	stats timeout 30s
	user haproxy
	group haproxy
	daemon

	# Default SSL material locations
	ca-base /etc/ssl/certs
	crt-base /etc/ssl/private

	ssl-default-bind-ciphers ECDH+AESGCM:DH+AESGCM:ECDH+AES256:DH+AES256:ECDH+AES128:DH+AES:RSA+AESGCM:RSA+AES:!aNULL:!MD5:!DSS
	ssl-default-bind-options no-sslv3
    ssl-dh-param-file /etc/haproxy/ssl/dhparams.pem

defaults
	log	global
	mode	http
	option	httplog
	option	dontlognull
    option http-ignore-probes
    timeout connect 5000
    timeout client  50000
    timeout server  300000
    timeout tunnel 70000ms
	errorfile 400 /etc/haproxy/errors/400.http
	errorfile 403 /etc/haproxy/errors/403.http
	errorfile 408 /etc/haproxy/errors/408.http
	errorfile 500 /etc/haproxy/errors/500.http
	errorfile 502 /etc/haproxy/errors/502.http
	errorfile 503 /etc/haproxy/errors/503.http
	errorfile 504 /etc/haproxy/errors/504.http

frontend frontend-http
  bind 11.11.11.22:80
  bind 11.11.11.33:80
  bind 11.11.11.22:443 ssl crt /etc/haproxy/ssl/certs/domain.com.pem alpn h2,http/1.1
  bind 11.11.11.33:443 ssl crt /etc/haproxy/ssl/certs/domain.com.pem alpn h2,http/1.1

  option accept-invalid-http-request

  reqadd X-Forwarded-Proto:\ https if { ssl_fc }
  reqadd X-Forwarded-Port:\ 443 if { ssl_fc }
  reqadd X-Forwarded-Proto:\ http if !{ ssl_fc }
  reqadd X-Forwarded-Port:\ 80 if !{ ssl_fc }

  rspidel Server
  http-request set-header X-GW-Client-IP %[src]
  acl hdr_connection_upgrade hdr(Connection)  -i upgrade
  acl hdr_upgrade_websocket  hdr(Upgrade)     -i websocket

  acl host-domain-com hdr_dom(host) -i -m reg ^(domain\.com)(:[0-9]+)?$
  acl host-img-domain-com hdr_dom(host) -i -m reg ^(img)([0-9])?\.(domain\.com)(:[0-9]+)?$

  use_backend backend-domain-com if host-domain-lv
  use_backend backend-img-domain-com if host-img-domain-com

backend Abuse
  stick-table type ip size 1m expire 30m store conn_rate(3s),conn_cur,gpc0,http_req_rate(10s),http_err_rate(20s)

backend per-src-path
  stick-table type binary len 20 size 1k expire 10m store http_req_rate(10s)

backend Logger
  stick-table type ip size 100k expire 30m store conn_rate(3s),gpc0,conn_cur,http_req_rate(10s),http_err_rate(10s)

backend backend-img-domain-com
  option httpclose
  option forwardfor
  balance roundrobin
  option httpchk HEAD / HTTP/1.1\r\nHost:img.domain.com
  server 177 1.1.1.177:6081 check
  server 100 1.1.1.100:8080 backup

backend backend-domain-com
  option httpclose
  option forwardfor
  balance roundrobin
  option httpchk HEAD / HTTP/1.1\r\nHost:domain.com
  acl abuse src_http_req_rate(Logger) ge 100
  acl flag_abuser src_inc_gpc0(Logger) ge 0
  tcp-request content reject if abuse flag_abuser
  server domain-rancher 1.1.1.21:80 check
  server 100 1.1.1.100:8080 backup

Please let me know if you notice anything off. Config is kind of old and was used on v1.7 haproxy.

And just to remind, log shows such CR entries -

Mar 15 10:25:10 boost-2 haproxy[31613]: 80.233.180.206:62924 [15/Mar/2021:10:25:10.416] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 1999/1011/0/0/3 0/0 "GET /resp/img/sp2.png?20200727 HTTP/2.0"
Mar 15 10:25:10 boost-2 haproxy[31613]: 80.233.180.206:62924 [15/Mar/2021:10:25:10.416] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 1999/1011/0/0/3 0/0 "GET /resp/img/logo/logo_flag.svg HTTP/2.0"
Mar 15 10:25:11 boost-2 haproxy[31613]: 78.28.237.240:59565 [15/Mar/2021:10:25:11.165] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 2027/1019/0/0/3 0/0 "GET /resp/js/pageLoad.js?20210309 HTTP/2.0"
Mar 15 10:25:12 boost-2 haproxy[31613]: 46.109.128.91:50745 [15/Mar/2021:10:25:12.191] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 2035/1022/2/0/3 0/0 "GET /resp/css2/messenger.css HTTP/2.0"
Mar 15 10:25:12 boost-2 haproxy[31613]: 46.109.128.91:50745 [15/Mar/2021:10:25:12.303] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 2044/1030/1/0/3 0/0 "GET /resp/img/sp2.png?20200605 HTTP/2.0"
Mar 15 10:25:12 boost-2 haproxy[31613]: 84.237.130.80:51406 [15/Mar/2021:10:25:12.542] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 2056/1047/2/0/3 0/0 "GET /img/icons/superagents.png HTTP/2.0"

Actually I think we are just talking about buggy, broken clients or scans, which are supposed to fail. Or aborted requests. And the error path could be different between h2 and without it, or even with or without alpn both because of different code paths in haproxy, but also in the client.

Do you know whether real applications and browser have actual issues because of this?

Do you know if something changed in logging from version v1.7 to v2.0? Because previously on v1.7 I didnt notice anything regarding CR in logs, but then again v1.7 didnt support h2. Although today I also noticed that CR popped up on frontend which is not set to use alpn h2,http/1.1

Actually I have not received any user complains for web page (haproxy frontend) where h2 is enabled currently but there was an issue where specific URL path is forwarded from different HAproxy/nginx/varnish chain to my haproxy which then forwards to nodejs app on my end and I got complains that there were times during the day where this specific URL path would hung up for a minute or so and would return 5xx errors on their side while in my haproxy logs I would see like 50-100 or more CR errors with NOSRV in a row all logged at the same timestamp and once h2 was disabled there have not been any complains, so yes I would say that this impacts application as well. This specific URL path is being requested a lot per second, basically on all the requests when browsing page as its used for cookie consent purposes. Quite weird actually why it would hung for such a long time, like hiccup.

CR logging has been there before 1.7, however with 2.0 the HTTP handling code has basically been completely rewritten. This is more about the HTTP handling code paths than logging. You can try no option http-use-htx in your defaults section in 2.0, to downgrade to the old HTTP engine. This is not possible in newer release branches, as the old HTTP engine has been completely removed.

Ok I tried to set no option http-use-htx in defaults section as per your suggestion and I noticed that now all CR entries in logs are related to HTTP/1.1 where previously it was HTTP/2.0 in headers -

Mar 16 10:30:23 boost-2 haproxy[17832]: 85.234.170.149:53029 [16/Mar/2021:10:30:23.607] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 805/716/2/0/3 0/0 "POST /loadHeader.php HTTP/1.1"
Mar 16 10:30:23 boost-2 haproxy[17832]: 85.234.170.149:53029 [16/Mar/2021:10:30:23.607] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 805/716/3/0/3 0/0 "GET /ajax/remoteArticles?portal=exx HTTP/1.1"
Mar 16 10:30:32 boost-2 haproxy[17832]: 159.148.112.49:50788 [16/Mar/2021:10:30:32.714] frontend-http~ backend-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 774/684/0/0/3 0/0 "GET /export/1/ HTTP/1.1"
Mar 16 10:32:03 boost-2 haproxy[17832]: 89.254.142.215:50751 [16/Mar/2021:10:32:03.368] frontend-http~ backend-img-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 790/716/1/0/3 0/0 "GET /upload2/articles/90/906548/quiz/qu_60422.jpg HTTP/1.1"
Mar 16 10:32:03 boost-2 haproxy[17832]: 89.254.142.215:50751 [16/Mar/2021:10:32:03.369] frontend-http~ backend-img-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 790/716/1/0/3 0/0 "GET /upload2/articles/90/906548/quiz/qu_60423.jpg HTTP/1.1"
Mar 16 10:32:03 boost-2 haproxy[17832]: 89.254.142.215:50751 [16/Mar/2021:10:32:03.376] frontend-http~ backend-img-domain-com/<NOSRV> 0/-1/-1/-1/0 -1 0 - - CR-- 790/716/1/0/3 0/0 "GET /upload2/articles/90/906548/quiz/qu_60426.jpg HTTP/1.1"

But if you take a look on one of my posts above, there is HTTP/2.0 at the end.
Does this mean anything?

That’s just a result of the older code path triggering (everything will be downgraded to HTTP/1.1).

I’m unsure what to think of the situation. I’d suggest to file a bug on Github, that way more folks are seeing it and maybe other users seeing the same can chime in as well, collecting more informations.