New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Running X/LXDE causes packet loss/dmesg errors on networking #29

Closed
marsman2020 opened this Issue May 31, 2012 · 62 comments

Comments

Projects
None yet
@marsman2020

I am seeing extreme packet loss/networking issues when launching X/LXDE, but not at the console. In an attempt to rule out an issue with my power supply setup, I have gone through the troubleshooting steps below.

Hardware configuration:
-Pi Power Supply -> HP Touchpad 5.3V/2A supply, 24AWG USB A to Micro B cable
-Pi Storage -> SandDisk Extreme HD Video 4GB 20MB/s Class 6 SDHC Card
-Ethernet connected directly to router
-USB Hub -> Belkin F5U307 w/PS0538 5V 3.5A power supply
--USB Mouse (connected to hub) -> Logitech Wireless, 100mA receiver
--Keyboard Adapter (connected to hub) -> Belkin F5U119vE PS/2 to USB Adapter
--PS/2 Keyboard (connected to keyboard adapter) -> IBM KPD8923
-Pi Monitor - Lenovo L220x connected via HDMI->DVI Cable

Software Configurations:
I used the latest Debian Squeeze image, with the latest kernel (PREEMPT #89) installed via rpi-update and the Debian system fully updated using apt-get upgrade.

I did the following:

  1. On another machine on the network - Used "python -m http.server" in Python 3.2.2 to create an http server. Picked a random ~90MB file on the machine as a test download over http
  2. On the Pi - Installed the 'stress' utility using apt-get. Used "stress -c 15" to load the Pis CPU to 100%. Started htop at the console
  3. On the other machine on the network - SSHed into the Pi and ran wget in the ssh terminal to download the 90MB test.zip onto the Pi using http over the local network. Download speeds ~2.9-3.0 MB/s. ssh window responsiveness is stable. Repeated over a period of 10 minutes to allow the Pis CPU to reach a steady state temperature/power draw at 100% CPU load. Started a final instance of the download
  4. On the Pi (do this while the download is running in the ssh window!) - Exited htop. Ran "Startx"
  5. On the other machine - Observed that the download running in the ssh window on the Pi slowed from ~3MB/s to ~44KB/s as soon as X/LXDE loaded . (The 'stress' command is still running in the background, loading the CPU to the same constant 100% as with the console download tests in Step 3)
  6. On the Pi - Exited X/LXDE ("Logout")
  7. On the other machine - Observed that the download returned to its original ~3MB/s speed as soon as the system returned to the console.
  8. On the Pi - Observed that there are error messages in the dmesg log releated to the eth0 driver - see http://paste.debian.net/172123

I do not believe this is solely a power related issue, as others on this forum have repeatedly stated when users have asked about it. I can peg my Pis CPU at 100% for > 10 minutes at the console and Ethernet works just find until I start X/LXDE (with the same stress programs still running). Only then does the Ethernet drop out. No change in hardware configuration between the two cases (100% CPU at console, 100% CPU with X/LXDE running).

Other reports of similar issues on the Raspberry Pi forums:
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=6928
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=6042
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=66&t=6827#p87855
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=6677
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=7075
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=7445
http://forum.stmlabs.com/showthread.php?tid=441&pid=3258#pid3258

@XECDesign

This comment has been minimized.

Show comment
Hide comment
@XECDesign

XECDesign Jun 1, 2012

Contributor

Does this happen if you go to console and start gpm?

Contributor

XECDesign commented Jun 1, 2012

Does this happen if you go to console and start gpm?

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jun 1, 2012

XECDesign: Yes! I did some more testing last night. Same hardware configuration.

-100% CPU load with "stress" applied for all cases
-At console, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network OK
-LXDE, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network DROPS
-LXDE, powered hub->pi w/ 5.3V 2A power supply => Network OK (no mouse/keyboard attached)
-LXDE, keyboard only ->powered hub->pi w/ 5.3V 2A power supply => Network OK
-LXDE, mouse only->powered hub->pi w/ 5.3V 2A power supply => Network OK
-LXDE, keyboard only ->powered hub->pi w/ 5.3V 2A power supply; mouse->pi usb port => Network DROPS
-LXDE, mouse+keyboard->pi USB ports w/ 5.3V 2A power supply => Network OK (mouse eventually became unreliable, probably a genuine power issue in this single case)

-At console
-Without GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network OK
-GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network DROPS
-Without GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => Network OK
-GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => Network DROPS

In LXDE, it seems like having 1 low speed device on a hub and 1 low speed device elsewhere or 2 on the hub causes the problem.

With GPM, it seems like just reading the mouse period is enough to cause the problem.

(Note that my PS/2 -> USB adapter I am using for the keyboard is a dual adapter - there is a mouse port I'm not using - so it shows up as 2 USB devices)

I've got plain jane wired USB keyboard/mouse on the way from Monoprice so I can test with less power-hungry devices....

Edit - another user has done some testing here - http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=7075#p89311

XECDesign: Yes! I did some more testing last night. Same hardware configuration.

-100% CPU load with "stress" applied for all cases
-At console, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network OK
-LXDE, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network DROPS
-LXDE, powered hub->pi w/ 5.3V 2A power supply => Network OK (no mouse/keyboard attached)
-LXDE, keyboard only ->powered hub->pi w/ 5.3V 2A power supply => Network OK
-LXDE, mouse only->powered hub->pi w/ 5.3V 2A power supply => Network OK
-LXDE, keyboard only ->powered hub->pi w/ 5.3V 2A power supply; mouse->pi usb port => Network DROPS
-LXDE, mouse+keyboard->pi USB ports w/ 5.3V 2A power supply => Network OK (mouse eventually became unreliable, probably a genuine power issue in this single case)

-At console
-Without GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network OK
-GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => Network DROPS
-Without GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => Network OK
-GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => Network DROPS

In LXDE, it seems like having 1 low speed device on a hub and 1 low speed device elsewhere or 2 on the hub causes the problem.

With GPM, it seems like just reading the mouse period is enough to cause the problem.

(Note that my PS/2 -> USB adapter I am using for the keyboard is a dual adapter - there is a mouse port I'm not using - so it shows up as 2 USB devices)

I've got plain jane wired USB keyboard/mouse on the way from Monoprice so I can test with less power-hungry devices....

Edit - another user has done some testing here - http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=7075#p89311

@XECDesign

This comment has been minimized.

Show comment
Hide comment
@XECDesign

XECDesign Jun 1, 2012

Contributor

I have the same issues, I haven't narrowed it down yet, but some things which you might want to check:

  • raspberrypi/firmware#9
  • Test the voltage between TP1 and TP2 before and after. If you have a scope , see if it oscillates or oscillated differently.
  • Try a different powered hub, or try plugging things in a different order, into different ports (sometimes seems to work)
  • Try a different power supply
  • Try a different (simpler) keyboard and mouse
Contributor

XECDesign commented Jun 1, 2012

I have the same issues, I haven't narrowed it down yet, but some things which you might want to check:

  • raspberrypi/firmware#9
  • Test the voltage between TP1 and TP2 before and after. If you have a scope , see if it oscillates or oscillated differently.
  • Try a different powered hub, or try plugging things in a different order, into different ports (sometimes seems to work)
  • Try a different power supply
  • Try a different (simpler) keyboard and mouse
@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jun 1, 2012

I do not believe this is a power supply issue.

I can load the Pi's CPU to 100% for 10+ minutes with no impact on networking util LXDE is started.

Conversely, starting GPM does not cause a major CPU load on the system, and yet it kills networking as well.

I think there is a software bug in the USB code that has to do with devices that require real-time updates like mice. I don't have the linux kernel skills to chase it down myself.

As I said, I have another mouse/keyboard set en route.

I do not believe this is a power supply issue.

I can load the Pi's CPU to 100% for 10+ minutes with no impact on networking util LXDE is started.

Conversely, starting GPM does not cause a major CPU load on the system, and yet it kills networking as well.

I think there is a software bug in the USB code that has to do with devices that require real-time updates like mice. I don't have the linux kernel skills to chase it down myself.

As I said, I have another mouse/keyboard set en route.

@XECDesign

This comment has been minimized.

Show comment
Hide comment
@XECDesign

XECDesign Jun 1, 2012

Contributor

Power does not equate directly to CPU load. But if activating your mouse draws another 100mA on top of that, that can make all the difference.

I have found that I can two of either the keyboard, mouse or internet, but not all three, regardless of CPU load. And I have found that there IS a voltage drop when all three are connected.

Either way, it's worth checking if only to rule it out.

Contributor

XECDesign commented Jun 1, 2012

Power does not equate directly to CPU load. But if activating your mouse draws another 100mA on top of that, that can make all the difference.

I have found that I can two of either the keyboard, mouse or internet, but not all three, regardless of CPU load. And I have found that there IS a voltage drop when all three are connected.

Either way, it's worth checking if only to rule it out.

@XECDesign

This comment has been minimized.

Show comment
Hide comment
@XECDesign

XECDesign Jun 1, 2012

Contributor

Also, from http://elinux.org/R-Pi_Troubleshooting#Ethernet_connection_is_lost_when_a_USB_device_is_plugged_in :
Ethernet connection is lost when a USB device is plugged in
This is caused by inadequate power. Use a good power supply and a good power cable. Some cheap cables that work with a cell phone, cannot fully power the R-Pi. Some USB devices require a lot of power (>100 mA), so they must be used with a powered USB hub. Some cheap USB hubs suck power from the Raspberry Pi even if a USB power supply is connected.

Contributor

XECDesign commented Jun 1, 2012

Also, from http://elinux.org/R-Pi_Troubleshooting#Ethernet_connection_is_lost_when_a_USB_device_is_plugged_in :
Ethernet connection is lost when a USB device is plugged in
This is caused by inadequate power. Use a good power supply and a good power cable. Some cheap cables that work with a cell phone, cannot fully power the R-Pi. Some USB devices require a lot of power (>100 mA), so they must be used with a powered USB hub. Some cheap USB hubs suck power from the Raspberry Pi even if a USB power supply is connected.

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jun 3, 2012

So, I got a hold of an oscilloscope, since I don't own one, and I can verify by checking across TP1-TP2 that this is not a power issue.

I have also re-run some more tests. Hardware configuration as follows:
-Pi Power Supply -> HP Touchpad 5.3V/2A supply, 24AWG USB A to Micro B cable
-Pi Storage -> SandDisk Extreme HD Video 4GB 20MB/s Class 6 SDHC Card
-Ethernet connected directly to router
-Powered USB Hub -> Belkin F5U307 w/PS0538 5V 3.5A power supply
--USB Mouse (connected to hub) -> Logitech Wireless, 100mA receiver
--Keyboard Adapter (connected to hub) -> Belkin F5U119vE PS/2 to USB Adapter
--PS/2 Keyboard (connected to keyboard adapter) -> IBM KPD8923
-Pi Monitor - Lenovo L220x connected via HDMI->DVI Cable
-Techtronix TDS1012 measuring across TP1 TP2, with cursors at 4.75V and 5.25V and set to trigger on falling edges at 4.75V. Measuring average, min, and max voltage.

-At console, with no extra CPU load
-Without GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => 4.86V min 4.88V mean 4.93V max, Network OK
-GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => 4.93V min 4.96V mean 4.98B max, Network DROPS ("eth0: kevent 4 may have been dropped")
-Without GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => 4.88V min 4.91V mean 4.94V max, Network OK
-GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => 4.88V min 4.91V mean 4.94V max, Network OK

-LXDE started, without GPM, no extra CPU load
-mouse+keyboard->pi w/ 5.3V 2A power supply => 4.85V min 4.89V mean 4.95V max, Network OK
(I logged out of LXDE to change to the powered hub)
-mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => 4.91V min 4.96V mean 5.00V max, Network DROPS
-unplug hub - network returns

The result with the mouse+keyboard directly attached to the Pi is different with GPM from last time, but consistent with the LXDE result.

As a final test of the possibility of any power supply issues in the previous testing I have done:
-LXDE running, dual USB->PS2 adapter with keyboard attached (no mouse) & USB Wireless Mouse Receiver attached to Pi USB ports, 100% CPU load via "stress -c 13" => 4.86V min 4.90V mean 4.95V max, Network WORKS

Paste of todays session dmesg log - http://paste.ubuntu.com/1021879/

Conclusions:
-The HP Touchpad power supply (5.3V/2A) is an excellent choice for the Pi, when paired with a 6ft 24AWG power wire USB cable. It keeps the TP1-TP2 voltage within spec even with multiple USB devices attached and using power, X running, and 100% CPU load
-There is a software issue related to (some? all? unclear as I only have Belkin hubs to test) powered hubs, that interferes with operation of the USB-attached Ethernet power on the Pi. The same issue may possibly manifest with USB-attached wireless adapters (I do not have one to test). Based on GPM triggering the issue, it would appear to be related to the mouse.

So, maybe we can get on with solving this issue?

So, I got a hold of an oscilloscope, since I don't own one, and I can verify by checking across TP1-TP2 that this is not a power issue.

I have also re-run some more tests. Hardware configuration as follows:
-Pi Power Supply -> HP Touchpad 5.3V/2A supply, 24AWG USB A to Micro B cable
-Pi Storage -> SandDisk Extreme HD Video 4GB 20MB/s Class 6 SDHC Card
-Ethernet connected directly to router
-Powered USB Hub -> Belkin F5U307 w/PS0538 5V 3.5A power supply
--USB Mouse (connected to hub) -> Logitech Wireless, 100mA receiver
--Keyboard Adapter (connected to hub) -> Belkin F5U119vE PS/2 to USB Adapter
--PS/2 Keyboard (connected to keyboard adapter) -> IBM KPD8923
-Pi Monitor - Lenovo L220x connected via HDMI->DVI Cable
-Techtronix TDS1012 measuring across TP1 TP2, with cursors at 4.75V and 5.25V and set to trigger on falling edges at 4.75V. Measuring average, min, and max voltage.

-At console, with no extra CPU load
-Without GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => 4.86V min 4.88V mean 4.93V max, Network OK
-GPM, mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => 4.93V min 4.96V mean 4.98B max, Network DROPS ("eth0: kevent 4 may have been dropped")
-Without GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => 4.88V min 4.91V mean 4.94V max, Network OK
-GPM, mouse+keyboard->pi w/ 5.3V 2A power supply => 4.88V min 4.91V mean 4.94V max, Network OK

-LXDE started, without GPM, no extra CPU load
-mouse+keyboard->pi w/ 5.3V 2A power supply => 4.85V min 4.89V mean 4.95V max, Network OK
(I logged out of LXDE to change to the powered hub)
-mouse+keyboard->powered hub->pi w/ 5.3V 2A power supply => 4.91V min 4.96V mean 5.00V max, Network DROPS
-unplug hub - network returns

The result with the mouse+keyboard directly attached to the Pi is different with GPM from last time, but consistent with the LXDE result.

As a final test of the possibility of any power supply issues in the previous testing I have done:
-LXDE running, dual USB->PS2 adapter with keyboard attached (no mouse) & USB Wireless Mouse Receiver attached to Pi USB ports, 100% CPU load via "stress -c 13" => 4.86V min 4.90V mean 4.95V max, Network WORKS

Paste of todays session dmesg log - http://paste.ubuntu.com/1021879/

Conclusions:
-The HP Touchpad power supply (5.3V/2A) is an excellent choice for the Pi, when paired with a 6ft 24AWG power wire USB cable. It keeps the TP1-TP2 voltage within spec even with multiple USB devices attached and using power, X running, and 100% CPU load
-There is a software issue related to (some? all? unclear as I only have Belkin hubs to test) powered hubs, that interferes with operation of the USB-attached Ethernet power on the Pi. The same issue may possibly manifest with USB-attached wireless adapters (I do not have one to test). Based on GPM triggering the issue, it would appear to be related to the mouse.

So, maybe we can get on with solving this issue?

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jun 4, 2012

I'm continuing to monitor the forums for apparent cases of this issue and am updating the first post of this issue with links to the threads as they appear.

I'm continuing to monitor the forums for apparent cases of this issue and am updating the first post of this issue with links to the threads as they appear.

@NickBT

This comment has been minimized.

Show comment
Hide comment
@NickBT

NickBT Jun 8, 2012

In support of this issue and to raise its profile, I would like to point out that I have similar errors which are related to a wireless dongle failing to connect after LXDE is started. I believe they may have a common cause, so I've cut and pasted some input from me in a couple of threads on the RPi forum.

I've managed to get my pi connected wirelessly with a Belkin FD7050 and the ralink drivers when at the command line. I can ping the BBC website and also ssh into the pi from my PC. I'm powering a Logik keyboard and a mouse from a Logik powered hub. Once I start LXDE with 'startx', I have no network connectivity from the pi and a ping from my PC shows it as unreachable (as is the router itself). When I quit LXDE, I still have no connectivity. LXDE works fine if I connect via the Ethernet cable.

The dmesg output after LXDE is started shows a lot of failed to read/write errors such as

smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118

I can fix it with a kludge of a workaround

A Google search for 'smsc95xx' brings up a few hits, many of them describing behaviour in the Rpi. It's a kernel module and it doesn't seem to like a mixture of high and low speed USB devices on the same hub.

The (fix):
I've got a Belkin wifi dongle, a keyboard, mouse and the recommended Logik powered (2.0A) hub. I've also got a crappy Asda unpowered 4 port hub which I wasn't using until now. Originally I had mouse, kbd, wifi all plugged into the powered hub and the wifi worked until I started LXDE. I then got identical errors to you. The wifi won't run off the Rpi port as there's not enough current capacity by the way.

So mindful of the hint not to mix devices on the same hub I got it going with the following sequence:

  1. Wifi in powered hub in one Rpi USB, Asda hub (NO DEVICES CONECTED) in the other RPi USB, turn on power
  2. Wait till login prompt, plug kbd into Asda hub, log in
  3. Type 'startx', wait for GUI, plug mouse into Asda hub

Browser works and if you quit to the cli, wifi is still up. If you plug the kbd in when you power up, or the mouse before LXDE starts, then you get errors or the wifi connectivity doesn't work. I reckon that two powered hubs, or a low power wifi dongle connected to the Rpi would probably work OK from power up with all device connected

I can confirm that this error is present even after an rpi-update. It also happens with the other lightweight desktop
XFCE. The 5V rail holds up at over 4.85 volts under all conditions tested.

NickBT commented Jun 8, 2012

In support of this issue and to raise its profile, I would like to point out that I have similar errors which are related to a wireless dongle failing to connect after LXDE is started. I believe they may have a common cause, so I've cut and pasted some input from me in a couple of threads on the RPi forum.

I've managed to get my pi connected wirelessly with a Belkin FD7050 and the ralink drivers when at the command line. I can ping the BBC website and also ssh into the pi from my PC. I'm powering a Logik keyboard and a mouse from a Logik powered hub. Once I start LXDE with 'startx', I have no network connectivity from the pi and a ping from my PC shows it as unreachable (as is the router itself). When I quit LXDE, I still have no connectivity. LXDE works fine if I connect via the Ethernet cable.

The dmesg output after LXDE is started shows a lot of failed to read/write errors such as

smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118

I can fix it with a kludge of a workaround

A Google search for 'smsc95xx' brings up a few hits, many of them describing behaviour in the Rpi. It's a kernel module and it doesn't seem to like a mixture of high and low speed USB devices on the same hub.

The (fix):
I've got a Belkin wifi dongle, a keyboard, mouse and the recommended Logik powered (2.0A) hub. I've also got a crappy Asda unpowered 4 port hub which I wasn't using until now. Originally I had mouse, kbd, wifi all plugged into the powered hub and the wifi worked until I started LXDE. I then got identical errors to you. The wifi won't run off the Rpi port as there's not enough current capacity by the way.

So mindful of the hint not to mix devices on the same hub I got it going with the following sequence:

  1. Wifi in powered hub in one Rpi USB, Asda hub (NO DEVICES CONECTED) in the other RPi USB, turn on power
  2. Wait till login prompt, plug kbd into Asda hub, log in
  3. Type 'startx', wait for GUI, plug mouse into Asda hub

Browser works and if you quit to the cli, wifi is still up. If you plug the kbd in when you power up, or the mouse before LXDE starts, then you get errors or the wifi connectivity doesn't work. I reckon that two powered hubs, or a low power wifi dongle connected to the Rpi would probably work OK from power up with all device connected

I can confirm that this error is present even after an rpi-update. It also happens with the other lightweight desktop
XFCE. The 5V rail holds up at over 4.85 volts under all conditions tested.

@jstsch

This comment has been minimized.

Show comment
Hide comment
@jstsch

jstsch Jun 10, 2012

Similar issues here. Also without running X. Setup:

  • Pi with the RS Electronics Micro USB Euro power supply
  • Belkin 7-Port USB hub
  • Logitech Pilot Mouse and Logitech K120 keyboard
  • TP-Link TL WN821N USB Wireless N Dongle

Using just the keyboard and mouse, with or without the hub gives no issues. When the wireless dongle is plugged in I get errors such as:

smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
Jun 9 15:05:23 raspberrypi kernel: DEBUG:handle_hc_chhltd_intr_dma:: XactErr without NYET/NAK/ACK
Jun 9 15:05:23 raspberrypi kernel: hub 1-1.2:1.0: hub_port_status failed (err = -71)
Jun 9 15:05:23 raspberrypi kernel: hub 1-1.2:1.0: Cannot enable port 4. Maybe the USB cable is bad?
Jan 1 01:07:55 raspberrypi kernel: INFO:: periodic_channel_available: Total channels: 8, Periodic: 4, Non-periodic: 4
Jan 1 01:07:55 raspberrypi kernel: INFO:: schedule_periodic: No host channel available for periodic transfer.
Jan 1 01:07:55 raspberrypi kernel: ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
Jan 1 01:07:55 raspberrypi kernel: usb 1-1.3.3: reset low speed USB device number 5 using dwc_otg

Last night everything was working. Had everything plugged into the hub. Browsing using Midori over the wireless connection. This morning the Pi had crashed (nothing on the screen). Booting with everything plugged in gave me a kernel panic just now after a stream of similar error messages.

Hopefully some useful information in here!

jstsch commented Jun 10, 2012

Similar issues here. Also without running X. Setup:

  • Pi with the RS Electronics Micro USB Euro power supply
  • Belkin 7-Port USB hub
  • Logitech Pilot Mouse and Logitech K120 keyboard
  • TP-Link TL WN821N USB Wireless N Dongle

Using just the keyboard and mouse, with or without the hub gives no issues. When the wireless dongle is plugged in I get errors such as:

smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
Jun 9 15:05:23 raspberrypi kernel: DEBUG:handle_hc_chhltd_intr_dma:: XactErr without NYET/NAK/ACK
Jun 9 15:05:23 raspberrypi kernel: hub 1-1.2:1.0: hub_port_status failed (err = -71)
Jun 9 15:05:23 raspberrypi kernel: hub 1-1.2:1.0: Cannot enable port 4. Maybe the USB cable is bad?
Jan 1 01:07:55 raspberrypi kernel: INFO:: periodic_channel_available: Total channels: 8, Periodic: 4, Non-periodic: 4
Jan 1 01:07:55 raspberrypi kernel: INFO:: schedule_periodic: No host channel available for periodic transfer.
Jan 1 01:07:55 raspberrypi kernel: ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
Jan 1 01:07:55 raspberrypi kernel: usb 1-1.3.3: reset low speed USB device number 5 using dwc_otg

Last night everything was working. Had everything plugged into the hub. Browsing using Midori over the wireless connection. This morning the Pi had crashed (nothing on the screen). Booting with everything plugged in gave me a kernel panic just now after a stream of similar error messages.

Hopefully some useful information in here!

@jstsch

This comment has been minimized.

Show comment
Hide comment
@jstsch

jstsch Jun 10, 2012

Some more:

Jun 9 23:16:39 raspberrypi kernel: mmc0: missed completion of cmd 17 DMA (512/512 [1]/[1]) - ignoring it
Jun 9 23:16:39 raspberrypi kernel: mmc0: DMA IRQ 6 ignored - results were reset
Jun 9 23:16:39 raspberrypi kernel: mmc0: missed completion of cmd 17 DMA (512/512 [1]/[1]) - ignoring it
Jun 9 23:16:39 raspberrypi kernel: mmc0: DMA IRQ 6 ignored - results were reset

Upon pluggin in the wireless dongle:

Jun 10 00:43:00 raspberrypi kernel: usb 1-1.3.6: new high speed USB device number 9 using dwc_otg
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: New USB device found, idVendor=0cf3, idProduct=7015
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: New USB device strings: Mfr=16, Product=32, SerialNumber=48
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: Product: USB WLAN
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: Manufacturer: ATHEROS
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: SerialNumber: 12345
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: ath9k_htc: Transferred FW: htc_7010.fw, size: 72992
Jun 10 00:43:02 raspberrypi kernel: usb 1-1.3.6: Service connection timeout for: 256
Jun 10 00:43:02 raspberrypi kernel: ath9k_htc 1-1.3.6:1.0: ath9k_htc: Unable to initialize HTC services
Jun 10 00:43:02 raspberrypi kernel: Failed to initialize the device
Jun 10 00:43:02 raspberrypi kernel: ath9k_htc: probe of 1-1.3.6:1.0 failed with error -22

jstsch commented Jun 10, 2012

Some more:

Jun 9 23:16:39 raspberrypi kernel: mmc0: missed completion of cmd 17 DMA (512/512 [1]/[1]) - ignoring it
Jun 9 23:16:39 raspberrypi kernel: mmc0: DMA IRQ 6 ignored - results were reset
Jun 9 23:16:39 raspberrypi kernel: mmc0: missed completion of cmd 17 DMA (512/512 [1]/[1]) - ignoring it
Jun 9 23:16:39 raspberrypi kernel: mmc0: DMA IRQ 6 ignored - results were reset

Upon pluggin in the wireless dongle:

Jun 10 00:43:00 raspberrypi kernel: usb 1-1.3.6: new high speed USB device number 9 using dwc_otg
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: New USB device found, idVendor=0cf3, idProduct=7015
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: New USB device strings: Mfr=16, Product=32, SerialNumber=48
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: Product: USB WLAN
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: Manufacturer: ATHEROS
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: SerialNumber: 12345
Jun 10 00:43:01 raspberrypi kernel: usb 1-1.3.6: ath9k_htc: Transferred FW: htc_7010.fw, size: 72992
Jun 10 00:43:02 raspberrypi kernel: usb 1-1.3.6: Service connection timeout for: 256
Jun 10 00:43:02 raspberrypi kernel: ath9k_htc 1-1.3.6:1.0: ath9k_htc: Unable to initialize HTC services
Jun 10 00:43:02 raspberrypi kernel: Failed to initialize the device
Jun 10 00:43:02 raspberrypi kernel: ath9k_htc: probe of 1-1.3.6:1.0 failed with error -22

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jun 11, 2012

I also was able to observe the issue in Arch Linux with their custom kernel.

However, changing mice seems to have semi-resolved my immediate issue. I went from a Logitech Wireless to a "Monoprice special" wired optical mouse.

That Logitech mouse has worked fine on multiple computers with several Linux distributions, Windows XP, and Windows 7 for the last ~4 years. It should work fine with a powered hub on the Pi. Based on the many, many other threads on issues with USB devices on this forum, I think it comes down to the USB driver provided by the company that made the USB IP core that Broadcom bought for the Pi's SoC just sucking, and until someone rewrites a complete new USB driver we will continue to have these types of issues.

It's unfortunate because with these kinds of issues, the Pi doesn't really meet the as-advertised "plug in whatever USB keyboard/mouse/hub you have in the house and start coding" that has been put forth by the Foundation for the last 6 months.

I will by trying to add an Arduino Uno and Open Bench Logic Sniffer to the same powered USB hub soon, to test out using the Pi as a low-cost host computer for open source hardware tools. I'll report back on what happens when those devices are added...

I also was able to observe the issue in Arch Linux with their custom kernel.

However, changing mice seems to have semi-resolved my immediate issue. I went from a Logitech Wireless to a "Monoprice special" wired optical mouse.

That Logitech mouse has worked fine on multiple computers with several Linux distributions, Windows XP, and Windows 7 for the last ~4 years. It should work fine with a powered hub on the Pi. Based on the many, many other threads on issues with USB devices on this forum, I think it comes down to the USB driver provided by the company that made the USB IP core that Broadcom bought for the Pi's SoC just sucking, and until someone rewrites a complete new USB driver we will continue to have these types of issues.

It's unfortunate because with these kinds of issues, the Pi doesn't really meet the as-advertised "plug in whatever USB keyboard/mouse/hub you have in the house and start coding" that has been put forth by the Foundation for the last 6 months.

I will by trying to add an Arduino Uno and Open Bench Logic Sniffer to the same powered USB hub soon, to test out using the Pi as a low-cost host computer for open source hardware tools. I'll report back on what happens when those devices are added...

@NickBT

This comment has been minimized.

Show comment
Hide comment
@NickBT

NickBT Jun 11, 2012

I've done some investigation into what fails when I startx and one of the peripherals plugged into the powered hub fails.
I did a fairly rough and ready hack to find out where the first error that I can locate is. I altered dwc_otg_hcd_queue.c's function

static int periodic_channel_available(dwc_otg_hcd_t * hcd)
{
/*
* Currently assuming that there is a dedicated host channnel for each
* periodic transaction plus at least one host channel for
* non-periodic transactions.
*/
int status;
int num_channels;

num_channels = hcd->core_if->core_params->host_channels;
if ((hcd->periodic_channels + hcd->non_periodic_channels < num_channels) &&
    (hcd->periodic_channels < num_channels - 1)) {
    status = 0;
} else {
    //DWC_INFO("%s: Total channels: %d, Periodic: %d, Non-periodic: %d\n",
    //  __func__, num_channels, hcd->periodic_channels, hcd->non_periodic_channels);    //NOTICE
    DWC_ERROR("%s: NBT Total channels: %d, Periodic: %d, Non-periodic: %d\n",
        __func__, num_channels, hcd->periodic_channels, hcd->non_periodic_channels);    //NOTICE
    status = -DWC_E_NO_SPACE;
}

return status;

}

(The 'NBT' is my marker for grepping)

When it fails it gives error in dmesg:

smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
ERROR::periodic_channel_available:342: periodic_channel_available: NBT Total channels: 8, Periodic: 5, Non-periodic: 3

Leaving aside that I may have given func as an incorrect argument to DWC_ERROR, we can see that the first condition will fail,as 5 + 3 is not less than 8.

I hope this sheds some light on the matter.

P.S. the dmesg output is crammed full of such messages after the failure
P.P.S - sorry if this doesn't format right.

NickBT commented Jun 11, 2012

I've done some investigation into what fails when I startx and one of the peripherals plugged into the powered hub fails.
I did a fairly rough and ready hack to find out where the first error that I can locate is. I altered dwc_otg_hcd_queue.c's function

static int periodic_channel_available(dwc_otg_hcd_t * hcd)
{
/*
* Currently assuming that there is a dedicated host channnel for each
* periodic transaction plus at least one host channel for
* non-periodic transactions.
*/
int status;
int num_channels;

num_channels = hcd->core_if->core_params->host_channels;
if ((hcd->periodic_channels + hcd->non_periodic_channels < num_channels) &&
    (hcd->periodic_channels < num_channels - 1)) {
    status = 0;
} else {
    //DWC_INFO("%s: Total channels: %d, Periodic: %d, Non-periodic: %d\n",
    //  __func__, num_channels, hcd->periodic_channels, hcd->non_periodic_channels);    //NOTICE
    DWC_ERROR("%s: NBT Total channels: %d, Periodic: %d, Non-periodic: %d\n",
        __func__, num_channels, hcd->periodic_channels, hcd->non_periodic_channels);    //NOTICE
    status = -DWC_E_NO_SPACE;
}

return status;

}

(The 'NBT' is my marker for grepping)

When it fails it gives error in dmesg:

smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
ERROR::periodic_channel_available:342: periodic_channel_available: NBT Total channels: 8, Periodic: 5, Non-periodic: 3

Leaving aside that I may have given func as an incorrect argument to DWC_ERROR, we can see that the first condition will fail,as 5 + 3 is not less than 8.

I hope this sheds some light on the matter.

P.S. the dmesg output is crammed full of such messages after the failure
P.P.S - sorry if this doesn't format right.

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@guisacouto

This comment has been minimized.

Show comment
Hide comment
@guisacouto

guisacouto Jun 21, 2012

I wouldn't be surprise if this had something to do with issue 9. My guess is that when you startx you start opening and reading a lot of files into memory, and there is where the problem is. Very I/O causes issues, and not the 100% CPU for itself.

If you combine high CPU usage with some sort of high usb usage (rather it is the ethernet using the usb bus, wifi, or usb storage) that generates a lot of I/0 opening, writing, and reading files that is what causes all this issues I think

I wouldn't be surprise if this had something to do with issue 9. My guess is that when you startx you start opening and reading a lot of files into memory, and there is where the problem is. Very I/O causes issues, and not the 100% CPU for itself.

If you combine high CPU usage with some sort of high usb usage (rather it is the ethernet using the usb bus, wifi, or usb storage) that generates a lot of I/0 opening, writing, and reading files that is what causes all this issues I think

@XECDesign

This comment has been minimized.

Show comment
Hide comment
@XECDesign

XECDesign Jun 21, 2012

Contributor

@guisacouto

starting x is not a requirement to replicate this. starting gpm (which wouldn't affect IO much) also.

usb interrupts is something that might be worth looking into.

Contributor

XECDesign commented Jun 21, 2012

@guisacouto

starting x is not a requirement to replicate this. starting gpm (which wouldn't affect IO much) also.

usb interrupts is something that might be worth looking into.

@guisacouto

This comment has been minimized.

Show comment
Hide comment
@guisacouto

guisacouto Jun 21, 2012

That skipped me. Then yes.. I guess it's all about usb interrupts. What bothers me is that there is a lot of people reporting this kind of problems, but I don't see updates on the repos to try solve this.. it always ends with a 'it must be a power supply issue' or something. I hope this gets more attention soon

That skipped me. Then yes.. I guess it's all about usb interrupts. What bothers me is that there is a lot of people reporting this kind of problems, but I don't see updates on the repos to try solve this.. it always ends with a 'it must be a power supply issue' or something. I hope this gets more attention soon

@jstsch

This comment has been minimized.

Show comment
Hide comment
@jstsch

jstsch Jun 21, 2012

Dito. Right now I am recommending people to wait getting a R-Pi until these issues are resolved. I wrote a short review the other day: http://jstsch.com/post/24_hours_with_the_raspberry_pi

jstsch commented Jun 21, 2012

Dito. Right now I am recommending people to wait getting a R-Pi until these issues are resolved. I wrote a short review the other day: http://jstsch.com/post/24_hours_with_the_raspberry_pi

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jun 22, 2012

Another case - http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=9077&p=106318#p106318

User bought a hub listed in the "verified peripherals" section of the Wiki...

Another case - http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=9077&p=106318#p106318

User bought a hub listed in the "verified peripherals" section of the Wiki...

@fbutler

This comment has been minimized.

Show comment
Hide comment
@fbutler

fbutler Jun 22, 2012

I'm seeing the same type of issue with a Logitech Di Novo Edge keyboard without running startx. I get variations of the same type of errors whether the device is plugged in at boot time or plugged in after booting has completed.

My Setup is:

Wheezy beta distro fully updated
A logilink 10 port powered hub
A USB Y cable powering the Pi from the Logilink hub
Voltage across TP1 and TP2 is 4.91V
Additional USB cable between the hub and the Pi with the red wire snipped to prevent back powering to the Pi
Logitech wireless adapter (Part Number 832243-0000) plugged into hub
Keyboard Part Number YRAY-81
No other USB devices plugged in

Here is a portion of the dmesg output from the point when the device is detected:

[ 940.096845] usb 1-1.2: new full speed USB device number 12 using dwc_otg
[ 940.200190] usb 1-1.2: New USB device found, idVendor=046d, idProduct=0b04
[ 940.200237] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 940.200259] usb 1-1.2: Product: Logitech BT Mini-Receiver
[ 940.200275] usb 1-1.2: Manufacturer: Logitech
[ 940.207521] hub 1-1.2:1.0: USB hub found
[ 940.207888] hub 1-1.2:1.0: 3 ports detected
[ 940.486952] usb 1-1.2.2: new full speed USB device number 13 using dwc_otg
[ 940.595807] usb 1-1.2.2: New USB device found, idVendor=046d, idProduct=c713
[ 940.595864] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 940.595889] usb 1-1.2.2: Product: Logitech BT Mini-Receiver
[ 940.595907] usb 1-1.2.2: Manufacturer: Logitech
[ 940.595924] usb 1-1.2.2: SerialNumber: 001F2039B887
[ 940.615500] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.2/1-1.2.2:1.0/input/input4
[ 940.618982] generic-usb 0003:046D:C713.0005: input: USB HID v1.11 Keyboard [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.2/input0
[ 940.707062] usb 1-1.2.3: new full speed USB device number 14 using dwc_otg
[ 940.815761] usb 1-1.2.3: New USB device found, idVendor=046d, idProduct=c714
[ 940.815799] usb 1-1.2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 940.815821] usb 1-1.2.3: Product: Logitech BT Mini-Receiver
[ 940.815852] usb 1-1.2.3: Manufacturer: Logitech
[ 940.815870] usb 1-1.2.3: SerialNumber: 001F2039B887
[ 940.849750] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.3/1-1.2.3:1.0/input/input5
[ 940.854898] logitech 0003:046D:C714.0006: input,hiddev0: USB HID v1.11 Mouse [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.3/input0
[ 945.923909] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 946.256616] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 946.256665] smsc95xx 1-1.1:1.0: eth0: MII is busy in smsc95xx_mdio_read
[ 951.248243] usb 1-1.2.2: USB disconnect, device number 13
[ 951.255861] usb 1-1.2.3: USB disconnect, device number 14
[ 951.346828] usb 1-1.2: reset full speed USB device number 12 using dwc_otg
[ 951.746821] usb 1-1.2.2: new full speed USB device number 15 using dwc_otg
[ 951.855081] usb 1-1.2.2: New USB device found, idVendor=046d, idProduct=c713
[ 951.855133] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 951.855155] usb 1-1.2.2: Product: Logitech BT Mini-Receiver
[ 951.855174] usb 1-1.2.2: Manufacturer: Logitech
[ 951.855190] usb 1-1.2.2: SerialNumber: 001F2039B887
[ 951.875358] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.2/1-1.2.2:1.0/input/input6
[ 951.879026] generic-usb 0003:046D:C713.0007: input: USB HID v1.11 Keyboard [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.2/input0
[ 951.966973] usb 1-1.2.3: new full speed USB device number 16 using dwc_otg
[ 952.075734] usb 1-1.2.3: New USB device found, idVendor=046d, idProduct=c714
[ 952.075783] usb 1-1.2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 952.075806] usb 1-1.2.3: Product: Logitech BT Mini-Receiver
[ 952.075823] usb 1-1.2.3: Manufacturer: Logitech
[ 952.075840] usb 1-1.2.3: SerialNumber: 001F2039B887
[ 952.103900] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.3/1-1.2.3:1.0/input/input7
[ 952.111451] logitech 0003:046D:C714.0008: input,hiddev0: USB HID v1.11 Mouse [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.3/input0
[ 957.106472] hub 1-1:1.0: hub_port_status failed (err = -110)
[ 957.246478] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 962.676429] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 966.206348] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 967.676337] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 971.206295] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 972.676267] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 977.306200] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 977.676223] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 982.306165] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 982.676153] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 991.286029] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 991.286066] hub 1-1.2:1.0: connect-debounce failed, port 1 disabled
[ 996.245957] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 996.285980] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 1001.245917] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1006.245838] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 1011.245784] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1020.475652] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1020.475703] smsc95xx 1-1.1:1.0: eth0: MII is busy in smsc95xx_mdio_read
[ 1025.475568] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1025.475618] smsc95xx 1-1.1:1.0: eth0: MII is busy in smsc95xx_mdio_read
[ 1029.401439] usb 1-1.2.2: USB disconnect, device number 15
[ 1029.414868] usb 1-1.2.3: USB disconnect, device number 16
[ 1029.515768] usb 1-1.2: reset full speed USB device number 12 using dwc_otg
[ 1029.915780] usb 1-1.2.1: new full speed USB device number 17 using dwc_otg
[ 1030.021981] usb 1-1.2.1: New USB device found, idVendor=046d, idProduct=c709
[ 1030.022018] usb 1-1.2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1030.022040] usb 1-1.2.1: Product: Logitech BT Mini-Receiver
[ 1030.022057] usb 1-1.2.1: Manufacturer: Logitech
[ 1030.022085] usb 1-1.2.1: SerialNumber: 001F2039B887
[ 1030.136063] usb 1-1.2.2: new full speed USB device number 18 using dwc_otg
[ 1030.247815] usb 1-1.2.2: New USB device found, idVendor=046d, idProduct=c713
[ 1030.247878] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1030.247923] usb 1-1.2.2: Product: Logitech BT Mini-Receiver
[ 1030.247968] usb 1-1.2.2: Manufacturer: Logitech
[ 1030.248008] usb 1-1.2.2: SerialNumber: 001F2039B887
[ 1030.286157] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.2/1-1.2.2:1.0/input/input8
[ 1030.286316] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.286330]
[ 1030.286346] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 1030.286358]
[ 1030.286378] ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
[ 1030.286391]
[ 1030.287573] generic-usb 0003:046D:C713.0009: input: USB HID v1.11 Keyboard [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.2/input0
[ 1030.305539] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.305557]
[ 1030.305581] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 1030.305594]
[ 1030.305616] ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
[ 1030.305629]
[ 1030.335596] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.335614]
[ 1030.335638] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 1030.335650]
[ 1030.335671] ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
[ 1030.335684]
[ 1030.366111] usb 1-1.2.3: new full speed USB device number 19 using dwc_otg
[ 1030.395543] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.395561]
[ 1030.395584] INFO:: schedule_periodic: No host channel available for periodic transfer.

