#274 Problems when Irexec systemd service is started before lircd

[Luca De Feo]

First reported to Arch at https://bugs.archlinux.org/task/53357, with suggested resolution:

• edit lircd.service:

[Service]
Type=forking
PIDFile=/var/run/lirc/lircd.pid
ExecStart=/usr/sbin/lircd

• edit irexec.service:

[Unit]
Requires=lircd.service
After=lircd.service

[Alec Leamas]

This is actually not a bug. LIRC provides lircd.socket which is the recommended way to start lircd. Using lircd.socket, the socket becomes available at an very early stage, and lircd is started when e. g., irexec.service accesses the socket. In systemd parlance, this is "socket activation", and it resolves the ordering issue described here.

EDIT: Note that the fix described above includes "editing" upstream files like lircd.service. This is basically never the right thing to do siince the file will be overwrtten when lirc is updated, Instead, use the standard systemd mechanism: add files to /etc/systemd/sysem whch overrides the upstream files. OTOH, no new files are needed to resolve this issue, just enable lircd.socket instead of lircd.service

[Luca De Feo]

I just tried your solution in Arch (i.e. disable lircd.service, enable lircd.socket and irexec.service, use upstream systemd files). Irexec is started properly and running, however it fails to pick IR events. irw shows events fine, instead. The only way to make irexec pick up the events is to manually restart the service. No error messages are printed to the journal.

