zephyr: Bluetooth: IPSP Sample Crash on nrf52840dk_nrf52840

Hi All, I am new to the zephyr OS and currently using it for an IoT project. I am trying to get the IPSP example working so that i can start from there. The example keeps crashing on connect (echo "connect DC:F2:F1:E7:96:E9 2" > /sys/kernel/debug/bluetooth/6lowpan_control) and I don’t know why. Can anyone help? I am working with the latest branch.

Git log on branch

commit 80f87b94806bef4f893b18f1dc8cea070382dd6b (HEAD -> main, origin/main, origin/HEAD) Author: Mariusz Skamra mariusz.skamra@codecoup.pl Date: Thu Jan 12 10:51:19 2023 +0100

To Reproduce

west build -p always -b nrf52840dk_nrf52840 samples/bluetooth/ipsp -DCONF_FILE=prj_dbg.conf
west flash

on Raspi Pi 3B Using this USB BLE dongle: https://www.2direct.de/media/pdf/fb/99/d0/bt0015IJ77DTdbLHOls.pdf

modprobe bluetooth_6lowpan
 echo 1 > /sys/kernel/debug/bluetooth/6lowpan_enable
 echo "connect  <nRF MAC> <type>" > /sys/kernel/debug/bluetooth/6lowpan_control

Logs and console output

