Config file is parsed every minute and "WARNING failed to parse /etc/keyd/default.conf"

qadzek commented 1 year ago

I have two laptops with similar hardware and almost the same software. They share exactly the same keyd configuration. I am using both /etc/keyd/default.conf and ~/.config/keyd/app.conf.

On one device keyd works perfectly fine, on the other the Application Specific Remapping often fails. It will work, then 30 seconds later my custom keyd key bindings aren't picked up, then 30 seconds later it will work again.

Running journalctl -b /usr/bin/keyd on the good device displays just a couple of lines, showing the configuration file is parsed at boot time. Running the same command on the bad device shows something completely different: there is a warning WARNING failed to parse /etc/keyd/default.conf and the config file is parsed every minute.

I have tried to remove and reinstall keyd several times. I have tried the latest release (v2.4.3) and the last commit (201a077).

journalctl -b /usr/bin/keyd

Sep 02 09:51:24 apollo keyd[1067]: CONFIG: parsing /etc/keyd/default.conf Sep 02 09:51:24 apollo keyd[1067]: DEVICE: WARNING failed to parse /etc/keyd/default.conf Sep 02 09:51:24 apollo keyd[1067]: Starting keyd v2.4.3 (201a077) Sep 02 09:51:24 apollo keyd[1067]: DEVICE: ignoring 0fac:1ade (keyd virtual pointer) Sep 02 09:51:24 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan TrackPoint) Sep 02 09:51:24 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan Touchpad) Sep 02 09:51:24 apollo keyd[1067]: DEVICE: ignoring 0001:0001 (AT Translated Set 2 keyboard) Sep 02 09:51:48 apollo keyd[1067]: CONFIG: parsing /etc/keyd/default.conf Sep 02 09:51:48 apollo keyd[1067]: DEVICE: WARNING failed to parse /etc/keyd/default.conf Sep 02 09:51:48 apollo keyd[1067]: DEVICE: ignoring 0fac:1ade (keyd virtual pointer) Sep 02 09:51:48 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan TrackPoint) Sep 02 09:51:48 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan Touchpad) Sep 02 09:51:48 apollo keyd[1067]: DEVICE: ignoring 0001:0001 (AT Translated Set 2 keyboard) Sep 02 09:52:01 apollo keyd[1067]: CONFIG: parsing /etc/keyd/default.conf Sep 02 09:52:01 apollo keyd[1067]: DEVICE: WARNING failed to parse /etc/keyd/default.conf Sep 02 09:52:01 apollo keyd[1067]: DEVICE: ignoring 0fac:1ade (keyd virtual pointer) Sep 02 09:52:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan TrackPoint) Sep 02 09:52:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan Touchpad) Sep 02 09:52:01 apollo keyd[1067]: DEVICE: ignoring 0001:0001 (AT Translated Set 2 keyboard) Sep 02 09:53:01 apollo keyd[1067]: CONFIG: parsing /etc/keyd/default.conf Sep 02 09:53:01 apollo keyd[1067]: DEVICE: ignoring 0fac:1ade (keyd virtual pointer) Sep 02 09:53:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan TrackPoint) Sep 02 09:53:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan Touchpad) Sep 02 09:53:01 apollo keyd[1067]: DEVICE: match 0001:0001 /etc/keyd/default.conf (AT Translated Set 2 keyboard) Sep 02 09:54:01 apollo keyd[1067]: CONFIG: parsing /etc/keyd/default.conf Sep 02 09:54:01 apollo keyd[1067]: DEVICE: ignoring 0fac:1ade (keyd virtual pointer) Sep 02 09:54:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan TrackPoint) Sep 02 09:54:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan Touchpad) Sep 02 09:54:01 apollo keyd[1067]: DEVICE: match 0001:0001 /etc/keyd/default.conf (AT Translated Set 2 keyboard) Sep 02 09:55:01 apollo keyd[1067]: CONFIG: parsing /etc/keyd/default.conf Sep 02 09:55:01 apollo keyd[1067]: DEVICE: ignoring 0fac:1ade (keyd virtual pointer) Sep 02 09:55:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan TrackPoint) Sep 02 09:55:01 apollo keyd[1067]: DEVICE: ignoring 04f3:002f (Elan Touchpad) Sep 02 09:55:01 apollo keyd[1067]: DEVICE: match 0001:0001 /etc/keyd/default.conf (AT Translated Set 2 keyboard)

