search

angelnu / docker-ccu

Script to create a docker container with the CCU2 firmware
Apache License 2.0
33 stars 14 forks source link

Problems with starting with the HmIP-RFUSB #36

Closed eisenreich closed 3 years ago

eisenreich commented 4 years ago

Hello,

FOA thank you for this this engagement with getting this project able to start with docker.

Now to the problem...

I'm trying to run the CCU on a Linux raspberrypi 4.19.75-v7l+ #1270 SMP Tue Sep 24 18:51:41 BST 2019 armv7l GNU/Linux Raspberry 4 with 4gb RAM.

I bought the usb-toolkit from elv-electronic and soldered it by myself. But because of bad equipment and no flux, the solder joints are not pretty good! So this could be also a reason because it's not working - I don't know for sure. When I unplug and plugin the USB-stick the following message is in the kernel log written:

[10265.234428] usb 1-1.4: USB disconnect, device number 3
[10265.235067] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
[10265.235202] cp210x 1-1.4:1.0: device disconnected
[10268.681832] usb 1-1.3: new full-speed USB device number 4 using xhci_hcd
[10268.817028] usb 1-1.3: New USB device found, idVendor=1b1f, idProduct=c020, bcdDevice= 1.00
[10268.817044] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[10268.817057] usb 1-1.3: Product: eQ-3 HmIP-RFUSB
[10268.817069] usb 1-1.3: Manufacturer: Silicon Labs
[10268.817081] usb 1-1.3: SerialNumber: 3014F711A061A7C00010CECF
[10268.820505] cp210x 1-1.3:1.0: cp210x converter detected
[10268.828717] usb 1-1.3: cp210x converter now attached to ttyUSB0

This does looks like the USB should work fine or?!

To go sure I started java -jar hmip-copro-update.jar -p /dev/ttyUSB0 -v which produced the following output:

[INFO] SGTIN = 3014f711a000041709adfa9d
[INFO] Checking coprocessor firmware version ...
[DEBUG] Start bootloader ...
[DEBUG] Bootloader running
[DEBUG] Request bootloader version ...
[INFO] Bootloader version = 1.0.12
[DEBUG] Start application ...
[DEBUG] Application 'HMIP_TRX_App' running
[DEBUG] Request application version ...
[DEBUG] Request application version ...
[INFO] Application version = 2.8.6

In the building instruction this command with the according output is written as the proof that the USB is working well. - I told you this because maybe you have made different experiences.

After this two circumstantial I was almost sure that the USB works fine and it's a configuration related issue.

So I cloned your repository and executed sudo deploy.sh. This command got stuck at

Starting /etc/init.d/S10udev
S10udev - skipping

Starting /etc/init.d/S11InitRFHardware
Identifying Homematic RF-Hardware: HmIP-RFUSB (1b1f:c020) USB stick is connected -> ensure you do the following on the host:
- modprobe cp210x
- echo 1b1f c020 >/sys/bus/usb-serial/drivers/cp210x/new_id

and I rebooted the Pi with half success.

Now the previous step succeeds, but gets stuck at another one (I cut of the copied files, if you need this let me know) :

sent 5,591,374 bytes  received 6,358 bytes  11,195,464.00 bytes/sec
total size is 5,568,316  speedup is 0.99

Starting CCU services

Starting /etc/init.d/S00InstallAddon

Starting /etc/init.d/S00watchdog
S00watchdog - skipping

Starting /etc/init.d/S01InitHost
S01InitHost - defaults
Checking device
Detected piVCCU kernel module

Starting /etc/init.d/S02InitRTC
S02InitRTC - skipping

Starting /etc/init.d/S03InitURandom
S03InitURandom - skipping

Starting /etc/init.d/S04CheckFactoryReset
Checking for Factory Reset: not required

Starting /etc/init.d/S04CheckResizeLocalFS
S04CheckResizeLocal - skipping

Starting /etc/init.d/S05CheckBackupRestore
Checking for Backup Restore: not required

Starting /etc/init.d/S05avahi-setup.sh

Starting /etc/init.d/S06InitSystem
mkdir: can't create directory '/var/lib/dbus': No such file or directory
chmod: /var/lib/dbus: No such file or directory
Initializing System: OK

Starting /etc/init.d/S07DisableHdmi
/entrypoint.sh: line 21: /etc/init.d/S07DisableHdmi: Permission denied

Starting /etc/init.d/S07logging
Starting logging: OK

Starting /etc/init.d/S10udev
S10udev - skipping

Starting /etc/init.d/S11InitRFHardware
Identifying Homematic RF-Hardware: HmIP-RFUSB (1b1f:c020) USB stick is connected -> ensure you do the following on the host:
- modprobe cp210x
- echo 1b1f c020 >/sys/bus/usb-serial/drivers/cp210x/new_id
Copying from /mnt to /usr/local/
sending incremental file list
etc/config/
etc/config/timezone

sent 8,220 bytes  received 82 bytes  1,509.45 bytes/sec
total size is 5,568,316  speedup is 670.72

Starting CCU services

Starting /etc/init.d/S00InstallAddon

Starting /etc/init.d/S00watchdog
S00watchdog - skipping

Starting /etc/init.d/S01InitHost
S01InitHost - defaults
Checking device
Detected piVCCU kernel module

Starting /etc/init.d/S02InitRTC
S02InitRTC - skipping

Starting /etc/init.d/S03InitURandom
S03InitURandom - skipping

Starting /etc/init.d/S04CheckFactoryReset
Checking for Factory Reset: not required

Starting /etc/init.d/S04CheckResizeLocalFS
S04CheckResizeLocal - skipping

Starting /etc/init.d/S05CheckBackupRestore
Checking for Backup Restore: not required

Starting /etc/init.d/S05avahi-setup.sh

Starting /etc/init.d/S06InitSystem
mkdir: can't create directory '/var/lib/dbus': No such file or directory
chmod: /var/lib/dbus: No such file or directory
Initializing System: OK

Starting /etc/init.d/S07DisableHdmi
/entrypoint.sh: line 21: /etc/init.d/S07DisableHdmi: Permission denied

Starting /etc/init.d/S07logging
Starting logging: OK

Starting /etc/init.d/S10udev
S10udev - skipping

Starting /etc/init.d/S11InitRFHardware
Identifying Homematic RF-Hardware: HmIP-RFUSB (1b1f:c020) USB stick is connected -> ensure you do the following on the host:
- modprobe cp210x
- echo 1b1f c020 >/sys/bus/usb-serial/drivers/cp210x/new_id
BidCos-RF: none, HmIP: HMIP-RFUSB, OK

Starting /etc/init.d/S12UpdateRFHardware
Updating Homematic RF-Hardware: HMIP-RFUSB: 2.8.6, OK

Starting /etc/init.d/S13irqbalance
S13irqbalance - skipping

Starting /etc/init.d/S21rngd
S21rngd - skipping

Starting /etc/init.d/S30dbus
Starting system message bus: done

Starting /etc/init.d/S31bluetooth
S31bluetooth - skipping

Starting /etc/init.d/S40network
S40network - skipping

Starting /etc/init.d/S45ifplugd
S45ifplugd - skipping

Starting /etc/init.d/S48MigrateSecuritySettings
Starting : OK

Starting /etc/init.d/S48ntp
Starting ntpd: OK

Starting /etc/init.d/S49hs485d
Preparing start of hs485d: no Hm-Wired hardware found

Starting /etc/init.d/S49xinetd
Starting xinetd: OK

Starting /etc/init.d/S50eq3configd
Starting eq3configd: OK

Starting /etc/init.d/S50lighttpd
Starting lighttpd: OK

Starting /etc/init.d/S50ssdpd
Starting ssdpd: OK

Starting /etc/init.d/S50sshd
Starting sshd: OK

Starting /etc/init.d/S55InitAddons
Initializing Third-Party Addons: OK

Starting /etc/init.d/S58LGWFirmwareUpdate
Starting LGWFirmwareUpdate: ...OK

Starting /etc/init.d/S59SetLGWKey
Setting LAN Gateway keys: OK

Starting /etc/init.d/S59snmpd

Starting /etc/init.d/S60hs485d
Starting hs485d: no Hm-Wired hardware found

Starting /etc/init.d/S60multimacd
Starting multimacd: .....ERROR

Starting /etc/init.d/S60openvpn

Starting /etc/init.d/S61rfd
Starting rfd:
sh: 296: unknown operand
sh: 296: unknown operand
Waiting for rfd to get ready...rfd is ready now.

Starting /etc/init.d/S62HMServer

This stucks until a timeout is reached I think and this step is skipped, then the following follow:

Starting /etc/init.d/S62HMServer
Starting HMIPServer: (/dev/mmd_hmip) .......................................................................................................................................................ERROR

Starting /etc/init.d/S69UDSServices
Starting eq3-uds-services: OK

Starting /etc/init.d/S70ReGaHss
Starting ReGaHss: .OK

Starting /etc/init.d/S97CloudMatic
Starting CloudMatic: OK

Starting /etc/init.d/S97NeoServer
Version is up to date / or Bigger

Starting /etc/init.d/S98StartAddons
Starting Third-Party Addons: OK

Starting /etc/init.d/S98crond
Starting crond: OK

Starting /etc/init.d/S99SetupLEDs
Setup onboard LEDs: booted, OK
Done starting CCU services

Register trap for SIGTERM
sending incremental file list
etc/config/
etc/config/InterfacesList.xml
etc/config/rfd.conf
etc/config/timezone
etc/config/addons/mh/ids

sent 9,316 bytes  received 139 bytes  18,910.00 bytes/sec
total size is 5,568,316  speedup is 588.93

After a while I can access the WebUi, but get the error information that a component of the Homatic is not responding anymore. This error popup message I receive for HmIP-RF and VirtualDevices.

And the adding new devices button opens a empty window where I just can push the Back or Inbox-Button. The inbox button opens a alert with Homeatic Wireless learning mode could not be activated. In the browser console the following error is displayed: anlernen-fehler

FYI: The error messages I translated from german to english as good as my english is. I also took some screenshots, if this helps you.

I tried to find some log-information but without success and don't know how to go further.

Thank you a lot in advice!

UPDATE 1 I copied the hmserver.log which holds the following content:

Jan 18 15:18:05 de.eq3.cbcs.vertx.management.VertxManager WARN  [vert.x-eventloop-thread-6] SYSTEM ADVICE: pre-conditions for deployment of LocalServerFirmwareUpdateInitialization still not met - check deployment configuration  (still unfulfilled: [connector.open])
Jan 18 15:18:05 de.eq3.cbcs.vertx.management.VertxManager WARN  [vert.x-eventloop-thread-2] SYSTEM ADVICE: pre-conditions for deployment of LegacyAPIWorker still not met - check deployment configuration  (still unfulfilled: [connector.open])
Jan 18 15:18:05 de.eq3.cbcs.vertx.management.VertxManager WARN  [vert.x-eventloop-thread-7] SYSTEM ADVICE: pre-conditions for deployment of LanRoutingWorker still not met - check deployment configuration  (still unfulfilled: [connector.open])
Jan 18 15:18:05 de.eq3.cbcs.vertx.management.VertxManager WARN  [vert.x-eventloop-thread-0] SYSTEM ADVICE: pre-conditions for deployment of LegacyNotificationHandler still not met - check deployment configuration  (still unfulfilled: [connector.open])
Jan 18 15:18:05 de.eq3.cbcs.vertx.management.VertxManager WARN  [vert.x-eventloop-thread-6] SYSTEM ADVICE: pre-conditions for deployment of LegacyInitializion still not met - check deployment configuration  (still unfulfilled: [legacy.api.worker][connector.open])
Jan 18 15:18:05 de.eq3.cbcs.vertx.management.VertxManager WARN  [vert.x-eventloop-thread-5] SYSTEM ADVICE: pre-conditions for deployment of LegacyBackendNotificationHandler still not met - check deployment configuration  (still unfulfilled: [connector.open])

This log entries happens each 7 seconds.

Update 2: I took a closer view to this log file and found the following exception:

Jan 18 14:50:28 de.eq3.cbcs.server.local.base.internal.LocalServerAdapterInitialization ERROR [vert.x-eventloop-thread-3] Error 'LOCAL_ADAPTER_NO_SUCH_PORT' while trying to open port '/dev/mmd_hmip':
de.eq3.cbcs.lib.commdevice.CommDeviceException: Exception while trying to open serial port. Check configured port '/dev/mmd_hmip'
        at de.eq3.cbcs.lib.nrjavaserialdevice.SerialCommDevice.open(SerialCommDevice.java:105)
        at de.eq3.cbcs.lib.hmiptrxcommadapter.HomeMaticIPTRXCommAdapter.open(HomeMaticIPTRXCommAdapter.java:726)
        at de.eq3.cbcs.lib.hmiptrxcommadapter.HomeMaticIPTRXCommAdapter.<init>(HomeMaticIPTRXCommAdapter.java:98)
        at de.eq3.cbcs.server.local.base.internal.ShareableHomeMaticIPTRXCommAdapter.<init>(ShareableHomeMaticIPTRXCommAdapter.java:20)
        at de.eq3.cbcs.server.local.base.internal.LocalServerAdapterInitialization.start(LocalServerAdapterInitialization.java:114)
        at io.vertx.core.AbstractVerticle.start(AbstractVerticle.java:111)
        at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:434)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
        at java.lang.Thread.run(Thread.java:748)
Caused by: gnu.io.NoSuchPortException
        at gnu.io.CommPortIdentifier.getPortIdentifier(CommPortIdentifier.java:294)
        at de.eq3.cbcs.lib.nrjavaserialdevice.SerialCommDevice.open(SerialCommDevice.java:96)
        ... 12 more
angelnu commented 4 years ago

Sorry for the late reply - in case you are still interested - the problem seems to be with the multimac service. This is responsible for multiplexing homematic and homematic IP over the same device and it is failing in your case.

Can you try to start it manually and see if you can get more info from it? I also released a new version of CCU3 - I had problems in the past where the firmware in the adapter was newer that in my container.

robologo1 commented 3 years ago

Hello angelnu, thanks for sharing and driving this Docker project. I'm verry interested in a solution for the described problem. I'm facing exactly the same issue. I also tried to start the multimac service manually without success. I only got the following output from the script:

/etc/init.d # ./S60multimacd restart
Stopping multimacd: OK
Starting multimacd: .....ERROR

In Messages I found the following:

Oct 28 21:57:37 ccu user.info kernel: [  530.044661] usb 1-1.4: New USB device found, idVendor=1b1f, idProduct=c020, bcdDevice= 1.00
Oct 28 21:57:37 ccu user.info kernel: [  530.044680] usb 1-1.4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Oct 28 21:57:37 ccu user.info kernel: [  530.044696] usb 1-1.4: Product: eQ-3 HmIP-RFUSB
Oct 28 21:57:37 ccu user.info kernel: [  530.044712] usb 1-1.4: Manufacturer: Silicon Labs
Oct 28 21:57:37 ccu user.info kernel: [  530.044726] usb 1-1.4: SerialNumber: 3014F711A061A7C00010CECF
Oct 28 21:57:37 ccu user.info kernel: [  530.059164] cp210x 1-1.4:1.0: cp210x converter detected
Oct 28 21:57:37 ccu user.info kernel: [  530.066366] usb 1-1.4: cp210x converter now attached to ttyUSB1
Oct 28 21:59:57 ccu syslog.info syslogd exiting
Oct 28 22:00:12 ccu syslog.info syslogd started: BusyBox v1.29.2
Oct 28 22:00:12 ccu user.notice kernel: klogd started: BusyBox v1.29.2 (2020-09-03 10:20:31 CEST)
Oct 28 22:07:51 ccu user.err multimac: No Coprocessor detected!!!
Oct 28 22:08:48 ccu user.info kernel: [ 1200.948120] eq3loop: created slave mmd_hmip
Oct 28 22:08:48 ccu user.info kernel: [ 1200.948505] eq3loop: created slave mmd_bidcos
Oct 28 22:08:54 ccu user.err multimac: No Coprocessor detected!!!
Oct 28 22:26:59 ccu user.info kernel: [ 2291.903954] eq3loop: created slave mmd_hmip
Oct 28 22:26:59 ccu user.info kernel: [ 2291.904514] eq3loop: created slave mmd_bidcos
Oct 28 22:27:05 ccu user.err multimac: No Coprocessor detected!!!
Oct 28 22:27:05 ccu user.info kernel: [ 2297.908091] eq3loop: eq3loop_close_master() mmd_hmip
Oct 28 22:27:05 ccu user.info kernel: [ 2297.908109] eq3loop: eq3loop_close_master() mmd_hmip destroy device

Please tell me, how I can support you to resolve this problem. Thanks a lot in advance ROBOlogo

eisenreich commented 3 years ago

So today I gave it a new try.

I set up a completely new Raspberry Pi 4 and so far I think the USB stick is working. I used the version e5a6a1c and execute the deploy.sh script without any config modifications.

Now I can access the web UI at the default HTTP port. Under devices one device is listed: image Is this the USB-stick?

The only problem I now have is to pair the HmIP-eTRV-2 (https://de.elv.com/elv-homematic-ip-komplettbausatz-heizkoerperthermostat-hmip-etrv-2-fuer-smart-home-hausautomation-153198). I did a factory reset and then started the teach-in mode, but the device is not detected. Do you have any idea what I can do else or what's wrong?

UPDATE 1:

The following notification happens from time to time: image

The startup log:

Starting CCU services

Starting /etc/init.d/S00InstallAddon

Starting /etc/init.d/S00watchdog
S00watchdog - skipping

Starting /etc/init.d/S01InitHost
S01InitHost - defaults
Checking device
Detected Raspberry PI

Starting /etc/init.d/S02InitRTC
S02InitRTC - skipping

Starting /etc/init.d/S03InitURandom
S03InitURandom - skipping

Starting /etc/init.d/S04CheckFactoryReset
Checking for Factory Reset: not required

Starting /etc/init.d/S04CheckResizeLocalFS
S04CheckResizeLocal - skipping

Starting /etc/init.d/S05CheckBackupRestore
Checking for Backup Restore: not required

Starting /etc/init.d/S05avahi-setup.sh

Starting /etc/init.d/S06InitSystem
Initializing System: OK
/entrypoint.sh: line 21: /etc/init.d/S07DisableHdmi: Permission denied

Starting /etc/init.d/S07DisableHdmi

Starting /etc/init.d/S07logging
Starting logging: OK

Starting /etc/init.d/S10udev
S10udev - skipping

Starting /etc/init.d/S11InitRFHardware
Identifying Homematic RF-Hardware: HmIP-RFUSB (1b1f:c020) USB stick is connected -> ensure you do the following on the host:
- modprobe cp210x
- echo 1b1f c020 >/sys/bus/usb-serial/drivers/cp210x/new_id
BidCos-RF: RPI-RF-MOD, HmIP: HMIP-RFUSB, OK

Starting /etc/init.d/S12UpdateRFHardware
Updating Homematic RF-Hardware: RPI-RF-MOD: 2.8.6=>4.2.6, ERROR ( != 4.2.6); HMIP-RFUSB: 2.8.6, OK

Starting /etc/init.d/S13irqbalance
S13irqbalance - skipping

Starting /etc/init.d/S21rngd
S21rngd - skipping

Starting /etc/init.d/S30dbus
Starting system message bus: done

Starting /etc/init.d/S31bluetooth
S31bluetooth - skipping

Starting /etc/init.d/S40network
S40network - skipping

Starting /etc/init.d/S45ifplugd
S45ifplugd - skipping

Starting /etc/init.d/S48MigrateSecuritySettings
Starting : OK

Starting /etc/init.d/S48ntp
Starting ntpd: OK

Starting /etc/init.d/S49hs485d
Preparing start of hs485d: no Hm-Wired hardware found

Starting /etc/init.d/S49xinetd
Starting xinetd: OK

Starting /etc/init.d/S50eq3configd
Starting eq3configd: OK

Starting /etc/init.d/S50lighttpd
Starting lighttpd: OK

Starting /etc/init.d/S50ssdpd
Starting ssdpd: OK

Starting /etc/init.d/S50sshd

Starting /etc/init.d/S55InitAddons
Initializing Third-Party Addons: OK

Starting /etc/init.d/S58LGWFirmwareUpdate
Starting LGWFirmwareUpdate: ...OK

Starting /etc/init.d/S59SetLGWKey
Setting LAN Gateway keys: OK

Starting /etc/init.d/S59snmpd

Starting /etc/init.d/S60hs485d
Starting hs485d: no Hm-Wired hardware found

Starting /etc/init.d/S60multimacd
Starting multimacd: SKIPPING (missing HM_HOST_GPIO_UART)

Starting /etc/init.d/S60openvpn

Starting /etc/init.d/S61rfd
Starting rfd: ........................................ERROR

Starting /etc/init.d/S62HMServer
Starting HMIPServer: (/dev/ttyUSB0) .............OK

Starting /etc/init.d/S69UDSServices
Starting eq3-uds-services: OK

Starting /etc/init.d/S70ReGaHss
Starting ReGaHss: .OK

Starting /etc/init.d/S97CloudMatic
Starting CloudMatic: OK

Starting /etc/init.d/S97NeoServer
[Sun Nov  8 14:18:40 CET 2020] /etc/init.d/S97NeoServer skipping (LAN Gateway)
[Sun Nov  8 14:18:40 CET 2020] /etc/init.d/S97NeoServer skipping (safemode)
[Sun Nov  8 14:18:40 CET 2020] /etc/init.d/S97NeoServer start -> check neo server add-on
[Sun Nov  8 14:18:40 CET 2020] /etc/init.d/S97NeoServer check neo server add-on
[Sun Nov  8 14:18:40 CET 2020] /opt/mediola/startup.sh check installed add-on
[Sun Nov  8 14:18:40 CET 2020] /opt/mediola/startup.sh default=2.5.5, installed=2.5.5
[Sun Nov  8 14:18:40 CET 2020] /opt/mediola/startup.sh add-on is up to date / or newer
[Sun Nov  8 14:18:40 CET 2020] /opt/mediola/startup.sh INSTALL=false, DISABLED=true

Starting /etc/init.d/S98StartAddons
Starting Third-Party Addons: OK

Starting /etc/init.d/S98crond
Starting crond: OK

Starting /etc/init.d/S99SetupLEDs
Setup onboard LEDs: booted, OK
Done starting CCU services

Register trap for SIGTERM
sending incremental file list
etc/config/
etc/config/rfd.conf
etc/config/timezone
etc/config/addons/mh/ids
etc/config/crRFD/data/3014F711A000041709ADFA9D.ap
etc/config/eshlight/mapdb/storage.mapdb.t

sent 68,996 bytes  received 479 bytes  138,950.00 bytes/sec
total size is 45,420,409  speedup is 653.77
angelnu commented 3 years ago

Sorry, I had been busy moving to RaspberryMatic -> see https://github.com/jens-maus/RaspberryMatic/wiki/Docker

Could you please test with the new RaspberryMatic container images - I will provide support so you can open issues there as well.