Is Innogy binding 2.5.0 working?

ruperts · July 7, 2019, 12:43pm

Hello,

I am using OpenHAB Version 2.5.0.M1 and innogy SmartHome Binding (binding-innogysmarthome - 2.5.0.M1). Since July 3rd, around 10am it stopped working with error messages like this (repeated every 30 seconds):

2019-07-03 09:56:43.559 [ERROR] [gysmarthome.internal.InnogyWebSocket] - innogy WebSocket onError() - null
2019-07-03 09:56:43.565 [INFO ] [gysmarthome.internal.InnogyWebSocket] - Connection to innogy Webservice was closed abnormally (code: 1006). Reason: WebSocket Read EOF
2019-07-03 09:57:17.627 [ERROR] [internal.handler.InnogyBridgeHandler] - Error starting device structure manager.
java.lang.NullPointerException: null
	at org.openhab.binding.innogysmarthome.internal.client.entity.device.Device.setReachable(Device.java:417) ~[209:org.openhab.binding.innogysmarthome:2.5.0.M1]
	at org.openhab.binding.innogysmarthome.internal.client.entity.device.Device.setMessageList(Device.java:407) ~[209:org.openhab.binding.innogysmarthome:2.5.0.M1]
	at org.openhab.binding.innogysmarthome.internal.client.InnogyClient.getFullDevices(InnogyClient.java:660) ~[209:org.openhab.binding.innogysmarthome:2.5.0.M1]
	at org.openhab.binding.innogysmarthome.internal.manager.DeviceStructureManager.refreshDevices(DeviceStructureManager.java:90) ~[209:org.openhab.binding.innogysmarthome:2.5.0.M1]
	at org.openhab.binding.innogysmarthome.internal.manager.DeviceStructureManager.start(DeviceStructureManager.java:69) ~[209:org.openhab.binding.innogysmarthome:2.5.0.M1]
	at org.openhab.binding.innogysmarthome.internal.handler.InnogyBridgeHandler$Initializer.run(InnogyBridgeHandler.java:132) [209:org.openhab.binding.innogysmarthome:2.5.0.M1]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

I tried restarting OpenHAB service, reinstalling the binding, or removing the thing “innogy SmartHome Controller” numerous times without success. In Paper UI the SHC is reported to be online, but all other things like RST, WDS, or ISR2 remain UNINITIALIZED - BRIDGE_UNINITIALIZED.

The last logs are

==> events.log <==
2019-07-07 14:11:14.457 [thome.event.ExtensionEvent] - Extension 'binding-innogysmarthome' has been installed.
2019-07-07 14:11:14.654 [hingStatusInfoChangedEvent] - 'innogysmarthome:RST:079e8c03:8f35af1e04484747a7a085420f2ef31e' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.663 [hingStatusInfoChangedEvent] - 'innogysmarthome:RST:079e8c03:b202521bd0ca4e02a4f3d65020f68540' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.669 [hingStatusInfoChangedEvent] - 'innogysmarthome:ISR2:079e8c03:452bb214d5b34d26bb9677af4bf3b505' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.672 [hingStatusInfoChangedEvent] - 'innogysmarthome:ISR2:079e8c03:1331b3ef22bb41d78ca1e17caf916a44' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.694 [hingStatusInfoChangedEvent] - 'innogysmarthome:ISR2:079e8c03:463bedf3f3214b758139c7fd1fef16dd' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.705 [hingStatusInfoChangedEvent] - 'innogysmarthome:WDS:079e8c03:962b8c22d8f7420e90f60bdd4deb5236' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.710 [hingStatusInfoChangedEvent] - 'innogysmarthome:VariableActuator:079e8c03:6cf838ba021b4ea5931d504a9c2eb0af' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.716 [hingStatusInfoChangedEvent] - 'innogysmarthome:WDS:079e8c03:1515dab865b04249b4a7adc2e951edd2' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.720 [hingStatusInfoChangedEvent] - 'innogysmarthome:WDS:079e8c03:aade34d8911d483095cad344b3e30573' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.726 [hingStatusInfoChangedEvent] - 'innogysmarthome:WDS:079e8c03:85ff74d948ff4c0ca0f832d450d9b4fe' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.732 [hingStatusInfoChangedEvent] - 'innogysmarthome:RST:079e8c03:bea9969a49ef40c99444035e38293462' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.739 [hingStatusInfoChangedEvent] - 'innogysmarthome:RST:079e8c03:183c1149a6fd407493e179bc54592f83' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.746 [hingStatusInfoChangedEvent] - 'innogysmarthome:ISS2:079e8c03:26673bf4d6a947639e887db3a554fcfa' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
2019-07-07 14:11:14.756 [hingStatusInfoChangedEvent] - 'innogysmarthome:bridge:SMARTHOME04' changed from UNINITIALIZED to INITIALIZING
2019-07-07 14:11:16.415 [me.event.ThingUpdatedEvent] - Thing 'innogysmarthome:bridge:SMARTHOME04' has been updated.
2019-07-07 14:11:19.315 [hingStatusInfoChangedEvent] - 'innogysmarthome:bridge:SMARTHOME04' changed from INITIALIZING to ONLINE

