broken access to a USB HID device after suspend

broken access to a USB HID device after suspend

[Tino Keitel]

Hi,

I use a tool called hidmon to control the parameters of my LCD in shell
scripts. I just had the case where this tool didn't work after suspend
to RAM. I just got this error message:

hid_force_open failed with return code 13

The kernel log contains lines like this:

usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110

Unplugging and replugging the USB cable of the LCD didn't work.
However, after a further suspend/resume cycle it works.

This is Linux 2.6.25-rc5. The behaviour is not repoducible, though.
However, I just mention it for the case that this might ring a bell
somewhere.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Jiri Kosina]

On Wed, 12 Mar 2008, Tino Keitel wrote:

> I use a tool called hidmon to control the parameters of my LCD in shell
> scripts. I just had the case where this tool didn't work after suspend
> to RAM. I just got this error message:
> 
> hid_force_open failed with return code 13
> 
> The kernel log contains lines like this:
> 
> usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110
> 
> Unplugging and replugging the USB cable of the LCD didn't work.
> However, after a further suspend/resume cycle it works.
> 
> This is Linux 2.6.25-rc5. The behaviour is not repoducible, though.
> However, I just mention it for the case that this might ring a bell
> somewhere.

This in fact looks like a problem with usbdevfs and/or libusb library, not 
the in-kernel HID drvier.

Did this work before? In 2.6.24? 2.6.23? Alan (added to CC, as well as USB 
devel mailinglist) has been doing some changes to usbdevfs to make it 
suspend-aware, if I recall correctly.

-- 
Jiri Kosina
SUSE Labs

Re: broken access to a USB HID device after suspend

[Alan Stern]

On Wed, 12 Mar 2008, Jiri Kosina wrote:

> On Wed, 12 Mar 2008, Tino Keitel wrote:
> 
> > I use a tool called hidmon to control the parameters of my LCD in shell
> > scripts. I just had the case where this tool didn't work after suspend
> > to RAM. I just got this error message:
> > 
> > hid_force_open failed with return code 13
> > 
> > The kernel log contains lines like this:
> > 
> > usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110
> > 
> > Unplugging and replugging the USB cable of the LCD didn't work.
> > However, after a further suspend/resume cycle it works.
> > 
> > This is Linux 2.6.25-rc5. The behaviour is not repoducible, though.
> > However, I just mention it for the case that this might ring a bell
> > somewhere.
> 
> This in fact looks like a problem with usbdevfs and/or libusb library, not 
> the in-kernel HID drvier.
> 
> Did this work before? In 2.6.24? 2.6.23? Alan (added to CC, as well as USB 
> devel mailinglist) has been doing some changes to usbdevfs to make it 
> suspend-aware, if I recall correctly.

No, usbfs hasn't undergone any significant changes recently.

Tino, it would help to see a kernel log showing what happened during 
the suspend, resume, and failure of hidmon.  It would help even more if 
you test under a kernel with CONFIG_USB_DEBUG enabled.

Even if you can't reproduce the problem, do you have the complete 
kernel log from before?

Is it possible that this is really a problem with the LCD device, not 
with the kernel?  I ask because if the device was working properly then 
unplugging and replugging the USB cable should do a complete reset.

Alan Stern

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Wed, Mar 12, 2008 at 17:44:56 -0400, Alan Stern wrote:

[...]

> Tino, it would help to see a kernel log showing what happened during 
> the suspend, resume, and failure of hidmon.  It would help even more if 
> you test under a kernel with CONFIG_USB_DEBUG enabled.

A full kernel log is available at http://tikei.de/dmesg

> 
> Even if you can't reproduce the problem, do you have the complete 
> kernel log from before?
> 
> Is it possible that this is really a problem with the LCD device, not 
> with the kernel?  I ask because if the device was working properly then 
> unplugging and replugging the USB cable should do a complete reset.

I did the following:

- suspended the computer

- switched off the LCD

- resumed the computer

- tried to use hidmon, got the error

- unplugged the LCD

- plugged in the LCD

- tried to use hidmon again, got the error again

- suspended the computer

- resumed the computer

- tried to use hidmon again, and it worked

Note that I didn't switch off the LCD during the second suspend, in the
case that matters.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Alan Stern]

On Wed, 12 Mar 2008, Tino Keitel wrote:

