TCP traffic with IPSP sample not working on 96Boards Nitrogen

[huawei-wojciech-zmuda]

Hello,

I'm trying to get the Bluetooth IPSP sample application working on 96Boards Nitrogen. I follow the readme and the connection itself and pings work fine, but the echo-client and telnet examples do not work. Below please find results of my debugging. I cannot narrow down the reason of the problem, but I've noticed some interesting patterns.

Hardware and software setup

I have tried the two following setups with the same results:

[ Zephyr@Nitrogen ] --- BLE --- [ Linux@Avenger96 ]

[ Zephyr@Nitrogen ] --- BLE --- [ Linux@Thinkpad P1 ]

Zephyr is built from the top of the master branch 65ac2f6d1b cmake: remove TOOLCHAIN_INCLUDES.

Avenger96 is another 96Boards board with Broadcom-based Murata 1MW BT chipset, while my Thinkpad has an Intel chipset. This does not affect the issue, so I think the problem is on Nitrogen/Zephyr side.

Thinkpad is running Ubuntu with generic 5.8.0-44-generic #50~20.04.1-Ubuntu SMP kernel. Avenger is running a custom yocto-based Linux distro with Linux stm32mp1-av96 5.4.56 #1 SMP PREEMPT kernel built from STMicro sources.

Nitrogen is v1.1 02/16/2017 revision, has no peripherals connected and I use the on-board USB port for UART and flashing.

How to reproduce

Going through the IPSP readme file

1. Build and flash the IPSP sample onto the board

west build -p auto -b 96b_nitrogen -d build-ipsp samples/bluetooth/ipsp
west flash --hex-file build-ipsp/zephyr/zephyr.hex

2. After the IPSP application happily started, enable 6LoWPAN on the PC and connect to Nitrogen, set IP address on the new Bluetooth interface

# modprobe bluetooth_6lowpan
# echo 1 > /sys/kernel/debug/bluetooth/6lowpan_enable
# echo "connect <bdaddr> <type>" > /sys/kernel/debug/bluetooth/6lowpan_control
# ip address add 2001:db8::2/64 dev bt0

3. Ping Nitrogen from the PC - works

# ping6 -I bt0 2001:db8::1                      
PING 2001:db8::1(2001:db8::1) from 2001:db8::2 bt0: 56 data bytes
64 bytes from 2001:db8::1: icmp_seq=1 ttl=64 time=377 ms
64 bytes from 2001:db8::1: icmp_seq=2 ttl=64 time=367 ms
^C

4. Try to use telnet to Nitrogen from the PC - does not work

# telnet 2001:db8::1 4242
Trying 2001:db8::1...
^C

5. Try to use echo-client to Nitrogen from the PC - works

# ./echo-client -i bt0 2001:db8::1
Binding to 2001:db8::2
....Timeout while waiting idx 4 len 1500
..
Average round trip 126 ms
Sent 6 packets

Additional tests

1. Try to use echo-client but in TCP mode - does not work

# ./echo-client -t -i bt0 2001:db8::1
Binding to 2001:db8::2
connect: Connection timed out

2. Try to connect with netcat in TCP mode - does not work

# time nc 2001:db8::1 4242

real    2m9,514s
user    0m0,003s
sys     0m0,000s

2. Try to connect with netcat in UDP mode - works

# nc -u 2001:db8::1 4242
hey
hey
this is echo
this is echo
^C

Deeper debugging

Kernel configs manipulations

I tried a couple of things that had no effect but I mention them here just in case it brings an idea to somebody's mind:

• switching to the legacy TCP stack,
• increasing NET_TCP_BACKLOG_SIZE,
• enabling NET_TCP_AUTO_ACCEPT,
• increasing NET_MAX_CONTEXTS.

Zephyr shell fun

I built Zephyr with CONFIG_NET_SHELL=y to get shell and net commands so I can do additional experiments. I also enabled additional TCP logging.

Connect from Zephyr to netcat server in TCP and UDP modes

TCP

1. On the PC side spawn a netcat server in TCP mode

# nc -l 2001:db8::2 4242

2. On the Nitrogen side try to connect to the server

