Re: usbhid control queue full, due to stuck control request

Re: usbhid control queue full, due to stuck control request

[Oliver Neukum]

Am Samstag, 6. Februar 2010 18:20:52 schrieb David Fries:
> resubmit it.  While it does work, I don't consider this the right
> solution and it still leaves the UPS unmonitored for the nearly hour
> that it takes the control queue to fill up and trigger my routine.  The
> usb monitor doesn't say why the control request doesn't complete, just
> that it was submitted and didn't complete.
> 
> Any ideas?  I can try changes or enable other debugging, just keep in
> mind the time for this to reproduce, which could be a week or a month
> between stuck control requests.

Hi,

it seems we need to implement a timeout. Does this patch help?
Comments?

	Regards
		Oliver

>From 7b10f302c6caa940ea5ad67efb8a517923abfcc7 Mon Sep 17 00:00:00 2001
From: Oliver Neukum <oliver@neukum.org>
Date: Mon, 8 Feb 2010 12:44:14 +0100
Subject: [PATCH] HID: usbhid: implement a timeout for control requests

Some devices do not react to a control request.
Therefore request need a timeout.

Signed-off-by: Oliver Neukum <oliver@neukum.org>
---
 drivers/hid/usbhid/hid-core.c |   14 +++++++++++++-
 drivers/hid/usbhid/usbhid.h   |    1 +
 2 files changed, 14 insertions(+), 1 deletions(-)

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index e2997a8..2f12a5a 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c
@@ -316,6 +316,7 @@ static int hid_submit_out(struct hid_device *hid)
 			err_hid("usb_submit_urb(out) failed");
 			return -1;
 		}
+		usbhid->last_out = jiffies;
 	} else {
 		/*
 		 * queue work to wake up the device.
@@ -512,9 +513,20 @@ static void __usbhid_submit_report(struct hid_device *hid, struct hid_report *re
 		usbhid->out[usbhid->outhead].report = report;
 		usbhid->outhead = head;
 
-		if (!test_and_set_bit(HID_OUT_RUNNING, &usbhid->iofl))
+		if (!test_and_set_bit(HID_OUT_RUNNING, &usbhid->iofl)) {
 			if (hid_submit_out(hid))
 				clear_bit(HID_OUT_RUNNING, &usbhid->iofl);
+		} else {
+			/*
+			 * the queue is known to run
+			 * but an earlier request may be stuck
+			 * we may need to time out
+			 * no race because this is called under
+			 * spinlock
+			 */
+			if (time_after(jiffies, usbhid->last_out + HZ * 5))
+				usb_unlink_urb(usbhid->urbout);
+		}
 		return;
 	}
 
diff --git a/drivers/hid/usbhid/usbhid.h b/drivers/hid/usbhid/usbhid.h
index 08f505c..09831f9 100644
--- a/drivers/hid/usbhid/usbhid.h
+++ b/drivers/hid/usbhid/usbhid.h
@@ -96,6 +96,7 @@ struct usbhid_device {
 	struct work_struct restart_work;				/* waking up for output to be done in a task */
 	wait_queue_head_t wait;						/* For sleeping */
 	int ledcount;							/* counting the number of active leds */
+	unsigned long last_out;							/* record of last output for timeouts */
 };
 
 #define	hid_to_usb_dev(hid_dev) \
-- 
1.6.4.2

Re: usbhid control queue full, due to stuck control request

[David Fries]

On Mon, Feb 08, 2010 at 12:56:01PM +0100, Oliver Neukum wrote:
> Am Samstag, 6. Februar 2010 18:20:52 schrieb David Fries:
> > resubmit it.  While it does work, I don't consider this the right
> > solution and it still leaves the UPS unmonitored for the nearly hour
> > that it takes the control queue to fill up and trigger my routine.  The
> > usb monitor doesn't say why the control request doesn't complete, just
> > that it was submitted and didn't complete.
> > 
> > Any ideas?  I can try changes or enable other debugging, just keep in
> > mind the time for this to reproduce, which could be a week or a month
> > between stuck control requests.
> 
> Hi,
> 
> it seems we need to implement a timeout. Does this patch help?
> Comments?
> 
> 	Regards
> 		Oliver

