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.

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

Logging: Using asserts with LOG in high pri ISR context blocks output #30418

Closed
koffes opened this issue Dec 3, 2020 · 3 comments
Closed

Logging: Using asserts with LOG in high pri ISR context blocks output #30418

koffes opened this issue Dec 3, 2020 · 3 comments
Assignees
Labels
area: Logging bug The issue is a bug, or the PR is fixing a bug priority: medium Medium impact/importance bug

Comments

@koffes
Copy link
Collaborator

koffes commented Dec 3, 2020

Describe the bug
When using log_panic() in a high pri ISR context, this call hangs in https://github.com/zephyrproject-rtos/zephyr/blob/master/drivers/serial/uart_nrfx_uarte.c#L1131

To Reproduce

  1. On a nRF5340:
  2. flash https://github.com/zephyrproject-rtos/zephyr/tree/master/samples/bluetooth/peripheral_hr to the APP core
  3. In https://github.com/zephyrproject-rtos/zephyr/blob/master/samples/bluetooth/hci_rpmsg/prj.conf I have added
CONFIG_LOG_BACKEND_UART=y
CONFIG_LOG_DEFAULT_LEVEL=2

although that is not strictly relevant
4. https://github.com/zephyrproject-rtos/zephyr/blob/master/subsys/bluetooth/controller/ll_sw/nordic/lll/lll_conn.c#L37

#include <logging/log.h>
#include <logging/log_ctrl.h>
  1. In https://github.com/zephyrproject-rtos/zephyr/blob/master/subsys/bluetooth/controller/ll_sw/nordic/lll/lll_conn.c#L317 add log_panic();
  2. Compile and flash to the NET core.

Step 5 is of course artificial. However, it is meant to simulate that an ASSERT is triggered here, which is then transferred to the user-defined error handler. In this handler, we wish to print some relevant information using LOG_ERR, call log_panic() to flush and then enter an infinite loop.

Expected behavior
This is a chicken-and-egg situation. We are trying to get UART output whilst calling log_panic() in a high priority ISR (>UART).
This likely causes the https://github.com/zephyrproject-rtos/zephyr/blob/master/drivers/serial/uart_nrfx_uarte.c#L1133 flag to never become ready.

It may be challenging, but there should be some call to terminate the calling ISR and transfer execution to the logger thread in fault situations.

Impact
The impact is rather severe in that all ASSERTS/calls to error handler originating from high-pri ISRs cannot print anything. The user is left in the blind as to what has happened on console.

Additional context

Related to #30353

@koffes koffes added the bug The issue is a bug, or the PR is fixing a bug label Dec 3, 2020
@koffes koffes changed the title Using asserts with LOG in high pri ISR context blocks output Logging: Using asserts with LOG in high pri ISR context blocks output Dec 3, 2020
@nashif nashif added the priority: medium Medium impact/importance bug label Dec 15, 2020
@nordic-krch
Copy link
Contributor

@koffes can you try to reproduce it again? There were some fixes in uarte driver to allow running poll out from any context (event interrupting other poll_out) #28961. I've added LL_ASSERT(false) to the line you've suggested and modified bt_ctlr_assert_handle by adding k_panic() and it outputs more or less what's expected:

[00:00:13.017,181] <err> hci_rpmsg: Controller assert in: WEST_TOPDIR/zephyr/subsys/bluetooth/controller/ll_sw/nordic/lll/lll_conn.c at 3os: r3/a4:  0x210051a4 r12/ip:  0x00000001 r14/lr:  0x0101982f
[00:00:13.017,211] <err> os:  xpsr:  0x61000018
[00:00:13.017,R FATAL ERROR 4: Kernel panic on CPU 0
[00:00:13.017,242] <err> os: Fault during interrupt handling 

@koffes
Copy link
Collaborator Author

koffes commented Jan 28, 2021

@nordic-krch I have retested on de73db9, and I can confirm that the issue is resolved. Closing this ticket.

@koffes koffes closed this as completed Jan 28, 2021
@koffes
Copy link
Collaborator Author

koffes commented Jan 28, 2021

@nordic-krch I don't get the chronology. The issue you referred to was merged in October, this ticket opened in December. There must be something else that changed after December which resolved this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: Logging bug The issue is a bug, or the PR is fixing a bug priority: medium Medium impact/importance bug
Projects
None yet
Development

No branches or pull requests

4 participants