uart:~$ net tcp connect 2001:db8::2 4242
Connecting from [2001:db8::1]:0 to [2001:db8::2]:4242
[03:36:43.755,645] <dbg> net_tcp.tcp_conn_ref: (shell_uart): conn: 0x2000c054, ref_count: 1
[03:36:43.755,645] <dbg> net_tcp.tcp_conn_alloc: (shell_uart): conn: 0x2000c054
[03:36:43.755,920] <dbg> net_tcp.net_tcp_connect: (shell_uart): context: 0x200041ac, local: 2001:db8::1, remote: 2001:db8::2
[03:36:43.755,981] <dbg> net_tcp.net_tcp_connect: (shell_uart): conn: 0x2000c054 src: 2001:db8::1, dst: 2001:db8::2
[03:36:43.756,134] <dbg> net_tcp.tcp_in: (<log_strdup alloc failed>): <log_strdup alloc failed>
[03:36:43.756,347] <dbg> net_tcp.tcp_out_ext: (<log_strdup alloc failed>): <log_strdup alloc failed>
[03:36:43.756,469] <dbg> net_tcp.tcp_send_process_no_lock: (<log_strdup alloc failed>): <log_strdup alloc failed>
[03:36:43.756,652] <dbg> net_tcp.tcp_send: (<log_strdup alloc failed>): <log_strdup alloc failed>
[03:36:43.756,958] <dbg> net_tcp.tcp_in: (<log_strdup alloc failed>): LISTEN->SYN_SENT
[03:36:43.756,988] <dbg> net_tcp.tcp_conn_unref: (<log_strdup alloc failed>): conn: 0x2000c054, ref_count=1
[03:36:43.757,019] <dbg> net_tcp.net_tcp_unref: (<log_strdup alloc failed>): context: 0x200041ac, conn: (nil)
[03:36:43.757,080] <dbg> net_tcp.net_tcp_connect: (<log_strdup alloc failed>): conn: 0x2000c054, ret=-60

See that it does not work and the connection fails immediately because of timeout. The -60 return code seems to be ret = -ETIMEDOUT set in tcp2.c:net_tcp_connect().

UDP

1. On the PC side spawn a netcat server in UDP mode

# nc -u -l 2001:db8::2 4242

2. On the Nitrogen side try to send a message to the server

uart:~$ net udp send 2001:db8::2 4242 "hello dear friends"
Message sent
[03:39:32.701,965] <dbg> net_tcp.net_tcp_unref: (shell_uart): context: 0x200041ac, conn: (nil)

3. The message arrives on the PC side

# nc -u -l 2001:db8::2 4242
hello dear friends

Statistics

I built Zephyr with CONFIG_NET_STATISTICS=y to get shell access to the interface statistics. By issuing net stats multiple times I had the following observations:

• during experiments when the TCP connection is initiated from the PC, there are no incoming or dropped packets. The counters do not increase.
• during experiments when the TCP connection is initiated from Nitrogen using Zephyr shell, Zephyr sees incoming packets and drops them and the connrst counter increases.

Packets sniffing

I hooked up with Wireshark to the bt0 interface and captured everything I describe in this post. I'm including the zipped pcap file if you would like to inspect it yourselves. Here are my observations from the capture session:

• UDP and ICMPv6 traffic works fine, neighbor solicitaion and advertisement packets are sent by both hosts with no issues.
• when TCP traffic is initiated from the PC, the first SYN packet sent from the PC does not get a response from Zephyr, therefore the PC keeps retransmiting it. This is the case where interface rx/drop counters on Zephyr do not increase.
• when TCP traffic is initiated from Zephyr, a SYN packet is received by the PC, then the PC sends a corresponding SYN,ACK packet. The SYN,ACK packet is then retransmitted and it is apparently never properly received by Zephyr. But this is the case where interface rx/drop counters on Zephyr do increase.

MQTT experiment

I also did a sniffing session with MQTT sample app with similar results, but I could also observe Zephyr sending FIN packets when it gave up connecting to a MQTT broker running on the PC. The connection was not possible from the same reason, i.e. SYN,ACK from the PC was never properly received by Zephyr. After some time Zephyr sent FIN, the PC responded with FIN,ACK and then went into rentransmission.

I will be grateful for any ideas how to proceed with debugging this issue.

Regards,
Wojciech

nitrogen-tcp-issue.zip

[jukkar]

Thanks for a great analysis, really helpful.
Did the TCP work for you in the past, if yes, have you tried to bisect the issue?
I checked the pcap file, it looked just fine. I try to get some time to investigate this later this week.

