Understanding TCP Reassembly drops

85714

Created On 09/25/18 19:21 PM - Last Modified 06/13/23 13:41 PM

PAN-OS

Next-Generation Firewall

Resolution

This document discusses one common scenario while troubleshooting TCP reassembly packet drops

Here is a case study where, a client, 172.22.136.50 attempts to connect to a server 192.16.31.62 on destination port 80. The firewall is configured with dynamic address and port translation, because of which the SYN on the receive and the transmit stage show different IP and port numbers, although the IP ID remains the same.

The client sends the SYN. The firewall receives the SYN, performs NAT and transmits the SYN. The server receives the SYN and responds with a SYN-ACK. The firewall receives the SYN-ACK, de-nats it and transmits the packet back to the client. The SYN-ACK never makes it to the client from the firewall, and hence the client retries to connect 4 more times on the same port number, before attempting to make a connection on a new port number.

The first snapshot shows SYNs from the client to the server, on the receive, firewall, transmit and the drop stages ( although drop stage has no packets ) of the firewall. The second snapshot shows SYN-ACKs from the server to the client, again on the receive, transmit, firewall and the drop stages of the firewall.

a) The client first attempts to connect to the server with a SYN packet with the below IP and TCP values:

S IP: 172.22.136.50, D IP: 192.16.31.62, Ip.Id 24915, src port 44912, dest port 80, Seq# 2033466733, Ack#0

b) The firewall receives the packet, and translates the IP from 172.22.136.50 to 198.180.162.5 and the source ports from 44912 to 21081, so the SYN packets at the transmit stage have the below IP and TCP values

S IP: 198.180.162.5, D IP: 192.16.31.62, Ip.id 24915 src port 21081, dest port 80, Seq# 2033466733, Ack#0

c) The SYN eventually reaches the server and the server responds with a SYN-ACK. The SYN-ACK when received on the firewall have the below IP and TCP values:

S IP: 192.16.31.62, D IP: 198.180.162.5, Ip.id 0, src port 80, dest port 21081, Seq# 743112262, Ack# 2033466734

d) The firewall de-nats the SYN-ACK and transmits the packet out, with the below IP and TCP values

S IP: 192.16.31.62, D IP: 172.22.136.50, Ip.id 0, src port 80, dest port 44912, Seq# 743112262, Ack# 2033466734

Because the client never received the SYN-ACK, it retries 4 more times on the same source IP, destination IP, source port, destination port, seq# and Ack# before eventually giving up, and then attempting to connect again on a new port number.

S IP: 172.22.136.50, D IP: 192.16.31.62, Ip.Id 24916, src port 44912, dest port 80, Seq# 2033466733, Ack#0

S IP: 172.22.136.50, D IP: 192.16.31.62, Ip.Id 24917, src port 44912, dest port 80, Seq# 2033466733, Ack#0

S IP: 172.22.136.50, D IP: 192.16.31.62, Ip.Id 24918, src port 44912, dest port 80, Seq# 2033466733, Ack#0

S IP: 172.22.136.50, D IP: 192.16.31.62, Ip.Id 24919, src port 44912, dest port 80, Seq# 2033466733, Ack#0

The server receives all these SYNs and responds back to all these SYNs with their SYN-ACKs. Similar to SYN, the SYN-ACKs too have the same source IP, destination IP, source port, destination port, seq# and Ack#.

S IP: 192.16.31.62, D IP: 198.180.162.5, Ip.id 0, src port 80, dest port 21081, Seq# 743112262, Ack# 2033466734

It is expected to see Ip.Id 0 for SYN-ACKs. This doesnt mean that the packet is malformed.

After the first 4 failed attempts, the Server continues to retransmits the SYN-ACKs, but now on a different sequence#. Ideally a change in seq# in the Syn-Ack will not matter to the client, because the client doesnt know of the seq# yet of the server ( Client's Syn packet has an ack# 0 ).

As shown in the snapshots, the server retransmits SYN-ACKs with the below IP and TCP values:

S IP: 192.16.31.62, D IP: 198.180.162.5, Ip.id 0, src port 80, dest port 21081, Seq# 883668401, Ack# 2033466734

The firewall receives these SYN-ACKs and drops them with the below counter:

tcp_drop_packet 2 0 warn tcp pktproc packets dropped because of failure in tcp reassembly

The reason for the failure in TCP reassembly can be understood by enabling "tcp reass", along with the regular filters, captures and flow basic.

> debug dataplane packet-diag set log feature tcp
all all
fptcp fptcp
reass reass

>debug dataplane packet-diag show setting

.....

Logging
Enabled: yes
Log-throttle: no
Sync-log-by-ticks: yes
Features:
flow : basic
tcp : reass fptcp
Counters:

