Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tests/bluetooth/hci_prop_evt fails with code coverage enabled in qemu_x86 #18207

Closed
keylime-unicorn opened this issue Aug 12, 2019 · 5 comments
Closed

tests/bluetooth/hci_prop_evt fails with code coverage enabled in qemu_x86 #18207

keylime-unicorn opened this issue Aug 12, 2019 · 5 comments
Assignees
@jhedberg
Labels
area: Bluetooth area: Code Coverage bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug

Comments

@keylime-unicorn
Copy link

This references #17324

This test fails with code coverage enabled in qemu_x86 with a double fault (see below)

SeaBIOS (version rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org)
Booting from ROM..Optimal CONFIG_X86_MMU_PAGE_POOL_PAGES 9
***** Booting Zephyr OS build v2.0.0-rc1-9-ga8b208aff77f *****
Running test suite test_hci_prop_evt
===================================================================
starting test - test_hci_prop_evt_entry
FATAL: Double Fault
FATAL: eax: 0x00000012, ebx: 0x00536040, ecx: 0x00000001, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052b018, esp: 0x0052b000
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x001032a7
FATAL:      0x001288df (0x52de9c)
FATAL:      0x0012ba18 (0x52de9c)
FATAL:      0x0012ab09 (0x52de9c)
FATAL:      0x00129961 (0x52de9c)
FATAL:      0x0012af0e (0x52de9c)
FATAL:      0x0012ce83 (0x52de9c)
FATAL:      0x0012cfd3 (0x52de9c)
FATAL:      0x00119a37 (0x52de9c)
FATAL: >>> ZEPHYR FATAL ERROR 0: CPU exception
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.000,000] <dbg> bt_hci_core.bt_hci_driver_register: Registered test
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000001, ebx: 0x0052b000, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f57c, esp: 0x0052f578
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00128dca (0x138734)
FATAL:      0x0012aad9 (0x52f5c8)
FATAL:      0x00129961 (0x51d180)
FATAL:      0x0012af0e (0x51d180)
FATAL:      0x00125cf1 (0x51d180)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x5369b8)
FATAL:      0x0010c6d8 (0x5369b8)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.010,000] <dbg> bt_hci_core.bt_hci_cmd_create: opcode 0x1003 param_len 0
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000002, ebx: 0x0052f578, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f34c, esp: 0x0052f348
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f39c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x536998)
FATAL:      0x0010c6d8 (0x536998)
FATAL:      0x0010c9a9 (0x536998)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
FATAL: Double Fault
FATAL: eax: 0x0010e3cd, ebx: 0x00000001, ecx: 0x000003e8, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f05c, esp: 0x0052f000
FATAL: eflags: 0x00000016 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x0010e3cd
FATAL:      0x0010e54c (0x10e3cd)
FATAL:      0x0010e850 (0x139aac)
FATAL:      0x0010fe10 (0x139aac)
FATAL:      0x001100bf (0x139aac)
FATAL:      0x001104c3 (0x139aac)
FATAL:      0x00110795 (0x139aac)
FATAL:      0x0010aa9c (0x1340ac)
FATAL:      0x0010c67f (0x1340ac)
FATAL: >>> ZEPHYR FATAL ERROR 0: CPU exception
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.020,000] <dbg> bt_hci_core.bt_hci_cmd_send_sync: buf 0x00536040 opcode 0x1003 len 3
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000003, ebx: 0x0052f000, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f5dc, esp: 0x0052f5d8
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f62c)
FATAL:      0x0010d4d7 (0x51d180)
FATAL:      0x0010d6c9 (0x536938)
FATAL:      0x0010d896 (0x536958)
FATAL:      0x0010c6d8 (0x536958)
FATAL:      0x0010c9a9 (0x536958)
FATAL:      0x0010c46f (0x0)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.030,000] <dbg> bt_hci_core.hci_tx_thread: Started
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000004, ebx: 0x0052f5d8, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f3ac, esp: 0x0052f3a8
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f3fc)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x536918)
FATAL:      0x0010c6d8 (0x536918)
FATAL:      0x0010c9a9 (0x536918)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
FATAL: Double Fault
FATAL: eax: 0x00000168, ebx: 0x005413ac, ecx: 0x00000001, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f00c, esp: 0x0052eff0
FATAL: eflags: 0x00000006 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x0010e595
FATAL:      0x0010e63e (0x1106ca)
FATAL:      0x0010e4e1 (0x139aac)
FATAL:      0x0010566c (0x5b)
FATAL:      0x0010e54c (0x10e3cd)
FATAL:      0x0010e850 (0x139aac)
FATAL:      0x0010fe10 (0x139aac)
FATAL:      0x001100bf (0x139aac)
FATAL:      0x001104c3 (0x139aac)
FATAL: >>> ZEPHYR FATAL ERROR 0: CPU exception
FATAL: Current thread: 0x0051d320 (BT TX)
[[00:00:00.030,000] <dbg> bt_hci_core.process_events: count 1
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000005, ebx: 0x0052eff0, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f60c, esp: 0x0052f608
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f65c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x5368d8)
FATAL:      0x0010c6d8 (0x5368d8)
FATAL:      0x0010c9a9 (0x5368d8)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.030,000] <dbg> bt_hci_core.process_events: ev->state 4
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000006, ebx: 0x0052f608, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f3dc, esp: 0x0052f3d8
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f42c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x5368b8)
FATAL:      0x0010c6d8 (0x5368b8)
FATAL:      0x0010c9a9 (0x5368b8)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
FATAL: Double Fault
FATAL: eax: 0x005413ac, ebx: 0x005413ac, ecx: 0x00000001, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f00c, esp: 0x0052eff4
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x001106ef
FATAL:      0x0010e5a3 (0x525fdb)
FATAL:      0x0010e63e (0x1106ca)
FATAL:      0x0010e4e1 (0x139aac)
FATAL:      0x0010566c (0x5b)
FATAL:      0x0010e54c (0x10e3cd)
FATAL:      0x0010e850 (0x139aac)
FATAL:      0x0010fe10 (0x139aac)
FATAL:      0x001100bf (0x139aac)
FATAL: >>> ZEPHYR FATAL ERROR 0: CPU exception
FATAL: Current thread: 0x0051d320 (BT TX)
[[00:00:00.030,000] <dbg> bt_hci_core.send_cmd: calling sem_take_wait
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000007, ebx: 0x0052eff4, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f60c, esp: 0x0052f608
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f65c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x536878)
FATAL:      0x0010c6d8 (0x536878)
FATAL:      0x0010c9a9 (0x536878)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.030,000] <dbg> bt_hci_core.send_cmd: Sending command 0x1003 (buf 0x00536040) to driver
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000008, ebx: 0x0052f608, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f3dc, esp: 0x0052f3d8
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f42c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x536858)
FATAL:      0x0010c6d8 (0x536858)
FATAL:      0x0010c9a9 (0x536858)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
FATAL: Double Fault
FATAL: eax: 0x005413ac, ebx: 0x005413ac, ecx: 0x00000001, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f00c, esp: 0x0052eff4
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x001106ef
FATAL:      0x0010e5a3 (0x525fdb)
FATAL:      0x0010e63e (0x1106ca)
FATAL:      0x0010e4e1 (0x139aac)
FATAL:      0x0010566c (0x5b)
FATAL:      0x0010e54c (0x10e3cd)
FATAL:      0x0010e850 (0x139aac)
FATAL:      0x0010fe10 (0x139aac)
FATAL:      0x001100bf (0x139aac)
FATAL: >>> ZEPHYR FATAL ERROR 0: CPU exception
FATAL: Current thread: 0x0051d320 (BT TX)
[[00:00:00.030,000] <dbg> bt_hci_core.bt_buf_get_cmd_complete: sent_cmd 0x00536040
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x00000009, ebx: 0x0052eff4, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f60c, esp: 0x0052f608
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f65c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x5367f8)
FATAL:      0x0010c6d8 (0x5367f8)
FATAL:      0x0010c9a9 (0x5367f8)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
[00:00:00.040,000] <dbg> bt_hci_core.hci_cmd_complete: opcode 0x1003
ASSERTION FAIL [z_spin_lock_valid(l)] @ ZEPHYR_BASE/include/spinlock.h:78
	Recursive spinlock
