LIRC / Tickets / #315 irsend / lircd hang when using repeats

Alec Leamas - 2018-02-11

SInce this a common function used by many users, I tend to think that this is a problem in the RPi's kernel driver. And, the kernel drivers are not part of lirc....

Have you any chance to test this on some other, non-RPi hardware?

Sorry for long delays. I lost lirc for some time, life requiring other things to be done.

EDIT: To clear things out: Unless proven wrong by a test on non-RPi hardware, this bug really belongs to the kernel (or possibly the distro, if they added their own driver).

Last edit: Alec Leamas 2018-02-11

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Please note that the issues were NOT observed with the downstream
lirc_rpi kernel driver but with the upstream mceusb and pwm-ir-tx
drivers from the rc-core subsystem.

As ir-ctl is working fine with these kernel drivers a bug in lircd
seems like a likely possibility (although I won't rule out some
other cause).

ATM I can't test lirc stuff on a non-RPi platform but I redid the
steps and had a closer look with gdb.

irsend seems to be hanging in read():

(gdb) where
#0  0x76caf16c in read () at ../sysdeps/unix/syscall-template.S:84
#1  0x76f35c90 in fill_string (fd=3, cmd=0x7e8e712c) at lirc_client.c:143
#2  0x76f35e58 in read_string (cmd=0x7e8e712c, fd=3, string=0x7e8e70b4)
    at lirc_client.c:173
#3  0x76f36018 in lirc_command_run (ctx=0x7e8e712c, fd=3) at lirc_client.c:221
#4  0x00010c70 in send_packet (ctx=0x7e8e712c, fd=3) at irsend.cpp:58
#5  0x000115f8 in main (argc=6, argv=0x7e8e76d4) at irsend.cpp:244
(gdb) up
(gdb) p *cmd
$2 = {
  packet = "SEND_ONCE Sony-RM-U305A KEY_POWER\n", '\000' <repeats 222 times>,
  buffer = '\000' <repeats 256 times>, reply = '\000' <repeats 256 times>,
  head = 0, reply_to_stdout = 1, next = 0x0}

lircd hangs in poll():

(gdb) where
#0  0x76c3cd28 in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x76ecec90 in curl_poll (ufds=0x2ff98 <poll_fds>, nfds=515, timeout_ms=-1)
    at curl_poll.c:75
#2  0x00018a78 in mywaitfordata (maxusec=0) at lircd.cpp:1967
#3  0x00019104 in loop () at lircd.cpp:2059
#4  0x0001abd4 in main (argc=10, argv=0x7edcc694) at lircd.cpp:2472
(gdb) up 2
#2  0x00018a78 in mywaitfordata (maxusec=0) at lircd.cpp:1967
1967                                                     -1);
(gdb) p tv
$1 = {tv_sec = 0, tv_usec = 0}
(gdb) p timeout
$2 = {tv_sec = 2128397144, tv_usec = 40}
(gdb) p release_time
$3 = {tv_sec = 0, tv_usec = 0}
(gdb) p reconnect
$4 = 0
(gdb) p start
$5 = {tv_sec = 1518456859, tv_usec = 439261}
(gdb) p maxusec
$6 = 0
(gdb) p *curr_driver
$7 = {device = 0x76ef0f24 <buff> "/dev/lirc0", fd = 8, features = 770,
  send_mode = 2, rec_mode = 0, code_length = 0,
  open_func = 0x76b5f5b4 <my_open>, init_func = 0x76b5f8f4 <default_init>,
  deinit_func = 0x76b60720 <default_deinit>,
  send_func = 0x76b60834 <default_send>, rec_func = 0x76b60afc <default_rec>,
  decode_func = 0x76ed3df0 <receive_decode>,
  drvctl_func = 0x76b60bc8 <drvctl>, readdata = 0x76b5f67c <default_readdata>,
  name = 0x76b60c6c "default", resolution = 0, api_version = 3,
  driver_version = 0x76b60c74 "0.10.0",
  info = 0x76b60c7c "See file:///opt/lirc-0.10.1/share/doc/lirc/plugindocs/default.html", close_func = 0x76ec7424 <default_close>,
  device_hint = 0x76b60cc0 "drvctl"}
