linux-kernel - Re: printk() from NMI backtrace can delay a lot

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20180703152944.GQ533219@devbig577.frc2.facebook.com>
Date:   Tue, 3 Jul 2018 08:29:44 -0700
From:   Tejun Heo <tj@...nel.org>
To:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
Cc:     Tetsuo Handa <penguin-kernel@...ove.sakura.ne.jp>,
        Steven Rostedt <rostedt@...dmis.org>,
        Petr Mladek <pmladek@...e.com>,
        Peter Zijlstra <peterz@...radead.org>,
        Linus Torvalds <torvalds@...ux-foundation.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Dmitry Vyukov <dvyukov@...gle.com>,
        linux-kernel@...r.kernel.org,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>
Subject: Re: printk() from NMI backtrace can delay a lot

Hello, Sergey.

On Tue, Jul 03, 2018 at 01:30:21PM +0900, Sergey Senozhatsky wrote:
> Cc-ing Linus, Tejun, Andrew
> [I'll keep the entire lockdep report]
> 
> On (07/02/18 19:26), Tetsuo Handa wrote:
> [..]
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606834] swapper/0/0 is trying to acquire lock:
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606835] 00000000316e1432 (console_owner){-.-.}, at: console_unlock+0x1ce/0x8b0
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606840] 
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606841] but task is already holding lock:
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606842] 000000009b45dcb4 (&(&pool->lock)->rlock){-.-.}, at: show_workqueue_state+0x3b2/0x900
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606847] 
> > 2018-07-02 12:13:13 192.168.159.129:6666 [  151.606848] which lock already depends on the new lock.
...
> But anyway. So we can have [but I'm not completely sure. Maybe lockdep has
> something else on its mind] something like this:
> 
> 	CPU1					CPU0
> 
> 	#IRQ					#soft irq
> 	serial8250_handle_irq()			wq_watchdog_timer_fn()
> 	 spin_lock(&uart_port->lock)		 show_workqueue_state()
> 	  serial8250_rx_chars()			   spin_lock(&pool->lock)
> 	   tty_flip_buffer_push()		    printk()
> 	    tty_schedule_flip()			     serial8250_console_write()
> 	     queue_work()			      spin_lock(&uart_port->lock)
> 	      __queue_work()
> 	       spin_lock(&pool->lock)
> 
> We need to break the pool->lock -> uart_port->lock chain.
> 
> - use printk_deferred() to show WQs states [show_workqueue_state() is
>   a timer callback, so local IRQs are enabled]. But show_workqueue_state()
>   is also available via sysrq.
> 
> - what Alan Cox suggested: use spin_trylock() in serial8250_console_write()
>   and just discard (do not print anything on console) console->writes() that
>   can deadlock us [uart_port->lock is already locked]. This basically means
>   that sometimes there will be no output on a serial console, or there
>   will be missing line. Which kind of contradicts the purpose of print
>   out.
> 
> We are facing the risk of no output on serial consoles in both case. Thus
> there must be some other way out of this.

show_workqueue_state() is only used when something is already horribly
broken or when invoked through sysrq.  I'm not sure it's worthwhile to
make invasive changes to avoid lockdep warnings.  If anything, we
should make show_workqueue_state() avoid grabbing pool->lock (e.g. use
trylock and fallback to probe_kernel_reads if that fails).  I'm a bit
skeptical how actually useful that'd be tho.

Thanks.

-- 
tejun