Events being missed.

[ruffle-b]

Version 5.9 (current master pulled 28th Feb zmeventnotification.pl md5sum e19936669c097873c2433bf46e53e36f).

Some events are being missed. I see events in the /var/log/zm/zma_m?.log but no corresponding entry in the /var/log/zm/zmeventnotification.log. This has happened 13 times between 11:24 on the 1st and 10:49 on the 3rd and all on the same monitor (m5). This monitor does have, many, other events 'seen' correctly.

The end result is that I have events left in ZM without any object detection run on them and, obviously, the event_end hook is not being called.

For example Event 41970.

russell@cctv:~$ grep 41970 /var/log/zm/zma_m?.log* 
/var/log/zm/zma_m1.log.1:03/01/20 09:30:52.318034 zma_m1[19727].INF-zm_monitor.cpp/1297 [Carpark: 1419700 - Analysing at 10.00 fps]
/var/log/zm/zma_m3.log.1:03/02/20 03:17:34.679580 zma_m3[21983].INF-zm_monitor.cpp/1297 [Courtyard: 419700 - Analysing at 10.00 fps]
/var/log/zm/zma_m5.log.1:03/01/20 11:24:44.811896 zma_m5[10092].INF-zm_monitor.cpp/1615 [House Gate: 1535081 - Opening new event 41970, alarm start]
/var/log/zm/zma_m5.log.1:03/01/20 11:24:48.028817 zma_m5[10092].INF-zm_monitor.cpp/1656 [House Gate: 1535113 - Left alarm state (41970) - 63(3) images]
/var/log/zm/zma_m5.log.1:03/01/20 11:24:48.029936 zma_m5[10092].INF-zm_monitor.cpp/1661 [House Gate: 1535113 - Closing event 41970, alarm end]
/var/log/zm/zma_m8.log.1:03/01/20 11:04:15.419703 zma_m8[10718].INF-zm_monitor.cpp/1297 [Office Gate: 1102100 - Analysing at 10.00 fps]
/var/log/zm/zma_m8.log.1:03/01/20 22:09:14.318963 zma_m8[10718].INF-zm_monitor.cpp/1297 [Office Gate: 1419700 - Analysing at 5.88 fps]
russell@cctv:~$ 

does not appear in zmeventnotification.log

russell@cctv:~$ grep 41970 /var/log/zm/zmeventnotification.log.1
russell@cctv:~$

zmeventnotification.log.1 does contain the right timeframe:

russell@cctv:~$ head /var/log/zm/zmeventnotification.log.1
01/03/20 08:19:42.821759 zmeventnotification[11432].DBG [main:852] [PARENT: log rotate HUP handler processed, logs re-inited]
01/03/20 08:19:43.888582 zmeventnotification[11432].DBG [main:852] [PARENT: ---------->Tick START<--------------]
01/03/20 08:19:43.888637 zmeventnotification[11432].DBG [main:852] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:1, invalid WEB: 0, PENDING: 0]
01/03/20 08:19:43.888662 zmeventnotification[11432].DBG [main:852] [PARENT: Finished processJobs()]
01/03/20 08:19:43.888780 zmeventnotification[11432].INF [main:861] [PARENT: There are 0 active child forks...]
01/03/20 08:19:43.890025 zmeventnotification[11432].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140250049413120]
01/03/20 08:19:43.890092 zmeventnotification[11432].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
01/03/20 08:19:43.890149 zmeventnotification[11432].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140250049400832]
01/03/20 08:19:43.890178 zmeventnotification[11432].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
01/03/20 08:19:43.890214 zmeventnotification[11432].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140250049392640]
russell@cctv:~$ tail /var/log/zm/zmeventnotification.log.1
02/03/20 06:46:33.896430 zmeventnotification[11432].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
02/03/20 06:46:33.896463 zmeventnotification[11432].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140250049396736]
02/03/20 06:46:33.896487 zmeventnotification[11432].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
02/03/20 06:46:33.896520 zmeventnotification[11432].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140250049388544]
02/03/20 06:46:33.896544 zmeventnotification[11432].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
02/03/20 06:46:33.896577 zmeventnotification[11432].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140250049409024]
02/03/20 06:46:33.896601 zmeventnotification[11432].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
02/03/20 06:46:33.896640 zmeventnotification[11432].DBG [main:852] [PARENT: checkEvents() new events found=0]
02/03/20 06:46:33.896705 zmeventnotification[11432].INF [main:861] [PARENT: There are 0 new Events to process]
02/03/20 06:46:33.897313 zmeventnotification[11432].DBG [main:852] [PARENT: ---------->Tick END<--------------]
russell@cctv:~$ 

Very happy to help debug - what would you like me to do?

[pliablepixels]

It is possible that the ES misses events if they start/close before the polling interval (which you can change in config). If that happens, there isn't much one can do.

[ruffle-b]

OK.. Looking at the timestamps in a selection of the missed events in zma_m?.log they were:

3.21 seconds 3.36 seconds 3.18 seconds 3.40 seconds

....I think I can see the pattern here. As standard, event_check_interval is set to 5. I've cut it down to 3 and I'll see what happens over the next day or so and report back.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.