qadzek commented 9 months ago

A helpful user in the IRC channel recommended to include some more information.

Hardware: Lenovo ThinkPad X390. The laptop has a keyboard, TrackPoint, mouse buttons and a touchpad.
OS: Linux Mint 21.2
DE: Cinnamon

To quickly recap my issue:

Regular Keyd is working without problems.
Application Specific Remapping breaks exactly at the start of every minute, e.g. at 21:12:00. After some time, or when I click on an application, it works back again, until the start of the next minute.
Keyd is parsing /etc/keyd/default.conf every single minute, which probably causes the above problem.
To try to find the root cause of the issue, I think we can ignore the Application Specific Remapping for now. That seems to be only the symptom, not the cause. Even when only regular Keyd is running, with a minimal configuration, the config file is parsed every minute.

Things I have tried:

I tried replacing the * in /etc/keyd/default.conf by 0001:0001, by k:0001:0001 and by -04f3:002f, but nothing solved the issue.
I installed the latest firmware by running fwupdmgr update.
keyd-application-mapper is not longer running, so ~/.config/keyd/app.conf can't be the cause of this issue.
This issue is present when I don't log in to my Desktop Environment, but immediately switch to a TTY (Ctrl+Alt+F4).
I run Keyd successfully on another laptop with the same distro and DE, so I don't think these are to blame.

$ keyd --version
keyd v2.4.3 (eeea96a)

The Elan TrackPoint and Elan Touchpad have the same device ID 04f3:002f. Maybe this is the cause?

$ sudo keyd monitor
device added: 04f3:002f Elan TrackPoint (/dev/input/event6)
device added: 04f3:002f Elan Touchpad (/dev/input/event5)
device added: 0001:0001 AT Translated Set 2 keyboard (/dev/input/event3)

$ cat /etc/keyd/default.conf
[ids]

*

$ journalctl -b /usr/bin/keyd
Dec 03 17:45:22 apollo keyd[955]: CONFIG: parsing /etc/keyd/default.conf
Dec 03 17:45:22 apollo keyd[955]: DEVICE: WARNING failed to parse /etc/keyd/default.conf
Dec 03 17:45:22 apollo keyd[955]: Starting keyd v2.4.3 (eeea96a)
Dec 03 17:45:22 apollo keyd[955]: DEVICE: ignoring 0fac:1ade  (keyd virtual pointer)
Dec 03 17:45:22 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan TrackPoint)
Dec 03 17:45:22 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan Touchpad)
Dec 03 17:45:22 apollo keyd[955]: DEVICE: ignoring 0001:0001  (AT Translated Set 2 keyboard)
Dec 03 17:45:38 apollo keyd[955]: CONFIG: parsing /etc/keyd/default.conf
Dec 03 17:45:38 apollo keyd[955]: DEVICE: ignoring 0fac:1ade  (keyd virtual pointer)
Dec 03 17:45:38 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan TrackPoint)
Dec 03 17:45:38 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan Touchpad)
Dec 03 17:45:38 apollo keyd[955]: DEVICE: match    0001:0001  /etc/keyd/default.conf        (AT Translated Set 2 keyboard)
Dec 03 17:46:01 apollo keyd[955]: CONFIG: parsing /etc/keyd/default.conf
Dec 03 17:46:01 apollo keyd[955]: DEVICE: ignoring 0fac:1ade  (keyd virtual pointer)
Dec 03 17:46:01 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan TrackPoint)
Dec 03 17:46:01 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan Touchpad)
Dec 03 17:46:01 apollo keyd[955]: DEVICE: match    0001:0001  /etc/keyd/default.conf        (AT Translated Set 2 keyboard)
Dec 03 17:47:01 apollo keyd[955]: CONFIG: parsing /etc/keyd/default.conf
Dec 03 17:47:01 apollo keyd[955]: DEVICE: ignoring 0fac:1ade  (keyd virtual pointer)
Dec 03 17:47:01 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan TrackPoint)
Dec 03 17:47:01 apollo keyd[955]: DEVICE: ignoring 04f3:002f  (Elan Touchpad)
Dec 03 17:47:01 apollo keyd[955]: DEVICE: match    0001:0001  /etc/keyd/default.conf        (AT Translated Set 2 keyboard)

