So i got now a full debug log for one switch event.
log.json (69.6 KB)
Hope the attached log will help to clarify the circumstances. I disabled energy reports from my network devices otherwise it would have 10 times more entries.
Best regards
Can you talk me through what is meant to happen? How is the rule triggered (incoming NODON command?) and what command does it send?
@chris the rule as follows…
rule "Remote Functions"
when
Item ZWaveNode35SoftRemoteRemoteControl_SceneNumber received update
then
if (ZWaveNode35SoftRemoteRemoteControl_SceneNumber.state == 3.3)
{
logInfo("Remote Functions", "Rule: Button3 DoubleClick")
if (ZWaveNode29ZW096SmartSwitch6_Switch.state == ON)
{
sendCommand(ZWaveNode29ZW096SmartSwitch6_Switch, OFF)
}
else
{
sendCommand(ZWaveNode29ZW096SmartSwitch6_Switch, ON)
}
}
end
Mention everything is working fine. The only problem is if i did not interact with any device for a long time (1h) i have delay from remote trigger (NODON) until the physical state changed. The INFO logs seems to be in realtime. So if i push the button a few ms later i got the log from rule and a INFO log from your binding to. BUt the physical state changes after 5 seconds and more. This happens after long inactivity.
So isn’t that this log then -:
The scene is received, and the OFF command is sent, and then the response from the device is received? All this happens in under 1/2 a second. Or am I missing something?
You are right chris. Now i have one with delay in it because i did not touched any device (remote ore other zwave devices) for a long time.
logdelay.json (79.7 KB)
please tell me how i can prepare the log the way you did the post before (ah already found it your hompage can do it…nice!)
Transmitter is not in sleep mode…as traffic logs show. Seems the rule engine is fireing to late as i can see the log created by the rule is delayed…
22:54:55.399 [INFO ] [rthome.model.script.Remote Functions] - Rule: Button3 DoubleClick
Any ideas why this is delayd after long inactivity?
It’s strange that it’s exactly 5 seconds. There are 2 places I know of where there are 5 second timeouts - either a timeout in the ZWave binding, or in the framework. I don’t think this is a zwave issue - there’s no timeout messages in the logfile, and in the log above the STATE UPDATE message is sent immediately, and the COMMAND RECEIVED is 5 seconds later.
So, there are other threads on this sort of thing -:
I don’t know if this is related or not, but it might be worth looking there?
Here is a snippit from the log when polling my NODE 33. The humidity value returned is 147 which doesn’t seem to make sense since it should be a percentage. I can provide more complete logs and create a ticket on your site if that makes more sense since this is a small excerpt. Of the three thermostats I have, only one provides a legitimate value. I would say it was a possible issue with the device database if it weren’t for one thermostat that appears to work. I haven’t had any issues reading humidity from these thermostats in the past.
Value returned:
2017-04-17 09:07:29.015 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got a value event from Z-Wave network, endpoint = 2, command class = COMMAND_CLASS_BASIC, value = 147
2017-04-17 09:07:29.015 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Updating channel state zwave:device:93af1255:node33:sensor_relhumidity2 to 147 [DecimalType]
Log of poll:
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-04-17 09:07:28.999 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 21 03 43 02 01 25 10 B1
2017-04-17 09:07:28.999 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 33: Sending REQUEST Message = 01 0A 00 13 21 03 43 02 01 25 10 B1
2017-04-17 09:07:28.999 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-17 09:07:28.999 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type SendData
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:1610 [WAIT_RESPONSE] callback: 16
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: COMMAND_CLASS_THERMOSTAT_SETPOINT
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 3
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Apr 17 09:07:30 EDT 2017 - 2000ms
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:1610 [WAIT_RESPONSE] callback: 16
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-17 09:07:28.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Apr 17 09:07:30 EDT 2017 - 2000ms
2017-04-17 09:07:29.000 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:1610 [WAIT_RESPONSE] callback: 16
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-17 09:07:29.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-17 09:07:29.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-17 09:07:29.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-17 09:07:29.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Apr 17 09:07:30 EDT 2017 - 1998ms
2017-04-17 09:07:29.006 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-04-17 09:07:29.006 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 09:07:29.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-04-17 09:07:29.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-04-17 09:07:29.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-04-17 09:07:29.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:1610 [WAIT_RESPONSE] callback: 16
2017-04-17 09:07:29.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-04-17 09:07:29.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:1610 [WAIT_RESPONSE] callback: 16
2017-04-17 09:07:29.006 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-04-17 09:07:29.007 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 33: Sent Data successfully placed on stack.
2017-04-17 09:07:29.007 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: WAIT_RESPONSE
2017-04-17 09:07:29.007 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null
2017-04-17 09:07:29.007 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: ApplicationCommandHandler
2017-04-17 09:07:29.007 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-04-17 09:07:29.007 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: WAIT_REQUEST
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction 16 advanced to WAIT_REQUEST
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: **** Transaction not completed
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-17 09:07:29.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Apr 17 09:07:34 EDT 2017 - 5000ms
2017-04-17 09:07:29.014 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 21 07 60 0D 02 01 20 03 93 0E
2017-04-17 09:07:29.014 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 09:07:29.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 07 60 0D 02 01 20 03 93
2017-04-17 09:07:29.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 07 60 0D 02 01 20 03 93
2017-04-17 09:07:29.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 07 60 0D 02 01 20 03 93
2017-04-17 09:07:29.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:1610 [WAIT_REQUEST] callback: 16
2017-04-17 09:07:29.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Application Command Request (ALIVE:DONE)
2017-04-17 09:07:29.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: resetResendCount initComplete=true isDead=false
2017-04-17 09:07:29.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-04-17 09:07:29.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Incoming command class COMMAND_CLASS_BASIC, endpoint 2
2017-04-17 09:07:29.015 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: SECURITY not supported
2017-04-17 09:07:29.015 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 33: Received COMMAND_CLASS_BASIC V0 BASIC_REPORT
2017-04-17 09:07:29.015 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 33: Basic report, value = 147
2017-04-17 09:07:29.015 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2017-04-17 09:07:29.015 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2017-04-17 09:07:29.015 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got a value event from Z-Wave network, endpoint = 2, command class = COMMAND_CLASS_BASIC, value = 147
2017-04-17 09:07:29.015 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Updating channel state zwave:device:93af1255:node33:sensor_relhumidity2 to 147 [DecimalType]
2017-04-17 09:07:29.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Commands processed 1.
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5de0cad5.
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Checking transaction 1610 ApplicationCommandHandler.
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Checking transaction : state >> WAIT_REQUEST
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Checking transaction : node >> 33
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Checking transaction : class >> 32 == 67.
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Checking transaction : commd >> 3 == 3.
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Ignoring transaction since not waiting for data.
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-17 09:07:29.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Apr 17 09:07:34 EDT 2017 - 4991ms
2017-04-17 09:07:29.035 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 10 00 F9
2017-04-17 09:07:29.035 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=16, payload=10 00
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=16, payload=10 00
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=16, payload=10 00
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID:1610 [WAIT_REQUEST] callback: 16
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID:1610 [WAIT_REQUEST] callback: 16
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - checking transaction 16 (Callback 16) ......
2017-04-17 09:07:29.035 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2017-04-17 09:07:29.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to transaction 16......
2017-04-17 09:07:29.035 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=16, payload=10 00
2017-04-17 09:07:29.035 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 33: SendData Request. CallBack ID = 16, Status = Transmission complete and ACK received(0)
2017-04-17 09:07:29.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: resetResendCount initComplete=true isDead=false
2017-04-17 09:07:29.035 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance ST: WAIT_REQUEST
2017-04-17 09:07:29.036 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TX: null
2017-04-17 09:07:29.036 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance WT: ApplicationCommandHandler
2017-04-17 09:07:29.036 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=16, payload=10 00
2017-04-17 09:07:29.036 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TransactionAdvance TO: DONE
2017-04-17 09:07:29.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction 16 advanced to DONE
2017-04-17 09:07:29.036 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction payload is the same [[67, 2, 1]] == [[67, 2, 1]]
2017-04-17 09:07:29.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Response processed after 37ms
2017-04-17 09:07:29.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: **** Transaction completed
2017-04-17 09:07:29.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: notifyTransactionResponse 1610 DONE
2017-04-17 09:07:29.036 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-04-17 09:07:29.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 83 -- 1610
2017-04-17 09:07:29.036 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-04-17 09:07:29.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
The sensor is returning this value (ie 147 or 93 in hex) -:
It’s returned as a BASIC message and in hte database this is linked to the sensor - maybe this is wrong and the message shouldn’t be linked to BASIC, or maybe the sensor is actually returning dud data, but based on the current configuration, the binding appears to be doing the right thing…
I’d suggest that possibly removing the BASIC class link might be a good move.
Wow, thanks! I updated my thing definition in the jsondb and that worked! Since things now look good for all 3 of my devices, I just updated the device database on your site.
Great - thanks for testing and updates.
Even though I opened in the wrong version, I see you already added it so won’t reopen it in the correct version. Thanks!!
Question, is there anyway to reference the labels in a rule? Just thinking ahead to when you have time to add the ability to get the user code entered during an Alarm Notification event.
Just in case anyone else ends up with this issue. I’ve had it happen twice, and both times I stopped openhab, deleted the Userdata/Cache directory and it worked on a restart.
I’m not sure - I doubt it. They are stored as parameters, so if the new rule system has the ability to access things parameters, then yes ;). I don’t think it’s possible right now though… There are other ways - using direct access to the REST interface, but it’s not nice.
Maybe one day…
When you add the channel for pulling the entered pin id, would it be possible to return the label rather than the ID #?
Sorry - I don’t know what you mean by this?
Anybody else experiencing high battery drain on their locks? My get lock yesterday went from 50% to zero in 1 day.
One thing I noticed from @shawnmix logfile is that his log has 200 user codes. The binding will download these each time it starts - this takes quite a long time - if you’re restarting the binding multiple times per day (as you might be at the moment) I could imagine this could impact battery quite considerably.
Under more routine operation, it should be fine as it won’t talk to the lock very often.
Sorry, what I was asking is that when you add the ability to get the userid # that comes as part of the alarm event notification string from the device, instead (or in addition) to just returning the 1-30 userid #, is it possible to return the label associated with that userid? Does that make more sense?
This is not so simple - how would you propose to do this? Would you propose to have multiple items - one with the alarm, one with userid, one with user name? How would you then use these? How would you tie them to a specific event so that you know you have a consistent set for data for a single alarm???
I’m not just asking these questions to be a pain ;). I’m quite interested in this as it’s a question I have myself, and I’ve recently raised this on the ESH forum so I’m interested in ideas.
I only have 3 userids and it’s a seldom used lock. I didn’t do any restarts until last night when I upgraded to the latest one and zwave snapshots. I’ll watch it the next few days and see if I can setup a persistence graph to observe the rate of loss. I know Vera did something to their code base last year that took them from an ok drain to almost no drain (unfortunately I have no idea what they did so not that much help…)