[PATCH v1 1/3] [media] mceusb: Disable "nonsensical irdata" messages

[PATCH v1 1/3] [media] mceusb: Disable "nonsensical irdata" messages

[A Sun]

mceusb device 2304:0225, and likely others, produces numerous
warnings:

[ 4231.111310] mceusb 1-1.1.2:1.0: nonsensical irdata 80 with duration 0
[ 4381.493597] mceusb 1-1.1.2:1.0: nonsensical irdata 80 with duration 0
[ 4410.247568] mceusb 1-1.1.2:1.0: nonsensical irdata 80 with duration 0
...
[60153.264064] mceusb 1-1.1.2:1.0: nonsensical irdata 00 with duration 0
...

due to reception of ambient IR noise.
Change these warning messages to debug messages.

Signed-off-by: A Sun <as1033x@comcast.net>
---
 drivers/media/rc/mceusb.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index 82d4261c9..0cd8f6f57 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -1182,8 +1182,8 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 			rawir.pulse = ((ir->buf_in[i] & MCE_PULSE_BIT) != 0);
 			rawir.duration = (ir->buf_in[i] & MCE_PULSE_MASK);
 			if (unlikely(!rawir.duration)) {
-				dev_warn(ir->dev, "nonsensical irdata %02x with duration 0",
-					 ir->buf_in[i]);
+				dev_dbg(ir->dev, "nonsensical irdata %02x with duration 0",
+					ir->buf_in[i]);
 				break;
 			}
 			if (rawir.pulse) {
-- 
2.11.0

[PATCH v1 2/3] [media] mceusb: Reword messages referring to "urb"

[A Sun]

Clarify messages referencing "request urb" to mean "tx urb"
(host transmit/send (to mceusb device)).
Qualify messages referencing plain "urb" to mean "rx urb"
(host receive (from mceusb device)).
Add missing "couldn't allocate rx urb" error message.
Clean extraneous "\n" in dev_dbg messages.

Signed-off-by: A Sun <as1033x@comcast.net>
---
 drivers/media/rc/mceusb.c | 24 +++++++++++++-----------
 1 file changed, 13 insertions(+), 11 deletions(-)

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index 0cd8f6f57..efffb1795 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -796,13 +796,13 @@ static void mce_async_callback(struct urb *urb)
 		break;
 
 	case -EPIPE:
-		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
+		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",
 			urb->status);
 		mceusb_defer_kevent(ir, EVENT_TX_HALT);
 		break;
 
 	default:
-		dev_err(ir->dev, "Error: request urb status = %d", urb->status);
+		dev_err(ir->dev, "Error: tx urb status = %d", urb->status);
 		break;
 	}
 
@@ -822,7 +822,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!");
+		dev_err(dev, "Error: couldn't allocate tx urb!");
 		return;
 	}
 
@@ -1268,13 +1268,13 @@ static void mceusb_dev_recv(struct urb *urb)
 		return;
 
 	case -EPIPE:
-		dev_err(ir->dev, "Error: urb status = %d (RX HALT)",
+		dev_err(ir->dev, "Error: rx 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);
+		dev_err(ir->dev, "Error: rx urb status = %d", urb->status);
 		break;
 	}
 
@@ -1544,27 +1544,27 @@ static int mceusb_dev_probe(struct usb_interface *intf,
 		if (ep_in == NULL) {
 			if (usb_endpoint_is_bulk_in(ep)) {
 				ep_in = ep;
-				dev_dbg(&intf->dev, "acceptable bulk inbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable bulk inbound endpoint found");
 			} else if (usb_endpoint_is_int_in(ep)) {
 				ep_in = ep;
 				ep_in->bInterval = 1;
-				dev_dbg(&intf->dev, "acceptable interrupt inbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable interrupt inbound endpoint found");
 			}
 		}
 
 		if (ep_out == NULL) {
 			if (usb_endpoint_is_bulk_out(ep)) {
 				ep_out = ep;
-				dev_dbg(&intf->dev, "acceptable bulk outbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable bulk outbound endpoint found");
 			} else if (usb_endpoint_is_int_out(ep)) {
 				ep_out = ep;
 				ep_out->bInterval = 1;
-				dev_dbg(&intf->dev, "acceptable interrupt outbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable interrupt outbound endpoint found");
 			}
 		}
 	}
 	if (!ep_in || !ep_out) {
-		dev_dbg(&intf->dev, "required endpoints not found\n");
+		dev_dbg(&intf->dev, "required endpoints not found");
 		return -ENODEV;
 	}
 
@@ -1584,8 +1584,10 @@ static int mceusb_dev_probe(struct usb_interface *intf,
 		goto buf_in_alloc_fail;
 
 	ir->urb_in = usb_alloc_urb(0, GFP_KERNEL);
-	if (!ir->urb_in)
+	if (!ir->urb_in) {
+		dev_err(&intf->dev, "Error: couldn't allocate rx urb!");
 		goto urb_in_alloc_fail;
+	}
 
 	ir->usbdev = usb_get_dev(dev);
 	ir->dev = &intf->dev;
-- 
2.11.0

[PATCH v1 3/3] [media] mceusb: Show USB halt/stall error recovery

[A Sun]

Update dev_err() messages to report status (including success) for each
step of USB RX HALT and TX HALT error recovery. If error recovery fails,
show the message:
        stuck RX HALT state requires USB Reset Device to clear
or
        stuck TX HALT state requires USB Reset Device to clear

This and related message revisions pertain to functions:
        mceusb_defer_kevent()           error handler dispatcher
        mceusb_deferred_kevent()        error handler itself

This patch just affects RX and TX HALT error handling and recovery
reporting.

A possible future patch may enable the mceusb driver to attempt
itself usb_reset_device() when necessary.

---

As seen on very rare occasions with mceusb device 2304:0225
        [59388.696941] mceusb 1-1.1.2:1.0: Error: urb status = -32 (RX HALT)
        [59388.698838] mceusb 1-1.1.2:1.0: rx clear halt error -32
the device can get into RX or TX HALT state where usb_clear_halt()
also fails and also returns -EPIPE (HALT/STALL). After which,
all further mceusb device control and data I/O fails with HALT/STALL.
Cause and problem replication conditions are still unknown.

As seen in https://ubuntuforums.org/showthread.php?t=2406882
        ...
        mceusb 2-1.4:1.0: Error: urb status = -32 (RX HALT)
        ...
for an unknown mceusb device, usb_clear_halt() apparently can return
false success. After which, RX HALT immediately reoccurs resulting in
a RX halt and clear halt infinite loop and message flooding. Again,
cause and problem replication conditions remain unknown.

After observing a rx clear halt fault with mceusb 2304:0225, further
troubleshooting reveals usb_reset_device() is able to restore device
functionality.
        $ lsusb
        Bus 001 Device 010: ID 2304:0225 Pinnacle Systems, Inc. Remote Kit Infrared Transceiver
        ...
        $ sudo ./usbreset /dev/bus/usb/001/010  # ioctl(fd, USBDEVFS_RESET, 0);
        Resetting USB device /dev/bus/usb/001/010
        Reset successful
        $ dmesg
        ...
        [272392.540679] usb 1-1.2.7: reset full-speed USB device number 10 using dwc_otg
        [272392.676616] Registered IR keymap rc-rc6-mce
        ...
        [272392.678313] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
        [272392.678616] mceusb 1-1.2.7:1.0: long-range (0x1) receiver active
        [272392.940671] mceusb 1-1.2.7:1.0: Registered Pinnacle Systems PCTV Remote USB with mce emulator interface version 1
        [272392.940687] mceusb 1-1.2.7:1.0: 2 tx ports (0x3 cabled) and 2 rx sensors (0x1 active)
        ...

Additional findings are "modprobe -r mceusb" and "modprobe mceusb"
are unable to clear stuck RX or TX HALT state.
Attempts to call usb_reset_endpoint() and usb_reset_configuration()
from within the mceusb driver also did not clear stuck HALTs.

A possible future patch could have the mceusb call usb_reset_device()
on itself, when necessary. Limiting the number of HALT error recovery
attempts may also be necessary to prevent halt/clear-halt loops.

Unresolved for now, deadlock complications occur if mceusb's worker
thread, mceusb_deferred_kevent(), calls usb_reset_device(),
which calls mceusb_dev_disconnect(), which calls cancel_work_sync(),
which waits on the still active worker thread.

Signed-off-by: A Sun <as1033x@comcast.net>
---
 drivers/media/rc/mceusb.c | 35 +++++++++++++++++++++++++----------
 1 file changed, 25 insertions(+), 10 deletions(-)

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index efffb1795..5d81ccafc 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -765,7 +765,7 @@ 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);
+		dev_dbg(ir->dev, "kevent %d already scheduled", kevent);
 	else
 		dev_dbg(ir->dev, "kevent %d scheduled", kevent);
 }