Pressing j, then accidentally touching the touchpad and finally Ctrl-c.

$ sudo KEYD_DEBUG=2 keyd
DEBUG: src/keyd.c:230: Debug mode activated
CONFIG: parsing /etc/keyd/default.conf
Starting keyd v2.4.3 (eeea96a)
DEBUG: src/device.c:121: capabilities of /dev/input/event16 (keyd virtual keyboard): 4
DEBUG: src/device.c:121: capabilities of /dev/input/event17 (keyd virtual pointer): 3
DEBUG: src/device.c:121: capabilities of /dev/input/event15 (Integrated Camera: Integrated C): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event14 (HDA Intel PCH HDMI/DP,pcm=10): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event13 (HDA Intel PCH HDMI/DP,pcm=9): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event9 (HDA Intel PCH Headphone): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event12 (HDA Intel PCH HDMI/DP,pcm=8): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event7 (ThinkPad Extra Buttons): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event6 (Elan TrackPoint): 1
DEBUG: src/device.c:121: capabilities of /dev/input/event4 (Video Bus): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event5 (Elan Touchpad): 3
DEBUG: src/device.c:121: capabilities of /dev/input/event11 (HDA Intel PCH HDMI/DP,pcm=7): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event8 (HDA Intel PCH Mic): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event10 (HDA Intel PCH HDMI/DP,pcm=3): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event3 (AT Translated Set 2 keyboard): 4
DEBUG: src/device.c:121: capabilities of /dev/input/event2 (Power Button): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event1 (Lid Switch): 0
DEBUG: src/device.c:121: capabilities of /dev/input/event0 (Sleep Button): 0
DEVICE: ignoring 0fac:1ade  (keyd virtual pointer)
DEVICE: ignoring 04f3:002f  (Elan TrackPoint)
DEVICE: ignoring 04f3:002f  (Elan Touchpad)
DEVICE: match    0001:0001  /etc/keyd/default.conf  (AT Translated Set 2 keyboard)
DEBUG: src/device.c:459: unrecognized evdev event type: 4 4 36
DEBUG: src/device.c:454: key j down
DEBUG: src/daemon.c:429: input j down
DEBUG: src/vkbd/uinput.c:324: output j down
DEBUG: src/device.c:454: key j down
DEBUG: src/device.c:459: unrecognized evdev event type: 4 4 36
DEBUG: src/device.c:454: key j up
DEBUG: src/daemon.c:429: input j up
DEBUG: src/vkbd/uinput.c:324: output j up
DEBUG: src/device.c:454: key j up
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 39
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 3a
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 31
DEBUG: src/device.c:454: key kpminus down
DEBUG: src/device.c:454: key numlock down
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 3a
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 30
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 31
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 3a
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 3a
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 3a
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 30
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 31
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 3a
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 35
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 36
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 39
DEBUG: src/device.c:454: key kpminus up
DEBUG: src/device.c:454: key numlock up
DEBUG: src/device.c:406: Unrecognized EV_ABS code: 18
DEBUG: src/device.c:459: unrecognized evdev event type: 4 4 29
DEBUG: src/device.c:454: key leftcontrol down
DEBUG: src/daemon.c:429: input leftcontrol down
DEBUG: src/keyboard.c:260: Activating layer control
DEBUG: src/vkbd/uinput.c:324: output leftcontrol down
DEBUG: src/device.c:454: key leftcontrol down
DEBUG: src/device.c:459: unrecognized evdev event type: 4 4 46
DEBUG: src/device.c:454: key c down
DEBUG: src/daemon.c:429: input c down
DEBUG: src/vkbd/uinput.c:324: output c down
DEBUG: src/device.c:454: key c down

