linux-kernel - Re: [Linux 2.6.29-rc2] BUG: using smp_processor

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: <200901262148.49717.rjw@sisk.pl>
Date:	Mon, 26 Jan 2009 21:48:48 +0100
From:	"Rafael J. Wysocki" <rjw@...k.pl>
To:	Ingo Molnar <mingo@...e.hu>
Cc:	Frédéric Weisbecker <fweisbec@...il.com>,
	Steven Rostedt <rostedt@...dmis.org>,
	Linus Torvalds <torvalds@...ux-foundation.org>,
	Maciej Rutecki <maciej.rutecki@...il.com>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Thomas Gleixner <tglx@...utronix.de>
Subject: Re: [Linux 2.6.29-rc2] BUG: using smp_processor_id() in preemptible

On Monday 26 January 2009, Ingo Molnar wrote:
> 
> * Rafael J. Wysocki <rjw@...k.pl> wrote:
> 
> > On Monday 26 January 2009, Ingo Molnar wrote:
> > > 
> > > * Rafael J. Wysocki <rjw@...k.pl> wrote:
> > > 
> > > > On Monday 26 January 2009, Linus Torvalds wrote:
> > > > > 
> > > > > On Sat, 17 Jan 2009, Maciej Rutecki wrote:
> > > > > >
> > > > > > During suspend to ram:
> > > > > > [  131.287012] BUG: using smp_processor_id() in preemptible [00000000]
> > > > > > code: suspend_to_ram./2958
> > > > > > [  131.287012] caller is retrigger_next_event+0x13/0xb0
> > > > > > [  131.287012] Pid: 2958, comm: suspend_to_ram. Not tainted 2.6.29-rc2 #1
> > > > > > [  131.287012] Call Trace:
> > > > > > [  131.287012]  [<c025b41f>] debug_smp_processor_id+0xbf/0xd0
> > > > > > [  131.287012]  [<c01473b3>] retrigger_next_event+0x13/0xb0
> > > > > > [  131.287012]  [<c01489b7>] raw_notifier_call_chain+0x17/0x20
> > > > > > [  131.287012]  [<c014b938>] timekeeping_resume+0xe8/0x110
> > > > > > [  131.287012]  [<c02cc651>] __sysdev_resume+0x11/0x50
> > > > > > [  131.287012]  [<c02cc6d7>] sysdev_resume+0x47/0x80
> > > > > > [  131.287012]  [<c02d2478>] device_power_up+0x8/0x10
> > > > > 
> > > > > Very scary.
> > > > > 
> > > > > device_power_up() calls sysdev_resume _before_ it enables interrupts so it 
> > > > > sounds like something else has - very incorrectly - enabled interrupts too 
> > > > > early in your resume sequence. 
> > > > > 
> > > > > The patch that Andrew sent out and that apparently fixed things for you 
> > > > > should absolutely not have made any difference. This is suspend_enter():
> > > > > 
> > > > > 	        arch_suspend_disable_irqs();
> > > > > 	        BUG_ON(!irqs_disabled());
> > > > > 
> > > > > 	        if ((error = device_power_down(PMSG_SUSPEND))) {
> > > > > 	                printk(KERN_ERR "PM: Some devices failed to power down\n");
> > > > > 	                goto Done;
> > > > > 	        }
> > > > > 	
> > > > > 	        if (!suspend_test(TEST_CORE))
> > > > > 	                error = suspend_ops->enter(state);
> > > > > 
> > > > > 	        device_power_up(PMSG_RESUME);
> > > > > 	 Done:
> > > > > 	        arch_suspend_enable_irqs();
> > > > > 
> > > > > and notice how the whole thing is surrounded by that 
> > > > > arch_suspend_disable/enable_irqs().
> > > > > 
> > > > > So it looks like some sysdev driver (device_power_up does the sysdev 
> > > > > drivers first, so it can't be the regular low-level PCI drivers) is 
> > > > > enabling interrupts in its resume function. Scary and very wrong.
> > > > > 
> > > > > It could easily be ACPI, of course. There was some other case where ACPI 
> > > > > did that, iirc.
> > > > 
> > > > There is a known bug in the USB controllers' suspend that enables interrupts
> > > > from within ->suspend_late().  It should be fixed by the next USB merge
> > > > AFAICS.
> > > 
> > > the patch from Andrew looks wrong, as it hides the only place in the 
> > > kernel that was able to report the resume bug. Nevertheless related to 
> > > that bug we've got a new debug check queued up in timers/urgent:
> > > 
> > >  void hres_timers_resume(void)
> > >  {
> > > -       /* Retrigger the CPU local events: */
> > > +       WARN_ONCE(!irqs_disabled(),
> > > +                 KERN_INFO "hres_timers_resume() called with IRQs enabled!");
> > > +
> > >         retrigger_next_event(NULL);
> > >  }
> > > 
> > > as the buggy 'irqs are enabled' condition was not detected reliably. (it 
> > > was only detected with certain lockdep options turned on - and even then 
> > > it did not seem to be 100% triggerable)
> > 
> > Yeah.
> > 
> > > i sent it to Linus earlier today.
> > 
> > OK, thanks.
> > 
> > I'll write a debug patch covering that more generally when I recover from the
> > flu a bit.
> > 
> > Rafael
> 
> note, we could reuse the ftrace/irqtrace callbacks as well to create an: 
> "enforce IRQs off and debug violations of that" facility.

Well, do we have to? ;-)

> It would work like this, you could mark IRQs as disabled 'permanently':
> 
>    force_irqs_off_start();
>    ...
>    force_irqs_off_end();
> 
> you could mark an arbitrarily complex code sequence that way, and ftrace 
> would emit a WARN_ONCE() if irqs are enable anytime during that sequence - 
> by using the irq-tracking facilities we have for the irqsoff tracer (and 
> which we also have for lockdep).
> 
> Would that be useful?

Not sure, I only know a little about ftrace, I really can't judge.

Anyway, I think that putting the checks directly into the code path in question
would be more reliable and would still work without ftrace.

Thanks,
Rafael
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/