Docker environment start fails with - Starting multimacd: ..........ERROR on Ubuntu 18.0.4 since 3.69.4.20230322-af1a3fc / 3.69.6.20230407

[dashart-ke]

Describe the issue you are experiencing

After pulling 3.69.6.20230407 the system start fails with Starting multimacd: ..........ERROR.
System was working with bild <= 3.67.10.20230225 fine.

If i try to open the webGUI, starting screen will be displayed (Bitte warten. Sie werden automatisch auf die Startseite weitergeleitet.), no redirect to login screen.

• Docker environment on Ubuntu 18.0.4.
• x86 based system
• HMIP-RFUSB: 4.4.18

docker compose logs output:

ccu_3  | Starting watchdog...
ccu_3  | Identifying host system: oci, OK
ccu_3  | Initializing RTC Clock: onboard, OK
ccu_3  | Running sysctl: OK
ccu_3  | Checking for Factory Reset: not required
ccu_3  | Checking for Backup Restore: not required
ccu_3  | Initializing System: OK
ccu_3  | Setup ca-certificates: OK
ccu_3  | Starting logging: OK
ccu_3  | Populating /dev using udev: done
ccu_3  | Init onboard LEDs: init, OK
ccu_3  | Starting irqbalance: OK
ccu_3  | Saving 256 bits of creditable seed for next boot
ccu_3  | Starting iptables: OK
ccu_3  | Starting network: eth0: link up, fixed, firewall, inet up, 172.31.0.2, OK
ccu_3  | Identifying Homematic RF-Hardware: ....HmRF: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-0000:00:15.0-8, HmIP: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-0000:00:15.0-8, OK
ccu_3  | Updating Homematic RF-Hardware: HMIP-RFUSB: 4.4.18, not necessary, OK
ccu_3  | Starting hs485dLoader: disabled
ccu_3  | Starting xinetd: OK
ccu_3  | Starting eq3configd: OK
ccu_3  | Starting lighttpd: OK
ccu_3  | Starting ser2net: disabled
ccu_3  | Starting ssdpd: OK
ccu_3  | Starting NUT services: disabled
ccu_3  | Initializing Third-Party Addons: OK
ccu_3  | Starting LGWFirmwareUpdate: ...OK
ccu_3  | Setting LAN Gateway keys: OK
ccu_3  | Starting hs485d: disabled
ccu_3  | Starting multimacd: ...........ERROR
ccu_3  | Starting rfd: ERROR: /dev/mmd_bidcos missing, no BidCos-RF hardware found
ccu_3  | Starting HMIPServer: ERROR: /dev/mmd_hmip missing
ccu_3  | Starting ReGaHss: ....................ERROR
ccu_3  | Starting CloudMatic: OK
ccu_3  | Starting Third-Party Addons: OK
ccu_3  | Starting crond: OK
ccu_3  | Setup onboard LEDs: booted, OK
ccu_3  | Finished Boot: 3.69.4.20230322 (raspmatic_oci_amd64)

docker-compose.yaml

version: "3.8"
services:
  raspberrymatic:
    image: ghcr.io/jens-maus/raspberrymatic:3.69.6.20230407
    container_name: ccu_3
    hostname: homematic-raspi
    privileged: true
    restart: unless-stopped
    stop_grace_period: 10s
    volumes:
      - ./volumes/ccudata:/usr/local:rw
      - /lib/modules:/lib/modules:ro
      - /run/udev/control:/run/udev/control
    ports:
      - "192.168.2.12:80:80"
      - "192.168.2.12:2001:2001"
      - "192.168.2.12:2010:2010"
      - "192.168.2.12:9292:9292"
      ##ccu jack
      - "192.168.2.12:2121:2121"
      - "192.168.2.12:2122:2122"
      - "192.168.2.12:1883:1883"
      - "192.168.2.12:8883:8883"

volumes:
  ccu_data:

Describe the behavior you expected

System starts as with 3.67.10.20230225 before.

ccu_3  | Starting watchdog...
ccu_3  | Identifying host system: oci, OK
ccu_3  | Initializing RTC Clock: onboard, OK
ccu_3  | Running sysctl: OK
ccu_3  | Checking for Factory Reset: not required
ccu_3  | Checking for Backup Restore: not required
ccu_3  | Initializing System: OK
ccu_3  | Setup ca-certificates: OK
ccu_3  | Starting logging: OK
ccu_3  | Populating /dev using udev: done
ccu_3  | Init onboard LEDs: init, OK
ccu_3  | Starting irqbalance: OK
ccu_3  | Starting iptables: OK
ccu_3  | Starting network: eth0: link up, fixed, firewall, inet up, 172.25.0.2, OK
ccu_3  | Identifying Homematic RF-Hardware: ....HmRF: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-0000:00:15.0-8, HmIP: HMIP-RFUSB/eQ-3 HmIP-RFUSB@usb-0000:00:15.0-8, OK
ccu_3  | Updating Homematic RF-Hardware: HMIP-RFUSB: 4.4.18, not necessary, OK
ccu_3  | Starting hs485dLoader: disabled
ccu_3  | Starting xinetd: OK
ccu_3  | Starting eq3configd: OK
ccu_3  | Starting lighttpd: OK
ccu_3  | Starting ser2net: disabled
ccu_3  | Starting ssdpd: OK
ccu_3  | Starting NUT services: disabled
ccu_3  | Initializing Third-Party Addons: OK
ccu_3  | Starting LGWFirmwareUpdate: ...OK
ccu_3  | Setting LAN Gateway keys: OK
ccu_3  | Starting hs485d: disabled
ccu_3  | Starting multimacd: ...OK
ccu_3  | Starting rfd: .OK
ccu_3  | Starting HMIPServer: .........OK
ccu_3  | Starting ReGaHss: .OK
ccu_3  | Starting CloudMatic: OK
ccu_3  | Starting Third-Party Addons: OK
ccu_3  | Starting crond: OK
ccu_3  | Setup onboard LEDs: booted, OK
ccu_3  | Finished Boot: 3.67.10.20230225 (raspmatic_oci_amd64)

Steps to reproduce the issue

1. Change image from ghcr.io/jens-maus/raspberrymatic:3.67.10.20230225 to ghcr.io/jens-maus/raspberrymatic:latest
2. Execute docker compose up
3. Wait a while until ' Finished Boot' displayed

What is the version this bug report is based on?

3.69.6.20230407

Which base platform are you running?

oci (Open Container Infrastructure)

Which HomeMatic/homematicIP radio module are you using?

HmIP-RFUSB

Anything in the logs that might be useful for us?

/var/log/message

May  2 22:46:41 homematic-raspi syslog.info syslogd started: BusyBox v1.36.0
May  2 22:46:42 homematic-raspi user.info firewall: configuration set
May  2 22:46:46 homematic-raspi daemon.err xinetd[1205]: Unable to read included directory: /etc/config/xinetd.d [file=/etc/xinetd.conf] [line=14]
May  2 22:46:46 homematic-raspi daemon.crit xinetd[1205]: 1205 {init_services} no services. Exiting...
May  2 22:46:46 homematic-raspi user.debug ccu-jack: Starting
May  2 22:46:46 homematic-raspi user.info ccu-jack: Started
May  2 22:47:47 homematic-raspi daemon.info : starting pid 4113, tty '': '/bin/mv /tmp/boot.log /var/log/boot.log'
May  2 22:47:47 homematic-raspi daemon.info : starting pid 4114, tty '/dev/null': '/usr/bin/monit -Ic /etc/monitrc'
May  2 22:47:47 homematic-raspi user.info monit[4114]: Starting Monit 5.30.0 daemon with http interface at /var/run/monit.sock
May  2 22:47:47 homematic-raspi user.info monit[4114]: 'homematic-raspi' Monit 5.30.0 started
May  2 22:47:47 homematic-raspi user.err monit[4114]: 'ssdpd' process is not running
May  2 22:47:47 homematic-raspi user.info monit[4114]: 'ssdpd' trying to restart
May  2 22:47:47 homematic-raspi user.info monit[4114]: 'ssdpd' restart: '/etc/init.d/S50ssdpd restart'
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'ssdpd' service restarted 1 times within 1 cycles(s) - exec
May  2 22:48:01 homematic-raspi user.info monit[4114]: 'ssdpd' exec: '/bin/triggerAlarm.tcl ssdpd restarted WatchDog: ssdpd-restart true'
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'ssdpd' process is not running
May  2 22:48:01 homematic-raspi user.info monit[4114]: 'ssdpd' trying to restart
May  2 22:48:01 homematic-raspi user.info monit[4114]: 'ssdpd' restart: '/etc/init.d/S50ssdpd restart'
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'sshdEnabled' status failed (1) -- no output
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'hs485dEnabled' status failed (2) -- grep: /var/etc/hs485d.conf: No such file or directory
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'hmlangwEnabled' status failed (1) -- no output
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'rfdEnabled' status failed (1) -- no output
May  2 22:48:01 homematic-raspi user.err monit[4114]: 'HMIPServer' process is not running
May  2 22:48:01 homematic-raspi user.info monit[4114]: 'HMIPServer' trying to restart
May  2 22:48:01 homematic-raspi user.info monit[4114]: 'HMIPServer' restart: '/etc/init.d/S62HMServer restart'
May  2 22:48:32 homematic-raspi user.err monit[4114]: 'HMIPServer' failed to restart (exit status 1) -- '/etc/init.d/S62HMServer restart': Stopping HMIPServer: OK Starting HMIPServer: ERROR: /dev/mmd_hmip missing
May  2 22:48:32 homematic-raspi user.err monit[4114]: 'ReGaHss' process is not running
May  2 22:48:32 homematic-raspi user.info monit[4114]: 'ReGaHss' trying to restart
May  2 22:48:32 homematic-raspi user.info monit[4114]: 'ReGaHss' restart: '/etc/init.d/S70ReGaHss restart'
May  2 22:49:02 homematic-raspi user.err monit[4114]: 'ReGaHss' failed to restart (exit status -1) -- '/etc/init.d/S70ReGaHss restart': Program timed out -- start-stop-daemon: warning: killing process 2294: No such process
May  2 22:49:02 homematic-raspi user.warn monit[4114]: 'hasUSB' status failed (1) -- no output
May  2 22:49:02 homematic-raspi user.err monit[4114]: 'hb_rf_eth-CheckEnabled' status failed (1) -- no output
May  2 22:49:02 homematic-raspi user.warn monit[4114]: 'rpi4usb3Check' status failed (1) -- no output
May  2 22:49:02 homematic-raspi user.err monit[4114]: 'tailscaleEnabled' status failed (1) -- no output
May  2 22:49:02 homematic-raspi user.err monit[4114]: 'multimacd' process is not running
May  2 22:49:02 homematic-raspi user.info monit[4114]: 'multimacd' trying to restart
May  2 22:49:02 homematic-raspi user.info monit[4114]: 'multimacd' restart: '/etc/init.d/S60multimacd restart'

Additional information

Issue has been introduces with snapshot 3.69.4.20230322-af1a3fc

[jens-maus]

This looks like some kernel modules are now missing on your host system (possibly due to a kernel or general ubuntu update process). This is quite a common problem if people tend to update their systems in general and are missing to take care of the necessary kernel modules that are required for the Homematic RF modules. Thus, have you tried to re-install the following packages:

sudo apt reinstall pivccu-modules-dkms

And if you are using a raspberrypi as your base platform also make sure to do:

sudo apt reinstall pivccu-modules-raspberrypi raspberrypi-kernel raspberrypi-kernel-headers raspberrypi-bootloader

If you use a different platform it can be that you have to install other packages for the kernel headers so that the necessary kernel modules can be compiled in during reinstall of the pivccu-modules-dkms package.

And then do the following and check that no error is returned.

sudo service pivccu-dkms restart
sudo modprobe eq3_char_loop

[mdewendt]

Hello.