Good solution, only it's urbctrl failing on me not urbout, no reason
not to do both of them.  Feel free to merge the patches into one.

I've added some additional print messages to tell me when the timeout
happens, and I'll watch for that.  Unfortunately it's a rare event and
might take a week or a month to happen.  I'll provide feedback again
when it happens, I don't know if you want to wait that long to submit
it upstream or not.

This does look good for my situation.  It's apcupsd polling the UPS
for battery, power status, etc.  A few seconds of missed reads doesn't
much matter, it is only looking for the latest data anyway.  I do
wonder for the control out or urb out cases if the current urb should
be retried instead of just silently dropped, again for other devices
that might depend on packets being complete and in order.

-- 
David Fries <david-CAZ2Ig26prheoWH0uzbU5w@public.gmane.org>
http://fries.net/~david/ (PGP encryption key available)

>From 4bf8e5d6d42891a6d01fee1b8f3bb674d8364843 Mon Sep 17 00:00:00 2001
From: David Fries <david-CAZ2Ig26prheoWH0uzbU5w@public.gmane.org>
Date: Mon, 8 Feb 2010 19:30:56 -0600
Subject: [PATCH] HID: usbhid: implement a timeout for control requests

Some devices do not react to a control request.
Therefore request need a timeout (control instead of output request).

Signed-off-by: David Fries <david-CAZ2Ig26prheoWH0uzbU5w@public.gmane.org>
---
 drivers/hid/usbhid/hid-core.c |   14 +++++++++++++-
 drivers/hid/usbhid/usbhid.h   |    3 ++-
 2 files changed, 15 insertions(+), 2 deletions(-)

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index b326edd..076a29a 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c
@@ -380,6 +380,7 @@ static int hid_submit_ctrl(struct hid_device *hid)
 			err_hid("usb_submit_urb(ctrl) failed");
 			return -1;
 		}
+		usbhid->last_ctrl = jiffies;
 	} else {
 		/*
 		 * queue work to wake up the device.
@@ -548,9 +549,20 @@ void __usbhid_submit_report(struct hid_device *hid, struct hid_report *report, u
 	usbhid->ctrl[usbhid->ctrlhead].dir = dir;
 	usbhid->ctrlhead = head;
 
-	if (!test_and_set_bit(HID_CTRL_RUNNING, &usbhid->iofl))
+	if (!test_and_set_bit(HID_CTRL_RUNNING, &usbhid->iofl)) {
 		if (hid_submit_ctrl(hid))
 			clear_bit(HID_CTRL_RUNNING, &usbhid->iofl);
+	} else {
+		/*
+		 * the queue is known to run
+		 * but an earlier request may be stuck
+		 * we may need to time out
+		 * no race because this is called under
+		 * spinlock
+		 */
+		if (time_after(jiffies, usbhid->last_ctrl + HZ * 5))
+			usb_unlink_urb(usbhid->urbctrl);
+	}
 }
 
 void usbhid_submit_report(struct hid_device *hid, struct hid_report *report, unsigned char dir)
