Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1598547 > unrolled thread

[BUG] 4.11.0-rc1 panic on shutdown X61s

Back to article view | Back to linux.kernel

Contents

  [BUG] 4.11.0-rc1 panic on shutdown X61s lkml@pengaru.com - 2017-03-12 06:40 +0100
    Re: [BUG] 4.11.0-rc1 panic on shutdown X61s Borislav Petkov <bp@alien8.de> - 2017-03-12 13:00 +0100
      Re: [BUG] 4.11.0-rc1 panic on shutdown X61s Borislav Petkov <bp@alien8.de> - 2017-03-12 13:30 +0100
        Re: [BUG] 4.11.0-rc1 panic on shutdown X61s Andy Shevchenko <andy.shevchenko@gmail.com> - 2017-03-12 15:00 +0100
          Re: [BUG] 4.11.0-rc1 panic on shutdown X61s Borislav Petkov <bp@alien8.de> - 2017-03-12 23:30 +0100
            Re: [BUG] 4.11.0-rc1 panic on shutdown X61s Bjørn Mork <bjorn@mork.no> - 2017-03-13 18:00 +0100
              RE: [BUG] 4.11.0-rc1 panic on shutdown X61s "Brown, Aaron F" <aaron.f.brown@intel.com> - 2017-03-14 02:30 +0100
        Re: [BUG] 4.11.0-rc1 panic on shutdown X61s lkml@pengaru.com - 2017-03-12 19:30 +0100

#1598547 — [BUG] 4.11.0-rc1 panic on shutdown X61s

Hello list,

Here's a photo of the panic, on imgur to be kind to vger:
http://imgur.com/a/wZI32

I'm out on a sailboat so can't really do much, but had a chance with internet
to send this FYI.  I don't even know if this happens always or not yet.

Never seen this before, up to and including 4.10.0.

Regards,
Vito Caputo

[toc] | [next] | [standalone]

#1598578

On Sat, Mar 11, 2017 at 09:37:23PM -0800, lkml@pengaru.com wrote:
> Hello list,
> 
> Here's a photo of the panic, on imgur to be kind to vger:
> http://imgur.com/a/wZI32
> 
> I'm out on a sailboat so can't really do much, but had a chance with internet

So you didn't bring another box with you on the sailboat to connect it to the
laptop over netconsole to catch full dmesg, did you?

:-)))

Because there's a taint W flag in that splat which means there was a
warning which fired before that. Which could be the important piece of
dmesg...

Other than that, this is the BUG() pci_msi_shutdown(). Hmm, maybe
linux-pci has an idea, CCed.

-- 
Regards/Gruss,
    Boris.

ECO tip #101: Trim your mails when you reply.
--

[toc] | [prev] | [next] | [standalone]

#1598584

On Sun, Mar 12, 2017 at 12:57:03PM +0100, Borislav Petkov wrote:
> On Sat, Mar 11, 2017 at 09:37:23PM -0800, lkml@pengaru.com wrote:
> > Hello list,
> > 
> > Here's a photo of the panic, on imgur to be kind to vger:
> > http://imgur.com/a/wZI32
> > 
> > I'm out on a sailboat so can't really do much, but had a chance with internet
> 
> So you didn't bring another box with you on the sailboat to connect it to the
> laptop over netconsole to catch full dmesg, did you?

Hahah, you're so in luck: I just sent this mail and hibernated my laptop
and got the same BUG. What's the chance of that happening?! Apparently
big enough.

But I was able to catch the warning before it too. So the question is,
do you have an e1000e eth controller in that machine too?

Because the symptoms below are consistent with the observed behavior:
e1000e fails to initialize MSI interrupts for whatever reason and falls
back to legacy interrupts.

Then, PCI core shuts down and BUGs because the msi_list is empty.

Anyway, lemme add e1000e people too to the fun thread.