fbutler commented Jun 22, 2012

I'm seeing the same type of issue with a Logitech Di Novo Edge keyboard without running startx. I get variations of the same type of errors whether the device is plugged in at boot time or plugged in after booting has completed.

My Setup is:

Wheezy beta distro fully updated
A logilink 10 port powered hub
A USB Y cable powering the Pi from the Logilink hub
Voltage across TP1 and TP2 is 4.91V
Additional USB cable between the hub and the Pi with the red wire snipped to prevent back powering to the Pi
Logitech wireless adapter (Part Number 832243-0000) plugged into hub
Keyboard Part Number YRAY-81
No other USB devices plugged in

Here is a portion of the dmesg output from the point when the device is detected:

[ 940.096845] usb 1-1.2: new full speed USB device number 12 using dwc_otg
[ 940.200190] usb 1-1.2: New USB device found, idVendor=046d, idProduct=0b04
[ 940.200237] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 940.200259] usb 1-1.2: Product: Logitech BT Mini-Receiver
[ 940.200275] usb 1-1.2: Manufacturer: Logitech
[ 940.207521] hub 1-1.2:1.0: USB hub found
[ 940.207888] hub 1-1.2:1.0: 3 ports detected
[ 940.486952] usb 1-1.2.2: new full speed USB device number 13 using dwc_otg
[ 940.595807] usb 1-1.2.2: New USB device found, idVendor=046d, idProduct=c713
[ 940.595864] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 940.595889] usb 1-1.2.2: Product: Logitech BT Mini-Receiver
[ 940.595907] usb 1-1.2.2: Manufacturer: Logitech
[ 940.595924] usb 1-1.2.2: SerialNumber: 001F2039B887
[ 940.615500] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.2/1-1.2.2:1.0/input/input4
[ 940.618982] generic-usb 0003:046D:C713.0005: input: USB HID v1.11 Keyboard [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.2/input0
[ 940.707062] usb 1-1.2.3: new full speed USB device number 14 using dwc_otg
[ 940.815761] usb 1-1.2.3: New USB device found, idVendor=046d, idProduct=c714
[ 940.815799] usb 1-1.2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 940.815821] usb 1-1.2.3: Product: Logitech BT Mini-Receiver
[ 940.815852] usb 1-1.2.3: Manufacturer: Logitech
[ 940.815870] usb 1-1.2.3: SerialNumber: 001F2039B887
[ 940.849750] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.3/1-1.2.3:1.0/input/input5
[ 940.854898] logitech 0003:046D:C714.0006: input,hiddev0: USB HID v1.11 Mouse [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.3/input0
[ 945.923909] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 946.256616] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 946.256665] smsc95xx 1-1.1:1.0: eth0: MII is busy in smsc95xx_mdio_read
[ 951.248243] usb 1-1.2.2: USB disconnect, device number 13
[ 951.255861] usb 1-1.2.3: USB disconnect, device number 14
[ 951.346828] usb 1-1.2: reset full speed USB device number 12 using dwc_otg
[ 951.746821] usb 1-1.2.2: new full speed USB device number 15 using dwc_otg
[ 951.855081] usb 1-1.2.2: New USB device found, idVendor=046d, idProduct=c713
[ 951.855133] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 951.855155] usb 1-1.2.2: Product: Logitech BT Mini-Receiver
[ 951.855174] usb 1-1.2.2: Manufacturer: Logitech
[ 951.855190] usb 1-1.2.2: SerialNumber: 001F2039B887
[ 951.875358] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.2/1-1.2.2:1.0/input/input6
[ 951.879026] generic-usb 0003:046D:C713.0007: input: USB HID v1.11 Keyboard [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.2/input0
[ 951.966973] usb 1-1.2.3: new full speed USB device number 16 using dwc_otg
[ 952.075734] usb 1-1.2.3: New USB device found, idVendor=046d, idProduct=c714
[ 952.075783] usb 1-1.2.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 952.075806] usb 1-1.2.3: Product: Logitech BT Mini-Receiver
[ 952.075823] usb 1-1.2.3: Manufacturer: Logitech
[ 952.075840] usb 1-1.2.3: SerialNumber: 001F2039B887
[ 952.103900] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.3/1-1.2.3:1.0/input/input7
[ 952.111451] logitech 0003:046D:C714.0008: input,hiddev0: USB HID v1.11 Mouse [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.3/input0
[ 957.106472] hub 1-1:1.0: hub_port_status failed (err = -110)
[ 957.246478] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 962.676429] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 966.206348] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 967.676337] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 971.206295] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 972.676267] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 977.306200] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 977.676223] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 982.306165] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 982.676153] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 991.286029] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 991.286066] hub 1-1.2:1.0: connect-debounce failed, port 1 disabled
[ 996.245957] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 996.285980] hub 1-1.2:1.0: hub_port_status failed (err = -110)
[ 1001.245917] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1006.245838] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 1011.245784] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1020.475652] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1020.475703] smsc95xx 1-1.1:1.0: eth0: MII is busy in smsc95xx_mdio_read
[ 1025.475568] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 1025.475618] smsc95xx 1-1.1:1.0: eth0: MII is busy in smsc95xx_mdio_read
[ 1029.401439] usb 1-1.2.2: USB disconnect, device number 15
[ 1029.414868] usb 1-1.2.3: USB disconnect, device number 16
[ 1029.515768] usb 1-1.2: reset full speed USB device number 12 using dwc_otg
[ 1029.915780] usb 1-1.2.1: new full speed USB device number 17 using dwc_otg
[ 1030.021981] usb 1-1.2.1: New USB device found, idVendor=046d, idProduct=c709
[ 1030.022018] usb 1-1.2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1030.022040] usb 1-1.2.1: Product: Logitech BT Mini-Receiver
[ 1030.022057] usb 1-1.2.1: Manufacturer: Logitech
[ 1030.022085] usb 1-1.2.1: SerialNumber: 001F2039B887
[ 1030.136063] usb 1-1.2.2: new full speed USB device number 18 using dwc_otg
[ 1030.247815] usb 1-1.2.2: New USB device found, idVendor=046d, idProduct=c713
[ 1030.247878] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1030.247923] usb 1-1.2.2: Product: Logitech BT Mini-Receiver
[ 1030.247968] usb 1-1.2.2: Manufacturer: Logitech
[ 1030.248008] usb 1-1.2.2: SerialNumber: 001F2039B887
[ 1030.286157] input: Logitech Logitech BT Mini-Receiver as /devices/platform/bcm2708_usb/usb1/1-1/1-1.2/1-1.2.2/1-1.2.2:1.0/input/input8
[ 1030.286316] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.286330]
[ 1030.286346] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 1030.286358]
[ 1030.286378] ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
[ 1030.286391]
[ 1030.287573] generic-usb 0003:046D:C713.0009: input: USB HID v1.11 Keyboard [Logitech Logitech BT Mini-Receiver] on usb-bcm2708_usb-1.2.2/input0
[ 1030.305539] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.305557]
[ 1030.305581] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 1030.305594]
[ 1030.305616] ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
[ 1030.305629]
[ 1030.335596] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.335614]
[ 1030.335638] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 1030.335650]
[ 1030.335671] ERROR::dwc_otg_hcd_urb_enqueue:487: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
[ 1030.335684]
[ 1030.366111] usb 1-1.2.3: new full speed USB device number 19 using dwc_otg
[ 1030.395543] INFO:: periodic_channel_available: Total channels: 8, Periodic: 6, Non-periodic: 2
[ 1030.395561]
[ 1030.395584] INFO:: schedule_periodic: No host channel available for periodic transfer.

@g4eml

This comment has been minimized.

Show comment
Hide comment
@g4eml

g4eml Jun 22, 2012

I too can confirm that I am seeing similar issues with low speed devices. I initially suspected power problems but have monitored the power with a scope and I am now totally confident that power is not the cause.

If I have two low speed devices plugged into an external hub I almost immediately start getting USB hub and Ethernet failure messages reported with dmesg. The hub cycles on and off repeatedly. Anything attached to the hub works for a few seconds then stops for a few seconds.

I initially saw this with just my keyboard and mouse plugged into the hub. Connecting either the keyboard or the mouse directly to the second port on the Pi and leaving the other device connected to the hub immediately stops the error messages .

Connecting two mice to the hub produces the same errors.

Connecting high speed devices doesn't seem to cause the same problems.

In conclusion it appears that having two low speed devices on an external hub is causing some sort of conflict in the software.

I am pretty sure this has been seen by many people but incorrectly attributed to power problems.

Colin...

g4eml commented Jun 22, 2012