[00:00:00.251,953] <dbg> net_core: net_init: (0x20002598): Priority 90
[00:00:00.252,105] <dbg> net_route: net_route_init: (0x20002598): Allocated 8 routing entries (576 bytes)
[00:00:00.252,136] <dbg> net_route: net_route_init: (0x20002598): Allocated 8 nexthop entries (224 bytes)
[00:00:00.252,136] <dbg> net_core: l3_init: (0x20002598): Network L3 init done
[00:00:00.252,258] <dbg> net_if: net_if_init: (0x20002598): 
[00:00:00.252,288] <dbg> net_if: init_iface: (0x20002598): On iface 0x20001354
[00:00:00.252,410] <dbg> net_if: update_operational_state: (0x20002598): iface 0x20001354, oper state DOWN admin DOWN carrier ON dormant ON
[00:00:00.252,471] <dbg> net_if: net_if_ipv6_calc_reachable_time: (0x20002598): min_reachable:15000 max_reachable:45000
[00:00:00.255,096] <dbg> net_if: net_if_post_init: (0x20002598): 
[00:00:00.255,096] <dbg> net_if: net_if_up: (0x20002598): iface 0x20001354
[00:00:00.255,249] <dbg> net_if: update_operational_state: (0x20002598): iface 0x20001354, oper state DORMANT admin UP carrier ON dormant ON
*** Booting Zephyr OS build zephyr-v3.2.0-3560-g80f87b94806b ***
[00:00:00.256,988] <inf> bt_hci_core: hci_vs_init: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.257,019] <inf> bt_hci_core: hci_vs_init: HW Variant: nRF52x (0x0002)
[00:00:00.257,080] <inf> bt_hci_core: hci_vs_init: Firmware: Standard Bluetooth controller (0x00) Version 3.2 Build 99
[00:00:00.258,026] <inf> bt_hci_core: bt_dev_show_info: Identity: DC:F2:F1:E7:96:E9 (random)
[00:00:00.258,056] <inf> bt_hci_core: bt_dev_show_info: HCI: version 5.3 (0x0c) revision 0x0000, manufacturer 0x05f1
[00:00:00.258,087] <inf> bt_hci_core: bt_dev_show_info: LMP: version 5.3 (0x0c) subver 0xffff
[00:00:00.258,636] <inf> net_config: net_config_init_by_iface: Initializing network
[00:00:00.258,666] <inf> net_config: check_interface: Waiting interface 1 (0x20001354) to be up...
[00:00:30.259,307] <err> net_config: net_config_init_by_iface: Timeout while waiting network interface
[00:00:30.259,338] <err> net_config: net_config_init_app: Network initialization failed (-115)
[00:00:30.259,368] <inf> ipsp: init_app: Run IPSP sample
[00:00:30.259,490] <dbg> net_if: net_if_ipv6_addr_add: (0x20002598): [0] interface 0x20001354 address 2001:db8::1 type MANUAL added
[00:00:30.259,582] <dbg> net_if: net_if_ipv6_maddr_add: (0x20002598): [0] interface 0x20001354 address ff02::1 added
[00:00:30.259,796] <dbg> net_if: net_if_tx: (0x20002598): Processing (pkt 0x2000db1c, prio 1) network packet iface 0x20001354/1
[00:00:30.259,796] <dbg> net_6lo: compress_da_mcast: (0x20002598): M_1 dst is mcast
[00:00:30.259,826] <dbg> net_6lo: compress_da_mcast: (0x20002598): DAM_11 dst maddr 8 bit compressible
[00:00:30.259,826] <dbg> net_6lo: compress_IPHC_header: (0x20002598): SAM_00, SAC_1 unspecified src address
[00:00:30.259,857] <dbg> net_6lo: compress_hoplimit: (0x20002598): HLIM compressed (1)
[00:00:30.259,857] <dbg> net_6lo: compress_tfl: (0x20002598): Traffic class and Flow label elided
[00:00:30.259,887] <err> net_bt: net_bt_send: Unable to send packet: -128
[00:00:30.260,009] <dbg> net_if: net_if_ipv6_maddr_add: (0x20002598): [1] interface 0x20001354 address ff02::1:ff00:1 added
[00:00:30.260,192] <dbg> net_if: net_if_tx: (0x20002598): Processing (pkt 0x2000db1c, prio 1) network packet iface 0x20001354/1
[00:00:30.260,223] <dbg> net_6lo: compress_da_mcast: (0x20002598): M_1 dst is mcast
[00:00:30.260,223] <dbg> net_6lo: compress_da_mcast: (0x20002598): DAM_11 dst maddr 8 bit compressible
[00:00:30.260,253] <dbg> net_6lo: compress_IPHC_header: (0x20002598): SAM_00, SAC_1 unspecified src address
[00:00:30.260,253] <dbg> net_6lo: compress_hoplimit: (0x20002598): HLIM compressed (1)
[00:00:30.260,284] <dbg> net_6lo: compress_tfl: (0x20002598): Traffic class and Flow label elided
[00:00:30.260,314] <err> net_bt: net_bt_send: Unable to send packet: -128
[00:00:30.260,375] <dbg> net_if: net_if_ipv6_start_dad: (0x20002598): Interface 0x20001354 is down, starting DAD for 2001:db8::1 later.
[00:00:30.260,803] <inf> ipsp: listen: Starting to wait
[00:01:08.527,404] <dbg> net_if: net_if_tx: (0x20001f18): Processing (pkt 0x2000dad8, prio 1) network packet iface 0x20001354/1
--- 16 messages dropped ---
[00:01:08.527,435] <dbg> net_6lo: compress_da_mcast: (0x20001f18): M_1 dst is mcast
[00:01:08.527,465] <dbg> net_6lo: compress_da_mcast: (0x20001f18): DAM_01 6 bytes: 2nd byte + last five bytes
[00:01:08.527,465] <dbg> net_6lo: compress_IPHC_header: (0x20001f18): SAM_00, SAC_1 unspecified src address
[00:01:08.527,496] <dbg> net_6lo: compress_hoplimit: (0x20001f18): HLIM compressed (255)
[00:01:08.527,526] <dbg> net_6lo: compress_tfl: (0x20001f18): Traffic class and Flow label elided
[00:01:08.527,679] <dbg> net_if: net_if_ipv6_start_dad: (0x20001f18): Interface 0x20001354 ll addr DC:F2:F1:E7:96:E9 tentative IPv6 addr 2001:db8::1
[00:01:08.527,862] <dbg> net_ipv6: nbr_new: (0x20001f18): nbr 0x20000900 iface 0x20001354/1 state 0 IPv6 2001:db8::1
[00:01:08.528,015] <dbg> net_ipv6: net_ipv6_send_ns: (0x20001f18): Sent Neighbor Solicitation from :: to ff02::1:ff00:1, target 2001:db8::1 iface 0x20001354/1
[00:01:08.528,076] <dbg> net_if: net_if_tx: (0x20001f18): Processing (pkt 0x2000dad8, prio 1) network packet iface 0x20001354/1
[00:01:08.528,076] <dbg> net_6lo: compress_da_mcast: (0x20001f18): M_1 dst is mcast
[00:01:08.528,106] <dbg> net_6lo: compress_da_mcast: (0x20001f18): DAM_01 6 bytes: 2nd byte + last five bytes
[00:01:08.528,137] <dbg> net_6lo: compress_IPHC_header: (0x20001f18): SAM_00, SAC_1 unspecified src [00:01:08.528,167] <dbg> net_6lo: compress_hoplimit: (0x20001f18): HLIM compressed (255)
[00:01:08.528,167] <dbg> net_6lo: compress_tfl: (0x20001f18): Traffic class and Flow label elided
[00:01:08.528,228] <dbg> net_if: net_if_start_rs: (0x20001f18): Starting ND/RS for iface 0x20001354
[00:01:08.528,442] <dbg> net_ipv6: net_ipv6_send_rs: (0x20001f18): Sent Router Solicitation from :: to ff02::2 iface 0x20001354/1
[00:01:08.528,503] <dbg> net_if: net_if_tx: (0x20001f18): Processing (pkt 0x2000dad8, prio 1) network packet iface 0x20001354/1
[00:01:08.528,503] <dbg> net_6lo: compress_da_mcast: (0x20001f18): M_1 dst is mcast
[00:01:08.528,533] <dbg> net_6lo: compress_da_mcast: (0x20001f18): DAM_11 dst maddr 8 bit compressible
[00:01:08.528,564] <dbg> net_6lo: compress_IPHC_header: (0x20001f18): SAM_00, SAC_1 unspecified src address
[00:01:08.528,564] <dbg> net_6lo: compress_hoplimit: (0x20001f18): HLIM compressed (255)
[00:01:08.528,594] <dbg> net_6lo: compress_tfl: (0x20001f18): Traffic class and Flow label elided
[00:01:08.627,685] <dbg> net_if: dad_timeout: (0x20002618): DAD succeeded for fe80::dcf2:f1ff:fee7:96e9
[00:01:08.627,716] <dbg> net_ipv6: nbr_free: (0x20002618): nbr 0x200008ac
[00:01:08.627,746] <dbg> net_ipv6: net_neighbor_data_remove: (0x20002618): Neighbor 0x200008ac removed
[00:01:08.628,875] <dbg> net_if: dad_timeout: (0x20002618): DAD succeeded for 2001:db8::1
[00:01:08.628,906] <dbg> net_ipv6: nbr_free: (0x20002618): nbr 0x20000900
[00:01:08.628,906] <dbg> net_ipv6: net_neighbor_data_remove: (0x20002618): Neighbor 0x20000900 removed
ASSERTION FAIL [buf] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/conn.c:873
[00:01:08.675,903] <err> os: esf_dump: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000011
[00:01:08.675,903] <err> os: esf_dump: r3/a4:  0x200014b0 r12/ip:  0x00000014 r14/lr:  0x00009d81
[00:01:08.675,933] <err> os: esf_dump:  xpsr:  0x61000000
[00:01:08.675,933] <err> os: esf_dump: Faulting instruction address (r15/pc): 0x00009d8c
[00:01:08.675,994] <err> os: z_fatal_error: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:01:08.676,025] <err> os: z_fatal_error: Current thread: 0x20001a10 (unknown)
[00:01:08.908,813] <err> os: k_sys_fatal_error_handler: Halting system