> On Wed, Mar 12, 2008 at 17:44:56 -0400, Alan Stern wrote:
> 
> [...]
> 
> > Tino, it would help to see a kernel log showing what happened during 
> > the suspend, resume, and failure of hidmon.  It would help even more if 
> > you test under a kernel with CONFIG_USB_DEBUG enabled.
> 
> A full kernel log is available at http://tikei.de/dmesg
> 
> > 
> > Even if you can't reproduce the problem, do you have the complete 
> > kernel log from before?
> > 
> > Is it possible that this is really a problem with the LCD device, not 
> > with the kernel?  I ask because if the device was working properly then 
> > unplugging and replugging the USB cable should do a complete reset.
> 
> I did the following:
> 
> - suspended the computer
> 
> - switched off the LCD

And switched it back on at some point?

> - resumed the computer
> 
> - tried to use hidmon, got the error
> 
> - unplugged the LCD
> 
> - plugged in the LCD
> 
> - tried to use hidmon again, got the error again
> 
> - suspended the computer
> 
> - resumed the computer
> 
> - tried to use hidmon again, and it worked
> 
> Note that I didn't switch off the LCD during the second suspend, in the
> case that matters.

Well, this isn't what your log shows.

According to the log, you booted the computer on March 10 and about 12 
minutes later started getting those -110 errors on the LCD device.  
Then you suspended the computer with no apparent problem.

Two days later you suspended three more times, and the the LCD monitor
was disconnected during the third suspend.  When it came back, you
started getting the errors again.

Next you unplugged and replugged the hub into which the LCD was 
connected.  Again there was another -110 error.  Finally you suspended 
and resumed.

To me that makes it look like the LCD's problems have no connection at
all with suspend/resume.

Alan Stern

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Thu, Mar 13, 2008 at 10:59:26 -0400, Alan Stern wrote:
> On Wed, 12 Mar 2008, Tino Keitel wrote:
> 
> > On Wed, Mar 12, 2008 at 17:44:56 -0400, Alan Stern wrote:
> > 
> > [...]
> > 
> > > Tino, it would help to see a kernel log showing what happened during 
> > > the suspend, resume, and failure of hidmon.  It would help even more if 
> > > you test under a kernel with CONFIG_USB_DEBUG enabled.
> > 
> > A full kernel log is available at http://tikei.de/dmesg
> > 
> > > 
> > > Even if you can't reproduce the problem, do you have the complete 
> > > kernel log from before?
> > > 
> > > Is it possible that this is really a problem with the LCD device, not 
> > > with the kernel?  I ask because if the device was working properly then 
> > > unplugging and replugging the USB cable should do a complete reset.
> > 
> > I did the following:
> > 
> > - suspended the computer
> > 
> > - switched off the LCD
> 
> And switched it back on at some point?

Err, yes, right after resume.

> 
> > - resumed the computer
> > 
> > - tried to use hidmon, got the error
> > 
> > - unplugged the LCD
> > 
> > - plugged in the LCD
> > 
> > - tried to use hidmon again, got the error again
> > 
> > - suspended the computer
> > 
> > - resumed the computer
> > 
> > - tried to use hidmon again, and it worked
> > 
> > Note that I didn't switch off the LCD during the second suspend, in the
> > case that matters.
> 
> Well, this isn't what your log shows.
> 
> According to the log, you booted the computer on March 10 and about 12 
> minutes later started getting those -110 errors on the LCD device.  

Uh, it looks like I just didn't noticed that.

> Then you suspended the computer with no apparent problem.
> 
> Two days later you suspended three more times, and the the LCD monitor
> was disconnected during the third suspend.  When it came back, you

What log message do you refer to here?

> started getting the errors again.
> 
> Next you unplugged and replugged the hub into which the LCD was 
> connected.  Again there was another -110 error.  Finally you suspended 
> and resumed.
> 
> To me that makes it look like the LCD's problems have no connection at
> all with suspend/resume.

Well, it seems to be "fixed" by a suspend/resume cycle. Do you have a
hint how I could try to fix it without suspend/resume, to test if it is
really the LCD's fault?

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Alan Stern]

On Thu, 13 Mar 2008, Tino Keitel wrote:

> > Then you suspended the computer with no apparent problem.
> > 
> > Two days later you suspended three more times, and the the LCD monitor
> > was disconnected during the third suspend.  When it came back, you
> 
> What log message do you refer to here?

The three resumes took place on March 12 at 05:21:02, 06:00:28, and 
19:20:08 (it's not always clear in the log what time the suspends took 
place).  The timestamp on the disconnect message is 19:20:09.37743.  In 
the next line the device was rediscovered.

> > To me that makes it look like the LCD's problems have no connection at
> > all with suspend/resume.
> 
> Well, it seems to be "fixed" by a suspend/resume cycle. Do you have a
> hint how I could try to fix it without suspend/resume, to test if it is
> really the LCD's fault?

