diff mbox

[v2,7/7] media: rc: mceusb: allow the timeout to be configurable

Message ID 20180418112428.zk3lmdxoqv46weph@gofer.mess.org (mailing list archive)
State New, archived
Headers show

Commit Message

Sean Young April 18, 2018, 11:24 a.m. UTC
Hello Hias,

On Tue, Apr 17, 2018 at 09:14:57PM +0200, Matthias Reichl wrote:
> On Sun, Apr 08, 2018 at 10:19:42PM +0100, Sean Young wrote:
> > mceusb devices have a default timeout of 100ms, but this can be changed.
> 
> We finally added a backport of the v2 series (and also the mce_kbd
> series) to LibreELEC yesterday and ratcher quickly received 2 bugreports
> from users using mceusb receivers.
> 
> Local testing on RPi/gpio-ir and Intel NUC/ite-cir was fine, I've
> been using the v2 series for over a week without issues on
> LibreELEC (RPi with kernel 4.14).
> 
> Here are the links to the bugreports and logs:
> https://forum.kodi.tv/showthread.php?tid=298461&pid=2726684#pid2726684
> https://forum.kodi.tv/showthread.php?tid=298462&pid=2726690#pid2726690
> 
> Both users are using similar mceusb receivers:
> 
> Log 1:
> [    6.418218] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (147a:e017) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/rc/rc0
> [    6.418358] input: Media Center Ed. eHome Infrared Remote Transceiver (147a:e017) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/rc/rc0/input0
> [    6.419443] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> [    6.608114] mceusb 1-1.3:1.0: Registered Formosa21 SnowflakeEmulation with mce emulator interface version 1
> [    6.608125] mceusb 1-1.3:1.0: 0 tx ports (0x0 cabled) and 1 rx sensors (0x1 active)
> 
> Log 2:
> [    3.023361] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (147a:e03e) as /devices/pci0000:00/0000:00:14.0/usb1/1-10/1-10:1.0/rc/rc0
> [    3.023393] input: Media Center Ed. eHome Infrared Remote Transceiver (147a:e03e) as /devices/pci0000:00/0000:00:14.0/usb1/1-10/1-10:1.0/rc/rc0/input11
> [    3.023868] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> [    3.119384] input: eventlircd as /devices/virtual/input/input21
> [    3.138625] ip6_tables: (C) 2000-2006 Netfilter Core Team
> [    3.196830] mceusb 1-10:1.0: Registered Formosa21 eHome Infrared Transceiver with mce emulator interface version 2
> [    3.196836] mceusb 1-10:1.0: 0 tx ports (0x0 cabled) and 1 rx sensors (0x1 active)
> 
> In both cases ir-keytable doesn't report any scancodes and the
> ir-ctl -r output contains very odd long space values where I'd expect
> a short timeout instead:
> 
> gap between messages:
> space 800
> pulse 450
> space 16777215
> space 25400
> pulse 2650
> space 800
> 
> end of last message:
> space 800
> pulse 450
> space 16777215
> timeout 31750
> 
> This patch applied cleanly on 4.14 and the mceusb history from
> 4.14 to media/master looked rather unsuspicious. I'm not 100% sure
> if I might have missed a dependency when backporting the patch
> or if this is indeed an issue of this patch on these particular
> (or maybe some more) mceusb receivers.

Thanks again for a great bug report and analysis! So, it seems with the
shorter timeout, some mceusb devices add a specific "timeout" code to
the IR data stream (0x80) rather than a space. The current mceusb code
resets the decoders in this case, causing the IR decoders to reset and
lirc to report a space of 0xffffff.

Turns out that one of my mceusb devices also suffers from this, I don't
know how I missed this. Anyway hopefully this will solve the problem.


Thanks

Sean

From 92d27b206e51993e927dc0b3aba210a621eef3d0 Mon Sep 17 00:00:00 2001
From: Sean Young <sean@mess.org>
Date: Wed, 18 Apr 2018 10:36:25 +0100
Subject: [PATCH] media: rc: mceusb: IR of length 0 means IR timeout, not reset

The last usb packet with IR data will end with 0x80 (MCE_IRDATA_TRAILER).
If we reset the decoder state at this point, IR decoding can fail.

