Attached Hardware: Amber Wireless AMB8465 stick to read out Wireless M-Bus from water & heat meter
Docker / Portainer 2.11.0
openHAB Software: 3.2.0 Release Build
openHAB Bindings: Homematic Binding (logging the heating, controlling lights and blinds), Gardena Binding for Gardena Gateway / smart irrigation control (logging soil humidity), Alexa Binding (controlling the Homematic lights)
Homematic IP Hardware: CCU2 (2.59.7), multiple Homematic IP devices
I’m observing a rather odd behavior which I believe could be a bug in the Homematic Binding.
Setting:
I got the HM-Sen-Wa-Od cistern fill level sensor (ELV Elektronik) working flawlessly. Every ~20 minutes it sends the fill level of my water cistern.
Overall I have 20+ Homematic IP-devices, and all of them update, next to their “main” values, certain service values, such as RSSI, Unreach, Lowbat, etc.
Problem description:
Now with the HM-Sen-Wa-Od, two things are odd which make me believe they might be a bug in the Homematic Binding (or a severe mis-usage by me?):
Whenever the fill level is updated every ~20 minutes, there is zero trace of this update of the fill level in the log. Maybe I misconfigured the openHAB logs, but since the log works perfectly well for all other Homematic IP-devices, maybe it has something to do with this specific device and the binding? See below an example:
Updated fill level by the sensor at 11:55 PM as seen in the openHAB graph…
… with zero entries in the log around that time…
23:52:23.439 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Systeminfo_Memory_Used' changed from 681 to 641
23:55:25.761 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Lichtsensor_Garten_HighestIllumination' changed from 1.08 lx to 1.09 lx
23:56:26.121 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'CCU_GATEWAYEXTRAS_DutyCycle' changed from 11 to 10
What made me check the logs on this specific device in the first place was a second odd behavior: Although the fill level gets nicely updated every ~20 minutes, unlike all other Homematic-devices, the “service values” (RSSI, etc)…
… don’t get updated at the same time (but only once after initial connection of the device and then once again after three days). As said, all other Homematic IP-devices behave differently and receive an update of all service-values with every update (so to speak an update of the complete set).
Example below: The RSSI was updated only once in x days even though the fill level received an update every ~20 minutes:
Is the HM-Sen-Wa-Od device your only non HmIP device? If no what about other non HmIP devices? Do they receive updates?
It it is the only non HmIP device, you should check whether the port 2001 is blocked on the openHAB side?
Let me explain how the binding works: when the binding is initialized it asks the CCU to send all current values (including RSSI values) to the binding. After that the binding waits for the CCU to send values updates as events. That means it depends on the CCU when new values are sent. HmIP and old device can behave differently.
Regarding the RSSI values it seems that the CCU does not send updates about changes automatically. Hence you have to trigger an update manually (see: Homematic - Bindings | openHAB).
That’s a good point. Did you check the events.log? Normally all events are written to this tog file. Buf if the graph is updated regularly it seems that the binding gets updates from the CCU. The event logging is done by openHAB core and not binding.
Can you elaborate where to check?
That depends on the OS and components installed on the Raspberry. You can try ufw if it is installed or iptables -L.
… while the events.log (against my initial observation) actually does contain entries…
… but only when the value changed (see below: last update for today at 12:40 pm, which is also the time when the value reached 100% and stayed there).
Or, the other way round, the events.log only contains changed values…
… while the openHAB graph contains all values (even if they did not change)
2022-02-26 23:32:48.547 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 100 % to 98 %
2022-02-26 23:50:34.339 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 98 % to 97 %
2022-02-27 00:05:52.399 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 97 % to 96 %
2022-02-27 00:26:54.226 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 96 % to 97 %
2022-02-27 01:34:57.177 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 97 % to 98 %
2022-02-27 02:15:12.290 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 98 % to 97 %
2022-02-27 02:48:43.394 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 97 % to 98 %
2022-02-27 04:44:11.252 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 98 % to 97 %
2022-02-27 05:03:22.038 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 97 % to 99 %
2022-02-27 05:20:41.586 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 98 %
2022-02-27 05:36:21.393 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 98 % to 99 %
2022-02-27 05:57:56.465 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 98 %
2022-02-27 06:16:52.259 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 98 % to 99 %
2022-02-27 07:49:29.798 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 100 %
2022-02-27 08:06:37.081 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 100 % to 99 %
2022-02-27 08:22:02.887 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 100 %
2022-02-27 08:43:16.959 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 100 % to 99 %
2022-02-27 09:03:00.758 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 100 %
2022-02-27 09:20:02.832 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 100 % to 99 %
2022-02-27 09:56:19.943 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 100 %
2022-02-27 11:46:17.772 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 100 % to 99 %
2022-02-27 12:40:57.410 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from 99 % to 100 %
So this part appears at least consistent (though different in behavior compared to the HmIP-devices), but does not explain why all other variables were only transmitted once (when setting up the devices, see bellw):
2022-02-15 23:49:06.718 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_LowBattery' changed from NULL to OFF
2022-02-15 23:49:06.741 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_Firmware' changed from NULL to 1.3
2022-02-15 23:49:06.982 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_SignalStrength' changed from NULL to 3
2022-02-15 23:49:07.001 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_UpdatePending' changed from NULL to OFF
2022-02-15 23:49:07.005 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_RssiPeer' changed from NULL to -69
2022-02-15 23:49:07.011 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_Unreach' changed from NULL to OFF
2022-02-15 23:49:07.019 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_RssiDevice' changed from NULL to 0
2022-02-15 23:49:07.022 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_Rssi' changed from NULL to -69
2022-02-15 23:49:07.320 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_DeleteDeviceMode' changed from NULL to LOCKED
2022-02-15 23:49:07.333 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_DeleteDevice' changed from NULL to OFF
2022-02-15 23:49:07.489 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_ConfigPending' changed from NULL to OFF
2022-02-15 23:49:07.493 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_BatteryType' changed from NULL to 3x AA/Mignon/LR06
2022-02-15 23:49:07.504 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_DeviceInBootloader' changed from NULL to OFF
2022-02-15 23:49:07.509 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_StickyUnreach' changed from NULL to OFF
2022-02-15 23:49:07.643 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_FillingLevel' changed from NULL to 0 %
2022-02-15 23:49:07.677 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zisterne_Fuellstandssensor_InstallTest' changed from NULL to OFF
I’m running openHAB on Docker / Raspi OS. This is what iptables -L reads, in case someone can read from this whether the problem arises from a blocked 2001-port.
sudo iptables -L
Chain INPUT (policy ACCEPT)
target prot opt source destination
Chain FORWARD (policy DROP)
target prot opt source destination
DOCKER-USER all -- anywhere anywhere
DOCKER-ISOLATION-STAGE-1 all -- anywhere anywhere
ACCEPT all -- anywhere anywhere ctstate RELATED,ESTABLISHED
DOCKER all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere ctstate RELATED,ESTABLISHED
DOCKER all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere ctstate RELATED,ESTABLISHED
DOCKER all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere ctstate RELATED,ESTABLISHED
DOCKER all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere ctstate RELATED,ESTABLISHED
DOCKER all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere ctstate RELATED,ESTABLISHED
DOCKER all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
ACCEPT all -- anywhere anywhere
Chain OUTPUT (policy ACCEPT)
target prot opt source destination
Chain DOCKER (6 references)
target prot opt source destination
ACCEPT tcp -- anywhere 172.26.0.2 tcp dpt:microsoft-ds
ACCEPT tcp -- anywhere 172.27.0.2 tcp dpt:8883
ACCEPT tcp -- anywhere 172.20.0.2 tcp dpt:9001
ACCEPT tcp -- anywhere 172.27.0.2 tcp dpt:1883
ACCEPT tcp -- anywhere 172.26.0.2 tcp dpt:netbios-ssn
ACCEPT udp -- anywhere 172.26.0.2 udp dpt:netbios-dgm
ACCEPT udp -- anywhere 172.26.0.2 udp dpt:netbios-ns
ACCEPT tcp -- anywhere 172.27.0.4 tcp dpt:8086
ACCEPT tcp -- anywhere 172.27.0.3 tcp dpt:3000
ACCEPT tcp -- anywhere 172.17.0.2 tcp dpt:9000
ACCEPT tcp -- anywhere 172.17.0.2 tcp dpt:8000
ACCEPT tcp -- anywhere 172.19.0.2 tcp dpt:8200
Chain DOCKER-ISOLATION-STAGE-1 (1 references)
target prot opt source destination
DOCKER-ISOLATION-STAGE-2 all -- anywhere anywhere
DOCKER-ISOLATION-STAGE-2 all -- anywhere anywhere
DOCKER-ISOLATION-STAGE-2 all -- anywhere anywhere
DOCKER-ISOLATION-STAGE-2 all -- anywhere anywhere
DOCKER-ISOLATION-STAGE-2 all -- anywhere anywhere
DROP all -- !172.28.0.0/16 anywhere
DROP all -- anywhere !172.28.0.0/16
DOCKER-ISOLATION-STAGE-2 all -- anywhere anywhere
RETURN all -- anywhere anywhere
Chain DOCKER-ISOLATION-STAGE-2 (6 references)
target prot opt source destination
DROP all -- anywhere anywhere
DROP all -- anywhere anywhere
DROP all -- anywhere anywhere
DROP all -- anywhere anywhere
DROP all -- anywhere anywhere
DROP all -- anywhere anywhere
RETURN all -- anywhere anywhere
Chain DOCKER-USER (1 references)
target prot opt source destination
RETURN all -- anywhere anywhere
That make sense in order to reduce the number of log entries. This is handle by openHAB Core and not by the binding.
As I already mentioned the RSSI values are not automatically sent from the CCU.
All other values won’t change that often and there will only be events from the CCU if they really change.
If you think that there is something missing even if the value has changed, please enable DEBUG logging, provoke a change and check the openhab.log whether there are any information about an event received from the CCU.
BTW: if OH is running within a docker container you must make sure that all necessary ports are mapped. You should also set an IP address for the callback address in the bridge configuration to make sure that the correct address is used.
There are lots of hints. Looking at my skillset, this will probably take me some time to look into.
Fun fact: Today was the second and third time in one week that the RSSI value got updated while (as said), the fill level gets nicely updated every 20 minutes.
