ZoneMinder / zmeventnotification

Machine Learning powered Secure Websocket & MQTT based ZoneMinder event notification server
416 stars 129 forks source link

Sometimes there are duplicate entries in event notes. #238

Closed connectnet closed 4 years ago

connectnet commented 4 years ago

Event Server version = 5.9.9 Hooks version = 5.9.9 The version of ZoneMinder you are using: = 1.34.6 What is the nature of your issue = Bug Details: Duplicate entries in event notes. double-entries

Thanks for fixing!

pliablepixels commented 4 years ago

I think this was fixed a few weeks ago, make sure you have the latest zm_event_end script - please update to master and use the install.sh script

connectnet commented 4 years ago

Event Server version = 5.10 Hooks version = 5.10 Problem remains as described.

pliablepixels commented 4 years ago

Debug logs.

connectnet commented 4 years ago

ok. that may take some time.

connectnet commented 4 years ago

Faster as expected: 2020-03-18 19-12-29

Streetcam


03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:254 [secret filename: /etc/zm/secrets.ini]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !ZM_PORTAL]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !ZM_API_PORTAL]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !ZM_USER]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !ZM_PASSWORD]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !ML_USER]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !ML_PASSWORD]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:227 [Secret token found in config: !PLATEREC_ALPR_KEY]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:277 [allowing self-signed certs to work...]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:296 [[monitor-4] overrides key:wait with value:5]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:296 [[monitor-4] overrides key:detect_pattern with value:.*]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:296 [[monitor-4] overrides key:poly_color with value:(255,0,0)]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:296 [[monitor-4] overrides key:models with value:yolo]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [config] is '/var/lib/zmeventnotification/models/yolov3/yolov3.cfg' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [weights] is '/var/lib/zmeventnotification/models/yolov3/yolov3.weights' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [labels] is '/var/lib/zmeventnotification/models/yolov3/yolov3_classes.txt' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [tiny_config] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.cfg' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [tiny_weights] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.weights' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [tiny_labels] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.txt' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [known_images_path] is '/var/lib/zmeventnotification/known_faces' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] DBG utils.py:332 [key [unknown_images_path] is '/var/lib/zmeventnotification/unknown_faces' after substitution]
03/18/20 18:08:02 zmesdetect_m4[763] INF zm_detect.py:180 [Importing local classes for Yolo/Face]
03/18/20 18:08:03 zmesdetect_m4[763] INF utils.py:99 [Sleeping for 5 seconds before downloading]
03/18/20 18:08:08 zmesdetect_m4[763] DBG utils.py:140 [Trying to download http://**.**.**.**/zm/index.php?view=image&eid=3457&fid=alarm&username=demo&password=*****]
03/18/20 18:08:08 zmesdetect_m4[763] DBG utils.py:158 [Trying to download http://**.**.**.**/zm/index.php?view=image&eid=3457&fid=snapshot&username=demo&password=*****]
03/18/20 18:08:08 zmesdetect_m4[763] DBG zm_detect.py:233 [No polygon area specfied, so adding a full image polygon:[{'name': 'full_image', 'value': [(0, 0), (1280, 0), (1280, 800), (0, 800)]}]]
03/18/20 18:08:08 zmesdetect_m4[763] DBG zm_detect.py:236 [resizing to 1200 before analysis...]
03/18/20 18:08:08 zmesdetect_m4[763] DBG utils.py:35 [resized polygons x=0.9375/y=0.9375: [{'name': 'full_image', 'value': [(0, 0), (1200, 0), (1200, 750), (0, 750)]}]]
03/18/20 18:08:08 zmesdetect_m4[763] DBG zm_detect.py:257 [User ALPR if vehicle found: False]
03/18/20 18:08:08 zmesdetect_m4[763] DBG zm_detect.py:339 [Using model: yolo with /var/lib/zmeventnotification/images/3457-alarm.jpg]
03/18/20 18:08:08 zmesdetect_m4[763] DBG yolo.py:48 [|---------- YOLO (input image: 1200w*750h, resized to: 416w*416h) ----------|]
03/18/20 18:08:08 zmesdetect_m4[763] DBG yolo.py:59 [Initializing Yolo]
03/18/20 18:08:08 zmesdetect_m4[763] DBG yolo.py:61 [config:/var/lib/zmeventnotification/models/yolov3/yolov3.cfg, weights:/var/lib/zmeventnotification/models/yolov3/yolov3.weights]
03/18/20 18:08:08 zmesdetect_m4[763] DBG yolo.py:83 [Not using CUDA backend]
03/18/20 18:08:08 zmesdetect_m4[763] DBG yolo.py:88 [YOLO initialization (loading model from disk) took: 237.351 milliseconds]
03/18/20 18:08:11 zmesdetect_m4[763] DBG yolo.py:103 [YOLO detection took: 134.282 milliseconds]
03/18/20 18:08:12 zmesdetect_m4[763] DBG yolo.py:136 [YOLO NMS filtering took: 1.689 milliseconds]
03/18/20 18:08:12 zmesdetect_m4[763] INF yolo.py:162 [object:car at [478, 606, 634, 736] has a acceptable confidence:0.968235969543457 compared to min confidence of: 0.3, adding]
03/18/20 18:08:12 zmesdetect_m4[763] INF yolo.py:162 [object:car at [30, 347, 214, 423] has a acceptable confidence:0.9626762270927429 compared to min confidence of: 0.3, adding]
03/18/20 18:08:13 zmesdetect_m4[763] INF yolo.py:162 [object:car at [44, 295, 216, 365] has a acceptable confidence:0.9116290807723999 compared to min confidence of: 0.3, adding]
03/18/20 18:08:13 zmesdetect_m4[763] INF yolo.py:162 [object:car at [463, 170, 617, 252] has a acceptable confidence:0.8148176670074463 compared to min confidence of: 0.3, adding]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:241 [intersection: polygon in process=[(478, 606), (634, 606), (634, 736), (478, 736)]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:248 [full_image intersects object:car[[(478, 606), (634, 606), (634, 736), (478, 736)]]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:241 [intersection: polygon in process=[(30, 347), (214, 347), (214, 423), (30, 423)]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:248 [full_image intersects object:car[[(30, 347), (214, 347), (214, 423), (30, 423)]]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:241 [intersection: polygon in process=[(44, 295), (216, 295), (216, 365), (44, 365)]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:248 [full_image intersects object:car[[(44, 295), (216, 295), (216, 365), (44, 365)]]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:241 [intersection: polygon in process=[(463, 170), (617, 170), (617, 252), (463, 252)]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:248 [full_image intersects object:car[[(463, 170), (617, 170), (617, 252), (463, 252)]]]
03/18/20 18:08:13 zmesdetect_m4[763] DBG zm_detect.py:568 [ALPR not in use, no need for look aheads in processing]
03/18/20 18:08:13 zmesdetect_m4[763] INF zm_detect.py:585 [labels found: ['car', 'car', 'car', 'car']]
03/18/20 18:08:13 zmesdetect_m4[763] DBG zm_detect.py:588 [match found in /var/lib/zmeventnotification/images/3457-alarm.jpg, breaking file loop...]
03/18/20 18:08:13 zmesdetect_m4[763] INF zm_detect.py:649 [Removing matches to past detections]
03/18/20 18:08:13 zmesdetect_m4[763] DBG image_manip.py:136 [trying to load /var/lib/zmeventnotification/images/monitor-4-data.pkl]
03/18/20 18:08:13 zmesdetect_m4[763] DBG zm_detect.py:655 [Saving detections for monitor 4 for future match]
03/18/20 18:08:13 zmesdetect_m4[763] DBG zm_detect.py:670 [Writing detected image to /var/cache/zoneminder/events/4/2020-03-18/3457/objdetect.jpg]
03/18/20 18:08:13 zmesdetect_m4[763] DBG zm_detect.py:674 [Writing JSON output to /var/cache/zoneminder/events/4/2020-03-18/3457/objects.json]
03/18/20 18:08:14 zmesdetect_m4[763] INF zm_detect.py:723 [Prediction string:[a] detected:car:97% ]
03/18/20 18:08:14 zmesdetect_m4[763] DBG zm_detect.py:725 [Prediction string JSON:[{"type": "object", "label": "car", "box": [478, 606, 634, 736], "confidence": "96.82%"}, {"type": "object", "label": "car", "box": [30, 347, 214, 423], "confidence": "96.27%"}, {"type": "object", "label": "car", "box": [44, 295, 216, 365], "confidence": "91.16%"}, {"type": "object", "label": "car", "box": [463, 170, 617, 252], "confidence": "81.48%"}]]
03/18/20 18:08:56 zmesdetect_m4[801] INF zm_detect.py:153 [---------| app version: 5.10.1 |------------]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:254 [secret filename: /etc/zm/secrets.ini]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !ZM_PORTAL]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !ZM_API_PORTAL]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !ZM_USER]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !ZM_PASSWORD]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !ML_USER]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !ML_PASSWORD]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:227 [Secret token found in config: !PLATEREC_ALPR_KEY]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:277 [allowing self-signed certs to work...]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:296 [[monitor-4] overrides key:wait with value:5]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:296 [[monitor-4] overrides key:detect_pattern with value:.*]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:296 [[monitor-4] overrides key:poly_color with value:(255,0,0)]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:296 [[monitor-4] overrides key:models with value:yolo]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [config] is '/var/lib/zmeventnotification/models/yolov3/yolov3.cfg' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [weights] is '/var/lib/zmeventnotification/models/yolov3/yolov3.weights' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [labels] is '/var/lib/zmeventnotification/models/yolov3/yolov3_classes.txt' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [tiny_config] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.cfg' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [tiny_weights] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.weights' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [tiny_labels] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.txt' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [known_images_path] is '/var/lib/zmeventnotification/known_faces' after substitution]
03/18/20 18:08:56 zmesdetect_m4[801] DBG utils.py:332 [key [unknown_images_path] is '/var/lib/zmeventnotification/unknown_faces' after substitution]
03/18/20 18:08:57 zmesdetect_m4[801] INF zm_detect.py:180 [Importing local classes for Yolo/Face]
03/18/20 18:08:57 zmesdetect_m4[801] INF utils.py:99 [Sleeping for 5 seconds before downloading]
03/18/20 18:09:02 zmesdetect_m4[801] DBG utils.py:140 [Trying to download http://**.**.**.**/zm/index.php?view=image&eid=3458&fid=alarm&username=demo&password=*****]
03/18/20 18:09:02 zmesdetect_m4[801] DBG utils.py:158 [Trying to download http://**.**.**.**/zm/index.php?view=image&eid=3458&fid=snapshot&username=demo&password=*****]
03/18/20 18:09:02 zmesdetect_m4[801] DBG zm_detect.py:233 [No polygon area specfied, so adding a full image polygon:[{'name': 'full_image', 'value': [(0, 0), (1280, 0), (1280, 800), (0, 800)]}]]
03/18/20 18:09:02 zmesdetect_m4[801] DBG zm_detect.py:236 [resizing to 1200 before analysis...]
03/18/20 18:09:02 zmesdetect_m4[801] DBG utils.py:35 [resized polygons x=0.9375/y=0.9375: [{'name': 'full_image', 'value': [(0, 0), (1200, 0), (1200, 750), (0, 750)]}]]
03/18/20 18:09:02 zmesdetect_m4[801] DBG zm_detect.py:257 [User ALPR if vehicle found: False]
03/18/20 18:09:02 zmesdetect_m4[801] DBG zm_detect.py:339 [Using model: yolo with /var/lib/zmeventnotification/images/3458-alarm.jpg]
03/18/20 18:09:02 zmesdetect_m4[801] DBG yolo.py:48 [|---------- YOLO (input image: 1200w*750h, resized to: 416w*416h) ----------|]
03/18/20 18:09:02 zmesdetect_m4[801] DBG yolo.py:59 [Initializing Yolo]
03/18/20 18:09:02 zmesdetect_m4[801] DBG yolo.py:61 [config:/var/lib/zmeventnotification/models/yolov3/yolov3.cfg, weights:/var/lib/zmeventnotification/models/yolov3/yolov3.weights]
03/18/20 18:09:03 zmesdetect_m4[801] DBG yolo.py:83 [Not using CUDA backend]
03/18/20 18:09:03 zmesdetect_m4[801] DBG yolo.py:88 [YOLO initialization (loading model from disk) took: 271.561 milliseconds]
03/18/20 18:09:06 zmesdetect_m4[801] DBG yolo.py:103 [YOLO detection took: 369.82 milliseconds]
03/18/20 18:09:06 zmesdetect_m4[801] DBG yolo.py:136 [YOLO NMS filtering took: 1.75 milliseconds]
03/18/20 18:09:08 zmesdetect_m4[801] INF yolo.py:162 [object:car at [372, 288, 530, 392] has a acceptable confidence:0.9965919852256775 compared to min confidence of: 0.3, adding]
03/18/20 18:09:08 zmesdetect_m4[801] INF yolo.py:162 [object:car at [34, 344, 208, 422] has a acceptable confidence:0.9820746183395386 compared to min confidence of: 0.3, adding]
03/18/20 18:09:08 zmesdetect_m4[801] INF yolo.py:162 [object:car at [472, 606, 626, 738] has a acceptable confidence:0.9690326452255249 compared to min confidence of: 0.3, adding]
03/18/20 18:09:08 zmesdetect_m4[801] INF yolo.py:162 [object:car at [954, 100, 1104, 164] has a acceptable confidence:0.9510518312454224 compared to min confidence of: 0.3, adding]
03/18/20 18:09:08 zmesdetect_m4[801] INF yolo.py:162 [object:bus at [414, 80, 612, 198] has a acceptable confidence:0.9341928958892822 compared to min confidence of: 0.3, adding]
03/18/20 18:09:09 zmesdetect_m4[801] INF yolo.py:162 [object:car at [46, 294, 212, 366] has a acceptable confidence:0.928948700428009 compared to min confidence of: 0.3, adding]
03/18/20 18:09:09 zmesdetect_m4[801] INF yolo.py:162 [object:person at [816, 371, 854, 447] has a acceptable confidence:0.7322129607200623 compared to min confidence of: 0.3, adding]
03/18/20 18:09:10 zmesdetect_m4[801] INF yolo.py:162 [object:traffic light at [627, 10, 671, 58] has a acceptable confidence:0.49877089262008667 compared to min confidence of: 0.3, adding]
03/18/20 18:09:10 zmesdetect_m4[801] INF yolo.py:162 [object:truck at [301, 501, 457, 747] has a acceptable confidence:0.3302479088306427 compared to min confidence of: 0.3, adding]
03/18/20 18:09:11 zmesdetect_m4[801] INF yolo.py:171 [rejecting object:car at [950, 112, 996, 156] because its confidence is :0.2994152009487152 compared to min confidence of: 0.3]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(372, 288), (530, 288), (530, 392), (372, 392)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:car[[(372, 288), (530, 288), (530, 392), (372, 392)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(34, 344), (208, 344), (208, 422), (34, 422)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:car[[(34, 344), (208, 344), (208, 422), (34, 422)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(472, 606), (626, 606), (626, 738), (472, 738)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:car[[(472, 606), (626, 606), (626, 738), (472, 738)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(954, 100), (1104, 100), (1104, 164), (954, 164)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:car[[(954, 100), (1104, 100), (1104, 164), (954, 164)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(414, 80), (612, 80), (612, 198), (414, 198)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:bus[[(414, 80), (612, 80), (612, 198), (414, 198)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(46, 294), (212, 294), (212, 366), (46, 366)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:car[[(46, 294), (212, 294), (212, 366), (46, 366)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(816, 371), (854, 371), (854, 447), (816, 447)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:person[[(816, 371), (854, 371), (854, 447), (816, 447)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(627, 10), (671, 10), (671, 58), (627, 58)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:traffic light[[(627, 10), (671, 10), (671, 58), (627, 58)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:241 [intersection: polygon in process=[(301, 501), (457, 501), (457, 747), (301, 747)]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG image_manip.py:248 [full_image intersects object:truck[[(301, 501), (457, 501), (457, 747), (301, 747)]]]
03/18/20 18:09:11 zmesdetect_m4[801] DBG zm_detect.py:568 [ALPR not in use, no need for look aheads in processing]
03/18/20 18:09:12 zmesdetect_m4[801] INF zm_detect.py:585 [labels found: ['car', 'car', 'car', 'car', 'bus', 'car', 'person', 'traffic light', 'truck']]
03/18/20 18:09:12 zmesdetect_m4[801] DBG zm_detect.py:588 [match found in /var/lib/zmeventnotification/images/3458-alarm.jpg, breaking file loop...]
03/18/20 18:09:12 zmesdetect_m4[801] INF zm_detect.py:649 [Removing matches to past detections]
03/18/20 18:09:12 zmesdetect_m4[801] DBG image_manip.py:136 [trying to load /var/lib/zmeventnotification/images/monitor-4-data.pkl]
03/18/20 18:09:12 zmesdetect_m4[801] DBG zm_detect.py:655 [Saving detections for monitor 4 for future match]
03/18/20 18:09:12 zmesdetect_m4[801] DBG zm_detect.py:670 [Writing detected image to /var/cache/zoneminder/events/4/2020-03-18/3458/objdetect.jpg]
03/18/20 18:09:12 zmesdetect_m4[801] DBG zm_detect.py:674 [Writing JSON output to /var/cache/zoneminder/events/4/2020-03-18/3458/objects.json]
03/18/20 18:09:12 zmesdetect_m4[801] INF zm_detect.py:723 [Prediction string:[a] detected:car:100% bus:93% person:73% traffic light:50% truck:33% ]
03/18/20 18:09:12 zmesdetect_m4[801] DBG zm_detect.py:725 [Prediction string JSON:[{"type": "object", "label": "car", "box": [372, 288, 530, 392], "confidence": "99.66%"}, {"type": "object", "label": "car", "box": [34, 344, 208, 422], "confidence": "98.21%"}, {"type": "object", "label": "car", "box": [472, 606, 626, 738], "confidence": "96.90%"}, {"type": "object", "label": "car", "box": [954, 100, 1104, 164], "confidence": "95.11%"}, {"type": "object", "label": "bus", "box": [414, 80, 612, 198], "confidence": "93.42%"}, {"type": "object", "label": "car", "box": [46, 294, 212, 366], "confidence": "92.89%"}, {"type": "object", "label": "person", "box": [816, 371, 854, 447], "confidence": "73.22%"}, {"type": "object", "label": "traffic light", "box": [627, 10, 671, 58], "confidence": "49.88%"}, {"type": "object", "label": "truck", "box": [301, 501, 457, 747], "confidence": "33.02%"}]]```
pliablepixels commented 4 years ago

I will need debug logs for zmeventnotification for this event (not detect) Also what is the exact command you used to upgrade?

connectnet commented 4 years ago

zmeventnotification.log:

03/18/20 18:08:23.257939 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/18/20 18:08:23.416274 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:08:26.189418 zmeventnotification[756].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:3457 Ending process:756 to handle alarms]
03/18/20 18:08:28.254696 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/18/20 18:08:28.386033 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:08:33.258612 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/18/20 18:08:33.344003 zmeventnotification[29348].INF [main:863] [PARENT: Total event client connections: 0]
03/18/20 18:08:33.422024 zmeventnotification[29348].INF [main:863] [PARENT: Reloading Monitors...]
03/18/20 18:08:33.612482 zmeventnotification[29348].INF [main:863] [PARENT: Re-loading monitors, emptying needsReload() list]
03/18/20 18:08:33.913216 zmeventnotification[29348].INF [main:863] [PARENT: ESCONTROL_INTERFACE is disabled. Not saving control data]
03/18/20 18:08:34.000992 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:08:38.254043 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/18/20 18:08:38.350192 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:08:43.255440 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/18/20 18:08:43.486406 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:08:48.253962 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/18/20 18:08:48.488324 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:08:53.258192 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/18/20 18:08:53.504546 zmeventnotification[29348].INF [main:863] [PARENT: New event 3458 reported for Monitor:4 (Name:Streetcam in Moscow) Motion All]
03/18/20 18:08:54.050036 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 new Events to process]
03/18/20 18:08:54.290082 zmeventnotification[797].INF [main:863] [PARENT: Forked process:797 to handle alarm eid:3458]
03/18/20 18:08:54.674058 zmeventnotification[797].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:3458 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 3458 4 "Streetcam in Moscow" "Motion All" "/var/cache/zoneminder/events/4/2020-03-18/3458"]
03/18/20 18:08:58.254562 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/18/20 18:08:58.388267 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:09:03.258521 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/18/20 18:09:03.628467 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:09:08.253842 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/18/20 18:09:08.474946 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/18/20 18:09:13.011739 zmeventnotification[797].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:3458 hook start returned with text:[a] detected:car:100% bus:93% person:73% traffic light:50% truck:33%  json:[{"type": "object", "label": "car", "box": [372, 288, 530, 392], "confidence": "99.66%"}, {"type": "object", "label": "car", "box": [34, 344, 208, 422], "confidence": "98.21%"}, {"type": "object", "label": "car", "box": [472, 606, 626, 738], "confidence": "96.90%"}, {"type": "object", "label": "car", "box": [954, 100, 1104, 164], "confidence": "95.11%"}, {"type": "object", "label": "bus", "box": [414, 80, 612, 198], "confidence": "93.42%"}, {"type": "object", "label": "car", "box": [46, 294, 212, 366], "confidence": "92.89%"}, {"type": "object", "label": "person", "box": [816, 371, 854, 447], "confidence": "73.22%"}, {"type": "object", "label": "traffic light", "box": [627, 10, 671, 58], "confidence": "49.88%"}, {"type": "object", "label": "truck", "box": [301, 501, 457, 747], "confidence": "33.02%"}] exit:0]
03/18/20 18:09:13.256973 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/18/20 18:09:13.313513 zmeventnotification[797].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:3458 Event 3458 for Monitor 4 has finished]

I deleted all first, than download the (master) zip, than sudo ./install.sh

pliablepixels commented 4 years ago

These are INF logs. Need debug. Please make sure you post the full debug logs (from start of event to finish) when you do.

connectnet commented 4 years ago

Can't find more than the posted INF logs above for this case. I give up. PS: if i am the only one with this problem it is probably due to my inability

pliablepixels commented 4 years ago

This was a problem a few weeks ago and was discussed in the ZM forums, which I fixed.

You need to make sure debug logs are enabled for ES and you'll start seeing it. See https://zmeventnotification.readthedocs.io/en/latest/guides/es_faq.html#debugging-and-reporting-problems and make sure you follow the correct logging setup.

connectnet commented 4 years ago

That exactly what I did:

In ZM->Options->Logs:
LOG_DEBUG is on
LOG_LEVEL_FILE = debug
LOG_LEVEL_SYSLOG = Info
LOG_LEVEL_DATABASE = Info
LOG_DEBUG_TARGET = _zmesdetect|_zmeventnotification. This enables DEBUG logs for both detection and event server scripts. Iff you have other targets, just separate them with | - example, _zmc|_zmesdetect. If you only want to track detection logs and not ES logs, just do _zmesdetect. You can also enable debug logs for just one monitor’s hooks like so: _zmesdetect_m4|_zmeventnotification

So I am sorry that the log is incomplete but thats all what I found for eid:3458.

connectnet commented 4 years ago

I think I realize now what log's you need. Please let me try again:

2020-03-19 21-31-36

zmc_m4.log for Event 6085:

03/19/20 19:21:58.693647 zmc_m4[32576].WAR-zm_monitor.cpp/2514 [Last image read from shared memory 7 seconds ago, zma may have gone away]
03/19/20 19:22:09.572046 zmc_m4[32576].INF-zm_monitor.cpp/2546 [Streetcam in Moscow: images:628100 - Capturing at 7.14 fps, capturing bandwidth 921013bytes/sec]
03/19/20 19:22:24.038429 zmc_m4[32576].INF-zm_monitor.cpp/2546 [Streetcam in Moscow: images:628200 - Capturing at 6.67 fps, capturing bandwidth 872903bytes/sec]
03/19/20 19:22:38.214682 zmc_m4[32576].INF-zm_monitor.cpp/2546 [Streetcam in Moscow: images:628300 - Capturing at 7.14 fps, capturing bandwidth 954286bytes/sec]
03/19/20 19:22:43.620914 zmc_m4[32576].WAR-zm_monitor.cpp/2509 [Buffer overrun at index 15, image 628335, slow down capture, speed up analysis or increase ring buffer size]
03/19/20 19:22:46.449756 zmc_m4[32576].WAR-zm_monitor.cpp/2509 [Buffer overrun at index 15, image 628355, slow down capture, speed up analysis or increase ring buffer size]
03/19/20 19:22:46.931783 zmc_m4[32576].WAR-zm_monitor.cpp/2514 [Last image read from shared memory 6 seconds ago, zma may have gone away]
03/19/20 19:22:52.388314 zmc_m4[32576].INF-zm_monitor.cpp/2546 [Streetcam in Moscow: images:628400 - Capturing at 7.14 fps, capturing bandwidth 928559bytes/sec]

zmesdetect_m4.log for Event 6085:

03/19/20 19:22:36 zmesdetect_m4[21693] INF zm_detect.py:153 [---------| app version: 5.10.1 |------------]
03/19/20 19:22:36 zmesdetect_m4[21693] INF zm_detect.py:180 [Importing local classes for Yolo/Face]
03/19/20 19:22:36 zmesdetect_m4[21693] INF utils.py:99 [Sleeping for 5 seconds before downloading]
03/19/20 19:22:46 zmesdetect_m4[21693] INF yolo.py:162 [object:car at [421, 215, 527, 315] has a acceptable confidence:0.9351872205734253 compared to min confidence of: 0.3, adding]
03/19/20 19:22:46 zmesdetect_m4[21693] INF yolo.py:162 [object:car at [118, 253, 264, 341] has a acceptable confidence:0.720533013343811 compared to min confidence of: 0.3, adding]
03/19/20 19:22:47 zmesdetect_m4[21693] INF yolo.py:162 [object:truck at [878, 386, 1118, 556] has a acceptable confidence:0.5689600706100464 compared to min confidence of: 0.3, adding]
03/19/20 19:22:47 zmesdetect_m4[21693] INF yolo.py:162 [object:person at [336, 242, 364, 300] has a acceptable confidence:0.47982215881347656 compared to min confidence of: 0.3, adding]
03/19/20 19:22:47 zmesdetect_m4[21693] INF zm_detect.py:585 [labels found: ['car', 'car', 'truck', 'person']]
03/19/20 19:22:47 zmesdetect_m4[21693] INF zm_detect.py:649 [Removing matches to past detections]
03/19/20 19:22:48 zmesdetect_m4[21693] INF zm_detect.py:723 [Prediction string:[a] detected:car:94% truck:57% person:48% ]```

zmeventnotification.log for Event 6085:

03/19/20 19:22:10.572271 zmeventnotification[21659].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6084 Ending process:21659 to handle alarms]
03/19/20 19:22:13.254474 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/19/20 19:22:14.406490 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:18.257884 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/19/20 19:22:18.576920 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:23.254729 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/19/20 19:22:23.467527 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:28.258311 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/19/20 19:22:28.520965 zmeventnotification[29348].INF [main:863] [PARENT: Total event client connections: 0]
03/19/20 19:22:28.655020 zmeventnotification[29348].INF [main:863] [PARENT: Reloading Monitors...]
03/19/20 19:22:28.792282 zmeventnotification[29348].INF [main:863] [PARENT: Re-loading monitors, emptying needsReload() list]
03/19/20 19:22:28.949647 zmeventnotification[29348].INF [main:863] [PARENT: ESCONTROL_INTERFACE is disabled. Not saving control data]
03/19/20 19:22:29.081655 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:33.254171 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/19/20 19:22:33.533286 zmeventnotification[29348].INF [main:863] [PARENT: New event 6085 reported for Monitor:4 (Name:Streetcam in Moscow) Motion All]
03/19/20 19:22:33.884601 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 new Events to process]
03/19/20 19:22:34.224261 zmeventnotification[21689].INF [main:863] [PARENT: Forked process:21689 to handle alarm eid:6085]
03/19/20 19:22:34.531578 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 6085 4 "Streetcam in Moscow" "Motion All" "/var/cache/zoneminder/events/4/2020-03-19/6085"]
03/19/20 19:22:38.258535 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:22:39.481249 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:43.254653 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:22:43.476456 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:48.234291 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 hook start returned with text:[a] detected:car:94% truck:57% person:48%  json:[{"type": "object", "label": "car", "box": [421, 215, 527, 315], "confidence": "93.52%"}, {"type": "object", "label": "car", "box": [118, 253, 264, 341], "confidence": "72.05%"}, {"type": "object", "label": "truck", "box": [878, 386, 1118, 556], "confidence": "56.90%"}, {"type": "object", "label": "person", "box": [336, 242, 364, 300], "confidence": "47.98%"}] exit:0]
03/19/20 19:22:48.256925 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:22:48.401577 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Event 6085 for Monitor 4 has finished]
03/19/20 19:22:48.401811 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:50.658450 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Matching alarm to connection rules...]
03/19/20 19:22:53.183288 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 6085 4 "Streetcam in Moscow" "[a] detected:car:94% truck:57% person:48%  Motion: All" "/var/cache/zoneminder/events/4/2020-03-19/6085"]
03/19/20 19:22:53.255001 zmeventnotification[29348].INF [main:863] [PARENT: Force updating event 6085 with desc:[a] detected:car:94% truck:57% person:48% ]
03/19/20 19:22:53.351134 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 hook end returned with text:[a] detected:car:94% truck:57% person:48%  Motion: All  json:[] exit:0]
03/19/20 19:22:53.928524 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:22:54.207214 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:55.684613 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Matching alarm to connection rules...]
03/19/20 19:22:58.257452 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:22:58.409360 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:22:59.909115 zmeventnotification[21689].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Ending process:21689 to handle alarms]
03/19/20 19:23:03.254641 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 active child forks...]
03/19/20 19:23:04.376829 zmeventnotification[29348].INF [main:863] [PARENT: New event 6085 reported for Monitor:4 (Name:Streetcam in Moscow) Motion All]
03/19/20 19:23:04.837227 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 new Events to process]
03/19/20 19:23:05.632987 zmeventnotification[21718].INF [main:863] [PARENT: Forked process:21718 to handle alarm eid:6085]
03/19/20 19:23:05.851246 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 6085 4 "Streetcam in Moscow" "Motion All" "/var/cache/zoneminder/events/4/2020-03-19/6085"]
03/19/20 19:23:08.256631 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:23:08.640973 zmeventnotification[29348].INF [main:863] [PARENT: New event 6086 reported for Monitor:4 (Name:Streetcam in Moscow) Motion All]
03/19/20 19:23:09.013450 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 new Events to process]
03/19/20 19:23:09.661783 zmeventnotification[21729].INF [main:863] [PARENT: Forked process:21729 to handle alarm eid:6086]
03/19/20 19:23:09.810978 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 6086 4 "Streetcam in Moscow" "Motion All" "/var/cache/zoneminder/events/4/2020-03-19/6086"]
03/19/20 19:23:13.254306 zmeventnotification[29348].INF [main:863] [PARENT: There are 2 active child forks...]
03/19/20 19:23:13.482996 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:23:18.268011 zmeventnotification[29348].INF [main:863] [PARENT: There are 2 active child forks...]
03/19/20 19:23:18.453595 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:23:20.221439 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 hook start returned with text: json:[] exit:1]
03/19/20 19:23:20.630046 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Event 6085 for Monitor 4 has finished]
03/19/20 19:23:22.790808 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 hook start returned with text:[a] detected:car:98%  json:[{"type": "object", "label": "car", "box": [471, 150, 623, 216], "confidence": "98.23%"}, {"type": "object", "label": "car", "box": [407, 296, 527, 402], "confidence": "97.88%"}, {"type": "object", "label": "car", "box": [561, 299, 715, 387], "confidence": "46.82%"}] exit:0]
03/19/20 19:23:22.864496 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Matching alarm to connection rules...]
03/19/20 19:23:22.932765 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 Event 6086 for Monitor 4 has finished]
03/19/20 19:23:23.255880 zmeventnotification[29348].INF [main:863] [PARENT: Force updating event 6086 with desc:[a] detected:car:98% ]
03/19/20 19:23:24.067083 zmeventnotification[29348].INF [main:863] [PARENT: There are 2 active child forks...]
03/19/20 19:23:24.214866 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:23:25.122479 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 6085 4 "Streetcam in Moscow" "[a] detected:car:94% truck:57% person:48%  [a] detected:car:94% truck:57% person:48%  Motion: All Motion: All" "/var/cache/zoneminder/events/4/2020-03-19/6085"]
03/19/20 19:23:25.255954 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 Matching alarm to connection rules...]
03/19/20 19:23:25.330770 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 hook end returned with text:[a] detected:car:94% truck:57% person:48%  [a] detected:car:94% truck:57% person:48%  Motion: All Motion: All  json:[] exit:0]
03/19/20 19:23:27.691218 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 Invoking hook on event end:'/var/lib/zmeventnotification/bin/zm_event_end.sh' 6086 4 "Streetcam in Moscow" "[a] detected:car:98%  Motion: All" "/var/cache/zoneminder/events/4/2020-03-19/6086"]
03/19/20 19:23:27.989702 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 hook end returned with text:[a] detected:car:98%  Motion: All  json:[] exit:0]
03/19/20 19:23:28.081671 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Not sending event end alarm, as we did not send a start alarm for this, or start hook processing failed]
03/19/20 19:23:28.257578 zmeventnotification[29348].INF [main:863] [PARENT: There are 2 active child forks...]
03/19/20 19:23:28.494202 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:23:30.172348 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 Matching alarm to connection rules...]
03/19/20 19:23:32.300563 zmeventnotification[21718].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6085 Ending process:21718 to handle alarms]
03/19/20 19:23:33.254517 zmeventnotification[29348].INF [main:863] [PARENT: There are 1 active child forks...]
03/19/20 19:23:33.519625 zmeventnotification[29348].INF [main:863] [PARENT: There are 0 new Events to process]
03/19/20 19:23:34.318147 zmeventnotification[21729].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:6086 Ending process:21729 to handle alarms]
connectnet commented 4 years ago

