Lockfile bleibt nach reboot stehen (bookworm)

[hm247]

Hallo,

ich verwende debmatic unter bookworm auf einem Debian System (arm64 - Linux 6.1.58).

Nach einem Neustart macht ein Lockfile Probleme, das von debmatic erzeugt wurde und stehen geblieben ist (das Lockfile hindert debmatic dann daran normal zu starten):

Code: Alles auswählen

# ls -la /var/lock/LCK..mmd_hmip 
-rw-r--r-- 1 root root 11 Oct 20 07:03 /var/lock/LCK..mmd_hmip

Das Lockfile bleibt auch stehen, wenn ich debmatic stoppe (systemctl stop debmatic). Was könnte die Ursache für das Problem sein ?

Als einfachen Workaround lösche ich das Lockfile mit einem Eintrag in der debmatic.service Datei:

Code: Alles auswählen

ExecStopPost=-/usr/bin/rm /var/lock/LCK..mmd_hmip

Ansonsten funktioniert debmatic unter bookworm bisher ganz gut.

Viele Grüße

P.S.: Ich habe debmatic mehrmals nach Rezept neu installiert und neu konfiguriert, aber das ändert nichts.

Code: Alles auswählen

# systemd-analyze blame | grep debmatic 
24.212s debmatic-hmserver.service
 7.152s debmatic.service
 5.329s debmatic-rega.service
 4.298s debmatic-rfd.service
 4.120s debmatic-multimacd.service
  157ms debmatic-eq3configd.service
  140ms debmatic-hssled.service
  138ms debmatic-updaterffirmware.service
  129ms debmatic-startupfinished.service
  112ms debmatic-lighttpd.service
  109ms debmatic-prepareinterfaceslist.service
  103ms debmatic-ssdpd.service
   73ms debmatic-updatelgwkey.service
   59ms debmatic-updatelgwfirmware.service
   
# systemd-analyze blame | grep pivccu
  590ms pivccu-dkms.service
  
