Add structured logging support

client/ayon_core/addon/base.py

@@ -672,7 +672,7 @@ def initialize_addons(self) -> None:
         # Make sure modules are loaded
         load_addons()
 
-        self.log.debug("*** AYON addons initialization.")
+        self.log.debug("AYON addons initialization.")
 
         # Prepare settings for addons
         settings = self._settings

client/ayon_core/cli.py

@@ -2,9 +2,8 @@
 """Package for handling AYON command line arguments."""
 import os
 import sys
-import logging
 import code
 import traceback
 from pathlib import Path
 
 import click
@@ -17,12 +16,17 @@
     initialize_ayon_connection,
     is_running_from_build,
     Logger,
+    configure_logger,
 )
 from ayon_core.lib.env_tools import (
     parse_env_variables_structure,
     compute_env_variables_structure,
     merge_env_variables,
 )
+import structlog
+
+
+configure_logger()
 
 
 @click.group(invoke_without_command=True)
@@ -275,10 +279,8 @@
         version_ids (str): Comma separated version ids.
 
     """
-
-    print(f">>> Launching browser for Delivery action '{project}'.")
-
-    log = Logger.get_logger("delivery")
+    log = structlog.get_logger("delivery")
+    log.debug("Launching browser for Delivery action.", project=project)
 
     try:
         from ayon_core.tools.delivery.delivery import DeliveryOptionsDialog
@@ -401,8 +403,7 @@
 
 
 def main(*args, **kwargs):
-    logging.basicConfig()
-
+    logger = structlog.get_logger("main")
     initialize_ayon_connection()
     python_path = os.getenv("PYTHONPATH", "")
     split_paths = python_path.split(os.pathsep)
@@ -419,10 +420,9 @@
             sys.path.insert(0, path)
     os.environ["PYTHONPATH"] = os.pathsep.join(split_paths)
 
-    print(">>> loading environments ...")
-    print("  - global AYON ...")
+    logger.debug("Loading environment for AYON.")
     _set_global_environments()
-    print("  - for addons ...")
+    logger.debug("Loading environment for addons.")
     addons_manager = AddonsManager()
     _set_addons_environments(addons_manager)
     _add_addons(addons_manager)
@@ -436,7 +436,5 @@
             args=(sys.argv[1:]),
         )
     except Exception:  # noqa
-        exc_info = sys.exc_info()
-        print("!!! AYON crashed:")
-        traceback.print_exception(*exc_info)
+        logger.error("AYON crashed", exc_info=True)
         sys.exit(1)

client/ayon_core/host/host.py

@@ -1,15 +1,22 @@
 from __future__ import annotations
 
 import os
-import logging
 import contextlib
 import typing
 from typing import Optional, Any
 from dataclasses import dataclass
 
 import ayon_api
 
+import structlog
+from structlog.contextvars import (
+    bind_contextvars,
+    clear_contextvars,
+    unbind_contextvars,
+)
+
 from ayon_core.lib import emit_event
+from ayon_core.lib.log import configure_logger
 
 from .constants import ContextChangeReason
 from .abstract import AbstractHost, ApplicationInformation
@@ -29,6 +36,13 @@ class ContextChangeData:
     anatomy: Anatomy
 
 
+@dataclass
+class AyonLogContext:
+    project: str
+    folder: str
+    task: str
+
+
 class HostBase(AbstractHost):
     """Base of host implementation class.
 
@@ -93,8 +107,9 @@ def __init__(self):
             to implement 'install' method which is triggered after global
             'install'.
         """
-
-        pass
+        configure_logger()
+        clear_contextvars()
+        bind_contextvars(host=self.__class__.__name__)
 
     def get_app_information(self) -> ApplicationInformation:
         """Running application information.