Environment:

OS: Ubuntu 20.04.1
raspi kernel: custom build with 6lowpan Linux raspberrypi 5.15.876lowpan-pi-v7+
Zephyr SDK – zephyr-sdk-0.15.2
commit 80f87b94806bef4f893b18f1dc8cea070382dd6b

About this issue

Original URL
State: closed
Created a year ago
Comments: 53 (24 by maintainers)

Commits related to this issue

try to reproduce #53871 Signed-off-by: Jonathan Rico <jonathan.rico@nordicsemi.no> — committed to jori-nordic/zephyr by jori-nordic a year ago
try to reproduce #53871 Signed-off-by: Jonathan Rico <jonathan.rico@nordicsemi.no> — committed to jori-nordic/zephyr by jori-nordic a year ago
try to reproduce #53871 Signed-off-by: Jonathan Rico <jonathan.rico@nordicsemi.no> — committed to jori-nordic/zephyr by jori-nordic a year ago

Most upvoted comments

I understand. I will try and get you a copy of a self-contained ubuntu20 that i was using for testing this.

seekaddo on Apr 21, 2023

I’m a big fan of your commit messages, made my day. And you are absolutely correct:

ASSERTION FAIL [user_data >= &l2cap_tx_meta_data_storage[0] && user_data <= &l2cap_tx_meta_data_storage[20]] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/l2cap.c:1890          
        user_data field has been corrupted                                                                                                                                    