# cat /var/log/syslog | grep debmatic
2023-10-21T18:02:47.200823+02:00 server systemd[1]: debmatic-setinterfaceclock.timer: Deactivated successfully.
2023-10-21T18:02:47.201036+02:00 server systemd[1]: Stopped debmatic-setinterfaceclock.timer - debmatic set interface clock timer.
2023-10-21T18:02:47.210147+02:00 server systemd[1]: Stopping debmatic-monitor-hb-rf-eth.service - debmatic Monitor HB-RF-ETH...
2023-10-21T18:03:49.444145+02:00 server systemd[1]: Starting debmatic.service - debmatic...
2023-10-21T18:03:56.516430+02:00 server systemd[1]: Finished debmatic.service - debmatic.
2023-10-21T18:03:56.547298+02:00 server systemd[1]: Starting debmatic-eq3configd.service - debmatic eq3configd...
2023-10-21T18:03:56.558789+02:00 server systemd[1]: Starting debmatic-hssled.service - debmatic HssLED...
2023-10-21T18:03:56.570453+02:00 server systemd[1]: Starting debmatic-prepareinterfaceslist.service - debmatic prepare InterfacesList.xml...
2023-10-21T18:03:56.580030+02:00 server systemd[1]: Starting debmatic-ssdpd.service - debmatic ssdpd...
2023-10-21T18:03:56.593957+02:00 server systemd[1]: Starting debmatic-updaterffirmware.service - debmatic update rf firmware...
2023-10-21T18:03:56.679327+02:00 server systemd[1]: Finished debmatic-prepareinterfaceslist.service - debmatic prepare InterfacesList.xml.
2023-10-21T18:03:56.689337+02:00 server systemd[1]: Started debmatic-ssdpd.service - debmatic ssdpd.
2023-10-21T18:03:56.699111+02:00 server systemd[1]: Started debmatic-hssled.service - debmatic HssLED.
2023-10-21T18:03:56.703992+02:00 server systemd[1]: Started debmatic-eq3configd.service - debmatic eq3configd.
2023-10-21T18:03:56.719730+02:00 server systemd[1]: Starting debmatic-lighttpd.service - debmatic lighttpd...
2023-10-21T18:03:56.723629+02:00 server systemd[1]: Starting debmatic-updatelgwfirmware.service - debmatic update lgw firmware...
2023-10-21T18:03:56.732247+02:00 server systemd[1]: Finished debmatic-updaterffirmware.service - debmatic update rf firmware.
2023-10-21T18:03:56.739795+02:00 server systemd[1]: Starting debmatic-multimacd.service - debmatic multimacd...
2023-10-21T18:03:56.785237+02:00 server systemd[1]: Finished debmatic-updatelgwfirmware.service - debmatic update lgw firmware.
2023-10-21T18:03:56.788768+02:00 server systemd[1]: Starting debmatic-updatelgwkey.service - debmatic update lgw key...
2023-10-21T18:03:56.839410+02:00 server systemd[1]: Started debmatic-lighttpd.service - debmatic lighttpd.
2023-10-21T18:03:56.839715+02:00 server systemd[1]: debmatic-hs485d.service - debmatic hs485d was skipped because of an unmet condition check (ConditionPathExists=!/var/status/debmatic_avoid_hs485d).
2023-10-21T18:03:56.862130+02:00 server systemd[1]: Finished debmatic-updatelgwkey.service - debmatic update lgw key.
2023-10-21T18:04:00.861246+02:00 server systemd[1]: Started debmatic-multimacd.service - debmatic multimacd.
2023-10-21T18:04:00.892179+02:00 server systemd[1]: Starting debmatic-rfd.service - debmatic rfd...
2023-10-21T18:04:05.190716+02:00 server systemd[1]: Started debmatic-rfd.service - debmatic rfd.
2023-10-21T18:04:05.282657+02:00 server systemd[1]: Starting debmatic-hmserver.service - debmatic hmserver...
2023-10-21T18:04:29.496781+02:00 server systemd[1]: Started debmatic-hmserver.service - debmatic hmserver.
2023-10-21T18:04:29.596308+02:00 server systemd[1]: Starting debmatic-rega.service - debmatic rega...
2023-10-21T18:04:34.926818+02:00 server systemd[1]: Started debmatic-rega.service - debmatic rega.
2023-10-21T18:04:35.006677+02:00 server systemd[1]: Starting debmatic-startupfinished.service - debmatic startup finished...
2023-10-21T18:04:35.135764+02:00 server systemd[1]: Finished debmatic-startupfinished.service - debmatic startup finished.
2023-10-21T18:04:35.141303+02:00 server systemd[1]: Started debmatic-setinterfaceclock.timer - debmatic set interface clock timer.
2023-10-21T18:04:35.169175+02:00 server systemd[1]: Started debmatic-monitor-hb-rf-eth.service - debmatic Monitor HB-RF-ETH.

root@server:~# cat /var/log/syslog | grep pivccu
2023-10-21T18:03:49.137375+02:00 server systemd[1]: Starting pivccu-dkms.service - piVCCU DKMS Modules...
2023-10-21T18:03:49.438095+02:00 server systemd[1]: pivccu-dkms.service: Deactivated successfully.
2023-10-21T18:03:49.438772+02:00 server systemd[1]: Finished pivccu-dkms.service - piVCCU DKMS Modules.

root@server:~# cat /var/log/syslog | grep hb-rf
2023-10-21T18:02:47.210147+02:00 server systemd[1]: Stopping debmatic-monitor-hb-rf-eth.service - debmatic Monitor HB-RF-ETH...
2023-10-21T18:03:49.901051+02:00 server kernel: [   20.292145] hb-rf-eth hb-rf-eth: failed creating connect sysfs file: 0
2023-10-21T18:03:49.941055+02:00 server kernel: [   20.332201] hb-rf-eth hb-rf-eth: Trying to connect to 192.168.xx.xx
2023-10-21T18:03:50.051411+02:00 server kernel: [   20.444057] hb-rf-eth hb-rf-eth: Successfully connected to 192.168.xx.xx
2023-10-21T18:04:35.169175+02:00 server systemd[1]: Started debmatic-monitor-hb-rf-eth.service - debmatic Monitor HB-RF-ETH.

