WARNING: possible circular locking dependency detected port->lock deadlock between console_unlock() and serial8250_handle_irq()

Issue

• I installed kernel-debug and found the below UBSAN warning message logged on boot.

[  122.041850] ======================================================
[  122.041850] WARNING: possible circular locking dependency detected
[  122.041851] 4.18.0-305.7.1.el8_4.x86_64+debug #1 Not tainted
[  122.041855] ------------------------------------------------------
[  122.041858] swapper/6/0 is trying to acquire lock:
[  122.041858] ffffffffb82382e0 (console_owner){-...}-{0:0}, at: console_unlock+0x409/0x9b0

[  122.041861] but task is already holding lock:
[  122.041861] ffffffffbb581ff8 (&port_lock_key){-.-.}-{2:2}, at: serial8250_handle_irq.part.15+0x1e/0x1d0

[  122.041864] which lock already depends on the new lock.


[  122.041865] the existing dependency chain (in reverse order) is:

[  122.041866] -> #1 (&port_lock_key){-.-.}-{2:2}:
[  122.041868]        lock_acquire+0x1b1/0x8a0
[  122.041868]        _raw_spin_lock_irqsave+0x4c/0x90
[  122.041869]        serial8250_console_write+0x611/0x760
[  122.041869]        console_unlock+0x602/0x9b0
[  122.041870]        register_console+0x54c/0xab0
[  122.041870]        univ8250_console_init+0x24/0x27
[  122.041871]        console_init+0x2ef/0x45a
[  122.041871]        start_kernel+0x4e6/0x7ba
[  122.041872]        secondary_startup_64_no_verify+0xc2/0xcb

[  122.041873] -> #0 (console_owner){-...}-{0:0}:
[  122.041874]        check_prevs_add+0x3ce/0x1650
[  122.041875]        __lock_acquire+0x223c/0x2da0
[  122.041875]        lock_acquire+0x1b1/0x8a0
[  122.041876]        console_unlock+0x46b/0x9b0
[  122.041876]        vprintk_emit+0x158/0x490
[  122.041877]        printk+0x9f/0xc5
[  122.041877]        __handle_sysrq.cold.11+0x4d3/0x579
[  122.041878]        serial8250_read_char+0x2bd/0x6b0
[  122.041878]        serial8250_rx_chars+0x25/0xb0
[  122.041879]        serial8250_handle_irq.part.15+0x142/0x1d0
[  122.041879]        serial8250_default_handle_irq+0x82/0xe0
[  122.041880]        serial8250_interrupt+0xdd/0x1b0
[  122.041880]        __handle_irq_event_percpu+0xfa/0x820
[  122.041881]        handle_irq_event_percpu+0x73/0x150
[  122.041881]        handle_irq_event+0xa1/0x12d
[  122.041882]        handle_edge_irq+0x20a/0xa40
[  122.041882]        handle_irq+0x3e/0x50
[  122.041883]        do_IRQ+0x9a/0x200
[  122.041883]        ret_from_intr+0x0/0x22
[  122.041884]        cpuidle_enter_state+0x256/0x1160
[  122.041884]        cpuidle_enter+0x50/0xa0
[  122.041884]        do_idle+0x3ef/0x4a0
[  122.041885]        cpu_startup_entry+0xcb/0xd4
[  122.041885]        start_secondary+0x48b/0x600
[  122.041886]        secondary_startup_64_no_verify+0xc2/0xcb

[  122.041887] other info that might help us debug this:

[  122.041888]  Possible unsafe locking scenario:

[  122.041889]        CPU0                    CPU1
[  122.041889]        ----                    ----
[  122.041890]   lock(&port_lock_key);
[  122.041891]                                lock(console_owner);
[  122.041892]                                lock(&port_lock_key);
[  122.041893]   lock(console_owner);

[  122.041895]  *** DEADLOCK ***

[  122.041895] 4 locks held by swapper/6/0:
[  122.041896]  #0: ffff897b126adc30 (&i->lock){-.-.}-{2:2}, at: serial8250_interrupt+0x30/0x1b0
[  122.041898]  #1: ffffffffbb581ff8 (&port_lock_key){-.-.}-{2:2}, at: serial8250_handle_irq.part.15+0x1e/0x1d0
[  122.041900]  #2: ffffffffb8273960 (rcu_read_lock){....}-{1:2}, at: __handle_sysrq+0x4d/0x100
[  122.041902]  #3: ffffffffb82387e0 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0x14b/0x490

