search

jens-maus / RaspberryMatic

:house: A feature-rich but lightweight, buildroot-based Linux operating system alternative for your CloudFree CCU3/ELV-Charly 'homematicIP CCU' IoT smarthome central. Running as a pure virtual appliance (ProxmoxVE, Home Assistant, LXC, Docker/OCI, Kubernetes/K8s, etc.) on a dedicated embedded device (RaspberryPi, etc.) or generic x86/ARM hardware.
https://raspberrymatic.de
Apache License 2.0
1.56k stars 192 forks source link

Home Assistant Add-on rfd & HMIPServer ERROR #1707

Closed jaqPi closed 2 years ago

jaqPi commented 2 years ago

Describe the issue you are experiencing

Hello!

I am running Home Assistant using Home Assistant OS on a RasPi3 and a HMIP-RFUSB. Today, I upgraded from HA OS 7.2 to 7.3. In addition, I upgraded the RaspberryMatic Add-on from 202110-something to latest 3.61.7.20220115. As expected during the first start up of the upgraded add-on, the stick's firmware was upgraded to version 4.4.16. A short test reveals that my connected HM-IP devices worked properly.

Back to the front page of the add-on, Home Assistant tells me, that I can enable protection mode. So I did and restarted the add-on. Unfortunately, now, the add-on seems to stop working properly. The log shows the following lines:

Starting rfd: ....................ERROR
Starting HMIPServer: .......................................................................................................................................................ERROR

Neither a restart of the add-on itself nor a reboot of the Raspberry Pi / HA OS fixed the problem.

Describe the behavior you expected

I expected that the new version of the plugin works properly with enabled protection mode or at least a way to disable protection mode again – the corresponding button was removed in the latest version version of the add-on.

Steps to reproduce the issue

  1. Use HA OS 7.3 + supervisor-2022.01.1 + core-2022.2.3
  2. Upgrade from RaspberryMatic 202110-something to latest 3.61.7.20220115
  3. Enable protection mode (was disabled as required by previous versions of RaspberryMatic).
  4. RestartRaspberryMatic Add-on ...

What is the version this bug report is based on?

3.61.7.20220115

Which base platform are you running?

ha-addon (HomeAssistant Add-on)

Which HomeMatic/homematicIP radio module are you using?

HmIP-RFUSB

Anything in the logs that might be useful for us?

Log from the add-on:

Mounting /data as /usr/local (Home Assistant Add-On): OK
Starting watchdog...
Identifying onboard hardware: oci, OK
Initializing RTC Clock: no hardware found
Running sysctl: OK
Checking for Factory Reset: not required
Checking for Backup Restore: not required
Initializing System: OK
Starting logging: OK
Init onboard LEDs: init, OK
Starting irqbalance: OK
Starting iptables: OK
Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.2, OK
Identifying Homematic RF-Hardware: ....HmRF: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.5, HmIP: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.5, OK
Updating Homematic RF-Hardware: HMIP-RFUSB: 4.4.16, OK
Starting hs485dLoader: disabled
Starting xinetd: OK
Starting eq3configd: OK
Starting lighttpd: OK
Starting ser2net: disabled
Starting ssdpd: OK
Starting ha-proxy: OK
Starting NUT services: disabled
Initializing Third-Party Addons: OK
Starting LGWFirmwareUpdate: ...OK
Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: .OK
Starting rfd: ....................ERROR
Starting HMIPServer: .......................................................................................................................................................ERROR
Starting ReGaHss: .OK
Starting CloudMatic: OK
Starting NeoServer: disabled
Starting Third-Party Addons: OK
Starting crond: OK
Setup onboard LEDs: booted, OK

In the past, the HmIP-RFUSB was recognized as ttyUSB0, whereas now, the only USB device recognized by HA OS is not related to the HmIP, isn't it?

Subsystem: usb
Device path:
/dev/bus/usb/001/001

BUSNUM: '001'
DEVNAME: /dev/bus/usb/001/001
DEVNUM: '001'
DEVPATH: /devices/platform/soc/3f980000.usb/usb1
DEVTYPE: usb_device
DRIVER: usb
ID_BUS: usb
ID_FOR_SEAT: usb-platform-3f980000_usb
ID_MODEL: DWC_OTG_Controller
ID_MODEL_ENC: DWC\x20OTG\x20Controller
ID_MODEL_ID: '0002'
ID_PATH: platform-3f980000.usb
ID_PATH_TAG: platform-3f980000_usb
ID_REVISION: '0510'
ID_SERIAL: Linux_5.10.92-v7_dwc_otg_hcd_DWC_OTG_Controller_3f980000.usb
ID_SERIAL_SHORT: 3f980000.usb
ID_USB_INTERFACES: ':090000:'
ID_VENDOR: Linux_5.10.92-v7_dwc_otg_hcd
ID_VENDOR_ENC: Linux\x205.10.92-v7\x20dwc_otg_hcd
ID_VENDOR_ID: 1d6b
MAJOR: '189'
MINOR: '0'
OF_COMPATIBLE_0: brcm,bcm2708-usb
OF_COMPATIBLE_N: '1'
OF_FULLNAME: /soc/usb@7e980000
OF_NAME: usb
PRODUCT: 1d6b/2/510
SUBSYSTEM: usb
TAGS: ':seat:'
TYPE: 9/0/1
USEC_INITIALIZED: '6692927'

Additional information

The HmIP-RFUSB is the only external USB device connected to the RPi.

jens-maus commented 2 years ago

Please try to see if using the latest snapshot version rather than the last stable version of the add-on solves your issues.

jaqPi commented 2 years ago

Hi Jens,

thank you for your answer!

I tested both 3.61.7.20220207-56fc555 and 3.61.7.20220208-0d5cb45 and both show the same interesting (at least from my point of view) behavior:

If I

the add-on boots without any errors:

Mounting /data as /usr/local (Home Assistant Add-On): OK
Starting watchdog...
Identifying onboard hardware: oci, OK
Initializing RTC Clock: no hardware found
Running sysctl: OK
Checking for Factory Reset: not required
Checking for Backup Restore: not required
Initializing System: OK
Starting logging: OK
Init onboard LEDs: init, OK
Starting irqbalance: OK
Starting iptables: OK
Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.2, OK
Identifying Homematic RF-Hardware: ....HmRF: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.5, HmIP: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.5, OK
Updating Homematic RF-Hardware: HMIP-RFUSB: 4.4.16, not necessary, OK
Starting hs485dLoader: disabled
Starting xinetd: OK
Starting eq3configd: OK
Starting lighttpd: OK
Starting ser2net: disabled
Starting ssdpd: OK
Starting ha-proxy: OK
Starting NUT services: disabled
Initializing Third-Party Addons: OK
Starting LGWFirmwareUpdate: ...OK
Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: .OK
Starting rfd: ..OK
Starting HMIPServer: .............OK
Starting ReGaHss: .OK
Starting CloudMatic: OK
Starting NeoServer: disabled
Starting Third-Party Addons: OK
Starting crond: OK
Setup onboard LEDs: booted, OK
Finished Boot: 3.61.7.20220207 (raspmatic_oci_arm)

However, if I restart the running add-on, the errors occur again, but with slightly more precise error messages:

Mounting /data as /usr/local (Home Assistant Add-On): OK
Starting watchdog...
Identifying onboard hardware: oci, OK
Initializing RTC Clock: no hardware found
Running sysctl: OK
Checking for Factory Reset: not required
Checking for Backup Restore: not required
Initializing System: OK
Starting logging: OK
Init onboard LEDs: init, OK
Starting irqbalance: OK
Starting iptables: OK
Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.2, OK
Identifying Homematic RF-Hardware: ....HmRF: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.5, HmIP: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.5, OK
Updating Homematic RF-Hardware: HMIP-RFUSB: 4.4.16, not necessary, OK
Starting hs485dLoader: disabled
Starting xinetd: OK
Starting eq3configd: OK
Starting lighttpd: OK
Starting ser2net: disabled
Starting ssdpd: OK
Starting ha-proxy: OK
Starting NUT services: disabled
Initializing Third-Party Addons: OK
Starting LGWFirmwareUpdate: ...OK
Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: ..........ERROR
Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
Starting HMIPServer: ERROR: /dev/mmd_hmip missing
Starting ReGaHss: .OK
Starting CloudMatic: OK
Starting NeoServer: disabled
Starting Third-Party Addons: OK
Starting crond: OK
Setup onboard LEDs: booted, OK
Finished Boot: 3.61.7.20220207 (raspmatic_oci_arm)

Given the first case, I am not able to test whether the add-on or the OCCU is working properly or not. I am able to

screenshot

As you can see, besides the default devices, my other devices are not listed. I think this is due to the fact I am running the dev instead of the stable add-on. Can I import the OCCU backup for testing purposes I created before upgrading from 202110-x to latest stable or would that break something?

Baxxy13 commented 2 years ago

Ich kann die Problematik hier reproduzieren.

Starting multimacd: ..........ERROR
Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
Starting HMIPServer: ERROR: /dev/mmd_hmip missing

Pi3B+ / HmIP-RFUSB / core-2022.2.3 / supervisor-2022.01.1 / Home Assistant OS 7.3 / RM-AddOn Nightly 3.61.7.20220208

Bin mal auf Nightly 3.61.7.20220120 zurück. Der hat keinerlei Probleme und lässt sich auch mehrfach hintereinander ohne Auffälligkeiten neu starten.

jens-maus commented 2 years ago

Bin mal auf Nightly 3.61.7.20220120 zurück. Der hat keinerlei Probleme und lässt sich auch mehrfach hintereinander ohne Auffälligkeiten neu starten.

Das dürfte nur Zufall sein. Bei meinen Tests hat die multimacd initialisierung auch immer verlässlich mit dem neuesten/aktuellsten nightly snapshot funktioniert. Bitte nochmal mehrmals probieren und vielleicht auch mal einen kompletten HaOS neustart dazwischen durchführen?!?

Baxxy13 commented 2 years ago

Ok, ich teste weiter. Der erste Start des heutigen Nightlys 3.61.7.20220209 (raspmatic_oci_arm64) sah noch gut aus. Nach dem Reboot über die WebUI dann wieder...

Starting hs485d: disabled
Starting multimacd: ..........ERROR
Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
Starting HMIPServer: ERROR: /dev/mmd_hmip missing
Starting ReGaHss: .OK

Ich starte nun mal den Pi3B+ neu...

jens-maus commented 2 years ago

Ok, ich teste weiter. Der erste Start des heutigen Nightlys 3.61.7.20220209 (raspmatic_oci_arm64) sah noch gut aus. Nach dem Reboot über die WebUI dann wieder...

Das ist sicher ein gewisses timing problem beim starten/nutzen von multimacd bzw. dem laden des eq3_char_loop kernel modules. Das hatte ich bereits vor einigen Tagen versucht mit folgender Zeile durch hinzufügen eines sleep 2 zu verbessern. Siehe:

https://github.com/jens-maus/RaspberryMatic/commit/07810f2dcb4b89757aa80e45f0426060caa92d98#diff-1ecddcf3cd4892abdc3ad0ad70ad9c471da9f6dce3746ec8852fff5560a23036R25

Du könntest nun natürlich einfach mal das sleep 2 gegen ein sleep 10 tauschen um zu schauen ob das bei aufeinander folgenden neustarts das verhalten verbessert. Dann könntest du dich langsam an kleinere Zahlen herantasten oder ich bau ne warteroutine ein die wartet bis /dev/eq3loop wirklich nutzbar zur Verfügung steht nach dem modprobe des eq3_char_loop kernel modules.

Baxxy13 commented 2 years ago

Geht das überhaupt? Bei meinen Tests hatten Änderungen am Dateisystem außerhalb /usr keine Persistenz. Also beim reboot wird alles zurückgesetzt. Wegen der Containerisierung vermutlich. Siehe Homematic-Forum: Fragen bezüglich Persistenz von Modifizierungen an RaspberryMatic

jens-maus commented 2 years ago

Geht das überhaupt? Bei meinen Tests hatten Änderungen am Dateisystem außerhalb /usr keine Persistenz. Also beim reboot wird alles zurückgesetzt. Wegen der Containerisierung vermutlich. Siehe Homematic-Forum: Fragen bezüglich Persistenz von Modifizierungen an RaspberryMatic

Mist, da hast du natürlich recht, ja. Dann müsste ich das vmtl. für den nächsten nightly build einfach mal so einbauen und dann kannst du schauen ob es mit einem "sleep 10" besser passt.

jens-maus commented 2 years ago

Oder noch ne Idee: Bau dir ein /usr/local/etc/rc.init skript der beim hochfahren das rootfs rw remountet und dann den multimacd init skript umpatcht BEVOR er gestartet wird. das müsste gehen.

Baxxy13 commented 2 years ago

Ich hab's mir etwas einfacher gemacht und ersetze einfach beim Booten die komplette /etc/init.d/S60multimacd durch eine modifizierte Version. ;-)

So wie es aussieht reichen 3s delay. Zumindest hier auf meinem Pi3B+ der aber mit SSD läuft. Daher würde ich trotzdem erstmal 5s vorschlagen. Das AddOn bootet ja auch mit delay noch schnell genug.

jens-maus commented 2 years ago

Super danke. Das wäre nen Ansatz. Kannst du aber nochmal testen gehen und direkt nach dem modprobe dort ein ls -la /dev/eq3loop jeweils VOR dem sleep und nach dem sleep einbauen und schauen was er ausgibt? Vielleicht könnte ich da ja was einbauen, das wir da auf irgendeinen definierten Status warten bis das entsprechende device angelegt/zugreifbar ist?!?

jens-maus commented 2 years ago

Oder am besten gleich das folgende mal einbauen:

ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop

das sollte mir dann hoffentlich alle notwendigen infos geben (also jeweils VOR und NACH dem modprobe)

Baxxy13 commented 2 years ago

Muss erstmal los, setze ich dann später um.

Baxxy13 commented 2 years ago

Soo, die Zeilen sehen jetzt so aus:

  # make sure /dev/eq3loop exists
  if [[ ! -c /dev/eq3loop ]]; then
    # load eq3_char_loop kernel module
    ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop
    modprobe eq3_char_loop
    ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop
    sleep 2 # wait to settle
  fi

Bin auch auf die 2s zurück und konnte gleich beim ersten Versuch den Fehler einfangen.

Starting hs485d: disabled
Starting multimacd: ls: /dev/eq3loop: No such file or directory
ls: /sys/class/eq3loop: No such file or directory
ls: /sys/module/eq3_char_loop: No such file or directory
crw-------    1 root     root      239,   0 Feb  9 14:29 /dev/eq3loop

/sys/class/eq3loop:
total 0
drwxr-xr-x    2 root     root             0 Feb  9 14:29 .
drwxr-xr-x   60 root     root             0 Feb  9 14:29 ..
lrwxrwxrwx    1 root     root             0 Feb  9 14:29 eq3loop -> ../../devices/virtual/eq3loop/eq3loop

/sys/module/eq3_char_loop:
total 0
drwxr-xr-x    5 root     root             0 Feb  9 14:29 .
drwxr-xr-x  129 root     root             0 Feb  9 14:29 ..
-r--r--r--    1 root     root          4096 Feb  9 14:29 coresize
drwxr-xr-x    2 root     root             0 Feb  9 14:29 holders
-r--r--r--    1 root     root          4096 Feb  9 14:29 initsize
-r--r--r--    1 root     root          4096 Feb  9 14:29 initstate
drwxr-xr-x    2 root     root             0 Feb  9 14:29 notes
-r--r--r--    1 root     root          4096 Feb  9 14:29 refcnt
drwxr-xr-x    2 root     root             0 Feb  9 14:29 sections
-r--r--r--    1 root     root          4096 Feb  9 14:29 srcversion
-r--r--r--    1 root     root          4096 Feb  9 14:29 taint
--w-------    1 root     root          4096 Feb  9 14:29 uevent
-r--r--r--    1 root     root          4096 Feb  9 14:29 version
..........ERROR
Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
Starting HMIPServer: ERROR: /dev/mmd_hmip missing
Starting ReGaHss: .OK
jens-maus commented 2 years ago

Soo, die Zeilen sehen jetzt so aus:

  # make sure /dev/eq3loop exists
  if [[ ! -c /dev/eq3loop ]]; then
    # load eq3_char_loop kernel module
    ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop
    modprobe eq3_char_loop
    ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop
    sleep 2 # wait to settle
  fi

Nee, falsch. So muss es aussehen:

  # make sure /dev/eq3loop exists
  if [[ ! -c /dev/eq3loop ]]; then
    # load eq3_char_loop kernel module
    modprobe eq3_char_loop
    ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop
    sleep 2
    ls -la /dev/eq3loop /sys/class/eq3loop /sys/module/eq3_char_loop
  fi

Hatte ja gesagt VOR und NACH dem sleep :)

Baxxy13 commented 2 years ago

Ok, war uneindeutig... ;-)

(also jeweils VOR und NACH dem modprobe)

Tests laufen...

Baxxy13 commented 2 years ago

Der hat sich gesträubt, aber nach dem 5. Reboot hab ich ihn erwischt. (/etc/init.d/S60multimacd nach deinen Vorgaben modifiziert)

Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: crw-------    1 root     root      239,   0 Feb  9 15:02 /dev/eq3loop

/sys/class/eq3loop:
total 0
drwxr-xr-x    2 root     root             0 Feb  9 15:02 .
drwxr-xr-x   60 root     root             0 Feb  9 15:02 ..
lrwxrwxrwx    1 root     root             0 Feb  9 15:02 eq3loop -> ../../devices/virtual/eq3loop/eq3loop

/sys/module/eq3_char_loop:
total 0
drwxr-xr-x    5 root     root             0 Feb  9 15:02 .
drwxr-xr-x  129 root     root             0 Feb  9 15:02 ..
-r--r--r--    1 root     root          4096 Feb  9 15:02 coresize
drwxr-xr-x    2 root     root             0 Feb  9 15:02 holders
-r--r--r--    1 root     root          4096 Feb  9 15:02 initsize
-r--r--r--    1 root     root          4096 Feb  9 15:02 initstate
drwxr-xr-x    2 root     root             0 Feb  9 15:02 notes
-r--r--r--    1 root     root          4096 Feb  9 15:02 refcnt
drwxr-xr-x    2 root     root             0 Feb  9 15:02 sections
-r--r--r--    1 root     root          4096 Feb  9 15:02 srcversion
-r--r--r--    1 root     root          4096 Feb  9 15:02 taint
--w-------    1 root     root          4096 Feb  9 15:02 uevent
-r--r--r--    1 root     root          4096 Feb  9 15:02 version
crw-------    1 root     root      239,   0 Feb  9 15:02 /dev/eq3loop

/sys/class/eq3loop:
total 0
drwxr-xr-x    2 root     root             0 Feb  9 15:02 .
drwxr-xr-x   60 root     root             0 Feb  9 15:02 ..
lrwxrwxrwx    1 root     root             0 Feb  9 15:02 eq3loop -> ../../devices/virtual/eq3loop/eq3loop

/sys/module/eq3_char_loop:
total 0
drwxr-xr-x    5 root     root             0 Feb  9 15:02 .
drwxr-xr-x  129 root     root             0 Feb  9 15:02 ..
-r--r--r--    1 root     root          4096 Feb  9 15:02 coresize
drwxr-xr-x    2 root     root             0 Feb  9 15:02 holders
-r--r--r--    1 root     root          4096 Feb  9 15:02 initsize
-r--r--r--    1 root     root          4096 Feb  9 15:02 initstate
drwxr-xr-x    2 root     root             0 Feb  9 15:02 notes
-r--r--r--    1 root     root          4096 Feb  9 15:02 refcnt
drwxr-xr-x    2 root     root             0 Feb  9 15:02 sections
-r--r--r--    1 root     root          4096 Feb  9 15:02 srcversion
-r--r--r--    1 root     root          4096 Feb  9 15:02 taint
--w-------    1 root     root          4096 Feb  9 15:02 uevent
-r--r--r--    1 root     root          4096 Feb  9 15:02 version
..........ERROR
Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
Starting HMIPServer: ERROR: /dev/mmd_hmip missing
Starting ReGaHss: .OK
jens-maus commented 2 years ago

Ok, danke dir. Die Ausgaben helfen aber leider nicht weiter bzgl. erkennen ob /dev/eq3loop zugreifbar ist oder nicht. Eben weil es vor und nach dem sleep ja genau gleich alles aussieht. Bleibt also momentan nur das sleep 5 an der stelle zu nutzen und zu hoffen das das alle möglichen fälle abdeckt. Denn ein bisschen unsauber ist das trotzdem, das man da ein sleep reinmachen muss. Problem wird sein, das der HA host jetzt ja dynamisch die rechte für den zugriff auf /dev/eq3loop vergibt (via cgroups) und das scheint nicht instantan zu funktionieren. Und wenn der container nun eben recht schnell bootet kommt der HA host beim anlegen des /dev/eq3loop nicht dazu dem container die notwendigen rechte zu gewähren und dann kann am schluss multimacd nicht auf /dev/eq3loop zugreifen. Hoffen wir also mal das sleep 5 wirklich für alle Nutzungsszenarien ausreichend ist.

Baxxy13 commented 2 years ago

Ja, schauen wir mal. Ein erfolgreicher Boot erzeugt auch die exakt gleichen Einträge.

Komisch ist halt das das nicht sauber reproduzierbar ist. Manchmal geht's 5x hintereinander gut, dann wieder 2x nicht.

jens-maus commented 2 years ago

Komisch ist halt das das nicht sauber reproduzierbar ist. Manchmal geht's 5x hintereinander gut, dann wieder 2x nicht.

Soweit ich weiss kann man im HA supervisor logfile die device zuordnungen zu einem container sehen. Das ist ja ein recht neues Feature. Vllt. kann man hier noch irgendetwas verbessern. Müsste da mal mit den HA Entwicklern drüber reden. Aber du kannst z.B. das HA Logfile mit den zeitstempeln da einfach mal parallel zu den ausgaben legen und dann schauen ob da irgendetwas auffällig ist. Ne alternativ wäre noch, das ich einbaue das der multimacd versucht wird mehrmals hintereinander zu starten wenn er beim ersten mal eben wegen zugriffsproblemen auf /dev/eq3loop nicht starten kann.

jens-maus commented 2 years ago

@Baxxy13

Ne alternativ wäre noch, das ich einbaue das der multimacd versucht wird mehrmals hintereinander zu starten wenn er beim ersten mal eben wegen zugriffsproblemen auf /dev/eq3loop nicht starten kann.

Vielleicht kannst du das ja wirklich mal für mich testen und folgende Änderung mal umsetzen bei dir in der Testumgebung:

--- a/buildroot-external/overlay/RFD/etc/init.d/S60multimacd
+++ b/buildroot-external/overlay/RFD/etc/init.d/S60multimacd
@@ -22,7 +22,6 @@ init() {
   if [[ ! -c /dev/eq3loop ]]; then
     # load eq3_char_loop kernel module
     modprobe eq3_char_loop
-    sleep 5 # wait for /dev/eq3loop to settle
   fi
 }

@@ -33,8 +32,11 @@ waitStartupComplete() {
     echo -n "."
     MMDSTATUSPID=$(cat /var/status/multimacd.status 2>&1)
     MMDPID=$(pidof multimacd)
-    if [[ "${MMDSTATUSPID}" == "${MMDPID}" ]] &&
-       [[ -c /dev/mmd_hmip ]] && [[ -c /dev/mmd_bidcos ]]; then
+    if [[ -z "${MMDPID}" ]]; then
+      # try to start multimacd again
+      start-stop-daemon -S -N -15 -q -b -m -p ${PIDFILE} --exec /bin/multimacd -- -f /var/etc/multimacd.conf -l ${LOGLEVEL_RFD}
+    elif [[ "${MMDSTATUSPID}" == "${MMDPID}" ]] &&
+         [[ -c /dev/mmd_hmip ]] && [[ -c /dev/mmd_bidcos ]]; then
       echo "OK"
       break
     fi

Das sollte den multimacd mehrmal versuchen neu zu starten wenn er nicht gestartet werden konnte. Probier das mal aus. vielleicht läuft das unterm strich stabiler. Dann kannst du das sleep auch einfach wieder entfernen für den Test, dann solltest du schnell sehen können ob es ein Problem gibt.

Baxxy13 commented 2 years ago

Im Host-Log von HA sieht ein korrekter Start so aus:

[ 5128.515553] eq3loop: created slave mmd_hmip
[ 5128.517084] eq3loop: created slave mmd_bidcos
[ 5130.695524] eq3loop: eq3loop_open_slave() mmd_bidcos
[ 5152.096732] eq3loop: eq3loop_open_slave() mmd_hmip
[ 5152.097057] eq3loop: eq3loop_close_slave() mmd_hmip
[ 5152.102167] eq3loop: eq3loop_open_slave() mmd_hmip
[ 5152.102510] eq3loop: eq3loop_close_slave() mmd_hmip
[ 5152.104603] eq3loop: eq3loop_open_slave() mmd_hmip
[ 5152.105047] eq3loop: eq3loop_close_slave() mmd_hmip
[ 5152.115876] eq3loop: eq3loop_open_slave() mmd_hmip

Beim Reboot...

[ 5739.277068] eq3loop: eq3loop_close_slave() mmd_bidcos
[ 5739.305312] eq3loop: eq3loop_close_master() mmd_bidcos
[ 5739.305336] eq3loop: eq3loop_close_master() mmd_bidcos destroy device
[ 5739.306234] eq3loop: eq3loop_close_master() mmd_hmip
[ 5739.665673] eq3loop: eq3loop_close_slave() mmd_hmip
[ 5739.665691] eq3loop: eq3loop_close_slave() mmd_hmip destroy device

Bei einem Fail gibt es gar keine Einträge.

Ich mache mal die Anpassungen rein...

jens-maus commented 2 years ago

Im Host-Log von HA sieht ein korrekter Start so aus:

Ne, ich meinte das Supervisor Log in der HA Weboberfläche. Da sieht man was der supervisor so dynamisch macht wenn das eq3loop auftaucht. dann weist er das dem RM Add-on Container zu.

Baxxy13 commented 2 years ago

Alles da. Funktionierender Start + Reboot:

22-02-09 16:16:43 WARNING (SyncWorker_3) [supervisor.docker.addon] RaspberryMatic CCU (snapshot) running with disabled protected mode!
22-02-09 16:16:45 INFO (SyncWorker_3) [supervisor.docker.addon] Starting Docker add-on ghcr.io/jens-maus/raspberrymatic with version 3.61.7.20220209-cafe9a3
22-02-09 16:16:54 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.ADD hardware /dev/eq3loop - None
22-02-09 16:16:54 INFO (MainThread) [supervisor.docker.addon] Added cgroup permissions for device /dev/eq3loop to addon_de838cd8_raspberrymatic-dev
22-02-09 16:16:56 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.ADD hardware /dev/mmd_hmip - None
22-02-09 16:16:56 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.ADD hardware /dev/mmd_bidcos - None
22-02-09 16:16:56 INFO (MainThread) [supervisor.docker.addon] Added cgroup permissions for device /dev/mmd_bidcos to addon_de838cd8_raspberrymatic-dev
22-02-09 16:16:56 INFO (MainThread) [supervisor.docker.addon] Added cgroup permissions for device /dev/mmd_hmip to addon_de838cd8_raspberrymatic-dev
22-02-09 16:24:42 INFO (MainThread) [supervisor.homeassistant.api] Updated Home Assistant API token
22-02-09 16:26:56 INFO (SyncWorker_1) [supervisor.docker.interface] Stopping addon_de838cd8_raspberrymatic-dev application
22-02-09 16:27:04 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.REMOVE hardware /dev/mmd_bidcos - None
22-02-09 16:27:05 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.REMOVE hardware /dev/mmd_hmip - None
22-02-09 16:27:06 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.REMOVE hardware /dev/eq3loop - None
22-02-09 16:27:12 INFO (SyncWorker_1) [supervisor.docker.interface] Cleaning addon_de838cd8_raspberrymatic-dev application

Fail Start + Shutdown:

22-02-09 16:27:12 WARNING (SyncWorker_6) [supervisor.docker.addon] RaspberryMatic CCU (snapshot) running with disabled protected mode!
22-02-09 16:27:14 INFO (SyncWorker_6) [supervisor.docker.addon] Starting Docker add-on ghcr.io/jens-maus/raspberrymatic with version 3.61.7.20220209-cafe9a3
22-02-09 16:27:23 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.ADD hardware /dev/eq3loop - None
22-02-09 16:27:23 INFO (MainThread) [supervisor.docker.addon] Added cgroup permissions for device /dev/eq3loop to addon_de838cd8_raspberrymatic-dev
22-02-09 16:39:25 INFO (SyncWorker_4) [supervisor.docker.interface] Stopping addon_de838cd8_raspberrymatic-dev application
22-02-09 16:39:36 INFO (MainThread) [supervisor.hardware.monitor] Detecting HardwareAction.REMOVE hardware /dev/eq3loop - None
22-02-09 16:39:41 INFO (SyncWorker_4) [supervisor.docker.interface] Cleaning addon_de838cd8_raspberrymatic-dev application
Baxxy13 commented 2 years ago

Die gepatchte /etc/init.d/S60multimacd geht gar nicht, also führt bei jedem Boot zum Fail. Da ich per copy&paste gepatcht habe kannst du ja nochmal gucken...

waitStartupComplete() {
  STEPS=10
  for i in $(seq 1 ${STEPS}); do
    sleep 2
    echo -n "."
    MMDSTATUSPID=$(cat /var/status/multimacd.status 2>&1)
    MMDPID=$(pidof multimacd)
    if [[ -z "${MMDPID}" ]]; then
      # try to start multimacd again
      start-stop-daemon -S -N -15 -q -b -m -p ${PIDFILE} --exec /bin/multimacd -- -f /var/etc/multimacd.conf -l ${LOGLEVEL_RFD}
    elif [[ "${MMDSTATUSPID}" == "${MMDPID}" ]] &&
         [[ -c /dev/mmd_hmip ]] && [[ -c /dev/mmd_bidcos ]]; then      
      echo "OK"
      break
    fi
    if [[ ${i} -eq ${STEPS} ]]; then
      echo "ERROR"
    fi
  done
}

... denke aber das passt.

Müssen wohl erstmal bei den Gedenksekunden für HA bleiben.

jens-maus commented 2 years ago

Ok, hab es noch einmal selbst getestet. Damit sollte es nun funktionieren:

--- a/buildroot-external/overlay/RFD/etc/init.d/S60multimacd
+++ b/buildroot-external/overlay/RFD/etc/init.d/S60multimacd
@@ -22,7 +22,6 @@ init() {
   if [[ ! -c /dev/eq3loop ]]; then
     # load eq3_char_loop kernel module
     modprobe eq3_char_loop
-    sleep 5 # wait for /dev/eq3loop to settle
   fi
 }

@@ -33,10 +32,17 @@ waitStartupComplete() {
     echo -n "."
     MMDSTATUSPID=$(cat /var/status/multimacd.status 2>&1)
     MMDPID=$(pidof multimacd)
-    if [[ "${MMDSTATUSPID}" == "${MMDPID}" ]] &&
-       [[ -c /dev/mmd_hmip ]] && [[ -c /dev/mmd_bidcos ]]; then
-      echo "OK"
-      break
+    if [[ "${MMDSTATUSPID}" == "${MMDPID}" ]]; then
+      if [[ ! -c /dev/mmd_hmip ]] || [[ ! -c /dev/mmd_bidcos ]]; then
+        echo -n "."
+        # restart multimacd
+        start-stop-daemon -K -q -p ${PIDFILE}
+        sleep 2
+        start-stop-daemon -S -N -15 -q -b -m -p ${PIDFILE} --exec /bin/multimacd -- -f /var/etc/multimacd.conf -l ${LOGLEVEL_RFD}
+      else
+        echo "OK"
+        break
+      fi
     fi
     if [[ ${i} -eq ${STEPS} ]]; then
       echo "ERROR"

Schau mal ob das nun so stabil auch bei dir funktioniert?!?

jaqPi commented 2 years ago

Guten Abend,

inhaltlich kann ich leider wenig beitragen. Aber gerne teste ich auf meinem System alles, was sich installieren lässt. Der letzte Commit müsste ab morgen über den dev snapshot installierbar sein?

Baxxy13 commented 2 years ago

ob das nun so stabil auch bei dir funktioniert?!?

Hab jetzt mit den letzten Änderungen etwa 10x hintereinander problemlos booten können, inklusive HA-Neustart und HA-Host Neustart. Sieht also gut aus.

Der letzte Commit müsste ab morgen über den dev snapshot installierbar sein?

Genau. Ab morgen dann für alle testbar.

Baxxy13 commented 2 years ago

Also bei läuft das heute reibungslos! 4x WebUI Reboot 4x Neustart über die HA-AddOn Einstellungen 1x HA-Neustart 1x HA-Host Neustart 1x HA-OS Upgrade auf 7.4

jens-maus commented 2 years ago

Dann können wir ja hier nun "dicht" machen. Danke an alle!

jaqPi commented 2 years ago

Kann die Ergebnisse von Baxxy13 bei mir bestätigen!

raidboy commented 2 years ago

Leider tritt wohl das originale problem auch mit dem heutigen snapshot auf. Details hier:

https://homematic-forum.de/forum/viewtopic.php?f=65&t=72639&p=706047#p706047

Interessanterweise nur wenn ich HMIP-RFUSB verwende, nicht aber wenn ich HMIP-RFUSB-TK verwende.

Baxxy13 commented 2 years ago

Jetzt bin ich nochmal den Thread im Homematic-Forum durchgegangen und habe festgestellt das mir ein wichtiges Detail durch die Lappen gegangen ist. Du nutzt nicht das HomeAssistant-OS 7.x sondern eine HomeAssistant Supervised Installation.

Das passt dann doch nicht hierher und erfordert möglicherweise ein neues Issue. Zwecks Tests bin ich dann aber auch raus, der Aufwand ist mir zu groß.

tpannes commented 2 years ago

Hallo zusammen. Bei mir gab es nach dem Switch vom HA "HomeMatic CCU" add-on zu RaspberryMatic ein Problem mit der Initialisierung der Hardware (Original HMIP-RFUSB, keine Telekom Version). Ich nutze HA-OS auf nem Pi3+. Nachdem ich diesen Thread gelesen hatte, hab ich einfach mal den nighly build probiert (3.61.7.20220212-be487fa) und siehe da, es läuft wieder. :-)

Hier die Log Meldungen vorher.. Identifying Homematic RF-Hardware: ...HmRF: none, HmIP: none, OK Updating Homematic RF-Hardware: HMIP-RFUSB: =>4.4.16, ERROR ( != 4.4.16) Identifying Homematic RF-Hardware: ...HmRF: none, HmIP: none, OK und nachher: Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.4, OK Identifying Homematic RF-Hardware: ....HmRF: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.3, HmIP: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-3f980000.usb-1.3, OK Updating Homematic RF-Hardware: HMIP-RFUSB: 4.4.16, not necessary, OK

Ich weiß nicht genau, ob dieses Problem dieselbe Ursache (Timing Problem) hatte, aber ich dachte es kann nicht schaden, es hier zu erwähnen.

Danke für eure tolle Arbeit!

dominikandreas commented 2 years ago

Ich habe leider auch das gleiche Problem wie anfangs beschrieben:

 Mounting /data as /usr/local (Home Assistant Add-On): OK
Identifying host system: oci, OK
Initializing RTC Clock: onboard, OK
Running sysctl: OK
Checking for Factory Reset: not required
Checking for Backup Restore: not required
Initializing System: OK
Starting logging: OK
Init onboard LEDs: init, OK
Starting irqbalance: OK
Starting iptables: OK
Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.7, OK
Identifying Homematic RF-Hardware: ....HmRF: RPI-RF-MOD/HB-RF-USB@usb-0000:00:14.0-1, HmIP: RPI-RF-MOD/HB-RF-USB@usb-0000:00:14.0-1, OK
Updating Homematic RF-Hardware: RPI-RF-MOD: 4.4.12, not necessary, OK
Starting hs485dLoader: disabled
Starting xinetd: OK
Starting eq3configd: OK
Starting lighttpd: OK
Starting ser2net: disabled
Starting ssdpd: OK
Starting ha-proxy: OK
Starting NUT services: disabled
Initializing Third-Party Addons: OK
Starting LGWFirmwareUpdate: ...OK
Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: .OK
Starting rfd: ....................ERROR
Starting HMIPServer: .....................................................................................................ERROR
Starting ReGaHss: .OK
Starting CloudMatic: OK
Starting NeoServer: disabled
Starting Third-Party Addons: OK
Starting crond: OK
Setup onboard LEDs: booted, OK
Finished Boot: 3.61.7.20220212 (raspmatic_oci_amd64)

Mein system besteht aus einem Intel NUC 11, Ubuntu 20.04, HB-RF-USB und Home Assistant Supervised mit supervisor-2022.01.1 und core-2022.2.9. Als Addon nutze ich den Snapshot 3.61.7.20220212-be487fa (mehrere Versionen seit Release ohne Erfolg getestet)

Wollte von debmatic zum HomeAssistant Addon wechseln. Debmatic natürlich vorher mit systemctl stop debmatic gestopped. Alternativ hätte ich auch noch einen HMIP-RFUSB zur Verfügung (allerdings bisher nicht im Einsatz gewesen). Ich kenne mich mit docker und linux ganz gut aus, also wenn ich irgendwie dazu beitragen kann den Fehler zu finden und zu beseitigen, stehe ich gerne zur Verfügung

o-l-i-v-e-r commented 2 years ago

Ich habe leider auch das gleiche Problem wie anfangs beschrieben:

Mounting /data as /usr/local (Home Assistant Add-On): OK
Identifying host system: oci, OK
Initializing RTC Clock: onboard, OK
Running sysctl: OK
Checking for Factory Reset: not required
Checking for Backup Restore: not required
Initializing System: OK
Starting logging: OK
Init onboard LEDs: init, OK
Starting irqbalance: OK
Starting iptables: OK
Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.7, OK
Identifying Homematic RF-Hardware: ....HmRF: RPI-RF-MOD/HB-RF-USB@usb-0000:00:14.0-1, HmIP: RPI-RF-MOD/HB-RF-USB@usb-0000:00:14.0-1, OK
Updating Homematic RF-Hardware: RPI-RF-MOD: 4.4.12, not necessary, OK
Starting hs485dLoader: disabled
Starting xinetd: OK
Starting eq3configd: OK
Starting lighttpd: OK
Starting ser2net: disabled
Starting ssdpd: OK
Starting ha-proxy: OK
Starting NUT services: disabled
Initializing Third-Party Addons: OK
Starting LGWFirmwareUpdate: ...OK
Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: .OK
Starting rfd: ....................ERROR
Starting HMIPServer: .....................................................................................................ERROR
Starting ReGaHss: .OK
Starting CloudMatic: OK
Starting NeoServer: disabled
Starting Third-Party Addons: OK
Starting crond: OK
Setup onboard LEDs: booted, OK
Finished Boot: 3.61.7.20220212 (raspmatic_oci_amd64)

Mein system besteht aus einem Intel NUC 11, Ubuntu 20.04, HB-RF-USB und Home Assistant Supervised mit supervisor-2022.01.1 und core-2022.2.9. Als Addon nutze ich den Snapshot 3.61.7.20220212-be487fa (mehrere Versionen seit Release ohne Erfolg getestet)

Wollte von debmatic zum HomeAssistant Addon wechseln. Debmatic natürlich vorher mit systemctl stop debmatic gestopped. Alternativ hätte ich auch noch einen HMIP-RFUSB zur Verfügung (allerdings bisher nicht im Einsatz gewesen). Ich kenne mich mit docker und linux ganz gut aus, also wenn ich irgendwie dazu beitragen kann den Fehler zu finden und zu beseitigen, stehe ich gerne zur Verfügung

@dominikandreas ich bin durch Zufall nach der Fehler-Suche von HA mit RaspberryMatic auf dich gestoßen. Könntest Du mir helfen mit dem Thema Starting rfd: ....................ERROR und HMIP-RFUSB . Kann meine Geräte nicht in der WebUi sehen. Danke für eine Rückmeldung. Oliver

Ro4cHii commented 1 year ago

Ich habe leider auch das gleiche Problem wie anfangs beschrieben:

Mounting /data as /usr/local (Home Assistant Add-On): OK
Identifying host system: oci, OK
Initializing RTC Clock: onboard, OK
Running sysctl: OK
Checking for Factory Reset: not required
Checking for Backup Restore: not required
Initializing System: OK
Starting logging: OK
Init onboard LEDs: init, OK
Starting irqbalance: OK
Starting iptables: OK
Starting network: eth0: link up, fixed, firewall, inet up, 172.30.33.7, OK
Identifying Homematic RF-Hardware: ....HmRF: RPI-RF-MOD/HB-RF-USB@usb-0000:00:14.0-1, HmIP: RPI-RF-MOD/HB-RF-USB@usb-0000:00:14.0-1, OK
Updating Homematic RF-Hardware: RPI-RF-MOD: 4.4.12, not necessary, OK
Starting hs485dLoader: disabled
Starting xinetd: OK
Starting eq3configd: OK
Starting lighttpd: OK
Starting ser2net: disabled
Starting ssdpd: OK
Starting ha-proxy: OK
Starting NUT services: disabled
Initializing Third-Party Addons: OK
Starting LGWFirmwareUpdate: ...OK
Setting LAN Gateway keys: OK
Starting hs485d: disabled
Starting multimacd: .OK
Starting rfd: ....................ERROR
Starting HMIPServer: .....................................................................................................ERROR
Starting ReGaHss: .OK
Starting CloudMatic: OK
Starting NeoServer: disabled
Starting Third-Party Addons: OK
Starting crond: OK
Setup onboard LEDs: booted, OK
Finished Boot: 3.61.7.20220212 (raspmatic_oci_amd64)

Mein system besteht aus einem Intel NUC 11, Ubuntu 20.04, HB-RF-USB und Home Assistant Supervised mit supervisor-2022.01.1 und core-2022.2.9. Als Addon nutze ich den Snapshot 3.61.7.20220212-be487fa (mehrere Versionen seit Release ohne Erfolg getestet) Wollte von debmatic zum HomeAssistant Addon wechseln. Debmatic natürlich vorher mit systemctl stop debmatic gestopped. Alternativ hätte ich auch noch einen HMIP-RFUSB zur Verfügung (allerdings bisher nicht im Einsatz gewesen). Ich kenne mich mit docker und linux ganz gut aus, also wenn ich irgendwie dazu beitragen kann den Fehler zu finden und zu beseitigen, stehe ich gerne zur Verfügung

@dominikandreas ich bin durch Zufall nach der Fehler-Suche von HA mit RaspberryMatic auf dich gestoßen. Könntest Du mir helfen mit dem Thema Starting rfd: ....................ERROR und HMIP-RFUSB . Kann meine Geräte nicht in der WebUi sehen. Danke für eine Rückmeldung. Oliver

Ich hatte vor einigen Monaten schon mal in https://github.com/jens-maus/RaspberryMatic/discussions/1861 Hilfe gesucht.

Nun bin ich etwas weitergekommen, scheine aber dasselbe bzw. ein ähnliches Problem zu haben.

Docker scheint die Hardware prinzipiell zu erkennen:

Identifying Homematic RF-Hardware: ....HmRF: HM-MOD-RPI-PCB/GPIO@c11084c0.serial, HmIP: HM-MOD-RPI-PCB/GPIO@c11084c0.serial, OK
Updating Homematic RF-Hardware: HM-MOD-RPI-PCB: 2.8.6, not necessary, OK

Aus mir nicht verständlichen Gründen werden dann aber folgende Errors geloggt:

Starting multimacd: ..........ERROR
Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
Starting HMIPServer: ERROR: /dev/mmd_hmip missing

Leider verstehe ich nicht, was jetzt noch fehlt.