(gdb) p now
$8 = {tv_sec = 1518456859, tv_usec = 384171}

A very wild guess would be a race in socket communication, but I
could be wrong as I'm not really familiar with the code.

If you suspect a race as well drop me a line if you want me to do
more testing. I can reliably reproduce the issue here.

Alec Leamas - 2018-02-12

Yes, but we are still talking about the RPi, right. And just as a clarification, the kernel drivers are part of the kernel, not lirc.

So, what's really needed here is doing the same thing on some non-RPi hardware. That should clear out if this this is a kernel or lirc problem. Being the lirc maintainer, of course my fist bet is the kernel...

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

I could now also reproduce this on x86: Debian Stretch, vanilla upstream 64-bit kernel 4.14.17 using the serial_ir driver.

lircd started as in initial report:

/opt/lirc-0.10.1/sbin/lircd --driver=default --device=/dev/lirc0 -n -o /tmp/lirc -P /tmp/lircd.pid sony-repeat.conf

then irsend started in a loop:

while true ; do /opt/lirc-0.10.1/bin/irsend -d /tmp/lirc SEND_ONCE Sony-RM-U305A KEY_POWER ; done

After about a minute or two lircd is stuck again in poll() and irsend in read()

camel2:~# gdb /opt/lirc-0.10.1/sbin/lircd -p 24433
...
(gdb) where
#0  0x00007f9525e99690 in __poll_nocancel ()
    at ../sysdeps/unix/syscall-template.S:84
#1  0x000055a8976362a3 in mywaitfordata (maxusec=0) at lircd.cpp:1967
#2  0x000055a89763699f in loop () at lircd.cpp:2059
#3  0x000055a8976315e1 in main (argc=<optimized out>, argv=<optimized out>)
    at lircd.cpp:2472

camel2:~# gdb /opt/lirc-0.10.1/bin/irsend -p 25012
...
(gdb) where
#0  0x00007ff328167700 in __read_nocancel ()
    at ../sysdeps/unix/syscall-template.S:84
#1  0x00007ff328ecf9cb in read (__nbytes=<optimized out>,
    __buf=<optimized out>, __fd=3)
    at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2  fill_string (cmd=0x7ffc9da1a900, fd=3) at lirc_client.c:143
#3  read_string (string=<synthetic pointer>, fd=3, cmd=0x7ffc9da1a900)
    at lirc_client.c:173
#4  lirc_command_run (ctx=0x7ffc9da1a900, fd=3) at lirc_client.c:221
#5  0x0000555bfb2ff5ea in send_packet (ctx=0x7ffc9da1a900, fd=3)
    at irsend.cpp:58
#6  0x0000555bfb2ff338 in main (argc=6, argv=0x7ffc9da1ad38) at irsend.cpp:244

Alec Leamas - 2018-02-13

OK, so this is about litc, agreed. Just to take the simple parts first: could you please verify the runtime linkage using ldd /opt/...irsend and ldd /opt/...lircd. Just to make sure nothing like /usr/lib/llblirc.so..0 .0.0 is imvolved?

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

ldd output looks fine to me:

camel2:~# ldd /opt/lirc-0.10.1/sbin/lircd
        linux-vdso.so.1 (0x00007ffe9f173000)
        libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007ff617b6a000)
        liblirc.so.0 => /opt/lirc-0.10.1/lib/liblirc.so.0 (0x00007ff617944000)
        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007ff617740000)
        libudev.so.1 => /lib/x86_64-linux-gnu/libudev.so.1 (0x00007ff618164000)
        libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007ff6173be000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007ff6170ba000)
        libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007ff616ea3000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007ff616b04000)
        /lib64/ld-linux-x86-64.so.2 (0x00007ff617f97000)
        librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007ff6168fc000)
