Lost 5 Seconds in Runtime

Tags: #<Tag:0x00007f617047c858>

Hello together,

based on the following Rule and the event on the ZWAVE-Bus I dont know, where I lost 5 seconds between event and action. It looks like this problem is a sleep-lag, because its not overall time, i think only if i dont use the hole System for a longer time. Where can i get more debugging-informations?
rule “Schlafzimmertuer geöffnet”
when
Item TuerSensorSchlafzimmer_SensorDoor changed to OPEN
then
// logInfo(“bewegung”, “Schlafzimmertuer geöffnet”)
if (orte_schlafzimmer_state.state == 0) {
logInfo(“bewegung”, “Schlafzimmer von aussen geöffnet”)
orte_schlafzimmer_state.sendCommand(1)
orte_flur_state.sendCommand(3)
}
if (orte_schlafzimmer_state.state == 2) {
logInfo(“bewegung”, “Schlafzimmer von innen geöffnet”)
orte_schlafzimmer_state.sendCommand(3)
}

2020-02-29 05:18:30.410 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 15 00 04 00 15 0D 56 01 71 05 00 00 00 FF 06 16 00 FF C5 C9 00 C9
2020-02-29 05:18:30.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=21, callback=0, payload=00 15     0D 56 01 71 05 00 00 00 FF 06 16 00 FF C5 C9 00
2020-02-29 05:18:30.420 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=21, callback=0, payload=00 15 0D 56 01 71 05 00     00 00 FF 06 16 00 FF C5 C9 00
2020-02-29 05:18:30.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-02-29 05:18:30.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Application Command Request (ALIVE:UPDATE_NEIGHBORS)
2020-02-29 05:18:30.423 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2020-02-29 05:18:30.425 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2020-02-29 05:18:30.426 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: SECURITY not supported
2020-02-29 05:18:30.427 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 21: Received COMMAND_CLASS_ALARM V5 NOTIFICATION_REPORT
2020-02-29 05:18:30.429 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 21: NOTIFICATION report - 0 = 0, event=22, status=255, plen=0
2020-02-29 05:18:30.430 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 21: Alarm Type = ACCESS_CONTROL (0)
2020-02-29 05:18:30.431 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2020-02-29 05:18:30.432 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ALARM, value=255
2020-02-29 05:18:30.434 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.435 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OnOffType
2020-02-29 05:18:30.436 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.437 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OpenClosedType
2020-02-29 05:18:30.439 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:512:node21:sensor_door to OPEN [OpenClosedType]
2020-02-29 05:18:30.441 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.442 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OnOffType
2020-02-29 05:18:30.444 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter processing NOTIFICATION
2020-02-29 05:18:30.446 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 21: Alarm converter NOTIFICATION event is 22, type OnOffType
2020-02-29 05:18:30.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Commands processed 1.
2020-02-29 05:18:30.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@158d37c.
2020-02-29 05:18:30.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-29 05:18:30.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-02-29 05:18:30.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-02-29 05:18:30.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-02-29 05:18:35.189 [INFO ] [ipse.smarthome.model.script.bewegung] - Schlafzimmer von innen geöffnet

Without a debug log it is only guessing, but 5 seconds sounds like a typical timeout in Z-Wave communication.

Related topics

1 Like

The solution for this is to use the new rule engine. If you’d like to still use scripts, there is scripted automation.