linux-kernel - pinctrl_cherryview: massive error messages (handle_bad

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-next>] [day] [month] [year] [list]
Date:   Wed, 19 Oct 2016 18:32:57 +0000
From:   Christian Steiner <christian.steiner@...look.de>
To:     "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>
Subject: pinctrl_cherryview: massive error messages (handle_bad_irq)

Hello,

since Kernel 4.8 I see a lot of the following error messages after
resuming from suspend to RAM:

> irq 117, desc: ffff88017a61e600, depth: 1, count: 0, unhandled: 0
> ->handle_irq():  ffffffff8109b613, handle_bad_irq+0x0/0x1e0
> ->irq_data.chip(): ffffffffa0020180, chv_pinctrl_exit+0x2d84/0x12 [pinctrl_cherryview]
> ->action():           (null)
>    IRQ_NOPROBE set

The messages appear a few thousand times and mess up the log. Despite
the messages everything seems to work fine.
I see the messages with Kernel 4.8.2 and 4.9-rc1. The do not appear with
Kernel 4.7.8 or earlier.
I have an Acer TravelMate B116-M laptop with an Intel Pentium N3700
processor.

Here are the full log messages of a suspend to RAM and resume cycle with
Kernel 4.7.8:

> [   22.605418] PM: Syncing filesystems ... done.
> [   22.613640] PM: Preparing system for sleep (mem)
> [   22.615108] Freezing user space processes ... (elapsed 0.001 seconds) done.
> [   22.616930] Double checking all user space processes after OOM killer disable... (elapsed 0.000 seconds)
> [   22.616956] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
> [   22.618611] PM: Suspending system (mem)
> [   22.618640] Suspending console(s) (use no_console_suspend to debug)
> [   22.619773] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> [   22.626173] sd 0:0:0:0: [sda] Stopping disk
> [   23.670076] PM: suspend of devices complete after 1051.008 msecs
> [   23.691058] PM: late suspend of devices complete after 20.971 msecs
> [   23.692104] r8169 0000:03:00.0: System wakeup enabled by ACPI
> [   23.693087] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
> [   23.711687] PM: noirq suspend of devices complete after 20.624 msecs
> [   23.711726] ACPI: Preparing to enter system sleep state S3
> [   23.712295] ACPI : EC: EC stopped
> [   23.712297] PM: Saving platform NVS memory
> [   23.712306] Disabling non-boot CPUs ...
> [   23.712590] Cannot set affinity for irq 191
> [   23.713647] smpboot: CPU 1 is now offline
> [   23.752643] smpboot: CPU 2 is now offline
> [   23.802930] smpboot: CPU 3 is now offline
> [   23.831827] ACPI: Low-level resume complete
> [   23.831938] ACPI : EC: EC started
> [   23.831939] PM: Restoring platform NVS memory
> [   23.832600] Enabling non-boot CPUs ...
> [   23.882819] x86: Booting SMP configuration:
> [   23.882821] smpboot: Booting Node 0 Processor 1 APIC 0x2
> [   23.885308]  cache: parent cpu1 should not be sleeping
> [   23.885757] CPU1 is up
> [   23.932612] smpboot: Booting Node 0 Processor 2 APIC 0x4
> [   23.935171]  cache: parent cpu2 should not be sleeping
> [   23.935674] CPU2 is up
> [   23.982749] smpboot: Booting Node 0 Processor 3 APIC 0x6
> [   23.985324]  cache: parent cpu3 should not be sleeping
> [   23.985840] CPU3 is up
> [   23.986370] ACPI: Waking up from system sleep state S3
> [   24.012307] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
> [   24.023417] PM: noirq resume of devices complete after 20.911 msecs
> [   25.052523] PM: early resume of devices complete after 1029.024 msecs
> [   25.053082] r8169 0000:03:00.0: System wakeup disabled by ACPI
> [   25.053124] iwlwifi 0000:02:00.0: RF_KILL bit toggled to disable radio.
> [   25.054222] rtc_cmos 00:04: System wakeup disabled by ACPI
> [   25.055645] sd 0:0:0:0: [sda] Starting disk
> [   25.075031] r8169 0000:03:00.0 eth0: link down
> [   25.374179] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
> [   25.377616] ata1.00: configured for UDMA/133
> [   26.025736] PM: resume of devices complete after 973.238 msecs
> [   26.026109] PM: Finishing wakeup.
> [   26.026111] Restarting tasks ... done.
> [   27.767611] r8169 0000:03:00.0 eth0: link up

