Handler takes more than 5000ms for processing event

[philKrylc (Phil)]

Hi everybody,

after upgrading from an OH2 RC1 to OH2 final I got a lot of errors regarding the handlers in my OH2 configuration. I have never seen these erros before. I was not able to solve the problem so I decided to re-install and configure my entire OH2 environment. Now, all of I sudden, I see those errors in the log again.

As I cannot start from scratch this time, I need to figure out how to solve this.

21:51:32.908 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'zwave:device:159dc840d04:node5' takes more than 5000ms for processing event
21:51:32.908 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1167148' takes more than 5000ms.
21:51:32.913 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1167148' takes more than 5000ms.
21:51:32.914 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'sonos:PLAY1:RINCON_5CAAFD40CDFE01400' takes more than 5000ms for processing event

In practice, things are responding very slowly to commands.

Does anyone have an idea on how to solve this or how to trace this?

Any help is appreciated. Thanks a lot in advance!

[Kai (Kai Kreuzer)]

In general, this points to bad handler implementations in some bindings.
Do you see this now for any binding that you use or only for Z-Wave and Sonos? Does it happen for ANY command or just in specific cases?
You could try to activate debug logging for those bindings and see if this provides any clue what takes so long:

log:set DEBUG org.openhab.binding.zwave
log:set DEBUG org.eclipse.smarthome.binding.sonos

[philKrylc (Phil)]

Thanks for the info!
I don’t see this for any binding. Right now “only” for Sonos and Z-Wave. I enabled debug logs for both and will update this post as soon as I have additional (log) information.

As far as I can see, this happens when commands are triggered in rules. However, these rules used to work fine for some month.

Edit:
It seems like sonos does not really log in debug mode.
I tried to improve my network configuration and the rule that I am using. However, it seems like processing this rule (or the events) is not really efficient - here is an example:

The rule is used to turn on music and ventilation, when the light in bathroom is turned on:

rule “BATHROOM: Turning devices ON based current setting”
when
Item ZW_DRS1_Switch changed to ON
then
logDebug(“bathroom_automation”, “Bathroom light switched to: " +ZW_DRS1_Switch.state +” - starting evaluation and executing commands to turn ON devices")

// Bathroom Music:
logDebug(“bathroom_automation”, “Bathroom music: Checking setting state and starting music …”)
if(Set_Bathroom_LightMusic.state == ON) {
logDebug(“bathroom_automation”, “Lights turned ON and setting ON - starting music.”)
sendCommand(Sonos_PLAY11_Control, PLAY)
}
// Bathroom Ventilation:
logDebug(“bathroom_automation”, “Bathroom ventilation: Checking setting state and starting ventilation …”)
if(Set_Bathroom_LightVentilation.state == ON) {
logDebug(“bathroom_automation”, “Lights turned ON and setting ON - starting ventilation.”)
sendCommand(ZW_DRS1_Switch2, ON)
}
end

And here is what is logged when bathroom light is turned on:

13:51:54.432 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 25 03 FF 2D 
13:51:54.437 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
13:51:54.439 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 05 03 25 03 FF 2D 
13:51:54.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 05 03 25 03 FF 2D 
13:51:54.442 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 03 25 03 FF 
13:51:54.443 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
13:51:54.444 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
13:51:54.445 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1350496 already registered
13:51:54.446 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class SWITCH_BINARY
13:51:54.448 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 5
13:51:54.449 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Switch Binary report, value = 255
13:51:54.450 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
13:51:54.451 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
13:51:54.453 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255
13:51:54.456 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:159dc840d04:node5:switch_binary to ON [OnOffType]
13:51:54.468 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_DRS1_Switch changed from OFF to ON
13:51:54.470 [INFO ] [ome.event.GroupItemStateChangedEvent] - Bathroom_Lights changed from OFF to ON through ZW_DRS1_Switch
13:51:54.472 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
13:51:54.478 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 07 0A 71 05 07 FF 00 FF 07 08 00 00 9A 
13:51:54.488 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
13:51:54.490 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 07 0A 71 05 07 FF 00 FF 07 08 00 00 9A 
13:51:54.492 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 07 0A 71 05 07 FF 00 FF 07 08 00 00 9A 
13:51:54.494 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 07 0A 71 05 07 FF 00 FF 07 08 00 00 
13:51:54.495 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Application Command Request (ALIVE:DETAILS)
13:51:54.496 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Incoming command class ALARM
13:51:54.497 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Received ALARM command V4
13:51:54.498 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Process NOTIFICATION_REPORT V4
13:51:54.499 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: NOTIFICATION report - 7 = 255, event=8, status=255
13:51:54.500 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Alarm Type = BURGLAR (7)
13:51:54.505 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent
13:51:54.511 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveAlarmValueEvent
13:51:54.516 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got a value event from Z-Wave network, endpoint = 0, command class = ALARM, value = 255
13:51:54.522 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
13:51:54.527 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 8, type OnOffType
13:51:54.532 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating channel state zwave:device:159dc840d04:node7:alarm_burglar to ON [OnOffType]
13:51:54.538 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
13:51:54.564 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 25 03 FF 2D 
13:51:54.569 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
13:51:54.573 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 05 03 25 03 FF 2D 
13:51:54.577 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 05 03 25 03 FF 2D 
13:51:54.580 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 03 25 03 FF 
13:51:54.583 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
13:51:54.586 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
13:51:54.590 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1350496 already registered
13:51:54.593 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class SWITCH_BINARY
13:51:54.596 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 5
13:51:54.599 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Switch Binary report, value = 255
13:51:54.603 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
13:51:54.607 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
13:51:54.610 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255
13:51:54.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:159dc840d04:node5:switch_binary to ON [OnOffType]
13:51:54.618 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 4: Transaction not completed: node address inconsistent.  lastSent=4, incoming=255
13:51:57.567 [DEBUG] [ome.model.script.bathroom_automation] - Bathroom light switched to: ON - starting evaluation and executing commands to turn ON devices
13:51:57.569 [DEBUG] [ome.model.script.bathroom_automation] - Bathroom music: Checking setting state and starting music ...
13:51:57.574 [DEBUG] [ome.model.script.bathroom_automation] - Lights turned ON and setting ON - starting music.
13:51:57.578 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Sonos_PLAY11_Control' received command PLAY