==> openhab.log <==
2019-07-07 14:11:20.327 [INFO ] [gysmarthome.internal.InnogyWebSocket] - Connected to innogy Webservice.

Is API 1.0 shut down by Innogy? See Innogy on Openhab 2.5 build #1577 throwing exceptions.

Thanks & Best regards
Rupert

weakfl · July 7, 2019, 1:23pm

Did you accept the new TOS?

ruperts · July 7, 2019, 2:07pm

Yes – I think. At least https://home.innogy-smarthome.de is working flawlessly…

oliver_kuhl · July 7, 2019, 8:33pm

API 1.0 is still running, so this cannot be the case. Good to know, that you already accepted new TOS, which could also be the reason.

Please check if you have the correct brand selected in the SHC Thing configuration. I heard innogy removed the other brands like start-smarthome etc.

If the error still occurs, please change the loglevel to DEBUG and post the logs arround the error. Thanks!

ruperts · July 8, 2019, 8:16pm

Thank you, Ollie, for the tip to increase the log level! It tells me that events are transmitted from innogy server to my openHAB:

2019-07-08 21:36:52.453 [DEBUG] [penhab.binding.innogysmarthome.internal.manager.DeviceStructureManager] - Devices loaded. Device structure manager ready.
2019-07-08 21:36:52.474 [DEBUG] [g.openhab.binding.innogysmarthome.internal.handler.InnogyBridgeHandler] - WebSocket URL: wss://api.services-smarthome.de/API/1.0/events?token=eyJ0eXAiOiJKV1QiL...YHDVcuwcOQ
2019-07-08 21:36:52.482 [DEBUG] [g.openhab.binding.innogysmarthome.internal.handler.InnogyBridgeHandler] - Starting innogy websocket.
2019-07-08 21:36:52.538 [DEBUG] [org.openhab.binding.innogysmarthome.internal.InnogyWebSocket          ] - Connecting to innogy WebSocket...
2019-07-08 21:36:52.831 [INFO ] [org.openhab.binding.innogysmarthome.internal.InnogyWebSocket          ] - Connected to innogy Webservice.
2019-07-08 21:38:15.378 [DEBUG] [org.openhab.binding.innogysmarthome.internal.InnogyWebSocket          ] - innogy WebSocket onMessage() - [{"type":"device/SHC.RWE/1.0/event/MessageStateChanged","timestamp":"2019-07-08T19:38:12.5370000Z","desc":"/desc/device/SHC.RWE/1.0/event/MessageStateChanged","link":{"value":"/message/7ae50be9c93846d18b2245b655ee6fc8"},"Properties":[{"name":"State","value":"Read"}]}]
2019-07-08 21:38:15.413 [DEBUG] [g.openhab.binding.innogysmarthome.internal.handler.InnogyBridgeHandler] - Event found: Type:device/SHC.RWE/1.0/event/MessageStateChanged Capability:/message/7ae50be9c93846d18b2245b655ee6fc8
2019-07-08 21:38:15.416 [DEBUG] [g.openhab.binding.innogysmarthome.internal.handler.InnogyBridgeHandler] - Unknown eventtype device/SHC.RWE/1.0/event/MessageStateChanged.

Checking my configuration in PaperUI and wondering why the thing innogy SmartHome Controller (SMARTHOME04) is reported with status ONLINE whereas all other innogy things like RST, WDS etc remain in status UNINITIALIZED - BRIDGE_UNINITIALIZED, I suddenly realized that I have to manually select the bridge for each of them… Silly me!
During initial setup, all things popped up automatically in the inbox. But as I uninstalled and reinstalled the binding multiple times, they obviously lost connection…

Again what learned. Maybe it helps others.

ruperts · August 25, 2019, 2:00pm

New finding, after the bridge keeps getting offline every now and then: The root cause seems to be the Smart Home Controller. If I give it a power-on reset, the bridge connection will be restored immediately without any other action. I’ll tell the Innogy guys.

I have a version 1 controller, old RWE brand.