@@ -1404,19 +1404,26 @@ static void mceusb_deferred_kevent(struct work_struct *work)
 		container_of(work, struct mceusb_dev, kevent);
 	int status;
 
+	dev_info(ir->dev, "kevent handler called (flags 0x%lx)",
+		 ir->kevent_flags);
+
 	if (test_bit(EVENT_RX_HALT, &ir->kevent_flags)) {
 		usb_unlink_urb(ir->urb_in);
 		status = usb_clear_halt(ir->usbdev, ir->pipe_in);
+		dev_err(ir->dev, "rx clear halt status = %d", status);
 		if (status < 0) {
-			dev_err(ir->dev, "rx clear halt error %d",
-				status);
-		}
-		clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
-		if (status == 0) {
+			/*
+			 * Unable to clear RX stall/halt.
+			 * Will need to call usb_reset_device().
+			 */
+			dev_err(ir->dev,
+				"stuck RX HALT state requires USB Reset Device to clear");
+		} else {
+			clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
 			status = usb_submit_urb(ir->urb_in, GFP_KERNEL);
 			if (status < 0) {
 				dev_err(ir->dev,
-					"rx unhalt submit urb error %d",
+					"rx unhalt submit urb error = %d",
 					status);
 			}
 		}
@@ -1424,9 +1431,17 @@ static void mceusb_deferred_kevent(struct work_struct *work)
 
 	if (test_bit(EVENT_TX_HALT, &ir->kevent_flags)) {
 		status = usb_clear_halt(ir->usbdev, ir->pipe_out);
-		if (status < 0)
-			dev_err(ir->dev, "tx clear halt error %d", status);
-		clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
+		dev_err(ir->dev, "tx clear halt status = %d", status);
+		if (status < 0) {
+			/*
+			 * Unable to clear TX stall/halt.
+			 * Will need to call usb_reset_device().
+			 */
+			dev_err(ir->dev,
+				"stuck TX HALT state requires USB Reset Device to clear");
+		} else {
+			clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
+		}
 	}
 }
 
-- 
2.11.0

Re: [PATCH v1 3/3] [media] mceusb: Show USB halt/stall error recovery

[Sean Young]

On Sat, Jun 01, 2019 at 07:35:09PM -0400, A Sun wrote:
> Update dev_err() messages to report status (including success) for each
> step of USB RX HALT and TX HALT error recovery. If error recovery fails,
> show the message:
>         stuck RX HALT state requires USB Reset Device to clear
> or
>         stuck TX HALT state requires USB Reset Device to clear
> 
> This and related message revisions pertain to functions:
>         mceusb_defer_kevent()           error handler dispatcher
>         mceusb_deferred_kevent()        error handler itself
> 
> This patch just affects RX and TX HALT error handling and recovery
> reporting.
> 
> A possible future patch may enable the mceusb driver to attempt
> itself usb_reset_device() when necessary.
> 
> ---
> 
> As seen on very rare occasions with mceusb device 2304:0225
>         [59388.696941] mceusb 1-1.1.2:1.0: Error: urb status = -32 (RX HALT)
>         [59388.698838] mceusb 1-1.1.2:1.0: rx clear halt error -32
> the device can get into RX or TX HALT state where usb_clear_halt()
> also fails and also returns -EPIPE (HALT/STALL). After which,
> all further mceusb device control and data I/O fails with HALT/STALL.
> Cause and problem replication conditions are still unknown.
> 
> As seen in https://ubuntuforums.org/showthread.php?t=2406882
>         ...
>         mceusb 2-1.4:1.0: Error: urb status = -32 (RX HALT)
>         ...
> for an unknown mceusb device, usb_clear_halt() apparently can return
> false success. After which, RX HALT immediately reoccurs resulting in

I'm having trouble understanding this. usb_clear_halt() returns an int.
Do you mean usb_clear_halt() returns 0? 

> a RX halt and clear halt infinite loop and message flooding. Again,
> cause and problem replication conditions remain unknown.

So usb_clear_halt() returns 0 yet after the next usb_submit_urb() 
the completion function gets -EPIPE again?

Are you trying to address this problem in this patch or just the error
reporting? If you're trying to change the error reporting then there is
no reason to move code around like you have.

> 
> After observing a rx clear halt fault with mceusb 2304:0225, further
> troubleshooting reveals usb_reset_device() is able to restore device
> functionality.
>         $ lsusb
>         Bus 001 Device 010: ID 2304:0225 Pinnacle Systems, Inc. Remote Kit Infrared Transceiver
>         ...
>         $ sudo ./usbreset /dev/bus/usb/001/010  # ioctl(fd, USBDEVFS_RESET, 0);
>         Resetting USB device /dev/bus/usb/001/010
>         Reset successful
>         $ dmesg
>         ...
>         [272392.540679] usb 1-1.2.7: reset full-speed USB device number 10 using dwc_otg
>         [272392.676616] Registered IR keymap rc-rc6-mce
>         ...
>         [272392.678313] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0

Note the ir-lirc-codec. This is a pre-4.16 kernel. 

>         [272392.678616] mceusb 1-1.2.7:1.0: long-range (0x1) receiver active
>         [272392.940671] mceusb 1-1.2.7:1.0: Registered Pinnacle Systems PCTV Remote USB with mce emulator interface version 1
>         [272392.940687] mceusb 1-1.2.7:1.0: 2 tx ports (0x3 cabled) and 2 rx sensors (0x1 active)


>         ...
> 
> Additional findings are "modprobe -r mceusb" and "modprobe mceusb"
> are unable to clear stuck RX or TX HALT state.
> Attempts to call usb_reset_endpoint() and usb_reset_configuration()
> from within the mceusb driver also did not clear stuck HALTs.
> 
> A possible future patch could have the mceusb call usb_reset_device()
> on itself, when necessary. Limiting the number of HALT error recovery
> attempts may also be necessary to prevent halt/clear-halt loops.
> 
> Unresolved for now, deadlock complications occur if mceusb's worker
> thread, mceusb_deferred_kevent(), calls usb_reset_device(),
> which calls mceusb_dev_disconnect(), which calls cancel_work_sync(),
> which waits on the still active worker thread.

I think you can call usb_lock_device_for_reset() to prevent that problem.

It would be nice to see this implemented too.

