[PATCH] mceusb: RX -EPIPE lockup fault and more

* [PATCH] mceusb: RX -EPIPE lockup fault and more
@ 2017-03-25 16:59 A Sun
  2017-03-26 10:27 ` Sean Young
  0 siblings, 1 reply; 14+ messages in thread
From: A Sun @ 2017-03-25 16:59 UTC (permalink / raw)
  To: linux-media; +Cc: Mauro Carvalho Chehab, as1033x

commit https://github.com/asunxx/linux/commit/e557c1d737462961f2aadfbfb0836ffa3c778518
Author: A Sun <as1033x@comcast.net>
Date:   Sat Mar 25 02:42:03 2017 -0400

[PATCH] mceusb RX -EPIPE fault and more

Patch for mceusb driver tested with

[    8.627769] mceusb 1-1.2:1.0: Registered Pinnacle Systems PCTV Remote USB with mce emulator interface version 1
[    8.627797] mceusb 1-1.2:1.0: 2 tx ports (0x1 cabled) and 2 rx sensors (0x1 active)

running on

pi@raspberrypi:~ $ uname -a
Linux raspberrypi 4.4.50-v7+ #970 SMP Mon Feb 20 19:18:29 GMT 2017 armv7l GNU/Linux
pi@raspberrypi:~ $

This patch is bug fix and debug messages fix (used for troubleshooting) for

Bug:

RX -EPIPE failure with infinite loop and flooding of
Mar 20 22:24:56 raspberrypi kernel: [ 2851.966506] mceusb 1-1.2:1.0: Error: urb status = -32
log message at 8000 messages per second.
Bug trigger appears to be normal, but heavy, IR receiver use.
Driver and Linux host become unusable after error.
Also seen at https://sourceforge.net/p/lirc/mailman/message/34886165/

Fix:

Message reports RX usb halt (stall) condition requiring usb_clear_halt() call in non-interrupt context to recover.
Add driver workqueue call to perform this recovery based on method in use for the usbnet device driver.

Bug:

Intermittent RX truncation and loss of IR received data. Results in receive data stream synchronization errors where driver attempts to incorrectly parse IR data as command responses.

Mar 22 12:01:40 raspberrypi kernel: [ 3969.139898] mceusb 1-1.2:1.0: processed IR data
Mar 22 12:01:40 raspberrypi kernel: [ 3969.151315] mceusb 1-1.2:1.0: rx data: 00 90 (length=2)
Mar 22 12:01:40 raspberrypi kernel: [ 3969.151321] mceusb 1-1.2:1.0: Unknown command 0x00 0x90
Mar 22 12:01:40 raspberrypi kernel: [ 3969.151336] mceusb 1-1.2:1.0: rx data: 98 0a 8d 0a 8e 0a 8e 0a 8e 0a 8e 0a 9a 0a 8e 0a 0b 3a 8e 00 80 41 59 00 00 (length=25)
Mar 22 12:01:40 raspberrypi kernel: [ 3969.151341] mceusb 1-1.2:1.0: Raw IR data, 24 pulse/space samples
Mar 22 12:01:40 raspberrypi kernel: [ 3969.151348] mceusb 1-1.2:1.0: Storing space with duration 500000

Bug trigger appears to be normal, but heavy, IR receiver use.

Fix:

Cause may be receiver with ep_in bulk endpoint incorrectly bound to usb_fill_int_urb() urb for interrupt endpoint.
In mceusb_dev_probe(), test ep_in endpoint for int versus bulk and use usb_fill_bulk_urb() as appropriate.

Bug:

Memory leak on disconnect for rc = rc_allocate_device().

Fix:

Add call rc_free_device() to mceusb_dev_disconnect()

Bug:

mceusb_dev_printdata() prints incorrect window of bytes (0 to len) that are of interest and will be processed next.

Fix:

Add size of received data argument to mceusb_dev_printdata().
Revise buffer print window (offset to offset+len).
Remove static USB_BUFLEN = 32, which is variable depending on device
(my receiver buffer size is 64 for Pinnacle IR transceiver).
Revise bound test to prevent reporting data beyond end of read or end of buffer.

Bug:

Debug messages; some misleading.

Fix:

Drop "\n" use from dev_dbg().
References to "receive request" should read "send request".
Various syntax and other corrections.

Signed-off-by: A Sun <as1033x@comcast.net>

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index 238d8ea..48e942e 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -36,18 +36,18 @@
 #include <linux/device.h>
 #include <linux/module.h>
 #include <linux/slab.h>
+#include <linux/workqueue.h>
 #include <linux/usb.h>
 #include <linux/usb/input.h>
 #include <linux/pm_wakeup.h>
 #include <media/rc-core.h>
 
-#define DRIVER_VERSION	"1.92"
+#define DRIVER_VERSION	"1.93"
 #define DRIVER_AUTHOR	"Jarod Wilson <jarod@redhat.com>"
 #define DRIVER_DESC	"Windows Media Center Ed. eHome Infrared Transceiver " \
 			"device driver"
 #define DRIVER_NAME	"mceusb"
 
-#define USB_BUFLEN		32 /* USB reception buffer length */
 #define USB_CTRL_MSG_SZ		2  /* Size of usb ctrl msg on gen1 hw */
 #define MCE_G1_INIT_MSGS	40 /* Init messages on gen1 hw to throw out */
 
@@ -417,6 +417,7 @@ struct mceusb_dev {
 	/* usb */
 	struct usb_device *usbdev;
 	struct urb *urb_in;
+	unsigned int pipe_in;
 	struct usb_endpoint_descriptor *usb_ep_out;
 
 	/* buffers and dma */
@@ -454,6 +455,12 @@ struct mceusb_dev {
 	u8 num_rxports;		/* number of receive sensors */
 	u8 txports_cabled;	/* bitmask of transmitters with cable */
 	u8 rxports_active;	/* bitmask of active receive sensors */
+
+	/* kevent support */
+	struct work_struct kevent;
+	unsigned long kevent_flags;
+#		define EVENT_TX_HALT	0
+#		define EVENT_RX_HALT	1
 };
 
 /* MCE Device Command Strings, generally a port and command pair */
@@ -527,7 +534,7 @@ static int mceusb_cmd_datasize(u8 cmd, u8 subcmd)
 }
 
 static void mceusb_dev_printdata(struct mceusb_dev *ir, char *buf,
-				 int offset, int len, bool out)
+				 int buf_len, int offset, int len, bool out)
 {
 #if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)
 	char *inout;
@@ -544,7 +551,8 @@ static void mceusb_dev_printdata(struct mceusb_dev *ir, char *buf,
 		return;
 
 	dev_dbg(dev, "%cx data: %*ph (length=%d)",
-		(out ? 't' : 'r'), min(len, USB_BUFLEN), buf, len);
+		(out ? 't' : 'r'),
+		min(len, buf_len - offset), buf + offset, len);
 
 	inout = out ? "Request" : "Got";
 
@@ -701,7 +709,8 @@ static void mce_async_callback(struct urb *urb)
 	case 0:
 		len = urb->actual_length;
 
-		mceusb_dev_printdata(ir, urb->transfer_buffer, 0, len, true);
+		mceusb_dev_printdata(ir, urb->transfer_buffer, len,
+				     0, len, true);
 		break;
 
 	case -ECONNRESET:
@@ -721,7 +730,7 @@ static void mce_async_callback(struct urb *urb)
 	usb_free_urb(urb);
 }
 
-/* request incoming or send outgoing usb packet - used to initialize remote */
+/* request outgoing (send) usb packet - used to initialize remote */
 static void mce_request_packet(struct mceusb_dev *ir, unsigned char *data,
 								int size)
 {
@@ -732,7 +741,7 @@ static void mce_request_packet(struct mceusb_dev *ir, unsigned char *data,
 
 	async_urb = usb_alloc_urb(0, GFP_KERNEL);
 	if (unlikely(!async_urb)) {
-		dev_err(dev, "Error, couldn't allocate urb!\n");
+		dev_err(dev, "Error, couldn't allocate urb!");
 		return;
 	}
 
@@ -758,17 +767,17 @@ static void mce_request_packet(struct mceusb_dev *ir, unsigned char *data,
 	}
 	memcpy(async_buf, data, size);
 
-	dev_dbg(dev, "receive request called (size=%#x)", size);
+	dev_dbg(dev, "send request called (size=%#x)", size);
 
 	async_urb->transfer_buffer_length = size;
 	async_urb->dev = ir->usbdev;
 
 	res = usb_submit_urb(async_urb, GFP_ATOMIC);
 	if (res) {
-		dev_err(dev, "receive request FAILED! (res=%d)", res);
+		dev_err(dev, "send request FAILED! (res=%d)", res);
 		return;
 	}
-	dev_dbg(dev, "receive request complete (res=%d)", res);
+	dev_dbg(dev, "send request complete (res=%d)", res);
 }
 
 static void mce_async_out(struct mceusb_dev *ir, unsigned char *data, int size)
@@ -974,7 +983,7 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 		switch (ir->parser_state) {
 		case SUBCMD:
 			ir->rem = mceusb_cmd_datasize(ir->cmd, ir->buf_in[i]);
-			mceusb_dev_printdata(ir, ir->buf_in, i - 1,
+			mceusb_dev_printdata(ir, ir->buf_in, buf_len, i - 1,
 					     ir->rem + 2, false);
 			mceusb_handle_command(ir, i);
 			ir->parser_state = CMD_DATA;
@@ -986,7 +995,7 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 			rawir.duration = (ir->buf_in[i] & MCE_PULSE_MASK)
 					 * US_TO_NS(MCE_TIME_UNIT);
 
-			dev_dbg(ir->dev, "Storing %s with duration %d",
+			dev_dbg(ir->dev, "Storing %s with duration %u",
 				rawir.pulse ? "pulse" : "space",
 				rawir.duration);
 
@@ -1007,7 +1016,7 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 				continue;
 			}
 			ir->rem = (ir->cmd & MCE_PACKET_LENGTH_MASK);
-			mceusb_dev_printdata(ir, ir->buf_in,
+			mceusb_dev_printdata(ir, ir->buf_in, buf_len,
 					     i, ir->rem + 1, false);
 			if (ir->rem)
 				ir->parser_state = PARSE_IRDATA;
@@ -1025,6 +1034,23 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 	}
 }
 
+/*
+ * Workqueue task dispatcher
+ * for work that can't be done in interrupt handlers
+ * (mceusb_dev_recv() and mce_async_callback()) nor tasklets.
+ * Invokes mceusb_deferred_kevent() for recovering from
+ * error events specified by the kevent bit field.
+ */
+static void mceusb_defer_kevent(struct mceusb_dev *ir, int kevent)
+{
+	set_bit(kevent, &ir->kevent_flags);
+	if (!schedule_work(&ir->kevent)) {
+		dev_err(ir->dev, "kevent %d may have been dropped", kevent);
+	} else {
+		dev_dbg(ir->dev, "kevent %d scheduled", kevent);
+	}
+}
+
 static void mceusb_dev_recv(struct urb *urb)
 {
 	struct mceusb_dev *ir;
@@ -1052,6 +1078,11 @@ static void mceusb_dev_recv(struct urb *urb)
 		return;
 
 	case -EPIPE:
+		dev_err(ir->dev, "Error: urb status = %d (RX HALT)",
+			urb->status);
+		mceusb_defer_kevent(ir, EVENT_RX_HALT);
+		return;
+
 	default:
 		dev_err(ir->dev, "Error: urb status = %d", urb->status);
 		break;
@@ -1170,6 +1201,37 @@ static void mceusb_flash_led(struct mceusb_dev *ir)
 	mce_async_out(ir, FLASH_LED, sizeof(FLASH_LED));
 }
 
+/*
+ * Workqueue function
+ * for resetting or recovering device after occurrence of error events
+ * specified in ir->kevent bit field.
+ * Function runs (via schedule_work()) in non-interrupt context, for
+ * calls here (such as usb_clear_halt()) requiring non-interrupt context.
+ */
+static void mceusb_deferred_kevent(struct work_struct *work)
+{
+	struct mceusb_dev *ir =
+		container_of(work, struct mceusb_dev, kevent);
+	int status;
+
+	if (test_bit(EVENT_RX_HALT, &ir->kevent_flags)) {
+		usb_unlink_urb(ir->urb_in);
+		status = usb_clear_halt(ir->usbdev, ir->pipe_in);
+		if (status < 0) {
+			dev_err(ir->dev, "rx clear halt error %d",
+				status);
+			return;
+		}
+		clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
+		status = usb_submit_urb(ir->urb_in, GFP_ATOMIC);
+		if (status < 0) {
+			dev_err(ir->dev, "rx unhalt submit urb error %d",
+				status);
+			return;
+		}
+	}
+}
+
 static struct rc_dev *mceusb_init_rc_dev(struct mceusb_dev *ir)
 {
 	struct usb_device *udev = ir->usbdev;
@@ -1336,17 +1398,25 @@ static int mceusb_dev_probe(struct usb_interface *intf,
 	if (!ir->rc)
 		goto rc_dev_fail;
 
+	ir->pipe_in = pipe;
+	INIT_WORK(&ir->kevent, mceusb_deferred_kevent);
+
 	/* wire up inbound data handler */
-	usb_fill_int_urb(ir->urb_in, dev, pipe, ir->buf_in, maxp,
+	if (usb_endpoint_xfer_int(ep_in)) {
+		usb_fill_int_urb(ir->urb_in, dev, pipe, ir->buf_in, maxp,
 				mceusb_dev_recv, ir, ep_in->bInterval);
+	} else {
+		usb_fill_bulk_urb(ir->urb_in, dev, pipe, ir->buf_in, maxp,
+				mceusb_dev_recv, ir);
+	}
 	ir->urb_in->transfer_dma = ir->dma_in;
 	ir->urb_in->transfer_flags |= URB_NO_TRANSFER_DMA_MAP;
 
 	/* flush buffers on the device */
-	dev_dbg(&intf->dev, "Flushing receive buffers\n");
+	dev_dbg(&intf->dev, "Flushing receive buffers");
 	res = usb_submit_urb(ir->urb_in, GFP_KERNEL);
 	if (res)
-		dev_err(&intf->dev, "failed to flush buffers: %d\n", res);
+		dev_err(&intf->dev, "failed to flush buffers: %d", res);
 
 	/* figure out which firmware/emulator version this hardware has */
 	mceusb_get_emulator_version(ir);
@@ -1405,7 +1475,9 @@ static void mceusb_dev_disconnect(struct usb_interface *intf)
 		return;
 
 	ir->usbdev = NULL;
+	cancel_work_sync(&ir->kevent);
 	rc_unregister_device(ir->rc);
+	rc_free_device(ir->rc);
 	usb_kill_urb(ir->urb_in);
 	usb_free_urb(ir->urb_in);
 	usb_free_coherent(dev, ir->len_in, ir->buf_in, ir->dma_in);

^ permalink raw reply related	[flat|nested] 14+ messages in thread