From d60ca9d7835b07d1ece8fc0468dba3ee28eedaa1 Mon Sep 17 00:00:00 2001 From: Blake Blackshear Date: Fri, 4 Dec 2020 06:59:03 -0600 Subject: [PATCH] log level configuration --- frigate/app.py | 6 ++++++ frigate/config.py | 30 +++++++++++++++++++++++++++++- frigate/edgetpu.py | 9 +++++---- frigate/log.py | 35 ++++++++++++++++++++++++++++++++++- frigate/test/test_config.py | 36 ++++++++++++++++++++++++++++++++++++ frigate/video.py | 34 ++++++++++++++++++++-------------- 6 files changed, 130 insertions(+), 20 deletions(-) diff --git a/frigate/app.py b/frigate/app.py index 9507ca3d0..cbf9badbd 100644 --- a/frigate/app.py +++ b/frigate/app.py @@ -65,6 +65,11 @@ class FrigateApp(): 'ffmpeg_pid': mp.Value('i', 0), 'frame_queue': mp.Queue(maxsize=2) } + + def set_log_levels(self): + logging.getLogger().setLevel(self.config.logger.default) + for log, level in self.config.logger.logs.items(): + logging.getLogger(log).setLevel(level) def init_queues(self): # Queues for clip processing @@ -149,6 +154,7 @@ class FrigateApp(): logger.error(f"Error parsing config: {e}") self.log_process.terminate() sys.exit(1) + self.set_log_levels() self.init_queues() self.init_database() self.init_mqtt() diff --git a/frigate/config.py b/frigate/config.py index 4bd74411a..55baa48b3 100644 --- a/frigate/config.py +++ b/frigate/config.py @@ -194,6 +194,10 @@ FRIGATE_CONFIG_SCHEMA = vol.Schema( { vol.Optional('detectors', default=DEFAULT_DETECTORS): DETECTORS_SCHEMA, 'mqtt': MQTT_SCHEMA, + vol.Optional('logger', default={'default': 'info', 'logs': {}}): { + vol.Optional('default', default='info'): vol.In(['info', 'debug', 'warning', 'error', 'critical']), + vol.Optional('logs', default={}): {str: vol.In(['info', 'debug', 'warning', 'error', 'critical']) } + }, vol.Optional('save_clips', default={}): SAVE_CLIPS_SCHEMA, vol.Optional('record', default={}): { vol.Optional('enabled', default=False): bool, @@ -224,6 +228,24 @@ class DetectorConfig(): 'device': self.device } +class LoggerConfig(): + def __init__(self, config): + self._default = config['default'].upper() + self._logs = {k: v.upper() for k, v in config['logs'].items()} + + @property + def default(self): + return self._default + + @property + def logs(self): + return self._logs + + def to_dict(self): + return { + 'default': self.default, + 'logs': self.logs + } class MqttConfig(): def __init__(self, config): @@ -728,6 +750,7 @@ class FrigateConfig(): self._mqtt = MqttConfig(config['mqtt']) self._save_clips = SaveClipsConfig(config['save_clips']) self._cameras = { name: CameraConfig(name, c, config) for name, c in config['cameras'].items() } + self._logger = LoggerConfig(config['logger']) def _sub_env_vars(self, config): frigate_env_vars = {k: v for k, v in os.environ.items() if k.startswith('FRIGATE_')} @@ -757,13 +780,18 @@ class FrigateConfig(): 'detectors': {k: d.to_dict() for k, d in self.detectors.items()}, 'mqtt': self.mqtt.to_dict(), 'save_clips': self.save_clips.to_dict(), - 'cameras': {k: c.to_dict() for k, c in self.cameras.items()} + 'cameras': {k: c.to_dict() for k, c in self.cameras.items()}, + 'logger': self.logger.to_dict() } @property def detectors(self) -> Dict[str, DetectorConfig]: return self._detectors + @property + def logger(self): + return self._logger + @property def mqtt(self): return self._mqtt diff --git a/frigate/edgetpu.py b/frigate/edgetpu.py index a45b10a9c..608e106ae 100644 --- a/frigate/edgetpu.py +++ b/frigate/edgetpu.py @@ -58,11 +58,11 @@ class LocalObjectDetector(ObjectDetector): if tf_device != 'cpu': try: - logging.info(f"Attempting to load TPU as {device_config['device']}") + logger.info(f"Attempting to load TPU as {device_config['device']}") edge_tpu_delegate = load_delegate('libedgetpu.so.1.0', device_config) - logging.info("TPU found") + logger.info("TPU found") except ValueError: - logging.info("No EdgeTPU detected. Falling back to CPU.") + logger.info("No EdgeTPU detected. Falling back to CPU.") if edge_tpu_delegate is None: self.interpreter = tflite.Interpreter( @@ -108,7 +108,8 @@ class LocalObjectDetector(ObjectDetector): def run_detector(name: str, detection_queue: mp.Queue, out_events: Dict[str, mp.Event], avg_speed, start, tf_device): threading.current_thread().name = f"detector:{name}" - logging.info(f"Starting detection process: {os.getpid()}") + logger = logging.getLogger(f"detector.{name}") + logger.info(f"Starting detection process: {os.getpid()}") listen() stop_event = mp.Event() diff --git a/frigate/log.py b/frigate/log.py index cee19a3d9..8bd01ae56 100644 --- a/frigate/log.py +++ b/frigate/log.py @@ -1,6 +1,7 @@ # adapted from https://medium.com/@jonathonbao/python3-logging-with-multiprocessing-f51f460b8778 import logging import threading +import os import signal import queue import multiprocessing as mp @@ -10,7 +11,7 @@ from logging import handlers def listener_configurer(): root = logging.getLogger() console_handler = logging.StreamHandler() - formatter = logging.Formatter('%(threadName)-25s %(name)-16s %(levelname)-8s: %(message)s') + formatter = logging.Formatter('%(name)-30s %(levelname)-8s: %(message)s') console_handler.setFormatter(formatter) root.addHandler(console_handler) root.setLevel(logging.INFO) @@ -40,3 +41,35 @@ def log_process(log_queue): continue logger = logging.getLogger(record.name) logger.handle(record) + +# based on https://codereview.stackexchange.com/a/17959 +class LogPipe(threading.Thread): + def __init__(self, log_name, level): + """Setup the object with a logger and a loglevel + and start the thread + """ + threading.Thread.__init__(self) + self.daemon = False + self.logger = logging.getLogger(log_name) + self.level = level + self.fdRead, self.fdWrite = os.pipe() + self.pipeReader = os.fdopen(self.fdRead) + self.start() + + def fileno(self): + """Return the write file descriptor of the pipe + """ + return self.fdWrite + + def run(self): + """Run the thread, logging everything. + """ + for line in iter(self.pipeReader.readline, ''): + self.logger.log(self.level, line.strip('\n')) + + self.pipeReader.close() + + def close(self): + """Close the write end of the pipe. + """ + os.close(self.fdWrite) \ No newline at end of file diff --git a/frigate/test/test_config.py b/frigate/test/test_config.py index 71b935540..5278dc193 100644 --- a/frigate/test/test_config.py +++ b/frigate/test/test_config.py @@ -278,6 +278,42 @@ class TestConfig(TestCase): } } self.assertRaises(vol.MultipleInvalid, lambda: FrigateConfig(config=config)) + + def test_save_clips_should_default_to_global_objects(self): + config = { + 'mqtt': { + 'host': 'mqtt' + }, + 'save_clips': { + 'retain': { + 'default': 20, + 'objects': { + 'person': 30 + } + } + }, + 'objects': { + 'track': ['person', 'dog'] + }, + 'cameras': { + 'back': { + 'ffmpeg': { + 'inputs': [ + { 'path': 'rtsp://10.0.0.1:554/video', 'roles': ['detect'] } + ] + }, + 'height': 1080, + 'width': 1920, + 'save_clips': { + 'enabled': True + } + } + } + } + config = FrigateConfig(config=config) + assert(len(config.cameras['back'].save_clips.objects) == 2) + assert('dog' in config.cameras['back'].save_clips.objects) + assert('person' in config.cameras['back'].save_clips.objects) if __name__ == '__main__': main(verbosity=2) diff --git a/frigate/video.py b/frigate/video.py index e7862f899..85996c3f5 100755 --- a/frigate/video.py +++ b/frigate/video.py @@ -20,6 +20,7 @@ import numpy as np from frigate.config import CameraConfig from frigate.edgetpu import RemoteObjectDetector +from frigate.log import LogPipe from frigate.motion import MotionDetector from frigate.objects import ObjectTracker from frigate.util import (EventsPerSecond, FrameManager, @@ -73,7 +74,7 @@ def create_tensor_input(frame, region): # Expand dimensions since the model expects images to have shape: [1, 300, 300, 3] return np.expand_dims(cropped_frame, axis=0) -def stop_ffmpeg(ffmpeg_process): +def stop_ffmpeg(ffmpeg_process, logger): logger.info("Terminating the existing ffmpeg process...") ffmpeg_process.terminate() try: @@ -85,14 +86,14 @@ def stop_ffmpeg(ffmpeg_process): ffmpeg_process.communicate() ffmpeg_process = None -def start_or_restart_ffmpeg(ffmpeg_cmd, frame_size=None, ffmpeg_process=None): +def start_or_restart_ffmpeg(ffmpeg_cmd, logger, logpipe: LogPipe, frame_size=None, ffmpeg_process=None): if not ffmpeg_process is None: - stop_ffmpeg(ffmpeg_process) + stop_ffmpeg(ffmpeg_process, logger) if frame_size is None: - process = sp.Popen(ffmpeg_cmd, stdout = sp.DEVNULL, stdin = sp.DEVNULL, start_new_session=True) + process = sp.Popen(ffmpeg_cmd, stdout = sp.DEVNULL, stderr=logpipe, stdin = sp.DEVNULL, start_new_session=True) else: - process = sp.Popen(ffmpeg_cmd, stdout = sp.PIPE, stdin = sp.DEVNULL, bufsize=frame_size*10, start_new_session=True) + process = sp.Popen(ffmpeg_cmd, stdout = sp.PIPE, stderr=logpipe, stdin = sp.DEVNULL, bufsize=frame_size*10, start_new_session=True) return process def capture_frames(ffmpeg_process, camera_name, frame_shape, frame_manager: FrameManager, @@ -139,11 +140,12 @@ def capture_frames(ffmpeg_process, camera_name, frame_shape, frame_manager: Fram class CameraWatchdog(threading.Thread): def __init__(self, camera_name, config, frame_queue, camera_fps, ffmpeg_pid, stop_event): threading.Thread.__init__(self) - self.name = f"watchdog:{camera_name}" + self.logger = logging.getLogger(f"watchdog.{camera_name}") self.camera_name = camera_name self.config = config self.capture_thread = None self.ffmpeg_detect_process = None + self.logpipe = LogPipe(f"ffmpeg.{self.camera_name}.detect", logging.ERROR) self.ffmpeg_other_processes = [] self.camera_fps = camera_fps self.ffmpeg_pid = ffmpeg_pid @@ -158,17 +160,21 @@ class CameraWatchdog(threading.Thread): for c in self.config.ffmpeg_cmds: if 'detect' in c['roles']: continue + logpipe = LogPipe(f"ffmpeg.{self.camera_name}.{'_'.join(sorted(c['roles']))}", logging.ERROR) self.ffmpeg_other_processes.append({ 'cmd': c['cmd'], - 'process': start_or_restart_ffmpeg(c['cmd']) + 'logpipe': logpipe, + 'process': start_or_restart_ffmpeg(c['cmd'], self.logger, logpipe) }) time.sleep(10) while True: if self.stop_event.is_set(): - stop_ffmpeg(self.ffmpeg_detect_process) + stop_ffmpeg(self.ffmpeg_detect_process, self.logger) for p in self.ffmpeg_other_processes: - stop_ffmpeg(p['process']) + stop_ffmpeg(p['process'], self.logger) + p['logpipe'].close() + self.logpipe.close() break now = datetime.datetime.now().timestamp() @@ -176,13 +182,13 @@ class CameraWatchdog(threading.Thread): if not self.capture_thread.is_alive(): self.start_ffmpeg_detect() elif now - self.capture_thread.current_frame.value > 20: - logger.info(f"No frames received from {self.camera_name} in 20 seconds. Exiting ffmpeg...") + self.logger.info(f"No frames received from {self.camera_name} in 20 seconds. Exiting ffmpeg...") self.ffmpeg_detect_process.terminate() try: - logger.info("Waiting for ffmpeg to exit gracefully...") + self.logger.info("Waiting for ffmpeg to exit gracefully...") self.ffmpeg_detect_process.communicate(timeout=30) except sp.TimeoutExpired: - logger.info("FFmpeg didnt exit. Force killing...") + self.logger.info("FFmpeg didnt exit. Force killing...") self.ffmpeg_detect_process.kill() self.ffmpeg_detect_process.communicate() @@ -190,14 +196,14 @@ class CameraWatchdog(threading.Thread): poll = p['process'].poll() if poll == None: continue - p['process'] = start_or_restart_ffmpeg(p['cmd'], ffmpeg_process=p['process']) + p['process'] = start_or_restart_ffmpeg(p['cmd'], self.logger, p['logpipe'], ffmpeg_process=p['process']) # wait a bit before checking again time.sleep(10) def start_ffmpeg_detect(self): ffmpeg_cmd = [c['cmd'] for c in self.config.ffmpeg_cmds if 'detect' in c['roles']][0] - self.ffmpeg_detect_process = start_or_restart_ffmpeg(ffmpeg_cmd, self.frame_size) + self.ffmpeg_detect_process = start_or_restart_ffmpeg(ffmpeg_cmd, self.logger, self.logpipe, self.frame_size) self.ffmpeg_pid.value = self.ffmpeg_detect_process.pid self.capture_thread = CameraCapture(self.camera_name, self.ffmpeg_detect_process, self.frame_shape, self.frame_queue, self.camera_fps)