For the past few weeks I have been trying to understand a problem that was brought to my attention when running a simple ab test through haproxy to a single Apache HTTP server. Attached are the config file and excerpts of the tcpdump.
This is a simple setup with 3 VMs: - Client: 10.15.85.151 - HAProxy: 10.15.85.152 - Server: 10.15.85.153 The HAProxy node is running haproxy-1.8.30, but the issue was originally reported with haproxy-1.8.27. Please note that I did not write this config file. I am using what was provided to me as a way to reproduce the problem locally. With httpd running on the server, an empty 5kb file is created on said server: # dd if=/dev/zero of=/var/www/html/5kb_dummy.html bs=1k count=5 On the client, run 'ab' to perform several HTTP requests: # ab -n 100000 -c 10000 http://10.15.85.152/5kb_dummy.html Occasionally I will see in the haproxy logs that a session was terminated with "SD" and a HTTP status of 200. Also, these responses seem truncated, which you might expect since the termination state is "SD". This is a static, 5kb file so we would expect to see log entries that have bytes_read (with headers) to be 5403. Here is a log entry: Apr 27 13:18:36 localhost haproxy[28516]: 10.15.85.151:39308 [27/Apr/2021:13:18:36.277] mesa mesa-http/mesa-virt-13 0/0/6/11/17 200 4344 - - SD-- 2000/2000/1998/1997/0 0/0 "GET /5kb_dummy.html HTTP/1.0" 10.15.85.152:59600 Here we have response code 200, termination state "SD" and bytes_read 4344. The timing values seem good. Note the custom format here just adds the backend source address and port, which makes it easier to find interesting packets in the pcap. Using tcpdump on the haproxy node and analyzing with wireshark, I filtered with: (ip.addr == 10.15.85.151 && tcp.port == 39308) || (ip.addr == 10.15.85.152 && tcp.port == 59600) Around time 13:18:36.277 is 1005899. This is where haproxy establishes a connection with the backend, as expected. Everything seems normal until the server sends the HTTP response, which seems to cause haproxy to send a RST to the server. That seems odd. Then I am not sure what happens, but this seems to be the case for every packet capture I've analyzed in which the SD problem occured. How I read the capture, just interesting frames: 1003310 - client connects to haproxy 1003634 - client sends HTTP GET request to haproxy 1005899 - haproxy connects to server 1006909 - haproxy sends HTTP GET request to server 1008524 - haproxy sends [FIN,ACK] to server I am assuming the FIN+ACK is haproxy telling the server is finished sending (ie. half-closed). Continuing: 1008541 - server sends HTTP response to haproxy If I drill down into this frame, I can see that there are 3 reassembled TCP segments for a total of 5403 bytes, which is correct. 1008543 - haproxy sends [RST] to the server Then it seems the connection between the client and haproxy is closed by both ends and we never see a response sent to the client. The way I understand the log entry is that bytes_read is the number of bytes sent to the client. What happened here? Now would be a good time to point out a few other observations: * Everytime I see a session terminated with SD, the number of active connections and frontend connections is 2000, which also happens to be maxconn for this config. Not sure if this is significant or not. * Using "show errors" with the stats socket shows nothing. * A colleague of mine can recreate this much more frequently than I can, despite the fact that we believe we have identical test environments. This does not happen often for me. I may have to run 'ab' on the client 10+ times before I trigger this issue. Other things I've tried: * Running strace on haproxy. Not a good idea. The performance penalty is so huge that it is impossible to reproduce the issue. * Running haproxy in debug mode. Somewhat helpful but everything appeared normal. * Attempted to debug httpd. I have no experience with this and found nothing useful. Also, I was informed that this only happens when nbthread is set (8 in case). While that seems to be true in my own testing, I don't think it is a factor. Removing 'nbthread 8' from this configuration just slows everything down so much that httpd isn't being hit with as many requests per second as it would when nbthread is set. I could be wrong about this. I definitely need to spend some time looking into request rate differences in this case. Appreciate any comments and/or suggestions. I am happy to provide more information if needed. Ryan
1003310 9.446910 10.15.85.151 → 10.15.85.152 TCP 74 [TCP Port numbers reused] 39308 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=626203413 TSecr=0 WS=128 1003311 9.446917 10.15.85.152 → 10.15.85.151 TCP 74 80 → 39308 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=2614875547 TSecr=626203413 WS=128 1003329 9.447032 10.15.85.151 → 10.15.85.152 TCP 66 39308 → 80 [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=626203413 TSecr=2614875547 1003634 9.449505 10.15.85.151 → 10.15.85.152 HTTP 160 GET /5kb_dummy.html HTTP/1.0 1005899 9.464642 10.15.85.152 → 10.15.85.153 TCP 74 [TCP Port numbers reused] 59600 → 80 [SYN] Seq=0 Win=29200 Len=0 MSS=1460 SACK_PERM=1 TSval=147502866 TSecr=0 WS=128 1006762 9.470015 10.15.85.153 → 10.15.85.152 TCP 74 80 → 59600 [SYN, ACK] Seq=0 Ack=1 Win=28960 Len=0 MSS=1460 SACK_PERM=1 TSval=641448456 TSecr=147502866 WS=128 1006763 9.470021 10.15.85.152 → 10.15.85.153 TCP 66 59600 → 80 [ACK] Seq=1 Ack=1 Win=29312 Len=0 TSval=147502871 TSecr=641448456 1006909 9.470699 10.15.85.152 → 10.15.85.153 HTTP 191 GET /5kb_dummy.html HTTP/1.0 1008137 9.479015 10.15.85.153 → 10.15.85.152 TCP 66 80 → 59600 [ACK] Seq=1 Ack=126 Win=29312 Len=0 TSval=641448466 TSecr=147502872 1008467 9.481508 10.15.85.153 → 10.15.85.152 TCP 2962 HTTP/1.1 200 OK [TCP segment of a reassembled PDU] 1008471 9.481521 10.15.85.152 → 10.15.85.153 TCP 66 59600 → 80 [ACK] Seq=126 Ack=2897 Win=35072 Len=0 TSval=147502883 TSecr=641448468 1008479 9.481540 10.15.85.153 → 10.15.85.152 TCP 1514 80 → 59600 [ACK] Seq=2897 Ack=126 Win=29312 Len=1448 TSval=641448468 TSecr=147502872 [TCP segment of a reassembled PDU] 1008487 9.481571 10.15.85.152 → 10.15.85.153 TCP 66 59600 → 80 [ACK] Seq=126 Ack=4345 Win=37888 Len=0 TSval=147502883 TSecr=641448468 1008524 9.481802 10.15.85.152 → 10.15.85.153 TCP 66 59600 → 80 [FIN, ACK] Seq=126 Ack=4345 Win=37888 Len=0 TSval=147502883 TSecr=641448468 1008528 9.481843 10.15.85.152 → 10.15.85.151 TCP 2962 HTTP/1.1 200 OK [TCP segment of a reassembled PDU] 1008531 9.481858 10.15.85.152 → 10.15.85.151 TCP 1514 80 → 39308 [ACK] Seq=2897 Ack=95 Win=29312 Len=1448 TSval=2614875614 TSecr=626203415 [TCP segment of a reassembled PDU] 1008541 9.481928 10.15.85.153 → 10.15.85.152 HTTP 1125 HTTP/1.1 200 OK (text/html) 1008543 9.481938 10.15.85.152 → 10.15.85.153 TCP 54 59600 → 80 [RST] Seq=126 Win=0 Len=0 1008569 9.482101 10.15.85.151 → 10.15.85.152 TCP 66 39308 → 80 [ACK] Seq=95 Ack=2897 Win=35072 Len=0 TSval=626203448 TSecr=2614875614 1008570 9.482108 10.15.85.152 → 10.15.85.151 TCP 66 80 → 39308 [FIN, ACK] Seq=4345 Ack=95 Win=29312 Len=0 TSval=2614875614 TSecr=626203448 1008573 9.482122 10.15.85.151 → 10.15.85.152 TCP 66 39308 → 80 [ACK] Seq=95 Ack=4345 Win=37888 Len=0 TSval=626203448 TSecr=2614875614 1008936 9.484817 10.15.85.151 → 10.15.85.152 TCP 66 39308 → 80 [FIN, ACK] Seq=95 Ack=4346 Win=37888 Len=0 TSval=626203451 TSecr=2614875614 1008937 9.484824 10.15.85.152 → 10.15.85.151 TCP 66 80 → 39308 [ACK] Seq=4346 Ack=96 Win=29312 Len=0 TSval=2614875617 TSecr=626203451
haproxy.cfg
Description: Binary data
