Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[John Donnelly]

Hello linux-usb.


I am seeing this message every time a server is rebooted, and it started around 5.2 release. It is benign behavior but it does not occur in prior 4.18 Linux kernels. 


Kernel 5.6.0-rc1.01.el8uek.rc1.x86_64 on an x86_64 


[  836.063284] irq 18: nobody cared (try booting with the "irqpoll" option) 
[  836.143498] CPU: 24 PID: 0 Comm: swapper/24 Kdump: loaded Not tainted 
5.3.6.jpd.01.+ #5 
[  836.239310] Hardware name: Oracle Corporation ORACLE SERVER 
X5-2/ASM,MOTHERBOARD,1U, BIOS 30140300 09/20/2018 
[  836.358010] Call Trace: 
[  836.387248]  <IRQ> 
[  836.411298]  dump_stack+0x63/0x8a 
[  836.450951]  __report_bad_irq+0x3c/0xb6 
[  836.496830]  note_interrupt.cold.10+0xb/0x5d 
[  836.547916]  handle_irq_event_percpu+0x6f/0x80 
[  836.601077]  handle_irq_event+0x3b/0x5a 
[  836.646962]  handle_fasteoi_irq+0x90/0x130 
[  836.695968]  handle_irq+0x20/0x30 
[  836.711139] megaraid_sas 0000:23:00.0: megasas_disable_intr_fusion is 
called outbound_intr_mask:0x40000009 
[  836.735612]  do_IRQ+0x4e/0xe0 
[  836.735616]  common_interrupt+0xf/0xf 
[  836.735619]  </IRQ>

[  336.622666] [<0000000010b50533>] usb_hcd_irq 
[  336.673746] [<0000000010b50533>] usb_hcd_irq


Device info :


lsusb -t 
/:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M 
   |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M 
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M 
   |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M 
[root@ca-dev55 ~]#



PCI infö :

[root@ca-dev55 kernel]# lspci -s 00:1d.0 -k -vv
00:1d.0 USB controller: Intel Corporation C610/X99 series chipset USB Enhanced Host Controller #1 (rev 05) (prog-if 20 [EHCI])
	Subsystem: Oracle/SUN Device 4852
	Control: I/O- Mem+ BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr+ Stepping- SERR+ FastB2B- DisINTx-
	Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Interrupt: pin C routed to IRQ 18
	NUMA node: 0
	Region 0: Memory at c7501000 (32-bit, non-prefetchable) [size=1K]
	Capabilities: [50] Power Management version 2
		Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
	Capabilities: [58] Debug port: BAR=1 offset=00a0
	Capabilities: [98] PCI Advanced Features
		AFCap: TP+ FLR+
		AFCtrl: FLR-
		AFStatus: TP-
	Kernel modules: ehci_pci


# cat  /sys/kernel/irq/18/* 
ehci_hcd:usb1,ehci_hcd:usb2 
IR-IO-APIC 
18 
fasteoi 
0,0,0,0,0,0,0,0,60,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0 
level



There are no USB devices attached to these ports ( like a keyboard or mouse ) so I am not sure why it would be producing spurious interrupts .

We have ehci_pci and echo_hcd  components compiled in the kernel ,but the behavior also occurs when those drivers are created as loadable  modules . 

If I removed the modules using rmmod  prior to Linux shutdown the issue does not occur .  

Any suggestions ?  

Thank you. 

John

Oracle Linux  team. 

Re: Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[Alan Stern]

On Mon, 2 Mar 2020, John Donnelly wrote:

> Hello linux-usb.
> 
> 
> I am seeing this message every time a server is rebooted, and it started around 5.2 release. It is benign behavior but it does not occur in prior 4.18 Linux kernels. 

What about 4.19?  4.20?  5.0?  And so on...

It still think your best bet for finding out what is happening is to do 
a bisection.