Testing has to come before fixing -- you can't fix the problem if you
don't know which component is at fault.  For all we know, the hardware
could be fine and the problem could lie in your application.

All I can think of for testing is to use usbmon to record the data 
transfers when those -110 errors come up.

Alan Stern

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Thu, Mar 13, 2008 at 14:59:48 -0400, Alan Stern wrote:

[...]

> > Well, it seems to be "fixed" by a suspend/resume cycle. Do you have
> > a
> > hint how I could try to fix it without suspend/resume, to test if
> > it is
> > really the LCD's fault?
>
> Testing has to come before fixing -- you can't fix the problem if you
> don't know which component is at fault.  For all we know, the
> hardware
> could be fine and the problem could lie in your application.

I meant a method other than suspend/resume to fix the broken behaviour,
so that we get an indication where the problem exactly is.

>
> All I can think of for testing is to use usbmon to record the data
> transfers when those -110 errors come up.

Well, I still don't have USB_DEBUG or usbmon enabled, but I just got
that error again. I pulled the power plug from the LCD and replugged
it, without success. Then I did a suspend/resume cycle, and it worked.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Fri, Mar 14, 2008 at 08:13:36 +0100, Tino Keitel wrote:

[...]

> Well, I still don't have USB_DEBUG or usbmon enabled, but I just got
> that error again. I pulled the power plug from the LCD and replugged
> it, without success. Then I did a suspend/resume cycle, and it worked.

Forgot to mention: yesterday it was working, and the computer was
suspended overnight, without a reboot inbetween.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Alan Stern]

On Fri, 14 Mar 2008, Tino Keitel wrote:

> On Fri, Mar 14, 2008 at 08:13:36 +0100, Tino Keitel wrote:
> 
> [...]
> 
> > Well, I still don't have USB_DEBUG or usbmon enabled, but I just got
> > that error again. I pulled the power plug from the LCD and replugged
> > it, without success. Then I did a suspend/resume cycle, and it worked.
> 
> Forgot to mention: yesterday it was working, and the computer was
> suspended overnight, without a reboot inbetween.

I suspect the suspend/resume connection is misleading you, that it has 
nothing to do with the real problem.

Have you tried using the LCD device with a different computer?  It's 
worth a try, just to rule out the possibility that something is wrong 
with your computer's USB hardware.

Alan Stern

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Fri, Mar 14, 2008 at 10:36:06 -0400, Alan Stern wrote:

[...]

> Have you tried using the LCD device with a different computer?  It's 
> worth a try, just to rule out the possibility that something is wrong 
> with your computer's USB hardware.

OK. When it happens again, I'll plug the USB cable into my notebook and
try to use hidmon on the notebook.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Alan Stern]

On Fri, 14 Mar 2008, Tino Keitel wrote:

> On Thu, Mar 13, 2008 at 14:59:48 -0400, Alan Stern wrote:
> 
> [...]
> 
> > > Well, it seems to be "fixed" by a suspend/resume cycle. Do you have
> > > a
> > > hint how I could try to fix it without suspend/resume, to test if
> > > it is
> > > really the LCD's fault?
> >
> > Testing has to come before fixing -- you can't fix the problem if you
> > don't know which component is at fault.  For all we know, the
> > hardware
> > could be fine and the problem could lie in your application.
> 
> I meant a method other than suspend/resume to fix the broken behaviour,
> so that we get an indication where the problem exactly is.

There's the blunt-force method: Buy a new LCD device.  That's not 
entirely a joke; the information you have provided so far indicate a
fairly high probability that your device is broken.  (Although a new 
device might also be broken in exactly the same way...)

> > All I can think of for testing is to use usbmon to record the data
> > transfers when those -110 errors come up.
> 
> Well, I still don't have USB_DEBUG or usbmon enabled, but I just got
> that error again. I pulled the power plug from the LCD and replugged
> it, without success. Then I did a suspend/resume cycle, and it worked.

I was going to suggest that something might be going wrong with the
data toggles.  But if that were the problem then cycling the power on
the device would definitely have fixed it.

When you get these errors, do you exit from the hidmon program and 
restart it?  Do the errors still occur after restarting?

My earlier suggestions remain: Use CONFIG_USB_DEBUG and usbmon.  
However without knowing what requests the device will accept and what 
its responses ought to be, it will be very difficult to debug this
problem.

Alan Stern

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Fri, Mar 14, 2008 at 10:34:06 -0400, Alan Stern wrote:

[...]

> When you get these errors, do you exit from the hidmon program and 
> restart it?  Do the errors still occur after restarting?