Is the Buffer overrun the reason for the duplicate entrys?

03/19/20 19:22:43.620914 zmc_m4[32576].WAR-zm_monitor.cpp/2509 [Buffer overrun at index 15, image 628335, slow down capture, speed up analysis or increase ring buffer size]
03/19/20 19:22:46.449756 zmc_m4[32576].WAR-zm_monitor.cpp/2509 [Buffer overrun at index 15, image 628355, slow down capture, speed up analysis or increase ring buffer size]
pliablepixels commented 4 years ago

No, the zmc_xx logs are related to ZoneMinder - not related to ES. The logs I needed were for zmeventnotification.log which you're provided. I'll take a look.

pliablepixels commented 4 years ago

Unfortunately, all the logs in zmeventnotification.log are INF not DBG. You need to enable Debug and restart the ES. Note that this will not create debug logs for past events. It will only create them for future events.

pliablepixels commented 4 years ago

However, I think I see what is happening

a) You have a hook on event start. That is creating the text correctly b) You also have a hook on event end and that is appending the text to event start text

That is the exact problem I fixed earlier.

Please update to master and restart. I get the feeling your /usr/bin/zmeventnotification.pl is not up to date, or you never shut it down, so its still running the older version

Next time this happens, please only post:

a) zmesdetect_mxx.log (xx=monitorID) b) zmeventnotification.log for the full event

