I have noticed over the last 3 or so weeks that I have been getting a number of delays or completely missed triggers, but hadn't been able to track down exactly what was responsible. I had updated HS, Zwave and Blradar all close to the same time so I started with moving back to an older version of Blradar, but the problems continued. Last night I had a chance when everyone was asleep to turn on debugging and watch the logs a bit and what I'm seeing is a 10 to 20 second delay between the sensor triggering and the code being run in BLRadar.
Dec-11 12:10:22 AM Z-Wave Device: Node 6 Basement Fridge (Light) Set to 255
Dec-11 12:10:22 AM Device Control Device: Node 6 Basement Fridge (Light) to On (255) by/from: CAPI Control Handler
Dec-11 12:10:12 AM Z-Wave Device: Node 4 Basement Motion Sensor Set to On/Open/Motion
(10 second delay turning on light from UDMC code for that motion sensor)
In that example the device triggered at 12:10:12 and didn't run the code in BLRadar until 12:10:22 -- so 10 seconds later. So I checked the debug log and sure enough it doesn't appear that BLRadar. So I checked the BLRadar debug log and it appears to confirm that it didn't receive the value change until 12:10:22
12/11/2017 12:10:22 AM : v2.0.127.0 - HSEvent(): EventType --> VALUE_CHANGE
12/11/2017 12:10:22 AM : v2.0.127.0 - HSEvent(): ref --> 2248
12/11/2017 12:10:22 AM : v2.0.127.0 - HSEvent(): doProcess --> True
12/11/2017 12:10:22 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue() started
12/11/2017 12:10:22 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue(): theDeviceReceivedData.ToString -->
DeviceReceivedData:
------------
EventType: VALUE_CHANGE
parms(1): 1024
parms(2): 003D21D1-004-Q226
parms(3): 255
parms(4): 0
parms(5): 2248
So in that case it doesn't appear BLRadar is slow just that it didn't receive the update from HS until that later time. I checked several other examples and they all appeared to confirm the same experience. And sometimes the device never triggers the on or off and in the case of the off being missed the Sensor Recovery will finally kick in.
Another example of it turning off and a 19 second delay:
Dec-11 12:14:43 AM Z-Wave Device: Node 6 Basement Fridge (Light) Set to 0
Dec-11 12:14:43 AM NO ECHO No Echo for Basement Motion Sensor, Echo (1 mins, 39 secs)
Dec-11 12:14:43 AM Device Control Device: Node 6 Basement Fridge (Light) to Off (0) by/from: CAPI Control Handler
Dec-11 12:14:24 AM Z-Wave Device: Node 4 Basement Motion Sensor Set to Off/Closed/No Motion
The value change from 12:14:43 instead of 12:14:24 when BLRadar should have received it:
12/11/2017 12:14:43 AM : v2.0.127.0 - HSEvent(): EventType --> VALUE_CHANGE
12/11/2017 12:14:43 AM : v2.0.127.0 - HSEvent(): ref --> 2248
12/11/2017 12:14:43 AM : v2.0.127.0 - HSEvent(): doProcess --> True
12/11/2017 12:14:43 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue() started
12/11/2017 12:14:43 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue(): theDeviceReceivedData.ToString -->
DeviceReceivedData:
------------
EventType: VALUE_CHANGE
parms(1): 1024
parms(2): 003D21D1-004-Q226
parms(3): 0
parms(4): 255
parms(5): 2248
I decided to try to downgrade from the current HS beta which is .393 and found a version of .379 I had saved and put in the files for it and restarted.
As of now I haven't noticed another delay although I'm still monitoring. Has anyone else noticed this with the newer HS betas? I'm not exactly sure which one the delay was first noticed in, but I think it was in the mid 380's as I know Rich has been working with some of how the queues for the plugins are processed so it is quite possible that one of those changes might be effecting this.
I might need Bob to help confirm this and explain how he receives those values from HS so that Rich can review this further as the last several version of HS have been fairly unreliable with BLRadar because of this.
Thanks,
Jeff
Dec-11 12:10:22 AM Z-Wave Device: Node 6 Basement Fridge (Light) Set to 255
Dec-11 12:10:22 AM Device Control Device: Node 6 Basement Fridge (Light) to On (255) by/from: CAPI Control Handler
Dec-11 12:10:12 AM Z-Wave Device: Node 4 Basement Motion Sensor Set to On/Open/Motion
(10 second delay turning on light from UDMC code for that motion sensor)
In that example the device triggered at 12:10:12 and didn't run the code in BLRadar until 12:10:22 -- so 10 seconds later. So I checked the debug log and sure enough it doesn't appear that BLRadar. So I checked the BLRadar debug log and it appears to confirm that it didn't receive the value change until 12:10:22
12/11/2017 12:10:22 AM : v2.0.127.0 - HSEvent(): EventType --> VALUE_CHANGE
12/11/2017 12:10:22 AM : v2.0.127.0 - HSEvent(): ref --> 2248
12/11/2017 12:10:22 AM : v2.0.127.0 - HSEvent(): doProcess --> True
12/11/2017 12:10:22 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue() started
12/11/2017 12:10:22 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue(): theDeviceReceivedData.ToString -->
DeviceReceivedData:
------------
EventType: VALUE_CHANGE
parms(1): 1024
parms(2): 003D21D1-004-Q226
parms(3): 255
parms(4): 0
parms(5): 2248
So in that case it doesn't appear BLRadar is slow just that it didn't receive the update from HS until that later time. I checked several other examples and they all appeared to confirm the same experience. And sometimes the device never triggers the on or off and in the case of the off being missed the Sensor Recovery will finally kick in.
Another example of it turning off and a 19 second delay:
Dec-11 12:14:43 AM Z-Wave Device: Node 6 Basement Fridge (Light) Set to 0
Dec-11 12:14:43 AM NO ECHO No Echo for Basement Motion Sensor, Echo (1 mins, 39 secs)
Dec-11 12:14:43 AM Device Control Device: Node 6 Basement Fridge (Light) to Off (0) by/from: CAPI Control Handler
Dec-11 12:14:24 AM Z-Wave Device: Node 4 Basement Motion Sensor Set to Off/Closed/No Motion
The value change from 12:14:43 instead of 12:14:24 when BLRadar should have received it:
12/11/2017 12:14:43 AM : v2.0.127.0 - HSEvent(): EventType --> VALUE_CHANGE
12/11/2017 12:14:43 AM : v2.0.127.0 - HSEvent(): ref --> 2248
12/11/2017 12:14:43 AM : v2.0.127.0 - HSEvent(): doProcess --> True
12/11/2017 12:14:43 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue() started
12/11/2017 12:14:43 AM : v2.0.127.0 - DeviceReceivedQueueSingleton.AddDeviceReceivedToQueue(): theDeviceReceivedData.ToString -->
DeviceReceivedData:
------------
EventType: VALUE_CHANGE
parms(1): 1024
parms(2): 003D21D1-004-Q226
parms(3): 0
parms(4): 255
parms(5): 2248
I decided to try to downgrade from the current HS beta which is .393 and found a version of .379 I had saved and put in the files for it and restarted.
As of now I haven't noticed another delay although I'm still monitoring. Has anyone else noticed this with the newer HS betas? I'm not exactly sure which one the delay was first noticed in, but I think it was in the mid 380's as I know Rich has been working with some of how the queues for the plugins are processed so it is quite possible that one of those changes might be effecting this.
I might need Bob to help confirm this and explain how he receives those values from HS so that Rich can review this further as the last several version of HS have been fairly unreliable with BLRadar because of this.
Thanks,
Jeff
Comment