Make logging code self-contained (#13785)

* Make logging code self-contained.

Rewrite logging code to use python's builting QueueListener, effectively
moving the logging process into a thread of the Frigate app.

Also, wrap this behaviour in a easy-to-use context manager to encourage
some consistency.

* Fixed typing errors

* Remove todo note from log filter

Co-authored-by: Nicolas Mowen <nickmowen213@gmail.com>

* Do not access log record's msg directly

* Clear all root handlers before starting app

---------

Co-authored-by: Nicolas Mowen <nickmowen213@gmail.com>

frigate/__main__.py

@@ -1,17 +1,28 @@
 import faulthandler
+import logging
 import threading
 
 from flask import cli
 
 from frigate.app import FrigateApp
 
-faulthandler.enable()
 
-threading.current_thread().name = "frigate"
+def main() -> None:
+    faulthandler.enable()
 
-cli.show_server_banner = lambda *x: None
+    # Clear all existing handlers.
+    logging.basicConfig(
+        level=logging.INFO,
+        handlers=[],
+        force=True,
+    )
 
-if __name__ == "__main__":
-    frigate_app = FrigateApp()
+    threading.current_thread().name = "frigate"
+    cli.show_server_banner = lambda *x: None
+
+    # Run the main application.
+    FrigateApp().start()
 
-    frigate_app.start()
+
+if __name__ == "__main__":
+    main()

frigate/app.py

@@ -43,7 +43,7 @@
 from frigate.events.cleanup import EventCleanup
 from frigate.events.external import ExternalEventProcessor
 from frigate.events.maintainer import EventProcessor
-from frigate.log import log_process, root_configurer
+from frigate.log import log_thread
 from frigate.models import (
     Event,
     Export,
@@ -113,15 +113,6 @@ def ensure_dirs(self) -> None:
             else:
                 logger.debug(f"Skipping directory: {d}")
 
-    def init_logger(self) -> None:
-        self.log_process = mp.Process(
-            target=log_process, args=(self.log_queue,), name="log_process"
-        )
-        self.log_process.daemon = True
-        self.log_process.start()
-        self.processes["logger"] = self.log_process.pid or 0
-        root_configurer(self.log_queue)
-
     def init_config(self) -> None:
         config_file = os.environ.get("CONFIG_FILE", "/config/config.yml")
 
@@ -667,6 +658,7 @@ def init_auth(self) -> None:
                 logger.info("********************************************************")
                 logger.info("********************************************************")
 
+    @log_thread()
     def start(self) -> None:
         parser = argparse.ArgumentParser(
             prog="Frigate",
@@ -675,7 +667,6 @@ def start(self) -> None:
         parser.add_argument("--validate-config", action="store_true")
         args = parser.parse_args()
 
-        self.init_logger()
         logger.info(f"Starting Frigate ({VERSION})")
 
         try:
@@ -702,13 +693,11 @@ def start(self) -> None:
                 print("*************************************************************")
                 print("***    End Config Validation Errors                       ***")
                 print("*************************************************************")
-                self.log_process.terminate()
                 sys.exit(1)
             if args.validate_config:
                 print("*************************************************************")
                 print("*** Your config file is valid.                            ***")
                 print("*************************************************************")
-                self.log_process.terminate()
                 sys.exit(0)
             self.set_environment_vars()
             self.set_log_levels()
@@ -725,7 +714,6 @@ def start(self) -> None:
             self.init_dispatcher()
         except Exception as e:
             print(e)
-            self.log_process.terminate()
             sys.exit(1)
         self.start_detectors()
         self.start_video_output_processor()
@@ -848,7 +836,4 @@ def stop(self) -> None:
             shm.close()
             shm.unlink()
 
-        self.log_process.terminate()
-        self.log_process.join()
-
         os._exit(os.EX_OK)

frigate/log.py

@@ -1,71 +1,71 @@
-# adapted from https://medium.com/@jonathonbao/python3-logging-with-multiprocessing-f51f460b8778
+import atexit
 import logging
 import multiprocessing as mp
 import os
-import queue
-import signal
 import threading
 from collections import deque
-from logging import handlers
-from multiprocessing import Queue
-from types import FrameType
+from contextlib import AbstractContextManager, ContextDecorator
+from logging.handlers import QueueHandler, QueueListener
+from types import TracebackType
 from typing import Deque, Optional
 
-from setproctitle import setproctitle
+from typing_extensions import Self
 
 from frigate.util.builtin import clean_camera_user_pass
 
+LOG_HANDLER = logging.StreamHandler()
+LOG_HANDLER.setFormatter(
+    logging.Formatter(
+        "[%(asctime)s] %(name)-30s %(levelname)-8s: %(message)s",
+        "%Y-%m-%d %H:%M:%S",
+    )
+)
 
-def listener_configurer() -> None:
-    root = logging.getLogger()
+LOG_HANDLER.addFilter(
+    lambda record: not record.getMessage().startswith(
+        "You are using a scalar distance function"
+    )
+)
 
-    if root.hasHandlers():
-        root.handlers.clear()
 
-    console_handler = logging.StreamHandler()
-    formatter = logging.Formatter(
-        "[%(asctime)s] %(name)-30s %(levelname)-8s: %(message)s", "%Y-%m-%d %H:%M:%S"
-    )
-    console_handler.setFormatter(formatter)
-    root.addHandler(console_handler)
-    root.setLevel(logging.INFO)
+class log_thread(AbstractContextManager, ContextDecorator):
+    def __init__(self, *, handler: logging.Handler = LOG_HANDLER):
+        super().__init__()
 
+        self._handler = handler
 
-def root_configurer(queue: Queue) -> None:
-    h = handlers.QueueHandler(queue)
-    root = logging.getLogger()
+        log_queue: mp.Queue = mp.Queue()
+        self._queue_handler = QueueHandler(log_queue)
 
-    if root.hasHandlers():
-        root.handlers.clear()
+        self._log_listener = QueueListener(
+            log_queue, self._handler, respect_handler_level=True
+        )
 
-    root.addHandler(h)
-    root.setLevel(logging.INFO)
+    @property
+    def handler(self) -> logging.Handler:
+        return self._handler
 
+    def _stop_thread(self) -> None:
+        self._log_listener.stop()
 
-def log_process(log_queue: Queue) -> None:
-    threading.current_thread().name = "logger"
-    setproctitle("frigate.logger")
-    listener_configurer()
+    def __enter__(self) -> Self:
+        logging.getLogger().addHandler(self._queue_handler)
 
-    stop_event = mp.Event()
+        atexit.register(self._stop_thread)
+        self._log_listener.start()
 
-    def receiveSignal(signalNumber: int, frame: Optional[FrameType]) -> None:
-        stop_event.set()
+        return self
 
-    signal.signal(signal.SIGTERM, receiveSignal)
-    signal.signal(signal.SIGINT, receiveSignal)
+    def __exit__(
+        self,
+        exc_type: Optional[type[BaseException]],
+        exc_info: Optional[BaseException],
+        exc_tb: Optional[TracebackType],
+    ) -> None:
+        logging.getLogger().removeHandler(self._queue_handler)
 
-    while True:
-        try:
-            record = log_queue.get(block=True, timeout=1.0)
-        except queue.Empty:
-            if stop_event.is_set():
-                break
-            continue
-        if record.msg.startswith("You are using a scalar distance function"):
-            continue
-        logger = logging.getLogger(record.name)
-        logger.handle(record)
+        atexit.unregister(self._stop_thread)
+        self._stop_thread()
 
 
 # based on https://codereview.stackexchange.com/a/17959

process_clip.py

@@ -28,8 +28,7 @@
     start_or_restart_ffmpeg,
 )
 
-logging.basicConfig()
-logging.root.setLevel(logging.DEBUG)
+logging.basicConfig(level=logging.DEBUG)
 
 logger = logging.getLogger(__name__)