> 
> Signed-off-by: A Sun <as1033x@comcast.net>
> ---
>  drivers/media/rc/mceusb.c | 35 +++++++++++++++++++++++++----------
>  1 file changed, 25 insertions(+), 10 deletions(-)
> 
> diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
> index efffb1795..5d81ccafc 100644
> --- a/drivers/media/rc/mceusb.c
> +++ b/drivers/media/rc/mceusb.c
> @@ -765,7 +765,7 @@ 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);
> +		dev_dbg(ir->dev, "kevent %d already scheduled", kevent);
>  	else
>  		dev_dbg(ir->dev, "kevent %d scheduled", kevent);
>  }
> @@ -1404,19 +1404,26 @@ static void mceusb_deferred_kevent(struct work_struct *work)
>  		container_of(work, struct mceusb_dev, kevent);
>  	int status;
>  
> +	dev_info(ir->dev, "kevent handler called (flags 0x%lx)",
> +		 ir->kevent_flags);
> +
>  	if (test_bit(EVENT_RX_HALT, &ir->kevent_flags)) {
>  		usb_unlink_urb(ir->urb_in);
>  		status = usb_clear_halt(ir->usbdev, ir->pipe_in);
> +		dev_err(ir->dev, "rx clear halt status = %d", status);
>  		if (status < 0) {
> -			dev_err(ir->dev, "rx clear halt error %d",
> -				status);
> -		}
> -		clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
> -		if (status == 0) {
> +			/*
> +			 * Unable to clear RX stall/halt.
> +			 * Will need to call usb_reset_device().
> +			 */
> +			dev_err(ir->dev,
> +				"stuck RX HALT state requires USB Reset Device to clear");

Here you say if the usb_clear_halt() returns < 0 then we're in the bad
code path. But in this code path, we're not re-submitting the urb so
we wouldn't end up in an infinite loop.


> +		} else {
> +			clear_bit(EVENT_RX_HALT, &ir->kevent_flags);

Why have you moved this line?

>  			status = usb_submit_urb(ir->urb_in, GFP_KERNEL);
>  			if (status < 0) {
>  				dev_err(ir->dev,
> -					"rx unhalt submit urb error %d",
> +					"rx unhalt submit urb error = %d",
>  					status);
>  			}
>  		}

I don't understand how this code change has changed anything. In the existing
code and the patch code the urb only gets re-submitted if usb_clear_halt()
succeeds.

> @@ -1424,9 +1431,17 @@ static void mceusb_deferred_kevent(struct work_struct *work)
>  
>  	if (test_bit(EVENT_TX_HALT, &ir->kevent_flags)) {
>  		status = usb_clear_halt(ir->usbdev, ir->pipe_out);
> -		if (status < 0)
> -			dev_err(ir->dev, "tx clear halt error %d", status);
> -		clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
> +		dev_err(ir->dev, "tx clear halt status = %d", status);
> +		if (status < 0) {
> +			/*
> +			 * Unable to clear TX stall/halt.
> +			 * Will need to call usb_reset_device().
> +			 */
> +			dev_err(ir->dev,
> +				"stuck TX HALT state requires USB Reset Device to clear");
> +		} else {
> +			clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
> +		}
>  	}
>  }
>  
> -- 
> 2.11.0

Re: [PATCH v1 3/3] [media] mceusb: Show USB halt/stall error recovery

[A Sun]

Hi Sean,

Thanks again for reviewing my patch submission.

This patch updates mceusb RX and TX HALT error handling and recovery reporting,
and provides placeholder for a later patch.

The possible later patch would have mceusb call usb_reset_device() in place of the
new "... requires USB Reset ..." message. I say "possible" because I'm running into
multiple issues invoking usb_reset_device() from within mceusb.

I'll also mention the difficulty obtaining even a single fault replication
(~ 1/month) and test cycle.

Additional comments below...  ..A Sun

On 6/6/2019 5:53 AM, Sean Young wrote:
> On Sat, Jun 01, 2019 at 07:35:09PM -0400, A Sun wrote:
>> Update dev_err() messages to report status (including success) for each
>> step of USB RX HALT and TX HALT error recovery. If error recovery fails,
>> show the message:
>>         stuck RX HALT state requires USB Reset Device to clear
>> or
>>         stuck TX HALT state requires USB Reset Device to clear
>>

>>
>> This patch just affects RX and TX HALT error handling and recovery
>> reporting.
>>
>> A possible future patch may enable the mceusb driver to attempt
>> itself usb_reset_device() when necessary.
>>

>> ---
>>
>> As seen on very rare occasions with mceusb device 2304:0225
>>         [59388.696941] mceusb 1-1.1.2:1.0: Error: urb status = -32 (RX HALT)
>>         [59388.698838] mceusb 1-1.1.2:1.0: rx clear halt error -32
>> the device can get into RX or TX HALT state where usb_clear_halt()
>> also fails and also returns -EPIPE (HALT/STALL). After which,
>> all further mceusb device control and data I/O fails with HALT/STALL.
>> Cause and problem replication conditions are still unknown.
>>
>> As seen in https://ubuntuforums.org/showthread.php?t=2406882
>>         ...
>>         mceusb 2-1.4:1.0: Error: urb status = -32 (RX HALT)
>>         ...
>> for an unknown mceusb device, usb_clear_halt() apparently can return
>> false success. After which, RX HALT immediately reoccurs resulting in
> 
> I'm having trouble understanding this. usb_clear_halt() returns an int.
> Do you mean usb_clear_halt() returns 0? 
> 
>> a RX halt and clear halt infinite loop and message flooding. Again,
>> cause and problem replication conditions remain unknown.
> 
> So usb_clear_halt() returns 0 yet after the next usb_submit_urb() 
> the completion function gets -EPIPE again?

Yes, for the infinite loop with the unknown mceusb device, RX completion gets -EPIPE,
usb_clear_halt() probably returned 0 (success), but after the usb_submit_urb(),
the RX completion again gets -EPIPE.

> Are you trying to address this problem in this patch or just the error
> reporting? If you're trying to change the error reporting then there is
> no reason to move code around like you have.

This patch is mainly just error reporting.
A future patch would replace the "stuck HALT state" placeholder with code.
The move code would be for the placeholder.

The infinite loop case isn't resolved. But a false usb_clear_halt() status 0 (success)
return would be printed/shown by this patch to confirm the infinite loop theory above.

> 
>>
>> After observing a rx clear halt fault with mceusb 2304:0225, further
>> troubleshooting reveals usb_reset_device() is able to restore device
>> functionality.
>>         $ lsusb
>>         Bus 001 Device 010: ID 2304:0225 Pinnacle Systems, Inc. Remote Kit Infrared Transceiver
>>         ...
>>         $ sudo ./usbreset /dev/bus/usb/001/010  # ioctl(fd, USBDEVFS_RESET, 0);
>>         Resetting USB device /dev/bus/usb/001/010
>>         Reset successful
>>         $ dmesg
>>         ...
>>         [272392.540679] usb 1-1.2.7: reset full-speed USB device number 10 using dwc_otg
>>         [272392.676616] Registered IR keymap rc-rc6-mce
>>         ...
>>         [272392.678313] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> 
> Note the ir-lirc-codec. This is a pre-4.16 kernel. 
> 
>>         [272392.678616] mceusb 1-1.2.7:1.0: long-range (0x1) receiver active
>>         [272392.940671] mceusb 1-1.2.7:1.0: Registered Pinnacle Systems PCTV Remote USB with mce emulator interface version 1
>>         [272392.940687] mceusb 1-1.2.7:1.0: 2 tx ports (0x3 cabled) and 2 rx sensors (0x1 active)
> 
> 
>>         ...
>>
>> Additional findings are "modprobe -r mceusb" and "modprobe mceusb"
>> are unable to clear stuck RX or TX HALT state.
>> Attempts to call usb_reset_endpoint() and usb_reset_configuration()
>> from within the mceusb driver also did not clear stuck HALTs.
>>
>> A possible future patch could have the mceusb call usb_reset_device()
>> on itself, when necessary. Limiting the number of HALT error recovery
>> attempts may also be necessary to prevent halt/clear-halt loops.
>>
>> Unresolved for now, deadlock complications occur if mceusb's worker
>> thread, mceusb_deferred_kevent(), calls usb_reset_device(),
>> which calls mceusb_dev_disconnect(), which calls cancel_work_sync(),
>> which waits on the still active worker thread.
> 
> I think you can call usb_lock_device_for_reset() to prevent that problem.