I too can confirm that I am seeing similar issues with low speed devices. I initially suspected power problems but have monitored the power with a scope and I am now totally confident that power is not the cause.

If I have two low speed devices plugged into an external hub I almost immediately start getting USB hub and Ethernet failure messages reported with dmesg. The hub cycles on and off repeatedly. Anything attached to the hub works for a few seconds then stops for a few seconds.

I initially saw this with just my keyboard and mouse plugged into the hub. Connecting either the keyboard or the mouse directly to the second port on the Pi and leaving the other device connected to the hub immediately stops the error messages .

Connecting two mice to the hub produces the same errors.

Connecting high speed devices doesn't seem to cause the same problems.

In conclusion it appears that having two low speed devices on an external hub is causing some sort of conflict in the software.

I am pretty sure this has been seen by many people but incorrectly attributed to power problems.

Colin...

@Pitel

This comment has been minimized.

Show comment
Hide comment
@Pitel

Pitel Jun 26, 2012

I can somehow confirm the previous findings.

I bought Pyramid 7 Port USB 2.0 Hub (powered). I have my wifi dongle connected to it, which is low-speed device. If I also try connecting my mouse, whch is also low-speed, bad things starts to happen.

Pitel commented Jun 26, 2012

I can somehow confirm the previous findings.

I bought Pyramid 7 Port USB 2.0 Hub (powered). I have my wifi dongle connected to it, which is low-speed device. If I also try connecting my mouse, whch is also low-speed, bad things starts to happen.

@mcphail

This comment has been minimized.

Show comment
Hide comment
@mcphail

mcphail Jun 29, 2012

I'm having almost identical problems but don't need to startx to drop eth0. Simply plugging a Huawei e173 modem causes a flood of similar error messages in the logs with frequent disconnection and reconnection of the USB modem. I have a Logitech K260 wireless keyboard and mouse combo. I've tried every combination of power supply and powered or passive USB hubs I can get my hands on. I'm running debian 6 and the latest firmware.

mcphail commented Jun 29, 2012

I'm having almost identical problems but don't need to startx to drop eth0. Simply plugging a Huawei e173 modem causes a flood of similar error messages in the logs with frequent disconnection and reconnection of the USB modem. I have a Logitech K260 wireless keyboard and mouse combo. I've tried every combination of power supply and powered or passive USB hubs I can get my hands on. I'm running debian 6 and the latest firmware.

@popcornmix

This comment has been minimized.

Show comment
Hide comment
@popcornmix

popcornmix Jul 10, 2012

Collaborator

Just an update. We have been looking into various USB issues, and some of the simpler ones have been fixed.
I think the comments in this thread, as usual has a mixture of issues, but one significant one is running out of periodic channels. E.g.
INFO:: schedule_periodic: No host channel available for periodic transfer.

Now, the hardware we have is limited to 8 host channels. Now that sounds like lots, but it turns out the ethernet takes one. The ethernet hub takes one. An external hub takes one. One is reserved for non-periodic transfers.
Some devices have multiple endpoints. E.g. we've seen an Air-Mouse with 4 endpoints.

Currently the driver just has a fixed allocation of host channels, so a mostly idle keyboard permanently consumes a channel.

Take a look at drivers/usb/host/dwc_otg/dwc_otg_hcd_queue.c#periodic_channel_available

https://github.com/raspberrypi/linux/blob/rpi-patches/drivers/usb/host/dwc_otg/dwc_otg_hcd_queue.c#L323

it requires there is one dedicated host channel for each 'periodic' (interrupt or isochronous I think) transaction. This
was actually fixed in the denx tree some time ago:

http://git.denx.de/?p=linux-denx.git;a=commit;h=9796e39e7a513d8a4acde759ec5d0023645143d8

This patch has been incorporated in to the dwc_otg patchset that APM have been trying to get upstream:

http://lkml.indiana.edu/hypermail/linux/kernel/1205.0/01170.html

So, we can see a flaw in the USB driver. And there is a potential solution.
Naren has ported it and we have just started testing. Fingers crossed it helps.

Collaborator

popcornmix commented Jul 10, 2012

Just an update. We have been looking into various USB issues, and some of the simpler ones have been fixed.
I think the comments in this thread, as usual has a mixture of issues, but one significant one is running out of periodic channels. E.g.
INFO:: schedule_periodic: No host channel available for periodic transfer.

Now, the hardware we have is limited to 8 host channels. Now that sounds like lots, but it turns out the ethernet takes one. The ethernet hub takes one. An external hub takes one. One is reserved for non-periodic transfers.
Some devices have multiple endpoints. E.g. we've seen an Air-Mouse with 4 endpoints.

Currently the driver just has a fixed allocation of host channels, so a mostly idle keyboard permanently consumes a channel.

Take a look at drivers/usb/host/dwc_otg/dwc_otg_hcd_queue.c#periodic_channel_available

https://github.com/raspberrypi/linux/blob/rpi-patches/drivers/usb/host/dwc_otg/dwc_otg_hcd_queue.c#L323

it requires there is one dedicated host channel for each 'periodic' (interrupt or isochronous I think) transaction. This
was actually fixed in the denx tree some time ago:

http://git.denx.de/?p=linux-denx.git;a=commit;h=9796e39e7a513d8a4acde759ec5d0023645143d8

This patch has been incorporated in to the dwc_otg patchset that APM have been trying to get upstream:

http://lkml.indiana.edu/hypermail/linux/kernel/1205.0/01170.html

So, we can see a flaw in the USB driver. And there is a potential solution.
Naren has ported it and we have just started testing. Fingers crossed it helps.

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jul 10, 2012

I'm willing to help, is there a place where I can get Naren's version of the patch and apply it to a custom compiled kernel, or a testing kernel image that includes the patch already?

Unfortunately my old patebins have expired, but it's likely I have been seeing the out of channels error just before all of the many repeated kevent 4 errors and failed to read register errors.

I'm willing to help, is there a place where I can get Naren's version of the patch and apply it to a custom compiled kernel, or a testing kernel image that includes the patch already?

Unfortunately my old patebins have expired, but it's likely I have been seeing the out of channels error just before all of the many repeated kevent 4 errors and failed to read register errors.

@popcornmix

This comment has been minimized.

Show comment
Hide comment
@popcornmix

popcornmix Jul 10, 2012

Collaborator

Well, I wouldn't recommend this to people who want a more stable system, as it has had very limited testing.
But if you want to help with testing, then try this:
https://dl.dropbox.com/u/3669512/temp/0001-added-microframe-schedule-from-the-linux-denx-tree.dc4.patch

It will probably only help if you were getting this error:
"schedule_periodic: No host channel available for periodic transfer"

But, try the patch. Report anything that used to work and now doesn't, or anything that didn't work and now does.

Collaborator

popcornmix commented Jul 10, 2012

Well, I wouldn't recommend this to people who want a more stable system, as it has had very limited testing.
But if you want to help with testing, then try this:
https://dl.dropbox.com/u/3669512/temp/0001-added-microframe-schedule-from-the-linux-denx-tree.dc4.patch

It will probably only help if you were getting this error:
"schedule_periodic: No host channel available for periodic transfer"

But, try the patch. Report anything that used to work and now doesn't, or anything that didn't work and now does.

@NickBT

This comment has been minimized.

Show comment
Hide comment
@NickBT

NickBT Jul 10, 2012

I've just applied this patch to a newly cloned kernel. For the first time ever I can get wifi dongle, keyboard, mouse all working in LXDE. It has wifi network connectivity through the browser. IT WORKS - no fail r/w on index 114 or 118 or failure to enque error messages. That's the good news! The bad news is that pinging bbc.co.uk from a terminal in the GUI gives 35% packet loss. It's a definite improvement from my point of view, well done.
Update : bit more bad news, I quit the GUI back to the command line and I can't even ping the router at 192.168.1.1. - host unreachable

NickBT commented Jul 10, 2012

I've just applied this patch to a newly cloned kernel. For the first time ever I can get wifi dongle, keyboard, mouse all working in LXDE. It has wifi network connectivity through the browser. IT WORKS - no fail r/w on index 114 or 118 or failure to enque error messages. That's the good news! The bad news is that pinging bbc.co.uk from a terminal in the GUI gives 35% packet loss. It's a definite improvement from my point of view, well done.
Update : bit more bad news, I quit the GUI back to the command line and I can't even ping the router at 192.168.1.1. - host unreachable

@popcornmix popcornmix referenced this issue Jul 11, 2012

Closed

Usb problem #51

@marsman2020

This comment has been minimized.

Show comment
Hide comment
@marsman2020

marsman2020 Jul 16, 2012

I cloned the 3.1.19 raspberry-pi branch and applied this patch. Tested with a Raspbian installation, fully updated with rpi-update and apt-get dist-upgrade.

I have satellite internet. Test on Linux Mint Debian Edition on an x86 latop:
-Ping = 8-10% packet loss

Test results with the stock unpatched 7/14 kernel:
-With no mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 8%-14% packet loss, ping LAN = 0% packet loss.
-With mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 8%-16% packet loss, ping LAN = % packet loss.
-With mouse, in X windows - wget test from local LAN - fails, ping 8.8.8.8 and LAN = extreme packet loss.

Tests results with the patched 7/14 kernel:
-With no mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 8%-14% packet loss, LAN = 0% packet loss.
-With mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 12% packet loss, LAN = 0% packet loss.
-With mouse, in X windows - wget test from local LAN - fails, ping 8.8.8.8 = 10-20% packet loss, LAN = 0% packet loss.

I'm going to run the patched kernel in IRC overnight and see if it's stable... But I haven't seen the downsides that NickBT did.... The packet loss seems to be due to my internet connection, since even the x86 machine has it.

I cloned the 3.1.19 raspberry-pi branch and applied this patch. Tested with a Raspbian installation, fully updated with rpi-update and apt-get dist-upgrade.

I have satellite internet. Test on Linux Mint Debian Edition on an x86 latop:
-Ping = 8-10% packet loss

Test results with the stock unpatched 7/14 kernel:
-With no mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 8%-14% packet loss, ping LAN = 0% packet loss.
-With mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 8%-16% packet loss, ping LAN = % packet loss.
-With mouse, in X windows - wget test from local LAN - fails, ping 8.8.8.8 and LAN = extreme packet loss.

Tests results with the patched 7/14 kernel:
-With no mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 8%-14% packet loss, LAN = 0% packet loss.
-With mouse, at command line - wget test from local LAN ok, ping 8.8.8.8 = 12% packet loss, LAN = 0% packet loss.
-With mouse, in X windows - wget test from local LAN - fails, ping 8.8.8.8 = 10-20% packet loss, LAN = 0% packet loss.

I'm going to run the patched kernel in IRC overnight and see if it's stable... But I haven't seen the downsides that NickBT did.... The packet loss seems to be due to my internet connection, since even the x86 machine has it.

@mchr3k

This comment has been minimized.

Show comment
Hide comment
@mchr3k

mchr3k Jul 16, 2012

I have also hit this issue: http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=10496&p=124750#p124750

I get "schedule_periodic: No host channel available for periodic transfer." when I plug in my webcam while I already have my USB wifi + USB keyboard/mouse plugged in. These are all plugged into a powered USB hub.

mchr3k commented Jul 16, 2012

I have also hit this issue: http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=10496&p=124750#p124750

I get "schedule_periodic: No host channel available for periodic transfer." when I plug in my webcam while I already have my USB wifi + USB keyboard/mouse plugged in. These are all plugged into a powered USB hub.

@davr

This comment has been minimized.

Show comment
Hide comment
@davr

davr Jul 26, 2012

I have the same problem, when I plug in an arduino, USB-Serial adaptor, and a USB webcam, via a powered USB hub. Whenever I try to access the webcam, I get the following erors:

Jul 25 18:30:59 raspberrypi kernel: [ 1207.331697] INFO:: periodic_channel_available: Total channels: 8, Periodic: 5, Non-periodic: 3
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331716]
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331741] INFO:: schedule_periodic: No host channel available for periodic transfer.
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331754]
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331842] ERROR::dwc_otg_hcd_urb_enqueue:518: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331856]
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331940] uvcvideo: Failed to submit URB 0 (-4008).

davr commented Jul 26, 2012

I have the same problem, when I plug in an arduino, USB-Serial adaptor, and a USB webcam, via a powered USB hub. Whenever I try to access the webcam, I get the following erors:

Jul 25 18:30:59 raspberrypi kernel: [ 1207.331697] INFO:: periodic_channel_available: Total channels: 8, Periodic: 5, Non-periodic: 3
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331716]
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331741] INFO:: schedule_periodic: No host channel available for periodic transfer.
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331754]
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331842] ERROR::dwc_otg_hcd_urb_enqueue:518: DWC OTG HCD URB Enqueue failed adding QTD. Error status -4008
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331856]
Jul 25 18:30:59 raspberrypi kernel: [ 1207.331940] uvcvideo: Failed to submit URB 0 (-4008).

@vmp32k

This comment has been minimized.

Show comment
Hide comment
@vmp32k

vmp32k Jul 30, 2012

I can confirm that popcornmix's patch, applied on a freshly pulled raspberrypi/linux tree, works.
I no longer get the schedule_periodic/periodic_channel_available messages though I have noticed, that enabling the SOF_reduction makes the keyboard/mouse (and potentially others) very unstable [see lines 2-29 of log below].

Syslog: http://pastebin.com/P8tJ5nzZ

Also, every now and then my mouse stopped working for a second or two and then resumed [see lines 30-38, 101-108 of log above].
And I have no idea if that memory allocation error [see line 44] is related to this patch or not, it didn't seem to have any lasting effect as apt-get completed cleanly.

I can't confirm any packet loss, I left a ping running while doing some resource intensive X stuff (opening chromium, browsing around while installing packages, system load was around 7.00 due to swapping) and only 4 out of ~4000 pings were lost; considering this ran via wireless, I don't seem to have the issue NickBT reported. :)

I'm running 3 devices off a powered USB hub connected to the RPi: Mouse, keyboard, Zyxel zd1211rw Wireless Adapter.

If you have any more patches that need testing or need more debugging info, let me know. :)

vmp32k commented Jul 30, 2012

I can confirm that popcornmix's patch, applied on a freshly pulled raspberrypi/linux tree, works.
I no longer get the schedule_periodic/periodic_channel_available messages though I have noticed, that enabling the SOF_reduction makes the keyboard/mouse (and potentially others) very unstable [see lines 2-29 of log below].

Syslog: http://pastebin.com/P8tJ5nzZ

Also, every now and then my mouse stopped working for a second or two and then resumed [see lines 30-38, 101-108 of log above].
And I have no idea if that memory allocation error [see line 44] is related to this patch or not, it didn't seem to have any lasting effect as apt-get completed cleanly.

I can't confirm any packet loss, I left a ping running while doing some resource intensive X stuff (opening chromium, browsing around while installing packages, system load was around 7.00 due to swapping) and only 4 out of ~4000 pings were lost; considering this ran via wireless, I don't seem to have the issue NickBT reported. :)

I'm running 3 devices off a powered USB hub connected to the RPi: Mouse, keyboard, Zyxel zd1211rw Wireless Adapter.

If you have any more patches that need testing or need more debugging info, let me know. :)

@andreasjhkarlsson

This comment has been minimized.

Show comment
Hide comment
@andreasjhkarlsson

andreasjhkarlsson Aug 4, 2012

I tried popcornmix's patch as well and the initial reaction was that it fixed my problems (My problems are described at the rpi forums: http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=12949).

However after more extensive testing (taking snapshots with the webcam and sending it over the network for several hours) the problems reappear although with the following errors:

Aug 4 16:57:04 bengt kernel: uvcvideo: Failed to resubmit video URB (-1).
Aug 4 16:59:05 bengt kernel: wlan0: deauthenticated from 4c:e6:76:c4:55:84 (Reason: 2)

I guess the time difference between the fail entries is due to some timeout for the wifi.

I guess that this could be another problem, however my feeling is that the patch doesn't go after the root cause of these problems but rather the symptoms.

I tried popcornmix's patch as well and the initial reaction was that it fixed my problems (My problems are described at the rpi forums: http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=12949).

However after more extensive testing (taking snapshots with the webcam and sending it over the network for several hours) the problems reappear although with the following errors:

Aug 4 16:57:04 bengt kernel: uvcvideo: Failed to resubmit video URB (-1).
Aug 4 16:59:05 bengt kernel: wlan0: deauthenticated from 4c:e6:76:c4:55:84 (Reason: 2)

I guess the time difference between the fail entries is due to some timeout for the wifi.

I guess that this could be another problem, however my feeling is that the patch doesn't go after the root cause of these problems but rather the symptoms.

@sspies

This comment has been minimized.

Show comment
Hide comment
@sspies

sspies Aug 4, 2012

I bought hardware from http://elinux.org/RPi_VerifiedPeripherals

Connected to Hama 4-way USB 2.0 Hub:

  • Tenda W311U Mini 11N
  • Cherry Keyboard
  • Saitek Mouse

RPi PSU is 1000mA
Hama PSU unknown

After booting up, everything seems to be recognized correctly, but once LXDE is started, wifi connection drops:
http://pastebin.com/1aBVBeX3

Voltage constantly 4,9V

sspies commented Aug 4, 2012

I bought hardware from http://elinux.org/RPi_VerifiedPeripherals

Connected to Hama 4-way USB 2.0 Hub:

  • Tenda W311U Mini 11N
  • Cherry Keyboard
  • Saitek Mouse

RPi PSU is 1000mA
Hama PSU unknown

After booting up, everything seems to be recognized correctly, but once LXDE is started, wifi connection drops:
http://pastebin.com/1aBVBeX3

Voltage constantly 4,9V

bmwiedemann pushed a commit to bmwiedemann/raspberrypi-linux that referenced this issue Aug 11, 2012

usb: usb-storage doesn't support dynamic id currently, the patch disa…
…bles the feature to fix an oops

Echo vendor and product number of a non usb-storage device to
usb-storage driver's new_id, then plug in the device to host and you
will find following oops msg, the root cause is usb_stor_probe1()
refers invalid id entry if giving a dynamic id, so just disable the
feature.

[ 3105.018012] general protection fault: 0000 [#1] SMP DEBUG_PAGEALLOC
[ 3105.018062] CPU 0
[ 3105.018075] Modules linked in: usb_storage usb_libusual bluetooth
dm_crypt binfmt_misc snd_hda_codec_analog snd_hda_intel snd_hda_codec
snd_hwdep hp_wmi ppdev sparse_keymap snd_pcm snd_seq_midi snd_rawmidi
snd_seq_midi_event snd_seq snd_timer snd_seq_device psmouse snd
serio_raw tpm_infineon soundcore i915 snd_page_alloc tpm_tis
parport_pc tpm tpm_bios drm_kms_helper drm i2c_algo_bit video lp
parport usbhid hid sg sr_mod sd_mod ehci_hcd uhci_hcd usbcore e1000e
usb_common floppy
[ 3105.018408]
[ 3105.018419] Pid: 189, comm: khubd Tainted: G          I  3.2.0-rc7+
#29 Hewlett-Packard HP Compaq dc7800p Convertible Minitower/0AACh
[ 3105.018481] RIP: 0010:[<ffffffffa045830d>]  [<ffffffffa045830d>]
usb_stor_probe1+0x2fd/0xc20 [usb_storage]
[ 3105.018536] RSP: 0018:ffff880056a3d830  EFLAGS: 00010286
[ 3105.018562] RAX: ffff880065f4e648 RBX: ffff88006bb28000 RCX: 0000000000000000
[ 3105.018597] RDX: ffff88006f23c7b0 RSI: 0000000000000001 RDI: 0000000000000206
[ 3105.018632] RBP: ffff880056a3d900 R08: 0000000000000000 R09: ffff880067365000
[ 3105.018665] R10: 00000000000002ac R11: 0000000000000010 R12: ffff6000b41a7340
[ 3105.018698] R13: ffff880065f4ef60 R14: ffff88006bb28b88 R15: ffff88006f23d270
[ 3105.018733] FS:  0000000000000000(0000) GS:ffff88007a200000(0000)
knlGS:0000000000000000
[ 3105.018773] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 3105.018801] CR2: 00007fc99c8c4650 CR3: 0000000001e05000 CR4: 00000000000006f0
[ 3105.018835] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 3105.018870] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 3105.018906] Process khubd (pid: 189, threadinfo ffff880056a3c000,
task ffff88005677a400)
[ 3105.018945] Stack:
[ 3105.018959]  0000000000000000 0000000000000000 ffff880056a3d8d0
0000000000000002
[ 3105.019011]  0000000000000000 ffff880056a3d918 ffff880000000000
0000000000000002
[ 3105.019058]  ffff880056a3d8d0 0000000000000012 ffff880056a3d8d0
0000000000000006
[ 3105.019105] Call Trace:
[ 3105.019128]  [<ffffffffa0458cd4>] storage_probe+0xa4/0xe0 [usb_storage]
[ 3105.019173]  [<ffffffffa0097822>] usb_probe_interface+0x172/0x330 [usbcore]
[ 3105.019211]  [<ffffffff815fda67>] driver_probe_device+0x257/0x3b0
[ 3105.019243]  [<ffffffff815fdd43>] __device_attach+0x73/0x90
[ 3105.019272]  [<ffffffff815fdcd0>] ? __driver_attach+0x110/0x110
[ 3105.019303]  [<ffffffff815fb93c>] bus_for_each_drv+0x9c/0xf0
[ 3105.019334]  [<ffffffff815fd6c7>] device_attach+0xf7/0x120
[ 3105.019364]  [<ffffffff815fc905>] bus_probe_device+0x45/0x80
[ 3105.019396]  [<ffffffff815f98a6>] device_add+0x876/0x990
[ 3105.019434]  [<ffffffffa0094e42>] usb_set_configuration+0x822/0x9e0 [usbcore]
[ 3105.019479]  [<ffffffffa00a3492>] generic_probe+0x62/0xf0 [usbcore]
[ 3105.019518]  [<ffffffffa0097a46>] usb_probe_device+0x66/0xb0 [usbcore]
[ 3105.019555]  [<ffffffff815fda67>] driver_probe_device+0x257/0x3b0
[ 3105.019589]  [<ffffffff815fdd43>] __device_attach+0x73/0x90
[ 3105.019617]  [<ffffffff815fdcd0>] ? __driver_attach+0x110/0x110
[ 3105.019648]  [<ffffffff815fb93c>] bus_for_each_drv+0x9c/0xf0
[ 3105.019680]  [<ffffffff815fd6c7>] device_attach+0xf7/0x120
[ 3105.019709]  [<ffffffff815fc905>] bus_probe_device+0x45/0x80
[ 3105.021040] usb usb6: usb auto-resume
[ 3105.021045] usb usb6: wakeup_rh
[ 3105.024849]  [<ffffffff815f98a6>] device_add+0x876/0x990
[ 3105.025086]  [<ffffffffa0088987>] usb_new_device+0x1e7/0x2b0 [usbcore]
[ 3105.025086]  [<ffffffffa008a4d7>] hub_thread+0xb27/0x1ec0 [usbcore]
[ 3105.025086]  [<ffffffff810d5200>] ? wake_up_bit+0x50/0x50
[ 3105.025086]  [<ffffffffa00899b0>] ? usb_remote_wakeup+0xa0/0xa0 [usbcore]
[ 3105.025086]  [<ffffffff810d49b8>] kthread+0xd8/0xf0
[ 3105.025086]  [<ffffffff81939884>] kernel_thread_helper+0x4/0x10
[ 3105.025086]  [<ffffffff8192a8c0>] ? _raw_spin_unlock_irq+0x50/0x80
[ 3105.025086]  [<ffffffff8192b1b4>] ? retint_restore_args+0x13/0x13
[ 3105.025086]  [<ffffffff810d48e0>] ? __init_kthread_worker+0x80/0x80
[ 3105.025086]  [<ffffffff81939880>] ? gs_change+0x13/0x13
[ 3105.025086] Code: 00 48 83 05 cd ad 00 00 01 48 83 05 cd ad 00 00
01 4c 8b ab 30 0c 00 00 48 8b 50 08 48 83 c0 30 48 89 45 a0 4c 89 a3
40 0c 00 00 <41> 0f b6 44 24 10 48 89 55 a8 3c ff 0f 84 b8 04 00 00 48
83 05
[ 3105.025086] RIP  [<ffffffffa045830d>] usb_stor_probe1+0x2fd/0xc20
[usb_storage]
[ 3105.025086]  RSP <ffff880056a3d830>
[ 3105.060037] hub 6-0:1.0: hub_resume
[ 3105.062616] usb usb5: usb auto-resume
[ 3105.064317] ehci_hcd 0000:00:1d.7: resume root hub
[ 3105.094809] ---[ end trace a7919e7f17c0a727 ]---
[ 3105.130069] hub 5-0:1.0: hub_resume
[ 3105.132131] usb usb4: usb auto-resume
[ 3105.132136] usb usb4: wakeup_rh
[ 3105.180059] hub 4-0:1.0: hub_resume
[ 3106.290052] usb usb6: suspend_rh (auto-stop)
[ 3106.290077] usb usb4: suspend_rh (auto-stop)

Signed-off-by: Huajun Li <huajun.li.lee@gmail.com>
Cc: stable <stable@vger.kernel.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>
@sulge

This comment has been minimized.

Show comment
Hide comment
@sulge

sulge Aug 12, 2012