[jukkar]

You can also enable debugging for IPv6 and network interface
CONFIG_NET_IPV6_LOG_LEVEL_DBG=y
CONFIG_NET_IF_LOG_LEVEL_DBG=y
also you need to increase the amount of strdup buffers
CONFIG_LOG_STRDUP_BUF_COUNT, put here some large value (default is 8 if BT is enabled) if you have enough memory, something like 64 or similar should be enough if you have many debugging options enabled.

[huawei-wojciech-zmuda]

Hey @jukkar, thanks for taking a look.

I'm barely starting learning Zephyr. I got some BLE experience recently and I'm now trying to add IP-over-BLE experience to finally get MQTT working on top of it. I've never tried to get it running before, therefore I haven't tried bisect, as I don't know if there was a working revision in the past.

I added debug options you recommended. I could get CONFIG_LOG_STRDUP_BUF_COUNT as high as 40 reaching 99.26% of SRAM used.

With IF and IPV6 debugs enabled I indeed see logs on things like ICMP. When I try to initiate TCP connection (be it netcat or echo-client), there is literally no debug output except of some random neighbor solicitation/advertisement that accidentally come in the same time. I think this is a consistent and expected behavior, since, as I mentioned in my original post, there are no drops or even rx packets visible in net stats.

However, this is what happens when I try to do net tcp connect <ip> <port> from Zephyr to a netcat server:

uart:~$ net tcp connect 2001:db8::2 4242
Connecting from [2001:db8::1]:0 to [2001:db8::2]:4242
[00:05:49.401,000] <dbg> net_ipv6.check_route: (shell_uart): No default route to 2001:db8::2
[00:05:49.401,062] <dbg> net_ipv6.net_ipv6_prepare_for_send: (shell_uart): Neighbor lookup 0x20000788 (0) iface (nil)/-1 addr 2001:db8::2 state stale
[00:05:49.401,123] <dbg> net_ipv6.net_ipv6_prepare_for_send: (shell_uart): Neighbor 0x20000788 addr 38:00:25:4D:1A:38
[00:05:49.401,123] <dbg> net_ipv6.ipv6_nbr_set_state: (shell_uart): nbr 0x20000788 stale -> delay
[00:05:49.401,184] <dbg> net_if.net_if_tx: (tx_q[0]): Processing (pkt 0x2000bc34, prio 1) network packet iface 0x2000118c/1
[00:05:49.463,623] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1
[00:05:50.453,704] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1
[00:05:52.523,620] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1
--- 1 messages dropped ---
[00:05:54.401,275] <dbg> net_ipv6.ipv6_nd_reachable_timeout: (sysworkq): nbr 0x20000788 probe count 1
[00:05:54.401,458] <dbg> net_ipv6.net_ipv6_send_ns: (sysworkq): Sent Neighbor Solicitation from 2001:db8::1 to ff02::1:ff00:2, target 2001:db8::2 iface 0x2000118c/1
[00:05:54.401,519] <dbg> net_if.net_if_tx: (tx_q[0]): Processing (pkt 0x2000bd24, prio 1) network packet iface 0x2000118c/1
[00:05:54.459,045] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 72 received from 2001:db8::2 to 2001:db8::1
[00:05:54.459,167] <dbg> net_ipv6.handle_na_input: (rx_q[0]): Received Neighbor Advertisement from 2001:db8::2 to 2001:db8::1, target 2001:db8::2 iface 0x2000118c/1
[00:05:54.459,228] <dbg> net_ipv6.handle_na_neighbor: (rx_q[0]): Neighbor lookup 0x20000788 iface 0x2000118c/1 addr 2001:db8::2
[00:05:54.459,259] <dbg> net_ipv6.ipv6_nbr_set_state: (rx_q[0]): nbr 0x20000788 probe -> reachable
[00:05:54.459,320] <dbg> net_ipv6.net_ipv6_nbr_set_reachable_timer: (rx_q[0]): Starting reachable timer nbr 0x20000788 data 0x2000079c time 30335 ms
[00:05:54.593,475] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 72 received from fe80::3800:25ff:fe4d:1a38 to 2001:db8::1
[00:05:54.593,627] <dbg> net_ipv6.handle_ns_input: (rx_q[0]): Received Neighbor Solicitation from fe80::3800:25ff:fe4d:1a38 to 2001:db8::1, target 2001:db8::1 iface 0x2000118c/1
[00:05:54.593,719] <dbg> net_ipv6.net_ipv6_nbr_add: (rx_q[0]): [0] nbr 0x20000734 state 0 router 0 IPv6 fe80::3800:25ff:fe4d:1a38 ll 38:00:25:4D:1A:38 iface 0x2000118c/1
[00:05:54.593,933] <dbg> net_ipv6.net_ipv6_send_na: (rx_q[0]): Sent Neighbor Advertisement from 2001:db8::1 to fe80::3800:25ff:fe4d:1a38, target 2001:db8::1 iface 0x2000118c/1
[00:05:54.593,994] <dbg> net_ipv6.check_route: (rx_q[0]): No default route to fe80::3800:25ff:fe4d:1a38
[00:05:54.594,024] <dbg> net_ipv6.net_ipv6_prepare_for_send: (rx_q[0]): Neighbor lookup 0x20000734 (0) iface (nil)/-1 addr fe80::3800:25ff:fe4d:1a38 state static
[00:05:54.594,055] <dbg> net_ipv6.net_ipv6_prepare_for_send: (rx_q[0]): Neighbor 0x20000734 addr 38:00:25:4D:1A:38
[00:05:54.594,146] <dbg> net_if.net_if_tx: (tx_q[0]): Processing (pkt 0x2000bd24, prio 1) network packet iface 0x2000118c/1
[00:05:56.618,499] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1
[00:06:04.943,359] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1
[00:06:21.098,144] <dbg> net_ipv6.net_ipv6_input: (rx_q[0]): IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1
[00:06:24.794,677] <dbg> net_ipv6.ipv6_nd_reachable_timeout: (sysworkq): nbr 0x20000788 moving 2001:db8::2 state to STALE (2)

