fix(utils): prevent duplicate log messages (#339) (#366)

* fix(utils): prevent duplicate log messages (#339)

Acquire a lock in utils.configure_logging. Otherwise this function has
a race where two threads can both call logger.remove(), and then both
call logger.add(), creating two identical sinks.

* refactor(record): remove redundant configure_logging calls

configure_logging is already called at the module level so there's no
need to call it with identical arguments in various functions.

* fixup! fix(utils): prevent duplicate log messages (#339)

Author: nweston

openadapt/record.py

@@ -134,7 +134,6 @@ def process_events(
         terminate_event: An event to signal the termination of the process.
     """
 
-    utils.configure_logging(logger, LOG_LEVEL)
     utils.set_start_time(recording_timestamp)
     logger.info(f"starting")
 
@@ -278,7 +277,6 @@ def write_events(
             the number of events left to be written.
     """
 
-    utils.configure_logging(logger, LOG_LEVEL)
     utils.set_start_time(recording_timestamp)
     logger.info(f"{event_type=} starting")
     signal.signal(signal.SIGINT, signal.SIG_IGN)
@@ -436,7 +434,6 @@ def read_screen_events(
         recording_timestamp: The timestamp of the recording.
     """
 
-    utils.configure_logging(logger, LOG_LEVEL)
     utils.set_start_time(recording_timestamp)
     logger.info(f"starting")
     while not terminate_event.is_set():
@@ -463,7 +460,6 @@ def read_window_events(
         recording_timestamp: The timestamp of the recording.
     """
 
-    utils.configure_logging(logger, LOG_LEVEL)
     utils.set_start_time(recording_timestamp)
     logger.info(f"starting")
     prev_window_data = {}
@@ -513,7 +509,6 @@ def performance_stats_writer(
         terminate_event: An event to signal the termination of the process.
     """
 
-    utils.configure_logging(logger, LOG_LEVEL)
     utils.set_start_time(recording_timestamp)
     logger.info("performance stats writer starting")
     signal.signal(signal.SIGINT, signal.SIG_IGN)
@@ -535,7 +530,6 @@ def performance_stats_writer(
 def memory_writer(
     recording_timestamp: float, terminate_event: multiprocessing.Event, record_pid: int
 ):
-    utils.configure_logging(logger, LOG_LEVEL)
     utils.set_start_time(recording_timestamp)
     logger.info("Memory writer starting")
     signal.signal(signal.SIGINT, signal.SIG_IGN)
@@ -689,7 +683,6 @@ def record(
         task_description: a text description of the task that will be recorded
     """
 
-    utils.configure_logging(logger, LOG_LEVEL)
     logger.info(f"{task_description=}")
 
     recording = create_recording(task_description)

openadapt/utils.py

@@ -6,6 +6,7 @@
 import inspect
 import os
 import sys
+import threading
 import time
 
 from loguru import logger
@@ -20,27 +21,31 @@
 
 EMPTY = (None, [], {}, "")
 
+_logger_lock = threading.Lock()
+
 
 def configure_logging(logger, log_level):
     # TODO: redact log messages (https://github.com/Delgan/loguru/issues/17#issuecomment-717526130)
     log_level_override = os.getenv("LOG_LEVEL")
     log_level = log_level_override or log_level
-    logger.remove()
-    logger_format = (
-        "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
-        "<level>{level: <8}</level> | "
-        "<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> "
-        "- <level>{message}</level>"
-    )
-    logger.add(
-        StreamHandler(sys.stderr),
-        colorize=True,
-        level=log_level,
-        enqueue=True,
-        format=logger_format,
-        filter=config.filter_log_messages if config.IGNORE_WARNINGS else None,
-    )
-    logger.debug(f"{log_level=}")
+
+    with _logger_lock:
+        logger.remove()
+        logger_format = (
+            "<green>{time:YYYY-MM-DD HH:mm:ss.SSS}</green> | "
+            "<level>{level: <8}</level> | "
+            "<cyan>{name}</cyan>:<cyan>{function}</cyan>:<cyan>{line}</cyan> "
+            "- <level>{message}</level>"
+        )
+        logger.add(
+            StreamHandler(sys.stderr),
+            colorize=True,
+            level=log_level,
+            enqueue=True,
+            format=logger_format,
+            filter=config.filter_log_messages if config.IGNORE_WARNINGS else None,
+        )
+        logger.debug(f"{log_level=}")
 
 
 def row2dict(row, follow=True):