Re: UART/TTY console deadlock

[Andy Shevchenko <andy.shevchenko@gmail.com>]

+Cc: Tony and console people

On Mon, Jun 22, 2020 at 8:32 PM Raul Rangel <rrangel@google.com> wrote:
>
> We are trying an S3 suspend stress test and occasionally while
> entering S3 we get a console deadlock. Is this a known issue? I'm not
> really sure why a probe would be happening while suspending.
>
> The kernel command line is `console=ttyS0` and kernel 5.4.39.
>
> Here is the log:
>
> [  278.885831] leds mmc0::: calling led_resume+0x0/0x1c @ 3909,
> parent: 0000:02:00.0
> [  278.885835] leds mmc0::: led_resume+0x0/0x1c returned 0 after 0 usecs
> [  278.890230]  secondary_startup_64+0xa4/0xb0
> [  278.890236] handlers:
> [  279.752138] [<00000000b8e5d375>] i8042_interrupt
> [  279.756915] Disabling IRQ #1
> [  279.759801]
> [  279.759802] ======================================================
> [  279.759803] WARNING: possible circular locking dependency detected
> [  279.759803] 5.4.39 #55 Not tainted
> [  279.759804] ------------------------------------------------------
> [  279.759804] swapper/0/0 is trying to acquire lock:
> [  279.759805] ffffffffab65b6c0 (console_owner){-...}, at:
> console_lock_spinning_enable+0x31/0x57
> [  279.759806]
> [  279.759807] but task is already holding lock:
> [  279.759807] ffff88810a8e34c0 (&irq_desc_lock_class){-.-.}, at:
> __report_bad_irq+0x5b/0xba
> [  279.759809]
> [  279.759809] which lock already depends on the new lock.
> [  279.759810]
> [  279.759810]
> [  279.759811] the existing dependency chain (in reverse order) is:
> [  279.759811]
> [  279.759811] -> #2 (&irq_desc_lock_class){-.-.}:
> [  279.759813]        _raw_spin_lock_irqsave+0x61/0x8d
> [  279.759813]        __irq_get_desc_lock+0x65/0x89
> [  279.759814]        __disable_irq_nosync+0x3b/0x93
> [  279.759814]        serial8250_do_startup+0x451/0x75c
> [  279.759815]        uart_startup+0x1b4/0x2ff
> [  279.759815]        uart_port_activate+0x73/0xa0
> [  279.759815]        tty_port_open+0xae/0x10a
> [  279.759816]        uart_open+0x1b/0x26
> [  279.759816]        tty_open+0x24d/0x3a0
> [  279.759817]        chrdev_open+0xd5/0x1cc
> [  279.759817]        do_dentry_open+0x299/0x3c8
> [  279.759817]        path_openat+0x434/0x1100
> [  279.759818]        do_filp_open+0x9b/0x10a
> [  279.759818]        do_sys_open+0x15f/0x3d7
> [  279.759819]        kernel_init_freeable+0x157/0x1dd
> [  279.759819]        kernel_init+0xe/0x105
> [  279.759819]        ret_from_fork+0x27/0x50
> [  279.759820]
> [  279.759820] -> #1 (&port_lock_key){-.-.}:
> [  279.759822]        _raw_spin_lock_irqsave+0x61/0x8d
> [  279.759822]        serial8250_console_write+0xa7/0x2a0
> [  279.759823]        console_unlock+0x3b7/0x528
> [  279.759823]        vprintk_emit+0x111/0x17f
> [  279.759823]        printk+0x59/0x73
> [  279.759824]        register_console+0x336/0x3a4
> [  279.759824]        uart_add_one_port+0x51b/0x5be
> [  279.759825]        serial8250_register_8250_port+0x454/0x55e
> [  279.759825]        dw8250_probe+0x4dc/0x5b9
> [  279.759825]        platform_drv_probe+0x67/0x8b
> [  279.759826]        really_probe+0x14a/0x422
> [  279.759826]        driver_probe_device+0x66/0x130
> [  279.759827]        device_driver_attach+0x42/0x5b
> [  279.759827]        __driver_attach+0xca/0x139
> [  279.759827]        bus_for_each_dev+0x97/0xc9
> [  279.759828]        bus_add_driver+0x12b/0x228
> [  279.759828]        driver_register+0x64/0xed
> [  279.759829]        do_one_initcall+0x20c/0x4a6
> [  279.759829]        do_initcall_level+0xb5/0xc5
> [  279.759829]        do_basic_setup+0x4c/0x58
> [  279.759830]        kernel_init_freeable+0x13f/0x1dd
> [  279.759830]        kernel_init+0xe/0x105
> [  279.759831]        ret_from_fork+0x27/0x50
> [  279.759831]
> [  279.759831] -> #0 (console_owner){-...}:
> [  279.759833]        __lock_acquire+0x118d/0x2714
> [  279.759833]        lock_acquire+0x203/0x258
> [  279.759834]        console_lock_spinning_enable+0x51/0x57
> [  279.759834]        console_unlock+0x25d/0x528
> [  279.759834]        vprintk_emit+0x111/0x17f
> [  279.759835]        printk+0x59/0x73
> [  279.759835]        __report_bad_irq+0xa3/0xba
> [  279.759836]        note_interrupt+0x19a/0x1d6
> [  279.759836]        handle_irq_event_percpu+0x57/0x79
> [  279.759836]        handle_irq_event+0x36/0x55
> [  279.759837]        handle_fasteoi_irq+0xc2/0x18a
> [  279.759837]        do_IRQ+0xb3/0x157
> [  279.759838]        ret_from_intr+0x0/0x1d
> [  279.759838]        cpuidle_enter_state+0x12f/0x1fd
> [  279.759838]        cpuidle_enter+0x2e/0x3d
> [  279.759839]        do_idle+0x1ce/0x2ce
> [  279.759839]        cpu_startup_entry+0x1d/0x1f
> [  279.759840]        start_kernel+0x406/0x46a
> [  279.759840]        secondary_startup_64+0xa4/0xb0
> [  279.759840]
> [  279.759841] other info that might help us debug this:
> [  279.759841]
> [  279.759841] Chain exists of:
> [  279.759842]   console_owner --> &port_lock_key --> &irq_desc_lock_class
> [  279.759844]
> [  279.759844]  Possible unsafe locking scenario:
> [  279.759845]
> [  279.759845]        CPU0                    CPU1
> [  279.759845]        ----                    ----
> [  279.759846]   lock(&irq_desc_lock_class);
> [  279.759847]                                lock(&port_lock_key);
> [  279.759848]                                lock(&irq_desc_lock_class);
> [  279.759849]   lock(console_owner);
> [  279.759850]
> [  279.759850]  *** DEADLOCK ***
> [  279.759850]
> [  279.759851] 2 locks held by swapper/0/0:
> [  279.759851]  #0: ffff88810a8e34c0 (&irq_desc_lock_class){-.-.}, at:
> __report_bad_irq+0x5b/0xba
> [  279.759853]  #1: ffffffffab65b5c0 (console_lock){+.+.}, at:
> console_trylock_spinning+0x20/0x181
> [  279.759855]
> [  279.759855] stack backtrace:
> [  279.759856] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.4.39 #55
> [  279.759856] Hardware name: XXXXXX
> [  279.759857] Call Trace:
> [  279.759857]  <IRQ>
> [  279.759857]  dump_stack+0xbf/0x133
> [  279.759858]  ? print_circular_bug+0xd6/0xe9
> [  279.759858]  check_noncircular+0x1b9/0x1c3
> [  279.759858]  __lock_acquire+0x118d/0x2714
> [  279.759859]  lock_acquire+0x203/0x258
> [  279.759859]  ? console_lock_spinning_enable+0x31/0x57
> [  279.759860]  console_lock_spinning_enable+0x51/0x57
> [  279.759860]  ? console_lock_spinning_enable+0x31/0x57
> [  279.759861]  console_unlock+0x25d/0x528
> [  279.759861]  ? console_trylock+0x18/0x4e
> [  279.759861]  vprintk_emit+0x111/0x17f
> [  279.759862]  ? lock_acquire+0x203/0x258
> [  279.759862]  printk+0x59/0x73
> [  279.759862]  __report_bad_irq+0xa3/0xba
> [  279.759863]  note_interrupt+0x19a/0x1d6
> [  279.759863]  handle_irq_event_percpu+0x57/0x79
> [  279.759864]  handle_irq_event+0x36/0x55
> [  279.759864]  handle_fasteoi_irq+0xc2/0x18a
> [  279.759864]  do_IRQ+0xb3/0x157
> [  279.759865]  common_interrupt+0xf/0xf
> [  279.759865]  </IRQ>
> [  279.759866] RIP: 0010:cpuidle_enter_state+0x12f/0x1fd
> [  279.759867] Code: aa aa aa aa aa aa aa 48 89 45 c8 9c 8f 45 c8 0f
> ba 65 c8 09 0f 82 cc 00 00 00 31 ff e8 57 25 76 ff e8 36 bb 7b ff fb
> 45 85 ff <78> 47 44 89 f8 48 6b d0 68 49 8b 4c 16 48 4c 2b 65 b8 4c 89
> 63 18
> [  279.759867] RSP: 0018:ffffffffab607e20 EFLAGS: 00000202 ORIG_RAX:
> ffffffffffffffda
> [  279.759869] RAX: 86733df5ce911a00 RBX: ffff888104709000 RCX: ffffffffa9bb229b
> [  279.759870] RDX: 0000000000000000 RSI: 0000000000000006 RDI: ffffffffab62d780
> [  279.759870] RBP: ffffffffab607e68 R08: dffffc0000000000 R09: fffffbfff56eb96f
> [  279.759871] R10: fffffbfff56eb96f R11: ffffffffa9f4f800 R12: 00000040eb0f7ad6
> [  279.759871] R13: 0000000000000000 R14: ffffffffab6caf68 R15: 0000000000000001
> [  279.759871]  ? flatten_lpi_states+0x190/0x1d7
> [  279.759872]  ? trace_irq_enable_rcuidle+0x22/0xee
> [  279.759872]  cpuidle_enter+0x2e/0x3d
> [  279.759872]  do_idle+0x1ce/0x2ce
> [  279.759873]  cpu_startup_entry+0x1d/0x1f
> [  279.759873]  start_kernel+0x406/0x46a
> [  279.759873]  secondary_startup_64+0xa4/0xb0
> [  279.927956] i2c_designware AMD0010:00: controller timed out
> [  280.388120] elan_i2c i2c-ELAN0000:00: reading cmd (0x0307) fail.
> [  280.394413] elan_i2c i2c-ELAN0000:00: failed to read current power
> state: -110
> [  280.542626] elan_i2c i2c-ELAN0000:00: elan_resume+0x0/0x5f returned
> 0 after 1607813 usecs
>
>
> Thanks,
> Raul



-- 
With Best Regards,
Andy Shevchenko