diff --git a/.github/workflows/build-ubuntu.yml b/.github/workflows/build-ubuntu.yml index 7ef47d67f2..1ea5cd7d41 100644 --- a/.github/workflows/build-ubuntu.yml +++ b/.github/workflows/build-ubuntu.yml @@ -875,7 +875,9 @@ jobs: # proxy up. This is the primary bring-up marker. BRINGUP_MARKER="CloudXR runtime and WSS proxy started" SESSION_MARKER="TeleopSession started successfully" - PLUGIN_MARKER_RE="wuji_glove\.WujiGlovePlugin\].*initialized and running" + # The console names a logger by its last segment only (logging_config's + # default), so the plugin's line reads "[WujiGlovePlugin] ...". + PLUGIN_MARKER_RE="\[WujiGlovePlugin\].*initialized and running" # Hard failures from the launcher, runtime, or plugin lifecycle. FAIL_RE="CloudXR runtime failed to start|SDK missing libcloudxr.so|CloudXR EULA was not accepted|CloudXR launcher is not running|runtime process exited unexpectedly|WSS proxy thread stopped unexpectedly|Plugin process exited immediately|Required plugin .* was not discovered" diff --git a/src/core/log_bridge/cpp/sink_config.cpp b/src/core/log_bridge/cpp/sink_config.cpp index a3b8abc1a8..310852e1fb 100644 --- a/src/core/log_bridge/cpp/sink_config.cpp +++ b/src/core/log_bridge/cpp/sink_config.cpp @@ -45,8 +45,10 @@ namespace constexpr std::size_t kFileMaxBytes = 10 * 1024 * 1024; // 10 MiB constexpr std::size_t kFileBackupCount = 5; -// Match Python's LINE_FORMAT; %* renders Python-style level names. -constexpr const char* kPattern = "[%Y-%m-%d %H:%M:%S.%e] [%*] [%n] [pid:%P] %v"; +// Match Python's LINE_FORMAT; %* renders Python-style level names. Only the console +// drops the date: log files need it across midnight, rotation and processes. +constexpr const char* kFilePattern = "[%Y-%m-%d %H:%M:%S.%e] [%*] [%n] [pid:%P] %v"; +constexpr const char* kConsolePattern = "[%H:%M:%S.%e] [%*] [%n] [pid:%P] %v"; // Map spdlog levels to Python's display names. std::string_view python_level_name(spdlog::level::level_enum level) @@ -91,10 +93,10 @@ class PythonLevelFormatter : public spdlog::custom_flag_formatter }; // Each sink owns its formatter. -std::unique_ptr make_formatter() +std::unique_ptr make_formatter(const char* pattern) { auto formatter = std::make_unique(); - formatter->add_flag('*').set_pattern(kPattern); + formatter->add_flag('*').set_pattern(pattern); return formatter; } @@ -337,7 +339,7 @@ const std::vector& local_sinks() { auto console = std::make_shared(); console->set_level(spdlog::level::trace); - console->set_formatter(make_formatter()); + console->set_formatter(make_formatter(kConsolePattern)); return std::vector{ console }; } @@ -352,7 +354,7 @@ const std::vector& local_sinks() // Build the infallible stderr sink before optional file setup. auto console = std::make_shared(); console->set_level(console_level()); - console->set_formatter(make_formatter()); + console->set_formatter(make_formatter(kConsolePattern)); auto dir = log_dir(); #ifndef _WIN32 @@ -399,7 +401,7 @@ const std::vector& local_sinks() auto file = std::make_shared( filename.string(), kFileMaxBytes, kFileBackupCount, false, events); file->set_level(spdlog::level::trace); // always captures everything. - file->set_formatter(make_formatter()); + file->set_formatter(make_formatter(kFilePattern)); return std::vector{ console, file }; } catch (const spdlog::spdlog_ex&) diff --git a/src/python/isaaccapture/logging_config/__init__.py b/src/python/isaaccapture/logging_config/__init__.py index 4219e0fa4d..a6b8336603 100644 --- a/src/python/isaaccapture/logging_config/__init__.py +++ b/src/python/isaaccapture/logging_config/__init__.py @@ -10,6 +10,9 @@ """ from ._console import set_console_filter, set_console_level, set_logger_colors +from ._console import ( + set_console_format, +) # Internal bootstrap; intentionally excluded from ``__all__``. from ._setup import install as install @@ -18,6 +21,7 @@ # Public configuration API. __all__ = [ "set_console_filter", + "set_console_format", "set_console_level", "set_logger_colors", "set_propagate_to_root", diff --git a/src/python/isaaccapture/logging_config/_console.py b/src/python/isaaccapture/logging_config/_console.py index ba32048922..5fa27b9d66 100644 --- a/src/python/isaaccapture/logging_config/_console.py +++ b/src/python/isaaccapture/logging_config/_console.py @@ -5,16 +5,17 @@ from __future__ import annotations +import functools import logging import os import re import threading +from collections.abc import Callable, Mapping +from typing import TypedDict, TypeVar from . import _forwarding, _native_fd from ._core import ( _LEVEL_NAME_BY_VALUE, - DATE_FORMAT, - LINE_FORMAT, TRACE, env_console_level, logging_enabled, @@ -50,13 +51,36 @@ def filter(self, record: logging.LogRecord) -> bool: # Accept only SGR color escapes such as ``\x1b[36m``. _SGR_ESCAPE = re.compile(r"(?:\x1b\[[0-9;]*m)+") -# Exact logger name to ANSI emphasis. +# Logger name to ANSI emphasis; a name's colour also covers its dotted descendants. _logger_colors: dict[str, str] = { # cloudxr.oob_teleop_env contains [setup-oob] / [usb-local] progress. "isaaccapture.cloudxr.oob_teleop_env": "\033[36m", } +_V = TypeVar("_V") + + +def _prefix_lookup(name: str, table: Mapping[str, _V]) -> _V | None: + """*table*'s value for *name* or its nearest dotted ancestor, else ``None``.""" + while name not in table and "." in name: + name = name.rpartition(".")[0] + return table.get(name) + + +def _cached_prefix_lookup(table: Mapping[str, _V]) -> Callable[[str], _V | None]: + """``_prefix_lookup`` over a copy of *table*, cached per logger name. + + The copy keeps every cached result valid, so a change to *table* needs a new lookup. + """ + table = dict(table) + return functools.cache(lambda name: _prefix_lookup(name, table)) + + +# set_logger_colors() replaces this lookup after every change, so it never goes stale. +_logger_color = _cached_prefix_lookup(_logger_colors) + + #: Color only WARNING and ERROR+ so severity remains distinctive. _LEVEL_WARNING_COLOR = "\033[33m" _LEVEL_ERROR_COLOR = "\033[31m" @@ -72,12 +96,19 @@ def _level_color(levelno: int) -> str | None: class _LoggerNameColorFormatter(logging.Formatter): - """Color terminal lines by level and optionally emphasize the logger name.""" - - def __init__(self, *args, handler: logging.StreamHandler, **kwargs) -> None: + """Color terminal lines by level; optionally emphasize or shorten logger names.""" + + def __init__( + self, + *args, + handler: logging.StreamHandler, + use_short_name: bool = False, + **kwargs, + ) -> None: super().__init__(*args, **kwargs) # Capture scopes can replace the handler stream after construction. self._handler = handler + self._use_short_name = use_short_name def _is_terminal(self) -> bool: stream = getattr(self._handler, "stream", None) @@ -87,18 +118,18 @@ def _is_terminal(self) -> bool: return False def format(self, record: logging.LogRecord) -> str: - if not self._is_terminal(): - return super().format(record) - - level = _level_color(record.levelno) - emphasis = _logger_colors.get(record.name) - if level is None and emphasis is None: + terminal = self._is_terminal() + level = _level_color(record.levelno) if terminal else None + emphasis = _logger_color(record.name) if terminal else None + if level is None and emphasis is None and not self._use_short_name: return super().format(record) # Restore the shared record before the file handler formats it. original = record.name + name = original.rpartition(".")[2] if self._use_short_name else original if emphasis is not None: - record.name = f"{emphasis}{original}{level or _ANSI_RESET}" + name = f"{emphasis}{name}{level or _ANSI_RESET}" + record.name = name try: line = super().format(record) finally: @@ -120,9 +151,7 @@ def ensure_handler() -> logging.StreamHandler: if _handler is not None: return _handler handler = logging.StreamHandler() - handler.setFormatter( - _LoggerNameColorFormatter(LINE_FORMAT, datefmt=DATE_FORMAT, handler=handler) - ) + handler.setFormatter(_console_formatter(handler)) handler.setLevel(env_console_level()) if not logging_enabled(): _handler = handler @@ -172,11 +201,81 @@ def set_console_filter(pattern: str | None, target: str = "both") -> None: handler.addFilter(replacement) +class _ConsoleFormat(TypedDict, total=False): + show_time: bool + show_level: bool + show_logger_name: bool + show_pid: bool + + use_short_name: bool # True: only the last dotted segment + + +# Console only: log files keep DATE_FORMAT's date, which sessions crossing midnight, +# rotated logs and cross-process correlation need. +_CONSOLE_DATE_FORMAT = "%H:%M:%S" + +# The console's current columns, starting from the defaults the handler is built with. +_console_format: dict[str, bool] = { + "show_time": True, + "show_level": True, + "show_logger_name": True, + "show_pid": False, + "use_short_name": True, +} + + +def _console_formatter(handler: logging.StreamHandler) -> _LoggerNameColorFormatter: + """Build the console formatter from the current ``_console_format`` columns.""" + columns = [ + "[%(asctime)s.%(msecs)03d]" if _console_format["show_time"] else "", + "[%(levelname)-5s]" if _console_format["show_level"] else "", + "[%(name)s]" if _console_format["show_logger_name"] else "", + "[pid:%(process)d]" if _console_format["show_pid"] else "", + "%(message)s", + ] + return _LoggerNameColorFormatter( + " ".join(column for column in columns if column), + datefmt=_CONSOLE_DATE_FORMAT, + handler=handler, + use_short_name=_console_format["use_short_name"], + ) + + +def set_console_format(changes: _ConsoleFormat) -> None: + """Update the console columns, changing only the given keys. + + Keys left out keep their current setting, which starts as time, level and the + last logger-name segment, without the pid; an unknown key or a non-bool value + is logged as an error and skipped. Columns keep the ``LINE_FORMAT`` order with + the time as ``HH:MM:SS.mmm``; log files from both halves keep the full + ``LINE_FORMAT``, date included, and logger colours still match the full name. + """ + for key, value in changes.items(): + if key not in _console_format: + root_logger.error( + "Unknown console format key %r, expected one of %s; ignoring it.", + key, + sorted(_console_format), + ) + continue + if not isinstance(value, bool): + root_logger.error( + "Console format %r must be a bool, got %r; ignoring it.", key, value + ) + continue + _console_format[key] = value + + handler = ensure_handler() + handler.setFormatter(_console_formatter(handler)) + + def set_logger_colors(colors: dict[str, str | None]) -> None: - """Set terminal-only SGR emphasis by exact logger name; ``None`` removes it. + """Set terminal-only SGR emphasis by logger name; ``None`` removes it. + A colour also covers the name's dotted descendants; the most specific name wins. A value that is not purely SGR escapes is logged as an error and skipped. """ + global _logger_color ensure_handler() for name, color in colors.items(): if color is None: @@ -191,3 +290,4 @@ def set_logger_colors(colors: dict[str, str | None]) -> None: ) continue _logger_colors[name] = color + _logger_color = _cached_prefix_lookup(_logger_colors) diff --git a/tests/python/core/logging_config/conftest.py b/tests/python/core/logging_config/conftest.py index 0f0462dbc8..1c5988f42a 100644 --- a/tests/python/core/logging_config/conftest.py +++ b/tests/python/core/logging_config/conftest.py @@ -47,6 +47,12 @@ r"\[(?P[A-Z]+ *)\] \[(?P[^]]+)\] \[pid:(?P\d+)\] (?P.*)$" ) +#: A C++ console line: ``LINE_FORMAT`` without the date, which only files keep. +CPP_CONSOLE_LINE_RE = re.compile( + r"^\[(?P