After updating the channel with

NODE 5: Updating channel state zwave:device:159dc840d04:node5:switch_binary to ON [OnOffType]

almost 3 seconds are lost until the rule executing starts. Finally, the rule execution is quick.

[chris (Chris Jackson)]

@philKrylc are you sure that this rule is sending a ZWave command? In the ZWave binding, the very first line of the handleCommand method is -:

    @Override
    public void handleCommand(ChannelUID channelUID, Command command) {
        logger.debug("NODE {}: Command received {} --> {}", nodeId, channelUID, command);

and I don’t see this message being logged so I don’t think it’s calling the zwave command handler. Can you provide a log that shows this please? Maybe it’s a little further down the log?

[staehler67 (Michael)]

I have a similar problem. In general a fritzbox rule (tr064) which worked fine on OH1, doesn’t work in OH2 - you find the rule in this post. This error appeared after getting a phone call:

2017-02-07 06:41:41.346 [INFO ] [tzboxtr064.internal.PhonebookManager] - 
Trying to resolve number xxxxxx to name comparing 7 characters
2017-02-07 06:41:41.367 [INFO ] [tzboxtr064.internal.PhonebookManager] - 
found name match yyyy in phonebook by comparing 
6843064375194+ with 6843064
2017-02-07 06:41:42.090 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@1453c2a' 
takes more than 5000ms.
2017-02-07 06:41:42.090 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@ed7506' 
takes more than 5000ms.
2017-02-07 06:41:47.093 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.monitor.internal.EventLogger@6a0537' takes 
more than 5000ms.
2017-02-07 06:41:47.093 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.io.myopenhab.internal.MyOpenHABService@1f3ccb3' takes more 
than 5000ms.
2017-02-07 06:41:52.095 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.core.events.internal.EventBridge@1a4825a' takes more than 
5000ms.
2017-02-07 06:41:52.095 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.internal.items.ItemUpdater@b53714' takes 
more than 5000ms.
2017-02-07 06:41:57.099 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@494697' 
takes more than 5000ms.
2017-02-07 06:41:57.099 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.thing.internal.ThingManager@1f55a04' takes 
more than 5000ms.
2017-02-07 06:42:02.195 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@1453c2a' 
takes more than 5000ms.
2017-02-07 06:42:02.198 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@ed7506' 
takes more than 5000ms.
2017-02-07 06:42:07.202 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.io.myopenhab.internal.MyOpenHABService@1f3ccb3' takes more 
than 5000ms.
2017-02-07 06:42:07.204 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.monitor.internal.EventLogger@6a0537' takes 
more than 5000ms.
2017-02-07 06:42:12.204 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.internal.items.ItemUpdater@b53714' takes 
more than 5000ms.
2017-02-07 06:42:12.209 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.core.events.internal.EventBridge@1a4825a' takes more than 
5000ms.
2017-02-07 06:42:17.209 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.thing.internal.ThingManager@1f55a04' takes 
more than 5000ms.
2017-02-07 06:42:17.211 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@494697' 
takes more than 5000ms.
2017-02-07 06:42:22.211 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@ed7506' 
takes more than 5000ms.
2017-02-07 06:42:22.215 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@1453c2a' 
takes more than 5000ms.
2017-02-07 06:42:27.213 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.monitor.internal.EventLogger@6a0537' takes 
more than 5000ms.
2017-02-07 06:42:27.218 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.io.myopenhab.internal.MyOpenHABService@1f3ccb3' takes more 
than 5000ms.
2017-02-07 06:42:32.221 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.core.events.internal.EventBridge@1a4825a' takes more than 
5000ms.
2017-02-07 06:42:32.222 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.internal.items.ItemUpdater@b53714' takes 
more than 5000ms.
2017-02-07 06:42:37.225 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@494697' 
takes more than 5000ms.
2017-02-07 06:42:37.225 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.thing.internal.ThingManager@1f55a04' takes 
more than 5000ms.
2017-02-07 06:42:42.231 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@1453c2a' 
takes more than 5000ms.
2017-02-07 06:42:42.231 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@ed7506' 
takes more than 5000ms.
2017-02-07 06:42:47.236 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.io.myopenhab.internal.MyOpenHABService@1f3ccb3' takes more 
than 5000ms.
2017-02-07 06:42:47.236 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.monitor.internal.EventLogger@6a0537' takes 
more than 5000ms.
2017-02-07 06:42:52.242 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.internal.items.ItemUpdater@b53714' takes 
more than 5000ms.
2017-02-07 06:42:52.243 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.core.events.internal.EventBridge@1a4825a' takes more than 
5000ms.
2017-02-07 06:42:57.249 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.thing.internal.ThingManager@1f55a04' takes 
more than 5000ms.
2017-02-07 06:42:57.250 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@494697' 
takes more than 5000ms.
2017-02-07 06:43:02.251 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.autoupdate.internal.AutoUpdateBinding@ed7506' 
takes more than 5000ms.
2017-02-07 06:43:02.253 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl@1453c2a' 
takes more than 5000ms.
2017-02-07 06:43:07.253 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.monitor.internal.EventLogger@6a0537' takes 
more than 5000ms.
2017-02-07 06:43:07.258 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.io.myopenhab.internal.MyOpenHABService@1f3ccb3' takes more 
than 5000ms.
2017-02-07 06:43:12.255 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.openhab.core.events.internal.EventBridge@1a4825a' takes more than 
5000ms.
2017-02-07 06:43:12.260 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.internal.items.ItemUpdater@b53714' takes 
more than 5000ms.
2017-02-07 06:43:17.257 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber@494697' 
takes more than 5000ms.
2017-02-07 06:43:17.262 [WARN ] [ore.internal.events.OSGiEventManager] - 
Dispatching event to subscriber 
'org.eclipse.smarthome.core.thing.internal.ThingManager@1f55a04' takes 
more than 5000ms.

The related items get updated, so the tr064 binding works so far. But my rule, which should trigger on this, doesn’t work. I’m not sure, if the above mentioned errors relate to the misbehaviour of the rule, but regarding to the log it seems so.
During this approx. 90 seconds, it seems no rule is processed and no events are logged.

What do you recommend to dig deeper? It should be mentioned, that I’m not quite familiar with OH2, as I migrated 3 days before from OH1. At the moment, I have both installations and my productive installation is still OH1.

[Kai (Kai Kreuzer)]

Might this rule be long-running, e.g. having issues doing the Xbmc notification or the HTTP request and running into a timeout?

[staehler67 (Michael)]

Hi Kai,
Some things changed with the tr064 CallType, I found your hint in this treat, which fixed my issue:

FritzBox TR064 Binding - Creation of ESH-Event failed

CallType does not exist anymore, you will have to adapt your rule to StringListType instead. Without having tested it, it should be something like: val incCall = fboxIncomingCallResolved.state as StringListType val callerNumber = incCall.getValue(0) I have created https://github.com/openhab/openhab/pull/4858, which adds the binding to the distro as it seems to work in general. For any further issues, simply open an issue for the binding itself, so that it can be addressed.

[philKrylc (Phil)]

@chris Sure, thanks a lot for looking into this.

Here is is a little more of the debug log. This does not include the debug log entries of my rule, but the rule has not changed in the meantime.

Node 7 that we see there is not important for this case. The “trigger” is a Fibaro double relay switch (Node 5).

21:57:29.813 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 07 0A 71 05 07 FF 00 FF 07 08 00 00 9A
21:57:29.815 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
21:57:29.817 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 10 00 04 00 07 0A 71 05 07 FF 00 FF 07 08 00 00 9A
21:57:29.819 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 10 00 04 00 07 0A 71 05 07 FF 00 FF 07 08 00 00 9A
21:57:29.821 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 07 0A 71 05 07 FF 00 FF 07 08 00 00
21:57:29.822 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Application Command Request (ALIVE:DETAILS)
21:57:29.823 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 7: Incoming command class ALARM
21:57:29.824 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Received ALARM command V4
21:57:29.825 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Process NOTIFICATION_REPORT V4
21:57:29.825 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: NOTIFICATION report - 7 = 255, event=8, status=255
21:57:29.826 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Alarm Type = BURGLAR (7)
21:57:29.827 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveAlarmValueEvent
21:57:29.828 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got an event from Z-Wave network: ZWaveAlarmValueEvent
21:57:29.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Got a value event from Z-Wave network, endpoint = 0, command class = ALARM, value = 255
21:57:29.830 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter processing NOTIFICATION
21:57:29.831 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - Alarm converter NOTIFICATION event is 8, type OnOffType
21:57:29.832 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Updating channel state zwave:device:controller:node7:alarm_burglar to ON [OnOffType]
21:57:29.835 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255
21:57:35.005 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 25 03 FF 2D
21:57:35.012 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
21:57:35.014 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 05 03 25 03 FF 2D
21:57:35.017 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 05 03 25 03 FF 2D
21:57:35.019 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 03 25 03 FF
21:57:35.021 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
21:57:35.022 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
21:57:35.023 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@112f5a1 already registered
21:57:35.024 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class SWITCH_BINARY
21:57:35.026 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 5
21:57:35.027 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Switch Binary report, value = 255
21:57:35.028 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
21:57:35.029 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
21:57:35.031 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255
21:57:35.033 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:controller:node5:switch_binary to ON [OnOffType]
21:57:35.041 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 255: Transaction not completed: node address inconsistent. lastSent=255, incoming=255
21:57:35.048 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_DRS1_Switch changed from OFF to ON
21:57:35.052 [INFO ] [ome.event.GroupItemStateChangedEvent] - Bathroom_Lights changed from OFF to ON through ZW_DRS1_Switch
21:57:37.945 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘Sonos_PLAY11_Control’ received command PLAY
21:57:37.946 [INFO ] [ome.event.GroupItemStateChangedEvent] - Sonos_Controller changed from PAUSE to UNDEF through Sonos_PLAY11_Control
21:57:37.950 [INFO ] [marthome.event.ItemStateChangedEvent] - Sonos_PLAY11_Control changed from PAUSE to PLAY
21:57:37.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:controller:node5:switch_binary2 → ON
21:57:37.963 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_SET
21:57:37.964 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Encapsulating message, instance / endpoint 2
21:57:37.966 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 5: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
21:57:37.968 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
21:57:37.968 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
21:57:37.969 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘ZW_DRS1_Switch2’ received command ON
21:57:37.970 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 05 07 60 0D 01 02 25 01 FF 25 A8 D8
21:57:37.971 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0E 00 13 05 07 60 0D 01 02 25 01 FF 25 A8 D8
21:57:37.973 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_DRS1_Switch2 changed from OFF to ON
21:57:37.985 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
21:57:38.008 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
21:57:38.009 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
21:57:38.012 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
21:57:38.015 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
21:57:38.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A8 00 00 02 41
21:57:38.019 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
21:57:38.024 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
21:57:38.028 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A8 00 00 02 00 00 4F
21:57:38.032 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A8 00 00 02 00 00 4F
21:57:38.036 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A8 00 00 02
21:57:38.040 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 168, Status = Transmission complete and ACK received(0)
21:57:38.043 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
21:57:38.044 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@112f5a1 already registered
21:57:38.046 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=5, callback=168, payload=05 07 60 0D 01 02 25 01 FF
21:57:38.050 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A8 00 00 02
21:57:38.051 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=168, expected=SendData, cancelled=false transaction complete!
21:57:38.052 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
21:57:38.053 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
21:57:38.053 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 81ms/358ms.
21:57:38.500 [INFO ] [marthome.event.ItemStateChangedEvent] - Sonos_PLAY11_Control changed from PLAY to UNDEF
21:57:39.220 [INFO ] [marthome.event.ItemStateChangedEvent] - Sonos_PLAY11_Control changed from UNDEF to PLAY

[chris (Chris Jackson)]

Did this event actually cause the error?

The command handler starts here →

21:57:37.961 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:controller:node5:switch_binary2 → ON

and completes here →

21:57:37.968 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}