Unfortunately, I have the following erros when testing @popcornmix's patch:
BUG: scheduling while atomic: testUSB.sh/1155/0x00000002
Modules linked in: ipv6 pl2303 ftdi_sio usbserial
Backtrace:
Function entered at [] from []
r6:cd860000 r5:ceb75440 r4:00000000
Function entered at [] from []
Function entered at [] from []
r4:c0427be0
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r8:000000a1 r7:00000000 r6:00000000 r5:00000007 r4:cea707c0
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r8:ceadf840 r7:cd9cdc00 r6:ceaaa634 r5:ceaaa604 r4:cd860000
Function entered at [] from []
r8:ceadf840 r7:0bc00000 r6:ceadf840 r5:ceaaa600 r4:cd9cdc00
Function entered at [] from []
r6:cd9cdc00 r5:ce9d18e0 r4:ce9d18e4
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r7:00000000 r6:00000000 r5:cd861ed0 r4:ce958798
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r8:00000003 r7:ceb16000 r6:000001b6 r5:00020241 r4:00000001
Function entered at [] from []
Function entered at [] from []

How can I help you to improve it?

sulge commented Aug 12, 2012

Unfortunately, I have the following erros when testing @popcornmix's patch:
BUG: scheduling while atomic: testUSB.sh/1155/0x00000002
Modules linked in: ipv6 pl2303 ftdi_sio usbserial
Backtrace:
Function entered at [] from []
r6:cd860000 r5:ceb75440 r4:00000000
Function entered at [] from []
Function entered at [] from []
r4:c0427be0
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r8:000000a1 r7:00000000 r6:00000000 r5:00000007 r4:cea707c0
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r8:ceadf840 r7:cd9cdc00 r6:ceaaa634 r5:ceaaa604 r4:cd860000
Function entered at [] from []
r8:ceadf840 r7:0bc00000 r6:ceadf840 r5:ceaaa600 r4:cd9cdc00
Function entered at [] from []
r6:cd9cdc00 r5:ce9d18e0 r4:ce9d18e4
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r7:00000000 r6:00000000 r5:cd861ed0 r4:ce958798
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
r8:00000003 r7:ceb16000 r6:000001b6 r5:00020241 r4:00000001
Function entered at [] from []
Function entered at [] from []

How can I help you to improve it?

@rstolfa

This comment has been minimized.

Show comment
Hide comment
@rstolfa

rstolfa Aug 17, 2012

Is there any word on this problem? I'm fighting it too, but I need a bit more help on getting the kernel sources and applying the patch from popcornmix ...unless it's out of testing and in the stable distribution?

rstolfa commented Aug 17, 2012

Is there any word on this problem? I'm fighting it too, but I need a bit more help on getting the kernel sources and applying the patch from popcornmix ...unless it's out of testing and in the stable distribution?

@virtualguy

This comment has been minimized.

Show comment
Hide comment
@virtualguy

virtualguy Aug 21, 2012

Perhaps a more concrete result of the issue still being persistant. See the periodic transfer failure in dmesg below:
dmesg | tail -n 30
[ 130.006004] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 132.026377] usb 1-1.3.1.2: reset low-speed USB device number 7 using dwc_otg
[ 144.016506] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 164.957246] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 169.957467] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 183.037925] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 190.358398] usb 1-1.3.1.2: reset low-speed USB device number 7 using dwc_otg
[ 208.978910] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 213.979717] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 224.069474] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 229.069674] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 262.070875] hub 1-1.3.1:1.0: cannot reset port 1 (err = -110)
[ 264.072250] usb 1-1.3.1.1: new high-speed USB device number 8 using dwc_otg
[ 273.001295] usb 1-1.3.1.1: unable to read config index 0 descriptor/all
[ 273.001359] usb 1-1.3.1.1: can't read configurations, error -110
[ 273.001484] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 274.211343] usb 1-1.3.1.1: new high-speed USB device number 9 using dwc_otg
[ 279.020280] usb 1-1.3.1.1: New USB device found, idVendor=1a40, idProduct=0101
[ 279.020315] usb 1-1.3.1.1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 279.020335] usb 1-1.3.1.1: Product: USB 2.0 Hub
[ 279.050900] hub 1-1.3.1.1:1.0: USB hub found
[ 279.051161] hub 1-1.3.1.1:1.0: 4 ports detected
[ 279.661520] INFO:: periodic_channel_available: Total channels: 8, Periodic: 7, Non-periodic: 1
[ 279.661537]
[ 279.661558] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 279.661569]
[ 279.661605] ERROR::dwc_otg_hcd_urb_enqueue:498: DWC OTG HCD URB Enqueue failed adding QTD. Error status -28
[ 279.661618]
[ 279.661648] hub 1-1.3.1.1:1.0: activate --> -28
[ 282.076255] usb 1-1.3.1.1.4: new full-speed USB device number 10 using dwc_otg

Perhaps a more concrete result of the issue still being persistant. See the periodic transfer failure in dmesg below:
dmesg | tail -n 30
[ 130.006004] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 132.026377] usb 1-1.3.1.2: reset low-speed USB device number 7 using dwc_otg
[ 144.016506] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 164.957246] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 169.957467] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 183.037925] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 190.358398] usb 1-1.3.1.2: reset low-speed USB device number 7 using dwc_otg
[ 208.978910] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 213.979717] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 224.069474] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
[ 229.069674] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
[ 262.070875] hub 1-1.3.1:1.0: cannot reset port 1 (err = -110)
[ 264.072250] usb 1-1.3.1.1: new high-speed USB device number 8 using dwc_otg
[ 273.001295] usb 1-1.3.1.1: unable to read config index 0 descriptor/all
[ 273.001359] usb 1-1.3.1.1: can't read configurations, error -110
[ 273.001484] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118
[ 274.211343] usb 1-1.3.1.1: new high-speed USB device number 9 using dwc_otg
[ 279.020280] usb 1-1.3.1.1: New USB device found, idVendor=1a40, idProduct=0101
[ 279.020315] usb 1-1.3.1.1: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 279.020335] usb 1-1.3.1.1: Product: USB 2.0 Hub
[ 279.050900] hub 1-1.3.1.1:1.0: USB hub found
[ 279.051161] hub 1-1.3.1.1:1.0: 4 ports detected
[ 279.661520] INFO:: periodic_channel_available: Total channels: 8, Periodic: 7, Non-periodic: 1
[ 279.661537]
[ 279.661558] INFO:: schedule_periodic: No host channel available for periodic transfer.
[ 279.661569]
[ 279.661605] ERROR::dwc_otg_hcd_urb_enqueue:498: DWC OTG HCD URB Enqueue failed adding QTD. Error status -28
[ 279.661618]
[ 279.661648] hub 1-1.3.1.1:1.0: activate --> -28
[ 282.076255] usb 1-1.3.1.1.4: new full-speed USB device number 10 using dwc_otg

@NickBT

This comment has been minimized.

Show comment
Hide comment
@NickBT

NickBT Aug 21, 2012

The issue of having no wifi connectivity through LXDE is now resolved for me with Linux version 3.2.27+ #24 PREEMPT and dwc_otg.microframe_schedule=1 in cmdline.txt.

I have a 4 port Logik hub powering the Pi, basic USB kbd and mouse and a Belkin USB wifi dongle. wlan0 and eth0 are both up. I had previously seen dmesg output full of the same index 00000114/118 errors that others have been, and in some cases still are, reporting. I see no such errors now in my setup.

I should have added that I'm using Raspbian.

NickBT commented Aug 21, 2012

The issue of having no wifi connectivity through LXDE is now resolved for me with Linux version 3.2.27+ #24 PREEMPT and dwc_otg.microframe_schedule=1 in cmdline.txt.

I have a 4 port Logik hub powering the Pi, basic USB kbd and mouse and a Belkin USB wifi dongle. wlan0 and eth0 are both up. I had previously seen dmesg output full of the same index 00000114/118 errors that others have been, and in some cases still are, reporting. I see no such errors now in my setup.

I should have added that I'm using Raspbian.

@popcornmix

This comment has been minimized.

Show comment
Hide comment
@popcornmix

popcornmix Aug 21, 2012

Collaborator

@virtualguy
Have you added to dwc_otg.microframe_schedule=1 to cmdline.txt?
(not config.txt as I originally mistyped)

Collaborator

popcornmix commented Aug 21, 2012

@virtualguy
Have you added to dwc_otg.microframe_schedule=1 to cmdline.txt?
(not config.txt as I originally mistyped)

@virtualguy

This comment has been minimized.

Show comment
Hide comment
@virtualguy

virtualguy Aug 21, 2012

I have indeed. I have updated my firmware do i need to update my kernel
too? Currently running what i think is the latest, 3.2.27+ from the default
wheezy install.
On Aug 21, 2012 10:59 PM, "popcornmix" notifications@github.com wrote:

@virtualguy https://github.com/virtualguy
Have you added to dwc_otg.microframe_schedule=1 to cmdline.txt?
(not config.txt as I originally mistyped)


Reply to this email directly or view it on GitHubhttps://github.com/raspberrypi/linux/issues/29#issuecomment-7897692.

I have indeed. I have updated my firmware do i need to update my kernel
too? Currently running what i think is the latest, 3.2.27+ from the default
wheezy install.
On Aug 21, 2012 10:59 PM, "popcornmix" notifications@github.com wrote:

@virtualguy https://github.com/virtualguy
Have you added to dwc_otg.microframe_schedule=1 to cmdline.txt?
(not config.txt as I originally mistyped)


Reply to this email directly or view it on GitHubhttps://github.com/raspberrypi/linux/issues/29#issuecomment-7897692.

@popcornmix

This comment has been minimized.

Show comment
Hide comment
@popcornmix

popcornmix Aug 21, 2012

Collaborator

@virtualguy
You will need latest firmware from rpi-update. "uname -a" should be 18th August or later.

Collaborator

popcornmix commented Aug 21, 2012

@virtualguy
You will need latest firmware from rpi-update. "uname -a" should be 18th August or later.

@virtualguy

This comment has been minimized.

Show comment
Hide comment
@virtualguy

virtualguy Aug 21, 2012

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.2.27+ #24 PREEMPT Sun Aug 19 21:28:36 BST 2012 armv6l GNU/Linux

I'll try a fresh install just to rule out any of the packages I have installed but looks to me like its still an issue. I'll also throw the scope on it today just to ensure the power supply is clean. I had have a powered hub providing +5V back upstream earlier but have "fixed" the hub now.

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.2.27+ #24 PREEMPT Sun Aug 19 21:28:36 BST 2012 armv6l GNU/Linux

I'll try a fresh install just to rule out any of the packages I have installed but looks to me like its still an issue. I'll also throw the scope on it today just to ensure the power supply is clean. I had have a powered hub providing +5V back upstream earlier but have "fixed" the hub now.

@htahola

This comment has been minimized.

Show comment
Hide comment
@htahola

htahola Aug 22, 2012

I have been trying to put up a video surveillance with usb-webcam and a USB-3G dongle. Using a 5V 5A PSU powering a USB hub (only as power distribution). Using USB-Y-cables to provide extra power for both camera and the 3G. I have applied the Aug 18 kernel patch, which made the improvement that I got it working in the first place. But it fails after random time. I then tried to put the 3G dongle on a separate 3G-router connected to PI with rj-45. That did not solve the case as I noticed the usb hub inside the Pi is a 3-port one. The rj-45 is just a usb device too. The problem, when it happens, persists over softboot. Only power off/on sorts it out. The problem occurs randomly in 6 hours or almost instantly after start. I Hope this helps in solving the problem. btw. I think half of the open issues (33) are related to this USB one. AND I added dwc_otg.microframe_schedule=1 to cmdline.txt :)

htahola commented Aug 22, 2012

I have been trying to put up a video surveillance with usb-webcam and a USB-3G dongle. Using a 5V 5A PSU powering a USB hub (only as power distribution). Using USB-Y-cables to provide extra power for both camera and the 3G. I have applied the Aug 18 kernel patch, which made the improvement that I got it working in the first place. But it fails after random time. I then tried to put the 3G dongle on a separate 3G-router connected to PI with rj-45. That did not solve the case as I noticed the usb hub inside the Pi is a 3-port one. The rj-45 is just a usb device too. The problem, when it happens, persists over softboot. Only power off/on sorts it out. The problem occurs randomly in 6 hours or almost instantly after start. I Hope this helps in solving the problem. btw. I think half of the open issues (33) are related to this USB one. AND I added dwc_otg.microframe_schedule=1 to cmdline.txt :)

@keithsuddick

This comment has been minimized.

Show comment
Hide comment
@keithsuddick

keithsuddick Aug 22, 2012

I'd like to add my experience today: I have a D-Link, powered 7 port hub only, connected to my RPi, attached to the hub are a keyboard, mouse and D-Link DWA-140 wi-fi dongle - lsusb gives the following:

Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp.
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp.
Bus 001 Device 004: ID 2001:f103 D-Link Corp. DUB-H7 7-port USB 2.0 hub
Bus 001 Device 005: ID 07d1:3c09 D-Link System DWA-140 RangeBooster N Adapter(rev.B1) [Ralink RT2870]
Bus 001 Device 010: ID 0b38:0010 Gear Head 107-Key Keyboard
Bus 001 Device 009: ID 413c:3016 Dell Computer Corp. Optical 5-Button Wheel Mouse

This combination has always worked at the command prompt but always failed when starting X - network connectivity fails, and mouse and keyboard work unpredictably even after exiting X.

After updating and adding dwc_otg.microframe_schedule=1 to cmdline.txt I can now start X and everything remains working - I can still SSH into the RPi and I can browse websites within X so this is a huge step forward from my point of view - thank you to those who contributed to this fix.

I am still seeing occasional errors and repeated reset messages for some of the USB devices and some have disconnected/reconnected as differently numbered devices, such as:

Aug 22 14:44:26 raspberrypi kernel: [ 146.284562] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:53:30 raspberrypi kernel: [ 690.008420] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
Aug 22 14:58:42 raspberrypi kernel: [ 1002.005468] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:42 raspberrypi kernel: [ 1002.575513] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:45 raspberrypi kernel: [ 1005.295643] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:46 raspberrypi kernel: [ 1005.865597] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:48 raspberrypi kernel: [ 1007.695616] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:48 raspberrypi kernel: [ 1008.378570] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:50 raspberrypi kernel: [ 1010.415711] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:54 raspberrypi kernel: [ 1013.685787] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:54 raspberrypi kernel: [ 1014.375376] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:56 raspberrypi kernel: [ 1015.626104] hub 1-1.3:1.0: port 5 disabled by hub (EMI?), re-enabling...
Aug 22 14:58:56 raspberrypi kernel: [ 1015.626332] usb 1-1.3.5: USB disconnect, device number 6
Aug 22 14:58:56 raspberrypi kernel: [ 1015.875795] usb 1-1.3.5: new low-speed USB device number 8 using dwc_otg
Aug 22 14:58:56 raspberrypi kernel: [ 1015.980960] usb 1-1.3.5: New USB device found, idVendor=0b38, idProduct=0010
Aug 22 14:58:56 raspberrypi kernel: [ 1015.980994] usb 1-1.3.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0

But this is a definite improvement. Thanks again.

I'd like to add my experience today: I have a D-Link, powered 7 port hub only, connected to my RPi, attached to the hub are a keyboard, mouse and D-Link DWA-140 wi-fi dongle - lsusb gives the following:

Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp.
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp.
Bus 001 Device 004: ID 2001:f103 D-Link Corp. DUB-H7 7-port USB 2.0 hub
Bus 001 Device 005: ID 07d1:3c09 D-Link System DWA-140 RangeBooster N Adapter(rev.B1) [Ralink RT2870]
Bus 001 Device 010: ID 0b38:0010 Gear Head 107-Key Keyboard
Bus 001 Device 009: ID 413c:3016 Dell Computer Corp. Optical 5-Button Wheel Mouse

This combination has always worked at the command prompt but always failed when starting X - network connectivity fails, and mouse and keyboard work unpredictably even after exiting X.

After updating and adding dwc_otg.microframe_schedule=1 to cmdline.txt I can now start X and everything remains working - I can still SSH into the RPi and I can browse websites within X so this is a huge step forward from my point of view - thank you to those who contributed to this fix.

I am still seeing occasional errors and repeated reset messages for some of the USB devices and some have disconnected/reconnected as differently numbered devices, such as:

Aug 22 14:44:26 raspberrypi kernel: [ 146.284562] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:53:30 raspberrypi kernel: [ 690.008420] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
Aug 22 14:58:42 raspberrypi kernel: [ 1002.005468] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:42 raspberrypi kernel: [ 1002.575513] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:45 raspberrypi kernel: [ 1005.295643] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:46 raspberrypi kernel: [ 1005.865597] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:48 raspberrypi kernel: [ 1007.695616] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:48 raspberrypi kernel: [ 1008.378570] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:50 raspberrypi kernel: [ 1010.415711] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:54 raspberrypi kernel: [ 1013.685787] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:54 raspberrypi kernel: [ 1014.375376] usb 1-1.3.5: reset low-speed USB device number 6 using dwc_otg
Aug 22 14:58:56 raspberrypi kernel: [ 1015.626104] hub 1-1.3:1.0: port 5 disabled by hub (EMI?), re-enabling...
Aug 22 14:58:56 raspberrypi kernel: [ 1015.626332] usb 1-1.3.5: USB disconnect, device number 6
Aug 22 14:58:56 raspberrypi kernel: [ 1015.875795] usb 1-1.3.5: new low-speed USB device number 8 using dwc_otg
Aug 22 14:58:56 raspberrypi kernel: [ 1015.980960] usb 1-1.3.5: New USB device found, idVendor=0b38, idProduct=0010
Aug 22 14:58:56 raspberrypi kernel: [ 1015.980994] usb 1-1.3.5: New USB device strings: Mfr=0, Product=0, SerialNumber=0

But this is a definite improvement. Thanks again.

@hugin84

This comment has been minimized.

Show comment
Hide comment
@hugin84

hugin84 Sep 1, 2012

...
[ 191.485350] smsc95xx 1-1.1:1.0: eth0: kevent 4 may have been dropped
[ 191.493347] smsc95xx 1-1.1:1.0: eth0: kevent 4 may have been dropped
[ 191.497462] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
...

In my case the issue was apparently caused by a cheap powered 7 port USB hub.

Switching from a Samsung cellphone charger (output: 5V, 0.7A) to an HTC cellphone charger (output: 5V, 2A) allowed me to get rid of the powered hub which then made things work. Just putting tape on the +5V pin of the hub's upstream cable (as suggested at http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=7445&p=105118) did not solve the issue, neither did using the hub after only changing the power supply or powering the Pi from the hub

used devices: just a cheap basic Hama keyboard and a Logitech Mouseman Dual Optical:

Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp.
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp.
Bus 001 Device 014: ID 046d:c012 Logitech, Inc. Mouseman Dual Optical
Bus 001 Device 005: ID 04d9:1603 Holtek Semiconductor, Inc. Keyboard

With no free USB ports left this "solution" obviously won't work for everyone but at least it's a quick fix to get the Pi working at all.

hugin84 commented Sep 1, 2012

...
[ 191.485350] smsc95xx 1-1.1:1.0: eth0: kevent 4 may have been dropped
[ 191.493347] smsc95xx 1-1.1:1.0: eth0: kevent 4 may have been dropped
[ 191.497462] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
...

In my case the issue was apparently caused by a cheap powered 7 port USB hub.

Switching from a Samsung cellphone charger (output: 5V, 0.7A) to an HTC cellphone charger (output: 5V, 2A) allowed me to get rid of the powered hub which then made things work. Just putting tape on the +5V pin of the hub's upstream cable (as suggested at http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=7445&p=105118) did not solve the issue, neither did using the hub after only changing the power supply or powering the Pi from the hub

used devices: just a cheap basic Hama keyboard and a Logitech Mouseman Dual Optical:

Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp.
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp.
Bus 001 Device 014: ID 046d:c012 Logitech, Inc. Mouseman Dual Optical
Bus 001 Device 005: ID 04d9:1603 Holtek Semiconductor, Inc. Keyboard

With no free USB ports left this "solution" obviously won't work for everyone but at least it's a quick fix to get the Pi working at all.

@peatmanb

This comment has been minimized.

Show comment
Hide comment
@peatmanb

peatmanb Sep 8, 2012

I got my Raspberry Pi today and had this issue. ping times were great until I started X and then they were terrible and soon i would just lose network.

I read this thread and did :

sudo apt-get upgrade

I got rpi-update and updated my kernel to:

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.2.27+ #114 PREEMPT Tue Sep 4 00:15:33 BST 2012 armv6l GNU/Linux

and I added :
dwc_otg.microframe_schedule=1

to the front of
/boot/cmdline.txt

Now everything is great. Thanks!
I had a Mac Keyboard so I had to use a USB powered hub. I guess thats part of the problem from reading this. Mine is USB 2.0 from IOGear.

peatmanb commented Sep 8, 2012

I got my Raspberry Pi today and had this issue. ping times were great until I started X and then they were terrible and soon i would just lose network.

I read this thread and did :

sudo apt-get upgrade

I got rpi-update and updated my kernel to:

pi@raspberrypi ~ $ uname -a
Linux raspberrypi 3.2.27+ #114 PREEMPT Tue Sep 4 00:15:33 BST 2012 armv6l GNU/Linux

and I added :
dwc_otg.microframe_schedule=1

to the front of
/boot/cmdline.txt

Now everything is great. Thanks!
I had a Mac Keyboard so I had to use a USB powered hub. I guess thats part of the problem from reading this. Mine is USB 2.0 from IOGear.

@licaon-kter

This comment has been minimized.

Show comment
Hide comment
@licaon-kter

licaon-kter Sep 8, 2012

adding smsc95xx.turbo_mode=N to /boot/cmdline.txt alleviates the issue?

adding smsc95xx.turbo_mode=N to /boot/cmdline.txt alleviates the issue?

@9er

This comment has been minimized.

Show comment
Hide comment
@9er

9er Sep 25, 2012

Same issues here, but without using X. I've got a powered USB Hub with 3 usb-rs232 adapters connected to it. Works perfectly for about about 1-2 hours, then ethernet fails.

Sep 25 01:47:42 raspberrypi kernel: [22656.813350] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
Sep 25 01:47:47 raspberrypi kernel: [22661.813241] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
Sep 25 01:47:52 raspberrypi kernel: [22666.813084] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
Sep 25 01:47:57 raspberrypi kernel: [22671.812965] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118

I'm using raspbian with the latest firmware.
Linux raspberrypi 3.2.27+ #168 PREEMPT Sat Sep 22 19:26:13 BST 2012 armv6l GNU/Linux

I've already tried:

  • smsc95xx.turbo_mode=N
  • dwc_otg.fiq_fix_enable=1
  • vm.min_free_kbytes = 32768
  • dwc_otg.microframe_schedule=1
  • dwc_otg.speed=1

and different combinations of these settings. (but not all)
I also tried different power supplies, as well as powering the RPi from the Hub, but there was no difference. The hub can also be used without power supply, but again, that doesn't change anything.
As I'm writing this, ethernet failed again.
Is there any chance this gets fixed?

9er commented Sep 25, 2012

Same issues here, but without using X. I've got a powered USB Hub with 3 usb-rs232 adapters connected to it. Works perfectly for about about 1-2 hours, then ethernet fails.

Sep 25 01:47:42 raspberrypi kernel: [22656.813350] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
Sep 25 01:47:47 raspberrypi kernel: [22661.813241] smsc95xx 1-1.1:1.0: eth0: Failed to write register index 0x00000114
Sep 25 01:47:52 raspberrypi kernel: [22666.813084] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000114
Sep 25 01:47:57 raspberrypi kernel: [22671.812965] smsc95xx 1-1.1:1.0: eth0: Failed to read register index 0x00000118

I'm using raspbian with the latest firmware.
Linux raspberrypi 3.2.27+ #168 PREEMPT Sat Sep 22 19:26:13 BST 2012 armv6l GNU/Linux

I've already tried:

  • smsc95xx.turbo_mode=N
  • dwc_otg.fiq_fix_enable=1
  • vm.min_free_kbytes = 32768
  • dwc_otg.microframe_schedule=1
  • dwc_otg.speed=1

and different combinations of these settings. (but not all)
I also tried different power supplies, as well as powering the RPi from the Hub, but there was no difference. The hub can also be used without power supply, but again, that doesn't change anything.
As I'm writing this, ethernet failed again.
Is there any chance this gets fixed?

@licaon-kter

This comment has been minimized.

Show comment
Hide comment
@licaon-kter

licaon-kter Sep 25, 2012

BTW, dwc_otg.fiq_fix_enable & dwc_otg.microframe_schedule are already included and activated, you can only disable them

BTW, dwc_otg.fiq_fix_enable & dwc_otg.microframe_schedule are already included and activated, you can only disable them

@ghollingworth

This comment has been minimized.

Show comment
Hide comment
@ghollingworth

ghollingworth Sep 26, 2012

Contributor

Are you sure dwc_otg.speed=1 didn't make any difference?

I would think this should stop any problems because everything drops back
to USB1.0

Gordon

On 25 September 2012 09:30, licaon-kter notifications@github.com wrote:

BTW, dwc_otg.fiq_fix_enable & dwc_otg.microframe_schedule are already
included and activated, you can only disable them


Reply to this email directly or view it on GitHubhttps://github.com/raspberrypi/linux/issues/29#issuecomment-8847039.

