[homematic] homematic RF devices not found after openhab 3.1.0 upgrade

[brainbug95]

Expected Behavior

After the upgrade all previously configured and working homematic RF devices should be operational.

Current Behavior

All homematic RF devices are showing "COMM:ERROR" on the main UI. Homematic RF devices are bound to a Homegear bridge as opposed to HMIP-Devices which are connected to the CCU2 bridge and work fine.

I attached openhab.log with the openhab binding set to DEBUG. I cleared out some irrelevant stuff. The log also shows a nullpointer exception which might be relevant.

openhab-3.1-clean-cache-debug-homematic.log

Steps to Reproduce (for Bugs)

1. systemctl stop openhab
2. openhab-cli clean-cache
3. update openhab via package-manager apt
4. systemctl start openhab

Your Environment

• Version used: openhab 3.1.0 form debian repositiory
• Homematic Bridge: Homegear latest 0.8 build on localhost with HMLGW ID: aa7e5585
• HomematicIP Bridge: CCU2 ID: CCU2
• Operating System and version: Debian 10 aka buster.
• Java: Azul Zulu 11.48+21 (11.0.11-b9)

[MHerbst]

Thanks for providing the log. I am now a bit confused because the log output does not match the implementation. There should be a debug message right before the exception message.

[brainbug95]

@MHerbst

I took a new log from openhab startup. This was taken after the Upgrade from 3.0.2 to 3.1.0 with "org.openhab.binding.homematic:3.2.0.202107011418". This time it is not only the openhab.log but a the combined output of "openhab-cli showlogs" command. I added <Logger level="DEBUG" name="org.openhab.binding.homematic"/> to log4j2.xml before starting up openhab - the rest of the logging is distribution default.

openhab-3.1-debug-homematic.log

I noticed a weird thing. Previously I said all of my Homematic RF devices are failing with Device with address 'DEVICEID' not found on gateway 'aa7e5585' - aa7e5585 is the homegear gateway. That was and is not true. A few of them are working.

Here is an example of a device of the same type "homematic:HG-HM-TC-IT-WM-W-EU" which I have three times. One is working, the others are not.

2021-07-11 10:14:08.991 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:OEQ1676984' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED) 2021-07-11 10:14:09.065 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:MEQ0235668' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED) 2021-07-11 10:14:09.129 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED) 2021-07-11 10:14:11.077 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:MEQ0235668' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING 2021-07-11 10:14:11.082 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:MEQ0235668' changed from INITIALIZING to OFFLINE (CONFIGURATION_ERROR): Device with address 'MEQ0235668' not found on gateway 'aa7e5585' 2021-07-11 10:14:11.284 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING 2021-07-11 10:14:11.367 [DEBUG] [ternal.handler.HomematicThingHandler] - Initializing thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030' from gateway 'aa7e5585' 2021-07-11 10:14:11.367 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030' changed from INITIALIZING to ONLINE 2021-07-11 10:14:11.829 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:OEQ1676984' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING 2021-07-11 10:14:12.234 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:0#LOWBAT' from thing id 'PEQ0030030' 2021-07-11 10:14:12.241 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#BATTERY_STATE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.289 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#AUTO_MODE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.291 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#ACTUAL_HUMIDITY' from thing id 'PEQ0030030' 2021-07-11 10:14:12.299 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#MANU_MODE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.321 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#COMFORT_MODE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.330 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#SET_TEMPERATURE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.341 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#CONTROL_MODE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.356 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#LOWERING_MODE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.361 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#BOOST_MODE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.379 [DEBUG] [ternal.handler.HomematicThingHandler] - Updating channel 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:PEQ0030030:2#ACTUAL_TEMPERATURE' from thing id 'PEQ0030030' 2021-07-11 10:14:12.422 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HG-HM-TC-IT-WM-W-EU:aa7e5585:OEQ1676984' changed from INITIALIZING to OFFLINE (CONFIGURATION_ERROR): Device with address 'OEQ1676984' not found on gateway 'aa7e5585'

I still do not see a Debug message around the NPE.

[MHerbst]

@brainbug95 Thank you for the detailed log output. I think, I have found the reason for the exception. It is probably caused by the "OpenWeatherMap" device. For this device an internal variable is not set and this causes the exception because of some necessary refactorings for version 3.1 of the binding.

I have uploaded a new test version here: https://github.com/MHerbst/openhab-addons-test

[brainbug95]

@MHerbst thanks for this fix. I installed OH3.1 and used your patched Homematic binding and it works so far. I will leave it running for now and see if more issues pop up in the future. I consider the issue closed if that's fine with you?

[MHerbst]

@brainbug95 Thanks for you feedback. The issue will be automatically closed when the fixed code is merged into the OH codebase.