@@ -118,12 +133,11 @@ def install(self):
         triggered.
 
         """
-        pass
 
     @property
-    def log(self) -> logging.Logger:
+    def log(self) -> structlog.BoundLogger:
         if self._log is None:
-            self._log = logging.getLogger(self.__class__.__name__)
+            self._log = structlog.get_logger(self.__class__.__name__)
         return self._log
 
     def get_current_project_name(self) -> str:
@@ -231,7 +245,12 @@ def set_current_context(
         self._before_context_change(context_change_data)
         self._set_current_context(context_change_data)
         self._after_context_change(context_change_data)
-
+        unbind_contextvars("ayon_context")
+        bind_contextvars(ayon_context=AyonLogContext(
+            project=project_name,
+            folder=folder_path,
+            task=task_name,
+        ))
         return self._emit_context_change_event(
             project_name,
             folder_path,

client/ayon_core/lib/__init__.py

@@ -3,7 +3,7 @@
 """AYON lib functions."""
 
 from .terminal import Terminal
-from .log import Logger
+from .log import Logger, configure_logger
 from ._compatibility import StrEnum
 from .local_settings import (
     IniSettingRegistry,
@@ -156,6 +156,7 @@
 
 __all__ = [
     "Logger",
+    "configure_logger",
 
     "StrEnum",
 

client/ayon_core/lib/log.py

@@ -3,16 +3,177 @@
 import copy
 import getpass
 import logging
+import queue
+from logging.handlers import QueueHandler, QueueListener
 import os
 import platform
+import requests
+import requests.adapters
 import socket
 import sys
 import time
 import threading
 import warnings
 
+import structlog
+
 from . import Terminal
 
+VECTOR_LOG_URL = os.getenv("AYON_VECTOR_LOG_URL", None)
+
+
+class _RawQueueHandler(QueueHandler):
+    """QueueHandler that does not pre-format/stringify the record.
+
+    The stdlib's default 'prepare' stringifies 'record.msg', which
+    destroys the structlog event dict before it reaches the listener's
+    handlers.
+    """
+
+    def prepare(self, record):
+        return record
+
+
+class VectorHTTPHandler(logging.Handler):
+    """Forward formatted log records to a Vector HTTP source."""
+
+    def __init__(self, url):
+        super().__init__()
+        self._url = url
+        # Reuse a single session so repeated POSTs reuse pooled
+        # connections instead of opening a new one per log record.
+        self._session = requests.Session()
+        adapter = requests.adapters.HTTPAdapter(
+            pool_connections=1, pool_maxsize=10
+        )
+        self._session.mount("http://", adapter)
+        self._session.mount("https://", adapter)
+
+    def emit(self, record):
+        try:
+            self._session.post(
+                self._url,
+                data=self.format(record),
+                headers={"Content-Type": "application/json"},
+                timeout=1,
+            )
+        except Exception:
+            self.handleError(record)
+
+    def close(self):
+        self._session.close()
+        super().close()
+
+
+def configure_logger() -> None:
+    """Configure logging for the application.
+
+    Including structlog and handlers for console and Vector HTTP.
+
+    Safe to call multiple times, and safe even if another package (e.g.
+    'ayon_common' in ayon-launcher) configures logging first - only the
+    first call in the process has any effect, to avoid attaching
+    duplicate handlers.
+
+    """
+    # 'structlog.is_configured()' is process-wide, so it also guards
+    # against other packages configuring logging first.
+    if structlog.is_configured():
+        return
+
+    def _add_site_id(logger, method_name, event_dict):
+        event_dict.setdefault(
+            "site_id", os.environ.get("AYON_SITE_ID", "unknown")
+        )
+        return event_dict
+
+    def _drop_site_id(logger, method_name, event_dict):
+        # Keep 'site_id' in JSON sent to Vector but not in console output
+        event_dict.pop("site_id", None)
+        return event_dict
+
+    shared_processors = [
+        structlog.contextvars.merge_contextvars,
+        structlog.processors.add_log_level,
+        structlog.stdlib.add_logger_name,
+        structlog.processors.TimeStamper(fmt="iso"),
+        structlog.processors.StackInfoRenderer(),
+        _add_site_id,
+    ]
+
+    structlog.configure(
+        processors=shared_processors + [
+            # Prepares details if sent to standard logging
+            structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
+        ],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        wrapper_class=structlog.stdlib.BoundLogger,
+        cache_logger_on_first_use=True,
+    )
+
+    console_formatter = structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=shared_processors + [
+            structlog.stdlib.PositionalArgumentsFormatter(),
+        ],
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            _drop_site_id,
+            structlog.dev.ConsoleRenderer(
+                exception_formatter=structlog.dev.rich_traceback,
+            ),
+        ],
+    )
+    json_formatter = structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=shared_processors,
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            structlog.processors.format_exc_info,
+            structlog.processors.JSONRenderer(),
+        ],
+    )
+
+    handler = logging.StreamHandler(sys.stdout)
+    handler.setFormatter(console_formatter)
+
+    if VECTOR_LOG_URL:
+        # Send logs to Vector asynchronously so HTTP calls don't block the app.
+        vector_handler = VectorHTTPHandler(VECTOR_LOG_URL)
+        vector_handler.setFormatter(json_formatter)
+        log_queue = queue.Queue(-1)
+        queue_handler = _RawQueueHandler(log_queue)
+        queue_listener = QueueListener(
+            log_queue, vector_handler, respect_handler_level=True
+        )
+        queue_listener.start()
+
+    root_logger = logging.getLogger()
+    root_logger.addHandler(handler)
+    if VECTOR_LOG_URL:
+        root_logger.addHandler(queue_handler)
+    # set default logging level to INFO, but
+    # allow override via AYON_LOG_LEVEL or AYON_DEBUG
+    root_logger.setLevel(logging.INFO)
+    if os.getenv("AYON_LOG_LEVEL") is not None:
+        root_logger.setLevel(int(os.getenv("AYON_LOG_LEVEL", logging.INFO)))
+    if os.getenv("AYON_DEBUG") is not None:
+        root_logger.setLevel(logging.DEBUG)
+
+    info_level = logging.getLevelNamesMapping()['INFO']
+    if (
+            os.getenv("AYON_DEBUG") == "1" or
+            int(os.getenv("AYON_LOG_LEVEL", info_level)) < info_level):
+        logging.getLogger("urllib3").setLevel(logging.WARNING)
+        logging.getLogger("requests").setLevel(logging.WARNING)
+        logging.getLogger("GlobalServerAPI").setLevel(logging.WARNING)
+
+    # 'Logger' (ayon_core.lib.log) may have attached its own fallback
+    # console handler to the "AYON" logger before structlog was configured.
+    # Drop it and let records propagate to the root logger instead, which
+    # now owns the shared handlers - avoids logging each record twice.
+    ayon_logger = Logger.get_root_logger()
+    for old_handler in list(ayon_logger.handlers):
+        ayon_logger.removeHandler(old_handler)
+
 
 class LogStreamHandler(logging.StreamHandler):
     """StreamHandler class.
@@ -138,10 +299,15 @@ class Logger:
 
     @classmethod
     @_deprecated_getter
-    def get_logger(cls, name: str) -> logging.Logger:
+    def get_logger(cls, name: str) -> structlog.BoundLogger | logging.Logger:
         if not cls.initialized:
             cls.initialize()
 
+        # Delegate to structlog when configured so records share the same
+        # processors (e.g. 'site_id', timestamps) as the rest of the app.
+        if structlog.is_configured():
+            return structlog.get_logger(name or "__main__")
+
         logger = logging.getLogger(name or "__main__")
         logger.setLevel(cls.log_level)
         logger.parent = cls._root_logger
@@ -191,9 +357,12 @@ def _initialize(cls):
                 log_level = 20
         cls.log_level = int(log_level)
         root_logger = logging.getLogger("AYON")
-        root_logger.propagate = False
+        # root_logger.propagate = False
         root_logger.setLevel(cls.log_level)
-        root_logger.addHandler(cls._get_console_handler())
+        # Skip own handler when structlog already owns the output pipeline
+        # to avoid double-formatting/handling the same records.
+        if not structlog.is_configured():
+            root_logger.addHandler(cls._get_console_handler())
         cls._root_logger = root_logger
 
         # Mark as initialized