Bluetooth 'central' failure on native_posix

[thomascp]

Describe the bug

When running the central sample on the v2.1-branch, after several seconds, the program will be crashed.

*** Booting Zephyr OS build zephyr-v2.1.0  ***
Bluetooth initialized
Scanning successfully started
Device found: 78:48:69:50:d6:3e (random) (RSSI -83)
Device found: 74:55:cb:8f:45:84 (random) (RSSI -71)
Device found: 54:cd:95:14:1d:67 (random) (RSSI -70)
Segmentation fault (core dumped)

To Reproduce
Steps to reproduce the behavior:

1. west build -b native_posix samples/bluetooth/central
2. sudo ./build/zephyr/zephyr.elf --bt-dev=hci0

Expected behavior
The program shouldn't crash.

Screenshots or console output

Booting Zephyr OS build zephyr-v2.1.0
Bluetooth initialized
Scanning successfully started
Device found: 78:48:69:50:d6:3e (random) (RSSI -83)
Device found: 74:55:cb:8f:45:84 (random) (RSSI -71)
Device found: 54:cd:95:14:1d:67 (random) (RSSI -70)
Segmentation fault (core dumped)

Core dump backtrace

(gdb)
#0  atomic_and (target=0x1efe2bcc, value=-4097) at ../include/sys/atomic.h:270
#1  0x0804d5ff in atomic_set_bit_to (target=<optimized out>, bit=<optimized out>, val=<optimized out>)
    at ../include/sys/atomic.h:455
#2  0x0804d7ca in hci_cmd_done (opcode=<optimized out>, status=<optimized out>, buf=0x8059c00 <net_buf_hci_cmd_pool>)
    at /home/neo/disk/bluetooth/zephyrproject/zephyr/subsys/bluetooth/host/hci_core.c:3404
#3  0x0804d890 in hci_cmd_complete (buf=0x8059c00 <net_buf_hci_cmd_pool>)
    at /home/neo/disk/bluetooth/zephyrproject/zephyr/subsys/bluetooth/host/hci_core.c:3431
#4  0x0804f012 in bt_recv_prio (buf=0x8059c00 <net_buf_hci_cmd_pool>)
    at /home/neo/disk/bluetooth/zephyrproject/zephyr/subsys/bluetooth/host/hci_core.c:4963
#5  0x0804b290 in rx_thread (p1=0x0, p2=0x0, p3=0x0)
    at /home/neo/disk/bluetooth/zephyrproject/zephyr/drivers/bluetooth/hci/userchan.c:113
#6  0x0804985f in z_thread_entry (entry=0x804b165 <rx_thread>, p1=0x0, p2=0x0, p3=0x0)
    at /home/neo/disk/bluetooth/zephyrproject/zephyr/lib/os/thread_entry.c:29
#7  0x0804b697 in posix_thread_starter (arg=0x5)
    at /home/neo/disk/bluetooth/zephyrproject/zephyr/arch/posix/core/posix_core.c:305
#8  0xf7f10295 in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
#9  0xf7e3b0ae in clone () from /lib/i386-linux-gnu/libc.so.6

(gdb) i r all
eax            0x1efcc5cc       519882188
ecx            0x1efcc5cc       519882188
edx            0xffffefff       -4097
ebx            0x8059c00        134585344
esp            0xf50fe260       0xf50fe260
ebp            0xf50fe268       0xf50fe268
esi            0x0      0
edi            0xf50fe2c4       -183508284
eip            0x804d5b5        0x804d5b5 <atomic_and+7>
eflags         0x10a06  [ PF IF OF RF ]
cs             0x23     35
ss             0x2b     43
ds             0x2b     43
es             0x2b     43
fs             0x0      0
gs             0x63     99

(gdb) disassemble atomic_and
Dump of assembler code for function atomic_and:
   0x0804d5ae <+0>:     push   %ebp
   0x0804d5af <+1>:     mov    %eax,%ecx
   0x0804d5b1 <+3>:     mov    %esp,%ebp
   0x0804d5b3 <+5>:     push   %esi
   0x0804d5b4 <+6>:     push   %ebx
=> 0x0804d5b5 <+7>:     mov    (%eax),%eax
   0x0804d5b7 <+9>:     mov    %eax,%esi
   0x0804d5b9 <+11>:    mov    %eax,%ebx
   0x0804d5bb <+13>:    and    %edx,%esi
   0x0804d5bd <+15>:    lock cmpxchg %esi,(%ecx)
   0x0804d5c1 <+19>:    jne    0x804d5b7 <atomic_and+9>
   0x0804d5c3 <+21>:    mov    %ebx,%eax
   0x0804d5c5 <+23>:    pop    %ebx
   0x0804d5c6 <+24>:    pop    %esi
   0x0804d5c7 <+25>:    pop    %ebp
   0x0804d5c8 <+26>:    ret

[jhedberg]

Looks like related to the cmd(buf)->state stuff that was recently added by @joerchan ?

[jhedberg]

@thomascp the backtraces are already very useful, however could you also try running the process through valgrind? That might give even more helpful information on what's going on.

[joerchan]

Looks like related to the cmd(buf)->state stuff that was recently added by @joerchan ?

Yeah, that was my conclusion as well. I will try to reproduce this.

[joerchan]

@thomascp I don't get the failure that you see.
Could you please enable CONFIG_ASSERT=y and see if that triggers an assertion anywhere?
Also please try valgrind as was suggested by Johan.
sudo valgrind ./build/zephyr/zephyr.exe --bt-dev=hci0 (I had to install libc6-dbg:i386)

[thomascp]

Hi,
Sorry to reply late, I am busy recently.
Which is weird, after I reboot my VirtualBox, it doesn't happen again.
Before the reboot, it happened all the time.

[joerchan]

Unable to reproduce.