> Kernel 5.6.0-rc1.01.el8uek.rc1.x86_64 on an x86_64 
> 
> 
> [  836.063284] irq 18: nobody cared (try booting with the "irqpoll" option) 
> [  836.143498] CPU: 24 PID: 0 Comm: swapper/24 Kdump: loaded Not tainted 
> 5.3.6.jpd.01.+ #5 
> [  836.239310] Hardware name: Oracle Corporation ORACLE SERVER 
> X5-2/ASM,MOTHERBOARD,1U, BIOS 30140300 09/20/2018 
> [  836.358010] Call Trace: 
> [  836.387248]  <IRQ> 
> [  836.411298]  dump_stack+0x63/0x8a 
> [  836.450951]  __report_bad_irq+0x3c/0xb6 
> [  836.496830]  note_interrupt.cold.10+0xb/0x5d 
> [  836.547916]  handle_irq_event_percpu+0x6f/0x80 
> [  836.601077]  handle_irq_event+0x3b/0x5a 
> [  836.646962]  handle_fasteoi_irq+0x90/0x130 
> [  836.695968]  handle_irq+0x20/0x30 
> [  836.711139] megaraid_sas 0000:23:00.0: megasas_disable_intr_fusion is 
> called outbound_intr_mask:0x40000009 
> [  836.735612]  do_IRQ+0x4e/0xe0 
> [  836.735616]  common_interrupt+0xf/0xf 
> [  836.735619]  </IRQ>
> 
> [  336.622666] [<0000000010b50533>] usb_hcd_irq 
> [  336.673746] [<0000000010b50533>] usb_hcd_irq
> 
> 
> Device info :
> 
> 
> lsusb -t 
> /:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M 
>    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M 
> /:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M 
>    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M 
> [root@ca-dev55 ~]#
> 
> 
> 
> PCI infö :
> 
> [root@ca-dev55 kernel]# lspci -s 00:1d.0 -k -vv
> 00:1d.0 USB controller: Intel Corporation C610/X99 series chipset USB Enhanced Host Controller #1 (rev 05) (prog-if 20 [EHCI])
> 	Subsystem: Oracle/SUN Device 4852
> 	Control: I/O- Mem+ BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr+ Stepping- SERR+ FastB2B- DisINTx-
> 	Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
> 	Interrupt: pin C routed to IRQ 18
> 	NUMA node: 0
> 	Region 0: Memory at c7501000 (32-bit, non-prefetchable) [size=1K]
> 	Capabilities: [50] Power Management version 2
> 		Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
> 		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
> 	Capabilities: [58] Debug port: BAR=1 offset=00a0
> 	Capabilities: [98] PCI Advanced Features
> 		AFCap: TP+ FLR+
> 		AFCtrl: FLR-
> 		AFStatus: TP-
> 	Kernel modules: ehci_pci
> 
> 
> # cat  /sys/kernel/irq/18/* 
> ehci_hcd:usb1,ehci_hcd:usb2 
> IR-IO-APIC 
> 18 
> fasteoi 
> 0,0,0,0,0,0,0,0,60,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0 
> level
> 
> 
> 
> There are no USB devices attached to these ports ( like a keyboard or mouse ) so I am not sure why it would be producing spurious interrupts .
> 
> We have ehci_pci and echo_hcd  components compiled in the kernel ,but the behavior also occurs when those drivers are created as loadable  modules . 
> 
> If I removed the modules using rmmod  prior to Linux shutdown the issue does not occur .  

So at least you have a workaround, if nothing else.

> Any suggestions ?  

Since the messages are benign, you can simply ignore them.

Or you can try to track down the code that causes them to appear, as
described above.

Alan Stern

Re: Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[John Donnelly]

On 3/2/20 3:56 PM, Alan Stern wrote:
> On Mon, 2 Mar 2020, John Donnelly wrote:
> 
>> Hello linux-usb.
>>
>>
>> I am seeing this message every time a server is rebooted, and it started around 5.2 release. It is benign behavior but it does not occur in prior 4.18 Linux kernels.
> 
> What about 4.19?  4.20?  5.0?  And so on...
> 
> It still think your best bet for finding out what is happening is to do
> a bisection.

   Thank you for the feedback.  This could take awhile !  I will update 
you on my findings.



