Object detection and event filters problem.

Forum for questions and support relating to the 1.34.x releases only.
Post Reply
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Object detection and event filters problem.

Post by russell_i_brown »

I'm doing object detection on Modect cameras and running a filter to delete events that don't have "detected:" in the notes.

This is working very well and I'm no longer seeing events featuring bats, birds and bugs :)

However, some events that I expect to see with objects detected are getting deleted. After some digging around I think
it's a timing problem. zmdetect did spot the object but zmfilter was being just a little to keen to delete things.

An event today has a zma log of:

Code: Select all

02/24/20 10:24:47.195667 zma_m5[30745].INF-zm_monitor.cpp/1615 [House Gate: 2451600 - Opening new event 32457, alarm start]
02/24/20 10:24:54.798464 zma_m5[30745].INF-zm_monitor.cpp/1656 [House Gate: 2451676 - Left alarm state (32457) - 107(39) images]
02/24/20 10:24:54.800082 zma_m5[30745].INF-zm_monitor.cpp/1661 [House Gate: 2451676 - Closing event 32457, alarm end]
The zmesdetect log for this event shows:

Code: Select all

02/24/20 10:24:52 zmesdetect_m5[20456] INF zm_detect.py:139 [---------| app version: 5.7.4 |------------]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:229 [secret filename: /etc/zm/secrets.ini]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:203 [Secret token found in config: !ZM_PORTAL]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:203 [Secret token found in config: !ZM_API_PORTAL]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:203 [Secret token found in config: !ZM_USER]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:203 [Secret token found in config: !ZM_PASSWORD]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:203 [Secret token found in config: !PLATEREC_ALPR_KEY]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:254 [allowing self-signed certs to work...]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:273 [[monitor-5] overrides key:wait with value:1]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:273 [[monitor-5] overrides key:import_zm_zones with value:yes]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:273 [[monitor-5] overrides key:match_past_detections with value:yes]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:59 [Getting ZM zones using http://localhost/zm/api/zones/forMonitor/5.json?user=xxx&pass=yyy]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:90 [importing zoneminder polygon: Main [0,79 219,78 273,133 555,152 555,0 636,0 636,163 638,275 639,479 0,479]]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:90 [importing zoneminder polygon: Gate Closeup [76,129 558,157 553,280 78,226]]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [config] is '/var/lib/zmeventnotification/models/yolov3/yolov3.cfg' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [weights] is '/var/lib/zmeventnotification/models/yolov3/yolov3.weights' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [labels] is '/var/lib/zmeventnotification/models/yolov3/yolov3_classes.txt' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [tiny_config] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.cfg' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [tiny_weights] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.weights' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [tiny_labels] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.txt' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] DBG utils.py:304 [key [known_images_path] is '/var/lib/zmeventnotification/known_faces' after substitution]
02/24/20 10:24:52 zmesdetect_m5[20456] INF zm_detect.py:165 [Importing remote shim classes for Yolo/Face]
02/24/20 10:24:52 zmesdetect_m5[20456] INF utils.py:96 [Sleeping for 1 seconds before downloading]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG utils.py:128 [Trying to download http://localhost/zm/index.php?view=image&eid=32457&fid=alarm&username=user&password=*****]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG utils.py:142 [Trying to download http://localhost/zm/index.php?view=image&eid=32457&fid=snapshot&username=user&password=*****]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:206 [resizing to 1200 before analysis...]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG utils.py:37 [resized polygons x=1.0/y=1.0: [{'name': 'Main', 'value': [(0, 79), (219, 78), (273, 133), (555, 152), (555, 0), (636, 0), (636, 163), (638, 275), (639, 479), (0, 479)]}, {'name': 'Gate Closeup', 'value': [(76, 129), (558, 157), (553, 280), (78, 226)]}]]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:224 [User ALPR if vehicle found: False]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:296 [Using model: yolo with /var/lib/zmeventnotification/images/32457-alarm.jpg]
02/24/20 10:24:53 zmesdetect_m5[20456] INF zm_detect.py:40 [Detecting using remote API Gateway http://localhost:5000/api/v1]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:51 [Found token file, checking if token has not expired]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:63 [Access token is valid for 69 more seconds]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG image_manip.py:127 [intersection: polygon in process=[(113, 96), (173, 96), (173, 226), (113, 226)]]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG image_manip.py:133 [Main intersects object:person[[(113, 96), (173, 96), (173, 226), (113, 226)]]]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:480 [ALPR not in use, no need for look aheads in processing]
02/24/20 10:24:53 zmesdetect_m5[20456] INF zm_detect.py:497 [labels found: ['person']]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:498 [match found in /var/lib/zmeventnotification/images/32457-alarm.jpg, breaking file loop...]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:508 [detection mode is set to first, breaking out of model loop...]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:547 [Writing out debug bounding box image to /var/lib/zmeventnotification/images/32457-alarm-bbox.jpg...]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:552 [Writing detected image to /var/cache/zoneminder/events/5/2020-02-24/32457/objdetect.jpg]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:559 [Writing JSON output to /var/cache/zoneminder/events/5/2020-02-24/32457/objects.json]
02/24/20 10:24:53 zmesdetect_m5[20456] INF zm_detect.py:570 [Removing matches to past detections]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG image_manip.py:27 [trying to load /var/lib/zmeventnotification/images/monitor-5-data.pkl]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:573 [Saving detections for monitor 5 for future match]
02/24/20 10:24:53 zmesdetect_m5[20456] INF zm_detect.py:611 [Prediction string:[a] detected:person:99% ]
02/24/20 10:24:53 zmesdetect_m5[20456] DBG zm_detect.py:613 [Prediction string JSON:[{"type": "object", "label": "person", "box": [113, 96, 173, 226], "confidence": "99.04%"}]]
and the zmfilter log

Code: Select all

24/02/20 10:24:55.875541 zmfilter_3[32573].INF [main:1008] [Executing '/usr/local/bin/rbtest /var/cache/zoneminder/events/5/2020-02-24/32457']
24/02/20 10:24:55.913510 zmfilter_3[32573].INF [ZoneMinder::Event:373] [Deleting event 32457 from Monitor 5 StartTime:2020-02-24 10:24:44 from /var/cache/zoneminder/events/5/2020-02-24/32457]
(/usr/local/bin/rbtest is a trivial bash script that copies the event elsewhere to help me debug this issue).

From the above logs, it looks like zmfilter deleted the event some 2 seconds after zmesdetect seemingly completed it's work. Presumably, the "detected:" string should have been added to the notes thereby negating the filter rule but it's taking time to filter back into zmeventnotification and the database.

<edit>Aha... found the evidence of this in zmeventnotification.log. It didn't update the database event until 10:24:56

Code: Select all

24/02/20 10:24:55.779117 zmeventnotification[20452].INF [main:837] [|----> FORK:House Gate (5), eid:32457 Event 32457 for Monitor 5 has finished]
24/02/20 10:24:56.822927 zmeventnotification[31068].INF [main:837] [PARENT: Force updating event 32457 with desc:[a] detected:person:99% ]
So.... the filter could exclude events completed N seconds ago to give time for zmdetect/zmeventnotification to do their stuff.

However, you can't do a filter on "1 minute ago" as filter relative times are not relative to the wall clock but the last filter reload time and guessing on a suitable time window doesn't seem that brilliant a solution.

A somewhat better method would be for the ObjectScore field of Events to be defaulted to -1 and signed, zmeventnotification sets this to zero or the percentage score once the detection has completed and zmfilter is changed to 'understand' filtering on ObjectScore so I can tell it not to select events that have not gone through Object Detection (ObjectScore < 0).

Ummmmm..... comments/suggestions/better ideas?
Last edited by russell_i_brown on Mon Feb 24, 2020 4:57 pm, edited 1 time in total.
Top
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: Object detection and event filters problem.

Post by asker »

I don't use filters, but isn't there an attribute where you can filter based on "age" of an event? You could probably set a filter that doesn't consider events whose End Dates are at least, say, 2 minutes from current time? Or did you say filters don't operate on current time?
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Correct - according to the documentation, filters work on FILTER_RELOAD_DELAY time so "1 minute ago" does not do what's expected with respect to wall clock time.

See section 2.7.4 here: https://readthedocs.org/projects/zonemi ... df/stable/

As I said above, using some 'magic' amount of time to determine if zmeventnotification has done its stuff really doesn't sound 'right'.
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Oh.... just for anyone else tuning in to this thread.... Asker's motion detection stuff really does make a huge huge difference to the usability of Zoneminder.

I'm still running a 'conventional' version and a test-rig with object detection and automagic event deletion. For the same camera I have 964 events for the week using conventional motion detection and only 66 for the object detection version; pretty much all of which do feature something of genuine interest (person, car, truck)... and the motion detection 'sensitivity' on the test-rig monitor setup is actually set higher than the 'conventional' version.

This now means that one can glance at the ZM home page and get a meaningful overview or show the event counts in something like Homeassistant and not get deluged with zillions of 'false' triggers that, let's face it, you never look at.

It's a game changer.
Top
User avatar
iconnor
Posts: 3197
Joined: Fri Oct 29, 2010 1:43 am
Location: Toronto
Contact:
Contact iconnor

Re: Object detection and event filters problem.

Post by iconnor »

The ZM_FILTER_RELOAD option is for how long the zmfilter process updates the filter terms from db... FILTER_EXECUTE_INTERVAL controls how long it sleeps between executions. Neither of these is useful. You need to add a term to the filter like StartDate/Time less than -5 minutes or something like that.
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Thanks for that Isaac.

Any time based solution (only delete after N seconds) is not pretty IMHO. So that means that either ZM's tables and filters have to be modified to work nicely with object detection or, having thought about it a bit more, zmeventnotification could delete events itself if no object is detected.

As I can't compile zoneminder at the moment (it's moaning about my libavformat.so.58 not having dependency information as it's not come from a package; true I compiled ffmpeg 4.1.4 to support my nvidia) I guess I'll explore the latter.
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Well.. that was easy. A change to zm_event_end.sh seems to do the trick nicely. As the name suggests, it's called from zmeventnotification at the end of an event so the object detection will have been run.

A touch on the crude side as it assumes a) you're running the script on the same host as ZM and b) that you're not using OPT_AUTH so calls to the API are simple. It'll do as a proof of concept.

Here's the modified script if anyone else wants to play the same game. Simply copy it to /var/lib/zmeventnotification/bin/zm_event_end.sh

Code: Select all

#!/bin/bash

# Just a dummy script for event end. Do what you want here

# When invoked by zmeventnotification.pl it will be passed:
# $1 = eventId that triggered an alarm
# $2 = monitor ID of monitor that triggered an alarm
# $3 = monitor Name of monitor that triggered an alarm
# $4 = cause of alarm 

# If people run it as is, without modifying it, lets make sure we 
# return the cause back so its sent in the notification
echo "${4}"
#echo "$(date): POST EVENT FOR EID:${1} FOR MONITOR ${2} NAME ${3} CAUSE ${4}" > /tmp/post_log.txt
#
#       RB Mod. Delete events with no object detection. Rather crude as it assumes you're
#       running ZM on localhost and not using OPT_AUTH but it works for me.
case "${4}" in
        *detected:*)
                echo "$(date) Preserve Event ${1} ${3} ${4}" >> /tmp/post_log.txt
                ;;
        *)
                echo "$(date) Delete Event ${1} ${3} ${4}" >> /tmp/post_log.txt
                curl -s -XDELETE http://localhost/zm/api/events/${1}.json >> /tmp/post_log.txt 2>&1
                ;;
