I’m hoping someone can shed some light on this. Most of the time my openhab2 set up (with almost all zwave devices) responds with a low lag/latency. But often there’s a lag of seconds.
Here is a snippet of a log where a zwave PIR sensor (Node 54) sees me and a rule fires to turn on a zwave bulb (Node 65)
2017-08-11 17:20:35.092 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 36 03 20 01 FF 19
2017-08-11 17:20:35.092 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-08-11 17:20:35.092 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 36 03 20 01 FF 19
2017-08-11 17:20:35.092 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 36 03 20 01 FF 19
2017-08-11 17:20:35.093 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 36 03 20 01 FF
2017-08-11 17:20:35.093 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 54: Application Command Request (ALIVE:DONE)
2017-08-11 17:20:35.093 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 54: Starting initialisation from DONE
2017-08-11 17:20:35.093 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@36f289de already registered
2017-08-11 17:20:35.093 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 54: Incoming command class BASIC
2017-08-11 17:20:35.093 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 54: Received Basic Request
2017-08-11 17:20:35.093 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 54: Basic Set sent to the controller will be processed as Basic Report
2017-08-11 17:20:35.093 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 54: Basic report, value = 0xFF
2017-08-11 17:20:35.093 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-08-11 17:20:35.093 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 54: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-08-11 17:20:35.093 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 54: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2017-08-11 17:20:35.093 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 54: Updating channel state zwave:device:88bf0286:node54:sensor_binary to ON [OnOffType]
2017-08-11 17:20:35.093 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 60: Transaction not completed: node address inconsistent. lastSent=60, incoming=255
2017-08-11 17:20:35.093 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'hall'
2017-08-11 17:20:35.094 [DEBUG] [pse.smarthome.model.script.autoLight] - turnOnLight [3364]
2017-08-11 17:20:35.097 [INFO ] [pse.smarthome.model.script.autoLight] - turn on dimmer HallLight_Dimmer [3364] to 100. Previous=true
2017-08-11 17:20:35.098 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Command received zwave:device:88bf0286:node65:switch_dimmer --> 100
2017-08-11 17:20:35.098 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 65: Creating new message for command SWITCH_MULTILEVEL_SET
2017-08-11 17:20:35.098 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-08-11 17:20:35.395 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 11 00 04 00 36 0B 71 05 00 00 00 FF 07 07 01 07 00 5A
To me that looks great! bulb is turned on almost instantly… however that’s not what actually happened. It turned on many seconds later.
2017-08-11 17:20:49.759 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-08-11 17:20:49.759 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 41 03 26 01 63 25 70 B5
2017-08-11 17:20:49.760 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 65: Sending REQUEST Message = 01 0A 00 13 41 03 26 01 63 25 70 B5
2017-08-11 17:20:49.765 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-08-11 17:20:49.765 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-08-11 17:20:49.765 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-08-11 17:20:49.765 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-08-11 17:20:49.765 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-08-11 17:20:49.765 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 65: Sent Data successfully placed on stack.
I’ve put the log into the zwave log viewer but I don’t really know what steps to take to identify what is going wrong? The log shows some rejected by controller, both for this node and another.
2017-08-11 17:20:54.909 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 65: Sent Data was not placed on stack due to error 0.
I’m running a nightly snapshot on centos7 (via RPMs) version 2.2.0.20170804002314-1
Here is the log file. I had to upload it as an XML cause .log and .txt are not allowed extensions. zwavelog1.log (85.6 KB)
I’m wondering if my zwave network is overloaded or the USB controller stick (aeotec z-stick gen5) is not up to the task or somthing else? Any advice or pointers would be much appreciated… i’m getting complaints from those that are dear to me reguarding dark rooms and arm waving 