From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933736AbcAYQ4h (ORCPT ); Mon, 25 Jan 2016 11:56:37 -0500 Received: from mail-pa0-f47.google.com ([209.85.220.47]:33068 "EHLO mail-pa0-f47.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S933723AbcAYQ4b (ORCPT ); Mon, 25 Jan 2016 11:56:31 -0500 Subject: Re: tty: deadlock between n_tracerouter_receivebuf and flush_to_ldisc To: Dmitry Vyukov References: <20160120130201.GA1027@worktop> <569FB10F.4080205@hurleysoftware.com> <20160121102013.GN6356@twins.programming.kicks-ass.net> <56A11A92.7030109@hurleysoftware.com> Cc: Peter Zijlstra , Jiri Slaby , One Thousand Gnomes , Greg Kroah-Hartman , LKML , J Freyensee , syzkaller , Kostya Serebryany , Alexander Potapenko , Sasha Levin , Eric Dumazet From: Peter Hurley Message-ID: <56A653BB.4010809@hurleysoftware.com> Date: Mon, 25 Jan 2016 08:56:27 -0800 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:38.0) Gecko/20100101 Thunderbird/38.5.1 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 01/22/2016 06:10 AM, Dmitry Vyukov wrote: > On Thu, Jan 21, 2016 at 6:51 PM, Peter Hurley wrote: >> On 01/21/2016 02:20 AM, Peter Zijlstra wrote: >>> On Thu, Jan 21, 2016 at 11:06:45AM +0100, Dmitry Vyukov wrote: >>>> On Wed, Jan 20, 2016 at 5:08 PM, Peter Hurley wrote: >>>>> On 01/20/2016 05:02 AM, Peter Zijlstra wrote: >>>>>> On Wed, Dec 30, 2015 at 11:44:01AM +0100, Dmitry Vyukov wrote: >>>>>>> -> #3 (&buf->lock){+.+...}: >>>>>>> [] lock_acquire+0x19f/0x3c0 kernel/locking/lockdep.c:3585 >>>>>>> [< inline >] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:112 >>>>>>> [] _raw_spin_lock_irqsave+0x50/0x70 kernel/locking/spinlock.c:159 >>>>>>> [] tty_get_pgrp+0x20/0x80 drivers/tty/tty_io.c:2502 >>>>>> >>>>>> So in any recent code that I look at this function tries to acquire >>>>>> tty->ctrl_lock, not buf->lock. Am I missing something ?! >>>>> >>>>> Yes. >>>>> >>>>> The tty locks were annotated with __lockfunc so were being elided from lockdep >>>>> stacktraces. Greg has a patch in his queue from me that removes the __lockfunc >>>>> annotation ("tty: Remove __lockfunc annotation from tty lock functions"). >>>>> >>>>> Unfortunately, I think syzkaller's post-processing stack trace isn't helping >>>>> either, giving the impression that the stack is still inside tty_get_pgrp(). >>>>> >>>>> It's not. >>>> >>>> I've got a new report on commit >>>> a200dcb34693084e56496960d855afdeaaf9578f (Jan 18). >>>> Here is unprocessed version: >>>> https://gist.githubusercontent.com/dvyukov/428a0c9bfaa867d8ce84/raw/0754db31668602ad07947f9964238b2f9cf63315/gistfile1.txt >>>> and here is processed one: >>>> https://gist.githubusercontent.com/dvyukov/42b874213de82d94c35e/raw/2bbced252035821243678de0112e2ed3a766fb5d/gistfile1.txt >>>> >>>> Peter, what exactly is wrong with the post-processed version? I would >>>> be interested in fixing the processing script. >>>> >>>> As far as I see it contains the same stacks just with line numbers and >>>> inlined frames. I am using a significantly different compilation mode >>>> (kasan + kcov + very recent gcc), so nobody except me won't be able to >>>> figure out line numbers based on offsets. >>> >>> I'm not sure anything is wrong with the post-processing. My confusion >>> (and Jiri) was that the stack trace lists >>> tty_get_pgrp()->_raw_spin_lock_irqsave() but that function acquires >>> tty->ctrl_lock, not as the report claims buf->lock. >> >> I think this is the other way around; that lockdep has graphed a circular >> dependency chain, but that something is wrong with the stack traces. >> >>> PeterH says that lockdep omits functions tagged with __lockfunc, but my >>> reading disagrees with that. >>> >>> kernel/locking/lockdep.c:save_trace() >>> save_stack_trace() >>> dump_trace(.ops = &save_stack_ops) >>> >>> which has: .address = save_stack_address >>> __save_stack_address(.nosched = false) >>> >>> So lockdep should very much include lock functions. >> >> Wild hypothesis on my part. >> >>> But this confusion is part of the original report, not because of the >>> post-processing. >> >> Yeah, agreed. The original report is very odd. > > > > > > > Peter H, I have not yet applied your patch, but got a slightly > differently looking report (n_tracesink_datadrain wasn't mentioned > before): May or may not be related. And this report suffers from the same deficiencies as the previous report which is that the saved stack trace doesn't match the lock dependency. Without understanding why the stack trace doesn't match the lock dependency, any solution is just based on conjecture. Regards, Peter Hurley > [ 1483.472724] ====================================================== > [ 1483.473033] [ INFO: possible circular locking dependency detected ] > [ 1483.473033] 4.4.0+ #275 Not tainted > [ 1483.473033] ------------------------------------------------------- > [ 1483.473033] kworker/u9:0/10808 is trying to acquire lock: > [ 1483.473033] (writelock){+.+...}, at: [] > n_tracesink_datadrain+0x24/0xc0 > [ 1483.473033] > [ 1483.473033] but task is already holding lock: > [ 1483.473033] (routelock){+.+...}, at: [] > n_tracerouter_receivebuf+0x20/0x40 > [ 1483.473033] > [ 1483.473033] which lock already depends on the new lock. > [ 1483.473033] > [ 1483.473033] > [ 1483.473033] the existing dependency chain (in reverse order) is: > [ 1483.473033] > -> #4 (routelock){+.+...}: > [ 1483.473033] [] lock_acquire+0x1dc/0x430 > [ 1483.473033] [] mutex_lock_nested+0xb1/0xa50 > [ 1483.473033] [] n_tracerouter_receivebuf+0x20/0x40 > [ 1483.473033] [] flush_to_ldisc+0x584/0x7f0 > [ 1483.473033] [] process_one_work+0x796/0x1440 > [ 1483.473033] [] worker_thread+0xdb/0xfc0 > [ 1483.473033] [] kthread+0x23f/0x2d0 > [ 1483.473033] [] ret_from_fork+0x3f/0x70 > [ 1483.473033] > -> #3 (&buf->lock){+.+...}: > [ 1483.473033] [] lock_acquire+0x1dc/0x430 > [ 1483.473033] [] _raw_spin_lock_irqsave+0x9f/0xd0 > [ 1483.473033] [] tty_get_pgrp+0x20/0x80 > [ 1483.473033] [] __isig+0x1a/0x50 > [ 1483.473033] [] isig+0xae/0x2c0 > [ 1483.473033] [] n_tty_receive_signal_char+0x22/0xf0 > [ 1483.473033] [] > n_tty_receive_char_special+0x10d2/0x2b30 > [ 1483.473033] [] > n_tty_receive_buf_common+0x19a3/0x2400 > [ 1483.473033] [] n_tty_receive_buf2+0x33/0x40 > [ 1483.473033] [] flush_to_ldisc+0x3bf/0x7f0 > [ 1483.473033] [] process_one_work+0x796/0x1440 > [ 1483.473033] [] worker_thread+0xdb/0xfc0 > [ 1483.473033] [] kthread+0x23f/0x2d0 > [ 1483.473033] [] ret_from_fork+0x3f/0x70 > [ 1483.473033] > -> #2 (&o_tty->termios_rwsem/1){++++..}: > [ 1483.473033] [] lock_acquire+0x1dc/0x430 > [ 1483.473033] [] down_read+0x47/0x60 > [ 1483.473033] [] n_tty_receive_buf_common+0x8d/0x2400 > [ 1483.473033] [] n_tty_receive_buf2+0x33/0x40 > [ 1483.473033] [] flush_to_ldisc+0x3bf/0x7f0 > [ 1483.473033] [] process_one_work+0x796/0x1440 > [ 1483.473033] [] worker_thread+0xdb/0xfc0 > [ 1483.473033] [] kthread+0x23f/0x2d0 > [ 1483.473033] [] ret_from_fork+0x3f/0x70 > [ 1483.473033] > -> #1 (&port->buf.lock/1){+.+...}: > [ 1483.473033] [] lock_acquire+0x1dc/0x430 > [ 1483.473033] [] mutex_lock_nested+0xb1/0xa50 > [ 1483.473033] [] n_tracesink_open+0x23/0xf0 > [ 1483.473033] [] tty_ldisc_open.isra.2+0x78/0xd0 > [ 1483.473033] [] tty_set_ldisc+0x292/0x8a0 > [ 1483.473033] [] tty_ioctl+0xb2e/0x2160 > [ 1483.473033] [] do_vfs_ioctl+0x18c/0xfb0 > [ 1483.473033] [] SyS_ioctl+0x8f/0xc0 > [ 1483.473033] [] entry_SYSCALL_64_fastpath+0x16/0x7a > [ 1483.473033] > -> #0 (writelock){+.+...}: > [ 1483.473033] [] __lock_acquire+0x31eb/0x4700 > [ 1483.473033] [] lock_acquire+0x1dc/0x430 > [ 1483.473033] [] mutex_lock_nested+0xb1/0xa50 > [ 1483.473033] [] n_tracesink_datadrain+0x24/0xc0 > [ 1483.473033] [] n_tracerouter_receivebuf+0x2b/0x40 > [ 1483.473033] [] flush_to_ldisc+0x584/0x7f0 > [ 1483.473033] [] process_one_work+0x796/0x1440 > [ 1483.473033] [] worker_thread+0xdb/0xfc0 > [ 1483.473033] [] kthread+0x23f/0x2d0 > [ 1483.473033] [] ret_from_fork+0x3f/0x70 > [ 1483.473033] > [ 1483.473033] other info that might help us debug this: > [ 1483.473033] > [ 1483.473033] Chain exists of: > writelock --> &buf->lock --> routelock > > [ 1483.473033] Possible unsafe locking scenario: > [ 1483.473033] > [ 1483.473033] CPU0 CPU1 > [ 1483.473033] ---- ---- > [ 1483.473033] lock(routelock); > [ 1483.473033] lock(&buf->lock); > [ 1483.473033] lock(routelock); > [ 1483.473033] lock(writelock); > [ 1483.473033] > [ 1483.473033] *** DEADLOCK *** > [ 1483.473033] > [ 1483.473033] 5 locks held by kworker/u9:0/10808: > [ 1483.473033] #0: ("events_unbound"){.+.+.+}, at: > [] process_one_work+0x69a/0x1440 > [ 1483.473033] #1: ((&buf->work)){+.+...}, at: [] > process_one_work+0x6ca/0x1440 > [ 1483.473033] #2: (&tty->ldisc_sem){++++++}, at: > [] tty_ldisc_ref+0x1b/0x80 > [ 1483.473033] #3: (&buf->lock){+.+...}, at: [] > flush_to_ldisc+0xe1/0x7f0 > [ 1483.473033] #4: (routelock){+.+...}, at: [] > n_tracerouter_receivebuf+0x20/0x40 > [ 1483.473033] > [ 1483.473033] stack backtrace: > [ 1483.473033] CPU: 1 PID: 10808 Comm: kworker/u9:0 Not tainted 4.4.0+ #275 > [ 1483.473033] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), > BIOS Bochs 01/01/2011 > [ 1483.473033] Workqueue: events_unbound flush_to_ldisc > [ 1483.473033] 00000000ffffffff ffff8800334ff7a0 ffffffff82994c8d > ffffffff88faf110 > [ 1483.473033] ffffffff88fdabb0 ffffffff88ff1ef0 ffff8800334ff7f0 > ffffffff8144fb58 > [ 1483.473033] ffff88003a290000 ffff88003a2908ea 0000000000000000 > ffff88003a2908c8 > [ 1483.473033] Call Trace: > [ 1483.473033] [] dump_stack+0x6f/0xa2 > [ 1483.473033] [] print_circular_bug+0x288/0x340 > [ 1483.473033] [] __lock_acquire+0x31eb/0x4700 > [ 1483.473033] [] ? debug_check_no_locks_freed+0x3c0/0x3c0 > [ 1483.473033] [] ? debug_check_no_locks_freed+0x3c0/0x3c0 > [ 1483.473033] [] ? debug_check_no_locks_freed+0x3c0/0x3c0 > [ 1483.473033] [] lock_acquire+0x1dc/0x430 > [ 1483.473033] [] ? n_tracesink_datadrain+0x24/0xc0 > [ 1483.473033] [] mutex_lock_nested+0xb1/0xa50 > [ 1483.473033] [] ? n_tracesink_datadrain+0x24/0xc0 > [ 1483.473033] [] ? trace_hardirqs_on+0xd/0x10 > [ 1483.473033] [] ? n_tracerouter_receivebuf+0x20/0x40 > [ 1483.473033] [] ? trace_hardirqs_on+0xd/0x10 > [ 1483.473033] [] ? > mutex_lock_interruptible_nested+0xbe0/0xbe0 > [ 1483.473033] [] ? > mutex_lock_interruptible_nested+0xbe0/0xbe0 > [ 1483.473033] [] ? > mutex_lock_interruptible_nested+0xbe0/0xbe0 > [ 1483.473033] [] n_tracesink_datadrain+0x24/0xc0 > [ 1483.473033] [] ? n_tracerouter_write+0x20/0x20 > [ 1483.473033] [] n_tracerouter_receivebuf+0x2b/0x40 > [ 1483.473033] [] flush_to_ldisc+0x584/0x7f0 > [ 1483.473033] [] ? tty_buffer_unlock_exclusive+0x120/0x120 > [ 1483.473033] [] process_one_work+0x796/0x1440 > [ 1483.473033] [] ? process_one_work+0x6ca/0x1440 > [ 1483.473033] [] ? pwq_dec_nr_in_flight+0x2e0/0x2e0 > [ 1483.473033] [] worker_thread+0xdb/0xfc0 > [ 1483.473033] [] kthread+0x23f/0x2d0 > [ 1483.473033] [] ? process_one_work+0x1440/0x1440 > [ 1483.473033] [] ? kthread_create_on_node+0x3b0/0x3b0 > [ 1483.473033] [] ? kthread_create_on_node+0x3b0/0x3b0 > [ 1483.473033] [] ret_from_fork+0x3f/0x70 > [ 1483.473033] [] ? kthread_create_on_node+0x3b0/0x3b0 >