These lines might be a clue: DEBUG: src/device.c:459: unrecognized evdev event type: 4 4 36 DEBUG: src/device.c:406: Unrecognized EV_ABS code: 39

inxi -Fxz
System:
  Kernel: 5.15.0-89-generic x86_64 bits: 64 compiler: gcc v: 11.4.0
    Desktop: Cinnamon 5.8.4 Distro: Linux Mint 21.2 Victoria
    base: Ubuntu 22.04 jammy
Machine:
  Type: Laptop System: LENOVO product: 20Q1S3UG41 v: ThinkPad X390
    serial: <superuser required>
  Mobo: LENOVO model: 20Q1S3UG41 v: SDK0J40697 WIN
    serial: <superuser required> UEFI: LENOVO v: N2JETA1W (1.79 )
    date: 02/02/2023
Battery:
  ID-1: BAT0 charge: 39.4 Wh (100.0%) condition: 39.4/48.1 Wh (81.9%)
    volts: 12.7 min: 11.4 model: Celxpert 5B10W13925 status: Full
CPU:
  Info: quad core model: Intel Core i5-8365U bits: 64 type: MT MCP
    arch: Comet/Whiskey Lake note: check rev: C cache: L1: 256 KiB L2: 1024 KiB
    L3: 6 MiB
  Speed (MHz): avg: 784 high: 800 min/max: 400/4100 cores: 1: 800 2: 800
    3: 800 4: 755 5: 719 6: 800 7: 800 8: 800 bogomips: 30399
  Flags: avx avx2 ht lm nx pae sse sse2 sse3 sse4_1 sse4_2 ssse3 vmx
Graphics:
  Device-1: Intel WhiskeyLake-U GT2 [UHD Graphics 620] vendor: Lenovo
    driver: i915 v: kernel bus-ID: 00:02.0
  Device-2: IMC Networks Integrated Camera type: USB driver: uvcvideo
    bus-ID: 1-8:2
  Display: x11 server: X.Org v: 1.21.1.4 driver: X: loaded: modesetting
    unloaded: fbdev,vesa gpu: i915 resolution: 1920x1080~60Hz
  OpenGL: renderer: Mesa Intel UHD Graphics 620 (WHL GT2)
    v: 4.6 Mesa 23.0.4-0ubuntu1~22.04.1 direct render: Yes
Audio:
  Device-1: Intel Cannon Point-LP High Definition Audio vendor: Lenovo
    driver: snd_hda_intel v: kernel bus-ID: 00:1f.3
  Sound Server-1: ALSA v: k5.15.0-89-generic running: yes
  Sound Server-2: PulseAudio v: 15.99.1 running: yes
  Sound Server-3: PipeWire v: 0.3.48 running: yes
Network:
  Device-1: Intel Cannon Point-LP CNVi [Wireless-AC] driver: iwlwifi
    v: kernel bus-ID: 00:14.3
  IF: wlp0s20f3 state: up mac: <filter>
  Device-2: Intel Ethernet I219-LM vendor: Lenovo driver: e1000e v: kernel
    port: N/A bus-ID: 00:1f.6
  IF: enp0s31f6 state: down mac: <filter>
Bluetooth:
  Device-1: Intel Bluetooth 9460/9560 Jefferson Peak (JfP) type: USB
    driver: btusb v: 0.8 bus-ID: 1-10:4
  Report: hciconfig ID: hci0 rfk-id: 2 state: up address: <filter>
    bt-v: 3.0 lmp-v: 5.1