Deadlock still occurs in test:
mceusb_deferred_kevent()
    ->usb_reset_device()
        ->mceusb_dev_disconnect()
            ->cancel_work_sync()
where cancel_work_sync() blocks because mceusb_deferred_kevent() is active.

> It would be nice to see this implemented too.
> 

Any additional tips to implement would help!
How to validate and test a rare condition with a larger audience?

>>
>> Signed-off-by: A Sun <as1033x@comcast.net>
>> ---
>>  drivers/media/rc/mceusb.c | 35 +++++++++++++++++++++++++----------
>>  1 file changed, 25 insertions(+), 10 deletions(-)
>>
>> diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
>> index efffb1795..5d81ccafc 100644
>> --- a/drivers/media/rc/mceusb.c
>> +++ b/drivers/media/rc/mceusb.c
>> @@ -765,7 +765,7 @@ 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);
>> +		dev_dbg(ir->dev, "kevent %d already scheduled", kevent);
>>  	else
>>  		dev_dbg(ir->dev, "kevent %d scheduled", kevent);
>>  }
>> @@ -1404,19 +1404,26 @@ static void mceusb_deferred_kevent(struct work_struct *work)
>>  		container_of(work, struct mceusb_dev, kevent);
>>  	int status;
>>  
>> +	dev_info(ir->dev, "kevent handler called (flags 0x%lx)",
>> +		 ir->kevent_flags);
>> +
>>  	if (test_bit(EVENT_RX_HALT, &ir->kevent_flags)) {
>>  		usb_unlink_urb(ir->urb_in);
>>  		status = usb_clear_halt(ir->usbdev, ir->pipe_in);
>> +		dev_err(ir->dev, "rx clear halt status = %d", status);
>>  		if (status < 0) {
>> -			dev_err(ir->dev, "rx clear halt error %d",
>> -				status);
>> -		}
>> -		clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
>> -		if (status == 0) {
>> +			/*
>> +			 * Unable to clear RX stall/halt.
>> +			 * Will need to call usb_reset_device().
>> +			 */
>> +			dev_err(ir->dev,
>> +				"stuck RX HALT state requires USB Reset Device to clear");
> 
> Here you say if the usb_clear_halt() returns < 0 then we're in the bad
> code path. But in this code path, we're not re-submitting the urb so
> we wouldn't end up in an infinite loop.
> 

The theory for the infinite loop case is usb_clear_halt() returned 0.
The infinite loop isn't resolved with this patch.

> 
>> +		} else {
>> +			clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
> 
> Why have you moved this line?
> 

Clear bit but only if usb_clear_halt() recovery succeeds.

A future usb_device_reset() operation affects both RX and TX and its
success code path must clear both EVENT_RX_HALT and EVENT_TX_HALT
and do its own usb_submit_urb() with message "rx reset device submit urb status = %d"

Hence, the moved line.

>>  			status = usb_submit_urb(ir->urb_in, GFP_KERNEL);
>>  			if (status < 0) {
>>  				dev_err(ir->dev,
>> -					"rx unhalt submit urb error %d",
>> +					"rx unhalt submit urb error = %d",
>>  					status);
>>  			}
>>  		}
> 
> I don't understand how this code change has changed anything. In the existing
> code and the patch code the urb only gets re-submitted if usb_clear_halt()
> succeeds.
> 

This patch is mainly just error reporting revisions.
A future patch would replace the "stuck HALT state" message and placeholder 
with code to perform USB reset.

>> @@ -1424,9 +1431,17 @@ static void mceusb_deferred_kevent(struct work_struct *work)
>>  
>>  	if (test_bit(EVENT_TX_HALT, &ir->kevent_flags)) {
>>  		status = usb_clear_halt(ir->usbdev, ir->pipe_out);
>> -		if (status < 0)
>> -			dev_err(ir->dev, "tx clear halt error %d", status);
>> -		clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
>> +		dev_err(ir->dev, "tx clear halt status = %d", status);
>> +		if (status < 0) {
>> +			/*
>> +			 * Unable to clear TX stall/halt.
>> +			 * Will need to call usb_reset_device().
>> +			 */
>> +			dev_err(ir->dev,
>> +				"stuck TX HALT state requires USB Reset Device to clear");
>> +		} else {
>> +			clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
>> +		}
>>  	}
>>  }
>>  
>> -- 
>> 2.11.0
> 

Re: [PATCH v1 3/3] [media] mceusb: Show USB halt/stall error recovery

[Sean Young]

Hi,

On Thu, Jun 06, 2019 at 05:11:04PM -0400, A Sun wrote:
> Hi Sean,
> 
> Thanks again for reviewing my patch submission.
> 
> This patch updates mceusb RX and TX HALT error handling and recovery reporting,
> and provides placeholder for a later patch.
> 
> The possible later patch would have mceusb call usb_reset_device() in place of the
> new "... requires USB Reset ..." message. I say "possible" because I'm running into
> multiple issues invoking usb_reset_device() from within mceusb.
> 
> I'll also mention the difficulty obtaining even a single fault replication
> (~ 1/month) and test cycle.

OK, thank you.

> Additional comments below...  ..A Sun
> 
> On 6/6/2019 5:53 AM, Sean Young wrote:
> > On Sat, Jun 01, 2019 at 07:35:09PM -0400, A Sun wrote:

-snip-

 >> Additional findings are "modprobe -r mceusb" and "modprobe mceusb"
> >> are unable to clear stuck RX or TX HALT state.
> >> Attempts to call usb_reset_endpoint() and usb_reset_configuration()
> >> from within the mceusb driver also did not clear stuck HALTs.
> >>
> >> A possible future patch could have the mceusb call usb_reset_device()
> >> on itself, when necessary. Limiting the number of HALT error recovery
> >> attempts may also be necessary to prevent halt/clear-halt loops.
> >>
> >> Unresolved for now, deadlock complications occur if mceusb's worker
> >> thread, mceusb_deferred_kevent(), calls usb_reset_device(),
> >> which calls mceusb_dev_disconnect(), which calls cancel_work_sync(),
> >> which waits on the still active worker thread.
> > 
> > I think you can call usb_lock_device_for_reset() to prevent that problem.
> 
> Deadlock still occurs in test:
> mceusb_deferred_kevent()
>     ->usb_reset_device()
>         ->mceusb_dev_disconnect()
>             ->cancel_work_sync()
> where cancel_work_sync() blocks because mceusb_deferred_kevent() is active.

I understand. The usb_reset_device() does not need to happen synchronously
in mceusb_deferred_kevent(). Possibly another delayed workqueue.

Actually there is also a function usb_queue_reset_device() which might do
what you want here.