[ 8295.723895] hib.sh (19178): drop_caches: 3
[ 8295.961695] PM: Syncing filesystems ... 
[ 8295.972559] done.
[ 8295.974699] Freezing user space processes ... (elapsed 0.001 seconds) done.
[ 8295.978484] PM: Preallocating image memory... done (allocated 197963 pages)
[ 8296.150973] PM: Allocated 791852 kbytes in 0.17 seconds (4657.95 MB/s)
[ 8296.151832] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[ 8296.155781] ACPI : EC: event blocked
[ 8296.449268] PM: freeze of devices complete after 294.716 msecs
[ 8296.469566] PM: late freeze of devices complete after 20.241 msecs
[ 8296.473369] ACPI : EC: interrupt blocked
[ 8296.477572] PM: noirq freeze of devices complete after 7.949 msecs
[ 8296.477605] Disabling non-boot CPUs ...
[ 8296.502106] Broke affinity for irq 16
[ 8296.502115] Broke affinity for irq 18
[ 8296.502124] Broke affinity for irq 23
[ 8296.503211] smpboot: CPU 1 is now offline
[ 8296.538391] Broke affinity for irq 16
[ 8296.538402] Broke affinity for irq 18
[ 8296.538412] Broke affinity for irq 23
[ 8296.538423] Broke affinity for irq 26
[ 8296.539527] smpboot: CPU 2 is now offline
[ 8296.578171] Broke affinity for irq 1
[ 8296.578180] Broke affinity for irq 8
[ 8296.578185] Broke affinity for irq 9
[ 8296.578191] Broke affinity for irq 12
[ 8296.578198] Broke affinity for irq 16
[ 8296.578204] Broke affinity for irq 18
[ 8296.578211] Broke affinity for irq 23
[ 8296.578218] Broke affinity for irq 26
[ 8296.578223] Broke affinity for irq 27
[ 8296.578228] Broke affinity for irq 28
[ 8296.579287] smpboot: CPU 3 is now offline
[ 8296.590166] PM: Creating hibernation image:
[ 8296.853347] PM: Need to copy 196464 pages
[ 8296.591954] Suspended for 284.763 seconds
[ 8296.592077] Enabling non-boot CPUs ...
[ 8296.603399] x86: Booting SMP configuration:
[ 8296.603423] smpboot: Booting Node 0 Processor 1 APIC 0x1
[ 8296.607663]  cache: parent cpu1 should not be sleeping
[ 8296.608456] CPU1 is up
[ 8296.627426] smpboot: Booting Node 0 Processor 2 APIC 0x2
[ 8296.631362]  cache: parent cpu2 should not be sleeping
[ 8296.632124] CPU2 is up
[ 8296.647451] smpboot: Booting Node 0 Processor 3 APIC 0x3
[ 8296.651451]  cache: parent cpu3 should not be sleeping
[ 8296.652258] CPU3 is up
[ 8296.659200] ACPI : EC: interrupt unblocked
[ 8296.662221] sdhci-pci 0000:02:00.0: MMC controller base frequency changed to 50Mhz.
[ 8296.703214] PM: noirq restore of devices complete after 44.358 msecs
[ 8296.704523] PM: early restore of devices complete after 1.246 msecs
[ 8296.777628] usb usb1: root hub lost power or was reset
[ 8296.777758] ACPI : EC: event unblocked
[ 8296.778121] usb usb2: root hub lost power or was reset
[ 8296.779447] rtc_cmos 00:02: System wakeup disabled by ACPI
[ 8296.779671] usb usb3: root hub lost power or was reset
[ 8296.779685] usb usb4: root hub lost power or was reset
[ 8296.781545] ehci-pci 0000:00:1a.0: cache line size of 64 is not supported
[ 8296.782034] ehci-pci 0000:00:1d.0: cache line size of 64 is not supported
[ 8296.788359] sd 0:0:0:0: [sda] Starting disk
[ 8296.788439] sd 2:0:0:0: [sdb] Starting disk
[ 8296.934415] ------------[ cut here ]------------
[ 8296.934428] WARNING: CPU: 0 PID: 19229 at drivers/pci/msi.c:1052 __pci_enable_msi_range+0x39e/0x3f0
[ 8296.934440] Modules linked in: ctr ccm fuse ntfs msdos ext2 msr cpufreq_powersave cpufreq_userspace cpufreq_conservative binfmt_misc uinput vfat fat loop dm_crypt dm_mod hid_generic usbhid hid snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal coretemp kvm_intel kvm irqbypass crc32_pclmul crc32c_intel ghash_clmulni_intel aesni_intel iTCO_wdt aes_x86_64 iTCO_vendor_support crypto_simd cryptd glue_helper intel_cstate arc4 intel_rapl_perf pcspkr i2c_i801 snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core sdhci_pci sdhci sg snd_pcm ehci_pci lpc_ich e1000e xhci_pci mmc_core snd_timer mfd_core ehci_hcd xhci_hcd wmi thinkpad_acpi nvram snd soundcore led_class ac battery serio_raw thermal [last unloaded: cfg80211]
[ 8296.934584] CPU: 0 PID: 19229 Comm: kworker/u8:49 Not tainted 4.10.0+ #2
[ 8296.934593] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
[ 8296.934605] Workqueue: events_unbound async_run_entry_fn
[ 8296.934613] Call Trace:
[ 8296.934621]  dump_stack+0x67/0x92
[ 8296.934629]  __warn+0xcb/0xf0
[ 8296.934636]  ? pci_pm_suspend_noirq+0x190/0x190
[ 8296.934644]  warn_slowpath_null+0x1d/0x20
[ 8296.934650]  __pci_enable_msi_range+0x39e/0x3f0
[ 8296.934662]  ? e1000_get_phy_info_82577+0x21/0x110 [e1000e]
[ 8296.934671]  ? pci_pm_suspend_noirq+0x190/0x190
[ 8296.934678]  pci_enable_msi+0x1a/0x30
[ 8296.934686]  e1000e_set_interrupt_capability+0x3c/0x110 [e1000e]
[ 8296.934697]  e1000e_pm_thaw+0x22/0x60 [e1000e]
[ 8296.934707]  e1000e_pm_resume+0x25/0x30 [e1000e]
[ 8296.934714]  pci_pm_restore+0x79/0xb0
[ 8296.934723]  dpm_run_callback+0x4e/0x2d0
[ 8296.934730]  device_resume+0x9d/0x1a0
[ 8296.934737]  async_resume+0x1d/0x50
[ 8296.934743]  async_run_entry_fn+0x37/0xe0
[ 8296.934752]  process_one_work+0x1e8/0x730
[ 8296.934759]  ? process_one_work+0x169/0x730
[ 8296.934768]  worker_thread+0x48/0x4e0
[ 8296.934777]  kthread+0x101/0x140
[ 8296.934783]  ? process_one_work+0x730/0x730
[ 8296.934790]  ? kthread_create_on_node+0x40/0x40
[ 8296.934798]  ret_from_fork+0x2e/0x40
[ 8296.934809] ---[ end trace 6ab732218e829ce9 ]---
[ 8296.934875] e1000e 0000:00:19.0 eth0: Failed to initialize MSI interrupts.  Falling back to legacy interrupts.