> 
>> Kernel 5.6.0-rc1.01.el8uek.rc1.x86_64 on an x86_64
>>
>>
>> [  836.063284] irq 18: nobody cared (try booting with the "irqpoll" option)
>> [  836.143498] CPU: 24 PID: 0 Comm: swapper/24 Kdump: loaded Not tainted
>> 5.3.6.jpd.01.+ #5
>> [  836.239310] Hardware name: Oracle Corporation ORACLE SERVER
>> X5-2/ASM,MOTHERBOARD,1U, BIOS 30140300 09/20/2018
>> [  836.358010] Call Trace:
>> [  836.387248]  <IRQ>
>> [  836.411298]  dump_stack+0x63/0x8a
>> [  836.450951]  __report_bad_irq+0x3c/0xb6
>> [  836.496830]  note_interrupt.cold.10+0xb/0x5d
>> [  836.547916]  handle_irq_event_percpu+0x6f/0x80
>> [  836.601077]  handle_irq_event+0x3b/0x5a
>> [  836.646962]  handle_fasteoi_irq+0x90/0x130
>> [  836.695968]  handle_irq+0x20/0x30
>> [  836.711139] megaraid_sas 0000:23:00.0: megasas_disable_intr_fusion is
>> called outbound_intr_mask:0x40000009
>> [  836.735612]  do_IRQ+0x4e/0xe0
>> [  836.735616]  common_interrupt+0xf/0xf
>> [  836.735619]  </IRQ>
>>
>> [  336.622666] [<0000000010b50533>] usb_hcd_irq
>> [  336.673746] [<0000000010b50533>] usb_hcd_irq
>>
>>
>> Device info :
>>
>>
>> lsusb -t
>> /:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
>>     |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/8p, 480M
>> /:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci-pci/2p, 480M
>>     |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/6p, 480M
>> [root@ca-dev55 ~]#
>>
>>
>>
>> PCI infö :
>>
>> [root@ca-dev55 kernel]# lspci -s 00:1d.0 -k -vv
>> 00:1d.0 USB controller: Intel Corporation C610/X99 series chipset USB Enhanced Host Controller #1 (rev 05) (prog-if 20 [EHCI])
>> 	Subsystem: Oracle/SUN Device 4852
>> 	Control: I/O- Mem+ BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr+ Stepping- SERR+ FastB2B- DisINTx-
>> 	Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
>> 	Interrupt: pin C routed to IRQ 18
>> 	NUMA node: 0
>> 	Region 0: Memory at c7501000 (32-bit, non-prefetchable) [size=1K]
>> 	Capabilities: [50] Power Management version 2
>> 		Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
>> 		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
>> 	Capabilities: [58] Debug port: BAR=1 offset=00a0
>> 	Capabilities: [98] PCI Advanced Features
>> 		AFCap: TP+ FLR+
>> 		AFCtrl: FLR-
>> 		AFStatus: TP-
>> 	Kernel modules: ehci_pci
>>
>>
>> # cat  /sys/kernel/irq/18/*
>> ehci_hcd:usb1,ehci_hcd:usb2
>> IR-IO-APIC
>> 18
>> fasteoi
>> 0,0,0,0,0,0,0,0,60,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
>> level
>>
>>
>>
>> There are no USB devices attached to these ports ( like a keyboard or mouse ) so I am not sure why it would be producing spurious interrupts .
>>
>> We have ehci_pci and echo_hcd  components compiled in the kernel ,but the behavior also occurs when those drivers are created as loadable  modules .
>>
>> If I removed the modules using rmmod  prior to Linux shutdown the issue does not occur .
> 
> So at least you have a workaround, if nothing else.
> 
>> Any suggestions ?
> 
> Since the messages are benign, you can simply ignore them.
> 
> Or you can try to track down the code that causes them to appear, as
> described above.
> 
> Alan Stern
> 


-- 
Thank You,
John

Re: Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[Alan Stern]

On Mon, 2 Mar 2020, John Donnelly wrote:

> On 3/2/20 3:56 PM, Alan Stern wrote:
> > On Mon, 2 Mar 2020, John Donnelly wrote:
> > 
> >> Hello linux-usb.
> >>
> >>
> >> I am seeing this message every time a server is rebooted, and it started around 5.2 release. It is benign behavior but it does not occur in prior 4.18 Linux kernels.
> > 
> > What about 4.19?  4.20?  5.0?  And so on...
> > 
> > It still think your best bet for finding out what is happening is to do
> > a bisection.
> 
>    Thank you for the feedback.  This could take awhile !  I will update 
> you on my findings.
> 
> 
> 
> > 
> >> Kernel 5.6.0-rc1.01.el8uek.rc1.x86_64 on an x86_64
> >>
> >>
> >> [  836.063284] irq 18: nobody cared (try booting with the "irqpoll" option)
> >> [  836.143498] CPU: 24 PID: 0 Comm: swapper/24 Kdump: loaded Not tainted
> >> 5.3.6.jpd.01.+ #5
> >> [  836.239310] Hardware name: Oracle Corporation ORACLE SERVER
> >> X5-2/ASM,MOTHERBOARD,1U, BIOS 30140300 09/20/2018
> >> [  836.358010] Call Trace:
> >> [  836.387248]  <IRQ>
> >> [  836.411298]  dump_stack+0x63/0x8a
> >> [  836.450951]  __report_bad_irq+0x3c/0xb6
> >> [  836.496830]  note_interrupt.cold.10+0xb/0x5d
> >> [  836.547916]  handle_irq_event_percpu+0x6f/0x80
> >> [  836.601077]  handle_irq_event+0x3b/0x5a
> >> [  836.646962]  handle_fasteoi_irq+0x90/0x130
> >> [  836.695968]  handle_irq+0x20/0x30
> >> [  836.711139] megaraid_sas 0000:23:00.0: megasas_disable_intr_fusion is
> >> called outbound_intr_mask:0x40000009
> >> [  836.735612]  do_IRQ+0x4e/0xe0
> >> [  836.735616]  common_interrupt+0xf/0xf
> >> [  836.735619]  </IRQ>
> >>
> >> [  336.622666] [<0000000010b50533>] usb_hcd_irq
> >> [  336.673746] [<0000000010b50533>] usb_hcd_irq

Let's try to be a little more precise.  You said this happens "every 
time a server is rebooted".  At first I thought you meant it happened 
during the boot process.  But the timestamps on these log messages 
indicate the unwanted IRQ happened 836 seconds _after_ boot, possibly 
also 336 seconds after.

So when exactly do you see this?

>     Removing the modules BEFORE I do a shutdown does not produce the error - which is kind of surprising . 

What exactly does this mean?  Do you mean that the error does not occur 
at the time the module is removed?  Or do you mean that if you remove 
the module and then reboot, the error does not occur during the reboot?  
Or do you mean that if you remove the module and reboot, the error does 
not occur until the system is booted yet again?

>    It appears the modules are actually loaded by the ramdisk too  - prior to getting to the single user mode when I built them as loadable module .. because I renamed them  so modprobe/udev  would not find them after systemd starts.

This depends on the contents of your initramfs.  Most likely you
rebuilt that along with the kernel, so if the kernel uses modules for
the EHCI drivers then so does the initramfs.

Alan Stern

Re: Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[John Donnelly]

Hi Alan,
 See inline.