diff --git a/drivers/hid/usbhid/usbhid.h b/drivers/hid/usbhid/usbhid.h
index 09831f9..ec20400 100644
--- a/drivers/hid/usbhid/usbhid.h
+++ b/drivers/hid/usbhid/usbhid.h
@@ -80,12 +80,14 @@ struct usbhid_device {
 	unsigned char ctrlhead, ctrltail;                               /* Control fifo head & tail */
 	char *ctrlbuf;                                                  /* Control buffer */
 	dma_addr_t ctrlbuf_dma;                                         /* Control buffer dma */
+	unsigned long last_ctrl;						/* record of last output for timeouts */
 
 	struct urb *urbout;                                             /* Output URB */
 	struct hid_output_fifo out[HID_CONTROL_FIFO_SIZE];              /* Output pipe fifo */
 	unsigned char outhead, outtail;                                 /* Output pipe fifo head & tail */
 	char *outbuf;                                                   /* Output buffer */
 	dma_addr_t outbuf_dma;                                          /* Output buffer dma */
+	unsigned long last_out;							/* record of last output for timeouts */
 
 	spinlock_t lock;						/* fifo spinlock */
 	unsigned long iofl;                                             /* I/O flags (CTRL_RUNNING, OUT_RUNNING) */
@@ -96,7 +98,6 @@ struct usbhid_device {
 	struct work_struct restart_work;				/* waking up for output to be done in a task */
 	wait_queue_head_t wait;						/* For sleeping */
 	int ledcount;							/* counting the number of active leds */
-	unsigned long last_out;							/* record of last output for timeouts */
 };
 
 #define	hid_to_usb_dev(hid_dev) \
-- 
1.5.6.5

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: usbhid control queue full, due to stuck control request

[David Fries]

On Mon, Feb 08, 2010 at 08:35:08PM -0600, David Fries wrote:
> On Mon, Feb 08, 2010 at 12:56:01PM +0100, Oliver Neukum wrote:
> > Am Samstag, 6. Februar 2010 18:20:52 schrieb David Fries:
> > > that it takes the control queue to fill up and trigger my routine.  The
> > > usb monitor doesn't say why the control request doesn't complete, just
> > > that it was submitted and didn't complete.
> > it seems we need to implement a timeout. Does this patch help?
> > Comments?

Your patch, 7b10f302c6caa940ea5ad67efb8a517923abfcc7 and my patch
4bf8e5d6d42891a6d01fee1b8f3bb674d8364843, (and some verbose output),
and usbhid gracefully recovered this afternoon.  Thanks, works for me.

My additional print messages,
Feb 10 12:53:31 SubSpace kernel: usbhid control queue 1 max 256
Feb 10 12:53:32 SubSpace kernel: usbhid urbctrl timeout -10020, unlink_urb
Feb 10 12:53:32 SubSpace kernel: usbhid -ECONNRESET
Feb 10 12:53:32 SubSpace kernel: usbhid control queue 0 max 256

usbmon dump, -104 was the -ECONNRESET unlink.
Wed Feb 10 12:53:01 CST 2010
c2fede40 161671434 S Ci:1:002:0 s a1 01 0326 0000 0004 8 <
c2fede40 161747009 C Ci:1:002:0 0 4 = 26343130
c2fede40 161847590 S Ci:1:002:0 s a1 01 0314 0000 0003 8 <
c2fede40 161848982 C Ci:1:002:0 0 3 = 140000
c2fede40 161908315 S Ci:1:002:0 s a1 01 0314 0000 0003 8 <
c2fede40 171928585 C Ci:1:002:0 -104 3 = 140000
c2fede40 171928605 S Ci:1:002:0 s a1 01 0306 0000 0004 8 <
c2fede40 171930579 C Ci:1:002:0 0 4 = 06000008
c2fede40 171968852 S Ci:1:002:0 s a1 01 030c 0000 0006 8 <
c2fede40 171970572 C Ci:1:002:0 0 6 = 0c640000 3f00
c2fede40 171989721 S Ci:1:002:0 s a1 01 030c 0000 0006 8 <
c2fede40 171991562 C Ci:1:002:0 0 6 = 0c640000 3f00
Wed Feb 10 12:54:01 CST 2010

-- 
David Fries <david-CAZ2Ig26prheoWH0uzbU5w@public.gmane.org>
http://fries.net/~david/ (PGP encryption key available)
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: usbhid control queue full, due to stuck control request

[Jiri Kosina]

On Wed, 10 Feb 2010, David Fries wrote:

> Your patch, 7b10f302c6caa940ea5ad67efb8a517923abfcc7 and my patch
> 4bf8e5d6d42891a6d01fee1b8f3bb674d8364843, (and some verbose output),
> and usbhid gracefully recovered this afternoon.  Thanks, works for me.
> 
> My additional print messages,
> Feb 10 12:53:31 SubSpace kernel: usbhid control queue 1 max 256
> Feb 10 12:53:32 SubSpace kernel: usbhid urbctrl timeout -10020, unlink_urb
> Feb 10 12:53:32 SubSpace kernel: usbhid -ECONNRESET
> Feb 10 12:53:32 SubSpace kernel: usbhid control queue 0 max 256
> 
> usbmon dump, -104 was the -ECONNRESET unlink.
> Wed Feb 10 12:53:01 CST 2010
> c2fede40 161671434 S Ci:1:002:0 s a1 01 0326 0000 0004 8 <
> c2fede40 161747009 C Ci:1:002:0 0 4 = 26343130
> c2fede40 161847590 S Ci:1:002:0 s a1 01 0314 0000 0003 8 <
> c2fede40 161848982 C Ci:1:002:0 0 3 = 140000
> c2fede40 161908315 S Ci:1:002:0 s a1 01 0314 0000 0003 8 <
> c2fede40 171928585 C Ci:1:002:0 -104 3 = 140000
> c2fede40 171928605 S Ci:1:002:0 s a1 01 0306 0000 0004 8 <
> c2fede40 171930579 C Ci:1:002:0 0 4 = 06000008
> c2fede40 171968852 S Ci:1:002:0 s a1 01 030c 0000 0006 8 <
> c2fede40 171970572 C Ci:1:002:0 0 6 = 0c640000 3f00
> c2fede40 171989721 S Ci:1:002:0 s a1 01 030c 0000 0006 8 <
> c2fede40 171991562 C Ci:1:002:0 0 6 = 0c640000 3f00
> Wed Feb 10 12:54:01 CST 2010

I only now noticed your patches, thanks for debugging this guys.

Could you please submit the condensed patch to me, with proper 
Signed-off-by: etc, so that I could apply it?

Thanks,

-- 
Jiri Kosina
SUSE Labs, Novell Inc.

--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: usbhid control queue full, due to stuck control request

[David Fries]

From: Oliver Neukum <oliver@neukum.org>

Some devices do not react to a control request (seen on APC UPS's)
resulting in a slow stream of messages,
"generic-usb ... control queue full".
Therefore request need a timeout.

Signed-off-by: Oliver Neukum <oliver@neukum.org>
Duplicated the change from last_out to last_ctrl and verified.
Signed-off-by: David Fries <david@fries.net>
---

Oliver Neukum, this is based on your patch, do you agree with the
changes?

One possible problem with this fix is it drops the stalled URB
transfer.  That might pose a problem for one shot messages, possibly
hid_ctrl and hid_irq_out could resubmit the same urb when -ECONNRESET
is received, assuming the message content wasn't the reason it
timedout in the first place.
David Fries <david@fries.net>

 drivers/hid/usbhid/hid-core.c |   28 ++++++++++++++++++++++++++--
 drivers/hid/usbhid/usbhid.h   |    2 ++
 2 files changed, 28 insertions(+), 2 deletions(-)

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 3c1fcb7..076a29a 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c
@@ -318,6 +318,7 @@ static int hid_submit_out(struct hid_device *hid)
 			err_hid("usb_submit_urb(out) failed");
 			return -1;
 		}
+		usbhid->last_out = jiffies;
 	} else {
 		/*
 		 * queue work to wake up the device.
@@ -379,6 +380,7 @@ static int hid_submit_ctrl(struct hid_device *hid)
 			err_hid("usb_submit_urb(ctrl) failed");
 			return -1;
 		}
+		usbhid->last_ctrl = jiffies;
 	} else {
 		/*
 		 * queue work to wake up the device.
@@ -513,9 +515,20 @@ void __usbhid_submit_report(struct hid_device *hid, struct hid_report *report, u
 		usbhid->out[usbhid->outhead].report = report;
 		usbhid->outhead = head;
 
-		if (!test_and_set_bit(HID_OUT_RUNNING, &usbhid->iofl))
+		if (!test_and_set_bit(HID_OUT_RUNNING, &usbhid->iofl)) {
 			if (hid_submit_out(hid))
 				clear_bit(HID_OUT_RUNNING, &usbhid->iofl);
+		} else {
+			/*
+			 * the queue is known to run
+			 * but an earlier request may be stuck
+			 * we may need to time out
+			 * no race because this is called under
+			 * spinlock
+			 */
+			if (time_after(jiffies, usbhid->last_out + HZ * 5))
+				usb_unlink_urb(usbhid->urbout);
+		}
 		return;
 	}
 