Signed-off-by: Sean Young <sean@mess.org>
---
 drivers/media/rc/mceusb.c | 7 ++++++-
 1 file changed, 6 insertions(+), 1 deletion(-)

Comments

Matthias Reichl April 18, 2018, 5:42 p.m. UTC | #1
Hi Sean,

On Wed, Apr 18, 2018 at 12:24:29PM +0100, Sean Young wrote:
> Hello Hias,
> 
> On Tue, Apr 17, 2018 at 09:14:57PM +0200, Matthias Reichl wrote:
> > On Sun, Apr 08, 2018 at 10:19:42PM +0100, Sean Young wrote:
> > > mceusb devices have a default timeout of 100ms, but this can be changed.
> > 
> > We finally added a backport of the v2 series (and also the mce_kbd
> > series) to LibreELEC yesterday and ratcher quickly received 2 bugreports
> > from users using mceusb receivers.
> > 
> > Local testing on RPi/gpio-ir and Intel NUC/ite-cir was fine, I've
> > been using the v2 series for over a week without issues on
> > LibreELEC (RPi with kernel 4.14).
> > 
> > Here are the links to the bugreports and logs:
> > https://forum.kodi.tv/showthread.php?tid=298461&pid=2726684#pid2726684
> > https://forum.kodi.tv/showthread.php?tid=298462&pid=2726690#pid2726690
> > 
> > Both users are using similar mceusb receivers:
> > 
> > Log 1:
> > [    6.418218] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (147a:e017) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/rc/rc0
> > [    6.418358] input: Media Center Ed. eHome Infrared Remote Transceiver (147a:e017) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/rc/rc0/input0
> > [    6.419443] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> > [    6.608114] mceusb 1-1.3:1.0: Registered Formosa21 SnowflakeEmulation with mce emulator interface version 1
> > [    6.608125] mceusb 1-1.3:1.0: 0 tx ports (0x0 cabled) and 1 rx sensors (0x1 active)
> > 
> > Log 2:
> > [    3.023361] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (147a:e03e) as /devices/pci0000:00/0000:00:14.0/usb1/1-10/1-10:1.0/rc/rc0
> > [    3.023393] input: Media Center Ed. eHome Infrared Remote Transceiver (147a:e03e) as /devices/pci0000:00/0000:00:14.0/usb1/1-10/1-10:1.0/rc/rc0/input11
> > [    3.023868] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> > [    3.119384] input: eventlircd as /devices/virtual/input/input21
> > [    3.138625] ip6_tables: (C) 2000-2006 Netfilter Core Team
> > [    3.196830] mceusb 1-10:1.0: Registered Formosa21 eHome Infrared Transceiver with mce emulator interface version 2
> > [    3.196836] mceusb 1-10:1.0: 0 tx ports (0x0 cabled) and 1 rx sensors (0x1 active)
> > 
> > In both cases ir-keytable doesn't report any scancodes and the
> > ir-ctl -r output contains very odd long space values where I'd expect
> > a short timeout instead:
> > 
> > gap between messages:
> > space 800
> > pulse 450
> > space 16777215
> > space 25400
> > pulse 2650
> > space 800
> > 
> > end of last message:
> > space 800
> > pulse 450
> > space 16777215
> > timeout 31750
> > 
> > This patch applied cleanly on 4.14 and the mceusb history from
> > 4.14 to media/master looked rather unsuspicious. I'm not 100% sure
> > if I might have missed a dependency when backporting the patch
> > or if this is indeed an issue of this patch on these particular
> > (or maybe some more) mceusb receivers.
> 
> Thanks again for a great bug report and analysis! So, it seems with the
> shorter timeout, some mceusb devices add a specific "timeout" code to
> the IR data stream (0x80) rather than a space. The current mceusb code
> resets the decoders in this case, causing the IR decoders to reset and
> lirc to report a space of 0xffffff.
> 
> Turns out that one of my mceusb devices also suffers from this, I don't
> know how I missed this. Anyway hopefully this will solve the problem.

Thanks a lot for the quick fix!

I can't test myself as I don't have the hardware, but we will
include the patch in tonight's LibreELEC build and I asked the
users to test it. I'll keep you posted about the outcome.

so long,

Hias