I have the same issue with a docker container 3.69.7.20230626 on debian 10. The HMIP-RFUSB/eQ-3 is found. Also reinstalling the kernel driver does not help.
root@vccu:~# systemctl status pivccu-dkms.service
● pivccu-dkms.service - piVCCU DKMS Modules
Loaded: loaded (/lib/systemd/system/pivccu-dkms.service; enabled; vendor preset: enabled)
Active: inactive (dead) since Thu 2023-06-29 11:53:59 CEST; 29min ago
Process: 14236 ExecStart=/var/lib/piVCCU/dkms/ensure_modules.sh (code=exited, status=0/SUCCESS)
Main PID: 14236 (code=exited, status=0/SUCCESS)

Jun 29 11:53:59 vccu systemd[1]: Starting piVCCU DKMS Modules...
Jun 29 11:53:59 vccu systemd[1]: pivccu-dkms.service: Succeeded.
Jun 29 11:53:59 vccu systemd[1]: Started piVCCU DKMS Modules.

I have device /dev/eq3loop but no /dev/mmd_bidcos and /dev/mmd_hmip. Guess that will let multimacd failing.
How to deeper trouble shoot that issue? Thx.

[jens-maus]

Sorry, but please use the new install-docker.sh installation script (cf. https://github.com/jens-maus/RaspberryMatic/wiki/Installation-Docker-OCI#installation-procedure) to ensure you have done everything correctly and also make sure to try the "uninstall" option of that script.

[mdewendt]

Hello.

I have used it before but tried uninstall and install again: same issue. The /dev/eq3loop device is there but no /dev/mmd_bidcos and /dev/mmd_hmip Any idea how to debug it? i guess this is more a piVCCU issue right? So the serial port is called by the kernel driver and ended in the loop modul? How is then the multimacd coming into the game? Calling those mmd devices? Who is creating them the loop device? How to debug then this guy? Thx.

[jens-maus]

The /dev/eq3loop device is there but no /dev/mmd_bidcos and /dev/mmd_hmip Any idea how to debug it?

The /dev/mmd_bidcos and /dev/mmd_hmip are generated when multimacd are started (because it creates them). So try to start it manually and see if there might be some permission errors, thought. In the end this is, however, not easy to debug and docker/OCI installation of RaspberryMatic are known to be prone to local installation differences and also critical in terms of what your actualy docker host system is (since RaspberryMatic requires kernel modules, etc.).

i guess this is more a piVCCU issue right? So the serial port is called by the kernel driver and ended in the loop modul? How is then the multimacd coming into the game? Calling those mmd devices? Who is creating them the loop device? How to debug then this guy? Thx.

Sorry, but this is no discussion/support fora here but a bug/issue tracker. If you need help or would like to discuss your problem move over to the discussion part since this is definitly no general issue here simply because a plain/fresh docker/OCI installation works perfectly here in all of my test systems and other ppl also have to perfectly running. Thus, I suspect a local issue on your end which needs debugging/analyses - however, this is not something that should be done here in the bug/issue tracker!

[mdewendt]

i found the reason for the fail in this RaspberryMatic docker setup: it does not support debian 10 and also ubuntu 18 anymore. reason is piVCCU brings an error regarding the old kernel/libc. you will figure out while trying to install debmatic. my other test setup was debian 12. i updated now to debian 11 and all is working fine.

[jens-maus]

That's exactly what I meant: The docker/OCI setup routine is too much prone and dependent on the actual underlying operating system used. That's why every other month someone is coming up here with issues and then we have to tell him that it is caused by their environment. That's why I always suggest to either use non-dockerized RaspberryMatic installation or use HomeAssistant and use RaspberryMatic as a HA addon or even better use ProxmoxVE as a virtualization platform and run RaspberryMatic as a plain VM. All these direct docker/OCI installation pathes are way to prone on the actual underlying OS and hardware platform used....

[github-actions]

@GDAV, the issue ticket you created does not seem to report a general issue/problem/bug in RaspberryMatic itself, but rather seems to point at a local usage issue that rather requires some support using a discussion fora. It will therefore be moved to the discussion area where you can continue for identifying solutions to your issue.