Drives:
  Local Storage: total: 238.47 GiB used: 248.43 GiB (104.2%)
  ID-1: /dev/nvme0n1 vendor: Western Digital
    model: PC SN730 SDBQNTY-256G-1001 size: 238.47 GiB temp: 24.9 C
Partition:
  ID-1: / size: 233.18 GiB used: 124.2 GiB (53.3%) fs: ext4
    dev: /dev/nvme0n1p2
  ID-2: /boot/efi size: 511 MiB used: 30.1 MiB (5.9%) fs: vfat
    dev: /dev/nvme0n1p1
Swap:
  ID-1: swap-1 type: file size: 2 GiB used: 0 KiB (0.0%) file: /swapfile
Sensors:
  System Temperatures: cpu: 29.0 C mobo: N/A
  Fan Speeds (RPM): N/A
Info:
  Processes: 277 Uptime: 1h 26m Memory: 15.4 GiB used: 1.43 GiB (9.3%)
  Init: systemd runlevel: 5 Compilers: gcc: 11.4.0 Packages: 2745 Shell: Zsh
  v: 5.8.1 inxi: 3.3.13

$ journalctl -fu local-fs.target
Nov 30 22:44:43 apollo systemd[1]: Stopped target Local File Systems.
-- Boot e7d84c4d8a774afa8b02eba162b49e15 --
Nov 30 22:45:14 apollo systemd[1]: Reached target Local File Systems.
Nov 30 22:48:27 apollo systemd[1]: Stopped target Local File Systems.
-- Boot 81603319d11c4bb3b138725f48fef54f --
Nov 30 22:48:59 apollo systemd[1]: Reached target Local File Systems.
Nov 30 22:53:07 apollo systemd[1]: Stopped target Local File Systems.
-- Boot b4e7957bc5e140b2a6906856811b5121 --
Nov 30 22:53:38 apollo systemd[1]: Reached target Local File Systems.
Nov 30 22:56:57 apollo systemd[1]: Stopped target Local File Systems.
-- Boot 7438166794034a85b2e824283385abd9 --
Nov 30 22:57:27 apollo systemd[1]: Reached target Local File Systems.
Nov 30 23:00:30 apollo systemd[1]: Stopped target Local File Systems.
-- Boot 6db14ee2352648b3b0bb606490f4de2c --
Dec 03 15:56:09 apollo systemd[1]: Reached target Local File Systems.

$ systemctl cat keyd.service
# /lib/systemd/system/keyd.service
[Unit]
Description=key remapping daemon
Requires=local-fs.target
After=local-fs.target

[Service]
Type=simple
ExecStart=/usr/bin/keyd

[Install]
WantedBy=sysinit.target

$python3 --version
Python 3.10.12

rvaiya commented 9 months ago

Odd, it doesn't seem the service is restarting and the only other thing that can trigger a reload is the IPC mechanism. Do you have keyd reload present in any of your custom scripts?

rvaiya commented 9 months ago

I just noticed your logs suggest you are running an older commit (eeea96a) than what you originally posted. Can you pull and build from the latest version and make sure the issue is still reproducible?

qadzek commented 9 months ago

Thanks for your reply.

Odd, it doesn't seem the service is restarting and the only other thing that can trigger a reload is the IPC mechanism. Do you have keyd reload present in any of your custom scripts?

This was something I was wondering as well. I did grep my entire home directory and couldn't find anything. However, your suggestion made me think. Turns out I had two cron jobs in my root's crontab...

@reboot keyd reload
* * * * * keyd reload

Apologies, I completely forgot about this.

I remember I included this because keyd wouldn't start automatically after a reboot. Removing these cron jobs of course fixed the issue of parsing the config file every minute. It seems like keyd still fails to start after a reboot (it is enabled, and I am now using the latest version 07a993d), but it looks like running sudo keyd reload manually once fixes this, so this is no big deal.

Thanks again for this wonderful application.

rvaiya / keyd

Config file is parsed every minute and "WARNING failed to parse /etc/keyd/default.conf" #571