The three IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1 lines are SYN,ACK packets (one original, 2 retransmissions) from my PC. Then there's neighbor solicitation/advertisement exchange with both unicast and link-local addresses (and they seem to match). Finally another 3 retransmitted SYN,ACK packets come in again.

The No default route lines seem suspicious a little but I don't think it should matter. The routing table is indeed empty

uart:~$ net route

IPv6 routes for interface 0x2000118c (Bluetooth)
================================================

but a quick glance at the source code shows the packet should be sent anyway. And I guess they are sent, since I'm observing packets going out of Nitrogen and reaching my PC. The whole fuss is about the IPv6 packet len 64 received from 2001:db8::2 to 2001:db8::1 packets that come in, are received and then dropped with no apparent reason.

Please see a pcap file matching exactly the debug lines above.
nitrogen-tcp-ipv6debug.pcapng.gz

Let me also mention that I'm building Zephyr from the top of the master branch 65ac2f6d1b cmake: remove TOOLCHAIN_INCLUDES. I added that information to the original post.

Cheers!

[jukkar]

I found the issue. This was nothing to do with IPSP, you just managed to be the first person to report this when using IPSP.
The issue was that the net-shell tcp connect command did not had any timeout in the connect. This meant that the connection was teared down before the peer was able to finish it 🤦
Anyway, I tested it with IPSP and the TCP connection is established just fine after the #33251 fix.

[huawei-wojciech-zmuda]

Hey @jukkar, that fix is helpful, but I can't say it closes the issue. I tested it and can observe the following:

• it is now possible to connect from Zephyr to netcat server on my PC
• it is now possible to send a message using such connection from Zephyr to my PC
• it is not possible to connect from my PC to the listening Zephyr (and I can see it is in fact listening in net conn)
• it is not possible to send a message from my PC to Zephyr even if it was Zephyr who initiated the connection
• the echo-client test application still cannot be used

I sniffed the interface and can see the same, i.e. retrnasmission of SYN and PSH,ACK packets from my PC to Zephyr. SYN,ACK now passes to Zephyr when my PC responds for an incoming connection.

So it solved a half of the problem. Is there anything I can take a look myself to help to narrow the issue down?

[jukkar]

Thanks for the info. I did not try all the combinations, I will retry this now.

[jukkar]

I can see similar behavior, TCP connections from PC to Zephyr just disappear. I see the packet being sent in wireshark, but btmon does not show those packets. This also means that zephyr does not receive them. So it looks like the packets are dropped in Linux side.