> On Mar 3, 2020, at 9:35 AM, Alan Stern <stern@rowland.harvard.edu> wrote:
> 
> On Mon, 2 Mar 2020, John Donnelly wrote:
> 
>> On 3/2/20 3:56 PM, Alan Stern wrote:
>>> On Mon, 2 Mar 2020, John Donnelly wrote:
>>> 
>>>> Hello linux-usb.
>>>> 
>>>> 
>>>> I am seeing this message every time a server is rebooted, and it started around 5.2 release. It is benign behavior but it does not occur in prior 4.18 Linux kernels.
>>> 
>>> What about 4.19?  4.20?  5.0?  And so on...
>>> 
>>> It still think your best bet for finding out what is happening is to do
>>> a bisection.
>> 
>>   Thank you for the feedback.  This could take awhile !  I will update 
>> you on my findings.
>> 
>> 
>> 
>>> 
>>>> Kernel 5.6.0-rc1.01.el8uek.rc1.x86_64 on an x86_64
>>>> 
>>>> 
>>>> [  836.063284] irq 18: nobody cared (try booting with the "irqpoll" option)
>>>> [  836.143498] CPU: 24 PID: 0 Comm: swapper/24 Kdump: loaded Not tainted
>>>> 5.3.6.jpd.01.+ #5
>>>> [  836.239310] Hardware name: Oracle Corporation ORACLE SERVER
>>>> X5-2/ASM,MOTHERBOARD,1U, BIOS 30140300 09/20/2018
>>>> [  836.358010] Call Trace:
>>>> [  836.387248]  <IRQ>
>>>> [  836.411298]  dump_stack+0x63/0x8a
>>>> [  836.450951]  __report_bad_irq+0x3c/0xb6
>>>> [  836.496830]  note_interrupt.cold.10+0xb/0x5d
>>>> [  836.547916]  handle_irq_event_percpu+0x6f/0x80
>>>> [  836.601077]  handle_irq_event+0x3b/0x5a
>>>> [  836.646962]  handle_fasteoi_irq+0x90/0x130
>>>> [  836.695968]  handle_irq+0x20/0x30
>>>> [  836.711139] megaraid_sas 0000:23:00.0: megasas_disable_intr_fusion is
>>>> called outbound_intr_mask:0x40000009
>>>> [  836.735612]  do_IRQ+0x4e/0xe0
>>>> [  836.735616]  common_interrupt+0xf/0xf
>>>> [  836.735619]  </IRQ>
>>>> 
>>>> [  336.622666] [<0000000010b50533>] usb_hcd_irq
>>>> [  336.673746] [<0000000010b50533>] usb_hcd_irq
> 
> Let's try to be a little more precise.  You said this happens "every 
> time a server is rebooted".  At first I thought you meant it happened 
> during the boot process.  But the timestamps on these log messages 
> indicate the unwanted IRQ happened 836 seconds _after_ boot, possibly 
> also 336 seconds after.
> 
> So when exactly do you see this?
> 
      On shutdown - init 6 

Started Show Plymouth Reboot Screen.
[  OK  ] Unmounted RPC Pipe File System.
[  OK  ] Stopped Logout off all iSCSI sessions on shutdown.
         Stopping Open-iSCSI...
[  OK  ] Stopped Open-iSCSI.
[  OK  ] Unmounted /home.
[  OK  ] Stopped Dynamic System Tuning Daemon.
[  OK  ] Stopped Login Service.
[  OK  ] Stopped target User and Group Name Lookups.
         Stopping System Security Services Daemon...
[  OK  ] Stopped System Security Services Daemon.
[  OK  ] Stopped VDO volume services.
[  OK  ] Stopped System Logging Service.
[  OK  ] Stopped target Network is Online.
[  OK  ] Stopped target Network.
         Stopping Network Manager...
         Stopping Network Name Resolution...
[  OK  ] Stopped Network Name Resolution.
[  OK  ] Stopped Network Manager.
         Stopping D-Bus System Message Bus...
[  OK  ] Stopped Rollback uncommitted netcf network config change transactions.
[  OK  ] Stoppe[ 1523.374186] irq 18: nobody cared (try booting with the "irqpoll" option)
d D-Bus System M[ 1523.470444] handlers:
[ 1523.514197] [<0000000024f18691>] usb_hcd_irq
[ 1523.565284] [<0000000024f18691>] usb_hcd_irq
[ 1523.675772] Disabling IRQ #18
[  OK  ] Stopped target Basic System.
[  OK  ] Stopped Forward Password Requests to Plymouth Directory Watch.
[  OK  ] Stopped target Sockets.
[  OK  ] Closed Avahi mDNS/DNS-SD Stack Activation Socket.
[  OK  ] Closed Activation socket for spice guest agent daemon.
[  OK  ] Closed Open-iSCSI iscsiuio Socket.
[  OK  ] Closed CUPS Scheduler.
[  OK  ] Closed Virtual machine log manager socket.
[  OK  ] Closed Virtual machine lock manager socket.
[  OK  ] Closed Open-iSCSI iscsid Socket.
[  OK  ] Closed PC/SC Smart Card Daemon Activation Socket.
[  OK  ] Closed SSSD Kerberos Cache Manager responder socket.
[  OK  ] Stopped target Paths.
[  OK  ] Stopped CUPS Scheduler.
[  OK  ] Stopped target Slices.
[  OK  ] Removed slice Virtual Machine and Container Slice.
[  OK  ] Removed slice User and Session Slice.
[  OK  ] Closed D-Bus System Message Bus Socket.
[  OK  ] Stopped target System Initialization.
[  OK  ] Stopped target Swap.
   [ 1524.987084] reboot: Restarting system
     