If, on the other hand, I override lircd.service and lircd.irexec as in the resolution above (I'm putting overrides in /etc/systemd/system/lircd.service.d/ and /etc/systemd/system/irexec.service.d/, not editing the upstream files, but whatever), irexec works properly from the start.

Any idead what might be causing this? Suggestions to help debug the problem?

Using lircd 0.9.4d.

[Alec Leamas]

Disabled irexec.service? why? If it's disabled, how come it works?
EDIT: sorry, misread your post.

Anyway, I don't see this as a bug but rather as a downstream configuration issue. The socket ectivation is pretty well tested, and a actual bugt report against that needs to be more specific.

[Luca De Feo]

a actual bugt report against that needs to be more specific.

Sure. Just asking if you have an idea of how to debug it. Since no messages appear in the journal, I'm at a loss.

[Alec Leamas]

raise the loglevel...

[Luca De Feo]

Both irexec and lircd run with -Ddebug, no messages are shown.

Just to be clear, here's a step by step reproduction of the problem:

• Raise lircd loglevel: systemctl edit lircd, then type

[Service]
ExecStart=
ExecStart=/usr/sbin/lircd --nodaemon -Ddebug

• Raise irexec loglevel: systemctl edit irexec, then type

[Service]
ExecStart=
ExecStart=/usr/bin/irexec -Ddebug /etc/lirc/irexec.lircrc

• Reload systemd configuration: systemctl daemon-reload
• Stop all services and sockets: systemctl stop irexec lircd.socket lircd
• Start lircd socket and irexec: systemctl start lircd.socket irexec
• Type keys on remote, as configured in irexec.lircrc
• Nothing appears in irexec logs (systemctl status irexec); I'm attaching the output of journalctl -e in lircd1.log
• Restart irexec: systemctl restart irexec
• Type keys on remote
• Keys now appear in irexec logs (systemctl status irexec); I'm attaching the output of journalctl -e in lircd2.log.

[Alec Leamas]

Please read the irexec(1) manpage for log file location.

[Luca De Feo]

~/.cache/irexec.log? I have no such file if I use the systemd service.

So I switched to starting irexec by hand (still using systemd's lircd.socket). With systemd overrides as before:

• Stop all services: systemctl stop lircd.socket lircd
• Start lircd.socket: systemctl start lircd.socket
• Start irexec: irexec -Ddebug /etc/lirc/irexec.lircrc
• Type keys on remote, irexec shows no output, Ctrl-C
• ~/.cache/irexec.log contains this lone line:

Mar 19 18:15:34.483727 palantir irexec: Debug: irexec:  Opening log, level: Debug

• Restart irexec: irexec -Ddebug /etc/lirc/irexec.lircrc
• Type keys on remote, irexec shows output this time, Ctrl-C
• ~/.cache/irexec.log contains now:

Mar 19 18:20:13.447745 palantir irexec: Debug: irexec:  Opening log, level: Debug
Mar 19 18:20:16.792917 palantir irexec: Debug: Execing command "echo "KEY_ENTER""
Mar 19 18:20:17.105100 palantir irexec: Debug: Execing command "echo "KEY_ENTER""
Mar 19 18:20:17.374314 palantir irexec: Debug: Execing command "echo "KEY_ENTER""

[Alec Leamas]

I have perhaps been able to reproduce this. It happens if lircd is built without systemd support in which case it will not pick up the socket provided by systemd. Of course, this means that lircd needs to be restarted after the /run/lirc/lircd socket is created.

Furthermore, systemd has changed the name of the pkg-config file tested by lirc on build. This means that after updating systemd, lircd by default will be built without systemd support.

I attached a patch to the master branch. Could you possibly apply this to the arch build, and verify that it builds with systemd support? One way is to check in the build logs for the output of the ./configure command which should contain

ENABLE_UINPUT:      yes         INSTALL_ETC:        yes         
DEVEL:              yes         DARWIN:             no          
LINUX_KERNEL:       yes         HAVE_DEVINPUT:      yes         
HAVE_SYSTEMD:       yes

notably the HAVE_SYSTEMD part. Another way is to check the generated config.h file.

If all is well, could you then verify that everything works without any patching of lthe service files?

[Luca De Feo]

This is the outuput of configure using the default PKGBUILD given by Arch (version 0.9.4d):

Summary of selected options:
----------------------------------------
prefix:                         /usr
sysconfdir:                     /etc
x_progs:                        irxevent xmode2
host:                           x86_64-unknown-linux-gnu
host_os:                        linux-gnu
forkpty:                        -lutil
usb_libs                        -lusb -lusb-1.0
lockdir:                        /var/lock

Conditionals:

BUILD_ALSA_SB_RC:yes
BUILD_DSP:yes
BUILD_FTDI:yes
BUILD_HIDDEV:yes
BUILD_I2CUSER:yes
BUILD_LIBALSA:yes
BUILD_LIBPORTAUDIO:yes
BUILD_USB:yes
BUILD_XTOOLS:yes
HAVE_DOXYGEN:no
HAVE_LIBUDEV:yes
HAVE_MAN2HTML:no
HAVE_PYMOD_YAML:no
INSTALL_ETC:yes
NEED_PYTHON3:no
SYSTEMD_INSTALL:yes
DEVEL:no
HAVE_UINPUT:yes
DARWIN:no
LINUX_KERNEL:yes

Changing the source to the master branch, I have

Summary of selected options:
----------------------------------------
prefix:                         /usr
lockdir:                        /var/lock
sysconfdir:                     /etc
x_progs:                        irxevent xmode2
host:                           x86_64-unknown-linux-gnu
host_os:                        linux-gnu
forkpty:                        -lutil
LIBUSB_LIBS:                    -lusb -lusb-1.0
PORTAUDIO_LIBS:                 -lportaudio -lasound -lm -lpthread

Conditionals:

BUILD_ALSA_SB_RC:   yes         BUILD_DSP:          yes         
BUILD_FTDI:         yes         BUILD_HIDDEV:       yes         
BUILD_I2CUSER:      yes         BUILD_LIBALSA:      yes         
BUILD_LIBPORTAUDIO: yes         BUILD_USB:          yes         
BUILD_XTOOLS:       yes         HAVE_DOXYGEN:       no          
HAVE_MAN2HTML:      no          HAVE_PYMOD_YAML:    no          
ENABLE_UINPUT:      yes         INSTALL_ETC:        yes         
DEVEL:              yes         DARWIN:             no          
LINUX_KERNEL:       yes         HAVE_DEVINPUT:      yes         

The problem persists, exactly as described in my last message.

Finally, I applied your patch, rebuilt, and got:

Summary of selected options:
----------------------------------------
prefix:                         /usr
lockdir:                        /var/lock
sysconfdir:                     /etc
x_progs:                        irxevent xmode2
host:                           x86_64-unknown-linux-gnu
host_os:                        linux-gnu
forkpty:                        -lutil
LIBUSB_LIBS:                    -lusb -lusb-1.0
PORTAUDIO_LIBS:                 -lportaudio -lasound -lm -lpthread

Conditionals:

BUILD_ALSA_SB_RC:   yes         BUILD_DSP:          yes         
BUILD_FTDI:         yes         BUILD_HIDDEV:       yes         
BUILD_I2CUSER:      yes         BUILD_LIBALSA:      yes         
BUILD_LIBPORTAUDIO: yes         BUILD_USB:          yes         
BUILD_XTOOLS:       yes         HAVE_DOXYGEN:       no          
HAVE_MAN2HTML:      no          HAVE_PYMOD_YAML:    no          
ENABLE_UINPUT:      yes         INSTALL_ETC:        yes         
DEVEL:              yes         DARWIN:             no          
LINUX_KERNEL:       yes         HAVE_DEVINPUT:      yes         
HAVE_SYSTEMD:       yes         

but the problem won't go away :/

[Alec Leamas]

Some double-checks:

• You have rebuilt and installed the result using that patch...
• You have raised the loglevel to 'debug' in lirc_options.conf
• You have stopped lircd.service
• You have restarted lircd.socket
• After this, you start irw and makes some remote keypresses.

Now, the patch adds some debug statements. What happens if you grep for systemd fd in the logs? logs which I presume are available using something like journalctl -b0 /usr/sbin/lircd.

[Luca De Feo]

My bad, I had botched my tests. The issue is present in master, but goes away with the patch.

[Alec Leamas]

I suspected something like that ;) To summarize, this in not that starting irexec before lircd is doesn't work, it's about that the systemd support is not present in lircd due to upstream systemd changes.

Thanks for reporting! This is a nasty bug giving subtle errors. In a better world there would be a unittest for this.

Fixed in [1b4a17], closing

[Luca De Feo]

Thanks to you for looking into this!