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

null function pointer called when using shell logger backend under heavy load #45463

Closed
MattCampbellST opened this issue May 7, 2022 · 0 comments · Fixed by #45464
Closed
Assignees
Labels
area: Logging bug The issue is a bug, or the PR is fixing a bug priority: medium Medium impact/importance bug

Comments

@MattCampbellST
Copy link
Contributor

Describe the bug
Using the shell logger back end and under certain heavly load situations can result in calling a null function pointer call in mpsc_pbuf. The shell logger back end sets the notify_drop callback to null when configuring it's mpsc buffer, but the mpsc code doesn't do a null check.

This was exposed in my application when I turned on mcumgr shell interface. This enables the dummy shell backend which seems to expose the problem. I'm not 100% sure why, but I my guess is it has to do with timing of the dummy backend being different (faster) than a real backend and causes the mpsc to overflow and drop.

To Reproduce
This doesn't reproduce in all situations and seems to depend on timing and task scheduling to hit the mpsc overflow. I was unable to reproduce it on the native_posix target, but did get it to happen with a minimal example on a nRF52840 DK.

example prj.conf:

CONFIG_SHELL=y
CONFIG_LOG=y
CONFIG_LOG2_MODE_DEFERRED=y
CONFIG_SHELL_LOG_BACKEND=y
CONFIG_SHELL_BACKEND_DUMMY=y
CONFIG_LOG_BUFFER_SIZE=4096
CONFIG_USE_SEGGER_RTT=y
CONFIG_SHELL_BACKEND_SERIAL=n

example main,c

#include <zephyr.h>
#include <logging/log.h>
LOG_MODULE_REGISTER(main);

void main(void)
{
	printk("Hello World! %s\n", CONFIG_BOARD);

	for (int i=0; i<1000; i++) {
		LOG_INF("This is a big old log message that takes of some space and I am out of things to say.");
	}
}

Expected behavior
Not to crash.

Impact
This seems to only show up under specific circumstances, but when it does the impact is high as it will crash the system.

Logs and console output

...
[00:00:00.391,876] <inf> main: This is a big old log message that takes of some space and I am out of things to say.
[00:00:00.391,876] <inf> main: This is a big old log message that takes of some space and I am out of things to say.
[00:00:00.391,906] <inf> main: This is a big old log message that takes of some space and I am out of things to say.
[00:00:00.732,696] <err> os: ***** USAGE FAULT *****
[00:00:00.732,696] <err> os:   Illegal use of the EPSR
[00:00:00.732,727] <err> os: r0/a1:  0x20001b98  r1/a2:  0x20001350  r2/a3:  0x80000000
[00:00:00.732,727] <err> os: r3/a4:  0x00000000 r12/ip:  0x00000000 r14/lr:  0x000084650m
[00:00:00.732,757] <err> os:  xpsr:  0x20000000
[00:00:00.732,757] <err> os: Faulting instruction address (r15/pc): 0x00000000
[00:00:00.732,788] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:00:00.732,788] <err> os: Current thread: 0x200011e0 (logging)
[00:00:07.468,505] <err> os: Halting system

The PC is at zero as expected when calling a null function pointer, and the LR is in the mpsc code where it is making the call to the notify_drop function pointer.

Environment (please complete the following information):

  • OS: Ubuntu Linux
  • Toolchain Zephyr SDK,
  • Commit SHA or Version used: tip of main (253cec5c95), but appears to be an issue since the shell log backend was introduced.

Additional context
N/A

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

Successfully merging a pull request may close this issue.

4 participants