esac

exit 0
It works for me after several minutes testing :)
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Oh Poo :-( Spoke too soon.

It doesn't work for either longer events or events with multiple zones - not sure which.

The event log below shows it detected objects and changed the Event Notes (at 18:04:04) to include "detected:".... but by the time zmeventnotification called zm_event_end.sh (18:05:15.146443) the Event.Notes had been changed and no longer contained "detected:".

FWIW, this event (I was watching it live) did go from Alarm to Alert to Alarm a couple of times and involved two zones (Close and Far - original eh?). The initial value of Event.Notes seems to have been "Motion Close" and something changed it to "Motion: Close, Far" overwriting the object detection info.

zmeventnotification.log:

Code: Select all

25/02/20 18:03:59.244167 zmeventnotification[27120].INF [main:837] [PARENT: New event 33640 reported for Monitor:1 (Name:Carpark) Motion Close]
25/02/20 18:03:59.253335 zmeventnotification[7391].INF [main:837] [PARENT: Forked process:7391 to handle alarm eid:33640]
25/02/20 18:03:59.258175 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 33640 1 "Carpark" "Motion Close" "/var/cache/zoneminder/events/1/2020-02-25/33640"]
25/02/20 18:04:01.125038 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 hook start returned with text:[a] detected:person:57% car:57%  json:[{"type": "object", "label": "person", "box": [210, 394, 272, 478], "confidence": "56.85%"}, {"type": "object", "label": "car", "box": [308, 54, 364, 116], "confidence": "56.75%"}, {"type": "object", "label": "car", "box": [248, 58, 276, 78], "confidence": "36.89%"}] exit:0]
25/02/20 18:04:03.127094 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Matching alarm to connection rules...]
25/02/20 18:04:03.128796 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Checking alarm rules for MQTT 192.168.1.125]
25/02/20 18:04:03.129654 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Monitor 1 event: should send out as  1317.74662995338 is >= interval of ]
25/02/20 18:04:03.131465 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Sending event_start notification for EID:33640 over MQTT]
25/02/20 18:04:04.247773 zmeventnotification[27120].INF [main:837] [PARENT: Force updating event 33640 with desc:[a] detected:person:57% car:57% ]
25/02/20 18:05:13.143001 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Event 33640 for Monitor 1 has finished]
25/02/20 18:05:15.146443 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 33640 1 "Carpark" "Motion: Close, Far" "/var/cache/zoneminder/events/1/2020-02-25/33640"]
25/02/20 18:05:15.252672 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 hook end returned with text:Motion: Close, Far  json:[] exit:0]
25/02/20 18:05:17.254343 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Matching alarm to connection rules...]
25/02/20 18:05:17.256399 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
25/02/20 18:05:21.258467 zmeventnotification[7391].INF [main:837] [|----> FORK:Carpark (1), eid:33640 Ending process:7391 to handle alarms]
as a comparison, here's a (admittedly shorter and single zone) event where Event.Notes did not get re-written and everything was peachy (although it does seem to have grown a colon between 'Motion' and 'All').

Code: Select all

25/02/20 18:04:49.243526 zmeventnotification[27120].INF [main:837] [PARENT: New event 33642 reported for Monitor:8 (Name:Office Gate) Motion All]
25/02/20 18:04:49.250831 zmeventnotification[15587].INF [main:837] [PARENT: Forked process:15587 to handle alarm eid:33642]
25/02/20 18:04:49.254455 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 33642 8 "Office Gate" "Motion All" "/var/cache/zoneminder/events/8/2020-02-25/33642"]
25/02/20 18:04:51.310206 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 hook start returned with text:[s] detected:car:98%  json:[{"type": "object", "label": "car", "box": [32, 284, 214, 364], "confidence": "98.11%"}] exit:0]
25/02/20 18:04:53.312063 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Matching alarm to connection rules...]
25/02/20 18:04:53.314159 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Checking alarm rules for MQTT 192.168.1.125]
25/02/20 18:04:53.315876 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Monitor 8 event: should send out as  504.654979944229 is >= interval of ]
25/02/20 18:04:53.317182 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Sending event_start notification for EID:33642 over MQTT]
25/02/20 18:04:54.247086 zmeventnotification[27120].INF [main:837] [PARENT: Force updating event 33642 with desc:[s] detected:car:98% ]
25/02/20 18:05:01.320187 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Event 33642 for Monitor 8 has finished]
25/02/20 18:05:03.322929 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 33642 8 "Office Gate" "[s] detected:car:98%  Motion: All" "/var/cache/zoneminder/events/8/2020-02-25/33642"]
25/02/20 18:05:03.334036 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 hook end returned with text:[s] detected:car:98%  Motion: All  json:[] exit:0]
25/02/20 18:05:05.336485 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Matching alarm to connection rules...]
25/02/20 18:05:05.338678 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
25/02/20 18:05:09.340805 zmeventnotification[15587].INF [main:837] [|----> FORK:Office Gate (8), eid:33642 Ending process:15587 to handle alarms]
You can see that at 18:05:03.322929 the "detected:" string was still part of Event.Notes.

Is it intentional that ZM will overwrite Event.Notes as the event progresses? If so, this will not only cast my cunning plan into the pit-of-despair but may impact on other aspects of zmeventnotification as it's carefully recorded detection info will be erased <thinks>this might also explain why some other events got unexpectedly deleted by my filter.

Comments from the knowledgeable ?
Top
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: Object detection and event filters problem.

Post by asker »

Yes, it is a problem. ZM seems to overwrites events with its own notes instead of concat, so if ZM detects a motion _after_ the ES writes detected, it will overwrite. Not nice.
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Oh dear - that isn't nice :-(

For my purposes, would it be possible for zmeventnotification to pass the original detection string to zm_event_end.sh ? (as arg 5 so as not to break existing uses).
Top
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: Object detection and event filters problem.

Post by asker »

Not a bad idea to add it as $5 anyway - but I prefer if it did not get deleted.
I've made a change to the ES to try and write it back
See https://github.com/pliablepixels/zmeven ... issues/224

Please give master a try - I did not test it
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Sadly, version 5.9 seems to be missing events.

I have an event 34541 on Monitor 5 at 10:01:23 to 10:01:31 that, obviously, shows up in the zma logs but there's no sign of it in the zmeventnotification log :( "grep 34541 zm/zmeventnotification.log" produces nothing.

Events 34550 and 34552 were handled by zmeventnotification.

zma_m5.log

Code: Select all

02/26/20 10:01:07.675236 zma_m5[975].INF-zm_monitor.cpp/1297 [House Gate: 1577900 - Analysing at 10.00 fps]
02/26/20 10:01:17.674575 zma_m5[975].INF-zm_monitor.cpp/1297 [House Gate: 1578000 - Analysing at 10.00 fps]
02/26/20 10:01:26.814757 zma_m5[975].INF-zm_monitor.cpp/1638 [House Gate: 1578091 - Gone into prealarm state]
02/26/20 10:01:26.885200 zma_m5[975].INF-zm_monitor.cpp/1564 [House Gate: 1578092 - Gone into alarm state PreAlarmCount: 1 > AlarmFrameCount:2 Cause:Motion Gate Closeup]
02/26/20 10:01:26.887153 zma_m5[975].INF-zm_monitor.cpp/1615 [House Gate: 1578092 - Opening new event 34541, alarm start]
02/26/20 10:01:27.658461 zma_m5[975].INF-zm_monitor.cpp/1297 [House Gate: 1578100 - Analysing at 10.00 fps]
02/26/20 10:01:28.674217 zma_m5[975].INF-zm_monitor.cpp/1648 [House Gate: 1578110 - Gone into alert state]
02/26/20 10:01:31.687507 zma_m5[975].INF-zm_monitor.cpp/1656 [House Gate: 1578140 - Left alarm state (34541) - 79(19) images]
02/26/20 10:01:31.688777 zma_m5[975].INF-zm_monitor.cpp/1661 [House Gate: 1578140 - Closing event 34541, alarm end]
02/26/20 10:01:31.693034 zma_m5[975].INF-zm_event.cpp/588 [Updating frames delta by -4.77 sec to match video file]
02/26/20 10:01:37.703313 zma_m5[975].INF-zm_monitor.cpp/1297 [House Gate: 1578200 - Analysing at 10.00 fps]
02/26/20 10:01:47.667313 zma_m5[975].INF-zm_monitor.cpp/1297 [House Gate: 1578300 - Analysing at 10.00 fps]
02/26/20 10:01:57.689308 zma_m5[975].INF-zm_monitor.cpp/1297 [House Gate: 1578400 - Analysing at 10.00 fps]
zmeventnotification.log

Code: Select all