The below pan_packet_diag logs explain how the TCP reassebly failures caused the packet drops

a) Logs of the SYN transmitted

== 2015-09-01 13:21:45.170 -0400 ==
Packet received at fastpath stage
Packet info: len 74 port 30 interface 30 vsys 1
wqe index 227771 packet 0x0x80000004162190e6
Packet decoded dump:
L2: 70:81:05:ec:d4:3f->00:1b:17:00:04:1e, type 0x0800
IP: 172.22.136.50->192.16.31.62, protocol 6
version 4, ihl 5, tos 0x00, len 60,
id 24915, frag_off 0x4000, ttl 60, checksum 51665
TCP: sport 44912, dport 80, seq 2033466733, ack 0,
reserved 0, offset 10, window 5840, checksum 49659,
flags 0x0002 ( SYN), urgent data 0
TCP option:
00000000: 02 04 05 b4 04 02 08 0a 99 03 5c 3e 00 00 00 00 ........ ..\>....
00000010: 01 03 03 00 ....
Flow fastpath, session 371381
NAT session, run address/port translation
2015-09-01 13:21:45.171 -0400 debug: pan_tcp_reass(pan_reass.c:1999): REASS: work 0x8000000418bcdd00 session=371381 seqno=2033466733 tcplen=0 l4plen=0 c2s state 0
2015-09-01 13:21:45.171 -0400 debug: pan_tcp_tcb_init_base(pan_reass.c:612): SYN: c2s
2015-09-01 13:21:45.171 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:539): tcp mss 1460
2015-09-01 13:21:45.171 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:560): sack permitted
2015-09-01 13:21:45.172 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:568): ignoring tcp option 8
2015-09-01 13:21:45.172 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:553): tcp window scale 0
Syn Cookie: pan_reass(Init state): c2s:0 c2s:nxtseq 2033466734 c2s:startseq 2033466734 c2s:win 0 c2s:st 3 c2s:newsyn 0 :: s2c:nxtseq 0 s2c:startseq 0 s2c:win 5840 s2c:st 0 s2c:newsyn 0 ack 0 nosyn 0
2015-09-01 13:21:45.172 -0400 debug: pan_tcp_reass(pan_reass.c:2484):
session=371381 work 0x8000000418bcdd00 payload len 0, tcp data len 0, ret 0
Forwarding lookup, ingress interface 30
L3 mode, virtual-router 2
Route lookup in virtual-router 2, IP 192.16.31.62

b) "Lessing" through the pan_packet_diag logs, we come across the first SYN-ACK received by the firewall.

The fireawall receives this SYN-ACK at the fast path stage and evaluates the next packet it expects in the c2s direction, ie packet with a seq# 2033466734 ( typically the ACK packet from the client ). Likewise the next packet that it expects from the s2c direction is one with the seq# 743112263. After evaluating these conditions the firewall transmits the packet out.

== 2015-09-01 13:21:45.173 -0400 ==
Packet received at fastpath stage
Packet info: len 66 port 28 interface 28 vsys 0
wqe index 224088 packet 0x0x8000000416faf0e6
Packet decoded dump:
L2: b4:14:89:85:4e:43->00:1b:17:00:04:1c, type 0x0800
IP: 192.16.31.62->198.180.162.5, protocol 6
version 4, ihl 5, tos 0x08, len 52,
id 0, frag_off 0x4000, ttl 57, checksum 63923
TCP: sport 80, dport 21081, seq 743112262, ack 2033466734,
reserved 0, offset 8, window 14600, checksum 47633,
flags 0x0012 ( SYN ACK), urgent data 0
TCP option:
00000000: 02 04 05 b4 01 01 04 02 01 03 03 09 ........ ....
Flow fastpath, session 371381
NAT session, run address/port translation
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_reass(pan_reass.c:1999): REASS: work 0x8000000418b5ab80 session=371381 seqno=743112262 tcplen=0 l4plen=0 s2c state 0
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_tcb_init_base(pan_reass.c:612): SYN: s2c
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:539): tcp mss 1460
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:560): sack permitted
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:553): tcp window scale 9
Syn Cookie: pan_reass(Init state): c2s:1 c2s:nxtseq 2033466734 c2s:startseq 2033466734 c2s:win 14600 c2s:st 3 c2s:newsyn 0 :: s2c:nxtseq 743112263 s2c:startseq 743112263 s2c:win 5840 s2c:st 3 s2c:newsyn 0 ack 2033466734 nosyn 0
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_tcb_upd_state(pan_reass.c:783): TCP state=1 prev=3
2015-09-01 13:21:45.173 -0400 debug: pan_tcp_reass(pan_reass.c:2484):
session=371381 work 0x8000000418b5ab80 payload len 0, tcp data len 0, ret 0
Forwarding lookup, ingress interface 28
L3 mode, virtual-router 2
Route lookup in virtual-router 2, IP 172.22.136.50
Route found, interface ethernet1/15, zone 8, nexthop 10.174.62.17
Resolve ARP for IP 10.174.62.17 on interface ethernet1/15
ARP entry found on interface 30
Transmit packet on port 30.