-- 
Regards/Gruss,
    Boris.

ECO tip #101: Trim your mails when you reply.
--

[toc] | [prev] | [next] | [standalone]

#1598627

On Sun, Mar 12, 2017 at 2:26 PM, Borislav Petkov <bp@alien8.de> wrote:
> On Sun, Mar 12, 2017 at 12:57:03PM +0100, Borislav Petkov wrote:
>> On Sat, Mar 11, 2017 at 09:37:23PM -0800, lkml@pengaru.com wrote:
>> > Hello list,
>> >
>> > Here's a photo of the panic, on imgur to be kind to vger:
>> > http://imgur.com/a/wZI32
>> >
>> > I'm out on a sailboat so can't really do much, but had a chance with internet
>>
>> So you didn't bring another box with you on the sailboat to connect it to the
>> laptop over netconsole to catch full dmesg, did you?
>
> Hahah, you're so in luck: I just sent this mail and hibernated my laptop
> and got the same BUG. What's the chance of that happening?! Apparently
> big enough.
>
> But I was able to catch the warning before it too. So the question is,
> do you have an e1000e eth controller in that machine too?
>
> Because the symptoms below are consistent with the observed behavior:
> e1000e fails to initialize MSI interrupts for whatever reason and falls
> back to legacy interrupts.
>
> Then, PCI core shuts down and BUGs because the msi_list is empty.
>
> Anyway, lemme add e1000e people too to the fun thread.
>