>>    Removing the modules BEFORE I do a shutdown does not produce the error - which is kind of surprising . 
> 
> What exactly does this mean?  Do you mean that the error does not occur 
> at the time the module is removed?

    Yes 

>  Or do you mean that if you remove 
> the module and then reboot, the error does not occur during the reboot?  

 Yes 

> Or do you mean that if you remove the module and reboot, the error does 
> not occur until the system is booted yet again?
> 

   Yes 

>>   It appears the modules are actually loaded by the ramdisk too  - prior to getting to the single user mode when I built them as loadable module .. because I renamed them  so modprobe/udev  would not find them after systemd starts.
> 
> This depends on the contents of your initramfs.  Most likely you
> rebuilt that along with the kernel, so if the kernel uses modules for
> the EHCI drivers then so does the initramfs.

    Yes .  I needed to make them modules so I could test the removal using rmmod. 
> 
> 

 I have determined the event goes all the back to 5.0-rc1, then  4.18.rc8 ;  and Kernel 4.18.0-147.3.1.el8_1.x86_64, which is the current RH 8.1 kernel . I was mistaken it was solely  a 5.4 issue. 







  

Re: Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[Alan Stern]

On Tue, 3 Mar 2020, John Donnelly wrote:

> > Let's try to be a little more precise.  You said this happens "every 
> > time a server is rebooted".  At first I thought you meant it happened 
> > during the boot process.  But the timestamps on these log messages 
> > indicate the unwanted IRQ happened 836 seconds _after_ boot, possibly 
> > also 336 seconds after.
> > 
> > So when exactly do you see this?
> > 
>       On shutdown - init 6 
> 
> Started Show Plymouth Reboot Screen.
> [  OK  ] Unmounted RPC Pipe File System.
> [  OK  ] Stopped Logout off all iSCSI sessions on shutdown.
>          Stopping Open-iSCSI...
> [  OK  ] Stopped Open-iSCSI.
> [  OK  ] Unmounted /home.
> [  OK  ] Stopped Dynamic System Tuning Daemon.
> [  OK  ] Stopped Login Service.
> [  OK  ] Stopped target User and Group Name Lookups.
>          Stopping System Security Services Daemon...
> [  OK  ] Stopped System Security Services Daemon.
> [  OK  ] Stopped VDO volume services.
> [  OK  ] Stopped System Logging Service.
> [  OK  ] Stopped target Network is Online.
> [  OK  ] Stopped target Network.
>          Stopping Network Manager...
>          Stopping Network Name Resolution...
> [  OK  ] Stopped Network Name Resolution.
> [  OK  ] Stopped Network Manager.
>          Stopping D-Bus System Message Bus...
> [  OK  ] Stopped Rollback uncommitted netcf network config change transactions.
> [  OK  ] Stoppe[ 1523.374186] irq 18: nobody cared (try booting with the "irqpoll" option)
> d D-Bus System M[ 1523.470444] handlers:
> [ 1523.514197] [<0000000024f18691>] usb_hcd_irq
> [ 1523.565284] [<0000000024f18691>] usb_hcd_irq
> [ 1523.675772] Disabling IRQ #18
> [  OK  ] Stopped target Basic System.
> [  OK  ] Stopped Forward Password Requests to Plymouth Directory Watch.
> [  OK  ] Stopped target Sockets.
> [  OK  ] Closed Avahi mDNS/DNS-SD Stack Activation Socket.
> [  OK  ] Closed Activation socket for spice guest agent daemon.
> [  OK  ] Closed Open-iSCSI iscsiuio Socket.
> [  OK  ] Closed CUPS Scheduler.
> [  OK  ] Closed Virtual machine log manager socket.
> [  OK  ] Closed Virtual machine lock manager socket.
> [  OK  ] Closed Open-iSCSI iscsid Socket.
> [  OK  ] Closed PC/SC Smart Card Daemon Activation Socket.
> [  OK  ] Closed SSSD Kerberos Cache Manager responder socket.
> [  OK  ] Stopped target Paths.
> [  OK  ] Stopped CUPS Scheduler.
> [  OK  ] Stopped target Slices.
> [  OK  ] Removed slice Virtual Machine and Container Slice.
> [  OK  ] Removed slice User and Session Slice.
> [  OK  ] Closed D-Bus System Message Bus Socket.
> [  OK  ] Stopped target System Initialization.
> [  OK  ] Stopped target Swap.
>    [ 1524.987084] reboot: Restarting system

