I installed OH2 a couple of months ago, with a small system based on Z-Wave, initially just to automate the hall lights.
Platform information:
* Hardware: Raspberry Pi Model 3B,
* JAVA: openjdk version “1.8.0_152” , OpenJDK Runtime Environment (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 1.8.0_152-b76). OpenJDK Client VM (Zulu Embedded 8.25.0.76-linux-aarch32hf) (build 25.152-b76, mixed mode, Evaluation)
* Z-Wave Node 005: Fibaro FGMS001 Motion Sensor
* Z-Wave Node 006: Fibaro FGD212 Dimmer 2
* Aeotec Z-Stick USB Controller
The simple expectation is for the lights to come on after movement has been detected by the sensor (although additionally time of day and luminance are used). The operational rules are based almost 100% from post 30 in ZekeB - How I have automated my lights - That is a great set of rules - thanks.
These worked almost from the start, but my problem was a delay of a few seconds between the sensor detecting movement and the light coming on. This occurred seemingly on a random basis. See here:
No Delay:
2020-03-16 21:10:16.787 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-16 21:10:16.792 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-16 21:10:16.908 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 68.0
2020-03-16 21:10:16.917 [vent.ItemStateChangedEvent] - FibaroHall_Light_Virtual changed from 0 to 68.0
Delay:
2020-03-17 08:46:41.102 [vent.ItemStateChangedEvent] - zwave_device_16fd2e2de4a_node5_alarm_motion changed from OFF to ON
2020-03-17 08:46:41.105 [vent.ItemStateChangedEvent] - FibaroHall_Motion_Sensor changed from OFF to ON
2020-03-17 08:46:45.287 [ome.event.ItemCommandEvent] - Item 'FibaroHall_Light_Virtual' received command 42.0
2020-03-17 08:46:45.293 [vent.ItemStateChangedEvent] - FibaroHall_Light_Virtual changed from 0 to 42.0
I noticed that delays did not occur one after the other, but only seemed to occur when there was a gap between detections of a few hours. Having searched on the forums about ‘delays’ and their remedies eg. [SOLVED] Rule execution delayed, I tried changing settings concerning the threadpool, EXTRA_JAVA and the sensitivity of the sensor, etc. But no luck
Next, a detailed comparison of the log entries between (1) occasions when the lights came on almost immediately and (2) occasions when there was a delay. One possibility I investigated was that any automatic updates of the sensor node caused the next sensor detection to have a delay. eg after:
2020-03-17 05:05:00.594 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:16fd2e2de4a:node5' has been updated
The Z-wave binding settings for the sensor on OH2 allow me to change the updating frequency on the sensor. Under ‘Wakeup Configuration’, the ‘Wakeup interval’ was at the default of 2 hours, which suggested a possible cause of the problem. So I changed this to the maximum permitted of 65535 seconds (approx 18 hours). This significantly reduced the number of delays to about one per day.
My conclusion is that the problem is with this updating of the node/thing. It would be useful to eliminate the problem completely. I do not know whether the problem is with the rules or something to do with the Zwave binding. I have turned on debugging for Zwave and here is the log for the delayed incident:
2020-03-17 08:46:41.040 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 05 09 71 05 00 00 00 FF 07 08 00 7C
2020-03-17 08:46:41.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 09 71 05 00 00 00 FF 07 08 00
2020-03-17 08:46:41.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 09 71 05 00 00 00 FF 07 08 00
2020-03-17 08:46:41.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-03-17 08:46:41.064 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
2020-03-17 08:46:41.067 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
2020-03-17 08:46:41.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_ALARM, endpoint 0
2020-03-17 08:46:41.071 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_ALARM
2020-03-17 08:46:41.073 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_ALARM V5 NOTIFICATION_REPORT
2020-03-17 08:46:41.075 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 5: NOTIFICATION report - 0 = 0, event=8, status=255, plen=0
2020-03-17 08:46:41.077 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 5: Alarm Type = BURGLAR (0)
2020-03-17 08:46:41.079 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveAlarmValueEvent
2020-03-17 08:46:41.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ALARM, value=255
2020-03-17 08:46:41.084 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter processing NOTIFICATION
2020-03-17 08:46:41.087 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter NOTIFICATION event is 8, type OnOffType
2020-03-17 08:46:41.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:16fd2e2de4a:node5:alarm_motion to ON [OnOffType]
2020-03-17 08:46:41.094 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter processing NOTIFICATION
2020-03-17 08:46:41.097 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 5: Alarm converter NOTIFICATION event is 8, type OnOffType
2020-03-17 08:46:41.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
2020-03-17 08:46:41.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@18cd06c.
2020-03-17 08:46:41.113 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-03-17 08:46:41.116 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-03-17 08:46:41.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-03-17 08:46:41.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-03-17 08:46:45.186 [INFO ] [pse.smarthome.model.script.Rule Info] - Step 1 of motion detectedHomeStatus: HomeStatus (Type=NumberItem, State=0, Label=State is, Category=null)
2020-03-17 08:46:45.220 [INFO ] [pse.smarthome.model.script.Rule Info] - Step 2 of motion detected room: FibaroHall control: FibaroHall_Motion_Pause (Type=SwitchItem, State=OFF, Label=Fibaro Hall Motion Control Pause, Category=null, Groups=[LightMotionControls, GF_Hall])FibaroHall_Motion_Override (Type=SwitchItem, State=OFF, Label=Fibaro Hall Motion Control Override, Category=null, Groups=[LightMotionControls, GF_Hall])Lux: 2
It does not seem to be any different to the log when there is no delay.
Any ideas please? Thank you.