And this is how it looks with Kernel 4.8.2:

> [   46.928231] PM: Syncing filesystems ... done.
> [   46.930391] PM: Preparing system for sleep (mem)
> [   46.932002] Freezing user space processes ... (elapsed 0.001 seconds) done.
> [   46.933721] Double checking all user space processes after OOM killer disable... (elapsed 0.000 seconds)
> [   46.933749] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
> [   46.935457] PM: Suspending system (mem)
> [   46.935486] Suspending console(s) (use no_console_suspend to debug)
> [   46.936492] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> [   46.936598] sd 0:0:0:0: [sda] Stopping disk
> [   48.026353] PM: suspend of devices complete after 1090.448 msecs
> [   48.057844] PM: late suspend of devices complete after 31.480 msecs
> [   48.059086] r8169 0000:03:00.0: System wakeup enabled by ACPI
> [   48.059240] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
> [   48.117234] PM: noirq suspend of devices complete after 59.386 msecs
> [   48.117269] ACPI: Preparing to enter system sleep state S3
> [   48.117836] ACPI : EC: EC stopped
> [   48.117837] PM: Saving platform NVS memory
> [   48.117846] Disabling non-boot CPUs ...
> [   48.118130] Cannot set affinity for irq 191
> [   48.119186] smpboot: CPU 1 is now offline
> [   48.179126] smpboot: CPU 2 is now offline
> [   48.229450] smpboot: CPU 3 is now offline
> [   48.278338] ACPI: Low-level resume complete
> [   48.278415] ACPI : EC: EC started
> [   48.278416] PM: Restoring platform NVS memory
> [   48.279036] irq 117, desc: ffff88017a61e600, depth: 1, count: 0, unhandled: 0
> [   48.279044] ->handle_irq():  ffffffff8109b613, handle_bad_irq+0x0/0x1e0
> [   48.279052] ->irq_data.chip(): ffffffffa0020180, chv_pinctrl_exit+0x2d84/0x12 [pinctrl_cherryview]
> [   48.279054] ->action():           (null)
> [   48.279055]    IRQ_NOPROBE set
> [   48.279057] unexpected IRQ trap at vector 75
> 
[...]
> 
> [   48.659033] irq 117, desc: ffff88017a61e600, depth: 1, count: 0, unhandled: 0
> [   48.659037] ->handle_irq():  ffffffff8109b613, handle_bad_irq+0x0/0x1e0
> [   48.659041] ->irq_data.chip(): ffffffffa0020180, chv_pinctrl_exit+0x2d84/0x12 [pinctrl_cherryview]
> [   48.659042] ->action():           (null)
> [   48.659043]    IRQ_NOPROBE set
> [   49.698698] PM: early resume of devices complete after 1089.068 msecs
> [   49.699601] r8169 0000:03:00.0: System wakeup disabled by ACPI
> [   49.699633] iwlwifi 0000:02:00.0: RF_KILL bit toggled to disable radio.
> [   49.708346] sd 0:0:0:0: [sda] Starting disk
> [   49.708581] rtc_cmos 00:04: System wakeup disabled by ACPI
> [   49.731492] r8169 0000:03:00.0 eth0: link down
> [   50.039718] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
> [   50.041544] ata1.00: configured for UDMA/133
> [   50.381833] PM: resume of devices complete after 683.151 msecs
> [   50.385539] PM: Finishing wakeup.
> [   50.385541] Restarting tasks ... done.

Are the messages just informational or is this something serious that
should be fixed?
If you need more information or if I should test a patch, please let me
know.

Regards,
Christian