Homematic reconnect does not work

Since it also occurs for me when the network connection is interrupted, I’m testing a sensor that checks the last pyhomematic log message time stamp in the HA log, and then to restart HA automatically maybe.

But I might also have a look at the code to see if there’s any obvious problem.

Hello All!

I’m also investigating the homemati.reconnect service.
To me it seems it does not do anything at all.
Does anyone know which port this service uses or what exactly it does?
Thanks!

Albert

It calls the init XML-RPC method for every configured interface. Pretty much the same as it does doing startup of Home Assistant.

I have exactly the same issue. My Homematic installation consists rf and also ip components. After loosing connection the ip-components don’t come back after homematic.reconnect. Only server restart replace them useable. This is painful if you try to open the door with e.g. HmIP-KRC4.

Do I read correctly, that the reconnect only fails for IP devices and RF devices start working again after the reconnect?

Thank you for your question. Correct!

My test scenario was:
Ongoing connection after server restart. I restarted RaspMatic by watching the HA debug log file. The event flow stops. After starting the homematic.reconnect service the event flow starts again. However, the events of the ip components are missing. This requires an HA server restart.

As a addition: if you call up the homematic.reconnect service without rebooting the RaspMatic, the ip connection is maintained. So the ip-events will only be lost after a restart of the Homematic server.

Thanks. That gives me a new perspective. Since I use RF devices that would explain why it’s working for me all the time.

Would it be possible to do some more debugging? I have to see the debug-output of pyhomematic during the reconnect. You can enable that by putting this into your configuration.yaml:

logger:
  default: warning
  logs:
    pyhomematic: debug

This supposedly is the problematic part in pyhomematic. It’s the code that’s also being used when Home Assistant is starting. So generally it appears to be doing it’s job. Just not when reconnecting. In a working setup you should see 2 messages like the following:
ServerThread.proxyInit: init('http://1.2.3.4:2001) and
ServerThread.proxyInit: init('http://1.2.3.4:2010), where both would either be confirmed with Proxy initialized or some exception. However, if you get the message just once, then the skipinit-part at the top of the loop becomes effective. We would have to figure out why this happens then.

Edit:
If it’s the skipinit, then the only reason for this problem I can identify by looking at the code seems to be, if the same key is used for one of the interfaces and and of the hosts.

Working example:

homematic:
  interfaces:
    hm_interface:
      host: 1.2.3.4
      port: 2010
  hosts:
    hm_host:
      host: 1.2.3.4
      ...

Broken example:

homematic:
  interfaces:
    hm:
      host: 1.2.3.4
      port: 2010
  hosts:
    hm:
      host: 1.2.3.4
      ...

In the second case the parameters for the interface-proxy-object would be overwritten by the parameters for the host-connector. And the host connector always has the flag to skip the initialization because in that context it is not needed.

Wooow, first of all, thank you very much for taking care of my problem. :grinning:
I am not quite sure what the difference between broken and working example is. Therefore I send you my config from the configuration.yaml

homematic:
  interfaces:
    rf:
      host: 192.168.xx.xx
      port: 2001
      resolvenames: json
      username: xxx
      password: xxx
    ip:
      host: 192.168.xx.xx
      port: 2010
      resolvenames: json
      username: xxxxx
      password: xxxxx

There is only one host and 2 interfaces: rf and ip. The installation is separate, HA and HM run on different servers. Is that okay?

Logging: I changed the logs to pyhomematic:debug. The result is very impressive. I have traced the initialization after HA-restart.

2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic.connection] HMConnection: Creating server object
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] ServerThread.__init__
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] __init__: Creating proxies
2020-02-02 10:10:29 INFO (SyncWorker_7) [pyhomematic._hm] Creating proxy rf. Connecting to 192.168.xx.xx:2001
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] LockingServerProxy.__init__: Getting local ip
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] LockingServerProxy.__init__: Got local ip 192.168.xx.xx
2020-02-02 10:10:29 INFO (SyncWorker_7) [pyhomematic._hm] Creating proxy ip. Connecting to 192.168.xx.xx:2010
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] LockingServerProxy.__init__: Getting local ip
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] LockingServerProxy.__init__: Got local ip 192.168.xx.xx
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] RPCFunctions.__init__
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] RPCFunctions.__init__: iterating proxy = homeassistant-rf
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] RPCFunctions.__init__: iterating proxy = homeassistant-ip
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] ServerThread.__init__: Setting up server
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] ServerThread.__init__: Registering RPC functions
2020-02-02 10:10:29 INFO (Thread-2) [pyhomematic._hm] Starting server at http://0.0.0.0:37391
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] ServerThread.proxyInit: init('http://192.168.xx.xx:37391', 'homeassistant-rf')
2020-02-02 10:10:29 DEBUG (Thread-2) [pyhomematic._hm] RPCFunctions.listDevices: interface_id = homeassistant-rf, _devices_raw = {'rf': [], 'ip': []}
2020-02-02 10:10:29 INFO (SyncWorker_7) [pyhomematic._hm] Proxy initialized
2020-02-02 10:10:29 DEBUG (SyncWorker_7) [pyhomematic._hm] ServerThread.proxyInit: init('http://192.168.xx.xx:37391', 'homeassistant-ip')
2020-02-02 10:10:29 INFO (SyncWorker_7) [pyhomematic._hm] Proxy initialized