Contributor

ghollingworth commented Sep 26, 2012

Are you sure dwc_otg.speed=1 didn't make any difference?

I would think this should stop any problems because everything drops back
to USB1.0

Gordon

On 25 September 2012 09:30, licaon-kter notifications@github.com wrote:

BTW, dwc_otg.fiq_fix_enable & dwc_otg.microframe_schedule are already
included and activated, you can only disable them


Reply to this email directly or view it on GitHubhttps://github.com/raspberrypi/linux/issues/29#issuecomment-8847039.

@9er

This comment has been minimized.

Show comment
Hide comment
@9er

9er Sep 26, 2012

Updated firmware to
Linux raspberrypi 3.2.27+ #171 PREEMPT Tue Sep 25 00:08:57 BST 2012 armv6l
and set dwc_otg.speed=1.
So now it fails the moment, I plug in the USB hub (or on boot if its already plugged in). But I've just noticed something interesting, that (at least I think) wasn't happening before: When I unplug the Hub with all the attatched stuff, ethernet starts working again (smcs95xx gets registered on usb). I think this is because of the limited number of channels?
I tried unplugging the UPS and it's working for now. The weird thing is, with firmware #160 and #168 it's been working with all the connected devices, even the UPS. At least for about an hour...

9er commented Sep 26, 2012

Updated firmware to
Linux raspberrypi 3.2.27+ #171 PREEMPT Tue Sep 25 00:08:57 BST 2012 armv6l
and set dwc_otg.speed=1.
So now it fails the moment, I plug in the USB hub (or on boot if its already plugged in). But I've just noticed something interesting, that (at least I think) wasn't happening before: When I unplug the Hub with all the attatched stuff, ethernet starts working again (smcs95xx gets registered on usb). I think this is because of the limited number of channels?
I tried unplugging the UPS and it's working for now. The weird thing is, with firmware #160 and #168 it's been working with all the connected devices, even the UPS. At least for about an hour...

@ghollingworth

This comment has been minimized.

Show comment
Hide comment
@ghollingworth

ghollingworth Sep 26, 2012

Contributor

Can you do a

Sudo lsusb -v
Sudo lsusb -t

And send the results with just the hub... I assume you have the
latest kernel? This deals with channel scheduling properly so
shouldn't be the cause of the issue

What are you actually plugging in, can you draw the hierarchy and try
one device at a time getting the lsusb -v information for each device

Gordon

Gordon

On 26/09/2012, 9er notifications@github.com wrote:

Updated firmware to
Linux raspberrypi 3.2.27+ #171 PREEMPT Tue Sep 25 00:08:57 BST 2012 armv6l
and set dwc_otg.speed=1.
So now it fails the moment, I plug in the USB hub (or on boot if its already
plugged in). But I've just noticed something interesting, that (at least I
think) wasn't happening before: When I unplug the Hub with all the attatched
stuff, ethernet starts working again (smcs95xx gets registered on usb). I
think this is because of the limited number of channels?
I tried unplugging the UPS and it's working for now. The weird thing is,
with firmware #160 and #168 it's been working with all the connected
devices, even the UPS. At least for about an hour...


Reply to this email directly or view it on GitHub:
#29 (comment)

Sent from my mobile device

Contributor

ghollingworth commented Sep 26, 2012

Can you do a

Sudo lsusb -v
Sudo lsusb -t

And send the results with just the hub... I assume you have the
latest kernel? This deals with channel scheduling properly so
shouldn't be the cause of the issue

What are you actually plugging in, can you draw the hierarchy and try
one device at a time getting the lsusb -v information for each device

Gordon

Gordon

On 26/09/2012, 9er notifications@github.com wrote:

Updated firmware to
Linux raspberrypi 3.2.27+ #171 PREEMPT Tue Sep 25 00:08:57 BST 2012 armv6l
and set dwc_otg.speed=1.
So now it fails the moment, I plug in the USB hub (or on boot if its already
plugged in). But I've just noticed something interesting, that (at least I
think) wasn't happening before: When I unplug the Hub with all the attatched
stuff, ethernet starts working again (smcs95xx gets registered on usb). I
think this is because of the limited number of channels?
I tried unplugging the UPS and it's working for now. The weird thing is,
with firmware #160 and #168 it's been working with all the connected
devices, even the UPS. At least for about an hour...


Reply to this email directly or view it on GitHub:
#29 (comment)

Sent from my mobile device

@9er

This comment has been minimized.

Show comment
Hide comment
@9er

9er Sep 26, 2012

Yep, latest kernel on raspbian.
Basicly I'm just plugging in the hub (which I think is actually two hubs internally) and then everything (three RS232 adapters and my UPS) into the hub.

Here are some pastes:

by the way I removed set dwc_otg.speed=1 to try this.

9er commented Sep 26, 2012

Yep, latest kernel on raspbian.
Basicly I'm just plugging in the hub (which I think is actually two hubs internally) and then everything (three RS232 adapters and my UPS) into the hub.

Here are some pastes:

by the way I removed set dwc_otg.speed=1 to try this.

@ghollingworth

This comment has been minimized.

Show comment
Hide comment
@ghollingworth

ghollingworth Sep 27, 2012

Contributor

OK there is a huge amount of interrupts per second in that system, basically you're looking at something like 60K interrupts per second just with the serial connections...

You could try increasing the ignore time for the NAK interrupting in the dwc_otg driver (this is the last change I made) currently when a bulk endpoint is NAK'd I don't bother retransmitting for a whole frame (8 uframes) this reduces the interrupt over head but it's still something like 17K interrupts per second for a single serial device.

Gordon

Contributor

ghollingworth commented Sep 27, 2012

OK there is a huge amount of interrupts per second in that system, basically you're looking at something like 60K interrupts per second just with the serial connections...

You could try increasing the ignore time for the NAK interrupting in the dwc_otg driver (this is the last change I made) currently when a bulk endpoint is NAK'd I don't bother retransmitting for a whole frame (8 uframes) this reduces the interrupt over head but it's still something like 17K interrupts per second for a single serial device.

Gordon

popcornmix pushed a commit that referenced this issue Oct 13, 2012

Luck, Tony H. Peter Anvin
x86: Remove some noise from boot log when starting cpus
Printing the "start_ip" for every secondary cpu is very noisy on a large
system - and doesn't add any value. Drop this message.

Console log before:
Booting Node   0, Processors  #1
smpboot cpu 1: start_ip = 96000
 #2
smpboot cpu 2: start_ip = 96000
 #3
smpboot cpu 3: start_ip = 96000
 #4
smpboot cpu 4: start_ip = 96000
       ...
 #31
smpboot cpu 31: start_ip = 96000
Brought up 32 CPUs

Console log after:
Booting Node   0, Processors  #1 #2 #3 #4 #5 #6 #7 Ok.
Booting Node   1, Processors  #8 #9 #10 #11 #12 #13 #14 #15 Ok.
Booting Node   0, Processors  #16 #17 #18 #19 #20 #21 #22 #23 Ok.
Booting Node   1, Processors  #24 #25 #26 #27 #28 #29 #30 #31
Brought up 32 CPUs

Acked-by: Borislav Petkov <bp@amd64.org>
Signed-off-by: Tony Luck <tony.luck@intel.com>
Link: http://lkml.kernel.org/r/4f452eb42507460426@agluck-desktop.sc.intel.com
Signed-off-by: H. Peter Anvin <hpa@zytor.com>
@feitingen

This comment has been minimized.

Show comment
Hide comment
@feitingen

feitingen Feb 5, 2013

I'm seeing similar behavior when displaying X windows from a remote machine with a lot of updates.
It works fine for a while, but after an hour or so, the connection drops, and I'm unable to shell in, I'm getting error "Wrong password" for 10-15 seconds, and then it resumes operation as usual.
Any chance this will be fixed?

I'm seeing similar behavior when displaying X windows from a remote machine with a lot of updates.
It works fine for a while, but after an hour or so, the connection drops, and I'm unable to shell in, I'm getting error "Wrong password" for 10-15 seconds, and then it resumes operation as usual.
Any chance this will be fixed?

@ghost ghost assigned ghollingworth Feb 5, 2013

ghaskins added a commit to ghaskins/raspberrypi-rt that referenced this issue Feb 20, 2013

Subject: perf: Make swevent hrtimer run in irq instead of softirq
Otherwise we get a deadlock like below:

[ 1044.042749] BUG: scheduling while atomic: ksoftirqd/21/141/0x00010003
[ 1044.042752] INFO: lockdep is turned off.
[ 1044.042754] Modules linked in:
[ 1044.042757] Pid: 141, comm: ksoftirqd/21 Tainted: G        W    3.4.0-rc2-rt3-23676-ga723175-dirty #29
[ 1044.042759] Call Trace:
[ 1044.042761]  <IRQ>  [<ffffffff8107d8e5>] __schedule_bug+0x65/0x80
[ 1044.042770]  [<ffffffff8168978c>] __schedule+0x83c/0xa70
[ 1044.042775]  [<ffffffff8106bdd2>] ? prepare_to_wait+0x32/0xb0
[ 1044.042779]  [<ffffffff81689a5e>] schedule+0x2e/0xa0
[ 1044.042782]  [<ffffffff81071ebd>] hrtimer_wait_for_timer+0x6d/0xb0
[ 1044.042786]  [<ffffffff8106bb30>] ? wake_up_bit+0x40/0x40
[ 1044.042790]  [<ffffffff81071f20>] hrtimer_cancel+0x20/0x40
[ 1044.042794]  [<ffffffff8111da0c>] perf_swevent_cancel_hrtimer+0x3c/0x50
[ 1044.042798]  [<ffffffff8111da31>] task_clock_event_stop+0x11/0x40
[ 1044.042802]  [<ffffffff8111da6e>] task_clock_event_del+0xe/0x10
[ 1044.042805]  [<ffffffff8111c568>] event_sched_out+0x118/0x1d0
[ 1044.042809]  [<ffffffff8111c649>] group_sched_out+0x29/0x90
[ 1044.042813]  [<ffffffff8111ed7e>] __perf_event_disable+0x18e/0x200
[ 1044.042817]  [<ffffffff8111c343>] remote_function+0x63/0x70
[ 1044.042821]  [<ffffffff810b0aae>] generic_smp_call_function_single_interrupt+0xce/0x120
[ 1044.042826]  [<ffffffff81022bc7>] smp_call_function_single_interrupt+0x27/0x40
[ 1044.042831]  [<ffffffff8168d50c>] call_function_single_interrupt+0x6c/0x80
[ 1044.042833]  <EOI>  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042840]  [<ffffffff8168b970>] ? _raw_spin_unlock_irq+0x30/0x70
[ 1044.042844]  [<ffffffff8168b976>] ? _raw_spin_unlock_irq+0x36/0x70
[ 1044.042848]  [<ffffffff810702e2>] run_hrtimer_softirq+0xc2/0x200
[ 1044.042853]  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042857]  [<ffffffff81045265>] __do_softirq_common+0xf5/0x3a0
[ 1044.042862]  [<ffffffff81045c3d>] __thread_do_softirq+0x15d/0x200
[ 1044.042865]  [<ffffffff81045dda>] run_ksoftirqd+0xfa/0x210
[ 1044.042869]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042873]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042877]  [<ffffffff8106b596>] kthread+0xb6/0xc0
[ 1044.042881]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042886]  [<ffffffff8168d994>] kernel_thread_helper+0x4/0x10
[ 1044.042889]  [<ffffffff8107d98c>] ? finish_task_switch+0x8c/0x110
[ 1044.042894]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042897]  [<ffffffff8168bd5d>] ? retint_restore_args+0xe/0xe
[ 1044.042900]  [<ffffffff8106b4e0>] ? kthreadd+0x1e0/0x1e0
[ 1044.042902]  [<ffffffff8168d990>] ? gs_change+0xb/0xb

Signed-off-by: Yong Zhang <yong.zhang0@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1341476476-5666-1-git-send-email-yong.zhang0@gmail.com
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
@ghollingworth

This comment has been minimized.

Show comment
Hide comment
@ghollingworth

ghollingworth Aug 22, 2013

Contributor

Many USB issues fixed... Please reopen if still a problem

Contributor

ghollingworth commented Aug 22, 2013

Many USB issues fixed... Please reopen if still a problem

popcornmix pushed a commit that referenced this issue Oct 8, 2014

NFSD: Put the reference of nfs4_file when freeing stid
After testing nfs4 lock, I restart the nfsd service, got messages as,

[ 5677.403419] nfsd: last server has exited, flushing export cache
[ 5677.463728] =============================================================================
[ 5677.463942] BUG nfsd4_files (Tainted: G    B      OE): Objects remaining in nfsd4_files on kmem_cache_close()
[ 5677.464055] -----------------------------------------------------------------------------

[ 5677.464203] INFO: Slab 0xffffea0000233400 objects=28 used=1 fp=0xffff880008cd3d98 flags=0x3ffc0000004080
[ 5677.464318] CPU: 0 PID: 3772 Comm: rmmod Tainted: G    B      OE 3.16.0-rc2+ #29
[ 5677.464420] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/31/2013
[ 5677.464538]  0000000000000000 0000000036af2c9f ffff88000ce97d68 ffffffff816eacfa
[ 5677.464643]  ffffea0000233400 ffff88000ce97e40 ffffffff811cda44 ffffffff00000020
[ 5677.464774]  ffff88000ce97e50 ffff88000ce97e00 656a624f00000008 616d657220737463
[ 5677.464875] Call Trace:
[ 5677.464925]  [<ffffffff816eacfa>] dump_stack+0x45/0x56
[ 5677.464983]  [<ffffffff811cda44>] slab_err+0xb4/0xe0
[ 5677.465040]  [<ffffffff811d0457>] ? __kmalloc+0x117/0x290
[ 5677.465099]  [<ffffffff81100eec>] ? on_each_cpu_cond+0xac/0xf0
[ 5677.465158]  [<ffffffff811d1bc0>] ? kmem_cache_close+0x110/0x2e0
[ 5677.465218]  [<ffffffff811d1be0>] kmem_cache_close+0x130/0x2e0
[ 5677.465279]  [<ffffffff8135a0c1>] ? kobject_cleanup+0x91/0x1b0
[ 5677.465338]  [<ffffffff811d22be>] __kmem_cache_shutdown+0xe/0x10
[ 5677.465399]  [<ffffffff8119bd28>] kmem_cache_destroy+0x48/0x100
[ 5677.465466]  [<ffffffffa05ef78d>] nfsd4_free_slabs+0x2d/0x50 [nfsd]
[ 5677.465530]  [<ffffffffa05fa987>] exit_nfsd+0x34/0x6ad [nfsd]
[ 5677.465589]  [<ffffffff81104ac2>] SyS_delete_module+0x162/0x200
[ 5677.465649]  [<ffffffff81013b69>] ? do_notify_resume+0x59/0x90
[ 5677.465759]  [<ffffffff816f2369>] system_call_fastpath+0x16/0x1b
[ 5677.465822] INFO: Object 0xffff880008cd0000 @offset=0
[ 5677.465882] INFO: Allocated in nfsd4_process_open1+0x61/0x350 [nfsd] age=7599 cpu=0 pid=3253
[ 5677.466115]  __slab_alloc+0x3b0/0x4b1
[ 5677.466166]  kmem_cache_alloc+0x1e4/0x240
[ 5677.466220]  nfsd4_process_open1+0x61/0x350 [nfsd]
[ 5677.466276]  nfsd4_open+0xee/0x860 [nfsd]
[ 5677.466329]  nfsd4_proc_compound+0x4d7/0x7f0 [nfsd]
[ 5677.466384]  nfsd_dispatch+0xbb/0x200 [nfsd]
[ 5677.466447]  svc_process_common+0x453/0x6f0 [sunrpc]
[ 5677.466506]  svc_process+0x103/0x170 [sunrpc]
[ 5677.466559]  nfsd+0x117/0x190 [nfsd]
[ 5677.466609]  kthread+0xd8/0xf0
[ 5677.466656]  ret_from_fork+0x7c/0xb0
[ 5677.466775] kmem_cache_destroy nfsd4_files: Slab cache still has objects
[ 5677.466839] CPU: 0 PID: 3772 Comm: rmmod Tainted: G    B      OE 3.16.0-rc2+ #29
[ 5677.466937] Hardware name: VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform, BIOS 6.00 07/31/2013
[ 5677.467049]  0000000000000000 0000000036af2c9f ffff88000ce97eb0 ffffffff816eacfa
[ 5677.467150]  ffff880020bb2d00 ffff88000ce97ed0 ffffffff8119bdd9 0000000000000000
[ 5677.467250]  ffffffffa06065c0 ffff88000ce97ee0 ffffffffa05ef78d ffff88000ce97ef0
[ 5677.467351] Call Trace:
[ 5677.467397]  [<ffffffff816eacfa>] dump_stack+0x45/0x56
[ 5677.467454]  [<ffffffff8119bdd9>] kmem_cache_destroy+0xf9/0x100
[ 5677.467516]  [<ffffffffa05ef78d>] nfsd4_free_slabs+0x2d/0x50 [nfsd]
[ 5677.467579]  [<ffffffffa05fa987>] exit_nfsd+0x34/0x6ad [nfsd]
[ 5677.467639]  [<ffffffff81104ac2>] SyS_delete_module+0x162/0x200
[ 5677.467765]  [<ffffffff81013b69>] ? do_notify_resume+0x59/0x90
[ 5677.467826]  [<ffffffff816f2369>] system_call_fastpath+0x16/0x1b

Signed-off-by: Kinglong Mee <kinglongmee@gmail.com>
Reviewed-by: Jeff Layton <jlayton@primarydata.com>
Fixes: 11b9164 "nfsd: Add a struct nfs4_file field to struct nfs4_stid"
Signed-off-by: J. Bruce Fields <bfields@redhat.com>

davet321 pushed a commit to davet321/rpi-linux that referenced this issue Aug 17, 2015

mm, vmscan: Do not wait for page writeback for GFP_NOFS allocations
commit ecf5fc6 upstream.

Nikolay has reported a hang when a memcg reclaim got stuck with the
following backtrace:

PID: 18308  TASK: ffff883d7c9b0a30  CPU: 1   COMMAND: "rsync"
  #0 __schedule at ffffffff815ab152
  #1 schedule at ffffffff815ab76e
  #2 schedule_timeout at ffffffff815ae5e5
  #3 io_schedule_timeout at ffffffff815aad6a
  #4 bit_wait_io at ffffffff815abfc6
  #5 __wait_on_bit at ffffffff815abda5
  #6 wait_on_page_bit at ffffffff8111fd4f
  #7 shrink_page_list at ffffffff81135445
  #8 shrink_inactive_list at ffffffff81135845
  #9 shrink_lruvec at ffffffff81135ead
 #10 shrink_zone at ffffffff811360c3
 #11 shrink_zones at ffffffff81136eff
 #12 do_try_to_free_pages at ffffffff8113712f
 #13 try_to_free_mem_cgroup_pages at ffffffff811372be
 #14 try_charge at ffffffff81189423
 #15 mem_cgroup_try_charge at ffffffff8118c6f5
 #16 __add_to_page_cache_locked at ffffffff8112137d
 #17 add_to_page_cache_lru at ffffffff81121618
 #18 pagecache_get_page at ffffffff8112170b
 #19 grow_dev_page at ffffffff811c8297
 #20 __getblk_slow at ffffffff811c91d6
 #21 __getblk_gfp at ffffffff811c92c1
 #22 ext4_ext_grow_indepth at ffffffff8124565c
 #23 ext4_ext_create_new_leaf at ffffffff81246ca8
 #24 ext4_ext_insert_extent at ffffffff81246f09
 #25 ext4_ext_map_blocks at ffffffff8124a848
 #26 ext4_map_blocks at ffffffff8121a5b7
 #27 mpage_map_one_extent at ffffffff8121b1fa
 #28 mpage_map_and_submit_extent at ffffffff8121f07b
 #29 ext4_writepages at ffffffff8121f6d5
 #30 do_writepages at ffffffff8112c490
 #31 __filemap_fdatawrite_range at ffffffff81120199
 #32 filemap_flush at ffffffff8112041c
 #33 ext4_alloc_da_blocks at ffffffff81219da1
 #34 ext4_rename at ffffffff81229b91
 #35 ext4_rename2 at ffffffff81229e32
 #36 vfs_rename at ffffffff811a08a5
 #37 SYSC_renameat2 at ffffffff811a3ffc
 #38 sys_renameat2 at ffffffff811a408e
 #39 sys_rename at ffffffff8119e51e
 #40 system_call_fastpath at ffffffff815afa89

Dave Chinner has properly pointed out that this is a deadlock in the
reclaim code because ext4 doesn't submit pages which are marked by
PG_writeback right away.

