linux-kernel - Re: console: lockup on boot

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: <20140611213111.GE9511@quack.suse.cz>
Date:	Wed, 11 Jun 2014 23:31:11 +0200
From:	Jan Kara <jack@...e.cz>
To:	Sasha Levin <sasha.levin@...cle.com>
Cc:	Peter Hurley <peter@...leysoftware.com>, Jan Kara <jack@...e.cz>,
	pmladek@...e.cz, Andrew Morton <akpm@...ux-foundation.org>,
	Jet Chen <jet.chen@...el.com>,
	LKML <linux-kernel@...r.kernel.org>,
	Linus Torvalds <torvalds@...ux-foundation.org>
Subject: Re: console: lockup on boot

On Wed 11-06-14 22:34:36, Jan Kara wrote:
> On Wed 11-06-14 10:55:55, Sasha Levin wrote:
> > On 06/10/2014 11:59 AM, Peter Hurley wrote:
> > > On 06/06/2014 03:05 PM, Sasha Levin wrote:
> > >> On 05/30/2014 10:07 AM, Jan Kara wrote:
> > >>> On Fri 30-05-14 09:58:14, Peter Hurley wrote:
> > >>>>> On 05/30/2014 09:11 AM, Sasha Levin wrote:
> > >>>>>>> Hi all,
> > >>>>>>>
> > >>>>>>> I sometime see lockups when booting my KVM guest with the latest -next kernel,
> > >>>>>>> it basically hangs right when it should start 'init', and after a while I get
> > >>>>>>> the following spew:
> > >>>>>>>
> > >>>>>>> [   30.790833] BUG: spinlock lockup suspected on CPU#1, swapper/1/0
> > >>>>>
> > >>>>> Maybe related to this report: https://lkml.org/lkml/2014/5/30/26
> > >>>>> from Jet Chen which was bisected to
> > >>>>>
> > >>>>> commit bafe980f5afc7ccc693fd8c81c8aa5a02fbb5ae0
> > >>>>> Author:     Jan Kara <jack@...e.cz>
> > >>>>> AuthorDate: Thu May 22 10:43:35 2014 +1000
> > >>>>> Commit:     Stephen Rothwell <sfr@...b.auug.org.au>
> > >>>>> CommitDate: Thu May 22 10:43:35 2014 +1000
> > >>>>>
> > >>>>>      printk: enable interrupts before calling console_trylock_for_printk()
> > >>>>>          We need interrupts disabled when calling console_trylock_for_printk() only
> > >>>>>      so that cpu id we pass to can_use_console() remains valid (for other
> > >>>>>      things console_sem provides all the exclusion we need and deadlocks on
> > >>>>>      console_sem due to interrupts are impossible because we use
> > >>>>>      down_trylock()).  However if we are rescheduled, we are guaranteed to run
> > >>>>>      on an online cpu so we can easily just get the cpu id in
> > >>>>>      can_use_console().
> > >>>>>          We can lose a bit of performance when we enable interrupts in
> > >>>>>      vprintk_emit() and then disable them again in console_unlock() but OTOH it
> > >>>>>      can somewhat reduce interrupt latency caused by console_unlock()
> > >>>>>      especially since later in the patch series we will want to spin on
> > >>>>>      console_sem in console_trylock_for_printk().
> > >>>>>          Signed-off-by: Jan Kara <jack@...e.cz>
> > >>>>>      Signed-off-by: Andrew Morton <akpm@...ux-foundation.org>
> > >>>>>
> > >>>>> ?
> > >>>    Yeah, very likely. I think I see the problem, I'll send the fix shortly.
> > >>
> > >> Hi Jan,
> > >>
> > >> It seems that the issue I'm seeing is different from the "[prink]  BUG: spinlock
> > >> lockup suspected on CPU#0, swapper/1".
> > >>
> > >> Is there anything else I could try here? The issue is very common during testing.
> > > 
> > > Sasha,
> > > 
> > > Is this bisectable? Maybe that's the best way forward here.
> > 
> > I've ran a bisection again and ended up at the same commit as Jet Chen
> > (the commit unfortunately already made it to Linus's tree).
> > 
> > Note that I did try Jan's proposed fix and that didn't solve the issue
> > for me, I believe we're seeing different issues caused by the same
> > commit.
>   Sorry it has been busy time lately and I didn't have as much time to look
> into this as would be needed.
  Oops, pressed send too early... So I have two debug patches for you. Can
you try whether the problem reproduces with the first one or with both of
them applied?

The stacktrace from spinlock lockup is somewhat weird - the spinlock lockup
message comes from NMI context where we tried to do print stack dump.
Indeed calling printk from NMI context *can* lead to this sort of lockups
(and the current process is a worker thread which apparently runs
fb_flashcursor() function which calls console_unlock() which can hold
logbuf_lock so all these things fit together).  What I really fail to see
is how my patch makes the problem happen to you pretty reliably.

Another somewhat strange thing to me is that although lock->owner in your
dump looks fine and points to currently running process, lock->owner_cpu is
-1 which is a combination that shouldn't ever happen as I'm looking into
spinlock debug code.

So for now I'm still puzzled.
								Honza

-- 
Jan Kara <jack@...e.cz>
SUSE Labs, CR

View attachment "0001-printk-Debug-patch1.patch" of type "text/x-patch" (1001 bytes)

View attachment "0002-printk-Debug-patch-2.patch" of type "text/x-patch" (1192 bytes)