@@ -536,9 +549,20 @@ void __usbhid_submit_report(struct hid_device *hid, struct hid_report *report, u
 	usbhid->ctrl[usbhid->ctrlhead].dir = dir;
 	usbhid->ctrlhead = head;
 
-	if (!test_and_set_bit(HID_CTRL_RUNNING, &usbhid->iofl))
+	if (!test_and_set_bit(HID_CTRL_RUNNING, &usbhid->iofl)) {
 		if (hid_submit_ctrl(hid))
 			clear_bit(HID_CTRL_RUNNING, &usbhid->iofl);
+	} else {
+		/*
+		 * the queue is known to run
+		 * but an earlier request may be stuck
+		 * we may need to time out
+		 * no race because this is called under
+		 * spinlock
+		 */
+		if (time_after(jiffies, usbhid->last_ctrl + HZ * 5))
+			usb_unlink_urb(usbhid->urbctrl);
+	}
 }
 
 void usbhid_submit_report(struct hid_device *hid, struct hid_report *report, unsigned char dir)
diff --git a/drivers/hid/usbhid/usbhid.h b/drivers/hid/usbhid/usbhid.h
index 08f505c..ec20400 100644
--- a/drivers/hid/usbhid/usbhid.h
+++ b/drivers/hid/usbhid/usbhid.h
@@ -80,12 +80,14 @@ struct usbhid_device {
 	unsigned char ctrlhead, ctrltail;                               /* Control fifo head & tail */
 	char *ctrlbuf;                                                  /* Control buffer */
 	dma_addr_t ctrlbuf_dma;                                         /* Control buffer dma */
+	unsigned long last_ctrl;						/* record of last output for timeouts */
 
 	struct urb *urbout;                                             /* Output URB */
 	struct hid_output_fifo out[HID_CONTROL_FIFO_SIZE];              /* Output pipe fifo */
 	unsigned char outhead, outtail;                                 /* Output pipe fifo head & tail */
 	char *outbuf;                                                   /* Output buffer */
 	dma_addr_t outbuf_dma;                                          /* Output buffer dma */
+	unsigned long last_out;							/* record of last output for timeouts */
 
 	spinlock_t lock;						/* fifo spinlock */
 	unsigned long iofl;                                             /* I/O flags (CTRL_RUNNING, OUT_RUNNING) */
-- 
1.5.6.5

Re: usbhid control queue full, due to stuck control request

[Oliver Neukum]

Am Freitag, 12. Februar 2010 01:49:10 schrieb David Fries:
> Oliver Neukum, this is based on your patch, do you agree with the
> changes?

I do agree.

> One possible problem with this fix is it drops the stalled URB
> transfer.  That might pose a problem for one shot messages, possibly
> hid_ctrl and hid_irq_out could resubmit the same urb when -ECONNRESET
> is received, assuming the message content wasn't the reason it
> timedout in the first place.

That is a big assumption. Realistically, if the hardware needs over 5s
to answer the hardware is buggy. We are working around that. It is best
to get not too fancy, unless testing shows that we need to.

	Regards
		Oliver

Re: usbhid control queue full, due to stuck control request

[Jiri Kosina]

On Fri, 12 Feb 2010, Oliver Neukum wrote:

> > Oliver Neukum, this is based on your patch, do you agree with the
> > changes?
> 
> I do agree.

Thanks a lot guys for tracking this down and fixing it. I have applied the 
patch.

-- 
Jiri Kosina
SUSE Labs, Novell Inc.

Re: usbhid control queue full, due to stuck control request

[Oliver Neukum]

Am Freitag, 12. Februar 2010 12:57:11 schrieb Jiri Kosina:
> On Fri, 12 Feb 2010, Oliver Neukum wrote:
> 
> > > Oliver Neukum, this is based on your patch, do you agree with the
> > > changes?
> > 
> > I do agree.
> 
> Thanks a lot guys for tracking this down and fixing it. I have applied the 
> patch.

This being a fix for broken hardware it should go into stable, too.
Would you forward it?

	Regards
		Oliver

Re: usbhid control queue full, due to stuck control request

[Jiri Kosina]

On Fri, 12 Feb 2010, Oliver Neukum wrote:

> > > > Oliver Neukum, this is based on your patch, do you agree with the
> > > > changes?
> > > 
> > > I do agree.
> > 
> > Thanks a lot guys for tracking this down and fixing it. I have applied the 
> > patch.
> 
> This being a fix for broken hardware it should go into stable, too.
> Would you forward it?

Yes, will take care of that.

-- 
Jiri Kosina
SUSE Labs, Novell Inc.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html