camel2:~# ldd /opt/lirc-0.10.1/bin/irsend
        linux-vdso.so.1 (0x00007ffd64d98000)
        liblirc.so.0 => /opt/lirc-0.10.1/lib/liblirc.so.0 (0x00007f77582cb000)
        liblirc_client.so.0 => /opt/lirc-0.10.1/lib/liblirc_client.so.0 (0x00007f77580c1000)
        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f7757ebd000)
        libudev.so.1 => /lib/x86_64-linux-gnu/libudev.so.1 (0x00007f77588c2000)
        libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007f7757b3b000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f7757837000)
        libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007f7757620000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f7757281000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f77586f5000)
        librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007f7757079000)
        libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f7756e5c000)

Matthias Reichl - 2018-02-13

Just noticed that when I run lircd with valgrind the lockup happens quite reproducibly here on my x86 box when running 2 irsend commands right after each other (irsend ... ; irsend ...).

Hope this helps you to reproduce the issue

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

I have also run into this issue "irsend / lircd hang when using repeats". It's not a irsend/lircd hard hang I see. Rather the IR send stalls and never completes.

Raspberry Pi 3 B: Linux raspberrypi 4.9.80-v7+ #1098 SMP Fri Mar 9 19:11:42 GMT 2018 armv7l GNU/Linux
mceusb IR transceiver

Native rc_core drivers
Native mceusb driver
Default lirc_dev, ir_lirc_codec, drivers (default lirc version 0.9.4c)

lirc-0.10.1 compiled from source and not installed, where lircd.conf just includes TUNER.lircd.conf

$ cat /etc/lirc/lircd.conf.d/TUNER.lircd.conf
#
# This config file has been automatically converted from a device file
# found in the 06/26/00 release of the Windows Slink-e software
# package.
#
# Many thanks to Colby Boles of Nirvis Systems Inc. for allowing us to
# use these files.
#
# The original filename was: "tunerir.cde"
#
# The original description for this device was:
#
# Sony Tuner
#

begin remote

  name  TUNER
  bits            7
  flags SPACE_ENC
  eps            20
  aeps          200

  header       2400   600
  one          1200   600
  zero          600   600
  post_data_bits  5
  post_data      0x16
  gap          25000
  min_repeat      2
  toggle_bit      0

  frequency    40000

      begin codes
          BAND                     0x0000000000000078
          PRESET+                  0x0000000000000004
          PRESET-                  0x0000000000000044
      end codes

end remote
pi@raspberrypi:~ $

pi@raspberrypi:~/projects/lirc-0.10.1/daemons $ sudo ./lircd -n -H default -d /dev/lirc0 -D10 -U /home/pi/projects/lirc-0.10.1/plugins/.libs -o /var/run/lirc/lircd -P /var/run/lirc/lircd.pid /etc/lirc/lircd.conf
Warning: cannot open /usr/local/etc/lirc/lirc_options.conf
...

pi@raspberrypi:~ $ irsend SEND_ONCE TUNER BAND
...hang/stall...

The "min_repeat 2" (or more) in the remote configuration is critical for triggering the irsend/lircd hang issue.

I believe I have tracked down the root cause of the issue. lircd uses SIGALRM to time the delay between IR repeats. There are race conditions with the delivery time of sigalrm and where sigalrm interrupts and resumes lircd main code execution, which affect irsend hang/stall. As such, the results of the race(s) are highly dependent on the host platform, as well as other activity, including unrelated actively, on the platform. Problem occurrence would also be random.

The race problems found are:

lircd-0.10.1[18825]: Trace: received command: "SEND_ONCE TUNER BAND"
lircd-0.10.1[18825]: Debug: Sending once, msg: SEND_ONCE TUNER BAND
, args: TUNER BAND, once: 1
lircd-0.10.1[18825]: Trace2: clearing transmit buffer
lircd-0.10.1[18825]: Trace2: adding to transmit buffer: 2400
...
lircd-0.10.1[18825]: Trace2: adding to transmit buffer: 600
lircd-0.10.1[18825]: Trace2: transmit buffer ready
lircd-0.10.1[18825]: Trace: alarm in 10 usecs

