search

ZoneMinder / zmeventnotification

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

HandleQueuedBulkIn transfer in failed. Not found: USB transfer error 5 [LibUsbDataInCallback] when multiple zm_detect.py processes are run at once with the edgetpu. #426

Closed waynieack closed 1 year ago

waynieack commented 1 year ago

Event Server version 6.1.28

Hooks version (if you are using Object Detection) app:6.1.28, pyzm:0.3.56

Are you using MLAPI? N

The version of ZoneMinder you are using: v1.37.25

What is the nature of your issue Bug

Details

Getting Error: HandleQueuedBulkIn transfer in failed. Not found: USB transfer error 5 [LibUsbDataInCallback] when multiple zm_detect.py processes are run at once with the edgetpu.

tpu_max_processes is set to 1.

I am executing the zm_detect.py with a custom script that dynamically generates the list of frames to check for objects after the event is complete which is for the most part all alarmed frames so the list can be up to 30 frames. While the script is going through the frames, it seems to lock and unlock with every frame and when a second process is running it seems to grab the lock from the other process which ends up killing the other process. This really isn't much of an issue with yolov4/GPU because it can handle more than 1 process but it does from time to time it will allow too many to run which causes an out of memory error.

If this happens to many times the TPU is completely locked up and I have to unplug it and plug it back in to get it working again. But I am really not able to use it at this point anyway because it just constantly fails like this.

Debug Logs 