The only change that IMHO matters happened between v4.10 and v4.11-rc1 is this:

@@ -6276,8 +6274,8 @@ static int e1000e_pm_freeze(struct device *dev)
                /* Quiesce the device without resetting the hardware */
                e1000e_down(adapter, false);
                e1000_free_irq(adapter);
+               e1000e_reset_interrupt_capability(adapter);
        }
-       e1000e_reset_interrupt_capability(adapter);

So, it apparently misses something for the other case, like
pci_disable_msi() call or so.

P.S. I'm not PCI or e1000e guy :-)

-- 
With Best Regards,
Andy Shevchenko

[toc] | [prev] | [next] | [standalone]

#1598786

On Sun, Mar 12, 2017 at 03:55:08PM +0200, Andy Shevchenko wrote:
> On Sun, Mar 12, 2017 at 2:26 PM, Borislav Petkov <bp@alien8.de> wrote:
> > On Sun, Mar 12, 2017 at 12:57:03PM +0100, Borislav Petkov wrote:
> >> On Sat, Mar 11, 2017 at 09:37:23PM -0800, lkml@pengaru.com wrote:
> >> > Hello list,
> >> >
> >> > Here's a photo of the panic, on imgur to be kind to vger:
> >> > http://imgur.com/a/wZI32
> >> >
> >> > I'm out on a sailboat so can't really do much, but had a chance with internet
> >>
> >> So you didn't bring another box with you on the sailboat to connect it to the
> >> laptop over netconsole to catch full dmesg, did you?
> >
> > Hahah, you're so in luck: I just sent this mail and hibernated my laptop
> > and got the same BUG. What's the chance of that happening?! Apparently
> > big enough.
> >
> > But I was able to catch the warning before it too. So the question is,
> > do you have an e1000e eth controller in that machine too?
> >
> > Because the symptoms below are consistent with the observed behavior:
> > e1000e fails to initialize MSI interrupts for whatever reason and falls
> > back to legacy interrupts.
> >
> > Then, PCI core shuts down and BUGs because the msi_list is empty.
> >
> > Anyway, lemme add e1000e people too to the fun thread.
> >
> 
> The only change that IMHO matters happened between v4.10 and v4.11-rc1 is this:
> 
> @@ -6276,8 +6274,8 @@ static int e1000e_pm_freeze(struct device *dev)
>                 /* Quiesce the device without resetting the hardware */
>                 e1000e_down(adapter, false);
>                 e1000_free_irq(adapter);
> +               e1000e_reset_interrupt_capability(adapter);
>         }
> -       e1000e_reset_interrupt_capability(adapter);
> 
> So, it apparently misses something for the other case, like
> pci_disable_msi() call or so.

Well, lemme add the people from

  7e54d9d063fa ("e1000e: driver trying to free already-free irq")

to CC then. :-)

Thanks.

-- 
Regards/Gruss,
    Boris.

Good mailing practices for 400: avoid top-posting and trim the reply.

[toc] | [prev] | [next] | [standalone]

#1599624

