252 lines
13 KiB
Markdown
252 lines
13 KiB
Markdown
# This SRE atempted to roll out an HAProxy config change. You won’t believe what happened next…
|
||
|
||
- **期号**: SRE Weekly Issue #255（2021-01-31）
|
||
- **作者**: Andre Newman — GitLab
|
||
- **链接**: https://about.gitlab.com/blog/2021/01/14/this-sre-attempted-to-roll-out-an-haproxy-change/
|
||
|
||
## 简介
|
||
|
||
I love this for the click-bait title and the content. An HAProxy feature designed for HA had a surprising an unexpected behavior.
|
||
|
||
## 正文
|
||
|
||
To search repositories and projects, login to [gitlab.com](https://gitlab.com/users/sign_in/).
|
||
|
||
Ship at agent speed. Prove every step. Transcend returns on October 6.Register now
|
||
|
||
Published on: January 14, 2021
|
||
|
||
9 min read
|
||
|
||
This post is about a wild discovery made while investigating strange behavior from HAProxy. We dive into the pathology, describe how we found it, and share some investigative techniques used along the way.
|
||
|
||
This blog post was originally published on the GitLab Unfiltered blog. It was reviewed and republished on 2021-02-12.
|
||
|
||
- 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.
|
||
|
||
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):
|
||
|
||
```
|
||
- 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 straightforward enough, let's go ahead and apply that change.
|
||
|
||
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.
|
||
|
||
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?
|
||
|
||
This is when I reached out to [Matt Smiley](https://about.gitlab.com/company/#/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:
|
||
|
||
 Traffic capture in Wireshark showing a TCP FIN and the string QUIT in the stream
|
||
|
||
|
||
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.
|
||
|
||
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, 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 behavior 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.
|
||
|
||
To validate the theory and develop a potential workaround, we modify
|
||
`haproxy.cfg` to use a different backend server name.
|
||
|
||
The new diff is:
|
||
|
||
```
|
||
- 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 merge request fixing it](https://gitlab.com/gitlab-cookbooks/gitlab-haproxy/-/merge_requests/261).
|
||
|
||
`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, Matt 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!
|
||
|
||
Engineering
|
||
|
||
Enjoyed reading this blog post or have questions or feedback? Share your thoughts by creating a new topic in the GitLab community forum.
|
||
|
||
Start building faster today
|
||
|
||
See what your team can do with the intelligent orchestration platform for DevSecOps.
|