c) The firewall also receives subsequent 3 retransmitted SYN-ACK packets with the seq# 743112262 and the ack# 2033466734, and transmits them out.

== 2015-09-01 13:21:46.169 -0400 ==
Packet received at fastpath stage
Packet info: len 66 port 28 interface 28 vsys 0
wqe index 222187 packet 0x0x80000004162018e6
Packet decoded dump:
L2: b4:14:89:85:4e:43->00:1b:17:00:04:1c, type 0x0800
IP: 192.16.31.62->198.180.162.5, protocol 6
version 4, ihl 5, tos 0x08, len 52,
id 0, frag_off 0x4000, ttl 57, checksum 63923
TCP: sport 80, dport 21081, seq 743112262, ack 2033466734,
reserved 0, offset 8, window 14600, checksum 47633,
flags 0x0012 ( SYN ACK), urgent data 0
TCP option:
00000000: 02 04 05 b4 01 01 04 02 01 03 03 09 ........ ....
Flow fastpath, session 371381
NAT session, run address/port translation
2015-09-01 13:21:46.169 -0400 debug: pan_tcp_reass(pan_reass.c:1999): REASS: work 0x8000000418b1f500 session=371381 seqno=743112262 tcplen=0 l4plen=0 s2c state 1
2015-09-01 13:21:46.169 -0400 debug: pan_tcp_tcb_init_base(pan_reass.c:612): SYN: s2c
2015-09-01 13:21:46.169 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:539): tcp mss 1460
2015-09-01 13:21:46.169 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:560): sack permitted
2015-09-01 13:21:46.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:553): tcp window scale 9
Syn Cookie: pan_reass(new syn): c2s:1 c2s:nxtseq 2033466734 c2s:startseq 2033466734 c2s:win 14600 c2s:st 3 c2s:newsyn 0 :: s2c:nxtseq 743112263 s2c:startseq 743112263 s2c:win 5840 s2c:st 1 s2c:newsyn 0 ack 2033466734 nosyn 0
2015-09-01 13:21:46.170 -0400 debug: pan_tcp_reass(pan_reass.c:2484):
session=371381 work 0x8000000418b1f500 payload len 0, tcp data len 0, ret 0
Forwarding lookup, ingress interface 28
L3 mode, virtual-router 2
Route lookup in virtual-router 2, IP 172.22.136.50
Route found, interface ethernet1/15, zone 8, nexthop 10.174.62.17
Resolve ARP for IP 10.174.62.17 on interface ethernet1/15
ARP entry found on interface 30
Transmit packet on port 30
-------------------------------------------
== 2015-09-01 13:21:48.169 -0400 ==
Packet received at fastpath stage
Packet info: len 66 port 28 interface 28 vsys 0
wqe index 227536 packet 0x0x8000000416e7e8e6
Packet decoded dump:
L2: b4:14:89:85:4e:43->00:1b:17:00:04:1c, type 0x0800
IP: 192.16.31.62->198.180.162.5, protocol 6
version 4, ihl 5, tos 0x08, len 52,
id 0, frag_off 0x4000, ttl 57, checksum 63923
TCP: sport 80, dport 21081, seq 743112262, ack 2033466734,
reserved 0, offset 8, window 14600, checksum 47633,
flags 0x0012 ( SYN ACK), urgent data 0
TCP option:
00000000: 02 04 05 b4 01 01 04 02 01 03 03 09 ........ ....
Flow fastpath, session 371381
NAT session, run address/port translation
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_reass(pan_reass.c:1999): REASS: work 0x8000000418bc6780 session=371381 seqno=743112262 tcplen=0 l4plen=0 s2c state 1
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_tcb_init_base(pan_reass.c:612): SYN: s2c
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:539): tcp mss 1460
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:560): sack permitted
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:553): tcp window scale 9
Syn Cookie: pan_reass(new syn): c2s:1 c2s:nxtseq 2033466734 c2s:startseq 2033466734 c2s:win 14600 c2s:st 3 c2s:newsyn 0 :: s2c:nxtseq 743112263 s2c:startseq 743112263 s2c:win 5840 s2c:st 1 s2c:newsyn 0 ack 2033466734 nosyn 0
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_reass(pan_reass.c:2484):
session=371381 work 0x8000000418bc6780 payload len 0, tcp data len 0, ret 0
Forwarding lookup, ingress interface 28
L3 mode, virtual-router 2
Route lookup in virtual-router 2, IP 172.22.136.50
Route found, interface ethernet1/15, zone 8, nexthop 10.174.62.17
Resolve ARP for IP 10.174.62.17 on interface ethernet1/15
ARP entry found on interface 30
Transmit packet on port 30
------------------------------------------

== 2015-09-01 13:21:48.170 -0400 ==
Packet received at fastpath stage
Packet info: len 66 port 28 interface 28 vsys 0
wqe index 226639 packet 0x0x8000000416a288e6
Packet decoded dump:
L2: b4:14:89:85:4e:43->00:1b:17:00:04:1c, type 0x0800
IP: 192.16.31.62->198.180.162.5, protocol 6
version 4, ihl 5, tos 0x08, len 52,
id 0, frag_off 0x4000, ttl 57, checksum 63923
TCP: sport 80, dport 21081, seq 743112262, ack 2033466734,
reserved 0, offset 8, window 14600, checksum 47633,
flags 0x0012 ( SYN ACK), urgent data 0
TCP option:
00000000: 02 04 05 b4 01 01 04 02 01 03 03 09 ........ ....
Flow fastpath, session 371381
NAT session, run address/port translation
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_reass(pan_reass.c:1999): REASS: work 0x8000000418baa700 session=371381 seqno=743112262 tcplen=0 l4plen=0 s2c state 1
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_tcb_init_base(pan_reass.c:612): SYN: s2c
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:539): tcp mss 1460
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:560): sack permitted
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_parse_options_syn(pan_reass.c:553): tcp window scale 9
Syn Cookie: pan_reass(new syn): c2s:1 c2s:nxtseq 2033466734 c2s:startseq 2033466734 c2s:win 14600 c2s:st 3 c2s:newsyn 0 :: s2c:nxtseq 743112263 s2c:startseq 743112263 s2c:win 5840 s2c:st 1 s2c:newsyn 0 ack 2033466734 nosyn 0
2015-09-01 13:21:48.170 -0400 debug: pan_tcp_reass(pan_reass.c:2484):
session=371381 work 0x8000000418baa700 payload len 0, tcp data len 0, ret 0
Forwarding lookup, ingress interface 28
L3 mode, virtual-router 2
Route lookup in virtual-router 2, IP 172.22.136.50
Route found, interface ethernet1/15, zone 8, nexthop 10.174.62.17
Resolve ARP for IP 10.174.62.17 on interface ethernet1/15
ARP entry found on interface 30
Transmit packet on port 30

d) When the firewall receives the next set of SYN-ACKs from the server with the changed seq# 883668401, it drops the packet. This is an expected behavior because while the firewall waits for the TCP Handshake timeout of 10 secs (Maximum length of time between receiving the SYN-ACK and the subsequent ACK to fully establish the session), it kept track of the next expected seq# from the server side as 743112263, but received a packet with the seq# 883668401. This mismatch in the seq# causes the firewall to drop the packet. Likewise all the subsequent packets with the seq# 883668401, are dropped by the PAN.

== 2015-09-01 13:21:54.169 -0400 ==
Packet received at fastpath stage
Packet info: len 66 port 28 interface 28 vsys 0
wqe index 222256 packet 0x0x80000004165330e6
Packet decoded dump:
L2: b4:14:89:85:4e:43->00:1b:17:00:04:1c, type 0x0800
IP: 192.16.31.62->198.180.162.5, protocol 6
version 4, ihl 5, tos 0x08, len 52,
id 0, frag_off 0x4000, ttl 57, checksum 63923
TCP: sport 80, dport 21081, seq 883668401, ack 2033466734,
reserved 0, offset 8, window 14600, checksum 64069,
flags 0x0012 ( SYN ACK), urgent data 0
TCP option:
00000000: 02 04 05 b4 01 01 04 02 01 03 03 09 ........ ....
Flow fastpath, session 371381
NAT session, run address/port translation
2015-09-01 13:21:54.169 -0400 debug: pan_tcp_reass(pan_reass.c:1999): REASS: work 0x8000000418b21780 session=371381 seqno=883668401 tcplen=0 l4plen=0 s2c state 1
2015-09-01 13:21:54.169 -0400 debug: pan_tcp_reass(pan_reass.c:2074): REASS: session=371381 seqno=883668401 rcv_nxt=743112263 new connection
2015-09-01 13:21:54.169 -0400 debug: pan_tcp_reass(pan_reass.c:2090): sequence number in SYN_ACK not consistent (current+1 883668402 vs start_seq 743112263), drop
2015-09-01 13:21:54.169 -0400 debug: pan_tcp_reass(pan_reass.c:2484):
session=371381 work 0x8000000418b21780 payload len 0, tcp data len 0, ret 2
TCP reassembly failed: ret 2

Understanding TCP Reassembly drops

Resolution

Other users also viewed: