It is still running, and most parts are working. However, I am having problems with some devices (slow response, not always triggering etc.) and just started to analyze the problem. However, the network looks strange to me.
Chris told somewhere else that the Network viewer is not completely reliable at the moment. You can see this, because according to your screenshot there is NO connection to the controller (“1”). So when you believe in the viewer, nothing should run.
But as there are other problems, something seems to be wrong.
Are the problems related to zwave only? Or do other bindings also make problems?
11:59:35.950 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing sonos:PLAY1:RINCON_XXXXXXX takes more than 5000ms for processing event
11:59:35.950 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.thing.internal.ThingManager@641337’ takes more than 5000ms.
11:59:35.950 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.thing.internal.ThingManager@641337’ takes more than 5000ms.
Sorry, but I’ve no idea why these messages do appear. Maybe the binding developer has a suggestion. But I’m sure he will ask for a DEBUG log. So you can grab this already and then upload it here.
This is what I get when a Z-Wave device is initialized:
22:22:04.651 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.IllegalStateException: Could not update status, because callback is missing
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:388)[105:org.eclipse.smarthome.core.thing:0.9.0.b3]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:415)[105:org.eclipse.smarthome.core.thing:0.9.0.b3]
at org.openhab.binding.zwave.handler.ZWaveThingHandler.ZWaveIncomingEvent(ZWaveThingHandler.java:1178)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:1117)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1306)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingResponseMessage(ZWaveController.java:293)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:217)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208)[209:org.openhab.binding.zwave:2.0.0.RC1]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324)[209:org.openhab.binding.zwave:2.0.0.RC1]
22:22:04.736 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:device:159ae42df3e:node14’ changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
22:22:04.747 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:device:159ae42df3e:node14’ changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
22:22:04.747 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing ‘zwave:device:159ae42df3e:node14’ has been updated.
22:22:04.755 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Initialising Thing Node…
22:22:04.755 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:device:159ae42df3e:node14’ changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
22:22:09.510 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
22:22:52.669 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:device:159ae42df3e:node14’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline
22:22:52.674 [INFO ] [me.event.ThingStatusInfoChangedEvent] - ‘zwave:device:159ae42df3e:node14’ changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
22:22:52.698 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Initialising Thing Node…
22:22:52.699 [INFO ] [marthome.event.ConfigStatusInfoEvent] - ConfigStatusInfo [configStatusMessages=]
22:22:52.700 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing ‘zwave:device:159ae42df3e:node14’ has been updated.
22:22:52.735 [INFO ] [smarthome.event.ThingUpdatedEvent ] - Thing ‘zwave:device:159ae42df3e:node14’ has been updated.
At OH2 startup I am also seeing:
Controller handler not found. Cannot handle command without ZWave controller.
This is strange. My Z-Wave network used to work well. @chris, do you have any idea? In case you need it, I am having a DEBUG log from OH2 startup (4.5k lines )
Is this using the latest version of everything (i.e. the latest runtime) or just the current zwave binding with an older runtime? The callback must have been set at some stage since we set the state to offline right at the beginning of the thing initialisation and this call is well after that as here we’re setting up. @kai - any thoughts on why the callback would now be missing? Nothing has changed in the binding for a little while now.
If I can download your debug file I’ll take a look - unfortunately internet is very poor where I am tonight
Only in ThingManager.doUnregisterHandler(). Looking through the code, I notice that this happens (shortly) before dispose() is called on the handler - so there is indeed the risk of a bad timing that the handler does not yet know that it is about to be disposed. But in any case, this situation should not be too critical as it would happen during handler unregistration only and never during normal “operation time”.
This is something completely different - I’d prefer not to confuse things as timeouts are more routine (depending on exactly why they happen).
What happens if we change thing type, or update configuration. Doesn’t this destroy the thing, and then create it again? I would say this is “normal operation” and it shouldn’t cause an exception? Maybe I need to catch this exception better in the binding, but I think there must be something wrong in the framework for it to happen at all?
@kai, so I think that this is what is happening -:
14:43:15.512 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveInitializationStateEvent
14:43:15.532 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 4: Serializing to file /var/lib/openhab2/zwave/node4.xml
14:43:15.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Updating node properties. Controller not found.
14:43:15.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Setting ONLINE
14:43:15.612 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread
java.lang.IllegalStateException: Could not update status, because callback is missing
From the above, I see that there is a single event from the ZWave protocol layers. The “Serializing” message indicates that the thing dispose is being called - as does the following NODE 0: messages since nodeId is only set to 0 in the dispose method.
The code is -:
case DONE:
// Update some properties first...
updateNodeNeighbours();
updateNodeProperties();
// Do we need to change type?
if (finalTypeSet == false) {
updateThingType();
}
// Set ourselves online if we have the final thing type set
if (finalTypeSet) {
logger.debug("NODE {}: Setting ONLINE", nodeId);
updateStatus(ThingStatus.ONLINE);
// Now that this node is completely initialised, we want to re-process all channels
initialiseNode();
}
break;
The exception occurs at the updateStatus toward the bottom, so from this I assume that the thing type is changing (in the call to updateThingType), dispose is being called at this point and we’re then updating the status.
I could possibly reorder some of this code to (hopefully) solve it, but I wonder if the framework shouldn’t defer the dispose call (somehow)?
)