[00:00:45.072,631] <err> os: esf_dump: r0/a1:  0x00000004  r1/a2:  0x00000762  r2/a3:  0x000000c4                                                                             
[00:00:45.072,662] <err> os: esf_dump: r3/a4:  0x20001a98 r12/ip:  0x2000e81c r14/lr:  0x00010e31                                                                             
[00:00:45.072,692] <err> os: esf_dump:  xpsr:  0x61000000                                                                                                                     
[00:00:45.072,723] <err> os: esf_dump: Faulting instruction address (r15/pc): 0x0003fda0                                                                                      
[00:00:45.072,753] <err> os: z_fatal_error: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0                                                                                   
[00:00:45.072,814] <err> os: z_fatal_error: Current thread: 0x20004db0 (sysworkq)                                                                                             
[00:00:47.362,731] <err> os: k_sys_fatal_error_handler: Halting system

bamkrs on Feb 24, 2023

okay so, barring the misconfiguration I talked about in my previous comment, this seems to be a BlueZ/linux ipsp bug:

We send 3 packets when the l2cap channel is initialized, so we exhaust the 3 credits that we had been given by the linux host. As seen from the pcap, linux clearly receives and parses them (No 34, 37 and 39).
We receive everything from the linux host and send back the credits accordingly, so the link it still active
The linux host never sends back the credits (see the zephyr logs + the pcap). We only get this message once, at channel init: l2cap_chan_tx_give_credits: chan 0x200002a0 got TX credits

Here’s the rev I used: https://github.com/jori-nordic/zephyr/commit/b01c54c3324e86b74ee91ed202267b584e8421ff Here’s the commands I ran in succession to get there: Once:

sudo btattach -B /dev/ttyACM14 -S 1000000 where ttyACM14 is the Laird BLE USB dongle
echo 1 | sudo tee /sys/kernel/debug/bluetooth/6lowpan_enable

And then for every test cycle: 4. echo "connect D7:99:F8:2D:DD:50 2" | sudo tee /sys/kernel/debug/bluetooth/6lowpan_control 5. sudo ip address add 2001:db8::2/64 dev bt0 6. ping6 2001:db8::1

ipsp.log ipsp.zip

edit: I should also mention my env:

jon@jori-pc:~/repos/zephyrproject/zephyr$ cat /etc/lsb-release 
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=22.04
DISTRIB_CODENAME=jammy
DISTRIB_DESCRIPTION="Ubuntu 22.04.1 LTS"
jon@jori-pc:~/repos/zephyrproject/zephyr$ uname -rv
5.15.0-58-generic #64-Ubuntu SMP Thu Jan 5 11:43:13 UTC 2023
jon@jori-pc:~/repos/zephyrproject/zephyr$

jori-nordic on Feb 17, 2023