"kernel log_level" shell command should not crash on invalid module name

[jcowgill]

Describe the bug
Zephyr crashes when you run the command "kernel log_level" with a garbage log source.

I originally saw this on an ARM board I'm working on, but I can also reproduce this with QEMU as well.

To Reproduce

$ west build -p always -b qemu_x86_64 samples/subsys/shell/shell_module
...
$ west build -t run
-- west build: running target run
[3/4] To exit from QEMU enter: 'CTRL+a, x'[QEMU] CPU: qemu64,+x2apic
qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.x2apic [bit 21]
qemu-system-x86_64: warning: TCG doesn't support requested feature: CPUID.01H:ECX.x2apic [bit 21]
SeaBIOS (version zephyr-v1.0.0-0-g31d4e0e-dirty-20200714_234759-fv-az50-zephyr)
Booting from ROM..

uart:~$ kernel log_level garbage 4
Unable to find log source: garbage
[[00:000:0:00:05.0159.0,190,00[[00:000:0:00:05.0159.0,190,00000] <err> <err>0os: <err> <err>os: Linear address not presentoin page tablesess not presentPage fault at address 
4D466e0 (error code 0x0)[000:05.190,000] <e0)[00
os: Access violation: supervisor thread not allowed to read
[00::00:05.190,000] <err> os: PDPTE: not present
[00:00:05.190,000] <err> os: RAX: 0x00000000ffffffc7 RBX: 0x0000000000000000 RCX: 0x0000000000000003 RDX: 0x0000000000000000
[00:00:05.190,000] <err> os: RSI: 0x0000000000000000 RD34 0x0000000000000001 RBP: 0x000D000000133ad0 RSP: 0x0000000000133a90
4D0:05.190,000] <err> os:  R8: 0x0000000000000070  R9: 0x0000000000000000 R10: 0x00000000001337d8 R11: 0x0000000000000002
[00:00:05.190,000] <err> os: R12: 0x00000000ffffffff R13: 0x0000000000000004 R14: 0x0000000000000000 R15: 0x0000000000000001
[00:00:05.190,000] <err> os: RSP: 0x0000000000133a90 RFLAGS: 0x0000000000000246 CS: 0x0018 CR3: 0x000000000014d000
[00:00:05.190,000] <err> os: RIP: 0x0000000000102f65
[00:00:05.190,000] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:00:05.190,000] <err> os: Current thread: 0x1196e0 (shell_uart)
[00:00:05.200,000] <err> os: Halting system

Expected behavior
It should just print an error and not crash.

Impact
Nothing for me really. I just fumbled the command and was surprised it crashed!

Logs and console output
It seems to crash in set_runtime_filter with source_id == UINT_MAX.

(gdb) bt
#0  0x0000000000102f65 in set_runtime_filter (domain_id=0 '\000', level=0, source_id=4294967295, backend_id=<optimized out>) at .../zephyr/subsys/logging/log_mgmt.c:408
#1  filter_set (id=<optimized out>, domain_id=0, source_id=<optimized out>, level=0) at .../zephyr/subsys/logging/log_mgmt.c:471
#2  0x0000000000102f15 in filter_set (id=<optimized out>, level=4, source_id=<optimized out>, domain_id=0) at .../zephyr/subsys/logging/log_mgmt.c:460
#3  filter_set (id=<optimized out>, domain_id=0, source_id=<optimized out>, level=4) at .../zephyr/subsys/logging/log_mgmt.c:438
#4  0x00000000001045f3 in log_filter_set (backend=0x0, domain_id=0, level=<optimized out>, source_id=-1) at .../zephyr/build/zephyr/include/generated/zephyr/syscalls/log_ctrl.h:105
#5  cmd_kernel_log_level_set (sh=0x113398 <shell_uart>, argc=<optimized out>, argv=0x133c40 <shell_uart_stack+2592>) at .../zephyr/subsys/shell/modules/kernel_service/log-level.c:39
#6  0x0000000000106024 in exec_cmd (help_entry=0x133bf8 <shell_uart_stack+2520>, argv=0x133c40 <shell_uart_stack+2592>, argc=<optimized out>, sh=0x113398 <shell_uart>) at .../zephyr/subsys/shell/shell.c:561
#7  execute (sh=sh@entry=0x113398 <shell_uart>) at .../zephyr/subsys/shell/shell.c:806
#8  0x00000000001067b1 in state_collect (sh=0x113398 <shell_uart>) at .../zephyr/subsys/shell/shell.c:1014
#9  shell_process (sh=sh@entry=0x113398 <shell_uart>) at .../zephyr/subsys/shell/shell.c:1505
#10 0x00000000001057d5 in shell_signal_handle (sh=sh@entry=0x113398 <shell_uart>, sig_idx=sig_idx@entry=SHELL_SIGNAL_RXRDY, handler=handler@entry=0x1065f1 <shell_process>) at .../zephyr/subsys/shell/shell.c:1307
#11 0x0000000000106c49 in shell_thread (arg_log_backend=0x1, arg_log_level=0x4, shell_handle=0x113398 <shell_uart>) at .../zephyr/subsys/shell/shell.c:1363
#12 shell_thread (shell_handle=shell_handle@entry=0x113398 <shell_uart>, arg_log_backend=arg_log_backend@entry=0x1, arg_log_level=arg_log_level@entry=0x4) at .../zephyr/subsys/shell/shell.c:1325
#13 0x0000000000101920 in z_thread_entry (entry=0x106b57 <shell_thread>, p1=0x113398 <shell_uart>, p2=0x1, p3=0x4) at .../zephyr/lib/os/thread_entry.c:48
#14 0x0000000000000000 in ?? ()

Environment (please complete the following information):

• OS: Linux
• Toolchain: Zephyr
• Commit SHA or Version used: 5faf471

[github-actions]

Hi @jcowgill! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

[kartben]

I've confirmed the bug, not sure if it's an issue with log_source_id_get() or something else, I didn't investigate further.

[nordic-krch]

I was not aware that this command exists. It is a duplication of a command present in logging command set (CONFIG_LOG_CMDS=y).

zephyr/subsys/logging/log_cmds.c

Line 241 in 74bbbdc

static int cmd_log_self_enable(const struct shell *sh,

Command in log enable works much better because allows auto-completion of logging names. It would be good to deprecate somehow this command. For now, I've fixed the bug.