Bluetooth: deadlock when canceling db_hash.work from settings commit handler

[mniestroj]

Describe the bug
There is a deadlock when cancelling db_hash.work:

	/* Stop work and generate the hash */
	(void)k_work_cancel_delayable_sync(&db_hash.work, &db_hash.sync);

from db_hash_commit. db_hash_commit is called with settings_lock mutex held and cancelling db_hash.work will never finish, as settings_save_one("bt/hash", ...) is waiting on settings_lock mutex as well and never continues.

This can be workarounded by adding some arbitrary sleep in application code.

To Reproduce
I was not successful with reproducing it with upstream code/sample. I have downstream project, which triggers this case every time, so I can test possible fixes.

Expected behavior
Deadlock case prevented.

Impact
Annoyance for now, but it could be triggered on real devices in the field and cause deadlock in boot process.

Logs and console output
main thread backtrace:

#0  arch_swap (key=0) at /project/zephyr/arch/arm/core/aarch32/swap.c:53
#1  0x0003fa7c in z_swap_irqlock (key=<optimized out>) at /project/zephyr/kernel/include/kswap.h:173
#2  z_swap (key=..., lock=0x200170f0) at /project/zephyr/kernel/include/kswap.h:173
#3  z_pend_curr (lock=lock@entry=0x200170f0, key=..., wait_q=wait_q@entry=0x20006610 <db_hash+72>, timeout=...)
    at /project/zephyr/kernel/sched.c:699
#4  0x0003f4c4 in z_impl_k_sem_take (sem=sem@entry=0x20006610 <db_hash+72>, timeout=...)
    at /project/zephyr/kernel/sem.c:159
#5  0x000539be in k_sem_take (timeout=..., sem=0x20006610 <db_hash+72>) at zephyr/include/generated/syscalls/kernel.h:769
#6  k_work_cancel_delayable_sync (dwork=dwork@entry=0x200065d8 <db_hash+16>, sync=sync@entry=0x20006608 <db_hash+64>)
    at /project/zephyr/kernel/work.c:1005
#7  0x0001552a in db_hash_commit () at /project/zephyr/subsys/bluetooth/host/gatt.c:5158
#8  0x0000b828 in settings_commit_subtree (subtree=subtree@entry=0x0 <_vector_table>)
    at /project/zephyr/subsys/settings/src/settings.c:249
#9  0x0000b5ba in settings_load_subtree (subtree=subtree@entry=0x0 <_vector_table>)
    at /project/zephyr/subsys/settings/src/settings_store.c:60
#10 0x000442da in settings_load () at /project/zephyr/subsys/settings/src/settings_store.c:39
#11 0x00002608 in bt_init (dev=<optimized out>) at /project/app/src/bt.c:209
#12 bt_init (dev=<optimized out>) at /project/app/src/bt.c:195
#13 0x0003e97c in z_sys_init_run_level (level=level@entry=3) at /project/zephyr/kernel/device.c:87
#14 0x0003ebe0 in bg_thread_main (unused1=<optimized out>, unused2=<optimized out>, unused3=<optimized out>)
    at /project/zephyr/kernel/init.c:161
#15 0x00040c5c in z_thread_entry (entry=0x3ebc9 <bg_thread_main>, p1=<optimized out>, p2=<optimized out>, p3=<optimized out>)
    at /project/zephyr/lib/os/thread_entry.c:29
#16 0x0000f004 in arch_switch_to_main_thread (main_thread=<optimized out>, 
    stack_ptr=0x20021480 <z_idle_stacks> '\252' <repeats 200 times>..., _main=0x3ebc9 <bg_thread_main>)
    at /project/zephyr/arch/arm/core/aarch32/thread.c:539

sysworkq thread backtrace:

#0  arch_swap (key=0) at /project/zephyr/arch/arm/core/aarch32/swap.c:53
#1  0x0003fa7c in z_swap_irqlock (key=<optimized out>) at /project/zephyr/kernel/include/kswap.h:173
#2  z_swap (key=..., lock=0x200170f0) at /project/zephyr/kernel/include/kswap.h:173
#3  z_pend_curr (lock=lock@entry=0x200170f0, key=..., key@entry=..., wait_q=wait_q@entry=0x20003300 <settings_lock>, timeout=...)
    at /project/zephyr/kernel/sched.c:699
#4  0x0003f2e6 in z_impl_k_mutex_lock (mutex=0x20003300 <settings_lock>, timeout=...)
    at /project/zephyr/kernel/mutex.c:164
#5  0x0000b52e in k_mutex_lock (mutex=<optimized out>, timeout=...) at zephyr/include/generated/syscalls/kernel.h:674
#6  settings_save_one (name=name@entry=0x6075a "bt/hash", value=value@entry=0x200065c8 <db_hash>, val_len=val_len@entry=16)
    at /project/zephyr/subsys/settings/src/settings_store.c:104
#7  0x00014740 in db_hash_store () at /project/zephyr/subsys/bluetooth/host/gatt.c:678
#8  0x0001544e in db_hash_gen (store=store@entry=true)
    at /project/zephyr/subsys/bluetooth/host/gatt.c:717
#9  0x000154c6 in db_hash_process (work=<optimized out>)
    at /project/zephyr/subsys/bluetooth/host/gatt.c:727
#10 0x0003f69a in work_queue_main (workq_ptr=0x20007270 <k_sys_work_q>, p2=<optimized out>, p3=<optimized out>)
    at /project/zephyr/kernel/work.c:680
#11 0x00040c5c in z_thread_entry (entry=0x3f5a1 <work_queue_main>, p1=<optimized out>, p2=<optimized out>, p3=<optimized out>)
    at /project/zephyr/lib/os/thread_entry.c:29
#12 0xaaaaaaaa in ?? ()

Environment (please complete the following information):

• OS: Linux
• Toolchain Zephyr SDK 0.12.4
• Commit SHA or Version used: 92d80d5

[joerchan]

@mniestroj Can you check if #35225 has any effect on this issue?

[pabigot]

Why is a deadlock a low-priority bug?

The problem will occur if the work queue thread takes &db_hash.work off the queue then releases the spinlock, but before it can invoke the handler is preempted by something that invokes db_hash_commit() (via `settings_commit()) from a thread context.

I don't believe the synchronous cancel from db_hash_read() (a GATT read for the hash characteristic) would deadlock, though it would sleep until the work handler regained control and completed the item.

#35225 will not fix the problem.

[pabigot]

If both settings_commit() and settings_save_one() have the sleep attribute, which I think they do, a fix could be difficult because neither has a no-sleep path that would allow simultaneous callers to avoid the deadlock.

A fix may require extending the settings API to support no-sleep failable API calls, and refactoring this module to always use the work item (or a dedicated thread) to maintain the hash, where if the update fails the work item is immediately rescheduled so that whatever holds the settings lock is given an opportunity to complete.

That would interfere with desire to be able to update the hash without sleeping, but I suspect that desire is ultimately unsatisfiable.

[carlescufi]

Switching the priority to medium as per @pabigot's assessment of the issue.

[joerchan]

@mniestroj Can you give #35403 a try?

[mniestroj]

Can you give #35403 a try?

Issue is no longer reproducible with that PR, so it helps.