lircd.cpp:1554 schedule_repeat_timer(&before_send);

Function send_core() sets the 1st repeat alarm. The sigalrm handler simply sets the global variable alrm = 1. If this alarm signal fires after checking for alarms in mywaitfordata() at

lircd.cpp:1878 if (alrm) {
lircd.cpp:1879         dosigalrm(SIGALRM);
lircd.cpp:1880         alrm = 0;
lircd.cpp:1881 }

but before

lircd.cpp:1965 ret = curl_poll((struct pollfd*)&poll_fds.byindex, POLLFDS_SIZE, -1);

the poll can block indefinitely.

lircd-0.10.1[18825]: Trace2: clearing transmit buffer
lircd-0.10.1[18825]: Trace2: adding to transmit buffer: 2400
...
lircd-0.10.1[18825]: Trace2: adding to transmit buffer: 600
lircd-0.10.1[18825]: Trace2: transmit buffer ready
lircd-0.10.1[18825]: Trace: alarm in 10 usecs

lircd.cpp:1203 schedule_repeat_timer(&before_send);

Function dosigalrm() sets the 2nd and subsequent repeat alarms. If this alarm signal fires before dosigalrm() returns, the alarm gets lost after return at

lircd.cpp:1880 alrm = 0;

and the IR repeat stalls permanently. If the alarm otherwise occurs before

lircd.cpp:1965 ret = curl_poll((struct pollfd*)&poll_fds.byindex, POLLFDS_SIZE, -1);

the poll can block indefinitely.

One of the race issues is easy to replicate by replacing code in function schedule_repeat_timer():

lircd.cpp:1174 setitimer(ITIMER_REAL, &repeat_timer, NULL);

with

lircd.cpp:1174 sigalrm(SIGALRM);

for simulating immediate alarm signal.

One possible fix is to increase the minimum 10 usecs alarm time to an unknown, but larger number. But this alters the timing of IR repeats, and is still not a guarantee to avoid the race conditions seen.

I believe a better solution will be to replace the IR repeat sigalrm timing method with using poll timeout and time of day clock comparison. This is already the method in use in the lircd.cpp code for IR release_time. I will post a patch candidate in a subsequent followup for your consideration.

Last edit: asunxx 2018-04-03

asunxx - 2018-04-03

[PATCH] lirc: #315 irsend / lircd hang when using repeats

irsend SEND_ONCE IR may stall forever for lircd.conf remote control buttons
with min_repeat setting 2 or higher. irsend SEND_START IR may stall forever
for any remote control buttons.

The root causes of IR send stall are due to race timing of SIGALRM in
lircd, used for IR repeat timing, with the time necessary for lircd code
execution to reach its main poll system call.

Patch replaces lircd IR repeat sigalrm timing method with poll timeout and
time of day clock comparison. Poll timeout method is already in use for
lircd IR release_time functionality. And is immune from the SIGALRM
method's timing race.

