Menu
▾
▴
#324 serial ir regressions / fixes
Hi,
I've been running a very unhappy homebrew serial ir the last 18
months or so after the last attempt at update ~mid 2016 resulted
in a 'ffs that'll have to do' state of, remote 'worked' again, but
repeats didn't.
Fast-forwarding/rewinding of late has finally caused me sufficent
anger (not to mention minor RSI pain) to deal with it. The
assumption that 'the lirc driver kernel migration efforts must be
well behind us and more or less stable by now' was also a not so
insignificant factor here too :)
> uname -r
4.15.10
> lsmod | grep ir
ir_lirc_codec 16384 0
lirc_dev 16384 2 ir_lirc_codec
serial_ir 16384 0
rc_core 36864 5 rc_rc6_mce,ir_lirc_codec,lirc_dev,serial_ir
remote config:
begin remote
name Toshiba_VT-852EW
bits 32
flags SPACE_ENC|CONST_LENGTH
eps 30
aeps 100
header 9109 4443
one 639 1620
zero 639 507
ptrail 638
repeat 9105 2173
gap 107971
toggle_bit_mask 0x0
begin codes
ch+ 0x22DDD827
ch- 0x22DDF807
I irrecorded this remote using git2014Aug07.
So attempting git2018Mar20 resulted in:
-single key press recognised by irw client, and only once too. lircd
receiving but failing to process any more input
Bisected back to:
beeb4adb1d114bcf5faf060b9543cc504e24a221 is the first bad commit
commit beeb4adb1d114bcf5faf060b9543cc504e24a221
Author: Alec Leamas <leamas.alec@gmail.com>
Date: Fri Jun 16 10:13:31 2017 +0200
lib, lircd: Remove --release support.
[reference attached: 'debug.once.pre' and 'debug.once.post' lircd logs]
pre beeb4adb1d114bcf5faf060b9543cc504e24a221
lircd-0.10.0-devel[21992]: Trace: writing to client 0: 0000000022dda857 00 play/arrow_up Toshiba_VT-852EW
..
lircd-0.10.0-devel[21992]: Trace: trying "Toshiba_VT-852EW" remote
..
lircd-0.10.0-devel[21992]: Trace: sync
lircd-0.10.0-devel[21992]: Trace2: expecting pulse: 9105
lircd-0.10.0-devel[21992]: Trace2: +p9075
lircd-0.10.0-devel[21992]: Trace2: pending space: 2173
lircd-0.10.0-devel[21992]: Trace2: expecting pulse: 638
lircd-0.10.0-devel[21992]: Trace2: +s2183
lircd-0.10.0-devel[21992]: Trace2: pending space: 0
lircd-0.10.0-devel[21992]: Trace2: timeout: 100000
lircd-0.10.0-devel[21992]: Trace: no repeat
..
lircd-0.10.0-devel[21992]: Trace: failed on bit 1
lircd-0.10.0-devel[21992]: Trace: failed on code
lircd-0.10.0-devel[21992]: Trace: decoding failed for all remotes
post beeb4adb1d114bcf5faf060b9543cc504e24a221:
lircd-0.10.0-devel[16590]: Trace: writing to client 0: 0000000022dda857 00 play/arrow_up Toshiba_VT-852EW
..
lircd-0.10.0-devel[16590]: Trace: trying "Toshiba_VT-852EW" remote
..
lircd-0.10.0-devel[16590]: Trace: sync
lircd-0.10.0-devel[16590]: Trace2: expecting pulse: 9105
lircd-0.10.0-devel[16590]: Trace2: +p9057
lircd-0.10.0-devel[16590]: Trace2: pending space: 2173
lircd-0.10.0-devel[16590]: Trace2: expecting pulse: 638
lircd-0.10.0-devel[16590]: Trace2: +s2211
lircd-0.10.0-devel[16590]: Trace2: pending space: 0
lircd-0.10.0-devel[16590]: Trace2: timeout: 100000
lircd-0.10.0-devel[16590]: Trace: no repeat
..
lircd-0.10.0-devel[16590]: Trace: failed on bit 1
lircd-0.10.0-devel[16590]: Trace: failed on code
lircd-0.10.0-devel[16590]: Trace: decoding failed for all remotes
lircd-0.10.0-devel[16590]: Trace2: pending pulse: 0
lircd-0.10.0-devel[16590]: Trace2: pending space: 0
lircd-0.10.0-devel[16590]: Trace: trying "Toshiba_VT-852EW" remote
lircd-0.10.0-devel[16590]: Trace2: pending pulse: 0
lircd-0.10.0-devel[16590]: Trace2: pending space: 0
lircd-0.10.0-devel[16590]: Trace2: <s2211
lircd-0.10.0-devel[16590]: Trace: sync
lircd-0.10.0-devel[16590]: Trace2: expecting pulse: 9109
lircd-0.10.0-devel[16590]: Trace2: +p630
lircd-0.10.0-devel[16590]: Trace2: unget: 1
lircd-0.10.0-devel[16590]: Trace: failed on header
lircd-0.10.0-devel[16590]: Trace: decoding failed for all remotes
lircd-0.10.0-devel[16590]: Trace2: pending pulse: 0
lircd-0.10.0-devel[16590]: Trace2: pending space: 0
lircd-0.10.0-devel[16590]: Trace: trying "Toshiba_VT-852EW" remote
lircd-0.10.0-devel[16590]: Trace2: pending pulse: 0
lircd-0.10.0-devel[16590]: Trace2: pending space: 0
lircd-0.10.0-devel[16590]: Trace2: <p630
lircd-0.10.0-devel[16590]: Trace1: space expected
lircd-0.10.0-devel[16590]: Trace: failed on sync
lircd-0.10.0-devel[16590]: Trace: decoding failed for all remotes
..
repeated..
..
The difference in the output is that 'pre', new presses would start
that log snippet again, the client (irw) registering a key press
each time, but 'post', those last 11 lines are just repeated over
and over without the client registering any new key presses.
I stumbled across this mailing list reference:
https://sourceforge.net/p/lirc/mailman/message/35911993/
and can confirm the same 100% cpu result.
The attached patch '0001-fix-regression-due-to-commit-beeb4ad.patch'
partially reverts the commit to 'fix' this issue.
From c137e343e6735979001c39652ef0c0cede0d299f Mon Sep 17 00:00:00 2001
From: Pete Beardmore <pete.beardmore@msn.com>
Date: Tue, 20 Mar 2018 07:42:28 +0000
Subject: [PATCH] fix regression due to commit 'beeb4ad'
-commit beeb4adb1d114bcf5faf060b9543cc504e24a221 strips out support
for forwarding 'release' events, but inadvertantly removes release
events locally
Could be totally off on the reasoning of course!
So then I was back to 'working' remote, but with no repeats.
Bisecting back to
commit c824c0f46d8d239c3ab55656422584500eaa469c (HEAD)
Author: Jon Bergli Heier snakebite@jvnv.net
Date: Sun Oct 4 20:44:00 2015 +0200
lib: receive: Return 0 on poll() timeout.
Signed-off-by: Jon Bergli Heier <snakebite@jvnv.net>
diff --git a/lib/receive.c b/lib/receive.c
index aaf21451..2bf37172 100644
--- a/lib/receive.c
+++ b/lib/receive.c
@@ -167,6 +167,8 @@ int waitfordata(__u32 maxusec)
do {
do {
ret = poll(&pfd, 1, (maxusec > 0) ? (maxusec / 1000) : -1);
+ if (maxusec > 0 && ret == 0)
+ return 0;
} while (ret == -1 && errno == EINTR);
if (ret == -1) {
log_perror_err("poll() failed");
[see https://sourceforge.net/p/lirc/tickets/149/]
Reverting this patch result in:
[reference attached: 'debug.repeat.pre' and 'debug.repeat.post' lircd logs]
pre c824c0f46d8d239c3ab55656422584500eaa469c
lircd-0.9.4-devel[20504]: Trace: found: play/arrow_up
lircd-0.9.4-devel[20504]: Trace: 179a740 0 0 0 0 0 0 0 0 1
lircd-0.9.4-devel[20504]: Trace: release_gap: 201453
lircd-0.9.4-devel[20504]: Trace: writing to client 0: 0000000022dda857 00 play/arrow_up Toshiba_VT-852EW
lircd-0.9.4-devel[20504]: Trace2: pending pulse: 0
lircd-0.9.4-devel[20504]: Trace2: pending space: 0
lircd-0.9.4-devel[20504]: Trace: trying "Toshiba_VT-852EW" remote
lircd-0.9.4-devel[20504]: Trace2: pending pulse: 0
lircd-0.9.4-devel[20504]: Trace2: pending space: 0
lircd-0.9.4-devel[20504]: Trace2: <s39710
lircd-0.9.4-devel[20504]: Trace: sync
lircd-0.9.4-devel[20504]: Trace2: expecting pulse: 9105
lircd-0.9.4-devel[20504]: Trace2: +p9071
lircd-0.9.4-devel[20504]: Trace2: pending space: 2173
lircd-0.9.4-devel[20504]: Trace2: expecting pulse: 638
lircd-0.9.4-devel[20504]: Trace2: +s2189
lircd-0.9.4-devel[20504]: Trace2: pending space: 0
lircd-0.9.4-devel[20504]: Trace2: +p607
lircd-0.9.4-devel[20504]: Trace1: sum: 11867
lircd-0.9.4-devel[20504]: Trace2: +s96104
lircd-0.9.4-devel[20504]: Trace2: unget: 1
lircd-0.9.4-devel[20504]: Trace: found: play/arrow_up
lircd-0.9.4-devel[20504]: Trace: 179a740 179a740 179a740 1 1 0 0 1 1 1
lircd-0.9.4-devel[20504]: Trace: release_gap: 201453
lircd-0.9.4-devel[20504]: Trace: writing to client 0: 0000000022dda857 01 play/arrow_up Toshiba_VT-852EW
lircd-0.9.4-devel[20504]: Trace2: pending pulse: 0
lircd-0.9.4-devel[20504]: Trace2: pending space: 0
post c824c0f46d8d239c3ab55656422584500eaa469c
lircd-0.9.4-devel[13779]: Trace: found: play/arrow_up
lircd-0.9.4-devel[13779]: Trace: 1b91740 0 0 0 0 0 0 0 0 1
lircd-0.9.4-devel[13779]: Trace: release_gap: 201453
lircd-0.9.4-devel[13779]: Trace: writing to client 0: 0000000022dda857 00 play/arrow_up Toshiba_VT-852EW
lircd-0.9.4-devel[13779]: Trace2: pending pulse: 0
lircd-0.9.4-devel[13779]: Trace2: pending space: 0
lircd-0.9.4-devel[13779]: Trace: trying "Toshiba_VT-852EW" remote
..
lircd-0.9.4-devel[13779]: Trace2: timeout: 100000
lircd-0.9.4-devel[13779]: Trace: no repeat
..
lircd-0.9.4-devel[13779]: Trace: failed on bit 1
lircd-0.9.4-devel[13779]: Trace: failed on code
lircd-0.9.4-devel[13779]: Trace: decoding failed for all remotes
..thus a working setup (repeats working)! This was the case as I
fast-forwarded back through the repo up until:
commit 224d38962b8fc8509740639fc4394b947f5b8426 (HEAD)
Author: Alec Leamas <leamas.alec@gmail.com>
Date: Mon May 8 15:14:26 2017 +0200
Use lircd waitfordata() instead of copy in lib/receive (#278).
Using a separate waitfordata() in lib/receive causes subtle errors
when transmitting if data is received concurrently. In all
circumstances, having two parallel poll()/select() loops is a
bad idea leading to hard-to-understand logics.
Patch lets clients such as lircd set the function used by
waitfordata() in lib/receive, effectively forcing drivers to
used the lircd waitfordata() function. This centralizes the
event loop to a single function.
lib/receive still uses the old function as default e. g., when
used by irrecord.
This commit again resulted in no repeat keys :(
[reference attached: 'debug.repeat.v2.pre' and 'debug.repeat.v2.post' lircd logs]
Reverting the use of the unified poll loop, thus running with the
likes of:
diff --git a/lib/receive.c b/lib/receive.c
index 2de203a7..61e3cb4b 100644
--- a/lib/receive.c
+++ b/lib/receive.c
@@ -178,15 +178,15 @@ int waitfordata(uint32_t maxusec)
struct pollfd pfd = {
.fd = curr_driver->fd, .events = POLLIN, .revents = 0 };
- if (lircd_waitfordata != NULL)
- return lircd_waitfordata(maxusec);
+// if (lircd_waitfordata != NULL)
+// return lircd_waitfordata(maxusec);
while (1) {
do {
do {
ret = curl_poll(&pfd, 1, (maxusec > 0) ? (maxusec / 1000) : -1);
- if (maxusec > 0 && ret == 0)
- return 0;
+// if (maxusec > 0 && ret == 0)
+// return 0;
} while (ret == -1 && errno == EINTR);
..gave a working setup right the way throught to current HEAD.
Not very useful as far as a real fix goes though, so looking a bit
harder, and noting the logging's additional timeout messages:
diff --git a/lib/receive.h b/lib/receive.h
index 51072376..222952bf 100644
--- a/lib/receive.h
+++ b/lib/receive.h
@@ -32,7 +32,7 @@ extern "C" {
/** Min value returned by receive_timeout. */
-#define MIN_RECEIVE_TIMEOUT 100000
+#define MIN_RECEIVE_TIMEOUT 125000
/**
* Set update mode, where recorded pre_data is verified to match
..also resulted in a fixed HEAD.. as did the attached
'0001-fix-pulse-timeout-remote-gap.patch':
From 1224be3e582d146b56b6457ac4ed9b012a31663b Mon Sep 17 00:00:00 2001
From: Pete Beardmore <pete.beardmore@msn.com>
Date: Sat, 24 Mar 2018 16:03:06 +0000
Subject: [PATCH] fix pulse timeout < remote gap
---
lib/receive.c | 3 ++-
1 file changed, 2 insertions(+), 1 deletion(-)
diff --git a/lib/receive.c b/lib/receive.c
index 2de203a7..7a3b692c 100644
--- a/lib/receive.c
+++ b/lib/receive.c
@@ -364,7 +364,8 @@ static int expectpulse(struct ir_remote* remote, int exdelta)
if (!sync_pending_space(remote))
return 0;
- deltap = get_next_pulse(rec_buffer.pendingp + exdelta);
+ deltap = get_next_pulse(remote->gap > rec_buffer.pendingp + exdelta ?
+ remote->gap : rec_buffer.pendingp + exdelta);
if (deltap == 0)
return 0;
if (rec_buffer.pendingp > 0) {
..which just (ultimately!) ensures a min 'maxusec' of
max(gap, MIN_RECEIVE_TIMEOUT)
So the attached two patches are the minimal to get my homebrew serial
ir back to a happy place.
Perhaps worthy of a mention - in comparison to the previous working
setup (way back ~2014), this setup seems a wee bit over responsive.
However, adding:
suppress_repeat 2
min_repeat 2
to the remote config has dealt with that issue just fine!
Thanks for your work on this project. Happy to test better/correct
patches as and when.
Cheers,
Pete.
[SF refused to attach these initially, hence I posted without, with the idea of just editing the post after the fact. Low and behold it appears one cannot edit their own posts! SF, poor!]
Thanks for your work! It's ENOTIME for me right now, but I'll try to find some time to look into this later this week.