Hello.
I’m running OH2 2.0.0 Release under Ubuntu server 16.04 LTS on a Shuttle XS35GT (Dual Core Atom@1.6GHz, 2GB RAM) & Aeotec Z-Stick gen5
I have a rule triggered by a NodOn CWS-3101 wall-switch.
Short pressing button 1, triggers this rule:
var swState = WallSwitchStua.state
logInfo("RemoteNodon5", "Rule: Got: " + swState)
switch swState {
case 1.0: {
logInfo("RemoteNodon5", "Rule: Button1 SingleClick " + swState)
if (BuildInKjokkenBench.state == ON) {
sendCommand(WallplugStuaCornerLamp, OFF)
sendCommand(WallplugStuaShelfLamp, OFF)
sendCommand(WallplugStuaWooferLamp, OFF)
sendCommand(WallplugStuaPianoLamp, OFF)
sendCommand(BuildInKjRoofBenchLamp, OFF)
sendCommand(BuildInKjRoofIslandLamp, OFF)
sendCommand(WallplugKjokkenPCBenchLamp, OFF)
sendCommand(BuildInKjokkenBench, OFF)
sendCommand(WallplugKjCornerLamp, OFF)
} else {
sendCommand(WallplugStuaCornerLamp, ON)
sendCommand(WallplugStuaShelfLamp, ON)
sendCommand(WallplugStuaWooferLamp, ON)
sendCommand(WallplugStuaPianoLamp, ON)
sendCommand(BuildInKjRoofBenchLamp, ON)
sendCommand(BuildInKjRoofIslandLamp, ON)
sendCommand(WallplugKjokkenPCBenchLamp, ON)
sendCommand(BuildInKjokkenBench, ON)
sendCommand(WallplugKjCornerLamp, ON)
}
}
Now, most of the time, there is a 5 second delay after sending all the commands to the controller.
There are no dead nodes in the network, but ‘NODE 255’ is often involved just after the delay.
Any thoughts are most welcome.
Log below. (quite lengthy, is pasting the only option on this forum?)
2017-02-28 22:08:41.
2017-02-28 22:08:46.
(Forum would not accept whole log, so it is snipped at the end)
There is a ‘Protocol error (CAN)’ in there. Relevant?
Appears only in this setting.
2017-02-28 22:08:41.176 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 05 05 5B 03 93 00 01 3A
2017-02-28 22:08:41.177 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-02-28 22:08:41.178 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 05 05 5B 03 93 00 01 3A
2017-02-28 22:08:41.178 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 05 05 5B 03 93 00 01 3A
2017-02-28 22:08:41.178 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 05 5B 03 93 00 01
2017-02-28 22:08:41.178 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
2017-02-28 22:08:41.178 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
2017-02-28 22:08:41.179 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4fd90cfb already registered
2017-02-28 22:08:41.179 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class CENTRAL_SCENE
2017-02-28 22:08:41.179 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 5: Received CENTRAL_SCENE command V2
2017-02-28 22:08:41.179 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 5: Received scene 1 at key 0 [Single Press]
2017-02-28 22:08:41.179 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-02-28 22:08:41.179 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-02-28 22:08:41.179 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint = 0, command class = CENTRAL_SCENE, value = 1.0
2017-02-28 22:08:41.180 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:3f5c8071:node5:scene_number to 1.0 [DecimalType]
2017-02-28 22:08:41.180 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 11: Transaction not completed: node address inconsistent. lastSent=11, incoming=255
2017-02-28 22:08:41.187 [INFO ] [.smarthome.model.script.RemoteNodon5] - Rule: Got: 1.0
2017-02-28 22:08:41.188 [INFO ] [.smarthome.model.script.RemoteNodon5] - Rule: Button1 SingleClick 1.0
2017-02-28 22:08:41.192 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:3f5c8071:node13:switch_dimmer --> OFF
2017-02-28 22:08:41.192 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 13: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.193 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-02-28 22:08:41.193 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0D 03 26 01 00 25 5B B1
2017-02-28 22:08:41.194 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 0A 00 13 0D 03 26 01 00 25 5B B1
2017-02-28 22:08:41.194 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 0. Queue={}
2017-02-28 22:08:41.199 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 05 02 84 07 77
2017-02-28 22:08:41.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:3f5c8071:node10:switch_dimmer --> OFF
2017-02-28 22:08:41.199 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 10: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.200 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-02-28 22:08:41.201 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
2017-02-28 22:08:41.202 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-02-28 22:08:41.202 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 05 02 84 07 77
2017-02-28 22:08:41.203 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 05 02 84 07 77
2017-02-28 22:08:41.203 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 05 02 84 07
2017-02-28 22:08:41.203 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Application Command Request (ALIVE:DONE)
2017-02-28 22:08:41.203 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
2017-02-28 22:08:41.203 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4fd90cfb already registered
2017-02-28 22:08:41.203 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 5: Incoming command class WAKE_UP
2017-02-28 22:08:41.203 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Received Wake Up Request
2017-02-28 22:08:41.203 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Received WAKE_UP_NOTIFICATION
2017-02-28 22:08:41.203 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Is awake with 1 messages in the wake-up queue.
2017-02-28 22:08:41.204 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveWakeUpEvent
2017-02-28 22:08:41.204 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveWakeUpEvent
2017-02-28 22:08:41.204 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-02-28 22:08:41.204 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 13: Transaction not completed: node address inconsistent. lastSent=13, incoming=255
2017-02-28 22:08:41.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:3f5c8071:node8:switch_dimmer --> OFF
2017-02-28 22:08:41.206 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 8: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.207 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-02-28 22:08:41.210 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:3f5c8071:node9:switch_dimmer --> OFF
2017-02-28 22:08:41.210 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 9: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.211 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-02-28 22:08:41.215 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:3f5c8071:node16:switch_dimmer --> OFF
2017-02-28 22:08:41.215 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 16: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.215 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2017-02-28 22:08:41.217 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Command received zwave:device:3f5c8071:node17:switch_dimmer --> OFF
2017-02-28 22:08:41.218 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 17: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.218 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 6. Queue={}
2017-02-28 22:08:41.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:3f5c8071:node3:switch_binary --> OFF
2017-02-28 22:08:41.221 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 3: Creating new message for application command SWITCH_BINARY_SET
2017-02-28 22:08:41.222 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 7. Queue={}
2017-02-28 22:08:41.224 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Command received zwave:device:3f5c8071:node15:switch_binary --> OFF
2017-02-28 22:08:41.225 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 15: Creating new message for application command SWITCH_BINARY_SET
2017-02-28 22:08:41.225 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 8. Queue={}
2017-02-28 22:08:41.227 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Command received zwave:device:3f5c8071:node14:switch_dimmer --> OFF
2017-02-28 22:08:41.228 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 14: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-28 22:08:41.228 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 9. Queue={}
2017-02-28 22:08:46.195 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2017-02-28 22:08:46.195 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Sending ABORT Message = 01 03 00 16 EA
2017-02-28 22:08:46.195 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
2017-02-28 22:08:46.195 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
2017-02-28 22:08:46.197 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 2 attempts left!
2017-02-28 22:08:46.198 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 13: Got an error while sending data. Resending message.
2017-02-28 22:08:46.198 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 10. Queue={}
2017-02-28 22:08:46.198 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 9
2017-02-28 22:08:46.198 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 05 02 80 02 25 5D 18
2017-02-28 22:08:46.198 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 09 00 13 05 02 80 02 25 5D 18
2017-02-28 22:08:46.207 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-02-28 22:08:46.207 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-02-28 22:08:46.209 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-02-28 22:08:46.210 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-02-28 22:08:46.211 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-02-28 22:08:46.211 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack.
2017-02-28 22:08:46.227 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5D 00 00 03 B5
2017-02-28 22:08:46.229 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-02-28 22:08:46.230 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5D 00 00 03 00 00 BB
2017-02-28 22:08:46.232 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5D 00 00 03 00 00 BB
2017-02-28 22:08:46.232 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5D 00 00 03
2017-02-28 22:08:46.232 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 93, Status = Transmission complete and ACK received(0)
2017-02-28 22:08:46.232 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Starting initialisation from DONE
2017-02-28 22:08:46.232 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@4fd90cfb already registered
2017-02-28 22:08:46.232 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=5, callback=93, payload=05 02 80 02
2017-02-28 22:08:46.232 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5D 00 00 03
2017-02-28 22:08:46.232 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=93, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2017-02-28 22:08:46.241 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive
.
.
.
transaction complete: class=SendData, callback id=102, expected=SendData, cancelled=false transaction complete!
2017-02-28 22:08:47.282 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-02-28 22:08:47.282 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Went to sleep
2017-02-28 22:08:47.282 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Is sleeping
2017-02-28 22:08:47.283 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-02-28 22:08:47.283 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 33ms/4621ms.