zmeventnotification start hook strange issue with one camera

Forum for questions and support relating to the 1.34.x releases only.
Post Reply
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

zmeventnotification start hook strange issue with one camera

Post by dave_88 »

ZM 1.34.19
ES 5.15

Hi All,

Installed Events Server recently and am really impressed. I just have one small issue with the start hook when used on one particular camera.

Code: Select all

[monitor-2]
models=yolo,face
detection_mode=all
When ZM generates an alarm, the start hook runs and seems to detect an object match, however zmeventnotification.log states exit code 1 (nothing detected).

Here is an example of what I mean...

Code: Select all

root@cctv:/var/lib/zmeventnotification/bin# cat /var/log/zm/zmesdetect_m2.log | grep 19654 | more
08/20/20 16:52:25 zmesdetect_m2[13092] DBG1 utils.py:166 [Trying to download https://XX/index.php?view=image&eid=19654&fid=alarm&username=admin&password=*****]
08/20/20 16:52:25 zmesdetect_m2[13092] DBG1 utils.py:185 [Trying to download https://XX/index.php?view=image&eid=19654&fid=snapshot&username=admin&password=*****]
08/20/20 16:52:27 zmesdetect_m2[13092] DBG1 zm_detect.py:373 [Using model: face with /var/lib/zmeventnotification/images/19654-alarm.jpg]
08/20/20 16:52:27 zmesdetect_m2[13092] DBG1 zm_detect.py:631 [No match found in /var/lib/zmeventnotification/images/19654-alarm.jpg using model:face]
08/20/20 16:52:27 zmesdetect_m2[13092] DBG1 zm_detect.py:373 [Using model: face with /var/lib/zmeventnotification/images/19654-snapshot.jpg]
08/20/20 16:52:28 zmesdetect_m2[13092] DBG1 zm_detect.py:631 [No match found in /var/lib/zmeventnotification/images/19654-snapshot.jpg using model:face]
08/20/20 16:52:28 zmesdetect_m2[13092] DBG1 zm_detect.py:373 [Using model: yolo with /var/lib/zmeventnotification/images/19654-alarm.jpg]
08/20/20 16:52:29 zmesdetect_m2[13092] DBG2 zm_detect.py:622 [match found in /var/lib/zmeventnotification/images/19654-alarm.jpg, breaking file loop...]
As you can see on the last line yolo finds a match so should be returning exit code 0 with a string of what it has detected?

Code: Select all

root@cctv:/var/lib/zmeventnotification/bin# cat /var/log/zm/zmeventnotification.log | grep 19654
20/08/20 16:52:24.975241 zmeventnotification[11655].INF [main:892] [PARENT: New event 19654 reported for Monitor:2 (Name:Front-Door) Motion FrontGarden[last processed eid:]]
20/08/20 16:52:25.059922 zmeventnotification[13088].DBG [main:883] [PARENT: Forked process:13088 to handle alarm eid:19654]
20/08/20 16:52:25.102006 zmeventnotification[13088].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 19654]
20/08/20 16:52:25.102826 zmeventnotification[13088].DBG [main:883] [|----> FORK:Front-Door (2), eid:19654 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 19654 2 "Front-Door" "Motion FrontGarden" "/mnt/md0/events/2/2020-08-20/19654"]
20/08/20 16:52:29.693864 zmeventnotification[13088].DBG [main:883] [|----> FORK:Front-Door (2), eid:19654 hook start returned with text: json:[] exit:1]
Looking at the last line in this log shows it didn't return anything.

I am very confused, this works fine with other cameras, and if I run '/var/lib/zmeventnotification/bin/zm_event_start.sh' 19654 2 "Front-Door" "Motion FrontGarden" "/mnt/md0/events/2/2020-08-20/19654" manually then it does exit code 0 with a JSON string as you would expect.

Any suggestions would be great!
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: zmeventnotification start hook strange issue with one camera

Post by dave_88 »

Just switched to yolo only for all camras and done a litle more debugging. It seems that that zm_detect.py isnt writing the JSON string for some reason, cant work out why.

I compared the zmesdetect_m*.log files for the camera that won't work and one that does.

***WORKING CAMERA***

Code: Select all

08/20/20 20:22:54 zmesdetect_m3[26965] DBG1 zm_detect.py:267 [No polygon area specfied, so adding a full image polygon:[{'name': 'full_image', 'value': [(0, 0), (1920, 0), (1920, 1080), (0, 1080)]}]]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG1 zm_detect.py:270 [resizing to 1200 before analysis...]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG2 utils.py:38 [resized polygons x=0.625/y=0.625: [{'name': 'full_image', 'value': [(0, 0), (1200, 0), (1200, 675), (0, 675)]}]]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG1 zm_detect.py:291 [User ALPR if vehicle found: False]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG1 zm_detect.py:373 [Using model: yolo with /var/lib/zmeventnotification/images/20094-alarm.jpg]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG1 yolo.py:48 [|---------- YOLO (input image: 1200w*675h, resized to: 416w*416h) ----------|]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG1 yolo.py:59 [Initializing Yolo]
08/20/20 20:22:54 zmesdetect_m3[26965] DBG2 yolo.py:61 [config:/var/lib/zmeventnotification/models/yolov3/yolov3.cfg, weights:/var/lib/zmeventnotification/models/yolov3/yolov3.weights]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 yolo.py:83 [Not using CUDA backend]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 yolo.py:88 [YOLO initialization (loading model from disk) took: 441.67 milliseconds]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 yolo.py:103 [YOLO detection took: 465.288 milliseconds]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 yolo.py:136 [YOLO NMS filtering took: 0.739 milliseconds]
08/20/20 20:22:55 zmesdetect_m3[26965] INF yolo.py:162 [object:person at [173, 296, 513, 678] has a acceptable confidence:0.9815893769264221 compared to min confidence of: 0.3, adding]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG2 image_manip.py:282 [intersection: polygon in process=[(173, 296), (513, 296), (513, 678), (173, 678)]]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG2 image_manip.py:289 [full_image intersects object:person[[(173, 296), (513, 296), (513, 678), (173, 678)]]]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG2 zm_detect.py:602 [ALPR not in use, no need for look aheads in processing]
08/20/20 20:22:55 zmesdetect_m3[26965] INF zm_detect.py:619 [labels found: ['person']]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG2 zm_detect.py:622 [match found in /var/lib/zmeventnotification/images/20094-alarm.jpg, breaking file loop...]
08/20/20 20:22:55 zmesdetect_m3[26965] INF zm_detect.py:660 [Removing matches to past detections]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG2 image_manip.py:164 [trying to load /var/lib/zmeventnotification/images/monitor-3-data.pkl]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 zm_detect.py:666 [Saving detections for monitor 3 for future match]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 zm_detect.py:696 [Writing out debug bounding box image to /var/lib/zmeventnotification/images/20094-alarm-bbox.jpg...]
08/20/20 20:22:55 zmesdetect_m3[26965] DBG1 zm_detect.py:703 [Writing detected image to /mnt/md0/events/3/2020-08-20/20094/objdetect.jpg]
08/20/20 20:22:56 zmesdetect_m3[26965] DBG1 zm_detect.py:707 [Writing JSON output to /mnt/md0/events/3/2020-08-20/20094/objects.json]
08/20/20 20:22:56 zmesdetect_m3[26965] INF zm_detect.py:761 [Prediction string:[a] detected:person:98% ]
08/20/20 20:22:56 zmesdetect_m3[26965] DBG1 zm_detect.py:764 [Prediction string JSON:[{"type": "object", "label": "person", "box": [173, 296, 513, 678], "confidence": "98.16%"}]]
**EOF**
***NOT WORKING CAMERA***

Code: Select all

08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 zm_detect.py:267 [No polygon area specfied, so adding a full image polygon:[{'name': 'full_image', 'value': [(0, 0), (2048, 0), (2048, 2048), (0, 2048)]}]]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 zm_detect.py:270 [resizing to 1200 before analysis...]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG2 utils.py:38 [resized polygons x=0.5859375/y=0.5859375: [{'name': 'full_image', 'value': [(0, 0), (1200, 0), (1200, 1200), (0, 1200)]}]]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 zm_detect.py:291 [User ALPR if vehicle found: False]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 zm_detect.py:373 [Using model: yolo with /var/lib/zmeventnotification/images/20079-alarm.jpg]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 yolo.py:48 [|---------- YOLO (input image: 1200w*1200h, resized to: 416w*416h) ----------|]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 yolo.py:59 [Initializing Yolo]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG2 yolo.py:61 [config:/var/lib/zmeventnotification/models/yolov3/yolov3.cfg, weights:/var/lib/zmeventnotification/models/yolov3/yolov3.weights]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 yolo.py:83 [Not using CUDA backend]
08/20/20 20:03:48 zmesdetect_m2[26606] DBG1 yolo.py:88 [YOLO initialization (loading model from disk) took: 57.769 milliseconds]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG1 yolo.py:103 [YOLO detection took: 440.549 milliseconds]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG1 yolo.py:136 [YOLO NMS filtering took: 0.71 milliseconds]
08/20/20 20:03:49 zmesdetect_m2[26606] INF yolo.py:162 [object:person at [472, 356, 694, 700] has a acceptable confidence:0.9916108846664429 compared to min confidence of: 0.3, adding]
08/20/20 20:03:49 zmesdetect_m2[26606] INF yolo.py:162 [object:car at [348, 42, 722, 160] has a acceptable confidence:0.6264652609825134 compared to min confidence of: 0.3, adding]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 image_manip.py:282 [intersection: polygon in process=[(472, 356), (694, 356), (694, 700), (472, 700)]]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 image_manip.py:289 [full_image intersects object:person[[(472, 356), (694, 356), (694, 700), (472, 700)]]]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 image_manip.py:282 [intersection: polygon in process=[(348, 42), (722, 42), (722, 160), (348, 160)]]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 image_manip.py:289 [full_image intersects object:car[[(348, 42), (722, 42), (722, 160), (348, 160)]]]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 zm_detect.py:602 [ALPR not in use, no need for look aheads in processing]
08/20/20 20:03:49 zmesdetect_m2[26606] INF zm_detect.py:619 [labels found: ['person', 'car']]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 zm_detect.py:622 [match found in /var/lib/zmeventnotification/images/20079-alarm.jpg, breaking file loop...]
08/20/20 20:03:49 zmesdetect_m2[26606] INF zm_detect.py:660 [Removing matches to past detections]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG2 image_manip.py:164 [trying to load /var/lib/zmeventnotification/images/monitor-2-data.pkl]
08/20/20 20:03:49 zmesdetect_m2[26606] DBG1 zm_detect.py:666 [Saving detections for monitor 2 for future match]
**EOF**
The difference seems to be on the last few lines of the "working camera". On the "non-working" camera, zm_detect.py isn't forming the JSON string at the end and assuming not setting the exit code to 0 either. I must be missing something obvious here!

Looking at the zmeventnotification log, it originally called the start hook like this (which seemed to find objects but return no JSON and ext code 1)...

Code: Select all

FORK:Front-Door (2), eid:20079 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 20079 2 "Front-Door" "Motion FrontGarden" "/mnt/md0/events/2/2020-08-20/20079"]
If I run that same command manually afterwards, it works!

