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,7 +2,6 @@
 """Package for handling AYON command line arguments."""
 import os
 import sys
-import logging
 import code
 import traceback
 from pathlib import Path
@@ -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 @@ def deliver(
         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 _cleanup_project_args():
 
 
 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 @@ def main(*args, **kwargs):
             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)
@@ -437,6 +437,7 @@ def main(*args, **kwargs):
         )
     except Exception:  # noqa
         exc_info = sys.exc_info()
+        logger.error("AYON crashed", exc_info=exc_info)
         print("!!! AYON crashed:")
         traceback.print_exception(*exc_info)
         sys.exit(1)

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,
@@ -154,6 +154,7 @@
 
 __all__ = [
     "Logger",
+    "configure_logger",
 
     "StrEnum",
 

client/ayon_core/lib/log.py

@@ -3,16 +3,161 @@
 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.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(),
+        ],
+    )
+    json_formatter = structlog.stdlib.ProcessorFormatter(
+        foreign_pre_chain=shared_processors,
+        processors=[
+            structlog.stdlib.ProcessorFormatter.remove_processors_meta,
+            _drop_site_id,
+            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)
+    root_logger.setLevel(
+        logging.INFO if os.getenv("AYON_DEBUG") != "1" else logging.DEBUG)
+
+    # '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 +283,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 +341,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

client/ayon_core/pipeline/publish/logic.py

@@ -12,7 +12,6 @@
 import pyblish.logic
 import pyblish.plugin
 
-from ayon_core.lib import Logger
 from ayon_core.settings import get_project_settings
 from ayon_core.pipeline.plugin_discover import DiscoverResult
 
@@ -1018,7 +1017,6 @@ def _inner_publish_iter(self) -> PublishIterGen:
     @contextmanager
     def _log_manager(self, plugin: PluginType):
         root = logging.getLogger()
-        ayon_root = Logger.get_root_logger()
         plugin_log_has_handler = False
         orig_propagate = plugin.log.propagate
         if not self._log_to_console:
@@ -1027,8 +1025,9 @@ def _log_manager(self, plugin: PluginType):
         if not plugin.log.propagate:
             plugin_log_has_handler = True
             plugin.log.addHandler(self._log_handler)
+        # "AYON" logger propagates into root by default, so attaching
+        # the handler here alone is enough to capture both trees.
         root.addHandler(self._log_handler)
-        ayon_root.addHandler(self._log_handler)
 
         try:
             yield self._log_handler
@@ -1038,7 +1037,6 @@ def _log_manager(self, plugin: PluginType):
                 plugin.log.removeHandler(self._log_handler)
             plugin.log.propagate = orig_propagate
             root.removeHandler(self._log_handler)
-            ayon_root.removeHandler(self._log_handler)
             self._log_handler.clear_records()
 
     def _process_plugin(

pyproject.toml

@@ -33,7 +33,10 @@ dependencies = [
     "numpy >=2.4.3",
     "qtpy >=2.4.3",
     "pyside6 >=6.8.3",
-    "Pillow ==9.5.0"
+    "Pillow ==9.5.0",
+    "structlog>=26.1.0",
+    "rich>=15.0.0",
+    "requests>=2.32.5",
 ]
 
 [project.optional-dependencies]
@@ -68,6 +71,7 @@ log_cli = true
 log_cli_level = "INFO"
 addopts = "-ra -q"
 testpaths = [
+    "tests/ayon_core",
     "client/ayon_core/tests",
     "tests/client/ayon_core/ui",
 ]
@@ -83,3 +87,9 @@ markers = [
     "slow: Slow tests",
     "server: Tests that require a running AYON server",
 ]
+
+[tool.ty.environment]
+extra-paths = [
+    "client",
+    "tests/client/ayon_core/ui",
+]