> 
> 
> Thanks
> 
> Sean
> 
> >>From 92d27b206e51993e927dc0b3aba210a621eef3d0 Mon Sep 17 00:00:00 2001
> From: Sean Young <sean@mess.org>
> Date: Wed, 18 Apr 2018 10:36:25 +0100
> Subject: [PATCH] media: rc: mceusb: IR of length 0 means IR timeout, not reset
> 
> The last usb packet with IR data will end with 0x80 (MCE_IRDATA_TRAILER).
> If we reset the decoder state at this point, IR decoding can fail.
> 
> Signed-off-by: Sean Young <sean@mess.org>
> ---
>  drivers/media/rc/mceusb.c | 7 ++++++-
>  1 file changed, 6 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
> index c97cb2eb1c5f..5c0bf61fae26 100644
> --- a/drivers/media/rc/mceusb.c
> +++ b/drivers/media/rc/mceusb.c
> @@ -1201,7 +1201,12 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
>  			if (ir->rem) {
>  				ir->parser_state = PARSE_IRDATA;
>  			} else {
> -				ir_raw_event_reset(ir->rc);
> +				init_ir_raw_event(&rawir);
> +				rawir.timeout = 1;
> +				rawir.duration = ir->rc->timeout;
> +				if (ir_raw_event_store_with_filter(ir->rc,
> +								   &rawir))
> +					event = true;
>  				ir->pulse_tunit = 0;
>  				ir->pulse_count = 0;
>  			}
> -- 
> 2.14.3
>
Matthias Reichl April 19, 2018, 10:17 p.m. UTC | #2
Hi Sean,

On Wed, Apr 18, 2018 at 07:42:29PM +0200, Matthias Reichl wrote:
> Hi Sean,
> 
> On Wed, Apr 18, 2018 at 12:24:29PM +0100, Sean Young wrote:
> > Hello Hias,
> > 
> > On Tue, Apr 17, 2018 at 09:14:57PM +0200, Matthias Reichl wrote:
> > > On Sun, Apr 08, 2018 at 10:19:42PM +0100, Sean Young wrote:
> > > > mceusb devices have a default timeout of 100ms, but this can be changed.
> > > 
> > > We finally added a backport of the v2 series (and also the mce_kbd
> > > series) to LibreELEC yesterday and ratcher quickly received 2 bugreports
> > > from users using mceusb receivers.
> > > 
> > > Local testing on RPi/gpio-ir and Intel NUC/ite-cir was fine, I've
> > > been using the v2 series for over a week without issues on
> > > LibreELEC (RPi with kernel 4.14).
> > > 
> > > Here are the links to the bugreports and logs:
> > > https://forum.kodi.tv/showthread.php?tid=298461&pid=2726684#pid2726684
> > > https://forum.kodi.tv/showthread.php?tid=298462&pid=2726690#pid2726690
> > > 
> > > Both users are using similar mceusb receivers:
> > > 
> > > Log 1:
> > > [    6.418218] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (147a:e017) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/rc/rc0
> > > [    6.418358] input: Media Center Ed. eHome Infrared Remote Transceiver (147a:e017) as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3/1-1.3:1.0/rc/rc0/input0
> > > [    6.419443] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> > > [    6.608114] mceusb 1-1.3:1.0: Registered Formosa21 SnowflakeEmulation with mce emulator interface version 1
> > > [    6.608125] mceusb 1-1.3:1.0: 0 tx ports (0x0 cabled) and 1 rx sensors (0x1 active)
> > > 
> > > Log 2:
> > > [    3.023361] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (147a:e03e) as /devices/pci0000:00/0000:00:14.0/usb1/1-10/1-10:1.0/rc/rc0
> > > [    3.023393] input: Media Center Ed. eHome Infrared Remote Transceiver (147a:e03e) as /devices/pci0000:00/0000:00:14.0/usb1/1-10/1-10:1.0/rc/rc0/input11
> > > [    3.023868] rc rc0: lirc_dev: driver ir-lirc-codec (mceusb) registered at minor = 0
> > > [    3.119384] input: eventlircd as /devices/virtual/input/input21
> > > [    3.138625] ip6_tables: (C) 2000-2006 Netfilter Core Team
> > > [    3.196830] mceusb 1-10:1.0: Registered Formosa21 eHome Infrared Transceiver with mce emulator interface version 2
> > > [    3.196836] mceusb 1-10:1.0: 0 tx ports (0x0 cabled) and 1 rx sensors (0x1 active)
> > > 
> > > In both cases ir-keytable doesn't report any scancodes and the
> > > ir-ctl -r output contains very odd long space values where I'd expect
> > > a short timeout instead:
> > > 
> > > gap between messages:
> > > space 800
> > > pulse 450
> > > space 16777215
> > > space 25400
> > > pulse 2650
> > > space 800
> > > 
> > > end of last message:
> > > space 800
> > > pulse 450
> > > space 16777215
> > > timeout 31750
> > > 
> > > This patch applied cleanly on 4.14 and the mceusb history from
> > > 4.14 to media/master looked rather unsuspicious. I'm not 100% sure
> > > if I might have missed a dependency when backporting the patch
> > > or if this is indeed an issue of this patch on these particular
> > > (or maybe some more) mceusb receivers.
> > 
> > Thanks again for a great bug report and analysis! So, it seems with the
> > shorter timeout, some mceusb devices add a specific "timeout" code to
> > the IR data stream (0x80) rather than a space. The current mceusb code
> > resets the decoders in this case, causing the IR decoders to reset and
> > lirc to report a space of 0xffffff.
> > 
> > Turns out that one of my mceusb devices also suffers from this, I don't
> > know how I missed this. Anyway hopefully this will solve the problem.
> 
> Thanks a lot for the quick fix!
> 
> I can't test myself as I don't have the hardware, but we will
> include the patch in tonight's LibreELEC build and I asked the
> users to test it. I'll keep you posted about the outcome.