connectnet commented 4 years ago

Ok, strange... /user/bin/zmeventnotification.pl = my $app_version = '5.10' I restart zoneminder now (again).

pliablepixels commented 4 years ago

Are you sure it is /user/bin and not /usr/bin? Make sure the version that is running is the version you are reporting.

connectnet commented 4 years ago

Ah - excuse me for my misspelling /usr/bin is the correct path that I mean.

connectnet commented 4 years ago

I hope to have done everything right now.

7035 Streetcam-7035 zmesdetect_m4.log:

03/20/20 07:27:58 zmesdetect_m4[26724] INF zm_detect.py:153 [---------| app version: 5.10.1 |------------]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:254 [secret filename: /etc/zm/secrets.ini]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !ZM_PORTAL]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !ZM_API_PORTAL]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !ZM_USER]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !ZM_PASSWORD]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !ML_USER]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !ML_PASSWORD]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:227 [Secret token found in config: !PLATEREC_ALPR_KEY]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:277 [allowing self-signed certs to work...]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:296 [[monitor-4] overrides key:wait with value:5]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:296 [[monitor-4] overrides key:detect_pattern with value:.*]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:296 [[monitor-4] overrides key:poly_color with value:(255,0,0)]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:296 [[monitor-4] overrides key:models with value:yolo]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [config] is '/var/lib/zmeventnotification/models/yolov3/yolov3.cfg' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [weights] is '/var/lib/zmeventnotification/models/yolov3/yolov3.weights' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [labels] is '/var/lib/zmeventnotification/models/yolov3/yolov3_classes.txt' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [tiny_config] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.cfg' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [tiny_weights] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.weights' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [tiny_labels] is '/var/lib/zmeventnotification/models/tinyyolo/yolov3-tiny.txt' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [known_images_path] is '/var/lib/zmeventnotification/known_faces' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] DBG utils.py:332 [key [unknown_images_path] is '/var/lib/zmeventnotification/unknown_faces' after substitution]
03/20/20 07:27:59 zmesdetect_m4[26724] INF zm_detect.py:180 [Importing local classes for Yolo/Face]
03/20/20 07:27:59 zmesdetect_m4[26724] INF utils.py:99 [Sleeping for 5 seconds before downloading]
03/20/20 07:28:04 zmesdetect_m4[26724] DBG utils.py:140 [Trying to download http://127.0.0.1/zm/index.php?view=image&eid=7035&fid=alarm&username=demo&password=*****]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG utils.py:158 [Trying to download http://127.0.0.1/zm/index.php?view=image&eid=7035&fid=snapshot&username=demo&password=*****]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG zm_detect.py:233 [No polygon area specfied, so adding a full image polygon:[{'name': 'full_image', 'value': [(0, 0), (1280, 0), (1280, 800), (0, 800)]}]]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG zm_detect.py:236 [resizing to 1200 before analysis...]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG utils.py:35 [resized polygons x=0.9375/y=0.9375: [{'name': 'full_image', 'value': [(0, 0), (1200, 0), (1200, 750), (0, 750)]}]]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG zm_detect.py:257 [User ALPR if vehicle found: False]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG zm_detect.py:339 [Using model: yolo with /var/lib/zmeventnotification/images/7035-alarm.jpg]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG yolo.py:48 [|---------- YOLO (input image: 1200w*750h, resized to: 416w*416h) ----------|]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG yolo.py:59 [Initializing Yolo]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG yolo.py:61 [config:/var/lib/zmeventnotification/models/yolov3/yolov3.cfg, weights:/var/lib/zmeventnotification/models/yolov3/yolov3.weights]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG yolo.py:83 [Not using CUDA backend]
03/20/20 07:28:05 zmesdetect_m4[26724] DBG yolo.py:88 [YOLO initialization (loading model from disk) took: 234.872 milliseconds]
03/20/20 07:28:09 zmesdetect_m4[26724] DBG yolo.py:103 [YOLO detection took: 838.289 milliseconds]
03/20/20 07:28:09 zmesdetect_m4[26724] DBG yolo.py:136 [YOLO NMS filtering took: 1.828 milliseconds]
03/20/20 07:28:10 zmesdetect_m4[26724] INF yolo.py:162 [object:car at [24, 348, 222, 418] has a acceptable confidence:0.9888333082199097 compared to min confidence of: 0.3, adding]
03/20/20 07:28:10 zmesdetect_m4[26724] INF yolo.py:162 [object:car at [680, 589, 860, 733] has a acceptable confidence:0.9814712405204773 compared to min confidence of: 0.3, adding]
03/20/20 07:28:10 zmesdetect_m4[26724] INF yolo.py:162 [object:car at [39, 274, 225, 346] has a acceptable confidence:0.9786641597747803 compared to min confidence of: 0.3, adding]
03/20/20 07:28:10 zmesdetect_m4[26724] INF yolo.py:162 [object:car at [746, 248, 866, 350] has a acceptable confidence:0.948123574256897 compared to min confidence of: 0.3, adding]
03/20/20 07:28:11 zmesdetect_m4[26724] INF yolo.py:162 [object:person at [1006, 290, 1028, 352] has a acceptable confidence:0.914705216884613 compared to min confidence of: 0.3, adding]
03/20/20 07:28:11 zmesdetect_m4[26724] INF yolo.py:162 [object:car at [912, 446, 1054, 558] has a acceptable confidence:0.8492088317871094 compared to min confidence of: 0.3, adding]
03/20/20 07:28:12 zmesdetect_m4[26724] INF yolo.py:162 [object:truck at [280, 509, 444, 741] has a acceptable confidence:0.44762831926345825 compared to min confidence of: 0.3, adding]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(24, 348), (222, 348), (222, 418), (24, 418)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:car[[(24, 348), (222, 348), (222, 418), (24, 418)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(680, 589), (860, 589), (860, 733), (680, 733)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:car[[(680, 589), (860, 589), (860, 733), (680, 733)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(39, 274), (225, 274), (225, 346), (39, 346)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:car[[(39, 274), (225, 274), (225, 346), (39, 346)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(746, 248), (866, 248), (866, 350), (746, 350)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:car[[(746, 248), (866, 248), (866, 350), (746, 350)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(1006, 290), (1028, 290), (1028, 352), (1006, 352)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:person[[(1006, 290), (1028, 290), (1028, 352), (1006, 352)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(912, 446), (1054, 446), (1054, 558), (912, 558)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:car[[(912, 446), (1054, 446), (1054, 558), (912, 558)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:241 [intersection: polygon in process=[(280, 509), (444, 509), (444, 741), (280, 741)]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG image_manip.py:248 [full_image intersects object:truck[[(280, 509), (444, 509), (444, 741), (280, 741)]]]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG zm_detect.py:568 [ALPR not in use, no need for look aheads in processing]
03/20/20 07:28:12 zmesdetect_m4[26724] INF zm_detect.py:585 [labels found: ['car', 'car', 'car', 'car', 'person', 'car', 'truck']]
03/20/20 07:28:12 zmesdetect_m4[26724] DBG zm_detect.py:588 [match found in /var/lib/zmeventnotification/images/7035-alarm.jpg, breaking file loop...]
03/20/20 07:28:13 zmesdetect_m4[26724] INF zm_detect.py:649 [Removing matches to past detections]
03/20/20 07:28:13 zmesdetect_m4[26724] DBG image_manip.py:136 [trying to load /var/lib/zmeventnotification/images/monitor-4-data.pkl]
03/20/20 07:28:13 zmesdetect_m4[26724] DBG zm_detect.py:655 [Saving detections for monitor 4 for future match]
03/20/20 07:28:13 zmesdetect_m4[26724] DBG zm_detect.py:670 [Writing detected image to /var/cache/zoneminder/events/4/2020-03-20/7035/objdetect.jpg]
03/20/20 07:28:13 zmesdetect_m4[26724] DBG zm_detect.py:674 [Writing JSON output to /var/cache/zoneminder/events/4/2020-03-20/7035/objects.json]
03/20/20 07:28:13 zmesdetect_m4[26724] INF zm_detect.py:723 [Prediction string:[a] detected:car:99% person:91% truck:45% ]
03/20/20 07:28:13 zmesdetect_m4[26724] DBG zm_detect.py:725 [Prediction string JSON:[{"type": "object", "label": "car", "box": [24, 348, 222, 418], "confidence": "98.88%"}, {"type": "object", "label": "car", "box": [680, 589, 860, 733], "confidence": "98.15%"}, {"type": "object", "label": "car", "box": [39, 274, 225, 346], "confidence": "97.87%"}, {"type": "object", "label": "car", "box": [746, 248, 866, 350], "confidence": "94.81%"}, {"type": "object", "label": "person", "box": [1006, 290, 1028, 352], "confidence": "91.47%"}, {"type": "object", "label": "car", "box": [912, 446, 1054, 558], "confidence": "84.92%"}, {"type": "object", "label": "truck", "box": [280, 509, 444, 741], "confidence": "44.76%"}]]

zmeventnotification.log:

03/20/20 07:27:53.239442 zmeventnotification[26626].DBG [main:854] [PARENT: ---------->Tick START<--------------]
03/20/20 07:27:53.239539 zmeventnotification[26626].DBG [main:854] [PARENT: After tick: TOTAL: 0,  ES_CONTROL: 0, FCM+WEB: 0, FCM: 0, WEB: 0, MQTT:0, invalid WEB: 0, PENDING: 0]
03/20/20 07:27:53.239832 zmeventnotification[26626].DBG [main:854] [PARENT: RAW TEXT-->active_event_delete--TYPE--1--SPLIT--7033]
03/20/20 07:27:53.239907 zmeventnotification[26626].DBG [main:854] [PARENT: Job: Deleting active_event eid:7033, mid:1]
03/20/20 07:27:53.240013 zmeventnotification[26626].DBG [main:854] [PARENT: Finished processJobs()]
03/20/20 07:27:53.240155 zmeventnotification[26626].INF [main:863] [PARENT: There are 1 active child forks...]
03/20/20 07:27:54.051431 zmeventnotification[26626].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140325816664064]
03/20/20 07:27:54.051579 zmeventnotification[26626].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 1: 1]
03/20/20 07:27:54.051715 zmeventnotification[26626].DBG [main:854] [PARENT: We've already worked on Monitor:1, Event:7034, not doing anything more]
03/20/20 07:27:54.051754 zmeventnotification[26626].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140325816631296]
03/20/20 07:27:54.051828 zmeventnotification[26626].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 2: 1]
03/20/20 07:27:54.051918 zmeventnotification[26626].DBG [ZoneMinder::Memory::Mapped:84] [zmMemAttach already attached at 140325816565760]
03/20/20 07:27:54.051981 zmeventnotification[26626].DBG [ZoneMinder::Memory:300] [Shared data appears valid for monitor 4: 1]
03/20/20 07:27:54.052210 zmeventnotification[26626].INF [main:863] [PARENT: New event 7035 reported for Monitor:4 (Name:Streetcam in Moscow) Motion All]
03/20/20 07:27:55.057433 zmeventnotification[26626].DBG [main:854] [PARENT: checkEvents() new events found=1]
03/20/20 07:27:55.057708 zmeventnotification[26626].INF [main:863] [PARENT: There are 1 new Events to process]
03/20/20 07:27:55.701786 zmeventnotification[26626].DBG [main:854] [PARENT: ---------->Tick END<--------------]
03/20/20 07:27:55.705968 zmeventnotification[26720].INF [main:863] [PARENT: Forked process:26720 to handle alarm eid:7035]
03/20/20 07:27:56.378982 zmeventnotification[26720].DBG [ZoneMinder::Object:115] [Loading ZoneMinder::Event from Events WHERE Id = 7035]
03/20/20 07:27:56.380718 zmeventnotification[26720].DBG [main:854] [|----> FORK:Streetcam in Moscow (4), eid:7035 Adding event path:/var/cache/zoneminder/events/4/2020-03-20/7035 to hook for image storage]
03/20/20 07:27:56.380885 zmeventnotification[26720].INF [main:863] [|----> FORK:Streetcam in Moscow (4), eid:7035 Invoking hook on event start:'/var/lib/zmeventnotification/bin/zm_event_start.sh' 7035 4 "Streetcam in Moscow" "Motion All" "/var/cache/zoneminder/events/4/2020-03-20/7035"]
pliablepixels commented 4 years ago

You've done in correctly but in the recent logs, there are no issues.

connectnet commented 4 years ago

I'm glad to hear that I did it right this time. The problem described occurs on two different servers.

stale[bot] commented 4 years ago

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

connectnet commented 4 years ago

Question: Is there someone else who has this issue or I am the onlyone?

pliablepixels commented 4 years ago

As of now you are the only one.

connectnet commented 4 years ago

Damn... I have this issue at three server... I can't belive it... :-(

sentiment-bot[bot] commented 4 years ago

Please be sure to review the code of conduct and be respectful of other users. cc/ @pliablepixels Keep in mind, this repository uses the Contributor Covenant.

pliablepixels commented 4 years ago

unless you are able to provide specific logs as I've asked I can't help

pliablepixels commented 4 years ago

I just saw this with another user. You may not be the only one.

pliablepixels commented 4 years ago

@connectnet replace ES with the master version and restart ES. Let me know if you still see the issue (and if so, please post DEBUG logs of only zmeventnotification.log). Make sure ES version is 5.12