diff --git a/client/ayon_core/addon/base.py b/client/ayon_core/addon/base.py index 342bcd810cb..260c378eec9 100644 --- a/client/ayon_core/addon/base.py +++ b/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 diff --git a/client/ayon_core/cli.py b/client/ayon_core/cli.py index b506b5ff0d6..514a047985f 100644 --- a/client/ayon_core/cli.py +++ b/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) @@ -436,7 +436,5 @@ def main(*args, **kwargs): 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) diff --git a/client/ayon_core/host/host.py b/client/ayon_core/host/host.py index b52506c0b8b..50c8bbb9270 100644 --- a/client/ayon_core/host/host.py +++ b/client/ayon_core/host/host.py @@ -1,7 +1,6 @@ from __future__ import annotations import os -import logging import contextlib import typing from typing import Optional, Any @@ -9,7 +8,15 @@ 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, diff --git a/client/ayon_core/lib/__init__.py b/client/ayon_core/lib/__init__.py index 6fd10ee0002..b6d30b9124e 100644 --- a/client/ayon_core/lib/__init__.py +++ b/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", diff --git a/client/ayon_core/lib/log.py b/client/ayon_core/lib/log.py index 335f2eaf97e..c910ea91540 100644 --- a/client/ayon_core/lib/log.py +++ b/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 diff --git a/client/ayon_core/pipeline/context_tools.py b/client/ayon_core/pipeline/context_tools.py index fba3e08e5bc..fcb31e02b4b 100644 --- a/client/ayon_core/pipeline/context_tools.py +++ b/client/ayon_core/pipeline/context_tools.py @@ -32,6 +32,10 @@ deregister_inventory_action_path ) +import structlog +from structlog.contextvars import bind_contextvars, clear_contextvars + + _is_installed = False _process_id = None @@ -163,6 +167,8 @@ def modified_emit(obj, record): for addon in addons_manager.get_enabled_addons(): addon.on_host_install(host, host_name, project_name) + bind_contextvars(host_name=host_name, project=project_name) + install_ayon_plugins(project_name, host_name) diff --git a/client/ayon_core/pipeline/publish/logic.py b/client/ayon_core/pipeline/publish/logic.py index 3c2b395fbeb..d384a8fbd63 100644 --- a/client/ayon_core/pipeline/publish/logic.py +++ b/client/ayon_core/pipeline/publish/logic.py @@ -1017,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 @@ -1027,7 +1026,6 @@ def _log_manager(self, plugin: PluginType): if not plugin.log.propagate: plugin_log_has_handler = True plugin.log.addHandler(self._log_handler) - root.addHandler(self._log_handler) ayon_root.addHandler(self._log_handler) try: @@ -1037,7 +1035,6 @@ def _log_manager(self, plugin: PluginType): if plugin_log_has_handler: 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() diff --git a/pyproject.toml b/pyproject.toml index 41f836f7560..14bfb4cb518 100644 --- a/pyproject.toml +++ b/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", +] diff --git a/uv.lock b/uv.lock index 12ff17841eb..b5c098be570 100644 --- a/uv.lock +++ b/uv.lock @@ -25,7 +25,7 @@ wheels = [ [[package]] name = "ayon-core" -version = "1.9.7+dev" +version = "1.9.10+dev" source = { virtual = "." } dependencies = [ { name = "arrow" }, @@ -43,9 +43,12 @@ dependencies = [ { name = "pyblish-base" }, { name = "pyside6" }, { name = "qtpy" }, + { name = "requests" }, + { name = "rich" }, { name = "ruff" }, { name = "semver" }, { name = "speedcopy" }, + { name = "structlog" }, ] [package.optional-dependencies] @@ -85,9 +88,12 @@ requires-dist = [ { name = "pytest-regressions", extras = ["image"], marker = "extra == 'test'" }, { name = "pytest-timeout", marker = "extra == 'test'" }, { name = "qtpy", specifier = ">=2.4.3" }, + { name = "requests", specifier = ">=2.32.5" }, + { name = "rich", specifier = ">=15.0.0" }, { name = "ruff", specifier = ">=0.11.7" }, { name = "semver", specifier = ">=3.0.2" }, { name = "speedcopy", specifier = ">=2.1.0" }, + { name = "structlog", specifier = ">=26.1.0" }, ] provides-extras = ["test"] @@ -238,6 +244,27 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/6f/e3/33450438ff3a8c581d4ed7f798a70b07c3206d298cf0b87d3806e72e3ed8/librt-0.7.8-cp311-cp311-win_arm64.whl", hash = "sha256:20e3946863d872f7cabf7f77c6c9d370b8b3d74333d3a32471c50d3a86c0a232", size = 43383, upload-time = "2026-01-14T12:55:07.49Z" }, ] +[[package]] +name = "markdown-it-py" +version = "4.2.0" +source = { registry = "https://pypi.org/simple" } +dependencies = [ + { name = "mdurl" }, +] +sdist = { url = "https://files.pythonhosted.org/packages/06/ff/7841249c247aa650a76b9ee4bbaeae59370dc8bfd2f6c01f3630c35eb134/markdown_it_py-4.2.0.tar.gz", hash = "sha256:04a21681d6fbb623de53f6f364d352309d4094dd4194040a10fd51833e418d49", size = 82454, upload-time = "2026-05-07T12:08:28.36Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/b3/81/4da04ced5a082363ecfa159c010d200ecbd959ae410c10c0264a38cac0f5/markdown_it_py-4.2.0-py3-none-any.whl", hash = "sha256:9f7ebbcd14fe59494226453aed97c1070d83f8d24b6fc3a3bcf9a38092641c4a", size = 91687, upload-time = "2026-05-07T12:08:27.182Z" }, +] + +[[package]] +name = "mdurl" +version = "0.1.2" +source = { registry = "https://pypi.org/simple" } +sdist = { url = "https://files.pythonhosted.org/packages/d6/54/cfe61301667036ec958cb99bd3efefba235e65cdeb9c84d24a8293ba1d90/mdurl-0.1.2.tar.gz", hash = "sha256:bb413d29f5eea38f31dd4754dd7377d4465116fb207585f97bf925588687c1ba", size = 8729, upload-time = "2022-08-14T12:40:10.846Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/b3/38/89ba8ad64ae25be8de66a6d463314cf1eb366222074cfda9ee839c56a4b4/mdurl-0.1.2-py3-none-any.whl", hash = "sha256:84008a41e51615a49fc9966191ff91509e3c40b939176e643fd50a5c2196b8f8", size = 9979, upload-time = "2022-08-14T12:40:09.779Z" }, +] + [[package]] name = "mock" version = "5.2.0" @@ -641,6 +668,19 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/1e/db/4254e3eabe8020b458f1a747140d32277ec7a271daf1d235b70dc0b4e6e3/requests-2.32.5-py3-none-any.whl", hash = "sha256:2462f94637a34fd532264295e186976db0f5d453d1cdd31473c85a6a161affb6", size = 64738, upload-time = "2025-08-18T20:46:00.542Z" }, ] +[[package]] +name = "rich" +version = "15.0.0" +source = { registry = "https://pypi.org/simple" } +dependencies = [ + { name = "markdown-it-py" }, + { name = "pygments" }, +] +sdist = { url = "https://files.pythonhosted.org/packages/c0/8f/0722ca900cc807c13a6a0c696dacf35430f72e0ec571c4275d2371fca3e9/rich-15.0.0.tar.gz", hash = "sha256:edd07a4824c6b40189fb7ac9bc4c52536e9780fbbfbddf6f1e2502c31b068c36", size = 230680, upload-time = "2026-04-12T08:24:00.75Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/82/3b/64d4899d73f91ba49a8c18a8ff3f0ea8f1c1d75481760df8c68ef5235bf5/rich-15.0.0-py3-none-any.whl", hash = "sha256:33bd4ef74232fb73fe9279a257718407f169c09b78a87ad3d296f548e27de0bb", size = 310654, upload-time = "2026-04-12T08:24:02.83Z" }, +] + [[package]] name = "ruff" version = "0.14.14" @@ -706,6 +746,15 @@ wheels = [ { url = "https://files.pythonhosted.org/packages/bb/e9/072654390b47e33fc84bc8fb593617d4b34431b6e78aa203d40343ae269a/speedcopy-2.1.5-py3-none-any.whl", hash = "sha256:903d0b466c2bef7c07dfac17493cdfbc09aadd70e947199c81caa6c6da2c095f", size = 12836, upload-time = "2024-02-20T13:44:49.762Z" }, ] +[[package]] +name = "structlog" +version = "26.1.0" +source = { registry = "https://pypi.org/simple" } +sdist = { url = "https://files.pythonhosted.org/packages/5e/89/b4a0bcfdf4f71a3dea31379f095929613d7e4528a0996bca6aa964cd0dca/structlog-26.1.0.tar.gz", hash = "sha256:f63a716cbd1b1291cf7661de7794b455acfa4c43c5bcf1630e6ad5ddc1adb3b7", size = 1459881, upload-time = "2026-06-06T07:33:39.348Z" } +wheels = [ + { url = "https://files.pythonhosted.org/packages/a9/18/489c97b834dfff9cf2fc2507cede4bcd4b11e67f84bc462acd1992496f86/structlog-26.1.0-py3-none-any.whl", hash = "sha256:e081a26d6c373e6d201eca24eede26d8ffab07f88f477822e679183428d3d91e", size = 73764, upload-time = "2026-06-06T07:33:38.046Z" }, +] + [[package]] name = "typing-extensions" version = "4.15.0"