FATAL: eax: 0x0000000a, ebx: 0x0052f608, ecx: 0x0000000a, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f3dc, esp: 0x0052f3d8
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x00106af5
FATAL:      0x00125299 (0x138048)
FATAL:      0x00125cc6 (0x52f42c)
FATAL:      0x0010d6f9 (0x51d180)
FATAL:      0x0010d896 (0x5367d8)
FATAL:      0x0010c6d8 (0x5367d8)
FATAL:      0x0010c9a9 (0x5367d8)
FATAL:      0x0010c46f (0x0)
FATAL:      0x0012401a (0x136a3a)
FATAL: >>> ZEPHYR FATAL ERROR 4: Kernel panic
FATAL: Current thread: 0x0051d320 (BT TX)
FATAL: Double Fault
FATAL: eax: 0x005413ac, ebx: 0x005413ac, ecx: 0x00000001, edx: 0x00000000
FATAL: esi: 0x00000000, edi: 0x00105165, ebp: 0x0052f00c, esp: 0x0052eff4
FATAL: eflags: 0x00000046 cs: 0x0008 cr3: 0x0051d200
FATAL: call trace:
FATAL: eip: 0x001106ef
FATAL:      0x0010e5a3 (0x525fdb)
FATAL:      0x0010e63e (0x1106ca)
FATAL:      0x0010e4e1 (0x139aac)
FATAL:      0x0010566c (0x5b)
FATAL:      0x0010e54c (0x10e3cd)
FATAL:      0x0010e850 (0x139aac)
FATAL:      0x0010fe10 (0x139aac)
FATAL:      0x001100bf (0x139aac)
FATAL: >>> ZEPHYR FATAL ERROR 0: CPU exception
FATAL: Current thread: 0x0051d320 (BT TX)
[FATAL: Halting system

This can be reproduced by running
./scripts/sanitycheck --coverage -p qemu_x86 -T tests/bluetooth/

$ ./scripts/sanitycheck --coverage -p qemu_x86 -T tests/bluetooth/
JOBS: 4
Cleaning output directory /home/camelot/zephyrproject/zephyr/sanity-out
Building testcase defconfigs...
Filtering test cases...
16 tests selected, 10425 tests discarded due to filters
total complete:    0/  16   0%  failed:    0

qemu_x86                  tests/bluetooth/hci_prop_evt/bluetooth.hci_prop_evt FAILED: handler_crash
	see: sanity-out/qemu_x86/tests/bluetooth/hci_prop_evt/bluetooth.hci_prop_evt/handler.log

total complete:   16/  16  100%  failed:    1
Generating coverage files...
HTML report generated: /home/camelot/zephyrproject/zephyr/sanity-out/coverage/index.html
15 of 16 tests passed with 0 warnings in 91 seconds

After running with gdb, it seems to be failing on line 339 of subsys/bluetooth/host/hci_core.c
@keylime-unicorn keylime-unicorn added the bug The issue is a bug, or the PR is fixing a bug label Aug 12, 2019
@andrewboie
Copy link
Contributor

This looks like it might be some kind of stack overflow.
Can you reproduce with mps2_an385 with --coverage?

@ioannisg ioannisg added the priority: low Low impact/importance bug label Aug 13, 2019
@keylime-unicorn
Copy link
Author

This looks like it might be some kind of stack overflow.
Can you reproduce with mps2_an385 with --coverage?

This test does not fail with coverage enabled on mps2_an385

@carlescufi
Copy link
Member

@joerchan can you please take a look?

@joerchan
Copy link
Contributor

Bluetooth TX stack was overflowing.
Adding these options would fix the problem:

CONFIG_BT_HCI_TX_STACK_SIZE_WITH_PROMPT=y
CONFIG_BT_HCI_TX_STACK_SIZE=1500

However, it appears enabling QEMU_X86 with code coverage has a severe stack size increase, almost twice the amount of stack use for all stacks. Enabling code coverage would break many optimized stack sizes in the system.
Would code coverage with native_posix be better perhaps? The test passes without modifications then.

QEMU Code Coverage = y

I: Stack analyze:
I:  BT RX               : unused 216 usage 808 / 1024 (78 %)
I:  BT TX               : unused 796 usage 1252 / 2048 (61 %)
I:  stack_size_analyzer : unused 124 usage 900 / 1024 (87 %)
I:  sysworkq            : unused 3304 usage 792 / 4096 (19 %)
I:  idle                : unused 2020 usage 28 / 2048 (1 %)

QEMU Code Coverage = n

I: Stack analyze:
I:  BT RX               : unused 608 usage 416 / 1024 (40 %)
I:  BT TX               : unused 1708 usage 340 / 2048 (16 %)
I:  stack_size_analyzer : unused 652 usage 372 / 1024 (36 %)
I:  sysworkq            : unused 628 usage 396 / 1024 (38 %)
I:  idle                : unused 228 usage 28 / 256 (10 %

Also shameless advertising to have a look at #23258 which provided me with these numbers.

@joerchan
Copy link
Contributor

Closing this issue without fixing the build configuration.

Running these tests with qemu_x86 will require increasing stack sizes for multiple tests.
Running code coverage with native_posix is recommended instead. This test passes for native_posix with code coverage enabled.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jhedberg jhedberg

Labels
area: Bluetooth area: Code Coverage bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
7 participants
@jhedberg @joerchan @ioannisg @andrewboie @carlescufi @keylime-unicorn @aescolar