The heuristic was introduced by commit e62e384 ("memcg: prevent OOM
with too many dirty pages") and it was applied only when may_enter_fs
was specified.  The code has been changed by c3b94f4 ("memcg:
further prevent OOM with too many dirty pages") which has removed the
__GFP_FS restriction with a reasoning that we do not get into the fs
code.  But this is not sufficient apparently because the fs doesn't
necessarily submit pages marked PG_writeback for IO right away.

ext4_bio_write_page calls io_submit_add_bh but that doesn't necessarily
submit the bio.  Instead it tries to map more pages into the bio and
mpage_map_one_extent might trigger memcg charge which might end up
waiting on a page which is marked PG_writeback but hasn't been submitted
yet so we would end up waiting for something that never finishes.

Fix this issue by replacing __GFP_IO by may_enter_fs check (for case 2)
before we go to wait on the writeback.  The page fault path, which is
the only path that triggers memcg oom killer since 3.12, shouldn't
require GFP_NOFS and so we shouldn't reintroduce the premature OOM
killer issue which was originally addressed by the heuristic.

As per David Chinner the xfs is doing similar thing since 2.6.15 already
so ext4 is not the only affected filesystem.  Moreover he notes:

: For example: IO completion might require unwritten extent conversion
: which executes filesystem transactions and GFP_NOFS allocations. The
: writeback flag on the pages can not be cleared until unwritten
: extent conversion completes. Hence memory reclaim cannot wait on
: page writeback to complete in GFP_NOFS context because it is not
: safe to do so, memcg reclaim or otherwise.

Cc: stable@vger.kernel.org # 3.9+
[tytso@mit.edu: corrected the control flow]
Fixes: c3b94f4 ("memcg: further prevent OOM with too many dirty pages")
Reported-by: Nikolay Borisov <kernel@kyup.com>
Signed-off-by: Michal Hocko <mhocko@suse.cz>
Signed-off-by: Hugh Dickins <hughd@google.com>
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

popcornmix pushed a commit that referenced this issue Aug 20, 2015

mm, vmscan: Do not wait for page writeback for GFP_NOFS allocations
Nikolay has reported a hang when a memcg reclaim got stuck with the
following backtrace:

PID: 18308  TASK: ffff883d7c9b0a30  CPU: 1   COMMAND: "rsync"
  #0 __schedule at ffffffff815ab152
  #1 schedule at ffffffff815ab76e
  #2 schedule_timeout at ffffffff815ae5e5
  #3 io_schedule_timeout at ffffffff815aad6a
  #4 bit_wait_io at ffffffff815abfc6
  #5 __wait_on_bit at ffffffff815abda5
  #6 wait_on_page_bit at ffffffff8111fd4f
  #7 shrink_page_list at ffffffff81135445
  #8 shrink_inactive_list at ffffffff81135845
  #9 shrink_lruvec at ffffffff81135ead
 #10 shrink_zone at ffffffff811360c3
 #11 shrink_zones at ffffffff81136eff
 #12 do_try_to_free_pages at ffffffff8113712f
 #13 try_to_free_mem_cgroup_pages at ffffffff811372be
 #14 try_charge at ffffffff81189423
 #15 mem_cgroup_try_charge at ffffffff8118c6f5
 #16 __add_to_page_cache_locked at ffffffff8112137d
 #17 add_to_page_cache_lru at ffffffff81121618
 #18 pagecache_get_page at ffffffff8112170b
 #19 grow_dev_page at ffffffff811c8297
 #20 __getblk_slow at ffffffff811c91d6
 #21 __getblk_gfp at ffffffff811c92c1
 #22 ext4_ext_grow_indepth at ffffffff8124565c
 #23 ext4_ext_create_new_leaf at ffffffff81246ca8
 #24 ext4_ext_insert_extent at ffffffff81246f09
 #25 ext4_ext_map_blocks at ffffffff8124a848
 #26 ext4_map_blocks at ffffffff8121a5b7
 #27 mpage_map_one_extent at ffffffff8121b1fa
 #28 mpage_map_and_submit_extent at ffffffff8121f07b
 #29 ext4_writepages at ffffffff8121f6d5
 #30 do_writepages at ffffffff8112c490
 #31 __filemap_fdatawrite_range at ffffffff81120199
 #32 filemap_flush at ffffffff8112041c
 #33 ext4_alloc_da_blocks at ffffffff81219da1
 #34 ext4_rename at ffffffff81229b91
 #35 ext4_rename2 at ffffffff81229e32
 #36 vfs_rename at ffffffff811a08a5
 #37 SYSC_renameat2 at ffffffff811a3ffc
 #38 sys_renameat2 at ffffffff811a408e
 #39 sys_rename at ffffffff8119e51e
 #40 system_call_fastpath at ffffffff815afa89

Dave Chinner has properly pointed out that this is a deadlock in the
reclaim code because ext4 doesn't submit pages which are marked by
PG_writeback right away.

The heuristic was introduced by commit e62e384 ("memcg: prevent OOM
with too many dirty pages") and it was applied only when may_enter_fs
was specified.  The code has been changed by c3b94f4 ("memcg:
further prevent OOM with too many dirty pages") which has removed the
__GFP_FS restriction with a reasoning that we do not get into the fs
code.  But this is not sufficient apparently because the fs doesn't
necessarily submit pages marked PG_writeback for IO right away.

ext4_bio_write_page calls io_submit_add_bh but that doesn't necessarily
submit the bio.  Instead it tries to map more pages into the bio and
mpage_map_one_extent might trigger memcg charge which might end up
waiting on a page which is marked PG_writeback but hasn't been submitted
yet so we would end up waiting for something that never finishes.

Fix this issue by replacing __GFP_IO by may_enter_fs check (for case 2)
before we go to wait on the writeback.  The page fault path, which is
the only path that triggers memcg oom killer since 3.12, shouldn't
require GFP_NOFS and so we shouldn't reintroduce the premature OOM
killer issue which was originally addressed by the heuristic.

As per David Chinner the xfs is doing similar thing since 2.6.15 already
so ext4 is not the only affected filesystem.  Moreover he notes:

: For example: IO completion might require unwritten extent conversion
: which executes filesystem transactions and GFP_NOFS allocations. The
: writeback flag on the pages can not be cleared until unwritten
: extent conversion completes. Hence memory reclaim cannot wait on
: page writeback to complete in GFP_NOFS context because it is not
: safe to do so, memcg reclaim or otherwise.

Cc: stable@vger.kernel.org # 3.9+
[tytso@mit.edu: corrected the control flow]
Fixes: c3b94f4 ("memcg: further prevent OOM with too many dirty pages")
Reported-by: Nikolay Borisov <kernel@kyup.com>
Signed-off-by: Michal Hocko <mhocko@suse.cz>
Signed-off-by: Hugh Dickins <hughd@google.com>
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>

davet321 pushed a commit to davet321/rpi-linux that referenced this issue Dec 14, 2015

cgroup: fix handling of multi-destination migration from subtree_cont…
…rol enabling

Consider the following v2 hierarchy.

  P0 (+memory) --- P1 (-memory) --- A
                                 \- B
       
P0 has memory enabled in its subtree_control while P1 doesn't.  If
both A and B contain processes, they would belong to the memory css of
P1.  Now if memory is enabled on P1's subtree_control, memory csses
should be created on both A and B and A's processes should be moved to
the former and B's processes the latter.  IOW, enabling controllers
can cause atomic migrations into different csses.

The core cgroup migration logic has been updated accordingly but the
controller migration methods haven't and still assume that all tasks
migrate to a single target css; furthermore, the methods were fed the
css in which subtree_control was updated which is the parent of the
target csses.  pids controller depends on the migration methods to
move charges and this made the controller attribute charges to the
wrong csses often triggering the following warning by driving a
counter negative.

 WARNING: CPU: 1 PID: 1 at kernel/cgroup_pids.c:97 pids_cancel.constprop.6+0x31/0x40()
 Modules linked in:
 CPU: 1 PID: 1 Comm: systemd Not tainted 4.4.0-rc1+ #29
 ...
  ffffffff81f65382 ffff88007c043b90 ffffffff81551ffc 0000000000000000
  ffff88007c043bc8 ffffffff810de202 ffff88007a752000 ffff88007a29ab00
  ffff88007c043c80 ffff88007a1d8400 0000000000000001 ffff88007c043bd8
 Call Trace:
  [<ffffffff81551ffc>] dump_stack+0x4e/0x82
  [<ffffffff810de202>] warn_slowpath_common+0x82/0xc0
  [<ffffffff810de2fa>] warn_slowpath_null+0x1a/0x20
  [<ffffffff8118e031>] pids_cancel.constprop.6+0x31/0x40
  [<ffffffff8118e0fd>] pids_can_attach+0x6d/0xf0
  [<ffffffff81188a4c>] cgroup_taskset_migrate+0x6c/0x330
  [<ffffffff81188e05>] cgroup_migrate+0xf5/0x190
  [<ffffffff81189016>] cgroup_attach_task+0x176/0x200
  [<ffffffff8118949d>] __cgroup_procs_write+0x2ad/0x460
  [<ffffffff81189684>] cgroup_procs_write+0x14/0x20
  [<ffffffff811854e5>] cgroup_file_write+0x35/0x1c0
  [<ffffffff812e26f1>] kernfs_fop_write+0x141/0x190
  [<ffffffff81265f88>] __vfs_write+0x28/0xe0
  [<ffffffff812666fc>] vfs_write+0xac/0x1a0
  [<ffffffff81267019>] SyS_write+0x49/0xb0
  [<ffffffff81bcef32>] entry_SYSCALL_64_fastpath+0x12/0x76

This patch fixes the bug by removing @css parameter from the three
migration methods, ->can_attach, ->cancel_attach() and ->attach() and
updating cgroup_taskset iteration helpers also return the destination
css in addition to the task being migrated.  All controllers are
updated accordingly.

* Controllers which don't care whether there are one or multiple
  target csses can be converted trivially.  cpu, io, freezer, perf,
  netclassid and netprio fall in this category.

* cpuset's current implementation assumes that there's single source
  and destination and thus doesn't support v2 hierarchy already.  The
  only change made by this patchset is how that single destination css
  is obtained.

* memory migration path already doesn't do anything on v2.  How the
  single destination css is obtained is updated and the prep stage of
  mem_cgroup_can_attach() is reordered to accomodate the change.

* pids is the only controller which was affected by this bug.  It now
  correctly handles multi-destination migrations and no longer causes
  counter underflow from incorrect accounting.

Signed-off-by: Tejun Heo <tj@kernel.org>
Reported-and-tested-by: Daniel Wagner <daniel.wagner@bmw-carit.de>
Cc: Aleksa Sarai <cyphar@cyphar.com>

giraldeau pushed a commit to giraldeau/linux that referenced this issue Apr 12, 2016

Yong Zhang Sebastian Andrzej Siewior
perf: Make swevent hrtimer run in irq instead of softirq
Otherwise we get a deadlock like below:

[ 1044.042749] BUG: scheduling while atomic: ksoftirqd/21/141/0x00010003
[ 1044.042752] INFO: lockdep is turned off.
[ 1044.042754] Modules linked in:
[ 1044.042757] Pid: 141, comm: ksoftirqd/21 Tainted: G        W    3.4.0-rc2-rt3-23676-ga723175-dirty #29
[ 1044.042759] Call Trace:
[ 1044.042761]  <IRQ>  [<ffffffff8107d8e5>] __schedule_bug+0x65/0x80
[ 1044.042770]  [<ffffffff8168978c>] __schedule+0x83c/0xa70
[ 1044.042775]  [<ffffffff8106bdd2>] ? prepare_to_wait+0x32/0xb0
[ 1044.042779]  [<ffffffff81689a5e>] schedule+0x2e/0xa0
[ 1044.042782]  [<ffffffff81071ebd>] hrtimer_wait_for_timer+0x6d/0xb0
[ 1044.042786]  [<ffffffff8106bb30>] ? wake_up_bit+0x40/0x40
[ 1044.042790]  [<ffffffff81071f20>] hrtimer_cancel+0x20/0x40
[ 1044.042794]  [<ffffffff8111da0c>] perf_swevent_cancel_hrtimer+0x3c/0x50
[ 1044.042798]  [<ffffffff8111da31>] task_clock_event_stop+0x11/0x40
[ 1044.042802]  [<ffffffff8111da6e>] task_clock_event_del+0xe/0x10
[ 1044.042805]  [<ffffffff8111c568>] event_sched_out+0x118/0x1d0
[ 1044.042809]  [<ffffffff8111c649>] group_sched_out+0x29/0x90
[ 1044.042813]  [<ffffffff8111ed7e>] __perf_event_disable+0x18e/0x200
[ 1044.042817]  [<ffffffff8111c343>] remote_function+0x63/0x70
[ 1044.042821]  [<ffffffff810b0aae>] generic_smp_call_function_single_interrupt+0xce/0x120
[ 1044.042826]  [<ffffffff81022bc7>] smp_call_function_single_interrupt+0x27/0x40
[ 1044.042831]  [<ffffffff8168d50c>] call_function_single_interrupt+0x6c/0x80
[ 1044.042833]  <EOI>  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042840]  [<ffffffff8168b970>] ? _raw_spin_unlock_irq+0x30/0x70
[ 1044.042844]  [<ffffffff8168b976>] ? _raw_spin_unlock_irq+0x36/0x70
[ 1044.042848]  [<ffffffff810702e2>] run_hrtimer_softirq+0xc2/0x200
[ 1044.042853]  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042857]  [<ffffffff81045265>] __do_softirq_common+0xf5/0x3a0
[ 1044.042862]  [<ffffffff81045c3d>] __thread_do_softirq+0x15d/0x200
[ 1044.042865]  [<ffffffff81045dda>] run_ksoftirqd+0xfa/0x210
[ 1044.042869]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042873]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042877]  [<ffffffff8106b596>] kthread+0xb6/0xc0
[ 1044.042881]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042886]  [<ffffffff8168d994>] kernel_thread_helper+0x4/0x10
[ 1044.042889]  [<ffffffff8107d98c>] ? finish_task_switch+0x8c/0x110
[ 1044.042894]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042897]  [<ffffffff8168bd5d>] ? retint_restore_args+0xe/0xe
[ 1044.042900]  [<ffffffff8106b4e0>] ? kthreadd+0x1e0/0x1e0
[ 1044.042902]  [<ffffffff8168d990>] ? gs_change+0xb/0xb

Signed-off-by: Yong Zhang <yong.zhang0@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1341476476-5666-1-git-send-email-yong.zhang0@gmail.com
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

mlyle added a commit to d-ronin/linux that referenced this issue Aug 21, 2016

perf: Make swevent hrtimer run in irq instead of softirq
Otherwise we get a deadlock like below:

[ 1044.042749] BUG: scheduling while atomic: ksoftirqd/21/141/0x00010003
[ 1044.042752] INFO: lockdep is turned off.
[ 1044.042754] Modules linked in:
[ 1044.042757] Pid: 141, comm: ksoftirqd/21 Tainted: G        W    3.4.0-rc2-rt3-23676-ga723175-dirty #29
[ 1044.042759] Call Trace:
[ 1044.042761]  <IRQ>  [<ffffffff8107d8e5>] __schedule_bug+0x65/0x80
[ 1044.042770]  [<ffffffff8168978c>] __schedule+0x83c/0xa70
[ 1044.042775]  [<ffffffff8106bdd2>] ? prepare_to_wait+0x32/0xb0
[ 1044.042779]  [<ffffffff81689a5e>] schedule+0x2e/0xa0
[ 1044.042782]  [<ffffffff81071ebd>] hrtimer_wait_for_timer+0x6d/0xb0
[ 1044.042786]  [<ffffffff8106bb30>] ? wake_up_bit+0x40/0x40
[ 1044.042790]  [<ffffffff81071f20>] hrtimer_cancel+0x20/0x40
[ 1044.042794]  [<ffffffff8111da0c>] perf_swevent_cancel_hrtimer+0x3c/0x50
[ 1044.042798]  [<ffffffff8111da31>] task_clock_event_stop+0x11/0x40
[ 1044.042802]  [<ffffffff8111da6e>] task_clock_event_del+0xe/0x10
[ 1044.042805]  [<ffffffff8111c568>] event_sched_out+0x118/0x1d0
[ 1044.042809]  [<ffffffff8111c649>] group_sched_out+0x29/0x90
[ 1044.042813]  [<ffffffff8111ed7e>] __perf_event_disable+0x18e/0x200
[ 1044.042817]  [<ffffffff8111c343>] remote_function+0x63/0x70
[ 1044.042821]  [<ffffffff810b0aae>] generic_smp_call_function_single_interrupt+0xce/0x120
[ 1044.042826]  [<ffffffff81022bc7>] smp_call_function_single_interrupt+0x27/0x40
[ 1044.042831]  [<ffffffff8168d50c>] call_function_single_interrupt+0x6c/0x80
[ 1044.042833]  <EOI>  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042840]  [<ffffffff8168b970>] ? _raw_spin_unlock_irq+0x30/0x70
[ 1044.042844]  [<ffffffff8168b976>] ? _raw_spin_unlock_irq+0x36/0x70
[ 1044.042848]  [<ffffffff810702e2>] run_hrtimer_softirq+0xc2/0x200
[ 1044.042853]  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042857]  [<ffffffff81045265>] __do_softirq_common+0xf5/0x3a0
[ 1044.042862]  [<ffffffff81045c3d>] __thread_do_softirq+0x15d/0x200
[ 1044.042865]  [<ffffffff81045dda>] run_ksoftirqd+0xfa/0x210
[ 1044.042869]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042873]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042877]  [<ffffffff8106b596>] kthread+0xb6/0xc0
[ 1044.042881]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042886]  [<ffffffff8168d994>] kernel_thread_helper+0x4/0x10
[ 1044.042889]  [<ffffffff8107d98c>] ? finish_task_switch+0x8c/0x110
[ 1044.042894]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042897]  [<ffffffff8168bd5d>] ? retint_restore_args+0xe/0xe
[ 1044.042900]  [<ffffffff8106b4e0>] ? kthreadd+0x1e0/0x1e0
[ 1044.042902]  [<ffffffff8168d990>] ? gs_change+0xb/0xb

Signed-off-by: Yong Zhang <yong.zhang0@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1341476476-5666-1-git-send-email-yong.zhang0@gmail.com
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

popcornmix pushed a commit that referenced this issue Mar 27, 2017

inet: frag: release spinlock before calling icmp_send()
Dmitry reported a lockdep splat [1] (false positive) that we can fix
by releasing the spinlock before calling icmp_send() from ip_expire()

This is a false positive because sending an ICMP message can not
possibly re-enter the IP frag engine.