One of the affected users reported back that the fix worked fine!

I'm keeping an eye on further reports but so far I'd say everything's
working really well.

Great job and thanks a lot for the improvements!

so long,

Hias

> 
> so long,
> 
> Hias
> 
> > 
> > 
> > Thanks
> > 
> > Sean
> > 
> > >>From 92d27b206e51993e927dc0b3aba210a621eef3d0 Mon Sep 17 00:00:00 2001
> > From: Sean Young <sean@mess.org>
> > Date: Wed, 18 Apr 2018 10:36:25 +0100
> > Subject: [PATCH] media: rc: mceusb: IR of length 0 means IR timeout, not reset
> > 
> > The last usb packet with IR data will end with 0x80 (MCE_IRDATA_TRAILER).
> > If we reset the decoder state at this point, IR decoding can fail.
> > 
> > Signed-off-by: Sean Young <sean@mess.org>
> > ---
> >  drivers/media/rc/mceusb.c | 7 ++++++-
> >  1 file changed, 6 insertions(+), 1 deletion(-)
> > 
> > diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
> > index c97cb2eb1c5f..5c0bf61fae26 100644
> > --- a/drivers/media/rc/mceusb.c
> > +++ b/drivers/media/rc/mceusb.c
> > @@ -1201,7 +1201,12 @@ static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
> >  			if (ir->rem) {
> >  				ir->parser_state = PARSE_IRDATA;
> >  			} else {
> > -				ir_raw_event_reset(ir->rc);
> > +				init_ir_raw_event(&rawir);
> > +				rawir.timeout = 1;
> > +				rawir.duration = ir->rc->timeout;
> > +				if (ir_raw_event_store_with_filter(ir->rc,
> > +								   &rawir))
> > +					event = true;
> >  				ir->pulse_tunit = 0;
> >  				ir->pulse_count = 0;
> >  			}
> > -- 
> > 2.14.3
> >
Matthias Reichl April 21, 2018, 1:18 p.m. UTC | #3
Hi Sean,

On Fri, Apr 20, 2018 at 12:17:23AM +0200, Matthias Reichl wrote:
> One of the affected users reported back that the fix worked fine!
> 
> I'm keeping an eye on further reports but so far I'd say everything's
> working really well.

Another bug report came in, button press results in multiple
key down/up events
https://forum.kodi.tv/showthread.php?tid=298461&pid=2727837#pid2727837
(and following posts).

ir-ctl -r output looks fine to me, but ir-keytable -t output suggests
we'll need a margin between raw timeout and key up timeout:

https://pastebin.com/6RTSGXvp
2199.824106: event type EV_MSC(0x04): scancode = 0x800f0419
2199.824106: event type EV_KEY(0x01) key_down: KEY_STOP(0x0080)
2199.824106: event type EV_SYN(0x00).
2199.887081: event type EV_KEY(0x01) key_up: KEY_STOP(0x0080)
2199.887081: event type EV_MSC(0x04): scancode = 0x800f0422
2199.887081: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
2199.887081: event type EV_SYN(0x00).
2200.029804: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
2200.029804: event type EV_SYN(0x00).

so long,

Hias
Matthias Reichl April 21, 2018, 5:41 p.m. UTC | #4
On Sat, Apr 21, 2018 at 03:18:52PM +0200, Matthias Reichl wrote:
> Hi Sean,
> 
> On Fri, Apr 20, 2018 at 12:17:23AM +0200, Matthias Reichl wrote:
> > One of the affected users reported back that the fix worked fine!
> > 
> > I'm keeping an eye on further reports but so far I'd say everything's
> > working really well.
> 
> Another bug report came in, button press results in multiple
> key down/up events
> https://forum.kodi.tv/showthread.php?tid=298461&pid=2727837#pid2727837
> (and following posts).
> 
> ir-ctl -r output looks fine to me, but ir-keytable -t output suggests
> we'll need a margin between raw timeout and key up timeout:
> 
> https://pastebin.com/6RTSGXvp
> 2199.824106: event type EV_MSC(0x04): scancode = 0x800f0419
> 2199.824106: event type EV_KEY(0x01) key_down: KEY_STOP(0x0080)
> 2199.824106: event type EV_SYN(0x00).
> 2199.887081: event type EV_KEY(0x01) key_up: KEY_STOP(0x0080)
> 2199.887081: event type EV_MSC(0x04): scancode = 0x800f0422
> 2199.887081: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
> 2199.887081: event type EV_SYN(0x00).
> 2200.029804: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
> 2200.029804: event type EV_SYN(0x00).

Sorry, just noticed I snipped off the interesting part, here
is the rest:

2200.036070: event type EV_MSC(0x04): scancode = 0x800f0422
2200.036070: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
2200.036070: event type EV_SYN(0x00).
2200.143067: event type EV_MSC(0x04): scancode = 0x800f0422
2200.143067: event type EV_SYN(0x00).
2200.206061: event type EV_MSC(0x04): scancode = 0x800f0422
2200.206061: event type EV_SYN(0x00).
2200.346472: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
2200.346472: event type EV_SYN(0x00).

I looked at the log again, and now it doesn't make much sense
to me.

I'm not exactly sure what happened with the first KEY_OK
scancode, that seems to have been decoded ~60ms after the
KEY_STOP scancode (.887 vs .824).

The second KEY_OK scancode was decoded ~ 150ms after the first,
(and caused the problem), delay to third is 107ms, to fourth 63ms.

I'll ask the user to change batteries on the remote and check
if the reception is OK, could be that this was a false alarm.

Adding some margin (maybe 20-50ms) for keyup could still make
sense though, as currently we have basically just the timeout
as margin, which can be quite low and round to 1-2 jiffies.

so long,

Hias
Matthias Reichl May 7, 2018, 3:54 p.m. UTC | #5
Hi Sean!

[ I trimmed the Cc list, as this is mceusb specific ]

On Sat, Apr 21, 2018 at 07:41:21PM +0200, Matthias Reichl wrote:
> On Sat, Apr 21, 2018 at 03:18:52PM +0200, Matthias Reichl wrote:
> > Another bug report came in, button press results in multiple
> > key down/up events
> > https://forum.kodi.tv/showthread.php?tid=298461&pid=2727837#pid2727837
> > (and following posts).

The original reporter gave up before I could get enough info
to understand what's going on, but now another user with an identical
receiver and the same problems showed up and I could get debug logs.

FYI: I've uploaded the full dmesg here if you need more info
or I snipped off too much:
http://www.horus.com/~hias/tmp/mceusb-settimeout-issue.txt

Here's the info about the IR receiver:
[    2.208684] usb 1-1.3: New USB device found, idVendor=1784, idProduct=0011
[    2.208699] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    2.208708] usb 1-1.3: Product: eHome Infrared Transceiver
[    2.208716] usb 1-1.3: Manufacturer: Topseed Technology Corp.
[    2.208724] usb 1-1.3: SerialNumber: EID0137AG-8-0000104054

With timeout configuration in the mceusb driver disabled everything
works fine. But with timeout configuration enabled spurious "keyup"
events show up during a button press and sometimes also a spurious
"ghost" keypress several seconds after the original button press.

Here's the ir-keytable -t output to illustrate the behaviour:

80.385585: event type EV_MSC(0x04): scancode = 0x800f0422
80.385585: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
80.385585: event type EV_SYN(0x00).
80.492469: event type EV_MSC(0x04): scancode = 0x800f0422
80.492469: event type EV_SYN(0x00).
80.633371: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
80.633371: event type EV_SYN(0x00).
80.642478: event type EV_MSC(0x04): scancode = 0x800f0422
80.642478: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
80.642478: event type EV_SYN(0x00).
80.783375: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
80.783375: event type EV_SYN(0x00).
84.318011: event type EV_MSC(0x04): scancode = 0x800f0422
84.318011: event type EV_KEY(0x01) key_down: KEY_OK(0x0160)
84.318011: event type EV_SYN(0x00).
84.460049: event type EV_KEY(0x01) key_up: KEY_OK(0x0160)
84.460049: event type EV_SYN(0x00).

From the kernel log the first 2 scancodes are perfectly fine,
we get the timeout space in chunks, followed by the "End of raw IR data"
message and the scancode is properly decoded. Then about 45ms later
the pulses of the following IR message come in.

Snippet from end of second scancode:

[   80.505896] mceusb 1-1.3:1.0: rx data: 81 7f (length=2)
[   80.505902] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   80.505907] mceusb 1-1.3:1.0: Storing space with duration 6350000
[   80.505911] mceusb 1-1.3:1.0: processed IR data
[   80.506894] mceusb 1-1.3:1.0: rx data: 81 05 (length=2)
[   80.506899] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   80.506904] mceusb 1-1.3:1.0: Storing space with duration 250000
[   80.506908] rc rc0: enter idle mode
[   80.506913] rc rc0: sample: (25650us space)
[   80.506918] mceusb 1-1.3:1.0: rx data: 80 (length=1)
[   80.506922] mceusb 1-1.3:1.0: End of raw IR data
[   80.506925] mceusb 1-1.3:1.0: processed IR data
[   80.506943] rc rc0: RC6 decode started at state 6 (25650us space)
[   80.506949] rc rc0: RC6 decode started at state 8 (25650us space)
[   80.506955] rc rc0: RC6(6A) proto 0x0013, scancode 0x800f0422 (toggle: 1)
[   80.506961] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (1784:0011): scancode 0x800f0422 keycode 0x160
[   80.552906] mceusb 1-1.3:1.0: rx data: 81 b5 (length=2)
[   80.552914] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   80.552919] mceusb 1-1.3:1.0: Storing pulse with duration 2650000
[   80.552924] rc rc0: leave idle mode

But then, the end of the third scancode gets interesting. The
last chunk of the timeout space is missing and instead we get
a combined message with the remaining space and a zero-length
pulse just before the fourth IR message starts. Of course, this is
too late and the keyup timer had already expired:

[   80.612896] mceusb 1-1.3:1.0: rx data: 81 7f (length=2)
[   80.612903] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   80.612908] mceusb 1-1.3:1.0: Storing space with duration 6350000
[   80.612912] mceusb 1-1.3:1.0: processed IR data
[   80.647880] rc rc0: keyup key 0x0160
[   80.656901] mceusb 1-1.3:1.0: rx data: 82 05 80 (length=3)
[   80.656908] mceusb 1-1.3:1.0: Raw IR data, 2 pulse/space samples
[   80.656913] mceusb 1-1.3:1.0: Storing space with duration 250000
[   80.656918] rc rc0: enter idle mode
[   80.656923] rc rc0: sample: (25650us space)
[   80.656928] mceusb 1-1.3:1.0: Storing pulse with duration 0
[   80.656931] rc rc0: leave idle mode
[   80.656935] mceusb 1-1.3:1.0: processed IR data
[   80.656967] rc rc0: RC6 decode started at state 6 (25650us space)
[   80.656973] rc rc0: RC6 decode started at state 8 (25650us space)
[   80.656979] rc rc0: RC6(6A) proto 0x0013, scancode 0x800f0422 (toggle: 1)
[   80.656986] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (1784:0011): scancode 0x800f0422 keycode 0x160
[   80.656998] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (1784:0011): key down event, key 0x0160, protocol 0x0013, scancode 0x800f0422
[   80.659900] mceusb 1-1.3:1.0: rx data: 81 b6 (length=2)
[   80.659908] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   80.659913] mceusb 1-1.3:1.0: Storing pulse with duration 2700000
[   80.659916] mceusb 1-1.3:1.0: processed IR data

