net_if_tx sends a 0 Reference counter(pkt->ref == 0) packet

[mazhenke]

Hi,
I am an engineer from ARM china, and I am using Zephyr for some network demo, and it seems I run into a zephyr network issue, please help to have a check.

My test is a socket API based stress test, descriptions as bellow:

1. On my PC, I ran a socket echo server, which simply did the following loop:
   connect -> receive -> send -> receive -> send -> ... ... -> receive -> send -> close
2. On my board (nucleo_f429zi) I have implemented a sample echo client loop using socket APIs:
   a. sock = socket(xxx) // using AF_INET and SOCK_STREAM
   b. ret = connect(socket, xxx,xxx)
   c. while (1) {
   ret = send(xxx)
   ret = recv(xxx)
   }
   d. close(sock)
3. In the project configurations, I only enabled IPV4 (CONFIG_NET_IPV6=n), and enabled some net debug options(CONFIG_NET_LOG=y, CONFIG_SYS_LOG_NET_LEVEL=4), and some other configurations which I think it is not related with this issue.

And also I add a assert at
static bool net_if_tx(struct net_if *iface, struct net_pkt *pkt)
function in net_if.c file :

**NET_ASSERT(pkt->ref != 0);
if (0 == pkt->ref) {
    while (1);
}**

and my stress test ran into the assert, UART log:

[net/ethernet] [DBG] ethernet_send: (0x200044f4): Found ARP entry, sending pkt 0x2000615c to iface 0x2000d6a0
[net/core] [DBG] processing_data: (0x200044f4): Consumed pkt 0x20005bb8
[net/pkt] [DBG] net_pkt_print: (0x200044f4): TX 13 RX 13 RDATA 32 TDATA 35
[net/if] [DBG] net_if_tx: (0x2000457c): Processing (pkt 0x2000615c, data len 40, prio 0, ref: 1) network packet
[net/pkt] [DBG] net_pkt_unref_debug: (0x2000457c): TX [13] pkt 0x2000615c ref 0 frags 0x20007708 (eth_tx():123)
[net/pkt] [DBG] net_pkt_unref_debug: (0x2000457c): TDATA (tx_bufs) [35] frag 0x20007708 ref 0 frags 0x00000000 (eth_tx():123)
[net/pkt] [DBG] net_pkt_frag_unref_debug: (0x2000457c): TDATA (tx_bufs) [35] frag 0x20007708 ref 0 (net_pkt_unref_debug():802)
[net/if] [DBG] net_if_tx: (0x2000457c): Calling context send cb 0x20003ac8 token 0x00000000 status 0
BG] find_entry: (0x20005004): [0] iface 0x2000d6a0 dst 192.168.1.101 ll 00:80:E1:D5:8F:62 pending 0x00000000
[net/arp] [DBG] net_arp_prepare: (0x20005004): ARP using ll 00:80:E1:D5:8F:62 for IP 57.76.0.8
[net/ethernet] [DBG] ethernet_send: (0x20005004): Found ARP entry, sending pkt 0x2000615c to iface 0x2000d6a0
[net/if] [DBG] net_if_tx: (0x2000457c): Processing (pkt 0x2000615c, data len 268, prio 0, **ref: 0**) network packet
**[net/if] [ERR] net_if_tx: {assert: 'pkt->ref != 0' failed}**

Please have a check, thanks a lot!

[pfalcon]

@mazhenke : Any chance that you can reproduce this issue with existing socket samples in https://github.com/zephyrproject-rtos/zephyr/tree/master/samples/net/sockets ?

[mazhenke]

The socket samples in
https://github.com/zephyrproject-rtos/zephyr/tree/master/samples/net/sockets
are implementing a echo server in Zephyr, but my stress test case is implementing echo client loop in Zephyr.

# I think I have found the root cause of this issue.

The TCP sends data flow is like this:
net_tcp_send_pkt(in tcp.c) -> net_send_data(in net_core.c) -> net_if_send_data(in net_if.c) -> net_if_l2(iface)->send(l2 layer send, in my case is ethernet_send)

I found that if ethernet receive interrupt occurred during net_if_send_data, then the kernel scheduled(swapped) to the receive thread and do the network receiving. The network receiving will take some time, and after receiving finished, the previous TCP has timed out (CPU somehow runs to the tcp_retry_expired function in tcp.c). In tcp_retry_expired function, CPU send and unreference the previous package. But anyway kernel will scheduled back to the thread of previous net_if_send_data, and then we can see that an unreferenced package will be send.

I have generated a referenced workaround/fix on this issue:
https://github.com/mazhenke/zephyr/commit/fa4d39ce9a953bb4b4e75facd88cd83f93b82ac6

[mazhenke]

log.log
I have attached one log of my mps2+ board, and add comments in the log using:
/////////////////////////////////////////////////////////////////////////////////////////////////

[jukkar]

I have generated a referenced workaround/fix on this issue:
mazhenke/zephyr@fa4d39c

IMHO that fix is not a proper thing to do inside IP stack. If some TCP timeout is too short, then I suggest you try to increase the corresponding TCP timeout and see if it fixes the issue.

[pfalcon]

@jukkar:

IMHO that fix is not a proper thing to do inside IP stack.

Actually, I had the same idea of using k_sched_lock(), at least as a debugging measure. And I'm not sure it's not the right solution (if TX and RX threads are cooperative, then why entire IP stack processing shouldn't be? And as a lot of this processing happens in calling thread (instead of the dedicated threads), ergo...) I describe my adventures in #8190 (comment)

[pfalcon]

@mazhenke :

The socket samples in
https://github.com/zephyrproject-rtos/zephyr/tree/master/samples/net/sockets
are implementing a echo server in Zephyr, but my stress test case is implementing echo client loop in Zephyr.

The sockets samples are 5 different applications, which provide more or less good coverage of the IP stack functionality. And to fix this issue, other developers would need to reproduce it. And the best way to reproduce something is start to a common, well-known base, and that's socket samples.

I'm sure other developers will join with reproducing and looking for a fix to it. (For example, I'm eager to join in, but first need to work on issues, for which it's already known how to reproduce them on existing samples, e.g. #7831). So, in the meantime don't hesitate to extend your testing of this issue to the existing socket samples and/or provide a reproduction test case. Thanks!

[mazhenke]

@pfalcon
I have put my test case at:

https://github.com/mazhenke/zephyr/commit/cda18027157fd82a68ffd7213447dd57d15aef0a

reference to the README in samples/net/sockets/echo_client_stress/socket_echo_client
to reproduce this issue.

[jukkar]

@rveerama1 has been investigating #7423 which although totally different problem than this, is crashing in weird ways that look similar as what is described here.
After more investigation in that PR, we found out that the culprit is that the IP stack is entered in preemptive mode from main thread. This can lead to issues in IP stack which expects that all its functions are run in co-operative mode. One workaround would be to run the main thread in co-operative priority, so you could try to set CONFIG_MAIN_THREAD_PRIORITY=-1 if it solves the issue here.