26/02/20 10:01:21.699961 zmeventnotification[31038].INF [main:836] [PARENT: There are 0 new Events to process]
26/02/20 10:01:21.702593 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick END<--------------]
26/02/20 10:01:26.695009 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick START<--------------]
26/02/20 10:01:26.695075 zmeventnotification[31038].DBG [main:827] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:1, invalid WEB: 0, PENDING: 0]
26/02/20 10:01:26.695106 zmeventnotification[31038].DBG [main:827] [PARENT: Finished processJobs()]
26/02/20 10:01:26.695198 zmeventnotification[31038].INF [main:836] [PARENT: There are 0 active child forks...]
26/02/20 10:01:26.696389 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078124544]
26/02/20 10:01:26.696463 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 10:01:26.696523 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 10:01:26.696559 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 10:01:26.696671 zmeventnotification[31038].INF [main:836] [PARENT: New event 34539 reported for Monitor:6 (Name:Car Port) Motion All]
26/02/20 10:01:26.697321 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 10:01:26.697407 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 10:01:26.697463 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078104064]
26/02/20 10:01:26.697498 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 7: 1]
26/02/20 10:01:26.697543 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 10:01:26.697575 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 10:01:26.697676 zmeventnotification[31038].INF [main:836] [PARENT: New event 34540 reported for Monitor:3 (Name:Courtyard) Linked]
26/02/20 10:01:26.698780 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078128640]
26/02/20 10:01:26.698857 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
26/02/20 10:01:26.698918 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078116352]
26/02/20 10:01:26.698956 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
26/02/20 10:01:26.699005 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 10:01:26.699040 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 10:01:26.699096 zmeventnotification[31038].DBG [main:827] [PARENT: checkEvents() new events found=2]
26/02/20 10:01:26.699167 zmeventnotification[31038].INF [main:836] [PARENT: There are 2 new Events to process]
26/02/20 10:01:26.701624 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick END<--------------]
26/02/20 10:01:26.703772 zmeventnotification[4523].INF [main:836] [PARENT: Forked process:4523 to handle alarm eid:34539]
26/02/20 10:01:26.704736 zmeventnotification[4524].INF [main:836] [PARENT: Forked process:4524 to handle alarm eid:34540]
26/02/20 10:01:26.705391 zmeventnotification[4523].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34539]
26/02/20 10:01:26.705677 zmeventnotification[4524].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34540]
26/02/20 10:01:26.706202 zmeventnotification[4523].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 10:01:26.706354 zmeventnotification[4524].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 10:01:26.707038 zmeventnotification[4524].DBG [main:827] [|----> FORK:Courtyard (3), eid:34540 Adding event path:/var/cache/zoneminder/events/3/2020-02-26/34540 to hook for image storage]
26/02/20 10:01:26.707040 zmeventnotification[4523].DBG [main:827] [|----> FORK:Car Port (6), eid:34539 Adding event path:/var/cache/zoneminder/events/6/2020-02-26/34539 to hook for image storage]
26/02/20 10:01:26.707143 zmeventnotification[4524].INF [main:836] [|----> FORK:Courtyard (3), eid:34540 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34540 3 "Courtyard" "Linked" "/var/cache/zoneminder/events/3/2020-02-26/34540"]
26/02/20 10:01:26.707150 zmeventnotification[4523].INF [main:836] [|----> FORK:Car Port (6), eid:34539 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34539 6 "Car Port" "Motion All" "/var/cache/zoneminder/events/6/2020-02-26/34539"]
26/02/20 10:01:29.014745 zmeventnotification[4523].DBG [main:827] [|----> FORK:Car Port (6), eid:34539 parse of hook: and []]
26/02/20 10:01:29.014928 zmeventnotification[4523].INF [main:836] [|----> FORK:Car Port (6), eid:34539 hook start returned with text: json:[] exit:1]
26/02/20 10:01:29.016049 zmeventnotification[4523].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 10:01:29.016164 zmeventnotification[4523].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 10:01:29.182493 zmeventnotification[4524].DBG [main:827] [|----> FORK:Courtyard (3), eid:34540 parse of hook: and []]
26/02/20 10:01:29.182712 zmeventnotification[4524].INF [main:836] [|----> FORK:Courtyard (3), eid:34540 hook start returned with text: json:[] exit:1]
26/02/20 10:01:29.183787 zmeventnotification[4524].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 10:01:29.183918 zmeventnotification[4524].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 10:01:31.016627 zmeventnotification[4523].INF [main:836] [|----> FORK:Car Port (6), eid:34539 Matching alarm to connection rules...]
26/02/20 10:01:31.018448 zmeventnotification[4523].INF [main:836] [|----> FORK:Car Port (6), eid:34539 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 10:01:31.019906 zmeventnotification[4523].INF [main:836] [|----> FORK:Car Port (6), eid:34539 Monitor 6 event: should send out as  30.2002398967743 is >= interval of ]
26/02/20 10:01:31.020753 zmeventnotification[4523].DBG [main:827] [|----> FORK:Car Port (6), eid:34539 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 10:01:31.020970 zmeventnotification[4523].DBG [main:827] [|----> FORK:Car Port (6), eid:34539 isAllowedChannel: got type:event_start resCode:1]
26/02/20 10:01:31.021119 zmeventnotification[4523].INF [main:836] [|----> FORK:Car Port (6), eid:34539 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 10:01:31.023779 zmeventnotification[4523].DBG [main:827] [|----> FORK:Car Port (6), eid:34539 child finished writing to parent]
26/02/20 10:01:31.023858 zmeventnotification[4523].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 10:01:31.023962 zmeventnotification[4523].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 10:01:31.184338 zmeventnotification[4524].INF [main:836] [|----> FORK:Courtyard (3), eid:34540 Matching alarm to connection rules...]
26/02/20 10:01:31.185854 zmeventnotification[4524].INF [main:836] [|----> FORK:Courtyard (3), eid:34540 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 10:01:31.187302 zmeventnotification[4524].INF [main:836] [|----> FORK:Courtyard (3), eid:34540 Monitor 3 event: should send out as  54.3144400119781 is >= interval of ]
26/02/20 10:01:31.188514 zmeventnotification[4524].DBG [main:827] [|----> FORK:Courtyard (3), eid:34540 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 10:01:31.188699 zmeventnotification[4524].DBG [main:827] [|----> FORK:Courtyard (3), eid:34540 isAllowedChannel: got type:event_start resCode:1]
26/02/20 10:01:31.188830 zmeventnotification[4524].INF [main:836] [|----> FORK:Courtyard (3), eid:34540 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 10:01:31.189640 zmeventnotification[4524].DBG [main:827] [|----> FORK:Courtyard (3), eid:34540 child finished writing to parent]
26/02/20 10:01:31.189703 zmeventnotification[4524].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 10:01:31.189791 zmeventnotification[4524].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 10:01:31.693621 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick START<--------------]
26/02/20 10:01:31.693787 zmeventnotification[31038].DBG [main:827] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:1, invalid WEB: 0, PENDING: 0]
26/02/20 10:01:31.694291 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--6--SPLIT--1582711291.02083]
26/02/20 10:01:31.694428 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:6 to 1582711291.02083 for id:]
26/02/20 10:01:31.694808 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--3--SPLIT--1582711291.18858]
26/02/20 10:01:31.694918 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:3 to 1582711291.18858 for id:]
26/02/20 10:01:31.694986 zmeventnotification[31038].DBG [main:827] [PARENT: Finished processJobs()]
26/02/20 10:01:31.695286 zmeventnotification[31038].INF [main:836] [PARENT: There are 2 active child forks...]
26/02/20 10:01:31.696565 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078124544]
26/02/20 10:01:31.696759 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 10:01:31.697139 zmeventnotification[31038].INF [main:836] [PARENT: New event 34543 reported for Monitor:2 (Name:Reception) Motion All]
26/02/20 10:01:31.698251 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 10:01:31.698377 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 10:01:31.698495 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:6, Event:34539, not doing anything more]
26/02/20 10:01:31.698539 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 10:01:31.698605 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 10:01:31.698694 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078104064]
26/02/20 10:01:31.698757 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 7: 1]
26/02/20 10:01:31.698846 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 10:01:31.698910 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 10:01:31.699007 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34540, not doing anything more]
26/02/20 10:01:31.699044 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078128640]
26/02/20 10:01:31.699103 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
26/02/20 10:01:31.699190 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078116352]
26/02/20 10:01:31.699255 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
26/02/20 10:01:31.699465 zmeventnotification[31038].INF [main:836] [PARENT: New event 34542 reported for Monitor:4 (Name:Patio) Motion All]
26/02/20 10:01:31.700137 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 10:01:31.700235 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 10:01:31.700345 zmeventnotification[31038].DBG [main:827] [PARENT: checkEvents() new events found=2]
26/02/20 10:01:31.700466 zmeventnotification[31038].INF [main:836] [PARENT: There are 2 new Events to process]
26/02/20 10:01:31.704425 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick END<--------------]
26/02/20 10:01:31.708043 zmeventnotification[5331].INF [main:836] [PARENT: Forked process:5331 to handle alarm eid:34543]
26/02/20 10:01:31.709006 zmeventnotification[5332].INF [main:836] [PARENT: Forked process:5332 to handle alarm eid:34542]
26/02/20 10:01:31.709841 zmeventnotification[5331].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34543]
26/02/20 10:01:31.710706 zmeventnotification[5332].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34542]
26/02/20 10:01:31.711012 zmeventnotification[5331].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 10:01:31.711875 zmeventnotification[5332].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 10:01:31.712368 zmeventnotification[5331].DBG [main:827] [|----> FORK:Reception (2), eid:34543 Adding event path:/var/cache/zoneminder/events/2/2020-02-26/34543 to hook for image storage]
26/02/20 10:01:31.712550 zmeventnotification[5331].INF [main:836] [|----> FORK:Reception (2), eid:34543 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34543 2 "Reception" "Motion All" "/var/cache/zoneminder/events/2/2020-02-26/34543"]
26/02/20 10:01:31.713287 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 Adding event path:/var/cache/zoneminder/events/4/2020-02-26/34542 to hook for image storage]
26/02/20 10:01:31.713493 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34542 4 "Patio" "Motion All" "/var/cache/zoneminder/events/4/2020-02-26/34542"]
26/02/20 10:01:33.024154 zmeventnotification[4523].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 10:01:33.024300 zmeventnotification[4523].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 10:01:33.190036 zmeventnotification[4524].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 10:01:33.190183 zmeventnotification[4524].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 10:01:33.844041 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 parse of hook: and []]
26/02/20 10:01:33.844232 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 hook start returned with text: json:[] exit:1]
26/02/20 10:01:33.844900 zmeventnotification[5332].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078116352]
26/02/20 10:01:33.845018 zmeventnotification[5332].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
26/02/20 10:01:35.024517 zmeventnotification[4523].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 10:01:35.024703 zmeventnotification[4523].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 10:01:35.190426 zmeventnotification[4524].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 10:01:35.190564 zmeventnotification[4524].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 10:01:35.845310 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 Matching alarm to connection rules...]
26/02/20 10:01:35.846527 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 10:01:35.846751 zmeventnotification[5331].DBG [main:827] [|----> FORK:Reception (2), eid:34543 parse of hook: and []]
26/02/20 10:01:35.846912 zmeventnotification[5331].INF [main:836] [|----> FORK:Reception (2), eid:34543 hook start returned with text: json:[] exit:1]
26/02/20 10:01:35.847153 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 Monitor 4 event: should send out as  58.6586699485779 is >= interval of ]
26/02/20 10:01:35.847718 zmeventnotification[5331].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078124544]
26/02/20 10:01:35.847841 zmeventnotification[5331].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 10:01:35.847986 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 10:01:35.848076 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 isAllowedChannel: got type:event_start resCode:1]
26/02/20 10:01:35.848142 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 10:01:35.848641 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 child finished writing to parent]
26/02/20 10:01:35.848671 zmeventnotification[5332].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078116352]
26/02/20 10:01:35.848710 zmeventnotification[5332].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
26/02/20 10:01:35.848749 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 For 4 (Patio), SHM says: state=0, eid=34542]
26/02/20 10:01:35.848804 zmeventnotification[5332].INF [main:836] [|----> FORK:Patio (4), eid:34542 Event 34542 for Monitor 4 has finished]
26/02/20 10:01:35.849608 zmeventnotification[5332].DBG [main:827] [|----> FORK:Patio (4), eid:34542 Event end object is: state=>pending with cause=>Motion: All]
26/02/20 10:01:36.693524 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick START<--------------]
26/02/20 10:01:36.693629 zmeventnotification[31038].DBG [main:827] [PARENT: MQTT tick interval (15 sec) elapsed.]
26/02/20 10:01:36.693956 zmeventnotification[31038].DBG [main:827] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:1, invalid WEB: 0, PENDING: 0]
26/02/20 10:01:36.694483 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--4--SPLIT--1582711295.84802]
26/02/20 10:01:36.694637 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:4 to 1582711295.84802 for id:]
26/02/20 10:01:36.694712 zmeventnotification[31038].DBG [main:827] [PARENT: Finished processJobs()]
Other events are being picked up from this and other monitors and the only change since yesterday is pulling v5.9, stopping zmeventnotification, installing with install.sh and restarting as per your docs. I did not overwrite my existing .ini files.

Very happy to debug if you tell me what you'd like me to do.

PS - This could have been happening before updating to 5.9 but as I was running the filter to delete events without "detected:" in the Notes I would not have noticed them lying around in the ZM console view. Now the event deletion is being handled by zm_event_end.sh, events that zmeventnotification hasn't handled will remain untouched.
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

Ahh... yes - just found other events that zmeventnotification didn't 'see' before I upgraded to 5.9.

Code: Select all

MariaDB [zm]> select Id,MonitorId,StartTime,EndTime,Notes from Events where Notes NOT like "%detected:%" and StorageId < 2;
+-------+-----------+---------------------+---------------------+----------------------+
| Id    | MonitorId | StartTime           | EndTime             | Notes                |
+-------+-----------+---------------------+---------------------+----------------------+
| 33653 |         5 | 2020-02-25 18:14:02 | 2020-02-25 18:14:08 | Motion: Gate Closeup |
| 33731 |         5 | 2020-02-25 18:51:57 | 2020-02-25 18:52:03 | Motion: Gate Closeup |
| 33847 |         5 | 2020-02-25 19:33:17 | 2020-02-25 19:33:23 | Motion: Gate Closeup |
| 33877 |         5 | 2020-02-25 19:51:52 | 2020-02-25 19:51:58 | Motion: Gate Closeup |
| 34152 |         5 | 2020-02-26 01:29:01 | 2020-02-26 01:29:08 | Motion: Gate Closeup |
| 34541 |         5 | 2020-02-26 10:01:23 | 2020-02-26 10:01:31 | Motion: Gate Closeup |
| 34735 |         5 | 2020-02-26 11:23:24 | 2020-02-26 11:23:31 | Motion: Gate Closeup |
+-------+-----------+---------------------+---------------------+----------------------+
10 rows in set (0.00 sec)

MariaDB [zm]>
I turned off my deletion filter yesterday PM so these are events that didn't have object detection run on them.

So.... how can I help debug this?
Top
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: Object detection and event filters problem.

Post by asker »

For the moment let's not conflate two unrelated issues into one.

The changes I made were specifically to make sure the detection text was not overwritten for long running events where ZM added motion notes after the detection was over. Was that resolved?

Once we resolve that, we can look at what is causing the ES to miss certain events. This discussion may benefit from being more real-time, if you'd like to join the ZM slack channel (see GitHub).
I no longer work on zmNinja, zmeventnotification, pyzm or mlapi. I may respond on occasion based on my available time/interest.

Please read before posting:
How to set up logging properly
How to troubleshoot and report - ES
How to troubleshoot and report - zmNinja
ES docs
zmNinja docs
Top
russell_i_brown
Posts: 42
Joined: Wed Mar 18, 2009 9:46 am
Location: Peterborough, England

Re: Object detection and event filters problem.

Post by russell_i_brown »

asker wrote: ↑Wed Feb 26, 2020 1:30 pm For the moment let's not conflate two unrelated issues into one.
Sorry - getting over enthusiastic :) It's sooooo close to being brilliant!
The changes I made were specifically to make sure the detection text was not overwritten for long running events where ZM added motion notes after the detection was over. Was that resolved?
Sadly it doesn't appear so. Here an event that got an object detected but by the time zm_event_end.sh was called it had lost "detected:"

grep 34885 zmeventnotification.log

Code: Select all

26/02/20 10:22:46.134885 zmeventnotification[19906].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 13:00:56.697677 zmeventnotification[31038].INF [main:836] [PARENT: New event 34885 reported for Monitor:3 (Name:Courtyard) Linked]
26/02/20 13:00:56.709650 zmeventnotification[4492].INF [main:836] [PARENT: Forked process:4492 to handle alarm eid:34885]
26/02/20 13:00:56.711584 zmeventnotification[4492].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34885]
26/02/20 13:00:56.714289 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 Adding event path:/var/cache/zoneminder/events/3/2020-02-26/34885 to hook for image storage]
26/02/20 13:00:56.714483 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34885 3 "Courtyard" "Linked" "/var/cache/zoneminder/events/3/2020-02-26/34885"]
26/02/20 13:00:58.820972 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 parse of hook:[a] detected:person:86%  and [{"type": "object", "label": "person", "box": [295, 80, 311, 118], "confidence": "85.99%"}]]
26/02/20 13:00:58.821176 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 hook start returned with text:[a] detected:person:86%  json:[{"type": "object", "label": "person", "box": [295, 80, 311, 118], "confidence": "85.99%"}] exit:0]
26/02/20 13:01:00.823139 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Matching alarm to connection rules...]
26/02/20 13:01:00.825460 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 13:01:00.827285 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Monitor 3 event: should send out as  58.7969601154327 is >= interval of ]
26/02/20 13:01:00.828435 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 13:01:00.828726 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 isAllowedChannel: got type:event_start resCode:0]
26/02/20 13:01:00.828941 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Sending event_start notification for EID:34885 over MQTT]
26/02/20 13:01:00.830662 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 requesting MQTT Publishing Job for EID:34885]
26/02/20 13:01:00.830841 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 child finished writing to parent]
26/02/20 13:01:01.699703 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->active_event_update--TYPE--3--SPLIT--34885--SPLIT--Start--SPLIT--Cause--SPLIT--[a] detected:person:86%  Linked--JSON--]
26/02/20 13:01:01.699820 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update active_event eid:34885, mid:3, type:Start, field:Cause to: [a] detected:person:86%  Linked--JSON--]
26/02/20 13:01:01.700153 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->event_description--TYPE--3--SPLIT--34885--SPLIT--[a] detected:person:86% ]
26/02/20 13:01:01.700385 zmeventnotification[31038].INF [main:836] [PARENT: Force updating event 34885 with desc:[a] detected:person:86% ]
26/02/20 13:01:01.701253 zmeventnotification[31038].DBG [main:827] [PARENT: updating Notes clause for Event:34885 with:[a] detected:person:86%  ]
26/02/20 13:01:01.705168 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->mqtt_publish--TYPE----SPLIT--zoneminder/3--SPLIT--{"hookvalue":"0","monitor":"3","eventtype":"event_start","name":"Courtyard:(34885) [a] detected:person:86%  Linked","state":"alarm","detection":[{"confidence":"85.99%","type":"object","label":"person","box":[295,80,311,118]}],"eventid":"34885"}]
26/02/20 13:01:01.708110 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:06.699107 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:11.696931 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:16.696226 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:21.693968 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:26.699902 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:31.696220 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:36.699858 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34885, not doing anything more]
26/02/20 13:01:38.839717 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 For 3 (Courtyard), SHM says: state=0, eid=34885]
26/02/20 13:01:38.839884 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Event 34885 for Monitor 3 has finished]
26/02/20 13:01:38.842058 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 Event end object is: state=>pending with cause=>Linked: Car PortMotion: Courtyard]
26/02/20 13:01:40.842751 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 Adding event path:/var/cache/zoneminder/events/3/2020-02-26/34885 to hook for image storage]
26/02/20 13:01:40.842977 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 34885 3 "Courtyard" "Linked: Car PortMotion: Courtyard" "/var/cache/zoneminder/events/3/2020-02-26/34885"]
26/02/20 13:01:40.926762 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 parse of hook:Linked: Car PortMotion: Courtyard and []]
26/02/20 13:01:40.927031 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 hook end returned with text:Linked: Car PortMotion: Courtyard  json:[] exit:0]
26/02/20 13:01:42.929179 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Matching alarm to connection rules...]
26/02/20 13:01:42.931252 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 isAllowedChannel: got type:event_end resCode:0]
26/02/20 13:01:42.931500 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 13:01:42.932686 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 child finished writing to parent]
26/02/20 13:01:46.934082 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 Making sure the detection text was not overwritten by ZM]
26/02/20 13:01:46.935084 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 ZM overwrote detection, adding detection notes back into DB [[a] detected:person:86% ]]
26/02/20 13:01:46.935247 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 updating Notes clause for Event:34885 with:[a] detected:person:86%   ]
26/02/20 13:01:46.936265 zmeventnotification[4492].DBG [main:827] [|----> FORK:Courtyard (3), eid:34885 exiting]
26/02/20 13:01:46.936602 zmeventnotification[4492].INF [main:836] [|----> FORK:Courtyard (3), eid:34885 Ending process:4492 to handle alarms]
26/02/20 13:01:51.693859 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->active_event_delete--TYPE--3--SPLIT--34885]
26/02/20 13:01:51.693927 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Deleting active_event eid:34885, mid:3]
longer extract of zmeventnotification.log for context:

Code: Select all

26/02/20 12:57:06.700150 zmeventnotification[31038].INF [main:836] [PARENT: New event 34855 reported for Monitor:6 (Name:Car Port) Motion, Linked All]
26/02/20 12:57:06.701643 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078124544]
26/02/20 12:57:06.701814 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 12:57:06.701960 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:06.702043 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:06.702303 zmeventnotification[31038].INF [main:836] [PARENT: New event 34857 reported for Monitor:8 (Name:Office Gate) Motion All]
26/02/20 12:57:06.703618 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:06.703784 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:06.704123 zmeventnotification[31038].INF [main:836] [PARENT: New event 34856 reported for Monitor:3 (Name:Courtyard) Motion, Linked Gate & Carports]
26/02/20 12:57:06.705149 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078104064]
26/02/20 12:57:06.705335 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 7: 1]
26/02/20 12:57:06.705554 zmeventnotification[31038].DBG [main:827] [PARENT: checkEvents() new events found=4]
26/02/20 12:57:06.705719 zmeventnotification[31038].INF [main:836] [PARENT: There are 4 new Events to process]
26/02/20 12:57:06.713524 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick END<--------------]
26/02/20 12:57:06.716690 zmeventnotification[30785].INF [main:836] [PARENT: Forked process:30785 to handle alarm eid:34854]
26/02/20 12:57:06.719925 zmeventnotification[30786].INF [main:836] [PARENT: Forked process:30786 to handle alarm eid:34855]
26/02/20 12:57:06.720024 zmeventnotification[30788].INF [main:836] [PARENT: Forked process:30788 to handle alarm eid:34856]
26/02/20 12:57:06.722741 zmeventnotification[30788].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34856]
26/02/20 12:57:06.723413 zmeventnotification[30786].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34855]
26/02/20 12:57:06.724260 zmeventnotification[30788].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 12:57:06.724263 zmeventnotification[30785].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34854]
26/02/20 12:57:06.725060 zmeventnotification[30786].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 12:57:06.725648 zmeventnotification[30785].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 12:57:06.725895 zmeventnotification[30788].DBG [main:827] [|----> FORK:Courtyard (3), eid:34856 Adding event path:/var/cache/zoneminder/events/3/2020-02-26/34856 to hook for image storage]
26/02/20 12:57:06.726104 zmeventnotification[30788].INF [main:836] [|----> FORK:Courtyard (3), eid:34856 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34856 3 "Courtyard" "Motion, Linked Gate & Carports" "/var/cache/zoneminder/events/3/2020-02-26/34856"]
26/02/20 12:57:06.726355 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 Adding event path:/var/cache/zoneminder/events/6/2020-02-26/34855 to hook for image storage]
26/02/20 12:57:06.726554 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34855 6 "Car Port" "Motion, Linked All" "/var/cache/zoneminder/events/6/2020-02-26/34855"]
26/02/20 12:57:06.727457 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 Adding event path:/var/cache/zoneminder/events/5/2020-02-26/34854 to hook for image storage]
26/02/20 12:57:06.727833 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34854 5 "House Gate" "Motion Gate Closeup" "/var/cache/zoneminder/events/5/2020-02-26/34854"]
26/02/20 12:57:06.736071 zmeventnotification[30787].INF [main:836] [PARENT: Forked process:30787 to handle alarm eid:34857]
26/02/20 12:57:06.737614 zmeventnotification[30787].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34857]
26/02/20 12:57:06.738521 zmeventnotification[30787].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 12:57:06.739329 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 Adding event path:/var/cache/zoneminder/events/8/2020-02-26/34857 to hook for image storage]
26/02/20 12:57:06.739644 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34857 8 "Office Gate" "Motion All" "/var/cache/zoneminder/events/8/2020-02-26/34857"]
26/02/20 12:57:09.099159 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 parse of hook:[a] detected:car:100%  and [{"type": "object", "label": "car", "box": [120, 276, 290, 350], "confidence": "99.68%"}]]
26/02/20 12:57:09.099356 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 hook start returned with text:[a] detected:car:100%  json:[{"type": "object", "label": "car", "box": [120, 276, 290, 350], "confidence": "99.68%"}] exit:0]
26/02/20 12:57:09.100682 zmeventnotification[30787].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:09.100803 zmeventnotification[30787].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:09.459247 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 parse of hook: and []]
26/02/20 12:57:09.459419 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 hook start returned with text: json:[] exit:1]
26/02/20 12:57:09.460755 zmeventnotification[30786].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:09.460870 zmeventnotification[30786].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:09.633963 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 parse of hook: and []]
26/02/20 12:57:09.634194 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 hook start returned with text: json:[] exit:1]
26/02/20 12:57:09.635245 zmeventnotification[30785].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:09.635372 zmeventnotification[30785].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:09.635442 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 For 5 (House Gate), SHM says: state=0, eid=34854]
26/02/20 12:57:09.635515 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Event 34854 for Monitor 5 has finished]
26/02/20 12:57:09.636968 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 Event end object is: state=>pending with cause=>Motion: Gate Closeup, Main]
26/02/20 12:57:09.805819 zmeventnotification[30788].DBG [main:827] [|----> FORK:Courtyard (3), eid:34856 parse of hook: and []]
26/02/20 12:57:09.806009 zmeventnotification[30788].INF [main:836] [|----> FORK:Courtyard (3), eid:34856 hook start returned with text: json:[] exit:1]
26/02/20 12:57:09.807525 zmeventnotification[30788].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:09.807650 zmeventnotification[30788].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:11.101202 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Matching alarm to connection rules...]
26/02/20 12:57:11.102873 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 12:57:11.104141 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Monitor 8 event: should send out as  31.3709700107574 is >= interval of ]
26/02/20 12:57:11.105411 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 12:57:11.105592 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 isAllowedChannel: got type:event_start resCode:0]
26/02/20 12:57:11.105763 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Sending event_start notification for EID:34857 over MQTT]
26/02/20 12:57:11.107096 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 requesting MQTT Publishing Job for EID:34857]
26/02/20 12:57:11.107210 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 child finished writing to parent]
26/02/20 12:57:11.107266 zmeventnotification[30787].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:11.107370 zmeventnotification[30787].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:11.461512 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Matching alarm to connection rules...]
26/02/20 12:57:11.463650 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 12:57:11.464974 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Monitor 6 event: should send out as  109.668509960175 is >= interval of ]
26/02/20 12:57:11.466442 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 12:57:11.466698 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 isAllowedChannel: got type:event_start resCode:1]
26/02/20 12:57:11.466875 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 12:57:11.467960 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 child finished writing to parent]
26/02/20 12:57:11.468060 zmeventnotification[30786].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:11.468182 zmeventnotification[30786].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:11.637374 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Matching alarm to connection rules...]
26/02/20 12:57:11.639282 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 12:57:11.640628 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Monitor 5 event: should send out as  109.843389987946 is >= interval of ]
26/02/20 12:57:11.641662 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 12:57:11.641897 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 isAllowedChannel: got type:event_start resCode:1]
26/02/20 12:57:11.642063 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 12:57:11.643461 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 child finished writing to parent]
26/02/20 12:57:11.643543 zmeventnotification[30785].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:11.643657 zmeventnotification[30785].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:11.693947 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick START<--------------]
26/02/20 12:57:11.694140 zmeventnotification[31038].DBG [main:827] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:1, invalid WEB: 0, PENDING: 0]
26/02/20 12:57:11.694951 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->active_event_update--TYPE--8--SPLIT--34857--SPLIT--Start--SPLIT--Cause--SPLIT--[a] detected:car:100%  Motion All--JSON--]
26/02/20 12:57:11.695182 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update active_event eid:34857, mid:8, type:Start, field:Cause to: [a] detected:car:100%  Motion All--JSON--]
26/02/20 12:57:11.695612 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->event_description--TYPE--8--SPLIT--34857--SPLIT--[a] detected:car:100% ]
26/02/20 12:57:11.695717 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update monitor 8 description:[a] detected:car:100% ]
26/02/20 12:57:11.696049 zmeventnotification[31038].INF [main:836] [PARENT: Force updating event 34857 with desc:[a] detected:car:100% ]
26/02/20 12:57:11.698259 zmeventnotification[31038].DBG [main:827] [PARENT: updating Notes clause for Event:34857 with:[a] detected:car:100%  ]
26/02/20 12:57:11.701763 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->mqtt_publish--TYPE----SPLIT--zoneminder/8--SPLIT--{"eventid":"34857","detection":[{"box":[120,276,290,350],"type":"object","confidence":"99.68%","label":"car"}],"state":"alarm","eventtype":"event_start","name":"Office Gate:(34857) [a] detected:car:100%  Motion All","monitor":"8","hookvalue":"0"}]
26/02/20 12:57:11.701900 zmeventnotification[31038].DBG [main:827] [PARENT: Job: MQTT Publish on topic: zoneminder/8]
26/02/20 12:57:11.702417 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--8--SPLIT--1582721831.10548]
26/02/20 12:57:11.702530 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:8 to 1582721831.10548 for id:]
26/02/20 12:57:11.702839 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--6--SPLIT--1582721831.46653]
26/02/20 12:57:11.702912 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:6 to 1582721831.46653 for id:]
26/02/20 12:57:11.703217 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--5--SPLIT--1582721831.64174]
26/02/20 12:57:11.703303 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:5 to 1582721831.64174 for id:]
26/02/20 12:57:11.703374 zmeventnotification[31038].DBG [main:827] [PARENT: Finished processJobs()]
26/02/20 12:57:11.703558 zmeventnotification[31038].INF [main:836] [PARENT: There are 4 active child forks...]
26/02/20 12:57:11.705135 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078128640]
26/02/20 12:57:11.705332 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
26/02/20 12:57:11.705578 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078116352]
26/02/20 12:57:11.705660 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
26/02/20 12:57:11.705767 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:11.705839 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:11.705937 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:11.706006 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:11.706125 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:6, Event:34855, not doing anything more]
26/02/20 12:57:11.706167 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078124544]
26/02/20 12:57:11.706233 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 12:57:11.706334 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:11.706404 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:11.706528 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:8, Event:34857, not doing anything more]
26/02/20 12:57:11.706572 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:11.706642 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:11.706765 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34856, not doing anything more]
26/02/20 12:57:11.706809 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078104064]
26/02/20 12:57:11.706879 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 7: 1]
26/02/20 12:57:11.706999 zmeventnotification[31038].DBG [main:827] [PARENT: checkEvents() new events found=0]
26/02/20 12:57:11.707156 zmeventnotification[31038].INF [main:836] [PARENT: There are 0 new Events to process]
26/02/20 12:57:11.708645 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick END<--------------]
26/02/20 12:57:11.808264 zmeventnotification[30788].INF [main:836] [|----> FORK:Courtyard (3), eid:34856 Matching alarm to connection rules...]
26/02/20 12:57:11.810448 zmeventnotification[30788].INF [main:836] [|----> FORK:Courtyard (3), eid:34856 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 12:57:11.813861 zmeventnotification[30788].INF [main:836] [|----> FORK:Courtyard (3), eid:34856 Monitor 3 event: should send out as  109.478749990463 is >= interval of ]
26/02/20 12:57:11.815478 zmeventnotification[30788].DBG [main:827] [|----> FORK:Courtyard (3), eid:34856 shouldSendEventToConn returned true, so calling sendEvent]
26/02/20 12:57:11.815765 zmeventnotification[30788].DBG [main:827] [|----> FORK:Courtyard (3), eid:34856 isAllowedChannel: got type:event_start resCode:1]
26/02/20 12:57:11.815979 zmeventnotification[30788].INF [main:836] [|----> FORK:Courtyard (3), eid:34856 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 12:57:11.817047 zmeventnotification[30788].DBG [main:827] [|----> FORK:Courtyard (3), eid:34856 child finished writing to parent]
26/02/20 12:57:11.817145 zmeventnotification[30788].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:11.817277 zmeventnotification[30788].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:13.107552 zmeventnotification[30787].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:13.107634 zmeventnotification[30787].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:13.468381 zmeventnotification[30786].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:13.468475 zmeventnotification[30786].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:13.644711 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 Adding event path:/var/cache/zoneminder/events/5/2020-02-26/34854 to hook for image storage]
26/02/20 12:57:13.644904 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 34854 5 "House Gate" "Motion: Gate Closeup, Main" "/var/cache/zoneminder/events/5/2020-02-26/34854"]
26/02/20 12:57:13.694822 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 parse of hook:Motion: Gate Closeup, Main and []]
26/02/20 12:57:13.695216 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 hook end returned with text:Motion: Gate Closeup, Main  json:[] exit:0]
26/02/20 12:57:13.696701 zmeventnotification[30785].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:13.696896 zmeventnotification[30785].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:13.817631 zmeventnotification[30788].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:13.817840 zmeventnotification[30788].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:15.107829 zmeventnotification[30787].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:15.108023 zmeventnotification[30787].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:15.108140 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 For 8 (Office Gate), SHM says: state=0, eid=34857]
26/02/20 12:57:15.108365 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Event 34857 for Monitor 8 has finished]
26/02/20 12:57:15.110863 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 Event end object is: state=>pending with cause=>[a] detected:car:100%  Motion: All]
26/02/20 12:57:15.468673 zmeventnotification[30786].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:15.468863 zmeventnotification[30786].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:15.468990 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 For 6 (Car Port), SHM says: state=0, eid=34855]
26/02/20 12:57:15.469191 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Event 34855 for Monitor 6 has finished]
26/02/20 12:57:15.471650 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 Event end object is: state=>pending with cause=>Linked: House GateMotion: All]
26/02/20 12:57:15.697233 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Not sending event end alarm, as we did not send a start alarm for this, or start hook processing failed]
26/02/20 12:57:15.698362 zmeventnotification[30785].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:15.698435 zmeventnotification[30785].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:15.818124 zmeventnotification[30788].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:15.818252 zmeventnotification[30788].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:16.696233 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick START<--------------]
26/02/20 12:57:16.696364 zmeventnotification[31038].DBG [main:827] [PARENT: MQTT tick interval (15 sec) elapsed.]
26/02/20 12:57:16.696525 zmeventnotification[31038].DBG [main:827] [PARENT: After tick: TOTAL: 1,  ES_CONTROL: 1, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:1, invalid WEB: 0, PENDING: 0]
26/02/20 12:57:16.696937 zmeventnotification[31038].DBG [main:827] [PARENT: RAW TEXT-->timestamp--TYPE----SPLIT--3--SPLIT--1582721831.81558]
26/02/20 12:57:16.697035 zmeventnotification[31038].DBG [main:827] [PARENT: Job: Update last sent timestamp of monitor:3 to 1582721831.81558 for id:]
26/02/20 12:57:16.697129 zmeventnotification[31038].DBG [main:827] [PARENT: Finished processJobs()]
26/02/20 12:57:16.697330 zmeventnotification[31038].INF [main:836] [PARENT: There are 4 active child forks...]
26/02/20 12:57:16.699023 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078128640]
26/02/20 12:57:16.699206 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
26/02/20 12:57:16.699366 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078116352]
26/02/20 12:57:16.699456 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
26/02/20 12:57:16.699588 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:16.699676 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:16.699829 zmeventnotification[31038].DBG [main:827] [PARENT: Closing unclosed event:34854 of Monitor:5 as we are in a new event]
26/02/20 12:57:16.700670 zmeventnotification[31038].INF [main:836] [PARENT: New event 34858 reported for Monitor:5 (Name:House Gate) Motion Gate Closeup]
26/02/20 12:57:16.701805 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:16.701994 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:16.702189 zmeventnotification[31038].DBG [main:827] [PARENT: Closing unclosed event:34855 of Monitor:6 as we are in a new event]
26/02/20 12:57:16.702914 zmeventnotification[31038].INF [main:836] [PARENT: New event 34859 reported for Monitor:6 (Name:Car Port) Linked]
26/02/20 12:57:16.704901 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078124544]
26/02/20 12:57:16.705083 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
26/02/20 12:57:16.705232 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:16.705324 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:16.705573 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:16.705669 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:16.705845 zmeventnotification[31038].DBG [main:827] [PARENT: We've already worked on Monitor:3, Event:34856, not doing anything more]
26/02/20 12:57:16.705914 zmeventnotification[31038].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078104064]
26/02/20 12:57:16.706003 zmeventnotification[31038].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 7: 1]
26/02/20 12:57:16.706139 zmeventnotification[31038].DBG [main:827] [PARENT: checkEvents() new events found=2]
26/02/20 12:57:16.706318 zmeventnotification[31038].INF [main:836] [PARENT: There are 2 new Events to process]
26/02/20 12:57:16.712425 zmeventnotification[31038].DBG [main:827] [PARENT: ---------->Tick END<--------------]
26/02/20 12:57:16.716350 zmeventnotification[32477].INF [main:836] [PARENT: Forked process:32477 to handle alarm eid:34858]
26/02/20 12:57:16.717465 zmeventnotification[32478].INF [main:836] [PARENT: Forked process:32478 to handle alarm eid:34859]
26/02/20 12:57:16.718502 zmeventnotification[32477].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34858]
26/02/20 12:57:16.720085 zmeventnotification[32477].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 12:57:16.719618 zmeventnotification[32478].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 34859]
26/02/20 12:57:16.721505 zmeventnotification[32478].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Storage from Storage WHERE Id = 1]
26/02/20 12:57:16.721686 zmeventnotification[32477].DBG [main:827] [|----> FORK:House Gate (5), eid:34858 Adding event path:/var/cache/zoneminder/events/5/2020-02-26/34858 to hook for image storage]
26/02/20 12:57:16.721893 zmeventnotification[32477].INF [main:836] [|----> FORK:House Gate (5), eid:34858 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34858 5 "House Gate" "Motion Gate Closeup" "/var/cache/zoneminder/events/5/2020-02-26/34858"]
26/02/20 12:57:16.722730 zmeventnotification[32478].DBG [main:827] [|----> FORK:Car Port (6), eid:34859 Adding event path:/var/cache/zoneminder/events/6/2020-02-26/34859 to hook for image storage]
26/02/20 12:57:16.722927 zmeventnotification[32478].INF [main:836] [|----> FORK:Car Port (6), eid:34859 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 34859 6 "Car Port" "Linked" "/var/cache/zoneminder/events/6/2020-02-26/34859"]
26/02/20 12:57:17.112581 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 Adding event path:/var/cache/zoneminder/events/8/2020-02-26/34857 to hook for image storage]
26/02/20 12:57:17.112690 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 34857 8 "Office Gate" "[a] detected:car:100%  Motion: All" "/var/cache/zoneminder/events/8/2020-02-26/34857"]
26/02/20 12:57:17.119641 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 parse of hook:[a] detected:car:100%  Motion: All and []]
26/02/20 12:57:17.119833 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 hook end returned with text:[a] detected:car:100%  Motion: All  json:[] exit:0]
26/02/20 12:57:17.120906 zmeventnotification[30787].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:17.121006 zmeventnotification[30787].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:17.472409 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 Adding event path:/var/cache/zoneminder/events/6/2020-02-26/34855 to hook for image storage]
26/02/20 12:57:17.472605 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 34855 6 "Car Port" "Linked: House GateMotion: All" "/var/cache/zoneminder/events/6/2020-02-26/34855"]
26/02/20 12:57:17.528842 zmeventnotification[30786].DBG [main:827] [|----> FORK:Car Port (6), eid:34855 parse of hook:Linked: House GateMotion: All and []]
26/02/20 12:57:17.529217 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 hook end returned with text:Linked: House GateMotion: All  json:[] exit:0]
26/02/20 12:57:17.531321 zmeventnotification[30786].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:17.531522 zmeventnotification[30786].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:17.698753 zmeventnotification[30785].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:17.698947 zmeventnotification[30785].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:17.818439 zmeventnotification[30788].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:17.818563 zmeventnotification[30788].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:19.049579 zmeventnotification[32477].DBG [main:827] [|----> FORK:House Gate (5), eid:34858 parse of hook: and []]
26/02/20 12:57:19.049764 zmeventnotification[32477].INF [main:836] [|----> FORK:House Gate (5), eid:34858 hook start returned with text: json:[] exit:1]
26/02/20 12:57:19.050824 zmeventnotification[32477].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078112256]
26/02/20 12:57:19.050937 zmeventnotification[32477].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 5: 1]
26/02/20 12:57:19.121262 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Matching alarm to connection rules...]
26/02/20 12:57:19.122520 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 isAllowedChannel: got type:event_end resCode:0]
26/02/20 12:57:19.122596 zmeventnotification[30787].INF [main:836] [|----> FORK:Office Gate (8), eid:34857 Not sending over MQTT as notify filters are on_success:all and on_fail:none]
26/02/20 12:57:19.123231 zmeventnotification[30787].DBG [main:827] [|----> FORK:Office Gate (8), eid:34857 child finished writing to parent]
26/02/20 12:57:19.123263 zmeventnotification[30787].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078099968]
26/02/20 12:57:19.123311 zmeventnotification[30787].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 8: 1]
26/02/20 12:57:19.220866 zmeventnotification[32478].DBG [main:827] [|----> FORK:Car Port (6), eid:34859 parse of hook: and []]
26/02/20 12:57:19.221065 zmeventnotification[32478].INF [main:836] [|----> FORK:Car Port (6), eid:34859 hook start returned with text: json:[] exit:1]
26/02/20 12:57:19.222266 zmeventnotification[32478].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:19.222390 zmeventnotification[32478].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:19.531942 zmeventnotification[30786].INF [main:836] [|----> FORK:Car Port (6), eid:34855 Not sending event end alarm, as we did not send a start alarm for this, or start hook processing failed]
26/02/20 12:57:19.533328 zmeventnotification[30786].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078108160]
26/02/20 12:57:19.533477 zmeventnotification[30786].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 6: 1]
26/02/20 12:57:19.699225 zmeventnotification[30785].DBG [main:827] [|----> FORK:House Gate (5), eid:34854 exiting]
26/02/20 12:57:19.699495 zmeventnotification[30785].INF [main:836] [|----> FORK:House Gate (5), eid:34854 Ending process:30785 to handle alarms]
26/02/20 12:57:19.818791 zmeventnotification[30788].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140257078120448]
26/02/20 12:57:19.818922 zmeventnotification[30788].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 3: 1]
26/02/20 12:57:21.051271 zmeventnotification[32477].INF [main:836] [|----> FORK:House Gate (5), eid:34858 Matching alarm to connection rules...]
26/02/20 12:57:21.052418 zmeventnotification[32477].INF [main:836] [|----> FORK:House Gate (5), eid:34858 Checking alarm rules for MQTT 192.168.1.125]
26/02/20 12:57:21.053558 zmeventnotification[32477].INF [main:836] [|----> FORK:House Gate (5), eid:34858 Monitor 5 event: should send out as  9.35825991630554 is >= interval of ]
Once we resolve that, we can look at what is causing the ES to miss certain events. This discussion may benefit from being more real-time, if you'd like to join the ZM slack channel (see GitHub).
OK (although real-time will be constrained by time-zones and w*rk interruptions at least on my side)
Top
Post Reply

Return to “ZoneMinder 1.34.x”