H2 + option httpclose => Error in the HTTP2 framing layer

Help!
1

I dont know if it’s a bug, or a deprecation in h2:

TL;DR: When I set a h2 frontend with a HTTP 1.1 backend (with the option httpclose, it works without it), half the time the request is corrupted:

user@ubuntu$ curl --http2 -i -k -v https://haproxy
* Rebuilt URL to: https://haproxy/
*   Trying 172.17.0.2...
* TCP_NODELAY set
* Connected to haproxy (172.17.0.2) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.2 (OUT), TLS header, Certificate Status (22):
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd; CN=haproxy
*  start date: Nov  2 08:50:11 2017 GMT
*  expire date: Nov  2 08:50:11 2018 GMT
*  issuer: C=AU; ST=Some-State; O=Internet Widgits Pty Ltd; CN=haproxy
*  SSL certificate verify result: self signed certificate (18), continuing anyway.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x563cb9439da0)
> GET / HTTP/1.1
> Host: haproxy
> User-Agent: curl/7.52.1
> Accept: */*
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
< HTTP/2 200 
HTTP/2 200 
< date: Tue, 07 Nov 2017 09:22:23 GMT
date: Tue, 07 Nov 2017 09:22:23 GMT
< server: Apache/2.4.18 (Ubuntu)
server: Apache/2.4.18 (Ubuntu)
< last-modified: Thu, 02 Nov 2017 08:54:37 GMT
last-modified: Thu, 02 Nov 2017 08:54:37 GMT
< etag: "2c39-55cfc234acb0a"
etag: "2c39-55cfc234acb0a"
< accept-language: bytes
accept-language: bytes
< content-length: 11321
content-length: 11321
< vary: Accept-Encoding
vary: Accept-Encoding
< content-type: text/html
content-type: text/html

< 

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
...
...
...
</html>

* Curl_http_done: called premature == 1
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, Client hello (1):
curl: (16) Error in the HTTP2 framing layer

How to reproduce:

Set HAProxy h2 frontend with a http 1.1 backend. Full config:

global
        log 127.0.0.1 len 10240   local0
        chroot /var/lib/haproxy
        stats socket /tmp/haproxy mode 666 level admin
        stats timeout 30s
        user haproxy
        group haproxy
        daemon
        tune.ssl.default-dh-param 2048
defaults
        log     global
        mode    tcp
        option  dontlognull
        option  redispatch
        retries 3
        maxconn 5000
        timeout connect 300s
        timeout client  300s
        timeout server  300s
        timeout queue   300s
        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 option redispatch
        errorfile 503 /etc/haproxy/errors/503.http option redispatch
        errorfile 504 /etc/haproxy/errors/504.http option redispatch

frontend f_myapp
    mode        http
    capture request header Host len 200
    capture request header User-Agent len 500
    bind 0.0.0.0:443 ssl crt /server.pem ciphers ECDHE-ECDSA-CHACHA20-POLY1305:ECDHE-RSA-CHACHA20-POLY1305:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES256-GCM-SHA384:ECDHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA:ECDHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES256-SHA:ECDHE-ECDSA-DES-CBC3-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:DES-CBC3-SHA:!DSS no-sslv3 alpn h2,http/1.1
     default_backend https

backend https
    mode                http
    option 		httpclose
    server              worker1 127.0.0.1:80 check inter 2s rise 5 fall 5

The backend is an Apache2 server (2.4.18-2ubuntu3.5)
haproxy -vv:

HA-Proxy version 1.8-rc2-2d34cd-18 2017/11/06
Copyright 2000-2017 Willy Tarreau <willy@haproxy.org>

Build options :
  TARGET  = custom
  CPU     = native
  CC      = gcc
  CFLAGS  = -O2 -march=native -g -fno-strict-aliasing -Wdeclaration-after-statement -fwrapv -Wno-unused-label
  OPTIONS = USE_LINUX_TPROXY=1 USE_ZLIB=1 USE_POLL=default USE_REGPARM=1 USE_OPENSSL=1 USE_PCRE=1

Default settings :
  maxconn = 2000, bufsize = 16384, maxrewrite = 40960, maxpollevents = 200

Built with OpenSSL version : OpenSSL 1.1.0d  26 Jan 2017
Running on OpenSSL version : OpenSSL 1.1.0f  25 May 2017
OpenSSL library supports TLS extensions : yes
OpenSSL library supports SNI : yes
OpenSSL library supports : TLSv1.0 TLSv1.1 TLSv1.2
Built with transparent proxy support using: IP_TRANSPARENT IPV6_TRANSPARENT IP_FREEBIND
Built with network namespace support.
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")
Encrypted password support via crypt(3): yes
Built with PCRE version : 8.38 2015-11-23
Running on PCRE version : 8.38 2015-11-23
PCRE library supports JIT : no (USE_PCRE_JIT not set)

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

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

curl --version:

curl 7.52.1 (x86_64-pc-linux-gnu) libcurl/7.52.1 OpenSSL/1.0.2l zlib/1.2.8 libidn2/0.16 libpsl/0.17.0 (+libidn2/0.16) libssh2/1.7.0 nghttp2/1.18.1 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets HTTPS-proxy PSL

I don’t use this option, but it was on a old staging config with a NodeJS backend and the same bug occured.

2

When you say corrupted, do you mean that the actual transferred file is corrupted or just is there just the framing error in curl?

3

curl : freeze 2-5s and displays the html body without error and prints the error: curl: (16) Error in the HTTP2 framing layer
firefox : the page is in pending indefinitely
chromium : the page is in pending indefinitely

Versions:
curl: 7.52.1-5+deb9u2
firefox: 57.0b14
chromium: 62.0.3202.75-1~deb9u1

4

I can’t reproduce the delay you’re experiencing, however I was facing a 200ms delay due to MSG_MORE being set on the connection to the server, I’ve just fixed it.

I’ve fixed also some errors in the error handling path of the H2 multiplexer, which used to cause RST_STREAM not to be sent sometimes, possibly causing the client to wait for a long time.

Also I think I’ve found why curl complains about the protocol error. Upon presence of “connection: close”, haproxy intends a graceful shutdown, letting the client know that it must avoid sending extra requests there (to remain compatible in behaviour with what is done on H1). So we’re seeing this on the response path :

<- GOAWAY(0)
Last stream id: 2147483647
Error code: NO_ERROR

<- HEADERS(1)
+ END_STREAM
+ END_HEADERS
:status: 200
content-length: 0
x-req: size=97, time=0 ms
x-rsp: id=dummy, code=200, cache=1, size=0, time=0 ms (0 real)

Error while reading next frame: EOF
Closing connection.
Error while reading next frame: read tcp 127.0.0.1:40636->127.0.0.1:4443: use of closed network connection
Closing connection.
-> GOAWAY(0)
Last stream id: 0
Error code: FRAME_SIZE_ERROR

Here it’s h2c-wiretap which complains. At first glance this was OK but it is not. There a non-obvious sentence in the spec (#6.8) that says that after the graceful shutdown we still need to send another GOAWAY with the last ID. I’m pretty sure that’s why the client complains. I’ll see how to add this now.