Correct possible premature timeout for mywaitfordata(maxusecs) where
maxusecs > 0. Premature timeout may occur when release_time
(and this patch's repeat_time) delay remaining is less than maxusecs
delay remaining.

Signed-off-by: A Sun asunxx@users.sourceforge.net

daemons/lircd.cpp | 100 +++++++++++++++++++++++++++++++++++-------------------
1 file changed, 66 insertions(+), 34 deletions(-)

Last edit: asunxx 2018-04-04

0003-lirc-315-irsend-lircd-hang-when-using-repeats.patch

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
- Alex L. - 2018-12-29
  
  I don't exactly know how to apply this patch. Is this just patch < <filepath> and if so, onto which file I need to apply that? Thx in advance.
  
  Last edit: Alex L. 2018-12-29
  
  If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
  - asunxx - 2019-02-06
    
    The 0003-lirc...patch file is a patch formatted with "git format-patch ...", and can be applied with "git apply ..."
    If git code manager is not applicable, then patch lircd.cpp < <filepath> should work. This patch only affects the lircd.cpp file from lirc 0.10.1.
    
    If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Andrew Kim - 2019-04-08

Can someone post step by step instructions on how to apply this patch to Raspbian? I dont understand the PATCH command syntax at all. Thanks in advanced.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Peter F. Patel-Schneider - 2019-11-29

I'm also experiencing this bug. Has it been fixed in the development version?

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Peter F. Patel-Schneider - 2019-11-30

I installed the patch in 0.10.1. Previously I almost always had the timout problem when sending SONY 20-bit codes but with the patch installed it works great.

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Colin Stearman - 2021-11-11

I recently had need to apply this patch to V0.10.1 and found it quite difficult. However, I did succeed and you can find my notes on the process on my website.
The version of LIRC in the Pi respository is still at this version, hence the need. I hope someone finds this useful. I feel that when someone succeeds in fixing a problem it's of little help saying they succeeded without saying how!

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
- Jim Kaiser - 2022-04-27
  
  Colin - Thank you for the detailed instructions on your website. irsend now works for me with the count flag, which my devices require.
  A couple of comments, though.
  1. the wget string for the patch has the filename truncated to .pa, where it should be .patch. wgetting the .pa file pulls a lot of website-related html code, not the patch.
  2. the arguments to configure did not work:
  ../configure ––prefix=/usr ––sysconfdir=/etc
  I had to use alternate flags like this:
  ../configure --p /usr -sysconfdir /etc
  3. Lastly, cd daemons/.lib should be cd daemons/.libs
  
  Again, Thank you for this. I'm running Debian Buster on a Raspberry Pi 3+
  
  Last edit: Jim Kaiser 2022-04-27
  
  If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Lee Ballard - 2023-02-22

Was this patch merged into v0.10.2? If not will there be a pull request created. I suspect this is related to the issue I'm seeing https://sourceforge.net/p/lirc/tickets/375/

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Lee Ballard - 2023-03-02

Created merge request of patch for 0.10.2 https://sourceforge.net/p/lirc/git/merge-requests/50/

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

David Röthlisberger - 2023-03-12

I also was affected by this bug. To summarize: The sigalarm used for scheduling repeat signals was racy with lircd's main poll loop. The symptom was: A 2nd irsend (hot on the heels of the 1st irsend) would hang (gdb showed lircd was in poll), until you sent a 3rd irsend (and then both the 2nd & 3rd irsends would be processed). I could only reproduce it with drivers/plugins that block while each signal is being sent, such as the kernel driver (I was using pwm-ir-tx) — I couldn't reproduce it with ftdix (which returns to the lircd main loop as soon as it writes the signal to the USB device, but before the USB device has finished sending it).

https://sourceforge.net/p/lirc/git/merge-requests/48/ narrowed the window of this race condition, and https://sourceforge.net/p/lirc/git/merge-requests/50/ fixes it (not tested personally, but we had a similar patch we wrote ourselves). Both are now merged to master.

Last edit: David Röthlisberger 2023-03-12

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sean Young - 2023-03-23

status: open --> accepted

Resolution: na --> fixed
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sean Young - 2023-03-23

https://sourceforge.net/p/lirc/git/merge-requests/50/ merged, should be fixed

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Sean Young - 2023-03-23

status: accepted --> closed
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

Jim Kaiser - 2023-10-18

I see that the Milestone for this fix is Future. However, the changed daemons/lircd.cpp file may be found here.

I downloaded and replaced the copy in the 0.10.2 distribution tarball with this one and irsend no longer hangs when using --count=2 (or greater). Thank you for the fix!

If you would like to refer to this comment somewhere else in this project, copy and paste the following link:

irsend / lircd hang when using repeats

Linux Infrared Remote Control

Milestone

Searches

Help

#315 irsend / lircd hang when using repeats

Discussion