Too Many TCP Resets
So, recently we enforced some firewall rules on a new environment, we did testing of the environment and everything was working as expected. In about 24 hours a lot of traffic from the web infrastructure was being denied and it continued, at first glance it looked like return traffic was being dropped, the web servers were sourcing at port 443 and the destination ports were using dynamic ports (RFC 6335) No user or application problems were reported when we enforced rules, and we waited additional days to see if anything came up. Nothing came up, the only thing was a spike in amount of syslog messages of dropped traffic coming from the web servers.
So from that point it really wasn’t an issue, but I thought it would be interesting to see what was going on. I started to look at the firewall logs and enabled debugging to syslog, and as you can see the TCP session is being built and we can also see the TCP Teardown, which should be the end of it, something else was happening instead and it was unexpected.
Wed Jun 20 11:58:46 2018;172.17.70.1; <167>Jun 20 2018 11:58:45 172.17.70.1 : %ASA-7-302013: Built inbound TCP connection 47772320 for OUTSIDE:203.0.113.147/43918 (203.0.113.147/43918) to INSIDE:172.17.77.250/443 (172.17.77.250/443)
Wed Jun 20 12:00:51 2018;172.17.70.1; <167>Jun 20 2018 12:00:50 172.17.70.1 : %ASA-7-302014: Teardown TCP connection 47772320 for OUTSIDE:203.0.113.147/43918 to INSIDE:172.17.77.250/443 duration 0:02:05 bytes 107244 TCP FINs from INSIDE
Wed Jun 20 12:00:51 2018;172.17.70.1; <167>Jun 20 2018 12:00:50 172.17.70.1 : %ASA-7-106015: Deny TCP (no connection) from 172.17.77.250/443 to 203.0.113.147/43918 flags RST on interface INSIDE
The web servers (172.17.77.250) are sending a RST (Reset) Flag back out the firewall which gets denied. This deny action generates the log message that I was seeing, but why would server 172.17.77.250 be sending a rest flag when the connection was already completed? To investigate this further I needed to do a packet capture to be able to determine what else is going on, maybe we where loosing traffic upstream and this was just a dirty TCP session I really couldn’t tell, so I started to capture the inside and outside interfaces on this firewall and here are the results: Inside Interface Capture
33437: 12:00:47.907301 172.17.77.250.443 > 203.0.113.147.43918: F 2320205170:2320205170(0) ack 991843171 win 65535
33438: 12:00:47.952480 203.0.113.147.43918 > 172.17.77.250.443: . ack 2320205171 win 65535
33748: 12:00:50.443687 203.0.113.147.43918 > 172.17.77.250.443: F 991843171:991843171(0) ack 2320205171 win 65535
33749: 12:00:50.443687 203.0.113.147.43918 > 172.17.77.250.443: R 991843172:991843172(0) ack 2320205171 win 0
33750: 12:00:50.443748 172.17.77.250.443 > 203.0.113.147.43918: R 2320205171:2320205171(0) win 0
On the first capture we can see the server 172.17.77.250 sending a FIN as noted with the letter “F”, so the server starts to end the connection. Following that we can see the client sending an acknowledgment as noted with the “. Ack”. We can also see that the client sends a FIN to finish up the connection. What’s interesting is at the same time the FIN is sent from the client a TCP Reset is also sent from the client. Normally we should have just ended the connection with a FIN and one more acknowledgment (ACK) from 172.17.77.250 since it started the TCP termination process. This would have end the connection peacefully, however in this example the client seems to send a FIN and a RST at the same time which causes 172.17.77.250 to also send a TCP RST back to the client.
If we looked at the outside interface capture, we pretty much see the same thing we can see the FIN being sent from 172.17.77.250 and acknowledgment from the client. The client sends the FIN and the reset flags back to 172.17.77.250 which ultimately should have just been a FIN, instead its FIN and RST. Notice we did not see 172.17.77.250 TCP RST across, this was because that packet was already denied from the inside interface. Outside Interface Capture
32158: 12:00:47.907316 172.17.77.250.443 > 203.0.113.147.43918: F 3349673389:3349673389(0) ack 965033113 win 65535
32159: 12:00:47.952480 203.0.113.147.43918 > 172.17.77.250.443: . ack 3349673390 win 65535
32468: 12:00:50.443672 203.0.113.147.43918 > 172.17.77.250.443: F 965033113:965033113(0) ack 3349673390 win 65535
32469: 12:00:50.443687 203.0.113.147.43918 > 172.17.77.250.443: R 965033114:965033114(0) ack 3349673390 win 0
I was not seeing this on every connection that was being made and the fact that this client was sending TCP RST at the end of the FIN tell us that it’s something the client is doing. I was able to run a test on my own against this to see what a good “peaceful” connection looks like to compare the results. I ran the same functions as what this client would be doing. In this example my IP address is 192.0.2.167, here are the results. From the firewall debugging logs we can see the TCP session being built for 192.0.2.167 and the TCP teardown, also notice we don’t see any denied TCP connections from 172.17.77.250, so that’s a good start!
Wed Jun 20 14:22:39 2018;172.17.70.1; <167>Jun 20 2018 14:22:34 172.17.70.1 : %ASA-7-609001: Built local-host OUTSIDE:192.0.2.167
Wed Jun 20 14:22:39 2018;172.17.70.1; <167>Jun 20 2018 14:22:34 172.17.70.1 : %ASA-7-302013: Built inbound TCP connection 49008818 for OUTSIDE:192.0.2.167/3954 (192.0.2.167/3954) to INSIDE:172.17.77.250/443 (172.17.77.250/443)
Wed Jun 20 14:22:55 2018;172.17.70.1; <167>Jun 20 2018 14:22:51 172.17.70.1 : %ASA-7-302014: Teardown TCP connection 49008818 for OUTSIDE:192.0.2.167/3954 to INSIDE:172.17.77.250/443 duration 0:00:16 bytes 1051013 TCP FINs from OUTSIDE
Wed Jun 20 14:22:55 2018;172.17.70.1; <167>Jun 20 2018 14:22:51 172.17.70.1 : %ASA-7-609002: Teardown local-host OUTSIDE:192.0.2.167 duration 0:00:16
Looking at the packet capture we can also see peaceful TCP sessions closing:
544: 14:22:51.372035 192.0.2.167.3954 > 172.17.77.250.443: F 221753878:221753878(0) ack 2290377569 win 64296 <nop,nop,timestamp 1618672784 1798676063>
545: 14:22:51.372218 172.17.77.250.443 > 192.0.2.167.3954: P 2290377569:2290377600(31) ack 221753879 win 64296 <nop,nop,timestamp 1798678251 1618672784>
546: 14:22:51.372234 172.17.77.250.443 > 192.0.2.167.3954: F 2290377600:2290377600(0) ack 221753879 win 64296 <nop,nop,timestamp 1798678251 1618672784>
547: 14:22:51.397608 192.0.2.167.3954 > 172.17.77.250.443: . ack 2290377600 win 64296 <nop,nop,timestamp 1618672790 1798678251>
548: 14:22:51.397699 192.0.2.167.3954 > 172.17.77.250.443: . ack 2290377601 win 64296 <nop,nop,timestamp 1618672790 1798678251>
The client (me) requested to finish up the connection, 172.17.77.250 is doing a TCP Push back to us we wait for the FIN from 172.17.77.250 which comes to us shortly. After that you can see two acknowledgments both are from me. The first ACK is for that TCP Push packet that was created by 172.17.77.250, the second ACK from the client (me) is acknowledgment of the FIN. We have ended the connection peacefully and that’s how it should be.
However, the Internet is a weird place and that’s not what’s happening, so what’s the issue? Well that really was hardest part of this problem and here’s my theory, 172.17.77.250 is sending a TCP RST back to the client is because 172.17.77.250 wasn’t expecting it in the first place. It was finishing up the connection between the client and because of this unexpected TCP packet from the client 172.17.77.250 sends a TCP RST. The connection is not valid, and our server wants to start over. In the meantime, the TCP session was already closed by the firewall because it saw that last FIN from the client. That last TCP RST packet from the server gets denied and never reaches the client, but that still does not answer our question.
Why are seeing a FIN and RST from the client in the first place? This TCP connection is using TLS, so I started to look at how TLS functions in a TCP connection. When communication starts, and we finish our TCP handshake, then if the connection is over TLS we do a TLS handshake-> After the two hosts agree on the ciphers and TLS settings data is exchanged encrypted->After TLS is done with the data TLS should send a close notify to “peacefully” end the TLS session->Following that TCP closes with a FIN and it is peaceful. :)
I couldn’t investigate the TLS packet because it was encrypted however I think it had something to do with the close notify action of TLS. Not all implementations of SSL/TLS follow that rule even through RFC 5246 seems to imply that a close notify is required. I think this would explain the reason why the server sends RST when it receives both a FIN and RST at the same time from the client, it was unexpected, and we did not close the TLS session properly. When I did the test, I didn’t get any TCP resets. Although we where not seeing any disruptions from this it was helpful to at least figure out what the problem is and then being able to theorize what we could do to fix that problem.
In this example its related to the client so we can’t do anything on our end. The fact that this is happening at the end of the TCP connection, you are not going to notice anyway because you already have data you requested. We don't really care how the connection closes. I hope this post was helpful in understanding how to dig in the weeds and even through the connection worked, its helpful to understand any anomalies because those could turn into problems in the future.