All right.  You never made this clear.

> >>    Removing the modules BEFORE I do a shutdown does not produce the error - which is kind of surprising . 
> > 
> > What exactly does this mean?  Do you mean that the error does not occur 
> > at the time the module is removed?
> 
>     Yes 

No!  You mean that the error does not occur at the time when the system
is shut down following module removal.  Right?

> >  Or do you mean that if you remove 
> > the module and then reboot, the error does not occur during the reboot?  
> 
>  Yes 

Again, no.

> > Or do you mean that if you remove the module and reboot, the error does 
> > not occur until the system is booted yet again?
> > 
> 
>    Yes 

And no.  I can't help if you don't give full and unambiguous answers.

> >>   It appears the modules are actually loaded by the ramdisk too  - prior to getting to the single user mode when I built them as loadable module .. because I renamed them  so modprobe/udev  would not find them after systemd starts.
> > 
> > This depends on the contents of your initramfs.  Most likely you
> > rebuilt that along with the kernel, so if the kernel uses modules for
> > the EHCI drivers then so does the initramfs.
> 
>     Yes .  I needed to make them modules so I could test the removal using rmmod. 
> > 
> > 
> 
>  I have determined the event goes all the back to 5.0-rc1, then  4.18.rc8 ;  and Kernel 4.18.0-147.3.1.el8_1.x86_64, which is the current RH 8.1 kernel . I was mistaken it was solely  a 5.4 issue. 

Good work.  Keep on going; what about 4.19 and 4.20?  And various 
release candidates in between, and so on...

Alan Stern

Re: Spurious EHCI interrupts with 5.2 and later on shutdown / init 6 reboot .

[John Donnelly]

