Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Crash due to locking not handled properly with multiple zm_detect.py processes are run at once with the edgetpu. #43

Open
waynieack opened this issue Nov 30, 2022 · 2 comments
Open

Crash due to locking not handled properly with multiple zm_detect.py processes are run at once with the edgetpu. #43

waynieack opened this issue Nov 30, 2022 · 2 comments

Comments

@waynieack
Copy link

Event Server version
6.1.28

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

The version of ZoneMinder you are using:
v1.37.25

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.

For this scenario, I have object enabled with the edge TPU only.

  1. If no locks are held, the model is loaded and the first image is run through the TPU detection process, the lock is released and the rest of the process is completed for the image.
  2. As soon as the lock is released by process 1 for the first image, process 2 loads the model on the edge TPU and starts running the images through the detection process.
  3. Process 1 tries to start processing the next image at which point it dies. I've run this same test many times and process 1 always dies at the exact same point.

If this happens to many times the TPU will completely lock up and I have to unplug it and plug it back in to get it working again. I believe this same thing happens with the GPU/Yolo which handles it ok, but it will run out of memory periodically. The TPU only allows 1 process to access it so it just dies every time.

From what I see there's a couple ways to solve this:

  1. We could lock the devices that we are going to be using when the process starts, but we don't know exactly what we need before process the images so devices may be locked when not needed.

  2. We could lock the device when the model is loaded and don't unlock until the current process is done processing images with that model. The process could load additional models with the same lock that is already held for the GPU, etc (not sure if the same process can load multiple models on the TPU or not).

As a side note, an option to be able to run the models sequentially in post processing scenarios such as mine would be nice because there's really no reason (for me) after the event is complete to process each frame through every model, it would be better to just run each model on all the frames, if nothing found move to model 2 and so on. The current sequence makes complete sense with real time detection/events.

My current work around is to comment out the lock release in /pyzm/ml/coral_edgetpu.py so it doesn't release the lock after each frame for the TPU which means the lock is only released once the script is done, but this limits me to only 1 model so I can't do the face detection.

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):

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
@waynieack waynieack changed the title Crash due to locking not handeled properly with multiple zm_detect.py processes are run at once with the edgetpu. Crash due to locking not handled properly with multiple zm_detect.py processes are run at once with the edgetpu. Nov 30, 2022
@waynieack
Copy link
Author

I found where auto locking was supposed to be disabled when only one model type is used, which locks the device in detect_stream def in detect_sequence.py but the "auto_lock" false option is not being passed down to detect def. This at least fixes the issue when using a single model but if you add any other models then you will run into the same issue because it enables the auto lock again.

To fix the above issue, I added the following in pyzm/ml/detect_sequence.py - def _load_models:

177                             obj_seq['disable_locks'] = self.ml_options.get('general',{}).get('disable_locks', 'no')
178                          + obj_seq['auto_lock'] = self.ml_options.get(seq,{}).get('auto_lock', 'True')

194                             face_seq['disable_locks'] = self.ml_options.get('general',{}).get('disable_locks', 'no')
195                          + face_seq['auto_lock'] = self.ml_options.get(seq,{}).get('auto_lock', 'True')

207                             alpr_seq['disable_locks'] = self.ml_options.get('general',{}).get('disable_locks', 'no')
208                          + alpr_seq['auto_lock'] = self.ml_options.get(seq,{}).get('auto_lock', 'True')

I believe that the solution for this is to just pass the lock(s) from object to face instead of locking/unlocking as we just want to hold the device for the current process.
IE:

  1. detect_sequence will lock all devices for the first model type (just as it does now with the manual locking).
  2. detect_sequence will pass the locks from the first model type to the next model type, if any of the devices locked in the first model type is needed by the second, it will be verified as locked and move on.
  3. If a new device is required in the second model type then it would be locked at that time or wait for another process to be done with it.
  4. This same process would happen for any additional model type in the sequence.
  5. When looping back to the first model, all locks held would be passed back to it.
  6. When the frame processing is complete then detect_sequence would unlock all locks.

When I get more time I can attempt to work on this. I don't know Python worth a flip so its slow going.

@baudneo
Copy link
Contributor

baudneo commented Nov 30, 2022

Great job on tracking down the root issue!

@waynieack waynieack mentioned this issue Dec 1, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@waynieack @baudneo