> 
> > It would be nice to see this implemented too.
> > 
> 
> Any additional tips to implement would help!
> How to validate and test a rare condition with a larger audience?

This is hard. Do you know the model of the mceusb and host hardware?

> >>
> >> Signed-off-by: A Sun <as1033x@comcast.net>
> >> ---
> >>  drivers/media/rc/mceusb.c | 35 +++++++++++++++++++++++++----------
> >>  1 file changed, 25 insertions(+), 10 deletions(-)
> >>
> >> diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
> >> index efffb1795..5d81ccafc 100644
> >> --- a/drivers/media/rc/mceusb.c
> >> +++ b/drivers/media/rc/mceusb.c
> >> @@ -765,7 +765,7 @@ 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);
> >> +		dev_dbg(ir->dev, "kevent %d already scheduled", kevent);
> >>  	else
> >>  		dev_dbg(ir->dev, "kevent %d scheduled", kevent);
> >>  }
> >> @@ -1404,19 +1404,26 @@ static void mceusb_deferred_kevent(struct work_struct *work)
> >>  		container_of(work, struct mceusb_dev, kevent);
> >>  	int status;
> >>  
> >> +	dev_info(ir->dev, "kevent handler called (flags 0x%lx)",
> >> +		 ir->kevent_flags);
> >> +
> >>  	if (test_bit(EVENT_RX_HALT, &ir->kevent_flags)) {
> >>  		usb_unlink_urb(ir->urb_in);
> >>  		status = usb_clear_halt(ir->usbdev, ir->pipe_in);
> >> +		dev_err(ir->dev, "rx clear halt status = %d", status);
> >>  		if (status < 0) {
> >> -			dev_err(ir->dev, "rx clear halt error %d",
> >> -				status);
> >> -		}
> >> -		clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
> >> -		if (status == 0) {
> >> +			/*
> >> +			 * Unable to clear RX stall/halt.
> >> +			 * Will need to call usb_reset_device().
> >> +			 */
> >> +			dev_err(ir->dev,
> >> +				"stuck RX HALT state requires USB Reset Device to clear");
> > 
> > Here you say if the usb_clear_halt() returns < 0 then we're in the bad
> > code path. But in this code path, we're not re-submitting the urb so
> > we wouldn't end up in an infinite loop.
> > 
> 
> The theory for the infinite loop case is usb_clear_halt() returned 0.
> The infinite loop isn't resolved with this patch.
> 
> > 
> >> +		} else {
> >> +			clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
> > 
> > Why have you moved this line?
> > 
> 
> Clear bit but only if usb_clear_halt() recovery succeeds.

To what affect? Will it be attempted again? Might it cause an infinite
loop?
> 
> A future usb_device_reset() operation affects both RX and TX and its
> success code path must clear both EVENT_RX_HALT and EVENT_TX_HALT
> and do its own usb_submit_urb() with message "rx reset device submit urb status = %d"
> 
> Hence, the moved line.

That's in a future patch. Please only change error strings in this patch.

Thanks,

Sean

Re: [PATCH v1 3/3] [media] mceusb: Show USB halt/stall error recovery

[A Sun]

On 6/8/2019 4:37 AM, Sean Young wrote:
> Hi,
> 

>>> I think you can call usb_lock_device_for_reset() to prevent that problem.
>>
>> Deadlock still occurs in test:
>> mceusb_deferred_kevent()
>>     ->usb_reset_device()
>>         ->mceusb_dev_disconnect()
>>             ->cancel_work_sync()
>> where cancel_work_sync() blocks because mceusb_deferred_kevent() is active.
> 
> I understand. The usb_reset_device() does not need to happen synchronously
> in mceusb_deferred_kevent(). Possibly another delayed workqueue.
> 
> Actually there is also a function usb_queue_reset_device() which might do
> what you want here.
> 

Thanks! Usb_queue_reset_device() appears to be exactly what I'm looking for.

With the help of your tip, I found Alan Stern ran into a virtually identical problem
(clear halt error and reset deadlock) with drivers/hid/usbhid/hid-core.c
https://linux-usb.vger.kernel.narkive.com/fc7Lng6q/patch-usbhid-improve-handling-of-clear-halt-and-reset
So patch for mceusb may be able to use the same techniques.

>>
>>> It would be nice to see this implemented too.
>>>
>>
>> Any additional tips to implement would help!
>> How to validate and test a rare condition with a larger audience?
> 
> This is hard. Do you know the model of the mceusb and host hardware?
> 

Host is Raspberry Pi 3B+ raspbian 4.14.xx version of mid year 2018.
mceusb Pinnacle Systems PCTV Remote USB with mce emulator interface version 1
device 2304:0225 produced the sequence:
        [59388.696941] mceusb 1-1.1.2:1.0: Error: urb status = -32 (RX HALT)
        [59388.698838] mceusb 1-1.1.2:1.0: rx clear halt error -32
RX permanently stops after the error.

All the work I'm doing for mceusb is with the above.


The other case (https://ubuntuforums.org/showthread.php?t=2406882) I heard about is:
Host ubuntu,
mceusb unknown, possibly
SMK eHome Infrared Transceiver with mce emulator interface version 1
Flooding of:
	mceusb 2-1.4:1.0: Error: urb status = -32 (RX HALT)

>> Hence, the moved line.
> 
> That's in a future patch. Please only change error strings in this patch.
> 

ok, I'll post a v2 version of this patch with only the error strings changes.

The instructions the error strings say (USB reset device manually) will be my patch
resolution for the mceusb stuck halt bug for some time.

In the meantime, I'll try and test (harder part) use of usb_queue_reset_device
for a future patch to automate the USB reset procedure.

Thanks again, ..A Sun

[PATCH v2 0/3] [media] mceusb: Error message text revisions

[A Sun]

patch v2 revisions:
  . limit patch to message changes only in part 3/3

Several error message revisions for mceusb.c

proposed patches applicable to mceusb.c version
https://github.com/torvalds/linux/blob/master/drivers/media/rc/mceusb.c
Mar 1, 2019 commit 04ad30112aec61004f994d8f51461ec06e208e54

[PATCH v2 1/3] [media] mceusb: Disable "nonsensical irdata" messages

[A Sun]

mceusb device 2304:0225, and likely others, produces numerous
warnings:

[ 4231.111310] mceusb 1-1.1.2:1.0: nonsensical irdata 80 with duration 0
[ 4381.493597] mceusb 1-1.1.2:1.0: nonsensical irdata 80 with duration 0
[ 4410.247568] mceusb 1-1.1.2:1.0: nonsensical irdata 80 with duration 0
...
[60153.264064] mceusb 1-1.1.2:1.0: nonsensical irdata 00 with duration 0
...

due to reception of ambient IR noise.
Change these warning messages to debug messages.

Signed-off-by: A Sun <as1033x@comcast.net>
---
 drivers/media/rc/mceusb.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index 82d4261c9..0cd8f6f57 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -1182,8 +1182,8 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 			rawir.pulse = ((ir->buf_in[i] & MCE_PULSE_BIT) != 0);
 			rawir.duration = (ir->buf_in[i] & MCE_PULSE_MASK);
 			if (unlikely(!rawir.duration)) {
-				dev_warn(ir->dev, "nonsensical irdata %02x with duration 0",
-					 ir->buf_in[i]);
+				dev_dbg(ir->dev, "nonsensical irdata %02x with duration 0",
+					ir->buf_in[i]);
 				break;
 			}
 			if (rawir.pulse) {
-- 
2.11.0

[PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[A Sun]

Clarify messages referencing "request urb" to mean "tx urb"
(host transmit/send (to mceusb device)).
Qualify messages referencing plain "urb" to mean "rx urb"
(host receive (from mceusb device)).
Add missing "couldn't allocate rx urb" error message.
Clean extraneous "\n" in dev_dbg messages.

Signed-off-by: A Sun <as1033x@comcast.net>
---
 drivers/media/rc/mceusb.c | 24 +++++++++++++-----------
 1 file changed, 13 insertions(+), 11 deletions(-)

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index 0cd8f6f57..efffb1795 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -796,13 +796,13 @@ static void mce_async_callback(struct urb *urb)
 		break;
 
 	case -EPIPE:
-		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
+		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",
 			urb->status);
 		mceusb_defer_kevent(ir, EVENT_TX_HALT);
 		break;
 
 	default:
-		dev_err(ir->dev, "Error: request urb status = %d", urb->status);
+		dev_err(ir->dev, "Error: tx urb status = %d", urb->status);
 		break;
 	}
 
@@ -822,7 +822,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!");
+		dev_err(dev, "Error: couldn't allocate tx urb!");
 		return;
 	}
 
@@ -1268,13 +1268,13 @@ static void mceusb_dev_recv(struct urb *urb)
 		return;
 
 	case -EPIPE:
-		dev_err(ir->dev, "Error: urb status = %d (RX HALT)",
+		dev_err(ir->dev, "Error: rx 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);
+		dev_err(ir->dev, "Error: rx urb status = %d", urb->status);
 		break;
 	}
 
@@ -1544,27 +1544,27 @@ static int mceusb_dev_probe(struct usb_interface *intf,
 		if (ep_in == NULL) {
 			if (usb_endpoint_is_bulk_in(ep)) {
 				ep_in = ep;
-				dev_dbg(&intf->dev, "acceptable bulk inbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable bulk inbound endpoint found");
 			} else if (usb_endpoint_is_int_in(ep)) {
 				ep_in = ep;
 				ep_in->bInterval = 1;
-				dev_dbg(&intf->dev, "acceptable interrupt inbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable interrupt inbound endpoint found");
 			}
 		}
 
 		if (ep_out == NULL) {
 			if (usb_endpoint_is_bulk_out(ep)) {
 				ep_out = ep;
-				dev_dbg(&intf->dev, "acceptable bulk outbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable bulk outbound endpoint found");
 			} else if (usb_endpoint_is_int_out(ep)) {
 				ep_out = ep;
 				ep_out->bInterval = 1;
-				dev_dbg(&intf->dev, "acceptable interrupt outbound endpoint found\n");
+				dev_dbg(&intf->dev, "acceptable interrupt outbound endpoint found");
 			}
 		}
 	}
 	if (!ep_in || !ep_out) {
-		dev_dbg(&intf->dev, "required endpoints not found\n");
+		dev_dbg(&intf->dev, "required endpoints not found");
 		return -ENODEV;
 	}
 
@@ -1584,8 +1584,10 @@ static int mceusb_dev_probe(struct usb_interface *intf,
 		goto buf_in_alloc_fail;
 
 	ir->urb_in = usb_alloc_urb(0, GFP_KERNEL);
-	if (!ir->urb_in)
+	if (!ir->urb_in) {
+		dev_err(&intf->dev, "Error: couldn't allocate rx urb!");
 		goto urb_in_alloc_fail;
+	}
 
 	ir->usbdev = usb_get_dev(dev);
 	ir->dev = &intf->dev;
-- 
2.11.0

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[Sean Young]

On Wed, Jun 19, 2019 at 03:54:21AM -0400, A Sun wrote:
> 
> Clarify messages referencing "request urb" to mean "tx urb"
> (host transmit/send (to mceusb device)).
> Qualify messages referencing plain "urb" to mean "rx urb"
> (host receive (from mceusb device)).
> Add missing "couldn't allocate rx urb" error message.
> Clean extraneous "\n" in dev_dbg messages.
> 
> Signed-off-by: A Sun <as1033x@comcast.net>
> ---
>  drivers/media/rc/mceusb.c | 24 +++++++++++++-----------
>  1 file changed, 13 insertions(+), 11 deletions(-)
> 
> diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
> index 0cd8f6f57..efffb1795 100644
> --- a/drivers/media/rc/mceusb.c
> +++ b/drivers/media/rc/mceusb.c
> @@ -796,13 +796,13 @@ static void mce_async_callback(struct urb *urb)
>  		break;
>  
>  	case -EPIPE:
> -		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
> +		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",

I am not sure this makes things clearer. Some of the code still refers
to request, e.g. mce_request_packet.

Since this is an IR device, there is IR TX and RX; however this unrelated
to that.

There is one urb/endpoint on which commands are sent; on the other, we
receiver responses and IR data. Calling those TX and RX is not a good
idea I think.

The existing code refers to request and response, and also TX and RX in
places. The microsoft documentation refers to "command and response" which
would be consistent with the #define's we have (MCE_CMD_* and MCE_RSP_*).


Thanks

Sean

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[A Sun]

Hi,

On 6/25/2019 6:51 AM, Sean Young wrote:
> On Wed, Jun 19, 2019 at 03:54:21AM -0400, A Sun wrote:
>>

>> -		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
>> +		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",
> 
> I am not sure this makes things clearer. Some of the code still refers
> to request, e.g. mce_request_packet.
> 
> Since this is an IR device, there is IR TX and RX; however this unrelated
> to that.
> 
> There is one urb/endpoint on which commands are sent; on the other, we
> receiver responses and IR data. Calling those TX and RX is not a good
> idea I think.

The tx urb described is also for IR data TX.
IR TX is one primary function/purpose of the device.
It happens that the urb/endpoint for IR TX is the same urb/endpoint for
mceusb device commands.

The same is found for IR data RX.
The urb/endpoint for IR RX is the same urb/endpoint for mceusb device
responses (to commands).

> 
> The existing code refers to request and response, and also TX and RX in
> places. The microsoft documentation refers to "command and response" which
> would be consistent with the #define's we have (MCE_CMD_* and MCE_RSP_*).
> 

My intent is to try and better word several of the USB layer messages,
and avoid confusing Microsoft MCE terms in those messages.

The original "(request) urb" phrases expand to "request USB Request Block"
and "<blank> USB Request Block" which are particularly confusing, and
non-specific, respectively.

Thanks, ..A Sun

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[Sean Young]

Hello,

On Tue, Jun 25, 2019 at 11:01:32AM -0400, A Sun wrote:
> On 6/25/2019 6:51 AM, Sean Young wrote:
> > On Wed, Jun 19, 2019 at 03:54:21AM -0400, A Sun wrote:
> >>
> 
> >> -		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
> >> +		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",
> > 
> > I am not sure this makes things clearer. Some of the code still refers
> > to request, e.g. mce_request_packet.
> > 
> > Since this is an IR device, there is IR TX and RX; however this unrelated
> > to that.
> > 
> > There is one urb/endpoint on which commands are sent; on the other, we
> > receiver responses and IR data. Calling those TX and RX is not a good
> > idea I think.
> 
> The tx urb described is also for IR data TX.
> IR TX is one primary function/purpose of the device.
>
> It happens that the urb/endpoint for IR TX is the same urb/endpoint for
> mceusb device commands.

The outgoing urb is for command, e.g. get version, set IR Rx timeout,
set IR Rx carrier report, set IR wakeup protocol/scancode, resume
device after suspend. Not everything is IR Tx.

> The same is found for IR data RX.
> The urb/endpoint for IR RX is the same urb/endpoint for mceusb device
> responses (to commands).

The response to get version, how many Tx ports are there etc. Responses
to commands and IR data. Not everything is IR Rx here.

> > The existing code refers to request and response, and also TX and RX in
> > places. The microsoft documentation refers to "command and response" which
> > would be consistent with the #define's we have (MCE_CMD_* and MCE_RSP_*).
> > 
> 
> My intent is to try and better word several of the USB layer messages,
> and avoid confusing Microsoft MCE terms in those messages.
> 
> The original "(request) urb" phrases expand to "request USB Request Block"
> and "<blank> USB Request Block" which are particularly confusing, and
> non-specific, respectively.

How about command and response?

Sean

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[A Sun]

Hi again,

On 6/25/2019 12:12 PM, Sean Young wrote:
> Hello,
> 
> On Tue, Jun 25, 2019 at 11:01:32AM -0400, A Sun wrote:
>> On 6/25/2019 6:51 AM, Sean Young wrote:
>>> On Wed, Jun 19, 2019 at 03:54:21AM -0400, A Sun wrote:
>>>>
>>
>>>> -		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
>>>> +		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",
>>>
>>> I am not sure this makes things clearer. Some of the code still refers
>>> to request, e.g. mce_request_packet.
>>>
>>> Since this is an IR device, there is IR TX and RX; however this unrelated
>>> to that.
>>>
>>> There is one urb/endpoint on which commands are sent; on the other, we
>>> receiver responses and IR data. Calling those TX and RX is not a good
>>> idea I think.
>>
>> The tx urb described is also for IR data TX.
>> IR TX is one primary function/purpose of the device.
>>
>> It happens that the urb/endpoint for IR TX is the same urb/endpoint for
>> mceusb device commands.
> 
> The outgoing urb is for command, e.g. get version, set IR Rx timeout,
> set IR Rx carrier report, set IR wakeup protocol/scancode, resume
> device after suspend. Not everything is IR Tx.
> 

Right. Not everything is command either.
The subject USB interface endpoint-out (and -in) is intended for data
(interrupt/bulk) transfer. The only true data here is IR data.

It's a quirk of mceusb devices to use endpoint-out as a command channel too,
where commands masquerade as data.

A quick sampling of other USB devices, I'm seeing they customarily use
USB default endpoint 0 and control transfers (rather than data transfers)
for device management commands.

>>> The existing code refers to request and response, and also TX and RX in
>>> places. The microsoft documentation refers to "command and response" which
>>> would be consistent with the #define's we have (MCE_CMD_* and MCE_RSP_*).
>>>
>>
>> My intent is to try and better word several of the USB layer messages,
>> and avoid confusing Microsoft MCE terms in those messages.
>>
>> The original "(request) urb" phrases expand to "request USB Request Block"
>> and "<blank> USB Request Block" which are particularly confusing, and
>> non-specific, respectively.
> 
> How about command and response?
> 

Still seem confusing and awkward to me, as in "response USB Request Block",
or "command USB Request Block" that might be IR data. "Command" also suggests
to me USB interface endpoint 0, which isn't the case with mceusb.

Again, my intent is to avoid Microsoft MCE specific terms in messages pertaining
to USB.

In a quick look though other USB drivers, here are some other possibilities:

Endpoint-in / Endpoint-out	(not concise)
ep-in / ep-out			(abbrev may be too obscure)
in / out			("Error: in urb status.." confusing,
				 "in" is noun, adj, or verb?)
read / write			(confusing, "read" is noun, adj, verb?)
RD / WR
RX / TX

I suggest RX/TX. However, I'll have to leave it up to you to make a choice.

Thanks, ..A Sun

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[Sean Young]

Hi,

On Tue, Jun 25, 2019 at 05:29:02PM -0400, A Sun wrote:
> 
> Hi again,
> 
> On 6/25/2019 12:12 PM, Sean Young wrote:
> > Hello,
> > 
> > On Tue, Jun 25, 2019 at 11:01:32AM -0400, A Sun wrote:
> >> On 6/25/2019 6:51 AM, Sean Young wrote:
> >>> On Wed, Jun 19, 2019 at 03:54:21AM -0400, A Sun wrote:
> >>>>
> >>
> >>>> -		dev_err(ir->dev, "Error: request urb status = %d (TX HALT)",
> >>>> +		dev_err(ir->dev, "Error: tx urb status = %d (TX HALT)",
> >>>
> >>> I am not sure this makes things clearer. Some of the code still refers
> >>> to request, e.g. mce_request_packet.
> >>>
> >>> Since this is an IR device, there is IR TX and RX; however this unrelated
> >>> to that.
> >>>
> >>> There is one urb/endpoint on which commands are sent; on the other, we
> >>> receiver responses and IR data. Calling those TX and RX is not a good
> >>> idea I think.
> >>
> >> The tx urb described is also for IR data TX.
> >> IR TX is one primary function/purpose of the device.
> >>
> >> It happens that the urb/endpoint for IR TX is the same urb/endpoint for
> >> mceusb device commands.
> > 
> > The outgoing urb is for command, e.g. get version, set IR Rx timeout,
> > set IR Rx carrier report, set IR wakeup protocol/scancode, resume
> > device after suspend. Not everything is IR Tx.
> > 
> 
> Right. Not everything is command either.
> The subject USB interface endpoint-out (and -in) is intended for data
> (interrupt/bulk) transfer. The only true data here is IR data.
> 
> It's a quirk of mceusb devices to use endpoint-out as a command channel too,
> where commands masquerade as data.
> 
> A quick sampling of other USB devices, I'm seeing they customarily use
> USB default endpoint 0 and control transfers (rather than data transfers)
> for device management commands.
> 
> >>> The existing code refers to request and response, and also TX and RX in
> >>> places. The microsoft documentation refers to "command and response" which
> >>> would be consistent with the #define's we have (MCE_CMD_* and MCE_RSP_*).
> >>>
> >>
> >> My intent is to try and better word several of the USB layer messages,
> >> and avoid confusing Microsoft MCE terms in those messages.
> >>
> >> The original "(request) urb" phrases expand to "request USB Request Block"
> >> and "<blank> USB Request Block" which are particularly confusing, and
> >> non-specific, respectively.
> > 
> > How about command and response?
> > 
> 
> Still seem confusing and awkward to me, as in "response USB Request Block",
> or "command USB Request Block" that might be IR data. "Command" also suggests
> to me USB interface endpoint 0, which isn't the case with mceusb.
> 
> Again, my intent is to avoid Microsoft MCE specific terms in messages pertaining
> to USB.

You are right. Command and response isn't great.

> In a quick look though other USB drivers, here are some other possibilities:
> 
> Endpoint-in / Endpoint-out	(not concise)
> ep-in / ep-out			(abbrev may be too obscure)
> in / out			("Error: in urb status.." confusing,
> 				 "in" is noun, adj, or verb?)
> read / write			(confusing, "read" is noun, adj, verb?)
> RD / WR
> RX / TX
> 
> I suggest RX/TX. However, I'll have to leave it up to you to make a choice.

TBH I've been mulling this over. I think you're right that the terms should
be usb centric. TX seems confusing, there are mceusb devices with no IR 
transmit ports, so it would be surprising to see errors about TX. Your
first option is usb centric and can be wordy in errors messages and concise
in code (option #2).

However as you're writing patches I'll leave it up to you. It would be nice
if the usage is consistent in the driver code.


Thanks

Sean

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[A Sun]

Hi again,

On 7/15/2019 8:28 AM, Sean Young wrote:
> Hi,
> 
> On Tue, Jun 25, 2019 at 05:29:02PM -0400, A Sun wrote:


>> In a quick look though other USB drivers, here are some other possibilities:
>>
>> Endpoint-in / Endpoint-out	(not concise)
>> ep-in / ep-out			(abbrev may be too obscure)
>> in / out			("Error: in urb status.." confusing,
>> 				 "in" is noun, adj, or verb?)
>> read / write			(confusing, "read" is noun, adj, verb?)
>> RD / WR
>> RX / TX
>>
>> I suggest RX/TX. However, I'll have to leave it up to you to make a choice.
> 
> TBH I've been mulling this over. I think you're right that the terms should
> be usb centric. TX seems confusing, there are mceusb devices with no IR 
> transmit ports, so it would be surprising to see errors about TX. Your
> first option is usb centric and can be wordy in errors messages and concise
> in code (option #2).
> 
> However as you're writing patches I'll leave it up to you. It would be nice
> if the usage is consistent in the driver code.
> 

ok, I'll leave this patch proposal as is, where RX/TX is the favored terminology.
rx/tx was already in use elsewhere outside the message text of this patch,
and is prevalent in mceusb_dev_printdata() output.

I also found that my later patch submission:
  [PATCH v1] [media] mceusb: USB reset device following USB clear halt error
has an unintended dependency on this [PATCH v2 2/3].


FYI, I'm in progress on another mceusb patch to fix, and eliminate, the driver's
TX IR length limits. Limit causes -EINVAL errors for > ~300 pulse/space samples and
I've seen reports (and patches for) of appliances with IR over 400 pulse/spaces.

The future patch rewrites:
  mceusb_tx_ir()
And revises "write/tx" async I/O to sync I/O to do unlimited multipart TX IR.
These functions will need rewrite and rename:
  mce_async_callback() -> mce_tx_callback()
  mce_request_packet() -> mce_tx()
The present mce_async_out() name will become misleading. mce_command_out()
or mce_request_out() (which calls mce_tx()), are probably better names.

I'm still mulling over whether the more generic "read/write" term
(e.g. mce_write() and mce_write_callback()) may be a better migration path,
for future work.

Thanks, ..A Sun

Re: [PATCH v2 2/3] [media] mceusb: Reword messages referring to "urb"

[Sean Young]

Hi,

On Sun, Jul 21, 2019 at 05:31:55PM -0400, A Sun wrote:
> FYI, I'm in progress on another mceusb patch to fix, and eliminate, the driver's
> TX IR length limits. Limit causes -EINVAL errors for > ~300 pulse/space samples and
> I've seen reports (and patches for) of appliances with IR over 400 pulse/spaces.

This always looked like it needed improvement. Thank you!

> 
> The future patch rewrites:
>   mceusb_tx_ir()
> And revises "write/tx" async I/O to sync I/O to do unlimited multipart TX IR.
> These functions will need rewrite and rename:
>   mce_async_callback() -> mce_tx_callback()
>   mce_request_packet() -> mce_tx()
> The present mce_async_out() name will become misleading. mce_command_out()
> or mce_request_out() (which calls mce_tx()), are probably better names.
> 
> I'm still mulling over whether the more generic "read/write" term
> (e.g. mce_write() and mce_write_callback()) may be a better migration path,
> for future work.

Thanks.

Another thing the mceusb driver could do with is usb wakeup. I've hadn't
had the time to look at that.


Sean

[PATCH v2 3/3] [media] mceusb: Show USB halt/stall error recovery

[A Sun]

patch v2 revisions:
 . Limit patch to message changes only.

Update dev_err() messages to report status (including success) for each
step of USB RX HALT and TX HALT error recovery. If error recovery fails,
show the message:
        stuck RX HALT state requires USB Reset Device to clear
or
        stuck TX HALT state requires USB Reset Device to clear

This patch only affects RX and TX HALT error reporting.

The capability for mceusb to invoke USB reset device for itself is
deferred to a future patch. It's unsafe to perform usb_reset_device()
when and where the driver posts the "... requires USB Reset ..."
message.

Users can fix their mceusb device manually by issuing
ioctl(fd, USBDEVFS_RESET, 0) to the mceusb device, as in:
        $ sudo ./usbreset /dev/bus/usb/001/010

---

As seen on very rare occasions with mceusb device 2304:0225
        [59388.696941] mceusb 1-1.1.2:1.0: Error: urb status = -32 (RX HALT)
        [59388.698838] mceusb 1-1.1.2:1.0: rx clear halt error -32
the device can get into RX or TX HALT state where usb_clear_halt()
also fails and also returns -EPIPE (HALT/STALL). After which,
all further mceusb device control and data I/O fails with HALT/STALL.
Cause and problem replication conditions are still unknown.

Further troubleshooting revealed that usb_reset_device() successfully
restores mceusb device operation.

Of note is "modprobe -r mceusb" with "modprobe mceusb"
usb_reset_endpoint(), and usb_reset_configuration(), were all
unsuccessful.

Signed-off-by: A Sun <as1033x@comcast.net>
---
 drivers/media/rc/mceusb.c | 27 +++++++++++++++++++++------
 1 file changed, 21 insertions(+), 6 deletions(-)

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index efffb1795..fffd826c6 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -765,7 +765,7 @@ 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);
+		dev_dbg(ir->dev, "kevent %d already scheduled", kevent);
 	else
 		dev_dbg(ir->dev, "kevent %d scheduled", kevent);
 }
@@ -1404,19 +1404,27 @@ static void mceusb_deferred_kevent(struct work_struct *work)
 		container_of(work, struct mceusb_dev, kevent);
 	int status;
 
+	dev_err(ir->dev, "kevent handler called (flags 0x%lx)",
+		ir->kevent_flags);
+
 	if (test_bit(EVENT_RX_HALT, &ir->kevent_flags)) {
 		usb_unlink_urb(ir->urb_in);
 		status = usb_clear_halt(ir->usbdev, ir->pipe_in);
+		dev_err(ir->dev, "rx clear halt status = %d", status);
 		if (status < 0) {
-			dev_err(ir->dev, "rx clear halt error %d",
-				status);
+			/*
+			 * Unable to clear RX halt/stall.
+			 * Will need to call usb_reset_device().
+			 */
+			dev_err(ir->dev,
+				"stuck RX HALT state requires USB Reset Device to clear");
 		}
 		clear_bit(EVENT_RX_HALT, &ir->kevent_flags);
 		if (status == 0) {
 			status = usb_submit_urb(ir->urb_in, GFP_KERNEL);
 			if (status < 0) {
 				dev_err(ir->dev,
-					"rx unhalt submit urb error %d",
+					"rx unhalt submit urb error = %d",
 					status);
 			}
 		}
@@ -1424,8 +1432,15 @@ static void mceusb_deferred_kevent(struct work_struct *work)
 
 	if (test_bit(EVENT_TX_HALT, &ir->kevent_flags)) {
 		status = usb_clear_halt(ir->usbdev, ir->pipe_out);
-		if (status < 0)
-			dev_err(ir->dev, "tx clear halt error %d", status);
+		dev_err(ir->dev, "tx clear halt status = %d", status);
+		if (status < 0) {
+			/*
+			 * Unable to clear TX halt/stall.
+			 * Will need to call usb_reset_device().
+			 */
+			dev_err(ir->dev,
+				"stuck TX HALT state requires USB Reset Device to clear");
+		}
 		clear_bit(EVENT_TX_HALT, &ir->kevent_flags);
 	}
 }
-- 
2.11.0

Re: [PATCH v2 3/3] [media] mceusb: Show USB halt/stall error recovery

[A Sun]

This patch is superseded by
  [PATCH v1] [media] mceusb: USB reset device following USB clear halt error