Borislav Petkov <bp@alien8.de> writes:
> On Sun, Mar 12, 2017 at 03:55:08PM +0200, Andy Shevchenko wrote:
>
>> The only change that IMHO matters happened between v4.10 and v4.11-rc1 is this:
>> 
>> @@ -6276,8 +6274,8 @@ static int e1000e_pm_freeze(struct device *dev)
>>                 /* Quiesce the device without resetting the hardware */
>>                 e1000e_down(adapter, false);
>>                 e1000_free_irq(adapter);
>> +               e1000e_reset_interrupt_capability(adapter);
>>         }
>> -       e1000e_reset_interrupt_capability(adapter);
>> 
>> So, it apparently misses something for the other case, like
>> pci_disable_msi() call or so.
>
> Well, lemme add the people from
>
>   7e54d9d063fa ("e1000e: driver trying to free already-free irq")
>
> to CC then. :-)

Already did that a week ago:
https://www.spinics.net/lists/netdev/msg423379.html

Haven't heard anything back yet.  Wondering if they are waiting for
someone else to submit the pretty obvious revert?  Don't understand why
that should take more than a minute to figure out.  It's not like they
are testing these changes anyway...


Bjørn

[toc] | [prev] | [next] | [standalone]

#1599970

> From: Bjørn Mork [mailto:bjorn@mork.no]
> Sent: Monday, March 13, 2017 9:46 AM
> To: Borislav Petkov <bp@alien8.de>
> Cc: Andy Shevchenko <andy.shevchenko@gmail.com>; lkml@pengaru.com;
> linux-kernel <linux-kernel@vger.kernel.org>; vcaputo@pengaru.com; linux-
> pci@vger.kernel.org; intel-wired-lan@lists.osuosl.org; khalidm
> <khalidm@cisco.com>; David Singleton <davsingl@cisco.com>; Brown, Aaron
> F <aaron.f.brown@intel.com>; Kirsher, Jeffrey T
> <jeffrey.t.kirsher@intel.com>
> Subject: Re: [BUG] 4.11.0-rc1 panic on shutdown X61s
> 
> Borislav Petkov <bp@alien8.de> writes:
> > On Sun, Mar 12, 2017 at 03:55:08PM +0200, Andy Shevchenko wrote:
> >
> >> The only change that IMHO matters happened between v4.10 and v4.11-
> rc1 is this:
> >>
> >> @@ -6276,8 +6274,8 @@ static int e1000e_pm_freeze(struct device *dev)
> >>                 /* Quiesce the device without resetting the hardware */
> >>                 e1000e_down(adapter, false);
> >>                 e1000_free_irq(adapter);
> >> +               e1000e_reset_interrupt_capability(adapter);
> >>         }
> >> -       e1000e_reset_interrupt_capability(adapter);
> >>
> >> So, it apparently misses something for the other case, like
> >> pci_disable_msi() call or so.
> >
> > Well, lemme add the people from
> >
> >   7e54d9d063fa ("e1000e: driver trying to free already-free irq")
> >
> > to CC then. :-)
> 
> Already did that a week ago:
> https://www.spinics.net/lists/netdev/msg423379.html
> 
> Haven't heard anything back yet.  Wondering if they are waiting for
> someone else to submit the pretty obvious revert?  Don't understand why
> that should take more than a minute to figure out.  It's not like they
> are testing these changes anyway...

Believe it or not we actually do test these changes.  This one was tested by me and I did not have the same results you and the other people reporting this trace did.  I made it back in the lab today and have spent a good part of the day attempting to reproduce this bug without success.  Freeze / resume works for me on all the systems I have tried, which includes a sampling of all the current parts and many older ones.  Given there are several other reports of this it is obviously an issue and I would like to be able to reproduce it in case another patch to resolve the issue this attempts to fix comes back in another form.  So I want to know what's different between the systems that hit this and my bank of systems that don't.