[  122.041905] stack backtrace:
[  122.041906] CPU: 6 PID: 0 Comm: swapper/6 Kdump: loaded Not tainted 4.18.0-305.7.1.el8_4.x86_64+debug #1
[  122.041907] Hardware name: Oracle Corporation ORACLE SERVER X5-4/ASSY,MB WITH TRAY, BIOS 36080200 12/10/2020
[  122.041907] Call Trace:
[  122.041908]  <IRQ>
[  122.041908]  dump_stack+0x8e/0xd0
[  122.041908]  check_noncircular+0x30e/0x3c0
[  122.041909]  ? print_circular_bug+0x300/0x300
[  122.041909]  ? do_profile_hits.isra.4.cold.9+0x2d/0x2d
[  122.041910]  check_prevs_add+0x3ce/0x1650
[  122.041910]  ? check_irq_usage+0xa50/0xa50
[  122.041911]  ? check_irq_usage+0xa50/0xa50
[  122.041911]  ? sched_clock+0x5/0x10
[  122.041912]  ? sched_clock_cpu+0x18/0x1e0
[  122.041912]  __lock_acquire+0x223c/0x2da0
[  122.041913]  ? rcu_read_lock_bh_held+0xc0/0xc0
[  122.041913]  lock_acquire+0x1b1/0x8a0
[  122.041914]  ? console_unlock+0x409/0x9b0
[  122.041914]  ? rcu_read_unlock+0x50/0x50
[  122.041914]  ? msg_print_ext_body+0x3a0/0x3a0
[  122.041915]  ? lock_contended+0xd40/0xd40
[  122.041915]  ? rcu_read_unlock+0x50/0x50
[  122.041916]  console_unlock+0x46b/0x9b0
[  122.041916]  ? console_unlock+0x409/0x9b0
[  122.041917]  vprintk_emit+0x158/0x490
[  122.041917]  ? lock_acquire+0x1b1/0x8a0
[  122.041918]  printk+0x9f/0xc5
[  122.041918]  ? kmsg_dump_rewind_nolock+0xd9/0xd9
[  122.041919]  ? rcu_read_lock_sched_held+0xaf/0xe0
[  122.041919]  ? serial8250_handle_irq.part.15+0x1e/0x1d0
[  122.041920]  ? find_held_lock+0x3a/0x1c0
[  122.041920]  ? do_raw_spin_unlock+0x54/0x230
[  122.041920]  __handle_sysrq.cold.11+0x4d3/0x579
[  122.041921]  serial8250_read_char+0x2bd/0x6b0
[  122.041921]  serial8250_rx_chars+0x25/0xb0
[  122.041922]  serial8250_handle_irq.part.15+0x142/0x1d0
[  122.041922]  serial8250_default_handle_irq+0x82/0xe0
[  122.041923]  serial8250_interrupt+0xdd/0x1b0
[  122.041923]  ? serial8250_backup_timeout+0x450/0x450
[  122.041924]  __handle_irq_event_percpu+0xfa/0x820
[  122.041924]  ? handle_edge_irq+0x2d/0xa40
[  122.041925]  handle_irq_event_percpu+0x73/0x150
[  122.041925]  ? __handle_irq_event_percpu+0x820/0x820
[  122.041926]  ? lock_contended+0xd40/0xd40
[  122.041926]  ? do_raw_spin_unlock+0x54/0x230
[  122.041927]  handle_irq_event+0xa1/0x12d
[  122.041927]  handle_edge_irq+0x20a/0xa40
[  122.041928]  handle_irq+0x3e/0x50
[  122.041928]  do_IRQ+0x9a/0x200
[  122.041928]  common_interrupt+0xf/0xf
[  122.041929]  </IRQ>
[  122.041929] RIP: 0010:cpuidle_enter_state+0x256/0x1160
[  122.041930] Code: 80 7c 24 10 00 74 17 9c 58 0f 1f 44 00 00 f6 c4 02 0f 85 91 09 00 00 31 ff e8 16 9d cc fe e8 d1 b4 e2 fe fb 66 0f 1f 44 00 00 <45> 85 f6 0f 88 85 04 00 00 49 63 ee 48 83 fd 09 0f 87 54 0c 00 00
[  122.041931] RSP: 0018:ffff8881010efcb0 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffde
[  122.041932] RAX: 0000000000000000 RBX: ffffe76fa9202d68 RCX: 0000000000000000
[  122.041933] RDX: 1ffff1102021b853 RSI: 0000000000000000 RDI: ffff8881010dc298
[  122.041933] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001
[  122.041934] R10: ffff88ee27bf4f9b R11: ffffed1dc4f7e9f3 R12: 0000000000000006
[  122.041934] R13: ffffffffb881b7e0 R14: 0000000000000004 R15: ffffffffb881b9e8
[  122.041935]  cpuidle_enter+0x50/0xa0
[  122.041935]  do_idle+0x3ef/0x4a0
[  122.041936]  ? arch_cpu_idle_exit+0x40/0x40
[  122.041937]  cpu_startup_entry+0xcb/0xd4
[  122.041937]  ? cpu_in_idle+0x20/0x20
[  122.041938]  ? lockdep_hardirqs_on_prepare+0x294/0x3e0
[  122.041938]  ? trace_hardirqs_on+0x20/0x195
[  122.041939]  start_secondary+0x48b/0x600
[  122.041939]  ? set_cpu_sibling_map+0x37f0/0x37f0
[  122.041940]  ? set_bringup_idt_handler.constprop.0+0x88/0x90
[  122.041941]  secondary_startup_64_no_verify+0xc2/0xcb
[  124.193110] sysrq: SysRq : HELP : loglevel(0-9) reboot(b) crash(c) show-all-locks(d) terminate-all-tasks(e) memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k) show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n) poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s) show-task-states(t) unmount(u) force-fb(V) show-blocked-tasks(w) dump-ftrace-buffer(z)