This is a post detailing a wild discovery made by @msmiley and I while investigating strange behaviour from HAProxy. We want to highlight the pathology, describe how we found it, and share some investigative techniques used along the way. Strap in. ## TLDR Spoiler alert. <details> - HAProxy has a `server-state-file` directive that persists some of its state across restarts. - This state file contains the port of each backend server. - If an `haproxy.cfg` change modifies the port, the new port will be overwritten with the previous one from the state file. - A workaround is to change the backend server name, so that it is considered to be a separate server that does not match what is in the state file. - This has implications for the rollout procedure we use on HAProxy. </details> ## Background All of this occurred in the context of [the gitlab-pages PROXYv2 project](https://gitlab.com/gitlab-com/gl-infra/infrastructure/-/issues/11902). The rollout to staging involves changing the request flow from TCP proxying: ``` 443 443 1443 [ client ] -> [ google lb ] -> [ fe-pages-01-lb-gstg ] -> [ web-pages-01-sv-gstg ] tcp,tls,http tcp tcp tcp,tls,http ``` To using the [PROXY protocol](https://www.haproxy.org/download/1.8/doc/proxy-protocol.txt): ``` 443 443 2443 [ client ] -> [ google lb ] -> [ fe-pages-01-lb-gstg ] -> [ web-pages-01-sv-gstg ] tcp,tls,http tcp proxyv2,tcp proxyv2,tcp,tls,http ``` This is done through this change to `/etc/haproxy/haproxy.cfg` on `fe-pages-01-lb-gstg`, note the port change: ```diff - server web-pages-01-sv-gstg web-pages-01-sv-gstg.c.gitlab-staging-1.internal:1443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 - server web-pages-02-sv-gstg web-pages-02-sv-gstg.c.gitlab-staging-1.internal:1443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 + server web-pages-01-sv-gstg web-pages-01-sv-gstg.c.gitlab-staging-1.internal:2443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 send-proxy-v2 + server web-pages-02-sv-gstg web-pages-02-sv-gstg.c.gitlab-staging-1.internal:2443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 send-proxy-v2 ``` Seems straight-forward enough, let's go ahead and apply that change. ## The brokenness After applying this change on one of the two `fe-pages` nodes, the requests to that node start failing. By retrying a few times via `curl` on the command line, we see this error: ``` ➜ ~ curl -vvv https://jarv.staging.gitlab.io/pages-test/ * Trying 35.229.69.78... * TCP_NODELAY set * Connected to jarv.staging.gitlab.io (35.229.69.78) port 443 (#0) * ALPN, offering h2 * ALPN, offering http/1.1 * successfully set certificate verify locations: * CAfile: /etc/ssl/cert.pem CApath: none * TLSv1.2 (OUT), TLS handshake, Client hello (1): * LibreSSL SSL_connect: SSL_ERROR_SYSCALL in connection to jarv.staging.gitlab.io:443 * Closing connection 0 curl: (35) LibreSSL SSL_connect: SSL_ERROR_SYSCALL in connection to jarv.staging.gitlab.io:443 ``` This looks like some issue in the TLS stack, or possibly with the underlying connection. It turns out that `LibreSSL` does not give us much insight into the underlying issue here. So to get a better idea, let's capture a traffic dump on the HAProxy node: ``` sudo tcpdump -v -w "$(pwd)/$(hostname).$(date +%Y%m%d_%H%M%S).pcap" ``` While `tcpdump` is running, we can generate some traffic, then ctrl+c and pull the dump down for further analysis. That `pcap` file can be opened in Wireshark, and this allows the data to be explored and filtered interactively. Here, the first really surprising thing happens: **We do not see any traffic on port 2443.** At the same time, we _do_ see some traffic on port 1443. But we came here to look at what underlies the LibreSSL error, and what we find is the following (by filtering for `ip.addr == <my external ip>`): We have a TCP SYN/ACK, establishing the connection. Followed by the client sending a TLS "hello". After which the server closes the connection with a FIN. In other words, the server is closing the connection on the client. ## The early hypotheses So here come the usual suspects: * Did we modify the correct place in the config file? * Did we catch all places we need to update in the config? * Did the haproxy process parse th econfig successfully? * Did haproxy actually reload? * Is there a difference between reload and restart? * Did we modify the correct config file? * Are there old lingering HAProxy processes on the box? * Are we actually sending traffic to this node? * Are backend health checks failing? * Is there anything in the HAProxy logs? None of these gave any insights whatsoever. In an effort to reproduce the issue, I ran HAProxy on my local machine with a similar config, proxying traffic to `web-pages-01-sv-gstg`. To my surprise, this worked correctly. I tested with different HAProxy versions. It worked locally, but not on `fe-pages-01`. At this point I'm stumped. The local config is not identical to gstg, but quite similar. What could possibly be the difference? ## Digging deeper This is when I reached out to @msmiley to help with the investigation. We started off by repeating the experiment. We saw the same results: * Server closes connection after client sends TLS hello * No traffic from fe-pages to web-pages on port 2443 * Traffic from fe-pages to web-pages on port 1443 The first lead was to look at the packets going to port 1443. What do they contain? We see this:  There is mention of `jarv.staging.gitlab.io` which does match what the client sent. And before that there is some really weird preamble: ``` "\r\n\r\n\0\r\nQUIT\n" ``` What on earth is this? Is it from the PROXY protocol? Let's search [the spec](https://www.haproxy.org/download/1.8/doc/proxy-protocol.txt) for the word "QUIT". Nothing. Is this something in the HAProxy source? Searching for "QUIT" in the code reveals some hits, but none that explain this. So this is a mystery. We leave it for now, and probe in a different direction. ## Honing in How come we are sending traffic to port 1443, when that port is not mentioned in `haproxy.cfg`? Where on earth is HAProxy getting that information from? I suggested running `strace` on HAProxy startup, so that we can see which files are being `open`ed. This is a bit tricky to do though, because the process is systemd-managed. It turns out that thanks to BPF and [BCC](https://github.com/iovisor/bcc), we can actually listen on open events system-wide using the wonderful [opensnoop](https://github.com/iovisor/bcc/blob/master/tools/opensnoop.py). So we run `opensnoop` and restart `haproxy`, and this is what we see: <details> ``` iwiedler@fe-pages-01-lb-gstg.c.gitlab-staging-1.internal:~$ sudo /usr/share/bcc/tools/opensnoop -T --name haproxy TIME(s) PID COMM FD ERR PATH 24.111742000 16702 (haproxy) 27 0 /proc/self/fd 24.112120000 16702 (haproxy) 3 0 /dev/null 24.112223000 16702 (haproxy) 3 0 /sys/fs/cgroup/systemd/system.slice/haproxy.service/control/cgroup.procs 24.112264000 16702 (haproxy) -1 2 /sys/fs/cgroup/cpu/system.slice/haproxy.service/control/cgroup.procs 24.112277000 16702 (haproxy) 3 0 /sys/fs/cgroup/cpu/system.slice/haproxy.service/cgroup.procs 24.112316000 16702 (haproxy) -1 2 /sys/fs/cgroup/cpuacct/system.slice/haproxy.service/control/cgroup.procs 24.112327000 16702 (haproxy) 3 0 /sys/fs/cgroup/cpuacct/system.slice/haproxy.service/cgroup.procs 24.112354000 16702 (haproxy) -1 2 /sys/fs/cgroup/blkio/system.slice/haproxy.service/control/cgroup.procs 24.112367000 16702 (haproxy) 3 0 /sys/fs/cgroup/blkio/system.slice/haproxy.service/cgroup.procs 24.112401000 16702 (haproxy) -1 2 /sys/fs/cgroup/memory/system.slice/haproxy.service/control/cgroup.procs 24.112455000 16702 (haproxy) 3 0 /sys/fs/cgroup/memory/system.slice/haproxy.service/cgroup.procs 24.112490000 16702 (haproxy) -1 2 /sys/fs/cgroup/devices/system.slice/haproxy.service/control/cgroup.procs 24.112504000 16702 (haproxy) 3 0 /sys/fs/cgroup/devices/system.slice/haproxy.service/cgroup.procs 24.112538000 16702 (haproxy) -1 2 /sys/fs/cgroup/pids/system.slice/haproxy.service/control/cgroup.procs 24.112550000 16702 (haproxy) 3 0 /sys/fs/cgroup/pids/system.slice/haproxy.service/cgroup.procs 24.112582000 16702 (haproxy) 3 0 /proc/self/fd 24.113260000 16702 haproxy 3 0 /etc/ld.so.cache 24.113289000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libcrypt.so.1 24.113342000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libz.so.1 24.113387000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libpthread.so.0 24.113437000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libssl.so.1.0.0 24.113492000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 24.113555000 16702 haproxy 3 0 /usr/lib/x86_64-linux-gnu/liblua5.3.so.0 24.113604000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libsystemd.so.0 24.113667000 16702 haproxy 3 0 /usr/lib/x86_64-linux-gnu/libpcre2-8.so.0 24.113714000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libc.so.6 24.113776000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libdl.so.2 24.113828000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libm.so.6 24.113877000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libselinux.so.1 24.113931000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/librt.so.1 24.113992000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/liblzma.so.5 24.114046000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libgcrypt.so.20 24.114186000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libpcre.so.3 24.114261000 16702 haproxy 3 0 /lib/x86_64-linux-gnu/libgpg-error.so.0 24.115749000 16702 haproxy 3 0 /proc/filesystems 24.116331000 16702 haproxy 3 0 /etc/localtime 24.117171000 16702 haproxy 3 0 /etc/haproxy/haproxy.cfg 24.117336000 16702 haproxy 4 0 /etc/nsswitch.conf 24.117389000 16702 haproxy 4 0 /etc/ld.so.cache 24.117424000 16702 haproxy 4 0 /lib/x86_64-linux-gnu/libnss_compat.so.2 24.117537000 16702 haproxy 4 0 /lib/x86_64-linux-gnu/libnsl.so.1 24.117698000 16702 haproxy 4 0 /etc/ld.so.cache 24.117729000 16702 haproxy 4 0 /lib/x86_64-linux-gnu/libnss_nis.so.2 24.117782000 16702 haproxy 4 0 /lib/x86_64-linux-gnu/libnss_files.so.2 24.117897000 16702 haproxy 4 0 /etc/passwd 24.117999000 16702 haproxy 4 0 /etc/group 24.118099000 16702 haproxy 4 0 /etc/haproxy/errors/400.http 24.118121000 16702 haproxy 4 0 /etc/haproxy/errors/429.http 24.118135000 16702 haproxy 4 0 /etc/haproxy/errors/400.http 24.118147000 16702 haproxy 4 0 /etc/haproxy/errors/500.http 24.118160000 16702 haproxy 4 0 /etc/haproxy/errors/502.http 24.118178000 16702 haproxy 4 0 /etc/haproxy/errors/503.http 24.118191000 16702 haproxy 4 0 /etc/haproxy/errors/504.http 24.118333000 16702 haproxy 4 0 /etc/haproxy/cloudflare_ips_v4.lst 24.118375000 16702 haproxy 4 0 /etc/haproxy/cloudflare_ips_v6.lst 24.118407000 16702 haproxy 4 0 /etc/resolv.conf 24.118433000 16702 haproxy 4 0 /etc/resolv.conf 24.118563000 16702 haproxy 4 0 /etc/haproxy/front-end-security/deny-403-ips.lst 24.118616000 16702 haproxy 4 0 /etc/haproxy/front-end-security/deny-403-pages-domains.lst 24.119109000 16702 haproxy 3 0 /etc/haproxy/state/global 24.119145000 16702 haproxy 3 0 /etc/haproxy/state/global 24.119160000 16702 haproxy 3 0 /etc/haproxy/state/global 24.126256000 14733 haproxy 3 0 /etc/ld.so.cache 24.126282000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libcrypt.so.1 24.126331000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libz.so.1 24.126370000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libpthread.so.0 24.126410000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libssl.so.1.0.0 24.126464000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 24.126533000 14733 haproxy 3 0 /usr/lib/x86_64-linux-gnu/liblua5.3.so.0 24.126579000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libsystemd.so.0 24.126635000 14733 haproxy 3 0 /usr/lib/x86_64-linux-gnu/libpcre2-8.so.0 24.126680000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libc.so.6 24.126741000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libdl.so.2 24.126808000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libm.so.6 24.126862000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libselinux.so.1 24.126916000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/librt.so.1 24.126983000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/liblzma.so.5 24.127048000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libgcrypt.so.20 24.127128000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libpcre.so.3 24.127199000 14733 haproxy 3 0 /lib/x86_64-linux-gnu/libgpg-error.so.0 24.128731000 14733 haproxy 3 0 /proc/filesystems 24.129352000 14733 haproxy 3 0 /etc/localtime 24.130408000 14733 haproxy 3 0 /etc/haproxy/haproxy.cfg 24.130529000 14733 haproxy 4 0 /etc/nsswitch.conf 24.130571000 14733 haproxy 4 0 /etc/ld.so.cache 24.130603000 14733 haproxy 4 0 /lib/x86_64-linux-gnu/libnss_compat.so.2 24.130680000 14733 haproxy 4 0 /lib/x86_64-linux-gnu/libnsl.so.1 24.130817000 14733 haproxy 4 0 /etc/ld.so.cache 24.130846000 14733 haproxy 4 0 /lib/x86_64-linux-gnu/libnss_nis.so.2 24.130909000 14733 haproxy 4 0 /lib/x86_64-linux-gnu/libnss_files.so.2 24.131024000 14733 haproxy 4 0 /etc/passwd 24.131135000 14733 haproxy 4 0 /etc/group 24.131234000 14733 haproxy 4 0 /etc/haproxy/errors/400.http 24.131250000 14733 haproxy 4 0 /etc/haproxy/errors/429.http 24.131266000 14733 haproxy 4 0 /etc/haproxy/errors/400.http 24.131407000 14733 haproxy 4 0 /etc/haproxy/errors/500.http 24.131427000 14733 haproxy 4 0 /etc/haproxy/errors/502.http 24.131446000 14733 haproxy 4 0 /etc/haproxy/errors/503.http 24.131459000 14733 haproxy 4 0 /etc/haproxy/errors/504.http 24.131629000 14733 haproxy 4 0 /etc/haproxy/cloudflare_ips_v4.lst 24.131670000 14733 haproxy 4 0 /etc/haproxy/cloudflare_ips_v6.lst 24.131700000 14733 haproxy 4 0 /etc/resolv.conf 24.131730000 14733 haproxy 4 0 /etc/resolv.conf 24.131805000 14733 haproxy 4 0 /etc/haproxy/front-end-security/deny-403-ips.lst 24.131889000 14733 haproxy 4 0 /etc/haproxy/front-end-security/deny-403-pages-domains.lst 24.132429000 14733 haproxy 3 0 /etc/haproxy/state/global 24.132459000 14733 haproxy 3 0 /etc/haproxy/state/global 24.132474000 14733 haproxy 3 0 /etc/haproxy/state/global 24.134915000 14733 haproxy 4 0 /dev/urandom 24.135515000 14733 haproxy 10 0 /run/haproxy.pid 24.136366000 16706 haproxy 10 0 /dev/null 24.162419000 15715 haproxy -1 2 /etc/ld.so.cache 24.162457000 15715 haproxy -1 2 /lib/x86_64-linux-gnu/tls/x86_64/libgcc_s.so.1 24.162466000 15715 haproxy -1 2 /lib/x86_64-linux-gnu/tls/libgcc_s.so.1 24.162473000 15715 haproxy -1 2 /lib/x86_64-linux-gnu/x86_64/libgcc_s.so.1 24.162479000 15715 haproxy -1 2 /lib/x86_64-linux-gnu/libgcc_s.so.1 24.162486000 15715 haproxy -1 2 /usr/lib/x86_64-linux-gnu/tls/x86_64/libgcc_s.so.1 24.162493000 15715 haproxy -1 2 /usr/lib/x86_64-linux-gnu/tls/libgcc_s.so.1 24.162499000 15715 haproxy -1 2 /usr/lib/x86_64-linux-gnu/x86_64/libgcc_s.so.1 24.162505000 15715 haproxy -1 2 /usr/lib/x86_64-linux-gnu/libgcc_s.so.1 24.162511000 15715 haproxy -1 2 /lib/tls/x86_64/libgcc_s.so.1 24.162517000 15715 haproxy -1 2 /lib/tls/libgcc_s.so.1 24.162524000 15715 haproxy -1 2 /lib/x86_64/libgcc_s.so.1 24.162530000 15715 haproxy -1 2 /lib/libgcc_s.so.1 24.162537000 15715 haproxy -1 2 /usr/lib/tls/x86_64/libgcc_s.so.1 24.162543000 15715 haproxy -1 2 /usr/lib/tls/libgcc_s.so.1 24.162551000 15715 haproxy -1 2 /usr/lib/x86_64/libgcc_s.so.1 24.162557000 15715 haproxy -1 2 /usr/lib/libgcc_s.so.1 24.162579000 15715 haproxy -1 2 /dev/tty ``` </details> Highlighting the relevant bit: ``` iwiedler@fe-pages-01-lb-gstg.c.gitlab-staging-1.internal:~$ sudo /usr/share/bcc/tools/opensnoop -T --name haproxy ... 24.117171000 16702 haproxy 3 0 /etc/haproxy/haproxy.cfg ... 24.118099000 16702 haproxy 4 0 /etc/haproxy/errors/400.http ... 24.118333000 16702 haproxy 4 0 /etc/haproxy/cloudflare_ips_v4.lst ... 24.119109000 16702 haproxy 3 0 /etc/haproxy/state/global ``` What do we have here? `/etc/haproxy/state/global`, this seems oddly suspicious. What could it possibly be? Let's see what this file contains. ``` iwiedler@fe-pages-01-lb-gstg.c.gitlab-staging-1.internal:~$ sudo cat /etc/haproxy/state/global 1 # be_id be_name srv_id srv_name srv_addr srv_op_state srv_admin_state srv_uweight srv_iweight srv_time_since_last_change srv_check_status srv_check_result srv_check_health srv_check_state srv_agent_state bk_f_forced_id srv_f_forced_id srv_fqdn srv_port srvrecord 5 pages_http 1 web-pages-01-sv-gstg 10.224.26.2 2 0 1 1 21134 15 3 4 6 0 0 0 web-pages-01-sv-gstg.c.gitlab-staging-1.internal 1080 - 5 pages_http 2 web-pages-02-sv-gstg 10.224.26.3 2 0 1 1 20994 15 3 4 6 0 0 0 web-pages-02-sv-gstg.c.gitlab-staging-1.internal 1080 - 6 pages_https 1 web-pages-01-sv-gstg 10.224.26.2 2 0 1 1 21134 15 3 4 6 0 0 0 web-pages-01-sv-gstg.c.gitlab-staging-1.internal 1443 - 6 pages_https 2 web-pages-02-sv-gstg 10.224.26.3 2 0 1 1 20994 15 3 4 6 0 0 0 web-pages-02-sv-gstg.c.gitlab-staging-1.internal 1443 - ``` It appears we are storing some metadata for each backend server, including its old port number! Now, looking again in `haproxy.cfg`, we see: ``` global ... server-state-file /etc/haproxy/state/global ``` So we are using the [`server-state-file`](https://cbonte.github.io/haproxy-dconv/1.8/configuration.html#server-state-file) directive. This will persist server state across HAProxy restarts. That is useful to keep metadata consistent, such as whether a server was marked as MAINT. **However, it appears to be clobbering the port from `haproxy.cfg`!** The suspected behaviour is: * HAProxy is running with the old config: `web-pages-01-sv-gstg`, `1443` * `haproxy.cfg` is updated with the new config: `web-pages-01-sv-gstg`, `2443`, `send-proxy-v2` * HAProxy reload is initiated * HAProxy writes out the state to `/etc/haproxy/state/global` (including the old port of each backend server) * HAProxy starts up, reads `haproxy.cfg`, initializes itself with the new config: `web-pages-01-sv-gstg`, `2443`, `send-proxy-v2` * HAProxy reads the state from `/etc/haproxy/state/global`, matches on the backend server `web-pages-01-sv-gstg`, and overrides all values, including the port! The result is that we are now attempting to send PROXYv2 traffic to the TLS port. ## The workaround To validate the theory and develop a potential workaround, we modify `haproxy.cfg` to use a different backend server name. The new diff is: ```diff - server web-pages-01-sv-gstg web-pages-01-sv-gstg.c.gitlab-staging-1.internal:1443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 - server web-pages-02-sv-gstg web-pages-02-sv-gstg.c.gitlab-staging-1.internal:1443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 + server web-pages-01-sv-gstg-proxyv2 web-pages-01-sv-gstg.c.gitlab-staging-1.internal:2443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 send-proxy-v2 + server web-pages-02-sv-gstg-proxyv2 web-pages-02-sv-gstg.c.gitlab-staging-1.internal:2443 check inter 3s fastinter 1s downinter 5s fall 3 port 1080 send-proxy-v2 ``` With this config change in place, we reload HAProxy and indeed, it is now serving traffic correctly. See [the fix MR](https://gitlab.com/gitlab-cookbooks/gitlab-haproxy/-/merge_requests/261). ## A follow-up on those `QUIT` bytes Now, what is up with that `QUIT` message? Is it part of the PROXY protocol? Remember, searching [the spec](https://www.haproxy.org/download/1.8/doc/proxy-protocol.txt) for that string did not find any matches. However, @msmiley actually read the spec, and found this section on version 2 of the protocol: ``` The binary header format starts with a constant 12 bytes block containing the protocol signature : \x0D \x0A \x0D \x0A \x00 \x0D \x0A \x51 \x55 \x49 \x54 \x0A ``` Those are indeed the bytes that make up "\r\n\r\n\0\r\nQUIT\n". Slightly less mnemonic than the header from text-based version 1 of the protocol: ``` - a string identifying the protocol : "PROXY" ( \x50 \x52 \x4F \x58 \x59 ) Seeing this string indicates that this is version 1 of the protocol. ``` Well, I suppose that explains it. I believe our work here is done. Don't forget to like and subscribe!