What exact part (or parts) are we looking at (lspci|grep -i eth) that trigger this?  Could it be a difference in .config files?  The trace says it is falling back to legacy interrupts, does the system continue to work and does the network continue to function in that mode?  In case it's related to user space what is the base distro?  Any other information you think can help me reproduce the issue would be appreciated.

Thanks,
Aaron

> 
> 
> Bjørn

[toc] | [prev] | [next] | [standalone]

#1598709

On Sun, Mar 12, 2017 at 01:26:21PM +0100, Borislav Petkov wrote:
> On Sun, Mar 12, 2017 at 12:57:03PM +0100, Borislav Petkov wrote:
> > On Sat, Mar 11, 2017 at 09:37:23PM -0800, lkml@pengaru.com wrote:
> > > Hello list,
> > > 
> > > Here's a photo of the panic, on imgur to be kind to vger:
> > > http://imgur.com/a/wZI32
> > > 
> > > I'm out on a sailboat so can't really do much, but had a chance with internet
> > 
> > So you didn't bring another box with you on the sailboat to connect it to the
> > laptop over netconsole to catch full dmesg, did you?
> 
> Hahah, you're so in luck: I just sent this mail and hibernated my laptop
> and got the same BUG. What's the chance of that happening?! Apparently
> big enough.
> 
> But I was able to catch the warning before it too. So the question is,
> do you have an e1000e eth controller in that machine too?
> 
> Because the symptoms below are consistent with the observed behavior:
> e1000e fails to initialize MSI interrupts for whatever reason and falls
> back to legacy interrupts.
> 
> Then, PCI core shuts down and BUGs because the msi_list is empty.
> 
> Anyway, lemme add e1000e people too to the fun thread.
> 
<snip>

Hihgly likely apparently, this machine does have e1000e and after a single
suspend+resume cycle this appears in dmesg:

[28539.220131] ------------[ cut here ]------------
[28539.220131] WARNING: CPU: 1 PID: 1432 at drivers/pci/msi.c:1052 __pci_enable_msi_range+0x39c/0x3f0
[28539.220131] CPU: 1 PID: 1432 Comm: kworker/u4:40 Not tainted 4.11.0-rc1 #51
[28539.220131] Hardware name: LENOVO 7668CTO/7668CTO, BIOS 7NETC2WW (2.22 ) 03/22/2011
[28539.220131] Workqueue: events_unbound async_run_entry_fn
[28539.220131] Call Trace:
[28539.220131]  dump_stack+0x4d/0x72
[28539.220131]  __warn+0xc7/0xf0
[28539.220131]  warn_slowpath_null+0x18/0x20
[28539.220131]  __pci_enable_msi_range+0x39c/0x3f0
[28539.220131]  ? e1000e_get_phy_info_igp+0x1c/0xf0
[28539.220131]  pci_enable_msi+0x15/0x30
[28539.220131]  e1000e_set_interrupt_capability+0xe0/0x130
[28539.220131]  e1000e_pm_thaw+0x1d/0x50
[28539.220131]  e1000e_pm_resume+0x20/0x30
[28539.220131]  pci_pm_resume+0x5f/0x90
[28539.220131]  dpm_run_callback+0x44/0x170
[28539.220131]  ? pci_pm_thaw+0x90/0x90
[28539.220131]  device_resume+0xce/0x1e0
[28539.220131]  async_resume+0x18/0x40
[28539.220131]  async_run_entry_fn+0x32/0xe0
[28539.220131]  process_one_work+0x13b/0x3e0
[28539.220131]  worker_thread+0x64/0x4a0
[28539.220131]  kthread+0x10f/0x150
[28539.220131]  ? process_one_work+0x3e0/0x3e0
[28539.220131]  ? __kthread_create_on_node+0x150/0x150
[28539.220131]  ret_from_fork+0x29/0x40
[28539.220131] ---[ end trace e7beefda13ba724f ]---
[28539.220131] e1000e 0000:00:19.0 eth3: Failed to initialize MSI interrupts.  Falling back to legacy interrupts.

Regards,
Vito Caputo

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web