invalid locking in shell

[pdunaj]

Describe the bug
When we put our board to sleep we stop shell. When board is woken up we start shell again.
I have a code that log messages in the loop from one thread. This happens even if we go to sleep.
I just noticed that when board is woken up it deadlocks. After connecting a debugger following backtrace is visible.

Remote debugging using :2331
0x00037ca4 in k_spin_unlock (key=..., l=0x2000452c <lock>) at /home/pdunaj/work/ncs/zephyr/include/spinlock.h:92
92              __ASSERT(z_spin_unlock_valid(l), "Not my spinlock!");
(gdb) bt
#0  0x00037ca4 in k_spin_unlock (key=..., l=0x2000452c <lock>) at /home/pdunaj/work/ncs/zephyr/include/spinlock.h:92
#1  _impl_k_poll (events=<optimized out>, num_events=num_events@entry=1, timeout=timeout@entry=-1) at /home/pdunaj/work/ncs/zephyr/kernel/poll.c:218
#2  0x00012bf6 in k_poll (timeout=-1, num_events=1, events=<optimized out>) at zephyr/include/generated/syscalls/kernel.h:133
#3  shell_pend_on_txdone (shell=<optimized out>) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_ops.c:361
#4  shell_write (shell=0x3d79c <shell_rtt>, data=0x20001d58 <shell_rtt_out_buffer>, length=12) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_ops.c:390
#5  0x000123b8 in shell_fprintf_buffer_flush (sh_fprintf=0x3d7cc <shell_rtt_fprintf>) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_fprintf.c:56
#6  shell_fprintf_fmt (sh_fprintf=0x3d7cc <shell_rtt_fprintf>, fmt=fmt@entry=0x39224 "%s", args=..., args@entry=...) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_fprintf.c:49
#7  0x00012d44 in shell_internal_vfprintf (shell=shell@entry=0x3d79c <shell_rtt>, color=color@entry=SHELL_VT100_COLOR_GREEN, fmt=fmt@entry=0x39224 "%s", args=args@entry=...)
    at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_ops.c:459
#8  0x00012d82 in shell_internal_fprintf (shell=shell@entry=0x3d79c <shell_rtt>, color=color@entry=SHELL_VT100_COLOR_GREEN, fmt=0x39224 "%s")
    at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_ops.c:480
#9  0x000130e4 in print_prompt (shell=0x3d79c <shell_rtt>) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_ops.c:339
#10 shell_print_prompt_and_cmd (shell=shell@entry=0x3d79c <shell_rtt>) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell_ops.c:349
#11 0x00011162 in shell_log_process (shell=0x3d79c <shell_rtt>) at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell.c:1055
#12 0x000111ac in shell_signal_handle (shell=shell@entry=0x3d79c <shell_rtt>, sig_idx=sig_idx@entry=SHELL_SIGNAL_LOG_MSG, handler=handler@entry=0x1112d <shell_log_process>)
    at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell.c:1148
#13 0x000120ea in shell_thread (shell_handle=0x3d79c <shell_rtt>, arg_log_backend=<optimized out>, arg_log_level=0x4 <crc32_ieee_update+4>)
    at /home/pdunaj/work/ncs/zephyr/subsys/shell/shell.c:1210
#14 0x00008616 in _thread_entry (entry=0x12065 <shell_thread>, p1=0x3d79c <shell_rtt>, p2=<optimized out>, p3=<optimized out>) at /home/pdunaj/work/ncs/zephyr/lib/os/thread_entry.c:29
#15 0xaaaaaaaa in ?? ()

To Reproduce
Steps to reproduce the behavior:
See description

Expected behavior
No crashes, no deadlocks.

Impact
Showstopper for projects with always enabled shell. Otherwise annoyance.

Screenshots or console output
N/A

Environment (please complete the following information):
ncs zephyr 745326266d9c32ba3aa67d5af1f727059d9a88e3 (from d9876be upstream)

Additional context
Add any other context about the problem here.
N/A

[andyross]

What's the reproduction strategy for this bug? It sounds like this is a custom power save state or something and not just the idle thread? If you get a chance, can you cherry pick the two patches in #13800 and reproduce it? Those will give more information about the location of the locks in question, and catch some problems (trying to swap/pend/sleep with a lock yeld) earlier.

[andyross]

Worth putting in a link here to #13591 , which is a very similar symptom. There it seems like it's plausibly due to a bug in the validation layer, though the rig is complicated enough that I'm not able to reproduce it directly myself. I'm hoping this one is easier.

[nashif]

@pdunaj Is this still an issue? Can you reply to comments above?

[nashif]

@carlescufi fyi

[pdunaj]

Hi @nashif , to be honest I am not sure if it is still replicating. I am not sure what happened in the bug - I suspected that maybe this was caused by the "simulated system off in debug mode".
I may try to check but this was a very low priority issue for us as we have no actively used configuration with shell enabled. I will try to add a comment within a week or two.

[pdunaj]

Hi @nordic-krch , do you know if shell handles switch to the deep sleep well?

[sslupsky]

Yes, I think this is still an issue. I was having a similar problem disabling the shell when I go to sleep. I submitted a PR #24404 that may address this issue. This likely needs a bit of discussion.

[pabigot]

#27342 was merged in lieu of #24404. I'm marking this stale; if it's still a problem please comment.

[nashif]

we should close this, this has been stale for a while.