A similar thing happened on the fourth IR message, a spurious pulse
picked up by the IR receiver about 4 seconds after the message seems
to have made it send out it's data and flush the decoder:

[   80.719899] mceusb 1-1.3:1.0: rx data: 81 7f (length=2)
[   80.719905] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   80.719910] mceusb 1-1.3:1.0: Storing space with duration 6350000
[   80.719914] mceusb 1-1.3:1.0: processed IR data
[   80.797908] rc rc0: keyup key 0x0160
[   84.332919] mceusb 1-1.3:1.0: rx data: 83 05 80 81 (length=4)
[   84.332934] mceusb 1-1.3:1.0: Raw IR data, 3 pulse/space samples
[   84.332944] mceusb 1-1.3:1.0: Storing space with duration 250000
[   84.332954] rc rc0: enter idle mode
[   84.332964] rc rc0: sample: (25650us space)
[   84.332973] mceusb 1-1.3:1.0: Storing pulse with duration 0
[   84.332981] rc rc0: leave idle mode
[   84.332989] mceusb 1-1.3:1.0: Storing pulse with duration 50000
[   84.332997] mceusb 1-1.3:1.0: processed IR data
[   84.333046] rc rc0: RC6 decode started at state 6 (25650us space)
[   84.333057] rc rc0: RC6 decode started at state 8 (25650us space)
[   84.333068] rc rc0: RC6(6A) proto 0x0013, scancode 0x800f0422 (toggle: 1)
[   84.333080] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (1784:0011): scanco
de 0x800f0422 keycode 0x160
[   84.333098] rc rc0: Media Center Ed. eHome Infrared Remote Transceiver (1784:0011): key do
wn event, key 0x0160, protocol 0x0013, scancode 0x800f0422
[   84.339912] mceusb 1-1.3:1.0: rx data: 81 7f (length=2)
[   84.339925] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   84.339934] mceusb 1-1.3:1.0: Storing space with duration 6350000
[   84.339944] rc rc0: sample: (00050us pulse)
[   84.339952] mceusb 1-1.3:1.0: processed IR data
[   84.339994] rc rc0: RC6 decode failed at state 0 (50us pulse)
[   84.345908] mceusb 1-1.3:1.0: rx data: 81 7f (length=2)
[   84.345918] mceusb 1-1.3:1.0: Raw IR data, 1 pulse/space samples
[   84.345927] mceusb 1-1.3:1.0: Storing space with duration 6350000
[   84.345935] mceusb 1-1.3:1.0: processed IR data

We have both rc-6 and NEC protocol enabled and the timeout is
therefore auto-configured to 25650us. I'm wondering if this could
have something to do with the odd behaviour as we'll get a very
short 250us space message from the IR receiver (in addition to
the 4 6350us spaces). Maybe this triggers some bug in the IR
receiver?

As we saw those issues on RPi, where USB has always been a bit
problematic, I wouldn't rule that out as a possible cause as well.

I've asked the reporter to test with various other timeout values,
this should hopefully provide some more info.

so long,

Hias
diff mbox

Patch

diff --git a/drivers/media/rc/mceusb.c b/drivers/media/rc/mceusb.c
index c97cb2eb1c5f..5c0bf61fae26 100644
--- a/drivers/media/rc/mceusb.c
+++ b/drivers/media/rc/mceusb.c
@@ -1201,7 +1201,12 @@  static void mceusb_process_ir_data(struct mceusb_dev *ir, int buf_len)
 			if (ir->rem) {
 				ir->parser_state = PARSE_IRDATA;
 			} else {
-				ir_raw_event_reset(ir->rc);
+				init_ir_raw_event(&rawir);
+				rawir.timeout = 1;
+				rawir.duration = ir->rc->timeout;
+				if (ir_raw_event_store_with_filter(ir->rc,
+								   &rawir))
+					event = true;
 				ir->pulse_tunit = 0;
 				ir->pulse_count = 0;
 			}