On 3/3/20 10:15 AM, Alan Stern wrote:
> On Tue, 3 Mar 2020, John Donnelly wrote:
> 
>>> Let's try to be a little more precise.  You said this happens "every
>>> time a server is rebooted".  At first I thought you meant it happened
>>> during the boot process.  But the timestamps on these log messages
>>> indicate the unwanted IRQ happened 836 seconds _after_ boot, possibly
>>> also 336 seconds after.
>>>
>>> So when exactly do you see this?
>>>
>>        On shutdown - init 6
>>
>> Started Show Plymouth Reboot Screen.
>> [  OK  ] Unmounted RPC Pipe File System.
>> [  OK  ] Stopped Logout off all iSCSI sessions on shutdown.
>>           Stopping Open-iSCSI...
>> [  OK  ] Stopped Open-iSCSI.
>> [  OK  ] Unmounted /home.
>> [  OK  ] Stopped Dynamic System Tuning Daemon.
>> [  OK  ] Stopped Login Service.
>> [  OK  ] Stopped target User and Group Name Lookups.
>>           Stopping System Security Services Daemon...
>> [  OK  ] Stopped System Security Services Daemon.
>> [  OK  ] Stopped VDO volume services.
>> [  OK  ] Stopped System Logging Service.
>> [  OK  ] Stopped target Network is Online.
>> [  OK  ] Stopped target Network.
>>           Stopping Network Manager...
>>           Stopping Network Name Resolution...
>> [  OK  ] Stopped Network Name Resolution.
>> [  OK  ] Stopped Network Manager.
>>           Stopping D-Bus System Message Bus...
>> [  OK  ] Stopped Rollback uncommitted netcf network config change transactions.
>> [  OK  ] Stoppe[ 1523.374186] irq 18: nobody cared (try booting with the "irqpoll" option)
>> d D-Bus System M[ 1523.470444] handlers:
>> [ 1523.514197] [<0000000024f18691>] usb_hcd_irq
>> [ 1523.565284] [<0000000024f18691>] usb_hcd_irq
>> [ 1523.675772] Disabling IRQ #18
>> [  OK  ] Stopped target Basic System.
>> [  OK  ] Stopped Forward Password Requests to Plymouth Directory Watch.
>> [  OK  ] Stopped target Sockets.
>> [  OK  ] Closed Avahi mDNS/DNS-SD Stack Activation Socket.
>> [  OK  ] Closed Activation socket for spice guest agent daemon.
>> [  OK  ] Closed Open-iSCSI iscsiuio Socket.
>> [  OK  ] Closed CUPS Scheduler.
>> [  OK  ] Closed Virtual machine log manager socket.
>> [  OK  ] Closed Virtual machine lock manager socket.
>> [  OK  ] Closed Open-iSCSI iscsid Socket.
>> [  OK  ] Closed PC/SC Smart Card Daemon Activation Socket.
>> [  OK  ] Closed SSSD Kerberos Cache Manager responder socket.
>> [  OK  ] Stopped target Paths.
>> [  OK  ] Stopped CUPS Scheduler.
>> [  OK  ] Stopped target Slices.
>> [  OK  ] Removed slice Virtual Machine and Container Slice.
>> [  OK  ] Removed slice User and Session Slice.
>> [  OK  ] Closed D-Bus System Message Bus Socket.
>> [  OK  ] Stopped target System Initialization.
>> [  OK  ] Stopped target Swap.
>>     [ 1524.987084] reboot: Restarting system
> 
> All right.  You never made this clear.
> 
>>>>     Removing the modules BEFORE I do a shutdown does not produce the error - which is kind of surprising .
>>>
>>> What exactly does this mean?  Do you mean that the error does not occur
>>> at the time the module is removed?
>>
>>      Yes
> 
> No!  You mean that the error does not occur at the time when the system
> is shut down following module removal.  Right?
> 
>>>   Or do you mean that if you remove
>>> the module and then reboot, the error does not occur during the reboot?
>>
>>   Yes
> 
> Again, no.

  yes --  If I remove the module(s) ehci_pci and/or ehci_hcd prior to 
rebooting - the error does not occur

> 
>>> Or do you mean that if you remove the module and reboot, the error does
>>> not occur until the system is booted yet again?
>>>
>>
>>     Yes
> 
> And no.  I can't help if you don't give full and unambiguous answers.
 >>> Or do you mean that if you remove the module and reboot, the error does
 >>> not occur

  Yes

> 
>>>>    It appears the modules are actually loaded by the ramdisk too  - prior to getting to the single user mode when I built them as loadable module .. because I renamed them  so modprobe/udev  would not find them after systemd starts.
>>>
>>> This depends on the contents of your initramfs.  Most likely you
>>> rebuilt that along with the kernel, so if the kernel uses modules for
>>> the EHCI drivers then so does the initramfs.
>>
>>      Yes .  I needed to make them modules so I could test the removal using rmmod.
>>>
>>>
>>
>>   I have determined the event goes all the back to 5.0-rc1, then  4.18.rc8 ;  and Kernel 4.18.0-147.3.1.el8_1.x86_64, which is the current RH 8.1 kernel . I was mistaken it was solely  a 5.4 issue.
> 
> Good work.  Keep on going; what about 4.19 and 4.20?  And various
> release candidates in between, and so on...
> 
> Alan Stern
> 


-- 
Thank You,
John