Code: Select all

root@cctv:/home/cctv# '/var/lib/zmeventnotification/bin/zm_event_start.sh' 20079 2 "Front-Door" "Motion FrontGarden" "/mnt/md0/events/2/2020-08-20/20079"]
[a] detected:person:99% car:63% --SPLIT--[{"type": "object", "label": "person", "box": [472, 356, 694, 700], "confidence": "99.16%"}, {"type": "object", "label": "car", "box": [348, 42, 722, 160], "confidence": "62.65%"}]
Stumped now...any help would be appreciated :D
User avatar
asker
Posts: 1553
Joined: Sun Mar 01, 2015 12:12 pm

Re: zmeventnotification start hook strange issue with one camera

Post by asker »

Thanks for the detailed reporting. Makes life easier for me to respond.
If I run that same command manually afterwards, it works!

Code: Select all

root@cctv:/home/cctv# '/var/lib/zmeventnotification/bin/zm_event_start.sh' 20079 2 "Front-Door" <etc>
logs from bad camera:

Code: Select all

08/20/20 20:03:49 zmesdetect_m2[26606] DBG1 zm_detect.py:666 [Saving detections for monitor 2 for future match]
**EOF**
I think what may be happening is your permissions are not set to www-data somewhere in /var/lib/zmeventnotification and specifically permissions for /var/lib/zmeventnotification/images/*.pkl. That should not be the last line in logs, and if it is, it may mean detect is crashing out. I've added exception handling to that part in master.

I noticed that when you ran in command line, you ran as root. If you have match past detections on, and while testing, you ran it the first time from command line, it might have created monitor-2-data.pkl as root and now when running the detection (which runs as www-data) it can't write.

Try disabling match past detections to test for that monitor or fix permissions.


Finally, I'd recommend you switch to master. I'm very close to releasing 6.0 that has breaking changes. See viewtopic.php?f=33&t=29848
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
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: zmeventnotification start hook strange issue with one camera

Post by dave_88 »

You mean like this:

Code: Select all

-rw-r--r-- 1 root     root     97 Aug 20 20:48 /var/lib/zmeventnotification/images/monitor-2-data.pkl
-rw-r--r-- 1 www-data www-data 59 Aug 20 20:22 /var/lib/zmeventnotification/images/monitor-3-data.pkl
-rw-r--r-- 1 www-data www-data 85 Aug 20 16:50 /var/lib/zmeventnotification/images/monitor-4-data.pkl
-rw-r--r-- 1 www-data www-data 56 Aug 20 14:20 /var/lib/zmeventnotification/images/monitor-5-data.pkl
Bang on! Thanks. I shall also take your advice and upgrade to master when I get some playtime.

:D
dave_88
Posts: 34
Joined: Mon Feb 25, 2019 6:15 pm
Location: Northamptonshire, England UK

Re: zmeventnotification start hook strange issue with one camera

Post by dave_88 »

Just upgraded to ES 6, but having a slight issue with my preview images no longer appearing in the notifications...

Posted here as suppose its now a new topic...
viewtopic.php?f=40&t=29950
Post Reply