After reboot RaspMatic (timestamp 10:23:05) you can see:

2020-02-02 10:22:20 WARNING (MainThread) [homeassistant.components.device_tracker] Updating device list from legacy took longer than the scheduled scan interval 0:00:12
2020-02-02 10:22:59 WARNING (MainThread) [homeassistant.components.device_tracker] Updating device list from legacy took longer than the scheduled scan interval 0:00:12
2020-02-02 10:23:05 DEBUG (SyncWorker_6) [pyhomematic._hm] ServerThread.proxyInit: init('http://192.168.xx.xx:37391', 'homeassistant-rf')
2020-02-02 10:23:05 DEBUG (Thread-2) [pyhomematic._hm] RPCFunctions.listDevices: interface_id = homeassistant-rf, _devices_raw = {'rf': [{'ADDRESS': 'BidCoS-RF', 'CHILDREN': ['BidCoS-RF:0', 'BidCoS-RF:1', 'BidCoS-RF:2', 'BidCoS-RF:3', 'BidCoS-RF:4', 'BidCoS-RF:5', 'BidCoS-RF:6', 'BidCoS-RF:7', 'BidCoS-RF:8', 'BidCoS-RF:9', 'BidCoS-RF:10', 'BidCoS-RF:11', 'BidCoS-RF:12', 'BidCoS-RF:13', 'BidCoS-RF:14', 'BidCoS-RF:15', 'BidCoS-RF:16', 'BidCoS-RF:17', 'BidCoS-RF:18', 'BidCoS-RF:19', 'BidCoS-RF:20', 'BidCoS-RF:21', 'BidCoS-RF:22', 'BidCoS-RF:23', 'BidCoS-RF:24', 'BidCoS-RF:25', 'BidCoS-RF:26', 'BidCoS-RF:27', 'BidCoS-RF:28', 'BidCoS-RF:29', 'BidCoS-RF:30', 'BidCoS-RF:31', 'BidCoS-RF:32', 'BidCoS-RF:33', 'BidCoS-RF:34', 'BidCoS-RF:35', 'BidCoS-RF:36', 'BidCoS-RF:37', 'BidCoS-RF:38', 'BidCoS-RF:39', 'BidCoS-RF:40', 'BidCoS-RF:41', 'BidCoS-RF:42', 'BidCoS-RF:43', 'BidCoS-RF:44', 'BidCoS-RF:45', 'BidCoS-RF:46', 'B ......

2020-02-02 10:23:05 INFO (SyncWorker_6) [pyhomematic._hm] Proxy initialized
2020-02-02 10:23:05 DEBUG (SyncWorker_6) [pyhomematic._hm] ServerThread.proxyInit: init('http://192.168.xx.xx:37391', 'homeassistant-ip')
2020-02-02 10:23:09 DEBUG (Thread-2) [pyhomematic._hm] RPCFunctions.event: interface_id = homeassistant-rf, address = JEQ0734475:1, value_key = MOTION, value = False
2020-02-02 10:23:09 INFO (Thread-2) [pyhomematic.devicetypes.generic] HMGeneric.event: address=JEQ0734475:1, interface_id=homeassistant-rf, key=MOTION, value=False

I’m not sure but I think, the ip-connection is also re-initialized. But no more events are received for ip-devices. :sob:

Is this helping you any?

(I have adjusted the IP addresses / PW for security reasons, but I hope that this does not hinder the analysis)

In my working and broken examples I did reuse the name hm in the hosts section (which you did not include in your config). But as it turns out, my guess does not seem to apply to your setup. As we can see in your logs, this part of the code does indeed get executed twice - once for each interface. But the second time the CCU/Raspi-Matic does not call the listDevices method, and you also don’t get the Proxy initialized message in the log.

My next best guess is that the Hm-IP Server software (on the CCU) is just too buggy. There are other cases where communicating with the regular server for RF and wired works, while the one for IP doesn’t respond correctly. So I think we’ll just have to wait until eq3 improves the server-code. Technically Home Assistant seems to be doing everything correctly, which is proven by the fact, that the exact same code is working during startup. It just gets rejected silently if there is a (stuck) previous initialization.

My recommendation: everybody who has this problem should reach out to eq3 regarding this problem. Maybe if enough people complain they’ll fix the server-code. :+1:

Edit:
Which RaspiMatic version are you using? Version 3.49.17.20191225 is using the CCU3 Firmware 3.49.17. On page 3 of the release notes there are stability improvements for the HMIPServer mentioned. So if you are on an older version it might be worth a try to upgrade and see if this solves the problem.

Edit 2:
No, wait, that’s for CCU version 3.47.18. So check if you have that or a later version installed.

Just to confirm that this doesn’t work for me either. The V_Last_Reboot variable is updated in HA and triggers the automation, but none of my HMIP devices reconnect. I’m running the latest version of RaspberryMatic.
It’s not really a problem for me as I rarely have to reboot my CCU, but it would be nice to get it fixed.

It’s the same with me, too. I also use the latest version of the RaspMatic. In fact, it’s not really a problem, but it’s ugly.

Once again in depth in terms of content: (HA means Home Assistant Server, HM means Homematic-Server, CCU2, RaspMatic, …)

  • You restart the HA server - and did NOT do anything on the HM server. All ip-devices are detected and can be seen on the event bus.
  • You reboot the HM Server - the connection is interrupted, with reconnect you do not restart the ip-components, will see nothing on the event bus.
  • But if you restart the HA server again (without changing HM), the ip-components are back on the event bus.

It must be due to the different start sequences (restart vs. reconnect), or am I making a mistake?

The problem appears to be, that the HM-IP-Component on the CCU does not accept new connections as long as a previous session hasn’t been terminated / unsubscribed, which only is done when HA shuts down / restarts.

Basically this is what happens:

With RF-Devices:
HA -> CCU: hello, send me events for devices
CCU -> HA: sure, here you go
CCU reboots
HA -> CCU: hello, send me events for devices
CCU -> HA: sure, here you go

With IP-Devices:
HA -> CCU: hello, send me events for devices
CCU -> HA: sure, here you go
CCU reboots
HA -> CCU: hello, send me events for devices
CCU -> HA: no, you didn’t say goodbye as I silently left

So the workaround probably would be to say goodbye each time before we say hello. :roll_eyes:

1 Like

Is there any progress on handling this problem? Restarting home assistant is rather inconvenient.

1 Like

As long as eq3 hasn’t fixed the bug in the CCU code, the problem will still be present. I haven’t followed their recent releases though, so I can’t make any statements about this topic. But my guess is, that they don’t care about this issue.

Thanks Daniel!
Would the workaround you mentioned in one of the posts above still be a possible solution?

Maybe. I have not tried it, and I don’t have the time to take care of this. But if someone is willing to give it a shot, the relevant code is somewhere around here.

If you mean restarting manually rather than needing a restart at all you could use one or both of the approaches in the docs and replace the homematic.reconnect with homeassistant.restart; you’ll still have a reboot everytime the ccu looses its connection, though.
I didn’t have connection issues besides a restart of the ccu so far, therefore I only am using the not-so-solid approach with the last reboot time at the moment:

- alias: HomeMatic CCU Reboot
  description: ''
  trigger:
    platform: state
    entity_id: sensor.v_last_reboot
  action:
  # - service: homematic.reconnect
  - service_template: persistent_notification.create
    data_template:
      title: "CCU rebooted"
      message: "Restarting in 30 seconds."
  - delay: '00:00:30'
  - service: homeassistant.restart

If you’re going to use the other approach, maybe you should use some form of preventing permanent reboots if the connection can’t be restored or only notify yourself of the connection loss and have a homeassistant.restart shortcut on your dashboard to manually trigger - in the latter case you’d at least detect the connection loss automatically.

opened a bug in github - maybe there will be a solution

That’s actually not a bug RaspberryMatic can fix. It’s the server binary that gets published by eq3. RaspberryMatic is just reusing the binary if I’m not mistaken.