[1]
[ INFO: possible circular locking dependency detected ]
4.10.0+ #29 Not tainted
-------------------------------------------------------
modprobe/12392 is trying to acquire lock:
 (_xmit_ETHER#2){+.-...}, at: [<ffffffff837a8182>] spin_lock
include/linux/spinlock.h:299 [inline]
 (_xmit_ETHER#2){+.-...}, at: [<ffffffff837a8182>] __netif_tx_lock
include/linux/netdevice.h:3486 [inline]
 (_xmit_ETHER#2){+.-...}, at: [<ffffffff837a8182>]
sch_direct_xmit+0x282/0x6d0 net/sched/sch_generic.c:180

but task is already holding lock:
 (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>] spin_lock
include/linux/spinlock.h:299 [inline]
 (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>]
ip_expire+0x51/0x6c0 net/ipv4/ip_fragment.c:201

which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

-> #1 (&(&q->lock)->rlock){+.-...}:
       validate_chain kernel/locking/lockdep.c:2267 [inline]
       __lock_acquire+0x2149/0x3430 kernel/locking/lockdep.c:3340
       lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3755
       __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
       _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
       spin_lock include/linux/spinlock.h:299 [inline]
       ip_defrag+0x3a2/0x4130 net/ipv4/ip_fragment.c:669
       ip_check_defrag+0x4e3/0x8b0 net/ipv4/ip_fragment.c:713
       packet_rcv_fanout+0x282/0x800 net/packet/af_packet.c:1459
       deliver_skb net/core/dev.c:1834 [inline]
       dev_queue_xmit_nit+0x294/0xa90 net/core/dev.c:1890
       xmit_one net/core/dev.c:2903 [inline]
       dev_hard_start_xmit+0x16b/0xab0 net/core/dev.c:2923
       sch_direct_xmit+0x31f/0x6d0 net/sched/sch_generic.c:182
       __dev_xmit_skb net/core/dev.c:3092 [inline]
       __dev_queue_xmit+0x13e5/0x1e60 net/core/dev.c:3358
       dev_queue_xmit+0x17/0x20 net/core/dev.c:3423
       neigh_resolve_output+0x6b9/0xb10 net/core/neighbour.c:1308
       neigh_output include/net/neighbour.h:478 [inline]
       ip_finish_output2+0x8b8/0x15a0 net/ipv4/ip_output.c:228
       ip_do_fragment+0x1d93/0x2720 net/ipv4/ip_output.c:672
       ip_fragment.constprop.54+0x145/0x200 net/ipv4/ip_output.c:545
       ip_finish_output+0x82d/0xe10 net/ipv4/ip_output.c:314
       NF_HOOK_COND include/linux/netfilter.h:246 [inline]
       ip_output+0x1f0/0x7a0 net/ipv4/ip_output.c:404
       dst_output include/net/dst.h:486 [inline]
       ip_local_out+0x95/0x170 net/ipv4/ip_output.c:124
       ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1492
       ip_push_pending_frames+0x64/0x80 net/ipv4/ip_output.c:1512
       raw_sendmsg+0x26de/0x3a00 net/ipv4/raw.c:655
       inet_sendmsg+0x164/0x5b0 net/ipv4/af_inet.c:761
       sock_sendmsg_nosec net/socket.c:633 [inline]
       sock_sendmsg+0xca/0x110 net/socket.c:643
       ___sys_sendmsg+0x4a3/0x9f0 net/socket.c:1985
       __sys_sendmmsg+0x25c/0x750 net/socket.c:2075
       SYSC_sendmmsg net/socket.c:2106 [inline]
       SyS_sendmmsg+0x35/0x60 net/socket.c:2101
       do_syscall_64+0x2e8/0x930 arch/x86/entry/common.c:281
       return_from_SYSCALL_64+0x0/0x7a

-> #0 (_xmit_ETHER#2){+.-...}:
       check_prev_add kernel/locking/lockdep.c:1830 [inline]
       check_prevs_add+0xa8f/0x19f0 kernel/locking/lockdep.c:1940
       validate_chain kernel/locking/lockdep.c:2267 [inline]
       __lock_acquire+0x2149/0x3430 kernel/locking/lockdep.c:3340
       lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3755
       __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
       _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
       spin_lock include/linux/spinlock.h:299 [inline]
       __netif_tx_lock include/linux/netdevice.h:3486 [inline]
       sch_direct_xmit+0x282/0x6d0 net/sched/sch_generic.c:180
       __dev_xmit_skb net/core/dev.c:3092 [inline]
       __dev_queue_xmit+0x13e5/0x1e60 net/core/dev.c:3358
       dev_queue_xmit+0x17/0x20 net/core/dev.c:3423
       neigh_hh_output include/net/neighbour.h:468 [inline]
       neigh_output include/net/neighbour.h:476 [inline]
       ip_finish_output2+0xf6c/0x15a0 net/ipv4/ip_output.c:228
       ip_finish_output+0xa29/0xe10 net/ipv4/ip_output.c:316
       NF_HOOK_COND include/linux/netfilter.h:246 [inline]
       ip_output+0x1f0/0x7a0 net/ipv4/ip_output.c:404
       dst_output include/net/dst.h:486 [inline]
       ip_local_out+0x95/0x170 net/ipv4/ip_output.c:124
       ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1492
       ip_push_pending_frames+0x64/0x80 net/ipv4/ip_output.c:1512
       icmp_push_reply+0x372/0x4d0 net/ipv4/icmp.c:394
       icmp_send+0x156c/0x1c80 net/ipv4/icmp.c:754
       ip_expire+0x40e/0x6c0 net/ipv4/ip_fragment.c:239
       call_timer_fn+0x241/0x820 kernel/time/timer.c:1268
       expire_timers kernel/time/timer.c:1307 [inline]
       __run_timers+0x960/0xcf0 kernel/time/timer.c:1601
       run_timer_softirq+0x21/0x80 kernel/time/timer.c:1614
       __do_softirq+0x31f/0xbe7 kernel/softirq.c:284
       invoke_softirq kernel/softirq.c:364 [inline]
       irq_exit+0x1cc/0x200 kernel/softirq.c:405
       exiting_irq arch/x86/include/asm/apic.h:657 [inline]
       smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:962
       apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:707
       __read_once_size include/linux/compiler.h:254 [inline]
       atomic_read arch/x86/include/asm/atomic.h:26 [inline]
       rcu_dynticks_curr_cpu_in_eqs kernel/rcu/tree.c:350 [inline]
       __rcu_is_watching kernel/rcu/tree.c:1133 [inline]
       rcu_is_watching+0x83/0x110 kernel/rcu/tree.c:1147
       rcu_read_lock_held+0x87/0xc0 kernel/rcu/update.c:293
       radix_tree_deref_slot include/linux/radix-tree.h:238 [inline]
       filemap_map_pages+0x6d4/0x1570 mm/filemap.c:2335
       do_fault_around mm/memory.c:3231 [inline]
       do_read_fault mm/memory.c:3265 [inline]
       do_fault+0xbd5/0x2080 mm/memory.c:3370
       handle_pte_fault mm/memory.c:3600 [inline]
       __handle_mm_fault+0x1062/0x2cb0 mm/memory.c:3714
       handle_mm_fault+0x1e2/0x480 mm/memory.c:3751
       __do_page_fault+0x4f6/0xb60 arch/x86/mm/fault.c:1397
       do_page_fault+0x54/0x70 arch/x86/mm/fault.c:1460
       page_fault+0x28/0x30 arch/x86/entry/entry_64.S:1011

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&(&q->lock)->rlock);
                               lock(_xmit_ETHER#2);
                               lock(&(&q->lock)->rlock);
  lock(_xmit_ETHER#2);

 *** DEADLOCK ***

10 locks held by modprobe/12392:
 #0:  (&mm->mmap_sem){++++++}, at: [<ffffffff81329758>]
__do_page_fault+0x2b8/0xb60 arch/x86/mm/fault.c:1336
 #1:  (rcu_read_lock){......}, at: [<ffffffff8188cab6>]
filemap_map_pages+0x1e6/0x1570 mm/filemap.c:2324
 #2:  (&(ptlock_ptr(page))->rlock#2){+.+...}, at: [<ffffffff81984a78>]
spin_lock include/linux/spinlock.h:299 [inline]
 #2:  (&(ptlock_ptr(page))->rlock#2){+.+...}, at: [<ffffffff81984a78>]
pte_alloc_one_map mm/memory.c:2944 [inline]
 #2:  (&(ptlock_ptr(page))->rlock#2){+.+...}, at: [<ffffffff81984a78>]
alloc_set_pte+0x13b8/0x1b90 mm/memory.c:3072
 #3:  (((&q->timer))){+.-...}, at: [<ffffffff81627e72>]
lockdep_copy_map include/linux/lockdep.h:175 [inline]
 #3:  (((&q->timer))){+.-...}, at: [<ffffffff81627e72>]
call_timer_fn+0x1c2/0x820 kernel/time/timer.c:1258
 #4:  (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>] spin_lock
include/linux/spinlock.h:299 [inline]
 #4:  (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>]
ip_expire+0x51/0x6c0 net/ipv4/ip_fragment.c:201
 #5:  (rcu_read_lock){......}, at: [<ffffffff8389a633>]
ip_expire+0x1b3/0x6c0 net/ipv4/ip_fragment.c:216
 #6:  (slock-AF_INET){+.-...}, at: [<ffffffff839b3313>] spin_trylock
include/linux/spinlock.h:309 [inline]
 #6:  (slock-AF_INET){+.-...}, at: [<ffffffff839b3313>] icmp_xmit_lock
net/ipv4/icmp.c:219 [inline]
 #6:  (slock-AF_INET){+.-...}, at: [<ffffffff839b3313>]
icmp_send+0x803/0x1c80 net/ipv4/icmp.c:681
 #7:  (rcu_read_lock_bh){......}, at: [<ffffffff838ab9a1>]
ip_finish_output2+0x2c1/0x15a0 net/ipv4/ip_output.c:198
 #8:  (rcu_read_lock_bh){......}, at: [<ffffffff836d1dee>]
__dev_queue_xmit+0x23e/0x1e60 net/core/dev.c:3324
 #9:  (dev->qdisc_running_key ?: &qdisc_running_key){+.....}, at:
[<ffffffff836d3a27>] dev_queue_xmit+0x17/0x20 net/core/dev.c:3423

stack backtrace:
CPU: 0 PID: 12392 Comm: modprobe Not tainted 4.10.0+ #29
Hardware name: Google Google Compute Engine/Google Compute Engine,
BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x2ee/0x3ef lib/dump_stack.c:52
 print_circular_bug+0x307/0x3b0 kernel/locking/lockdep.c:1204
 check_prev_add kernel/locking/lockdep.c:1830 [inline]
 check_prevs_add+0xa8f/0x19f0 kernel/locking/lockdep.c:1940
 validate_chain kernel/locking/lockdep.c:2267 [inline]
 __lock_acquire+0x2149/0x3430 kernel/locking/lockdep.c:3340
 lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3755
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
 spin_lock include/linux/spinlock.h:299 [inline]
 __netif_tx_lock include/linux/netdevice.h:3486 [inline]
 sch_direct_xmit+0x282/0x6d0 net/sched/sch_generic.c:180
 __dev_xmit_skb net/core/dev.c:3092 [inline]
 __dev_queue_xmit+0x13e5/0x1e60 net/core/dev.c:3358
 dev_queue_xmit+0x17/0x20 net/core/dev.c:3423
 neigh_hh_output include/net/neighbour.h:468 [inline]
 neigh_output include/net/neighbour.h:476 [inline]
 ip_finish_output2+0xf6c/0x15a0 net/ipv4/ip_output.c:228
 ip_finish_output+0xa29/0xe10 net/ipv4/ip_output.c:316
 NF_HOOK_COND include/linux/netfilter.h:246 [inline]
 ip_output+0x1f0/0x7a0 net/ipv4/ip_output.c:404
 dst_output include/net/dst.h:486 [inline]
 ip_local_out+0x95/0x170 net/ipv4/ip_output.c:124
 ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1492
 ip_push_pending_frames+0x64/0x80 net/ipv4/ip_output.c:1512
 icmp_push_reply+0x372/0x4d0 net/ipv4/icmp.c:394
 icmp_send+0x156c/0x1c80 net/ipv4/icmp.c:754
 ip_expire+0x40e/0x6c0 net/ipv4/ip_fragment.c:239
 call_timer_fn+0x241/0x820 kernel/time/timer.c:1268
 expire_timers kernel/time/timer.c:1307 [inline]
 __run_timers+0x960/0xcf0 kernel/time/timer.c:1601
 run_timer_softirq+0x21/0x80 kernel/time/timer.c:1614
 __do_softirq+0x31f/0xbe7 kernel/softirq.c:284
 invoke_softirq kernel/softirq.c:364 [inline]
 irq_exit+0x1cc/0x200 kernel/softirq.c:405
 exiting_irq arch/x86/include/asm/apic.h:657 [inline]
 smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:962
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:707
RIP: 0010:__read_once_size include/linux/compiler.h:254 [inline]
RIP: 0010:atomic_read arch/x86/include/asm/atomic.h:26 [inline]
RIP: 0010:rcu_dynticks_curr_cpu_in_eqs kernel/rcu/tree.c:350 [inline]
RIP: 0010:__rcu_is_watching kernel/rcu/tree.c:1133 [inline]
RIP: 0010:rcu_is_watching+0x83/0x110 kernel/rcu/tree.c:1147
RSP: 0000:ffff8801c391f120 EFLAGS: 00000a03 ORIG_RAX: ffffffffffffff10
RAX: dffffc0000000000 RBX: ffff8801c391f148 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 000055edd4374000 RDI: ffff8801dbe1ae0c
RBP: ffff8801c391f1a0 R08: 0000000000000002 R09: 0000000000000000
R10: dffffc0000000000 R11: 0000000000000002 R12: 1ffff10038723e25
R13: ffff8801dbe1ae00 R14: ffff8801c391f680 R15: dffffc0000000000
 </IRQ>
 rcu_read_lock_held+0x87/0xc0 kernel/rcu/update.c:293
 radix_tree_deref_slot include/linux/radix-tree.h:238 [inline]
 filemap_map_pages+0x6d4/0x1570 mm/filemap.c:2335
 do_fault_around mm/memory.c:3231 [inline]
 do_read_fault mm/memory.c:3265 [inline]
 do_fault+0xbd5/0x2080 mm/memory.c:3370
 handle_pte_fault mm/memory.c:3600 [inline]
 __handle_mm_fault+0x1062/0x2cb0 mm/memory.c:3714
 handle_mm_fault+0x1e2/0x480 mm/memory.c:3751
 __do_page_fault+0x4f6/0xb60 arch/x86/mm/fault.c:1397
 do_page_fault+0x54/0x70 arch/x86/mm/fault.c:1460
 page_fault+0x28/0x30 arch/x86/entry/entry_64.S:1011
RIP: 0033:0x7f83172f2786
RSP: 002b:00007fffe859ae80 EFLAGS: 00010293
RAX: 000055edd4373040 RBX: 00007f83175111c8 RCX: 000055edd4373238
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00007f8317510970
RBP: 00007fffe859afd0 R08: 0000000000000009 R09: 0000000000000000
R10: 0000000000000064 R11: 0000000000000000 R12: 000055edd4373040
R13: 0000000000000000 R14: 00007fffe859afe8 R15: 0000000000000000

Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Dmitry Vyukov <dvyukov@google.com>
Signed-off-by: David S. Miller <davem@davemloft.net>

popcornmix pushed a commit that referenced this issue Sep 29, 2017

ALSA: seq: Cancel pending autoload work at unbinding device
commit fc27fe7 upstream.

ALSA sequencer core has a mechanism to load the enumerated devices
automatically, and it's performed in an off-load work.  This seems
causing some race when a sequencer is removed while the pending
autoload work is running.  As syzkaller spotted, it may lead to some
use-after-free:
  BUG: KASAN: use-after-free in snd_rawmidi_dev_seq_free+0x69/0x70
  sound/core/rawmidi.c:1617
  Write of size 8 at addr ffff88006c611d90 by task kworker/2:1/567

  CPU: 2 PID: 567 Comm: kworker/2:1 Not tainted 4.13.0+ #29
  Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
  Workqueue: events autoload_drivers
  Call Trace:
   __dump_stack lib/dump_stack.c:16 [inline]
   dump_stack+0x192/0x22c lib/dump_stack.c:52
   print_address_description+0x78/0x280 mm/kasan/report.c:252
   kasan_report_error mm/kasan/report.c:351 [inline]
   kasan_report+0x230/0x340 mm/kasan/report.c:409
   __asan_report_store8_noabort+0x1c/0x20 mm/kasan/report.c:435
   snd_rawmidi_dev_seq_free+0x69/0x70 sound/core/rawmidi.c:1617
   snd_seq_dev_release+0x4f/0x70 sound/core/seq_device.c:192
   device_release+0x13f/0x210 drivers/base/core.c:814
   kobject_cleanup lib/kobject.c:648 [inline]
   kobject_release lib/kobject.c:677 [inline]
   kref_put include/linux/kref.h:70 [inline]
   kobject_put+0x145/0x240 lib/kobject.c:694
   put_device+0x25/0x30 drivers/base/core.c:1799
   klist_devices_put+0x36/0x40 drivers/base/bus.c:827
   klist_next+0x264/0x4a0 lib/klist.c:403
   next_device drivers/base/bus.c:270 [inline]
   bus_for_each_dev+0x17e/0x210 drivers/base/bus.c:312
   autoload_drivers+0x3b/0x50 sound/core/seq_device.c:117
   process_one_work+0x9fb/0x1570 kernel/workqueue.c:2097
   worker_thread+0x1e4/0x1350 kernel/workqueue.c:2231
   kthread+0x324/0x3f0 kernel/kthread.c:231
   ret_from_fork+0x25/0x30 arch/x86/entry/entry_64.S:425

The fix is simply to assure canceling the autoload work at removing
the device.

Reported-by: Andrey Konovalov <andreyknvl@google.com>
Tested-by: Andrey Konovalov <andreyknvl@google.com>
Signed-off-by: Takashi Iwai <tiwai@suse.de>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

popcornmix pushed a commit that referenced this issue Nov 18, 2017

ALSA: seq: Cancel pending autoload work at unbinding device
commit fc27fe7 upstream.

ALSA sequencer core has a mechanism to load the enumerated devices
automatically, and it's performed in an off-load work.  This seems
causing some race when a sequencer is removed while the pending
autoload work is running.  As syzkaller spotted, it may lead to some
use-after-free:
  BUG: KASAN: use-after-free in snd_rawmidi_dev_seq_free+0x69/0x70
  sound/core/rawmidi.c:1617
  Write of size 8 at addr ffff88006c611d90 by task kworker/2:1/567

  CPU: 2 PID: 567 Comm: kworker/2:1 Not tainted 4.13.0+ #29
  Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
  Workqueue: events autoload_drivers
  Call Trace:
   __dump_stack lib/dump_stack.c:16 [inline]
   dump_stack+0x192/0x22c lib/dump_stack.c:52
   print_address_description+0x78/0x280 mm/kasan/report.c:252
   kasan_report_error mm/kasan/report.c:351 [inline]
   kasan_report+0x230/0x340 mm/kasan/report.c:409
   __asan_report_store8_noabort+0x1c/0x20 mm/kasan/report.c:435
   snd_rawmidi_dev_seq_free+0x69/0x70 sound/core/rawmidi.c:1617
   snd_seq_dev_release+0x4f/0x70 sound/core/seq_device.c:192
   device_release+0x13f/0x210 drivers/base/core.c:814
   kobject_cleanup lib/kobject.c:648 [inline]
   kobject_release lib/kobject.c:677 [inline]
   kref_put include/linux/kref.h:70 [inline]
   kobject_put+0x145/0x240 lib/kobject.c:694
   put_device+0x25/0x30 drivers/base/core.c:1799
   klist_devices_put+0x36/0x40 drivers/base/bus.c:827
   klist_next+0x264/0x4a0 lib/klist.c:403
   next_device drivers/base/bus.c:270 [inline]
   bus_for_each_dev+0x17e/0x210 drivers/base/bus.c:312
   autoload_drivers+0x3b/0x50 sound/core/seq_device.c:117
   process_one_work+0x9fb/0x1570 kernel/workqueue.c:2097
   worker_thread+0x1e4/0x1350 kernel/workqueue.c:2231
   kthread+0x324/0x3f0 kernel/kthread.c:231
   ret_from_fork+0x25/0x30 arch/x86/entry/entry_64.S:425

The fix is simply to assure canceling the autoload work at removing
the device.

Reported-by: Andrey Konovalov <andreyknvl@google.com>
Tested-by: Andrey Konovalov <andreyknvl@google.com>
Signed-off-by: Takashi Iwai <tiwai@suse.de>
Cc: Ben Hutchings <ben.hutchings@codethink.co.uk>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

Jajcus added a commit to Jajcus/rpi-kernel-rt that referenced this issue Dec 20, 2017

perf: Make swevent hrtimer run in irq instead of softirq
Otherwise we get a deadlock like below:

[ 1044.042749] BUG: scheduling while atomic: ksoftirqd/21/141/0x00010003
[ 1044.042752] INFO: lockdep is turned off.
[ 1044.042754] Modules linked in:
[ 1044.042757] Pid: 141, comm: ksoftirqd/21 Tainted: G        W    3.4.0-rc2-rt3-23676-ga723175-dirty #29
[ 1044.042759] Call Trace:
[ 1044.042761]  <IRQ>  [<ffffffff8107d8e5>] __schedule_bug+0x65/0x80
[ 1044.042770]  [<ffffffff8168978c>] __schedule+0x83c/0xa70
[ 1044.042775]  [<ffffffff8106bdd2>] ? prepare_to_wait+0x32/0xb0
[ 1044.042779]  [<ffffffff81689a5e>] schedule+0x2e/0xa0
[ 1044.042782]  [<ffffffff81071ebd>] hrtimer_wait_for_timer+0x6d/0xb0
[ 1044.042786]  [<ffffffff8106bb30>] ? wake_up_bit+0x40/0x40
[ 1044.042790]  [<ffffffff81071f20>] hrtimer_cancel+0x20/0x40
[ 1044.042794]  [<ffffffff8111da0c>] perf_swevent_cancel_hrtimer+0x3c/0x50
[ 1044.042798]  [<ffffffff8111da31>] task_clock_event_stop+0x11/0x40
[ 1044.042802]  [<ffffffff8111da6e>] task_clock_event_del+0xe/0x10
[ 1044.042805]  [<ffffffff8111c568>] event_sched_out+0x118/0x1d0
[ 1044.042809]  [<ffffffff8111c649>] group_sched_out+0x29/0x90
[ 1044.042813]  [<ffffffff8111ed7e>] __perf_event_disable+0x18e/0x200
[ 1044.042817]  [<ffffffff8111c343>] remote_function+0x63/0x70
[ 1044.042821]  [<ffffffff810b0aae>] generic_smp_call_function_single_interrupt+0xce/0x120
[ 1044.042826]  [<ffffffff81022bc7>] smp_call_function_single_interrupt+0x27/0x40
[ 1044.042831]  [<ffffffff8168d50c>] call_function_single_interrupt+0x6c/0x80
[ 1044.042833]  <EOI>  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042840]  [<ffffffff8168b970>] ? _raw_spin_unlock_irq+0x30/0x70
[ 1044.042844]  [<ffffffff8168b976>] ? _raw_spin_unlock_irq+0x36/0x70
[ 1044.042848]  [<ffffffff810702e2>] run_hrtimer_softirq+0xc2/0x200
[ 1044.042853]  [<ffffffff811275b0>] ? perf_event_overflow+0x20/0x20
[ 1044.042857]  [<ffffffff81045265>] __do_softirq_common+0xf5/0x3a0
[ 1044.042862]  [<ffffffff81045c3d>] __thread_do_softirq+0x15d/0x200
[ 1044.042865]  [<ffffffff81045dda>] run_ksoftirqd+0xfa/0x210
[ 1044.042869]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042873]  [<ffffffff81045ce0>] ? __thread_do_softirq+0x200/0x200
[ 1044.042877]  [<ffffffff8106b596>] kthread+0xb6/0xc0
[ 1044.042881]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042886]  [<ffffffff8168d994>] kernel_thread_helper+0x4/0x10
[ 1044.042889]  [<ffffffff8107d98c>] ? finish_task_switch+0x8c/0x110
[ 1044.042894]  [<ffffffff8168b97b>] ? _raw_spin_unlock_irq+0x3b/0x70
[ 1044.042897]  [<ffffffff8168bd5d>] ? retint_restore_args+0xe/0xe
[ 1044.042900]  [<ffffffff8106b4e0>] ? kthreadd+0x1e0/0x1e0
[ 1044.042902]  [<ffffffff8168d990>] ? gs_change+0xb/0xb

Signed-off-by: Yong Zhang <yong.zhang0@gmail.com>
Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Steven Rostedt <rostedt@goodmis.org>
Link: http://lkml.kernel.org/r/1341476476-5666-1-git-send-email-yong.zhang0@gmail.com
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

popcornmix pushed a commit that referenced this issue Dec 29, 2017

inet: frag: release spinlock before calling icmp_send()
[ Upstream commit ec4fbd6 ]

Dmitry reported a lockdep splat [1] (false positive) that we can fix
by releasing the spinlock before calling icmp_send() from ip_expire()

This is a false positive because sending an ICMP message can not
possibly re-enter the IP frag engine.

[1]
[ INFO: possible circular locking dependency detected ]
4.10.0+ #29 Not tainted
-------------------------------------------------------
modprobe/12392 is trying to acquire lock:
 (_xmit_ETHER#2){+.-...}, at: [<ffffffff837a8182>] spin_lock
include/linux/spinlock.h:299 [inline]
 (_xmit_ETHER#2){+.-...}, at: [<ffffffff837a8182>] __netif_tx_lock
include/linux/netdevice.h:3486 [inline]
 (_xmit_ETHER#2){+.-...}, at: [<ffffffff837a8182>]
sch_direct_xmit+0x282/0x6d0 net/sched/sch_generic.c:180

but task is already holding lock:
 (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>] spin_lock
include/linux/spinlock.h:299 [inline]
 (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>]
ip_expire+0x51/0x6c0 net/ipv4/ip_fragment.c:201

which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

-> #1 (&(&q->lock)->rlock){+.-...}:
       validate_chain kernel/locking/lockdep.c:2267 [inline]
       __lock_acquire+0x2149/0x3430 kernel/locking/lockdep.c:3340
       lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3755
       __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
       _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
       spin_lock include/linux/spinlock.h:299 [inline]
       ip_defrag+0x3a2/0x4130 net/ipv4/ip_fragment.c:669
       ip_check_defrag+0x4e3/0x8b0 net/ipv4/ip_fragment.c:713
       packet_rcv_fanout+0x282/0x800 net/packet/af_packet.c:1459
       deliver_skb net/core/dev.c:1834 [inline]
       dev_queue_xmit_nit+0x294/0xa90 net/core/dev.c:1890
       xmit_one net/core/dev.c:2903 [inline]
       dev_hard_start_xmit+0x16b/0xab0 net/core/dev.c:2923
       sch_direct_xmit+0x31f/0x6d0 net/sched/sch_generic.c:182
       __dev_xmit_skb net/core/dev.c:3092 [inline]
       __dev_queue_xmit+0x13e5/0x1e60 net/core/dev.c:3358
       dev_queue_xmit+0x17/0x20 net/core/dev.c:3423
       neigh_resolve_output+0x6b9/0xb10 net/core/neighbour.c:1308
       neigh_output include/net/neighbour.h:478 [inline]
       ip_finish_output2+0x8b8/0x15a0 net/ipv4/ip_output.c:228
       ip_do_fragment+0x1d93/0x2720 net/ipv4/ip_output.c:672
       ip_fragment.constprop.54+0x145/0x200 net/ipv4/ip_output.c:545
       ip_finish_output+0x82d/0xe10 net/ipv4/ip_output.c:314
       NF_HOOK_COND include/linux/netfilter.h:246 [inline]
       ip_output+0x1f0/0x7a0 net/ipv4/ip_output.c:404
       dst_output include/net/dst.h:486 [inline]
       ip_local_out+0x95/0x170 net/ipv4/ip_output.c:124
       ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1492
       ip_push_pending_frames+0x64/0x80 net/ipv4/ip_output.c:1512
       raw_sendmsg+0x26de/0x3a00 net/ipv4/raw.c:655
       inet_sendmsg+0x164/0x5b0 net/ipv4/af_inet.c:761
       sock_sendmsg_nosec net/socket.c:633 [inline]
       sock_sendmsg+0xca/0x110 net/socket.c:643
       ___sys_sendmsg+0x4a3/0x9f0 net/socket.c:1985
       __sys_sendmmsg+0x25c/0x750 net/socket.c:2075
       SYSC_sendmmsg net/socket.c:2106 [inline]
       SyS_sendmmsg+0x35/0x60 net/socket.c:2101
       do_syscall_64+0x2e8/0x930 arch/x86/entry/common.c:281
       return_from_SYSCALL_64+0x0/0x7a

-> #0 (_xmit_ETHER#2){+.-...}:
       check_prev_add kernel/locking/lockdep.c:1830 [inline]
       check_prevs_add+0xa8f/0x19f0 kernel/locking/lockdep.c:1940
       validate_chain kernel/locking/lockdep.c:2267 [inline]
       __lock_acquire+0x2149/0x3430 kernel/locking/lockdep.c:3340
       lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3755
       __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
       _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
       spin_lock include/linux/spinlock.h:299 [inline]
       __netif_tx_lock include/linux/netdevice.h:3486 [inline]
       sch_direct_xmit+0x282/0x6d0 net/sched/sch_generic.c:180
       __dev_xmit_skb net/core/dev.c:3092 [inline]
       __dev_queue_xmit+0x13e5/0x1e60 net/core/dev.c:3358
       dev_queue_xmit+0x17/0x20 net/core/dev.c:3423
       neigh_hh_output include/net/neighbour.h:468 [inline]
       neigh_output include/net/neighbour.h:476 [inline]
       ip_finish_output2+0xf6c/0x15a0 net/ipv4/ip_output.c:228
       ip_finish_output+0xa29/0xe10 net/ipv4/ip_output.c:316
       NF_HOOK_COND include/linux/netfilter.h:246 [inline]
       ip_output+0x1f0/0x7a0 net/ipv4/ip_output.c:404
       dst_output include/net/dst.h:486 [inline]
       ip_local_out+0x95/0x170 net/ipv4/ip_output.c:124
       ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1492
       ip_push_pending_frames+0x64/0x80 net/ipv4/ip_output.c:1512
       icmp_push_reply+0x372/0x4d0 net/ipv4/icmp.c:394
       icmp_send+0x156c/0x1c80 net/ipv4/icmp.c:754
       ip_expire+0x40e/0x6c0 net/ipv4/ip_fragment.c:239
       call_timer_fn+0x241/0x820 kernel/time/timer.c:1268
       expire_timers kernel/time/timer.c:1307 [inline]
       __run_timers+0x960/0xcf0 kernel/time/timer.c:1601
       run_timer_softirq+0x21/0x80 kernel/time/timer.c:1614
       __do_softirq+0x31f/0xbe7 kernel/softirq.c:284
       invoke_softirq kernel/softirq.c:364 [inline]
       irq_exit+0x1cc/0x200 kernel/softirq.c:405
       exiting_irq arch/x86/include/asm/apic.h:657 [inline]
       smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:962
       apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:707
       __read_once_size include/linux/compiler.h:254 [inline]
       atomic_read arch/x86/include/asm/atomic.h:26 [inline]
       rcu_dynticks_curr_cpu_in_eqs kernel/rcu/tree.c:350 [inline]
       __rcu_is_watching kernel/rcu/tree.c:1133 [inline]
       rcu_is_watching+0x83/0x110 kernel/rcu/tree.c:1147
       rcu_read_lock_held+0x87/0xc0 kernel/rcu/update.c:293
       radix_tree_deref_slot include/linux/radix-tree.h:238 [inline]
       filemap_map_pages+0x6d4/0x1570 mm/filemap.c:2335
       do_fault_around mm/memory.c:3231 [inline]
       do_read_fault mm/memory.c:3265 [inline]
       do_fault+0xbd5/0x2080 mm/memory.c:3370
       handle_pte_fault mm/memory.c:3600 [inline]
       __handle_mm_fault+0x1062/0x2cb0 mm/memory.c:3714
       handle_mm_fault+0x1e2/0x480 mm/memory.c:3751
       __do_page_fault+0x4f6/0xb60 arch/x86/mm/fault.c:1397
       do_page_fault+0x54/0x70 arch/x86/mm/fault.c:1460
       page_fault+0x28/0x30 arch/x86/entry/entry_64.S:1011

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0                    CPU1
       ----                    ----
  lock(&(&q->lock)->rlock);
                               lock(_xmit_ETHER#2);
                               lock(&(&q->lock)->rlock);
  lock(_xmit_ETHER#2);

 *** DEADLOCK ***

10 locks held by modprobe/12392:
 #0:  (&mm->mmap_sem){++++++}, at: [<ffffffff81329758>]
__do_page_fault+0x2b8/0xb60 arch/x86/mm/fault.c:1336
 #1:  (rcu_read_lock){......}, at: [<ffffffff8188cab6>]
filemap_map_pages+0x1e6/0x1570 mm/filemap.c:2324
 #2:  (&(ptlock_ptr(page))->rlock#2){+.+...}, at: [<ffffffff81984a78>]
spin_lock include/linux/spinlock.h:299 [inline]
 #2:  (&(ptlock_ptr(page))->rlock#2){+.+...}, at: [<ffffffff81984a78>]
pte_alloc_one_map mm/memory.c:2944 [inline]
 #2:  (&(ptlock_ptr(page))->rlock#2){+.+...}, at: [<ffffffff81984a78>]
alloc_set_pte+0x13b8/0x1b90 mm/memory.c:3072
 #3:  (((&q->timer))){+.-...}, at: [<ffffffff81627e72>]
lockdep_copy_map include/linux/lockdep.h:175 [inline]
 #3:  (((&q->timer))){+.-...}, at: [<ffffffff81627e72>]
call_timer_fn+0x1c2/0x820 kernel/time/timer.c:1258
 #4:  (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>] spin_lock
include/linux/spinlock.h:299 [inline]
 #4:  (&(&q->lock)->rlock){+.-...}, at: [<ffffffff8389a4d1>]
ip_expire+0x51/0x6c0 net/ipv4/ip_fragment.c:201
 #5:  (rcu_read_lock){......}, at: [<ffffffff8389a633>]
ip_expire+0x1b3/0x6c0 net/ipv4/ip_fragment.c:216
 #6:  (slock-AF_INET){+.-...}, at: [<ffffffff839b3313>] spin_trylock
include/linux/spinlock.h:309 [inline]
 #6:  (slock-AF_INET){+.-...}, at: [<ffffffff839b3313>] icmp_xmit_lock
net/ipv4/icmp.c:219 [inline]
 #6:  (slock-AF_INET){+.-...}, at: [<ffffffff839b3313>]
icmp_send+0x803/0x1c80 net/ipv4/icmp.c:681
 #7:  (rcu_read_lock_bh){......}, at: [<ffffffff838ab9a1>]
ip_finish_output2+0x2c1/0x15a0 net/ipv4/ip_output.c:198
 #8:  (rcu_read_lock_bh){......}, at: [<ffffffff836d1dee>]
__dev_queue_xmit+0x23e/0x1e60 net/core/dev.c:3324
 #9:  (dev->qdisc_running_key ?: &qdisc_running_key){+.....}, at:
[<ffffffff836d3a27>] dev_queue_xmit+0x17/0x20 net/core/dev.c:3423

stack backtrace:
CPU: 0 PID: 12392 Comm: modprobe Not tainted 4.10.0+ #29
Hardware name: Google Google Compute Engine/Google Compute Engine,
BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:16 [inline]
 dump_stack+0x2ee/0x3ef lib/dump_stack.c:52
 print_circular_bug+0x307/0x3b0 kernel/locking/lockdep.c:1204
 check_prev_add kernel/locking/lockdep.c:1830 [inline]
 check_prevs_add+0xa8f/0x19f0 kernel/locking/lockdep.c:1940
 validate_chain kernel/locking/lockdep.c:2267 [inline]
 __lock_acquire+0x2149/0x3430 kernel/locking/lockdep.c:3340
 lock_acquire+0x2a1/0x630 kernel/locking/lockdep.c:3755
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x33/0x50 kernel/locking/spinlock.c:151
 spin_lock include/linux/spinlock.h:299 [inline]
 __netif_tx_lock include/linux/netdevice.h:3486 [inline]
 sch_direct_xmit+0x282/0x6d0 net/sched/sch_generic.c:180
 __dev_xmit_skb net/core/dev.c:3092 [inline]
 __dev_queue_xmit+0x13e5/0x1e60 net/core/dev.c:3358
 dev_queue_xmit+0x17/0x20 net/core/dev.c:3423
 neigh_hh_output include/net/neighbour.h:468 [inline]
 neigh_output include/net/neighbour.h:476 [inline]
 ip_finish_output2+0xf6c/0x15a0 net/ipv4/ip_output.c:228
 ip_finish_output+0xa29/0xe10 net/ipv4/ip_output.c:316
 NF_HOOK_COND include/linux/netfilter.h:246 [inline]
 ip_output+0x1f0/0x7a0 net/ipv4/ip_output.c:404
 dst_output include/net/dst.h:486 [inline]
 ip_local_out+0x95/0x170 net/ipv4/ip_output.c:124
 ip_send_skb+0x3c/0xc0 net/ipv4/ip_output.c:1492
 ip_push_pending_frames+0x64/0x80 net/ipv4/ip_output.c:1512
 icmp_push_reply+0x372/0x4d0 net/ipv4/icmp.c:394
 icmp_send+0x156c/0x1c80 net/ipv4/icmp.c:754
 ip_expire+0x40e/0x6c0 net/ipv4/ip_fragment.c:239
 call_timer_fn+0x241/0x820 kernel/time/timer.c:1268
 expire_timers kernel/time/timer.c:1307 [inline]
 __run_timers+0x960/0xcf0 kernel/time/timer.c:1601
 run_timer_softirq+0x21/0x80 kernel/time/timer.c:1614
 __do_softirq+0x31f/0xbe7 kernel/softirq.c:284
 invoke_softirq kernel/softirq.c:364 [inline]
 irq_exit+0x1cc/0x200 kernel/softirq.c:405
 exiting_irq arch/x86/include/asm/apic.h:657 [inline]
 smp_apic_timer_interrupt+0x76/0xa0 arch/x86/kernel/apic/apic.c:962
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:707
RIP: 0010:__read_once_size include/linux/compiler.h:254 [inline]
RIP: 0010:atomic_read arch/x86/include/asm/atomic.h:26 [inline]
RIP: 0010:rcu_dynticks_curr_cpu_in_eqs kernel/rcu/tree.c:350 [inline]
RIP: 0010:__rcu_is_watching kernel/rcu/tree.c:1133 [inline]
RIP: 0010:rcu_is_watching+0x83/0x110 kernel/rcu/tree.c:1147
RSP: 0000:ffff8801c391f120 EFLAGS: 00000a03 ORIG_RAX: ffffffffffffff10
RAX: dffffc0000000000 RBX: ffff8801c391f148 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 000055edd4374000 RDI: ffff8801dbe1ae0c
RBP: ffff8801c391f1a0 R08: 0000000000000002 R09: 0000000000000000
R10: dffffc0000000000 R11: 0000000000000002 R12: 1ffff10038723e25
R13: ffff8801dbe1ae00 R14: ffff8801c391f680 R15: dffffc0000000000
 </IRQ>
 rcu_read_lock_held+0x87/0xc0 kernel/rcu/update.c:293
 radix_tree_deref_slot include/linux/radix-tree.h:238 [inline]
 filemap_map_pages+0x6d4/0x1570 mm/filemap.c:2335
 do_fault_around mm/memory.c:3231 [inline]
 do_read_fault mm/memory.c:3265 [inline]
 do_fault+0xbd5/0x2080 mm/memory.c:3370
 handle_pte_fault mm/memory.c:3600 [inline]
 __handle_mm_fault+0x1062/0x2cb0 mm/memory.c:3714
 handle_mm_fault+0x1e2/0x480 mm/memory.c:3751
 __do_page_fault+0x4f6/0xb60 arch/x86/mm/fault.c:1397
 do_page_fault+0x54/0x70 arch/x86/mm/fault.c:1460
 page_fault+0x28/0x30 arch/x86/entry/entry_64.S:1011
RIP: 0033:0x7f83172f2786
RSP: 002b:00007fffe859ae80 EFLAGS: 00010293
RAX: 000055edd4373040 RBX: 00007f83175111c8 RCX: 000055edd4373238
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00007f8317510970
RBP: 00007fffe859afd0 R08: 0000000000000009 R09: 0000000000000000
R10: 0000000000000064 R11: 0000000000000000 R12: 000055edd4373040
R13: 0000000000000000 R14: 00007fffe859afe8 R15: 0000000000000000

Signed-off-by: Eric Dumazet <edumazet@google.com>
Reported-by: Dmitry Vyukov <dvyukov@google.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
Signed-off-by: Sasha Levin <alexander.levin@verizon.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

popcornmix pushed a commit that referenced this issue May 21, 2018

nsh: fix infinite loop
[ Upstream commit af50e4b ]

syzbot caught an infinite recursion in nsh_gso_segment().

Problem here is that we need to make sure the NSH header is of
reasonable length.

BUG: MAX_LOCK_DEPTH too low!
turning off the locking correctness validator.
depth: 48  max: 48!
48 locks held by syz-executor0/10189:
 #0:         (ptrval) (rcu_read_lock_bh){....}, at: __dev_queue_xmit+0x30f/0x34c0 net/core/dev.c:3517
 #1:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #1:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #2:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #2:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #3:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #3:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #4:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #4:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #5:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #5:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #6:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #6:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #7:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #7:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #8:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #8:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #9:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #9:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #10:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #10:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #11:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #11:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #12:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #12:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #13:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #13:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #14:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #14:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #15:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #15:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #16:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #16:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #17:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #17:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #18:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #18:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #19:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #19:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #20:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #20:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #21:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #21:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #22:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #22:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #23:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #23:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #24:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #24:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #25:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #25:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #26:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #26:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #27:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #27:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #28:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #28:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #29:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #29:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #30:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #30:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #31:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #31:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
dccp_close: ABORT with 65423 bytes unread
 #32:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #32:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #33:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #33:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #34:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #34:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #35:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #35:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #36:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #36:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #37:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #37:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #38:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #38:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #39:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #39:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #40:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #40:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #41:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #41:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #42:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #42:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #43:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #43:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #44:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #44:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #45:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #45:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #46:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #46:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #47:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #47:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
INFO: lockdep is turned off.
CPU: 1 PID: 10189 Comm: syz-executor0 Not tainted 4.17.0-rc2+ #26
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1b9/0x294 lib/dump_stack.c:113
 __lock_acquire+0x1788/0x5140 kernel/locking/lockdep.c:3449
 lock_acquire+0x1dc/0x520 kernel/locking/lockdep.c:3920
 rcu_lock_acquire include/linux/rcupdate.h:246 [inline]
 rcu_read_lock include/linux/rcupdate.h:632 [inline]
 skb_mac_gso_segment+0x25b/0x720 net/core/dev.c:2789
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 __skb_gso_segment+0x3bb/0x870 net/core/dev.c:2865
 skb_gso_segment include/linux/netdevice.h:4025 [inline]
 validate_xmit_skb+0x54d/0xd90 net/core/dev.c:3118
 validate_xmit_skb_list+0xbf/0x120 net/core/dev.c:3168
 sch_direct_xmit+0x354/0x11e0 net/sched/sch_generic.c:312
 qdisc_restart net/sched/sch_generic.c:399 [inline]
 __qdisc_run+0x741/0x1af0 net/sched/sch_generic.c:410
 __dev_xmit_skb net/core/dev.c:3243 [inline]
 __dev_queue_xmit+0x28ea/0x34c0 net/core/dev.c:3551
 dev_queue_xmit+0x17/0x20 net/core/dev.c:3616
 packet_snd net/packet/af_packet.c:2951 [inline]
 packet_sendmsg+0x40f8/0x6070 net/packet/af_packet.c:2976
 sock_sendmsg_nosec net/socket.c:629 [inline]
 sock_sendmsg+0xd5/0x120 net/socket.c:639
 __sys_sendto+0x3d7/0x670 net/socket.c:1789
 __do_sys_sendto net/socket.c:1801 [inline]
 __se_sys_sendto net/socket.c:1797 [inline]
 __x64_sys_sendto+0xe1/0x1a0 net/socket.c:1797
 do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
 entry_SYSCALL_64_after_hwframe+0x49/0xbe

Fixes: c411ed8 ("nsh: add GSO support")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Cc: Jiri Benc <jbenc@redhat.com>
Reported-by: syzbot <syzkaller@googlegroups.com>
Acked-by: Jiri Benc <jbenc@redhat.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

popcornmix pushed a commit that referenced this issue May 21, 2018

nsh: fix infinite loop
[ Upstream commit af50e4b ]

syzbot caught an infinite recursion in nsh_gso_segment().

Problem here is that we need to make sure the NSH header is of
reasonable length.

BUG: MAX_LOCK_DEPTH too low!
turning off the locking correctness validator.
depth: 48  max: 48!
48 locks held by syz-executor0/10189:
 #0:         (ptrval) (rcu_read_lock_bh){....}, at: __dev_queue_xmit+0x30f/0x34c0 net/core/dev.c:3517
 #1:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #1:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #2:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #2:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #3:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #3:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #4:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #4:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #5:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #5:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #6:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #6:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #7:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #7:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #8:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #8:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #9:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #9:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #10:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #10:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #11:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #11:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #12:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #12:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #13:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #13:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #14:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #14:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #15:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #15:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #16:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #16:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #17:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #17:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #18:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #18:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #19:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #19:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #20:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #20:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #21:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #21:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #22:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #22:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #23:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #23:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #24:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #24:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #25:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #25:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #26:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #26:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #27:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #27:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #28:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #28:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #29:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #29:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #30:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #30:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #31:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #31:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
dccp_close: ABORT with 65423 bytes unread
 #32:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #32:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #33:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #33:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #34:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #34:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #35:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #35:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #36:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #36:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #37:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #37:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #38:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #38:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #39:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #39:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #40:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #40:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #41:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #41:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #42:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #42:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #43:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #43:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #44:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #44:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #45:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #45:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #46:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #46:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
 #47:         (ptrval) (rcu_read_lock){....}, at: __skb_pull include/linux/skbuff.h:2080 [inline]
 #47:         (ptrval) (rcu_read_lock){....}, at: skb_mac_gso_segment+0x221/0x720 net/core/dev.c:2787
INFO: lockdep is turned off.
CPU: 1 PID: 10189 Comm: syz-executor0 Not tainted 4.17.0-rc2+ #26
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x1b9/0x294 lib/dump_stack.c:113
 __lock_acquire+0x1788/0x5140 kernel/locking/lockdep.c:3449
 lock_acquire+0x1dc/0x520 kernel/locking/lockdep.c:3920
 rcu_lock_acquire include/linux/rcupdate.h:246 [inline]
 rcu_read_lock include/linux/rcupdate.h:632 [inline]
 skb_mac_gso_segment+0x25b/0x720 net/core/dev.c:2789
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 nsh_gso_segment+0x405/0xb60 net/nsh/nsh.c:107
 skb_mac_gso_segment+0x3ad/0x720 net/core/dev.c:2792
 __skb_gso_segment+0x3bb/0x870 net/core/dev.c:2865
 skb_gso_segment include/linux/netdevice.h:4025 [inline]
 validate_xmit_skb+0x54d/0xd90 net/core/dev.c:3118
 validate_xmit_skb_list+0xbf/0x120 net/core/dev.c:3168
 sch_direct_xmit+0x354/0x11e0 net/sched/sch_generic.c:312
 qdisc_restart net/sched/sch_generic.c:399 [inline]
 __qdisc_run+0x741/0x1af0 net/sched/sch_generic.c:410
 __dev_xmit_skb net/core/dev.c:3243 [inline]
 __dev_queue_xmit+0x28ea/0x34c0 net/core/dev.c:3551
 dev_queue_xmit+0x17/0x20 net/core/dev.c:3616
 packet_snd net/packet/af_packet.c:2951 [inline]
 packet_sendmsg+0x40f8/0x6070 net/packet/af_packet.c:2976
 sock_sendmsg_nosec net/socket.c:629 [inline]
 sock_sendmsg+0xd5/0x120 net/socket.c:639
 __sys_sendto+0x3d7/0x670 net/socket.c:1789
 __do_sys_sendto net/socket.c:1801 [inline]
 __se_sys_sendto net/socket.c:1797 [inline]
 __x64_sys_sendto+0xe1/0x1a0 net/socket.c:1797
 do_syscall_64+0x1b1/0x800 arch/x86/entry/common.c:287
 entry_SYSCALL_64_after_hwframe+0x49/0xbe

Fixes: c411ed8 ("nsh: add GSO support")
Signed-off-by: Eric Dumazet <edumazet@google.com>
Cc: Jiri Benc <jbenc@redhat.com>
Reported-by: syzbot <syzkaller@googlegroups.com>
Acked-by: Jiri Benc <jbenc@redhat.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

popcornmix pushed a commit that referenced this issue Jul 25, 2018

scsi: qla2xxx: Fix NULL pointer dereference for fcport search
commit 36eb8ff672faee83ccce60c191f0fef07c6adce6 upstream.

Crash dump shows following instructions

crash> bt
PID: 0      TASK: ffffffffbe412480  CPU: 0   COMMAND: "swapper/0"
 #0 [ffff891ee0003868] machine_kexec at ffffffffbd063ef1
 #1 [ffff891ee00038c8] __crash_kexec at ffffffffbd12b6f2
 #2 [ffff891ee0003998] crash_kexec at ffffffffbd12c84c
 #3 [ffff891ee00039b8] oops_end at ffffffffbd030f0a
 #4 [ffff891ee00039e0] no_context at ffffffffbd074643
 #5 [ffff891ee0003a40] __bad_area_nosemaphore at ffffffffbd07496e
 #6 [ffff891ee0003a90] bad_area_nosemaphore at ffffffffbd074a64
 #7 [ffff891ee0003aa0] __do_page_fault at ffffffffbd074b0a
 #8 [ffff891ee0003b18] do_page_fault at ffffffffbd074fc8
 #9 [ffff891ee0003b50] page_fault at ffffffffbda01925
    [exception RIP: qlt_schedule_sess_for_deletion+15]
    RIP: ffffffffc02e526f  RSP: ffff891ee0003c08  RFLAGS: 00010046
    RAX: 0000000000000000  RBX: 0000000000000000  RCX: ffffffffc0307847
    RDX: 00000000000020e6  RSI: ffff891edbc377c8  RDI: 0000000000000000
    RBP: ffff891ee0003c18   R8: ffffffffc02f0b20   R9: 0000000000000250
    R10: 0000000000000258  R11: 000000000000b780  R12: ffff891ed9b43000
    R13: 00000000000000f0  R14: 0000000000000006  R15: ffff891edbc377c8
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #10 [ffff891ee0003c20] qla2x00_fcport_event_handler at ffffffffc02853d3 [qla2xxx]
 #11 [ffff891ee0003cf0] __dta_qla24xx_async_gnl_sp_done_333 at ffffffffc0285a1d [qla2xxx]
 #12 [ffff891ee0003de8] qla24xx_process_response_queue at ffffffffc02a2eb5 [qla2xxx]
 #13 [ffff891ee0003e88] qla24xx_msix_rsp_q at ffffffffc02a5403 [qla2xxx]
 #14 [ffff891ee0003ec0] __handle_irq_event_percpu at ffffffffbd0f4c59
 #15 [ffff891ee0003f10] handle_irq_event_percpu at ffffffffbd0f4e02
 #16 [ffff891ee0003f40] handle_irq_event at ffffffffbd0f4e90
 #17 [ffff891ee0003f68] handle_edge_irq at ffffffffbd0f8984
 #18 [ffff891ee0003f88] handle_irq at ffffffffbd0305d5
 #19 [ffff891ee0003fb8] do_IRQ at ffffffffbda02a18
 --- <IRQ stack> ---
 #20 [ffffffffbe403d30] ret_from_intr at ffffffffbda0094e
    [exception RIP: unknown or invalid address]
    RIP: 000000000000001f  RSP: 0000000000000000  RFLAGS: fff3b8c2091ebb3f
    RAX: ffffbba5a0000200  RBX: 0000be8cdfa8f9fa  RCX: 0000000000000018
    RDX: 0000000000000101  RSI: 000000000000015d  RDI: 0000000000000193
    RBP: 0000000000000083   R8: ffffffffbe403e38   R9: 0000000000000002
    R10: 0000000000000000  R11: ffffffffbe56b820  R12: ffff891ee001cf00
    R13: ffffffffbd11c0a4  R14: ffffffffbe403d60  R15: 0000000000000001
    ORIG_RAX: ffff891ee0022ac0  CS: 0000  SS: ffffffffffffffb9
 bt: WARNING: possibly bogus exception frame
 #21 [ffffffffbe403dd8] cpuidle_enter_state at ffffffffbd67c6fd
 #22 [ffffffffbe403e40] cpuidle_enter at ffffffffbd67c907
 #23 [ffffffffbe403e50] call_cpuidle at ffffffffbd0d98f3
 #24 [ffffffffbe403e60] do_idle at ffffffffbd0d9b42
 #25 [ffffffffbe403e98] cpu_startup_entry at ffffffffbd0d9da3
 #26 [ffffffffbe403ec0] rest_init at ffffffffbd81d4aa
 #27 [ffffffffbe403ed0] start_kernel at ffffffffbe67d2ca
 #28 [ffffffffbe403f28] x86_64_start_reservations at ffffffffbe67c675
 #29 [ffffffffbe403f38] x86_64_start_kernel at ffffffffbe67c6eb
 #30 [ffffffffbe403f50] secondary_startup_64 at ffffffffbd0000d5

Fixes: 040036b ("scsi: qla2xxx: Delay loop id allocation at login")
Cc: <stable@vger.kernel.org> # v4.17+
Signed-off-by: Chuck Anderson <chuck.anderson@oracle.com>
Signed-off-by: Himanshu Madhani <himanshu.madhani@cavium.com>
Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

popcornmix pushed a commit that referenced this issue Jul 30, 2018

scsi: qla2xxx: Fix NULL pointer dereference for fcport search
Crash dump shows following instructions

crash> bt
PID: 0      TASK: ffffffffbe412480  CPU: 0   COMMAND: "swapper/0"
 #0 [ffff891ee0003868] machine_kexec at ffffffffbd063ef1
 #1 [ffff891ee00038c8] __crash_kexec at ffffffffbd12b6f2
 #2 [ffff891ee0003998] crash_kexec at ffffffffbd12c84c
 #3 [ffff891ee00039b8] oops_end at ffffffffbd030f0a
 #4 [ffff891ee00039e0] no_context at ffffffffbd074643
 #5 [ffff891ee0003a40] __bad_area_nosemaphore at ffffffffbd07496e
 #6 [ffff891ee0003a90] bad_area_nosemaphore at ffffffffbd074a64
 #7 [ffff891ee0003aa0] __do_page_fault at ffffffffbd074b0a
 #8 [ffff891ee0003b18] do_page_fault at ffffffffbd074fc8
 #9 [ffff891ee0003b50] page_fault at ffffffffbda01925
    [exception RIP: qlt_schedule_sess_for_deletion+15]
    RIP: ffffffffc02e526f  RSP: ffff891ee0003c08  RFLAGS: 00010046
    RAX: 0000000000000000  RBX: 0000000000000000  RCX: ffffffffc0307847
    RDX: 00000000000020e6  RSI: ffff891edbc377c8  RDI: 0000000000000000
    RBP: ffff891ee0003c18   R8: ffffffffc02f0b20   R9: 0000000000000250
    R10: 0000000000000258  R11: 000000000000b780  R12: ffff891ed9b43000
    R13: 00000000000000f0  R14: 0000000000000006  R15: ffff891edbc377c8
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #10 [ffff891ee0003c20] qla2x00_fcport_event_handler at ffffffffc02853d3 [qla2xxx]
 #11 [ffff891ee0003cf0] __dta_qla24xx_async_gnl_sp_done_333 at ffffffffc0285a1d [qla2xxx]
 #12 [ffff891ee0003de8] qla24xx_process_response_queue at ffffffffc02a2eb5 [qla2xxx]
 #13 [ffff891ee0003e88] qla24xx_msix_rsp_q at ffffffffc02a5403 [qla2xxx]
 #14 [ffff891ee0003ec0] __handle_irq_event_percpu at ffffffffbd0f4c59
 #15 [ffff891ee0003f10] handle_irq_event_percpu at ffffffffbd0f4e02
 #16 [ffff891ee0003f40] handle_irq_event at ffffffffbd0f4e90
 #17 [ffff891ee0003f68] handle_edge_irq at ffffffffbd0f8984
 #18 [ffff891ee0003f88] handle_irq at ffffffffbd0305d5
 #19 [ffff891ee0003fb8] do_IRQ at ffffffffbda02a18
 --- <IRQ stack> ---
 #20 [ffffffffbe403d30] ret_from_intr at ffffffffbda0094e
    [exception RIP: unknown or invalid address]
    RIP: 000000000000001f  RSP: 0000000000000000  RFLAGS: fff3b8c2091ebb3f
    RAX: ffffbba5a0000200  RBX: 0000be8cdfa8f9fa  RCX: 0000000000000018
    RDX: 0000000000000101  RSI: 000000000000015d  RDI: 0000000000000193
    RBP: 0000000000000083   R8: ffffffffbe403e38   R9: 0000000000000002
    R10: 0000000000000000  R11: ffffffffbe56b820  R12: ffff891ee001cf00
    R13: ffffffffbd11c0a4  R14: ffffffffbe403d60  R15: 0000000000000001
    ORIG_RAX: ffff891ee0022ac0  CS: 0000  SS: ffffffffffffffb9
 bt: WARNING: possibly bogus exception frame
 #21 [ffffffffbe403dd8] cpuidle_enter_state at ffffffffbd67c6fd
 #22 [ffffffffbe403e40] cpuidle_enter at ffffffffbd67c907
 #23 [ffffffffbe403e50] call_cpuidle at ffffffffbd0d98f3
 #24 [ffffffffbe403e60] do_idle at ffffffffbd0d9b42
 #25 [ffffffffbe403e98] cpu_startup_entry at ffffffffbd0d9da3
 #26 [ffffffffbe403ec0] rest_init at ffffffffbd81d4aa
 #27 [ffffffffbe403ed0] start_kernel at ffffffffbe67d2ca
 #28 [ffffffffbe403f28] x86_64_start_reservations at ffffffffbe67c675
 #29 [ffffffffbe403f38] x86_64_start_kernel at ffffffffbe67c6eb
 #30 [ffffffffbe403f50] secondary_startup_64 at ffffffffbd0000d5

Fixes: 040036b ("scsi: qla2xxx: Delay loop id allocation at login")
Cc: <stable@vger.kernel.org> # v4.17+
Signed-off-by: Chuck Anderson <chuck.anderson@oracle.com>
Signed-off-by: Himanshu Madhani <himanshu.madhani@cavium.com>
Signed-off-by: Martin K. Petersen <martin.petersen@oracle.com>

popcornmix pushed a commit that referenced this issue Jul 30, 2018

Juri Lelli Ingo Molnar
sched/deadline: Fix switched_from_dl() warning
Mark noticed that syzkaller is able to reliably trigger the following warning:

  dl_rq->running_bw > dl_rq->this_bw
  WARNING: CPU: 1 PID: 153 at kernel/sched/deadline.c:124 switched_from_dl+0x454/0x608
  Kernel panic - not syncing: panic_on_warn set ...

  CPU: 1 PID: 153 Comm: syz-executor253 Not tainted 4.18.0-rc3+ #29
  Hardware name: linux,dummy-virt (DT)
  Call trace:
   dump_backtrace+0x0/0x458
   show_stack+0x20/0x30
   dump_stack+0x180/0x250
   panic+0x2dc/0x4ec
   __warn_printk+0x0/0x150
   report_bug+0x228/0x2d8
   bug_handler+0xa0/0x1a0
   brk_handler+0x2f0/0x568
   do_debug_exception+0x1bc/0x5d0
   el1_dbg+0x18/0x78
   switched_from_dl+0x454/0x608
   __sched_setscheduler+0x8cc/0x2018
   sys_sched_setattr+0x340/0x758
   el0_svc_naked+0x30/0x34

syzkaller reproducer runs a bunch of threads that constantly switch
between DEADLINE and NORMAL classes while interacting through futexes.

The splat above is caused by the fact that if a DEADLINE task is setattr
back to NORMAL while in non_contending state (blocked on a futex -
inactive timer armed), its contribution to running_bw is not removed
before sub_rq_bw() gets called (!task_on_rq_queued() branch) and the
latter sees running_bw > this_bw.

Fix it by removing a task contribution from running_bw if the task is
not queued and in non_contending state while switched to a different
class.

Reported-by: Mark Rutland <mark.rutland@arm.com>
Signed-off-by: Juri Lelli <juri.lelli@redhat.com>
Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
Reviewed-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Reviewed-by: Luca Abeni <luca.abeni@santannapisa.it>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: claudio@evidence.eu.com
Cc: rostedt@goodmis.org
Link: http://lkml.kernel.org/r/20180711072948.27061-1-juri.lelli@redhat.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment