Merge pull request #229 from angelala3252/feat/tracing

Implement tracing

openadapt/record.py

@@ -24,6 +24,8 @@
 
 from openadapt import config, crud, utils, window
 
+import functools
+
 
 EVENT_TYPES = ("screen", "action", "window")
 LOG_LEVEL = "INFO"
@@ -37,6 +39,39 @@
 
 Event = namedtuple("Event", ("timestamp", "type", "data"))
 
+utils.configure_logging(logger, LOG_LEVEL)
+
+
+def args_to_str(*args):
+    return ", ".join(map(str, args))
+
+
+def kwargs_to_str(**kwargs):
+    return ",".join([f"{k}={v}" for k, v in kwargs.items()])
+
+
+def trace(logger):
+    def decorator(func):
+        @functools.wraps(func)
+        def wrapper_logging(*args, **kwargs):
+            func_name = func.__qualname__
+            func_args = args_to_str(*args)
+            func_kwargs = kwargs_to_str(**kwargs)
+
+            if func_kwargs != "":
+                logger.info(f" -> Enter: {func_name}({func_args}, {func_kwargs})")
+            else:
+                logger.info(f" -> Enter: {func_name}({func_args})")
+
+            result = func(*args, **kwargs)
+
+            logger.info(f" <- Leave: {func_name}({result})")
+            return result
+
+        return wrapper_logging
+
+    return decorator
+
 
 def process_event(event, write_q, write_fn, recording_timestamp, perf_q):
     if PROC_WRITE_BY_EVENT_TYPE[event.type]:
@@ -45,6 +80,7 @@ def process_event(event, write_q, write_fn, recording_timestamp, perf_q):
         write_fn(recording_timestamp, event, perf_q)
 
 
+@trace(logger)
 def process_events(
     event_q: queue.Queue,
     screen_write_q: multiprocessing.Queue,
@@ -186,6 +222,7 @@ def write_window_event(
     perf_q.put((event.type, event.timestamp, utils.get_timestamp()))
 
 
+@trace(logger)
 def write_events(
     event_type: str,
     write_fn: Callable,
@@ -347,6 +384,7 @@ def read_screen_events(
     logger.info("done")
 
 
+@trace(logger)
 def read_window_events(
     event_q: queue.Queue,
     terminate_event: multiprocessing.Event,
@@ -394,7 +432,8 @@ def read_window_events(
         prev_window_data = window_data
 
 
-def performance_stats_writer(
+@trace(logger)
+def performance_stats_writer (
     perf_q: multiprocessing.Queue,
     recording_timestamp: float,
     terminate_event: multiprocessing.Event,
@@ -428,6 +467,7 @@ def performance_stats_writer(
     logger.info("performance stats writer done")
 
 
+@trace(logger)
 def create_recording(
     task_description: str,
 ) -> Dict[str, Any]:
@@ -504,6 +544,7 @@ def read_mouse_events(
     mouse_listener.stop()
 
 
+@trace(logger)
 def record(
     task_description: str,
 ):

openadapt/utils.py

@@ -14,6 +14,7 @@
 import mss
 import mss.base
 import numpy as np
+from logging import StreamHandler
 
 from openadapt import common, config
 
@@ -26,9 +27,18 @@ def configure_logging(logger, log_level):
     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(
-        sys.stderr,
+        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=}")