Process 1:
11/21/22 17:54:25 zmesdetect_m5[8761] INF zm_detect.py:285 [---------| app:6.1.28, pyzm:0.3.56, ES:6.1.28 , OpenCV:4.6.0|------------]
11/21/22 17:56:31 zmesdetect_m6[8942] INF utils.py:405 [Reading config from: /etc/zm/objectconfig_edgetpu.ini]
11/21/22 17:56:31 zmesdetect_m6[8942] INF utils.py:410 [Reading secrets from: /etc/zm/secrets.ini]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !ZM_PORTAL]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !ZM_USER]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !ZM_PASSWORD]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !ZM_API_PORTAL]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !ML_USER]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !ML_PASSWORD]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:382 [Secret token found in config: !PLATEREC_ALPR_KEY]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG1 utils.py:445 [allowing self-signed certs to work...]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:455 [Now checking for monitor overrides]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:174 [import_zm_zones: match_reason=True and reason=[x] detected:car:99% Motion: Road]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:177 [Getting ZM zones using http://127.0.0.1/zm/api/zones/forMonitor/6.json?username=xxx&password=yyy&user=xxx&pass=yyy]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:228 [importing zoneminder polygon: road [519,8 845,20 1381,100 1908,223 1910,416 1115,191 513,60]]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:221 [Skipping Filter_Gas_Light as it is inactive]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG1 utils.py:225 [dropping Porch as zones in alarm cause is [x] detected:car:99% Motion: Road]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG1 utils.py:225 [dropping Driveway as zones in alarm cause is [x] detected:car:99% Motion: Road]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:221 [Skipping Filter_Bush as it is inactive]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG1 utils.py:225 [dropping Front_Yard as zones in alarm cause is [x] detected:car:99% Motion: Road]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:221 [Skipping Filter_Chain1 as it is inactive]
11/21/22 17:56:31 zmesdetect_m6[8942] DBG2 utils.py:221 [Skipping Filter_Chain2 as it is inactive]
11/21/22 17:56:31 zmesdetect_m6[8942] INF zm_detect.py:310 [Importing local classes for Object/Face]
11/21/22 17:56:32 zmesdetect_m6[8942] INF zm_detect.py:335 [Connecting with ZM APIs]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 api.py:72 [API SSL certificate check has been disbled]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 api.py:181 [using username/password for login]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 api.py:210 [Using new token API]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 api.py:217 [Access token expires on:2022-11-21 19:56:32.338138 [7200s]]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 api.py:221 [Refresh token expires on:2022-11-22 17:56:32.338518 [86400s]]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 zm_detect.py:343 [using ml_sequence]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 zm_detect.py:355 [using stream_sequence]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 zm_detect.py:360 [Using frme_set from args.]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 detect_sequence.py:160 [Resetting models, will be loaded on next run]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 Media.py:51 [Media get SSL certificate check has been disbled]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 Media.py:99 [Using URL 14298252 for stream]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 Media.py:114 [We will only process frames: ['167', '169', '170', '171', '166', '168', '172', '165', '162', '163', '164', '174', '175', '173', '161', '176', '160', '177', '159', '158', '178', '157', '179', '156', '180', '134', '135', '136', '137', '138']]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 Media.py:137 [No need to start streams, we are picking images from http://127.0.0.1/zm/index.php?view=image&eid=14298252]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 detect_sequence.py:654 [perf: Starting for frame:167]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG1 detect_sequence.py:669 [============ Frame: 167 Running object detection type in sequence ==================]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 detect_sequence.py:178 [Loading sequence: TPU object detection]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 detect_sequence.py:179 [Initializing model  type:object with options:{'name': 'TPU object detection', 'enabled': 'yes', 'object_weights': '/var/lib/zmeventnotification/models/coral_edgetpu/ssdlite_mobiledet_coco_qat_postprocess_edgetpu.tflite', 'object_labels': '/var/lib/zmeventnotification/models/coral_edgetpu/coco_indexed.names', 'object_min_confidence': 0.6, 'object_framework': 'coral_edgetpu', 'tpu_max_processes': 1, 'tpu_max_lock_wait': 160, 'max_detection_size': '90%', 'disable_locks': 'no'}]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:37 [portalock: max:1, name:pyzm_uid33_tpu_lock, timeout:160]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 detect_sequence.py:174 [Skipping YoloV4 GPU/CPU as it is disabled]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 detect_sequence.py:174 [Skipping YoloV4 Night Time Bug Check as it is disabled]
11/21/22 17:56:32 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:34 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:34 zmesdetect_m6[8942] DBG1 detect_sequence.py:701 [--------- Frame:167 Running variation: #1 -------------]
11/21/22 17:56:34 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:48 [pyzm_uid33_tpu_lock portalock already acquired]
11/21/22 17:56:34 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:89 [|--------- Loading "TPU object detection" model from disk -------------|]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:97 [perf: processor:tpu TPU initialization (loading /var/lib/zmeventnotification/models/coral_edgetpu/ssdlite_mobiledet_coco_qat_postprocess_edgetpu.tflite from disk) took: 2674.61 ms]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 36.38 ms]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:66 [core model detection over, got 1 objects. Now filtering]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:103 [Returning filtered list of 1 objects.]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: ['car'],conf:[0.76953125]]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:502 [intersection: object:car,POLYGON ((583 42, 756 42, 756 134, 583 134, 583 42)) intersects polygon:road,POLYGON ((216 3, 352 8, 575 41, 795 92, 795 173, 464 79, 213 25, 216 3))]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:518 [Using global match pattern: (person|car|motorbike|bus|truck|boat|dog|cat|bike|nightbug)]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:526 [road intersects object:car[[(583, 42), (756, 42), (756, 134), (583, 134)]]]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:753 [breaking out of same model loop, as matches found and strategy is "first"]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:654 [perf: Starting for frame:169]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:669 [============ Frame: 169 Running object detection type in sequence ==================]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:701 [--------- Frame:169 Running variation: #1 -------------]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 16.99 ms]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:66 [core model detection over, got 1 objects. Now filtering]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:103 [Returning filtered list of 1 objects.]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: ['car'],conf:[0.76171875]]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:502 [intersection: object:car,POLYGON ((608 51, 771 51, 771 139, 608 139, 608 51)) intersects polygon:road,POLYGON ((216 3, 352 8, 575 41, 795 92, 795 173, 464 79, 213 25, 216 3))]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:518 [Using global match pattern: (person|car|motorbike|bus|truck|boat|dog|cat|bike|nightbug)]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:526 [road intersects object:car[[(608, 51), (771, 51), (771, 139), (608, 139)]]]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:753 [breaking out of same model loop, as matches found and strategy is "first"]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:654 [perf: Starting for frame:170]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:669 [============ Frame: 170 Running object detection type in sequence ==================]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:701 [--------- Frame:170 Running variation: #1 -------------]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 17.62 ms]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:66 [core model detection over, got 1 objects. Now filtering]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 object.py:103 [Returning filtered list of 1 objects.]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: ['car'],conf:[0.76953125]]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:502 [intersection: object:car,POLYGON ((616 51, 793 51, 793 145, 616 145, 616 51)) intersects polygon:road,POLYGON ((216 3, 352 8, 575 41, 795 92, 795 173, 464 79, 213 25, 216 3))]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:518 [Using global match pattern: (person|car|motorbike|bus|truck|boat|dog|cat|bike|nightbug)]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:526 [road intersects object:car[[(616, 51), (793, 51), (793, 145), (616, 145)]]]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG2 detect_sequence.py:753 [breaking out of same model loop, as matches found and strategy is "first"]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:654 [perf: Starting for frame:171]
11/21/22 17:56:37 zmesdetect_m6[8942] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]

<SNIP>

11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 detect_sequence.py:701 [--------- Frame:138 Running variation: #1 -------------]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 17.79 ms]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 object.py:66 [core model detection over, got 0 objects. Now filtering]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 object.py:103 [Returning filtered list of 0 objects.]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: [],conf:[]]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 detect_sequence.py:770 [We did not find any object matches in frame: 138]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG2 coral_edgetpu.py:64 [pyzm_uid33_tpu_lock portalock already released]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 detect_sequence.py:827 [perf: TOTAL detection sequence (with image loads) took: 6398.91 ms  to process 14298252]
11/21/22 17:56:38 zmesdetect_m6[8942] INF zm_detect.py:483 [Prediction string:[x] detected:car:77% ]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 zm_detect.py:485 [Prediction string JSON:{"labels": ["car"], "boxes": [[583, 42, 756, 134]], "frame_id": "167", "confidences": [0.76953125], "image_dimensions": {"original": [1080, 1920], "resized": [450, 800]}}]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 zm_detect.py:503 [Writing detected image to /mnt/ext-video/events/6/2022-11-21/14298252/objdetect.jpg]
11/21/22 17:56:38 zmesdetect_m6[8942] DBG1 zm_detect.py:507 [Writing JSON output to /mnt/ext-video/events/6/2022-11-21/14298252/objects.json]
11/21/22 17:56:39 zmesdetect_m6[8942] DBG1 zm_detect.py:534 [Replacing old note:[x] detected:car:99% Motion: Road with new note:[x] detected:car:77% Motion: Road]
11/21/22 17:56:39 zmesdetect_m6[8942] DBG1 zm_detect.py:561 [Closing logs]

Process 2:
11/21/22 17:56:30 zmesdetect_m5[8930] INF zm_detect.py:285 [---------| app:6.1.28, pyzm:0.3.56, ES:6.1.28
 , OpenCV:4.6.0|------------]
11/21/22 17:56:30 zmesdetect_m5[8930] INF utils.py:405 [Reading config from: /etc/zm/objectconfig.ini]
11/21/22 17:56:30 zmesdetect_m5[8930] INF utils.py:410 [Reading secrets from: /etc/zm/secrets.ini]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !ZM_PORTAL]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !ZM_USER]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !ZM_PASSWORD]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !ZM_API_PORTAL]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !ML_USER]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !ML_PASSWORD]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:382 [Secret token found in config: !PLATEREC_ALPR_KEY]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG1 utils.py:445 [allowing self-signed certs to work...]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:455 [Now checking for monitor overrides]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:491 [tpu_object_enabled is not a polygon, adding it as unknown string key]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:491 [yolo4_object_enabled is not a polygon, adding it as unknown string key]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:174 [import_zm_zones: match_reason=True and reason=[x] detected:car:61% Motion: Road]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:177 [Getting ZM zones using http://127.0.0.1/zm/api/zones/forMonitor/5.json?username=xxx&password=yyy&user=xxx&pass=yyy]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG1 utils.py:225 [dropping Driveway as zones in alarm cause is [x] detected:car:61% Motion: Road]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG1 utils.py:225 [dropping Front_Yard as zones in alarm cause is [x] detected:car:61% Motion: Road]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:228 [importing zoneminder polygon: road [1476,25 1466,107 1359,121 1230,134 1212,84 443,253 0,368 0,182 337,132 349,95 479,10 1276,7]]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG1 utils.py:225 [dropping Porch as zones in alarm cause is [x] detected:car:61% Motion: Road]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG2 utils.py:221 [Skipping Filter_Gas_Light as it is inactive]
11/21/22 17:56:30 zmesdetect_m5[8930] DBG1 utils.py:225 [dropping Filter_Bush as zones in alarm cause is [x] detected:car:61% Motion: Road]
11/21/22 17:56:30 zmesdetect_m5[8930] INF zm_detect.py:310 [Importing local classes for Object/Face]
11/21/22 17:56:31 zmesdetect_m5[8930] INF zm_detect.py:335 [Connecting with ZM APIs]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 api.py:72 [API SSL certificate check has been disbled]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 api.py:181 [using username/password for login]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 api.py:210 [Using new token API]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 api.py:217 [Access token expires on:2022-11-21 19:56:31.490423 [7200s]]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 api.py:221 [Refresh token expires on:2022-11-22 17:56:31.490835 [86400s]]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 zm_detect.py:343 [using ml_sequence]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 zm_detect.py:355 [using stream_sequence]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 zm_detect.py:360 [Using frme_set from args.]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 detect_sequence.py:160 [Resetting models, will be loaded on next run]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 Media.py:51 [Media get SSL certificate check has been disbled]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 Media.py:99 [Using URL 14298249 for stream]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 Media.py:114 [We will only process frames: ['107', '108', '69', '70', '71', '73', '75', '76', '77', '78', '79', '80', '81', '82', '83', '84', '85', '86', '87', '88', '89', '90', '91', '92', '93', '94', '95', '96', '97', '98']]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 Media.py:137 [No need to start streams, we are picking images from http://127.0.0.1/zm/index.php?view=image&eid=14298249]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 detect_sequence.py:654 [perf: Starting for frame:107]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 detect_sequence.py:669 [============ Frame: 107 Running object detection type in sequence ==================]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 detect_sequence.py:178 [Loading sequence: TPU object detection]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 detect_sequence.py:179 [Initializing model  type:object with options:{'name': 'TPU object detection', 'enabled': 'yes', 'object_weights': '/var/lib/zmeventnotification/models/coral_edgetpu/ssdlite_mobiledet_coco_qat_postprocess_edgetpu.tflite', 'object_labels': '/var/lib/zmeventnotification/models/coral_edgetpu/coco_indexed.names', 'object_min_confidence': 0.6, 'object_framework': 'coral_edgetpu', 'tpu_max_processes': 1, 'tpu_max_lock_wait': 160, 'max_detection_size': '90%', 'disable_locks': 'no'}]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:37 [portalock: max:1, name:pyzm_uid33_tpu_lock, timeout:160]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 detect_sequence.py:174 [Skipping YoloV4 GPU/CPU as it is disabled]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 detect_sequence.py:174 [Skipping YoloV4 Night Time Bug Check as it is disabled]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 detect_sequence.py:701 [--------- Frame:107 Running variation: #1 -------------]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:48 [pyzm_uid33_tpu_lock portalock already acquired]
11/21/22 17:56:31 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:89 [|--------- Loading "TPU object detection" model from disk -------------|]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:97 [perf: processor:tpu TPU initialization (loading /var/lib/zmeventnotification/models/coral_edgetpu/ssdlite_mobiledet_coco_qat_postprocess_edgetpu.tflite from disk) took: 2665.68 ms]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 35.90 ms]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:66 [core model detection over, got 1 objects. Now filtering]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:103 [Returning filtered list of 1 objects.]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: ['car'],conf:[0.60546875]]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:502 [intersection: object:car,POLYGON ((285 6, 361 6, 361 40, 285 40, 285 6)) intersects polygon:road,POLYGON ((615 10, 610 44, 566 50, 512 55, 505 35, 184 105, 0 153, 0 75, 140 55, 145 39, 199 4, 531 2, 615 10))]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:518 [Using global match pattern: (person|car|motorbike|bus|truck|boat|dog|cat|bike|nightbug)]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:526 [road intersects object:car[[(285, 6), (361, 6), (361, 40), (285, 40)]]]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:753 [breaking out of same model loop, as matches found and strategy is "first"]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:654 [perf: Starting for frame:108]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:669 [============ Frame: 108 Running object detection type in sequence ==================]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:701 [--------- Frame:108 Running variation: #1 -------------]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 18.38 ms]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:66 [core model detection over, got 1 objects. Now filtering]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:103 [Returning filtered list of 1 objects.]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: ['car'],conf:[0.61328125]]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:502 [intersection: object:car,POLYGON ((290 6, 363 6, 363 39, 290 39, 290 6)) intersects polygon:road,POLYGON ((615 10, 610 44, 566 50, 512 55, 505 35, 184 105, 0 153, 0 75, 140 55, 145 39, 199 4, 531 2, 615 10))]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:518 [Using global match pattern: (person|car|motorbike|bus|truck|boat|dog|cat|bike|nightbug)]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:526 [road intersects object:car[[(290, 6), (363, 6), (363, 39), (290, 39)]]]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:753 [breaking out of same model loop, as matches found and strategy is "first"]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:654 [perf: Starting for frame:69]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:669 [============ Frame: 69 Running object detection type in sequence ==================]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:701 [--------- Frame:69 Running variation: #1 -------------]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:53 [Got pyzm_uid33_tpu_lock portalock]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:163 [|---------- TPU (input image: 800w*450h) ----------|]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:68 [Released portalock pyzm_uid33_tpu_lock]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 coral_edgetpu.py:185 [perf: processor:tpu Coral TPU detection took: 17.38 ms]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:66 [core model detection over, got 1 objects. Now filtering]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:70 [Max object size found to be: 90%]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:78 [Converted 90% to 324000.0]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 object.py:103 [Returning filtered list of 1 objects.]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:711 [This model iteration inside object found: labels: ['car'],conf:[0.60546875]]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:424 [Max object size found to be: 90%]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:432 [Converted 90% to 324000.0]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:502 [intersection: object:car,POLYGON ((199 10, 234 10, 234 31, 199 31, 199 10)) intersects polygon:road,POLYGON ((615 10, 610 44, 566 50, 512 55, 505 35, 184 105, 0 153, 0 75, 140 55, 145 39, 199 4, 531 2, 615 10))]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:518 [Using global match pattern: (person|car|motorbike|bus|truck|boat|dog|cat|bike|nightbug)]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:526 [road intersects object:car[[(199, 10), (234, 10), (234, 31), (199, 31)]]]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 detect_sequence.py:753 [breaking out of same model loop, as matches found and strategy is "first"]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:654 [perf: Starting for frame:70]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:664 [Sequence of detection types to execute: ['object']]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:669 [============ Frame: 70 Running object detection type in sequence ==================]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG1 detect_sequence.py:701 [--------- Frame:70 Running variation: #1 -------------]
11/21/22 17:56:34 zmesdetect_m5[8930] DBG2 coral_edgetpu.py:51 [Waiting for pyzm_uid33_tpu_lock portalock...]
<< This is exactly where the log ends for this process>>

This is from the output of my custom script running process 2:
Mon Nov 21 17:56:29 2022: Using normal config: /etc/zm/objectconfig.ini
F driver/usb/usb_driver.cc:1148] HandleQueuedBulkIn transfer in failed. Not found: USB transfer error 5 [LibUsbDataInCallback]
Mon Nov 21 17:56:36 2022: zm_detect: Monitorid: 5, Eventid: 14298249, ReturnCode0, ErrorCode:0

Thanks!

waynieack commented 1 year ago

Update: It's def an issue with how it locks and unlocks for every frame with the edge tpu. I updated /pyzm/ml/coral_edgetpu.py as below in def detect to not release the lock after each frame, so now it just releases when the zm_detect.py script is done and I don't get the error when a second process starts any more.

But this could cause issues where the lock is never released. I believe I am seeing this when I chain the edge tpu and 2 other yolov4 models, I don't see any issue when I chain the edge tpu with 1 yolo model. I need to do more investigation for the locks with more than 2 models to verify if its caused by the change I made or if its happening anyway. 

179
180             if self.options.get('auto_lock',True):
181                 #self.release_lock()
182                 g.logger.Debug(2,'Not Releasing Lock')
183         except:
184             if self.options.get('auto_lock',True):
waynieack commented 1 year ago

Moved this to pyzm. https://github.com/ZoneMinder/pyzm/issues/43