That’s 7ms to process the command - looks ok to me in this case at least - right?

[philKrylc (Phil)]

Not sure if this was the cause. I am currently monitoring the rule behavior and trying to make it more efficient, because I don’t know what slows down the handler processing.
Currently I am not seeing the error, everything is executed in time.

I am just wondering if the rule can influence the handler speed at all?

[chris (Chris Jackson)]

@philKrylc

I am just wondering if the rule can influence the handler speed at all?

I wouldn’t have thought so - the handler is pretty short and just queues the message. Unless something ‘bad’ is happening within the system that’s slowing down the VM or something, I wouldn’t think the rule should influence the handler…

[philKrylc (Phil)]

I just had another bunch of warnings regarding the handler in my log. I am using a fresh installation of OH2 (one day old). This time there is no rule involved. I used a group item to trigger all lights of:

15:50:42.181 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Lights' received command OFF
15:50:42.189 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Bedroom_Lights' received command OFF
15:50:42.201 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light12_Brightness' received command OFF
15:50:42.205 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Bathroom_Lights' received command OFF
15:50:42.223 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light14_Brightness' received command OFF
15:50:42.224 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hall_Lights' received command OFF
15:50:43.234 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Livingarea_Lights' received command OFF
15:50:43.237 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light17_Brightness' received command OFF
15:50:43.250 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Livingroom_Lights' received command OFF
15:50:43.259 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Kitchen_Lights' received command OFF
15:50:44.278 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light13_Brightness' received command OFF
15:50:44.278 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Office_Lights' received command OFF
15:50:44.298 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Outdoor_Lights' received command OFF
15:50:44.300 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Livingroom_Lights' received command OFF
15:50:44.316 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZW_DRS1_Switch' received command OFF
15:50:44.320 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Kitchen_Lights' received command OFF
15:50:45.327 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:controller:node5:switch_binary --> OFF
15:50:45.327 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_SET
15:50:45.328 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
15:50:45.328 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
15:50:45.330 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 25 01 00 25 9C 7D 
15:50:45.331 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 25 01 00 25 9C 7D 
15:50:45.337 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZW_DIM1_Dimmer' received command OFF
15:50:45.338 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZW_WP3_Switch' received command OFF
15:50:45.343 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
15:50:45.345 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:45.346 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
15:50:45.347 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
15:50:45.348 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
15:50:45.348 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
15:50:45.360 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9C 00 00 02 75 
15:50:45.362 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:45.363 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9C 00 00 02 00 00 7B 
15:50:45.364 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 9C 00 00 02 00 00 7B 
15:50:45.365 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9C 00 00 02 
15:50:45.366 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 156, Status = Transmission complete and ACK received(0)
15:50:45.366 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
15:50:45.366 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@92ac80 already registered
15:50:45.367 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=5, callback=156, payload=05 03 25 01 00 
15:50:45.368 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9C 00 00 02 
15:50:45.369 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=156, expected=SendData, cancelled=false        transaction complete!
15:50:45.369 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
15:50:45.370 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:50:45.370 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 37ms/4361ms.
15:50:50.344 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:50:50.349 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:50:50.345 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'zwave:device:controller:node9' takes more than 5000ms for processing event
15:50:50.351 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'zwave:device:controller:node11' takes more than 5000ms for processing event
15:50:50.352 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:controller:node11:switch_binary --> OFF
15:50:50.352 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 11: Creating new message for application command SWITCH_BINARY_SET
15:50:50.352 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:controller:node9:switch_dimmer --> OFF
15:50:50.354 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
15:50:50.354 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
15:50:50.356 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 9: Creating new message for command SWITCH_MULTILEVEL_SET
15:50:50.356 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0B 03 25 01 00 25 9D 72 
15:50:50.357 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
15:50:50.358 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 0A 00 13 0B 03 25 01 00 25 9D 72 
15:50:50.361 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light8_Brightness' received command OFF
15:50:50.374 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
15:50:50.377 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:50.378 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
15:50:50.379 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
15:50:50.381 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
15:50:50.381 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
15:50:50.390 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9D 00 00 02 74 
15:50:50.393 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:50.395 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9D 00 00 02 00 00 7A 
15:50:50.396 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 9D 00 00 02 00 00 7A 
15:50:50.397 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9D 00 00 02 
15:50:50.398 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 157, Status = Transmission complete and ACK received(0)
15:50:50.399 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Starting initialisation from DONE
15:50:50.402 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=11, callback=157, payload=0B 03 25 01 00 
15:50:50.404 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9D 00 00 02 
15:50:50.405 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=157, expected=SendData, cancelled=false        transaction complete!
15:50:50.405 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
15:50:50.406 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:50:50.407 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Response processed after 48ms/4361ms.
15:50:50.408 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
15:50:50.410 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 09 03 26 01 00 25 9E 70 
15:50:50.411 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 9: Sending REQUEST Message = 01 0A 00 13 09 03 26 01 00 25 9E 70 
15:50:50.427 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
15:50:50.429 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:50.431 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
15:50:50.432 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
15:50:50.434 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
15:50:50.435 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: Sent Data successfully placed on stack.
15:50:50.447 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9E 00 00 03 76 
15:50:50.449 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:50.452 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9E 00 00 03 00 00 78 
15:50:50.453 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 9E 00 00 03 00 00 78 
15:50:50.455 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9E 00 00 03 
15:50:50.457 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 158, Status = Transmission complete and ACK received(0)
15:50:50.457 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE
15:50:50.459 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@97101b already registered
15:50:50.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=9, callback=158, payload=09 03 26 01 00 
15:50:50.465 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9E 00 00 03 
15:50:50.467 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=158, expected=SendData, cancelled=false        transaction complete!
15:50:50.467 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
15:50:50.468 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:50:50.470 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Response processed after 57ms/4361ms.
15:50:50.523 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 09 03 26 03 00 DD 
15:50:50.525 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:50:50.526 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 09 03 26 03 00 DD 
15:50:50.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 09 03 26 03 00 DD 
15:50:50.528 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 03 26 03 00 
15:50:50.529 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DONE)
15:50:50.529 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE
15:50:50.530 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@97101b already registered
15:50:50.530 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SWITCH_MULTILEVEL
15:50:50.531 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 9: Received SWITCH_MULTILEVEL command V3
15:50:50.532 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 9: Switch Multi Level report, value = 0
15:50:50.533 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
15:50:50.533 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
15:50:50.534 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 0
15:50:50.536 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating channel state zwave:device:controller:node9:switch_dimmer to 0 [PercentType]
15:50:50.542 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=9, callback=158, payload=09 03 26 01 00 
15:50:50.543 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 03 26 03 00 
15:50:50.545 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=158, expected=SendData, cancelled=false      MISMATCH
15:50:55.370 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:50:55.374 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'hue:0220:1:light8' takes more than 5000ms for processing event
15:50:55.373 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:50:55.373 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing hue:0200:1:light17 takes more than 5000ms for processing event
15:50:55.389 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light9_Brightness' received command OFF
15:50:55.397 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light15_Brightness' received command OFF
15:50:55.420 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light10_Brightness' received command OFF
15:50:55.425 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light16_Brightness' received command OFF
15:50:55.445 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light18_Brightness' received command OFF
15:50:55.464 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light19_Brightness' received command OFF
15:50:55.476 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZW_WP2_Switch' received command OFF
15:51:00.479 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'zwave:device:controller:node10' takes more than 5000ms for processing event
15:51:00.479 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing hue:0220:1:light13 takes more than 5000ms for processing event
15:51:00.480 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:controller:node10:switch_binary --> OFF
15:51:00.483 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 10: Creating new message for application command SWITCH_BINARY_SET
15:51:00.484 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
15:51:00.484 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
15:51:00.486 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:51:00.486 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 25 01 00 25 9F 71 
15:51:00.487 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 25 01 00 25 9F 71 
15:51:00.490 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light11_Brightness' received command OFF
15:51:00.498 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
15:51:00.500 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:51:00.501 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
15:51:00.502 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
15:51:00.503 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
15:51:00.503 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: Sent Data successfully placed on stack.
15:51:00.507 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZW_WP3_Switch' received command OFF
15:51:00.509 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:controller:node11:switch_binary --> OFF
15:51:00.509 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 11: Creating new message for application command SWITCH_BINARY_SET
15:51:00.510 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
15:51:00.515 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light15_Brightness' received command OFF
15:51:00.517 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light8_Brightness' received command OFF
15:51:00.518 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 9F 00 00 02 76 
15:51:00.521 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:51:00.522 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 9F 00 00 02 00 00 78 
15:51:00.523 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 9F 00 00 02 00 00 78 
15:51:00.524 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9F 00 00 02 
15:51:00.524 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 10: SendData Request. CallBack ID = 159, Status = Transmission complete and ACK received(0)
15:51:00.525 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Starting initialisation from DONE
15:51:00.526 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=10, callback=159, payload=0A 03 25 01 00 
15:51:00.527 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=9F 00 00 02 
15:51:00.527 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=159, expected=SendData, cancelled=false        transaction complete!
15:51:00.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
15:51:00.528 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:51:00.528 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 10: Response processed after 40ms/4361ms.
15:51:00.529 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
15:51:00.530 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0B 03 25 01 00 25 A0 4F 
15:51:00.530 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 0A 00 13 0B 03 25 01 00 25 A0 4F 
15:51:00.543 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
15:51:00.544 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:51:00.548 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
15:51:00.548 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
15:51:00.552 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
15:51:00.553 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
15:51:00.559 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 A0 00 00 02 49 
15:51:00.561 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:51:00.563 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 A0 00 00 02 00 00 47 
15:51:00.566 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 A0 00 00 02 00 00 47 
15:51:00.567 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A0 00 00 02 
15:51:00.568 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 160, Status = Transmission complete and ACK received(0)
15:51:00.569 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Starting initialisation from DONE
15:51:00.569 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@dae012 already registered
15:51:00.570 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=11, callback=160, payload=0B 03 25 01 00 
15:51:00.572 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=A0 00 00 02 
15:51:00.573 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=160, expected=SendData, cancelled=false        transaction complete!
15:51:00.574 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
15:51:00.574 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15:51:00.575 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 11: Response processed after 44ms/4361ms.
15:51:01.551 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light16_Brightness' received command OFF
15:51:01.554 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light9_Brightness' received command OFF
15:51:02.581 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light10_Brightness' received command OFF
15:51:02.801 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light18_Brightness' received command OFF
15:51:02.817 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Hue_Light19_Brightness' received command OFF
15:51:04.403 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 0A 08 32 02 21 74 00 00 00 00 92 
15:51:04.406 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:51:04.408 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 04 00 0A 08 32 02 21 74 00 00 00 00 92 
15:51:04.410 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0E 00 04 00 0A 08 32 02 21 74 00 00 00 00 92 
15:51:04.412 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0A 08 32 02 21 74 00 00 00 00 
15:51:04.413 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 10: Application Command Request (ALIVE:DONE)
15:51:04.413 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Starting initialisation from DONE
15:51:04.414 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@13d5af0 already registered
15:51:04.415 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 10: Incoming command class METER
15:51:04.415 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 10: Received METER command V3
15:51:04.416 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 10: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
15:51:04.416 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
15:51:04.417 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got an event from Z-Wave network: ZWaveMeterValueEvent
15:51:04.417 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 0E+1
15:51:04.418 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_W
15:51:04.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Updating channel state zwave:device:controller:node10:meter_watts to 0 [DecimalType]
15:51:04.425 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_A <> E_W
15:51:04.426 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_V <> E_W
15:51:04.426 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 11: Transaction not completed: node address inconsistent.  lastSent=11, incoming=255
15:51:07.832 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing zwave:device:controller:node5 takes more than 5000ms for processing event
15:51:07.832 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing hue:0200:1:light18 takes more than 5000ms for processing event
15:51:07.834 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:51:07.833 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
15:51:07.857 [INFO ] [ome.event.GroupItemStateChangedEvent] - Lights changed from OFF to ON through Bedroom_Lights
15:51:08.889 [INFO ] [ome.event.GroupItemStateChangedEvent] - Office_Lights changed from OFF to ON through Hue_Light11_Brightness
15:51:08.893 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_WP2_Switch changed from ON to OFF
15:51:08.896 [INFO ] [ome.event.GroupItemStateChangedEvent] - Office_Lights changed from ON to OFF through ZW_WP2_Switch
15:51:08.901 [INFO ] [ome.event.GroupItemStateChangedEvent] - Lights changed from ON to OFF through Office_Lights
15:51:08.911 [INFO ] [ome.event.GroupItemStateChangedEvent] - Power changed from 9.095 to 5.1 through ZW_WP2_Power
15:51:08.942 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_WP2_Power changed from 3.995 to 0
15:51:10.192 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 13 06 31 05 03 0A 00 53 8C 
15:51:10.194 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
15:51:10.195 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 04 00 13 06 31 05 03 0A 00 53 8C 
15:51:10.196 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0C 00 04 00 13 06 31 05 03 0A 00 53 8C 
15:51:10.197 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 13 06 31 05 03 0A 00 53 
15:51:10.197 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 19: Application Command Request (INITIALIZING:PING)
15:51:10.198 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Node is ALIVE. Init stage is PING.
15:51:10.198 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
15:51:10.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node Status event during initialisation - Node is ALIVE
15:51:10.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer - PING: queue length(0), free to send(true)
15:51:10.199 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: loop - PING try 1: stageAdvanced(false)
15:51:10.199 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: PING - send NoOperation
15:51:10.199 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 19: Creating new message for command No Operation
15:51:10.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer - queued packet. Queue length is 1 [...]

[philKrylc (Phil)]

And this one for Sonos:

16:01:52.661 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Sonos_PLAY51_Control' received command PLAY
16:01:57.669 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing sonos:zoneplayer:3 takes more than 5000ms for processing event
16:01:57.669 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
16:01:57.674 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'sonos:zoneplayer:3' takes more than 5000ms for processing event
16:01:57.688 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Sonos_PLAY51_Control' received command PAUSE
16:01:57.697 [INFO ] [marthome.event.ItemStateChangedEvent] - Sonos_PLAY51_Control changed from PAUSE to PLAY

[chris (Chris Jackson)]

I note that there are also errors in here for Hue as well -:

15:50:55.373 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing hue:0200:1:light17 takes more than 5000ms for processing event

@kai to me this seems to be more widespread than a binding or two. I see other messages on the forum about mgtt, here we have hue, sonos and zwave and I think I’ve also seen messages about exec and network as well.

https://community.openhab.org/search?q=more%20than%205000ms

[poertner (Stefan)]

Same here for the “milight” binding.
Lights won’t switch from time to time…

2017-02-08 23:15:51.300 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'milight:rgbLed:b827ebe64882:9' takes more than 5000ms for processing event
2017-02-08 23:15:51.301 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@d060bf' takes more than 5000ms.

[J-N-K (Jan N. Klug)]

Not much help: the new DMX binding shows it, Too. But It’s not everytime and I can’ figure our how to reproduce it.

[sjka (Simon Kaufmann)]

Does anybody have a log with DEBUG enabled for (at least) org.eclipse.smarthome.core.common.*? There should be something like
Timeout of [...]ms exceeded, thread [...] in state [...] is at [...]).
This would help to get an idea where it got stuck.

[philKrylc (Phil)]

@sjka

DEBUG enabled for (at least) org.eclipse.smarthome.core.common.*?

Here you go:

ZWave:

09:13:56.286 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'ZW_WP2_Switch' received command ON
09:14:01.301 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded with no thread info available.
09:14:01.307 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded, thread safeCall-856 (22744) in state RUNNABLE is at sun.misc.Unsafe.park(Unsafe.java:-2).
09:14:01.317 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
09:14:01.301 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded with no thread info available.
09:14:01.311 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'zwave:device:controller:node10' takes more than 5000ms for processing event
09:14:01.321 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing zwave:device:controller:node10 takes more than 5000ms for processing event
09:14:01.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:controller:node10:switch_binary --> ON
09:14:01.311 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded, thread safeCall-857 (22745) in state BLOCKED is at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:231).
09:14:01.324 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 10: Creating new message for application command SWITCH_BINARY_SET
09:14:01.325 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
09:14:01.327 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
09:14:01.331 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0A 03 25 01 FF 25 9F 8E 
09:14:01.331 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
09:14:01.335 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 10: Sending REQUEST Message = 01 0A 00 13 0A 03 25 01 FF 25 9F 8E 
09:14:01.343 [INFO ] [marthome.event.ItemStateChangedEvent] - ZW_WP2_Switch changed from OFF to ON

Sonos:

09:19:00.204 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'Sonos_PLAY51_Control' received command PLAY
09:19:05.211 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded with no thread info available.
09:19:05.211 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded with no thread info available.
09:19:05.215 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing sonos:zoneplayer:3 takes more than 5000ms for processing event
09:19:05.211 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded, thread safeCall-859 (22839) in state RUNNABLE is at sun.misc.Unsafe.park(Unsafe.java:-2).
09:19:05.215 [WARN ] [ome.core.thing.internal.ThingManager] - Handler for thing 'sonos:zoneplayer:3' takes more than 5000ms for processing event
09:19:05.216 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
09:19:05.216 [DEBUG] [arthome.core.common.SafeMethodCaller] - Timeout of 5000ms exceeded, thread safeCall-860 (22840) in state TIMED_WAITING is at sun.nio.cs.UTF_8$Encoder.encodeArrayLoop(UTF_8.java:596).
09:19:05.217 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.ThingManager@1ddd675' takes more than 5000ms.
09:19:05.232 [INFO ] [marthome.event.ItemStateChangedEvent] - Sonos_PLAY51_Control changed from PAUSE to PLAY

[chris (Chris Jackson)]

In the case of the ZWave log, the binding doesn’t receive the command message until after the error.

This message -:

09:14:01.324 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 10: Creating new message for application command SWITCH_BINARY_SET

:- is when the binding is called (the first line in the handler is to log this message).

[Kai (Kai Kreuzer)]

It seems as if the thread pools go out of threads. The warning logs actually blame the wrong ones in that case: It’s the ones that do not get a thread assigned anymore in time. This also explains why the binding receives the events only afterwards.
One short term workaround would be to increase the safeCall threadpool size. You could try to add the line

org.eclipse.smarthome.threadpool:safeCall=10

to conf/services/runtime.cfg and see if that helps.
We will look at improving the thread assignment and the warning logging within the ThingManager.