[hm247]

Hallo,

ich habe inzwischen versucht das Verhalten mit einer anderen SD Karte und frisch installiertem debian 12.2 nachzustellen. Das Problem tritt nach dem ersten Start nicht auf.

Bei nachfolgenden Starts von debmatic gibt es dann folgende Meldungen vom System (debian 12.2, Linux 6.1.58):

Code: Alles auswählen

# cat /var/log/syslog | grep mine
2023-10-22T13:03:28.200863+02:00 server start_hmserver.sh[2275]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..mmd_hmip: File exists. It is NOT mine
2023-10-22T13:03:28.201930+02:00 server start_hmserver.sh[2275]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..mmd_hmip: File exists. It is NOT mine
2023-10-22T13:03:28.202541+02:00 server start_hmserver.sh[2275]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..mmd_hmip: File exists. It is NOT mine
2023-10-22T13:03:28.202996+02:00 server start_hmserver.sh[2275]: RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..mmd_hmip: File exists. It is NOT mine

# systemd-analyze blame | grep debmatic
4min 925ms debmatic-hmserver.service
   10.942s debmatic.service
    5.262s debmatic-rega.service
    4.109s debmatic-multimacd.service
    2.258s debmatic-rfd.service
     384ms debmatic-eq3configd.service
     371ms debmatic-hssled.service
     122ms debmatic-updaterffirmware.service
     121ms debmatic-ssdpd.service
      87ms debmatic-lighttpd.service
      78ms debmatic-prepareinterfaceslist.service
      72ms debmatic-updatelgwfirmware.service
      70ms debmatic-startupfinished.service
      45ms debmatic-updatelgwkey.service

'File exists. It is NOT mine': der hmserver scheint das existierende Lockfile nicht zu mögen: der hmserver benötigt 4min um in diesem Fall zu starten, statt 24s.

Aber mit dem zuvor beschriebenen Workaround funktioniert alles wie erwartet.

Viele Grüße

[hm247]

Hallo,

also nachdem ich alles nochmals neu aufgesetzt habe, einschließlich aktualisiertem Kernel (6.1.58) mit passenden Header files, bleibt zwar das Lockfile nach einem regulären Shutdown oder Stop von debmatic immer noch stehen, aber der hmserver räumt es jetzt selbst beim Start erfolgreich aus dem Weg:

Code: Alles auswählen

2023-10-23T17:01:58.602054+02:00 server start_hmserver.sh[5139]: RXTX Warning: Removing stale lock file. /var/lock/LCK..mmd_hmip

Das hat bisher bei mir nicht funktioniert. Da muss unter der Haube irgend etwas schiefgelaufen sein bei der Nachinstallation des verwendeten Kernels und der Header (dabei gab es einen Konflikt - es mussten für die linux-header zwei neue Abhängikeiten installiert werden).

Debmatic läuft auch bei mir jetzt zuverlässig unter bookworm in der aktuellen Version 12.2, die erst vor 14 Tagen erschienen ist.

Viele Grüße

P.S. Ich verwende Armbian auf einem rk3399, Kernel und passende Header wurden selbst mit dem Armbian build System gebaut.

[hm247]

Hallo,

für die "early adopter": debmatic läuft unter bookworm 12.2 auch mit linux Kernel 6.6.0, welcher gestern veröffentlicht wurde.
Vielen Dank an Alex!

Viele Grüße

Code: Alles auswählen

# debmatic-info
debmatic version: 3.71.12-109
OS:               Armbian 23.08.0-trunk bookworm
Kernel:           6.6.0-edge-rockchip64 aarch64
Service Status:   Running
Kernel modules:   Available
Raw UART dev:     Available
HMRF Hardware:    RPI-RF-MOD
 Connected via:   HB-RF-ETH@192.168.xx.xx (/dev/raw-uart)
 Board serial:    1234567890
 Radio MAC:       0xffffff
HMIP Hardware:    RPI-RF-MOD
 Connected via:   HB-RF-ETH@192.168.xx.xx (/dev/raw-uart)
 SGTIN:           xxx
 Radio MAC:    yyy