Hidmon is a simple commandline application, something like hdparm for
LCD's. So, yes, I restarted it multiple times.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Fri, Mar 14, 2008 at 08:13:36 +0100, Tino Keitel wrote:
> On Thu, Mar 13, 2008 at 14:59:48 -0400, Alan Stern wrote:
> 
> [...]
> 
> > > Well, it seems to be "fixed" by a suspend/resume cycle. Do you have
> > > a
> > > hint how I could try to fix it without suspend/resume, to test if
> > > it is
> > > really the LCD's fault?
> >
> > Testing has to come before fixing -- you can't fix the problem if you
> > don't know which component is at fault.  For all we know, the
> > hardware
> > could be fine and the problem could lie in your application.
> 
> I meant a method other than suspend/resume to fix the broken behaviour,
> so that we get an indication where the problem exactly is.
> 
> >
> > All I can think of for testing is to use usbmon to record the data
> > transfers when those -110 errors come up.
> 
> Well, I still don't have USB_DEBUG or usbmon enabled, but I just got
> that error again. I pulled the power plug from the LCD and replugged
> it, without success. Then I did a suspend/resume cycle, and it worked.

Hi again,

I now have CONFIG_USB_DEBUG enabled, and the bug occurred again. Here
is the kernel log:

2008-03-18_19:08:50.59598 kern.debug: usb usb3: usb auto-resume
2008-03-18_19:08:50.59606 kern.debug: usb usb3: wakeup_rh
2008-03-18_19:08:50.62971 kern.debug: hub 3-0:1.0: hub_resume
2008-03-18_19:08:50.62977 kern.debug: hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
2008-03-18_19:08:50.62994 kern.debug: usb usb4: usb auto-resume
2008-03-18_19:08:50.62998 kern.debug: usb usb4: wakeup_rh
2008-03-18_19:08:50.66637 kern.debug: hub 4-0:1.0: hub_resume
2008-03-18_19:08:50.66644 kern.debug: hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
2008-03-18_19:08:50.66662 kern.debug: usb usb2: usb auto-resume
2008-03-18_19:08:50.66666 kern.debug: usb usb2: wakeup_rh
2008-03-18_19:08:50.70342 kern.debug: hub 2-0:1.0: hub_resume
2008-03-18_19:08:50.70348 kern.debug: hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0000
2008-03-18_19:08:51.84851 kern.debug: usb usb3: suspend_rh (auto-stop)
2008-03-18_19:08:51.84858 kern.debug: usb usb4: suspend_rh (auto-stop)
2008-03-18_19:08:51.84862 kern.debug: usb usb2: suspend_rh (auto-stop)
2008-03-18_19:08:53.34640 kern.debug: hub 3-0:1.0: hub_suspend
2008-03-18_19:08:53.34646 kern.debug: usb usb3: bus auto-suspend
2008-03-18_19:08:53.34650 kern.debug: usb usb3: suspend_rh
2008-03-18_19:08:53.34654 kern.debug: hub 4-0:1.0: hub_suspend
2008-03-18_19:08:53.34658 kern.debug: usb usb4: bus auto-suspend
2008-03-18_19:08:53.34662 kern.debug: usb usb4: suspend_rh
2008-03-18_19:08:53.34666 kern.debug: hub 2-0:1.0: hub_suspend
2008-03-18_19:08:53.34670 kern.debug: usb usb2: bus auto-suspend
2008-03-18_19:08:53.34674 kern.debug: usb usb2: suspend_rh
2008-03-18_19:09:00.70316 kern.debug: usb 1-1.3: hidmon timed out on ep0in len=0/9
2008-03-18_19:09:00.70322 kern.debug: usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110
2008-03-18_19:09:00.70339 kern.debug: usb 1-1.3: manual set_interface for iface 0, alt 0

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Alan Stern]

On Tue, 18 Mar 2008, Tino Keitel wrote:

> Hi again,
> 
> I now have CONFIG_USB_DEBUG enabled, and the bug occurred again. Here
> is the kernel log:
> 
> 2008-03-18_19:08:50.59598 kern.debug: usb usb3: usb auto-resume
> 2008-03-18_19:08:50.59606 kern.debug: usb usb3: wakeup_rh
> 2008-03-18_19:08:50.62971 kern.debug: hub 3-0:1.0: hub_resume
> 2008-03-18_19:08:50.62977 kern.debug: hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
> 2008-03-18_19:08:50.62994 kern.debug: usb usb4: usb auto-resume
> 2008-03-18_19:08:50.62998 kern.debug: usb usb4: wakeup_rh
> 2008-03-18_19:08:50.66637 kern.debug: hub 4-0:1.0: hub_resume
> 2008-03-18_19:08:50.66644 kern.debug: hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
> 2008-03-18_19:08:50.66662 kern.debug: usb usb2: usb auto-resume
> 2008-03-18_19:08:50.66666 kern.debug: usb usb2: wakeup_rh
> 2008-03-18_19:08:50.70342 kern.debug: hub 2-0:1.0: hub_resume
> 2008-03-18_19:08:50.70348 kern.debug: hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0000
> 2008-03-18_19:08:51.84851 kern.debug: usb usb3: suspend_rh (auto-stop)
> 2008-03-18_19:08:51.84858 kern.debug: usb usb4: suspend_rh (auto-stop)
> 2008-03-18_19:08:51.84862 kern.debug: usb usb2: suspend_rh (auto-stop)
> 2008-03-18_19:08:53.34640 kern.debug: hub 3-0:1.0: hub_suspend
> 2008-03-18_19:08:53.34646 kern.debug: usb usb3: bus auto-suspend
> 2008-03-18_19:08:53.34650 kern.debug: usb usb3: suspend_rh
> 2008-03-18_19:08:53.34654 kern.debug: hub 4-0:1.0: hub_suspend
> 2008-03-18_19:08:53.34658 kern.debug: usb usb4: bus auto-suspend
> 2008-03-18_19:08:53.34662 kern.debug: usb usb4: suspend_rh
> 2008-03-18_19:08:53.34666 kern.debug: hub 2-0:1.0: hub_suspend
> 2008-03-18_19:08:53.34670 kern.debug: usb usb2: bus auto-suspend
> 2008-03-18_19:08:53.34674 kern.debug: usb usb2: suspend_rh
> 2008-03-18_19:09:00.70316 kern.debug: usb 1-1.3: hidmon timed out on ep0in len=0/9
> 2008-03-18_19:09:00.70322 kern.debug: usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110
> 2008-03-18_19:09:00.70339 kern.debug: usb 1-1.3: manual set_interface for iface 0, alt 0

This isn't enough.  I need the log starting from before the suspend,
including _all_ the kernel messages, not just the debugging messages.  
I also need the usbmon trace.

Alan Stern

Re: broken access to a USB HID device after suspend

[Tino Keitel]

On Wed, Mar 12, 2008 at 22:23:46 +0100, Jiri Kosina wrote:
> On Wed, 12 Mar 2008, Tino Keitel wrote:
> 
> > I use a tool called hidmon to control the parameters of my LCD in shell
> > scripts. I just had the case where this tool didn't work after suspend
> > to RAM. I just got this error message:
> > 
> > hid_force_open failed with return code 13
> > 
> > The kernel log contains lines like this:
> > 
> > usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110
> > 
> > Unplugging and replugging the USB cable of the LCD didn't work.
> > However, after a further suspend/resume cycle it works.
> > 
> > This is Linux 2.6.25-rc5. The behaviour is not repoducible, though.
> > However, I just mention it for the case that this might ring a bell
> > somewhere.
> 
> This in fact looks like a problem with usbdevfs and/or libusb library, not 
> the in-kernel HID drvier.
> 
> Did this work before? In 2.6.24? 2.6.23? Alan (added to CC, as well as USB 

It worked in 2.6.24 and several 2.6.25-rc kernels, including the
currently running 2.6.25-rc5.

Regards,
Tino

Re: broken access to a USB HID device after suspend

[Jiri Kosina]

On Wed, 12 Mar 2008, Tino Keitel wrote:

> > > I use a tool called hidmon to control the parameters of my LCD in shell
> > > scripts. I just had the case where this tool didn't work after suspend
> > > to RAM. I just got this error message:
> > > 
> > > hid_force_open failed with return code 13
> > > 
> > > The kernel log contains lines like this:
> > > 
> > > usb 1-1.3: usbfs: USBDEVFS_CONTROL failed cmd hidmon rqt 129 rq 6 len 9 ret -110
> > > 
> > > Unplugging and replugging the USB cable of the LCD didn't work.
> > > However, after a further suspend/resume cycle it works.
> > > 
> > > This is Linux 2.6.25-rc5. The behaviour is not repoducible, though.
> > > However, I just mention it for the case that this might ring a bell
> > > somewhere.
> > 
> > This in fact looks like a problem with usbdevfs and/or libusb library, not 
> > the in-kernel HID drvier.
> > 
> > Did this work before? In 2.6.24? 2.6.23? Alan (added to CC, as well as USB 
> 
> It worked in 2.6.24 and several 2.6.25-rc kernels, including the
> currently running 2.6.25-rc5.

Please don't drop people and mailinglists from CC. It makes it hard to 
find your posts, if you do so.

I have restored it.

-- 
Jiri Kosina
SUSE Labs