TCP2: Handling of RST flag from server makes poll() call unable to return indefinitely

[escriber]

Describe the bug
The poll()/zsock_poll() call hangs when a TCP message with a RST flag is received.

I have looked into the TCP2 code and added some debug statements to determine whether the message is passed to the TCP2 stack, which is not the case. This same was done to the zsock_poll() call where I can see that the z_pend_curr() in z_impl_k_poll() doesn't return.

To Reproduce
Run the supplied code example
tcp_rst.zip

Expected behavior
I expect the TCP message to be handled by the TCP2 code and the poll() call to return with a POLLHUP event on my socket.

Impact
Showstopper as it completely blocks the thread.

Logs and console output

Text log from zephyr OS

*** Booting Zephyr OS build v2.4.0-ncs1  ***
TCP_RST problem code started
[00:00:00.038,757] <err> eth_ksz8851: Memory self test: 0x1010
[00:00:00.040,222] <err> eth_ksz8851: KSZ8851 driver thread id: 0x200107f8
[00:00:00.040,496] <inf> eth_ksz8851: KSZ8851 Initialized
[00:00:00.040,679] <dbg> net_conn.conn_register_debug: (0x20011bf8): [0x200124b4/17/1/0x1d] remote -/67
[00:00:00.040,710] <dbg> net_conn.conn_register_debug: (0x20011bf8):   local 0.0.0.0/68 cb 0x00015155 ud 0x00000000
[00:00:00.093,322] <err> module_Tcp: Tcp thread id: 0x200103b8
[00:00:00.093,353] <dbg> module_Tcp.TcpInit: TcpInit start
[00:00:00.093,383] <inf> module_Tcp: Pointer to iface ETH_0 0x20010348
[00:00:00.093,475] <dbg> module_Tcp.NetworkMgmtHandler: callback_handler start
[00:00:00.093,475] <err> module_Tcp: Received Network management event: 3758358529
[00:00:00.093,505] <err> module_Tcp: Network management event: IPV4_ADDR_ADD
[00:00:00.093,688] <err> module_Tcp: Interface 0x20010348: ip=172.16.16.200, netmask=255.255.255.0, gateway=192.168.0.254
[00:00:00.093,688] <dbg> module_Tcp.NetworkMgmtHandler: callback_handler end
[00:00:00.093,719] <dbg> module_Tcp.TcpInit: TcpInit end
[00:00:02.170,104] <inf> eth_ksz8851: Link status changed
[00:00:02.170,166] <inf> eth_ksz8851: Port Status: status link up 1, an done 1, speed: 100, duplex: half
[00:00:02.170,166] <inf> eth_ksz8851: Partner Capability: 10BT half 0, 10BT full 0, 100BT half 4, 100BT full 0
[00:00:02.170,196] <err> eth_ksz8851: Clear Wake-Up Event Indication
[00:00:10.093,811] <dbg> module_Tcp.TcpOpenSocket: NetworkingSocketOpen start
[00:00:11.139,953] <dbg> net_tcp.tcp_conn_ref: (0x200103b8): conn: 0x20024890, ref_count: 1
[00:00:11.139,984] <dbg> net_tcp.tcp_conn_alloc: (0x200103b8): conn: 0x20024890
[00:00:11.186,920] <dbg> net_sock.zsock_socket_internal: (0x200103b8): socket: ctx=0x20012190, fd=0
[00:00:11.232,940] <dbg> net_tcp.net_tcp_connect: (0x200103b8): context: 0x20012190, local: 0.0.0.0, remote: 172.16.16.80
[00:00:11.233,032] <dbg> net_tcp.net_tcp_connect: (0x200103b8): conn: 0x20024890 src: 172.16.16.200, dst: 172.16.16.80
[00:00:11.233,154] <dbg> net_conn.conn_register_debug: (0x200103b8): [0x20012494/6/1/0x3f] remote 172.16.16.80/4433
[00:00:11.233,215] <dbg> net_conn.conn_register_debug: (0x200103b8):   local 0.0.0.0/43581 cb 0x00017d99 ud 0x20012190
[00:00:11.233,215] <wrn> net_tcp: Received flags:0xffffffff, and len=-1|-1
[00:00:11.233,306] <dbg> net_tcp.tcp_in: (0x200103b8):  [LISTEN Seq=2183506434 Ack=0]
[00:00:11.233,520] <dbg> net_tcp.tcp_out_ext: (0x200103b8): SYN Seq=2183506434 Len=0
[00:00:11.233,612] <dbg> net_tcp.tcp_send_process_no_lock: (0x200103b8): SYN Seq=2183506434 Len=0
[00:00:11.233,795] <dbg> net_tcp.tcp_send: (0x200103b8): SYN Seq=2183506434 Len=0
[00:00:11.234,558] <err> eth_ksz8851: Packet (0x20023908) transmitted. bytes: 42 (2006)
[00:00:11.234,741] <err> eth_ksz8851: Finished transmit routine
[00:00:11.235,076] <inf> eth_ksz8851: Transmitted frame. TXQ space:(6144)
[00:00:11.235,809] <dbg> net_tcp.tcp_in: (0x200103b8): LISTEN->SYN_SENT
[00:00:11.236,877] <err> eth_ksz8851: Packet (0x20023950) transmitted. bytes: 54 (2006)
[00:00:11.237,060] <err> eth_ksz8851: Finished transmit routine
[00:00:11.237,396] <inf> eth_ksz8851: Transmitted frame. TXQ space:(6144)
[00:00:11.238,616] <dbg> net_ipv4.net_ipv4_input: (0x200119a0): IPv4 packet received from 172.16.16.80 to 172.16.16.200
[00:00:11.238,677] <dbg> net_conn.net_conn_input: (0x200119a0): Check TCP listener for pkt 0x200235f0 src port 4433 dst port 43581 family 1
[00:00:11.238,677] <dbg> net_conn.net_conn_input: (0x200119a0): [0x20012494] match found cb 0x00017d99 ud 0x20012190 rank 0x3f
[00:00:11.238,739] <wrn> net_tcp: Received flags:0x12, and len=44|0
[00:00:11.238,952] <dbg> net_tcp.tcp_in: (0x200119a0): SYN,ACK Seq=1762929497 Ack=2183506435 Len=0 [SYN_SENT Seq=2183506435 Ack=0]
[00:00:11.238,952] <dbg> net_tcp.tcp_options_check: (0x200119a0): len=4
[00:00:11.238,983] <dbg> net_tcp.tcp_options_check: (0x200119a0): opt: 2, opt_len: 4
[00:00:11.238,983] <dbg> net_tcp.tcp_options_check: (0x200119a0): MSS=1460
[00:00:11.239,013] <dbg> net_tcp.tcp_in: (0x200119a0): Lowering send window from 14600 to 1536
[00:00:11.239,105] <dbg> net_tcp.tcp_send_timer_cancel: (0x200119a0): SYN Seq=2183506434 Len=0
[00:00:11.239,379] <dbg> net_tcp.tcp_out_ext: (0x200119a0): ACK Seq=2183506435 Ack=1762929498 Len=0
[00:00:11.239,501] <dbg> net_tcp.tcp_send_process_no_lock: (0x200119a0): ACK Seq=2183506435 Ack=1762929498 Len=0
[00:00:11.239,654] <dbg> net_tcp.tcp_send: (0x200119a0): ACK Seq=2183506435 Ack=1762929498 Len=0
[00:00:11.239,685] <dbg> net_tcp.tcp_in: (0x200119a0): SYN_SENT->ESTABLISHED
[00:00:11.239,715] <err> net_tcp: TCP_ESTABLISHED flags=0x00
[00:00:11.240,203] <dbg> net_tcp.net_tcp_connect: (0x200103b8): conn: 0x20024890, ret=0
[00:00:11.240,386] <err> eth_ksz8851: Packet (0x20023998) transmitted. bytes: 54 (2006)
[00:00:11.240,570] <err> eth_ksz8851: Finished transmit routine
[00:00:11.235,076] <inf> eth_ksz8851: Transmitted frame. TXQ space:(6144)
[00:00:11.240,997] <dbg> net_tcp.net_tcp_recv: (0x200103b8): context: 0x20012190, cb: 0x0000f341, user_data: 0x00000000
[00:00:11.241,027] <dbg> module_Tcp.TcpThreadFxn: Start Tcp Msg handling
[00:00:11.241,058] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): loop: k_poll timeout=4294967296, no_wait=0, k_forever=1
[00:00:11.241,058] <dbg> zsoc_poll.z_impl_k_poll: register_events
[00:00:11.241,088] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End k_poll. ret=-11
[00:00:11.241,088] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End loop. ret=1
[00:00:11.241,088] <wrn> module_Tcp: SOCKET OPENED
[00:00:11.241,119] <dbg> module_Tcp.TcpThreadFxn: Ended Tcp Msg handling
[00:00:11.241,119] <dbg> module_Tcp.TcpThreadFxn: Start Tcp Msg handling
[00:00:11.241,149] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): loop: k_poll timeout=16383, no_wait=0, k_forever=1
[00:00:11.241,149] <dbg> zsoc_poll.z_impl_k_poll: register_events
[00:00:11.241,180] <dbg> zsoc_poll.z_impl_k_poll: Z_WAIT_Q_INIT
[00:00:11.241,180] <dbg> zsoc_poll.z_impl_k_poll: z_pend_curr 16383
[00:00:11.741,241] <dbg> zsoc_poll.z_impl_k_poll: clear_event_registrations
[00:00:11.741,271] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End k_poll. ret=-11
[00:00:11.741,302] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End loop. ret=0
[00:00:11.741,302] <dbg> module_Tcp.TcpThreadFxn: Ended Tcp Msg handling
...
[00:01:10.766,510] <dbg> module_Tcp.TcpThreadFxn: Start Tcp Msg handling
[00:01:10.766,540] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): loop: k_poll timeout=16384, no_wait=0, k_forever=1
[00:01:10.766,571] <dbg> zsoc_poll.z_impl_k_poll: register_events
[00:01:10.766,571] <dbg> zsoc_poll.z_impl_k_poll: Z_WAIT_Q_INIT
[00:01:10.766,571] <dbg> zsoc_poll.z_impl_k_poll: z_pend_curr 16384
[00:01:11.243,591] <dbg> net_ipv4.net_ipv4_input: (0x200119a0): IPv4 packet received from 172.16.16.80 to 172.16.16.200
[00:01:11.243,652] <dbg> net_conn.net_conn_input: (0x200119a0): Check TCP listener for pkt 0x200235f0 src port 4433 dst port 43581 family 1
[00:01:11.243,682] <dbg> net_conn.net_conn_input: (0x200119a0): [0x20012494] match found cb 0x00017d99 ud 0x20012190 rank 0x3f
[00:01:11.243,713] <wrn> net_tcp: Received flags:0x10, and len=40|0
[00:01:11.243,957] <dbg> net_tcp.tcp_in: (0x200119a0): ACK Seq=1762929497 Ack=2183506435 Len=0 [ESTABLISHED Seq=2183506435 Ack=1762929498]
[00:01:11.243,957] <dbg> net_tcp.tcp_in: (0x200119a0): Lowering send window from 14600 to 1536
[00:01:11.243,988] <err> net_tcp: TCP_ESTABLISHED flags=0x10
[00:01:11.266,662] <dbg> zsoc_poll.z_impl_k_poll: clear_event_registrations
[00:01:11.266,662] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End k_poll. ret=-11
[00:01:11.266,693] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End loop. ret=0
[00:01:11.266,693] <dbg> module_Tcp.TcpThreadFxn: Ended Tcp Msg handling
...
[00:01:15.768,615] <dbg> module_Tcp.TcpThreadFxn: Start Tcp Msg handling
[00:01:15.768,646] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): loop: k_poll timeout=16384, no_wait=0, k_forever=1
[00:01:15.768,676] <dbg> zsoc_poll.z_impl_k_poll: register_events
[00:01:15.768,676] <dbg> zsoc_poll.z_impl_k_poll: Z_WAIT_Q_INIT
[00:01:15.768,676] <dbg> zsoc_poll.z_impl_k_poll: z_pend_curr 16384
[00:01:16.244,873] <dbg> net_ipv4.net_ipv4_input: (0x200119a0): IPv4 packet received from 172.16.16.80 to 172.16.16.200
[00:01:16.244,903] <dbg> net_conn.net_conn_input: (0x200119a0): Check TCP listener for pkt 0x200235f0 src port 4433 dst port 43581 family 1
[00:01:16.244,934] <dbg> net_conn.net_conn_input: (0x200119a0): [0x20012494] match found cb 0x00017d99 ud 0x20012190 rank 0x3f
[00:01:16.244,964] <wrn> net_tcp: Received flags:0x10, and len=40|0
[00:01:16.245,178] <dbg> net_tcp.tcp_in: (0x200119a0): ACK Seq=1762929497 Ack=2183506435 Len=0 [ESTABLISHED Seq=2183506435 Ack=1762929498]
[00:01:16.245,208] <dbg> net_tcp.tcp_in: (0x200119a0): Lowering send window from 14600 to 1536
[00:01:16.245,208] <err> net_tcp: TCP_ESTABLISHED flags=0x10
[00:01:16.268,768] <dbg> zsoc_poll.z_impl_k_poll: clear_event_registrations
[00:01:16.268,768] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End k_poll. ret=-11
[00:01:16.268,798] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): End loop. ret=0
[00:01:16.268,798] <dbg> module_Tcp.TcpThreadFxn: Ended Tcp Msg handling
...
[00:01:20.270,507] <dbg> module_Tcp.TcpThreadFxn: Start Tcp Msg handling
[00:01:20.270,538] <dbg> net_sock.z_impl_zsock_poll: (0x200103b8): loop: k_poll timeout=16384, no_wait=0, k_forever=1
[00:01:20.270,568] <dbg> zsoc_poll.z_impl_k_poll: register_events
[00:01:20.270,568] <dbg> zsoc_poll.z_impl_k_poll: Z_WAIT_Q_INIT
[00:01:20.270,568] <dbg> zsoc_poll.z_impl_k_poll: z_pend_curr 16384

Environment (please complete the following information):
Custom NRF9160 board with a KSZ8851 ethernet chip.
Using the Nordic SDK v1.4.0

[jukkar]

I just fixed one RST packet handling in commit b519ba5. Could you try to revert that commit and report did it help?

[jukkar]

The RST handling patch introduced in #29835 was missing unit tests. The tests can be found in #30142

[escriber]

I have updated to #30142 and the problem remains. I did some additional testing where i discovered the following:

• Calling poll() after the socket connection was established, results in the thread blocking on poll() while the RST message is never passed from the ethernet driver to the upper layers.
• Stop calling poll() after the connection was established, results in the RST message being passed to the upper layers and the TCP connection is closed.

So maybe the fault doesn't occur in the TCP2 code, but earlier?

[00:01:15.462,646] <inf> eth_ksz8851: RX interrupt with framecount: 1
[00:01:15.463,806] <err> eth_ksz8851: read_fifo: length=64
[00:01:15.464,355] <inf> eth_ksz8851: Forwarded packet to higher layer: 64
[00:01:15.464,752] <dbg> net_ipv4.net_ipv4_input: (rx_q[0]): IPv4 packet received from 172.16.16.80 to 172.16.16.98
[00:01:15.464,813] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20026090 src port 4433 dst port 56724 family 1
[00:01:15.464,874] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x20014610] match found cb 0x0001ca71 ud 0x2001430c rank 0x3f
[00:01:15.465,209] <dbg> net_tcp.tcp_in: (rx_q[0]): ACK,RST Seq=3791526107 Ack=4097630127 Len=0 [ESTABLISHED Seq=4097630127 Ack=3791526107]
[00:01:15.465,240] <dbg> net_tcp.tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:01:15.465,362] <dbg> net_tcp.tcp_conn_unref: (rx_q[0]): conn: 0x20029730, ref_count=1
[00:01:15.465,393] <dbg> net_conn.net_conn_unregister: (rx_q[0]): Connection handler 0x20014610 removed
[00:01:15.465,423] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x2001430c, pkt=0x00000000, st=-54, user_data=0x00000000
[00:01:15.465,454] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Marked socket 0x2001430c as peer-closed

[escriber]

By giving the logging thread a higher priority to my thread calling pol() I figured out what my thread was doing. Seems that I misunderstood the behavior of the thread. The RST flag is properly received by the TCP2 code regardless of whether I'm calling poll().

When the connection is closed the poll() call keeps returning with a POLLIN event on the socket and the recv() call returns 0 bytes.

Is this how the poll() call should return when the connection is closed?

RX interrupt with framecount: 1
[00:01:16.334,259] <err> eth_ksz8851: read_fifo: length=64,len=64
[00:01:16.334,594] <dbg> net_core.net_recv_data: (KSZ8851): prio 0 iface 0x20010380 pkt 0x20026088 len 64
Forwarded packet to higher layer: 64
Received frame size: 64
RX interrupt end
[00:01:16.334,930] <dbg> net_core.net_rx: (rx_q[0]): Received pkt 0x20026088 len 64
[00:01:16.335,083] <dbg> net_ipv4.net_ipv4_input: (rx_q[0]): IPv4 packet received from 172.16.16.80 to 172.16.16.98
[00:01:16.335,144] <dbg> net_conn.net_conn_input: (rx_q[0]): Check TCP listener for pkt 0x20026088 src port 4433 dst port 36341 family 1
[00:01:16.335,235] <dbg> net_conn.net_conn_input: (rx_q[0]): [0x20014610] match found cb 0x0001cf41 ud 0x2001430c rank 0x3f
[00:01:16.335,571] <dbg> net_tcp.tcp_in: (rx_q[0]): ACK,RST Seq=619260065 Ack=3440184932 Len=0 [ESTABLISHED Seq=3440184932 Ack=619260065]
[00:01:16.335,601] <dbg> net_tcp.tcp_in: (rx_q[0]): ESTABLISHED->CLOSED
[00:01:16.335,693] <dbg> net_tcp.tcp_conn_unref: (rx_q[0]): conn: 0x20029728, ref_count=1
[00:01:16.335,723] <dbg> net_conn.net_conn_unregister: (rx_q[0]): Connection handler 0x20014610 removed
[00:01:16.335,754] <dbg> net_sock.zsock_received_cb: (rx_q[0]): ctx=0x2001430c, pkt=0x00000000, st=-54, user_data=0x00000000
[00:01:16.335,815] <dbg> net_sock.zsock_received_cb: (rx_q[0]): Marked socket 0x2001430c as peer-closed
[00:01:16.335,876] <dbg> net_core.processing_data: (rx_q[0]): Dropping pkt 0x20026088
[00:01:16.914,398] <wrn> module_rms: RECEIVED DATA
[00:01:16.914,428] <wrn> module_rms: Received (0) bytes
[00:01:16.914,489] <wrn> module_rms: RECEIVED DATA
[00:01:16.914,489] <wrn> module_rms: Received (0) bytes
[00:01:16.983,093] <wrn> module_rms: RECEIVED DATA
[00:01:16.983,093] <wrn> module_rms: Received (0) bytes
[00:01:17.053,436] <wrn> module_rms: RECEIVED DATA
[00:01:17.053,466] <wrn> module_rms: Received (0) bytes
[00:01:17.053,527] <wrn> module_rms: RECEIVED DATA
[00:01:17.053,558] <wrn> module_rms: Received (0) bytes
[00:01:17.211,914] <wrn> module_rms: RECEIVED DATA
[00:01:17.211,944] <wrn> module_rms: Received (0) bytes

[jukkar]

When the connection is closed the poll() call keeps returning with a POLLIN event on the socket and the recv() call returns 0 bytes.

Is this how the poll() call should return when the connection is closed?

Yes, if the connection is closed, any read will return 0 bytes. This is the normal BSD socket API convention.

[escriber]

Ok, thanks for your help.