From 52896dbcbc2f4a24bacbfb5d4ea58d0ed60edf1a Mon Sep 17 00:00:00 2001 From: adrunkhuman <16039109+adrunkhuman@users.noreply.github.com> Date: Thu, 21 May 2026 21:58:24 +0200 Subject: [PATCH 1/4] chore: make deployed logs plain by default --- .env.example | 3 ++ README.md | 2 + tests/test_logger.py | 84 +++++++++++++++++++++++++++++++++++++++ typer_bot/utils/logger.py | 50 ++++++++++++++--------- 4 files changed, 121 insertions(+), 18 deletions(-) create mode 100644 tests/test_logger.py diff --git a/.env.example b/.env.example index 5f05c0e..6d30eb7 100644 --- a/.env.example +++ b/.env.example @@ -30,6 +30,9 @@ DISCORD_TOKEN=your_bot_token_here # Logging (optional) # Levels: DEBUG, INFO, WARNING, ERROR LOG_LEVEL=INFO +# Formats: json, plain, color. Default: json in production, color for interactive +# local terminals, plain for non-interactive non-production logs. +# LOG_FORMAT=plain # Channel ID for reminders (optional) # REMINDER_CHANNEL_ID=123456789012345678 diff --git a/README.md b/README.md index 3fa38a5..111bbe5 100644 --- a/README.md +++ b/README.md @@ -86,6 +86,8 @@ uv run ruff format --check . uv run ty check typer_bot ``` +Non-interactive preview/test deployments use plain single-line logs by default. Set `LOG_FORMAT=json`, `LOG_FORMAT=plain`, or `LOG_FORMAT=color` only when you need to override formatter selection. + ## License MIT. diff --git a/tests/test_logger.py b/tests/test_logger.py new file mode 100644 index 0000000..31a8cea --- /dev/null +++ b/tests/test_logger.py @@ -0,0 +1,84 @@ +"""Tests for runtime logging formatter selection.""" + +import io +import logging + +import pytest + +from typer_bot.utils import logger as logger_module + + +class TtyBuffer(io.StringIO): + def isatty(self) -> bool: + return True + + +class NonTtyBuffer(io.StringIO): + def isatty(self) -> bool: + return False + + +@pytest.fixture(autouse=True) +def restore_logging_state(): + root_logger = logging.getLogger() + root_handlers = list(root_logger.handlers) + root_level = root_logger.level + discord_level = logging.getLogger("discord").level + discord_http_level = logging.getLogger("discord.http").level + + yield + + root_logger.handlers.clear() + root_logger.handlers.extend(root_handlers) + root_logger.setLevel(root_level) + logging.getLogger("discord").setLevel(discord_level) + logging.getLogger("discord.http").setLevel(discord_http_level) + + +def test_production_environment_uses_json_formatter(monkeypatch): + monkeypatch.setenv("ENVIRONMENT", "production") + monkeypatch.delenv("LOG_FORMAT", raising=False) + + formatter = logger_module._select_formatter(NonTtyBuffer()) + + assert isinstance(formatter, logger_module.ProductionJSONFormatter) + + +def test_non_interactive_non_production_uses_plain_formatter(monkeypatch): + monkeypatch.setenv("ENVIRONMENT", "test") + monkeypatch.delenv("LOG_FORMAT", raising=False) + + formatter = logger_module._select_formatter(NonTtyBuffer()) + + assert isinstance(formatter, logger_module.PlainFormatter) + + +def test_interactive_non_production_uses_color_formatter(monkeypatch): + monkeypatch.setenv("ENVIRONMENT", "development") + monkeypatch.delenv("LOG_FORMAT", raising=False) + + formatter = logger_module._select_formatter(TtyBuffer()) + + assert isinstance(formatter, logger_module.LocalFormatter) + + +def test_plain_formatter_does_not_emit_ansi_sequences(monkeypatch): + monkeypatch.setenv("ENVIRONMENT", "test") + monkeypatch.delenv("LOG_FORMAT", raising=False) + output = NonTtyBuffer() + monkeypatch.setattr(logger_module.sys, "stdout", output) + + logger_module.setup_logging(logging.INFO) + logging.getLogger("test.plain").info("readable message") + + assert "\x1b[" not in output.getvalue() + assert "[INFO ] test.plain: readable message" in output.getvalue() + + +def test_log_format_override_can_force_json(monkeypatch): + monkeypatch.setenv("ENVIRONMENT", "test") + monkeypatch.setenv("LOG_FORMAT", "json") + + formatter = logger_module._select_formatter(TtyBuffer()) + + assert isinstance(formatter, logger_module.ProductionJSONFormatter) diff --git a/typer_bot/utils/logger.py b/typer_bot/utils/logger.py index 44ec984..3f4f14a 100644 --- a/typer_bot/utils/logger.py +++ b/typer_bot/utils/logger.py @@ -317,18 +317,37 @@ def format(self, record: logging.LogRecord) -> str: return formatter.format(record) +class PlainFormatter(logging.Formatter): + FMT = "[%(asctime)s] [%(levelname)-8s] %(name)s: %(message)s" + DATEFMT = "%H:%M:%S" + + def __init__(self) -> None: + super().__init__(self.FMT, datefmt=self.DATEFMT) + + def is_production_environment() -> bool: - """Detect if running in a deployed production environment.""" - return ( - os.getenv("ENVIRONMENT") == "production" - or os.getenv("COOLIFY_ENVIRONMENT_NAME") is not None - or os.getenv("RAILWAY_ENVIRONMENT") is not None - or os.getenv("RAILWAY_SERVICE_NAME") is not None - ) + """Return whether ENVIRONMENT explicitly selects production.""" + return os.getenv("ENVIRONMENT", "development").lower() in ("production", "prod") + + +def _select_formatter(stream: Any) -> logging.Formatter: + log_format = os.getenv("LOG_FORMAT", "").lower() + if log_format == "json": + return ProductionJSONFormatter() + if log_format == "plain": + return PlainFormatter() + if log_format == "color": + return LocalFormatter() + + if is_production_environment(): + return ProductionJSONFormatter() + if stream.isatty(): + return LocalFormatter() + return PlainFormatter() def setup_logging(level: int | None = None) -> None: - """Configure root logger for production or local environment. + """Configure root logger on stdout with the selected formatter. Forces ALL output to stdout. Some hosts treat stderr as error-level logs regardless of content, which breaks log level filtering. @@ -341,13 +360,10 @@ def setup_logging(level: int | None = None) -> None: root_logger.handlers.clear() root_logger.setLevel(level) - handler = logging.StreamHandler(sys.stdout) + stream = sys.stdout + handler = logging.StreamHandler(stream) handler.setLevel(level) - - if is_production_environment(): - handler.setFormatter(ProductionJSONFormatter()) - else: - handler.setFormatter(LocalFormatter()) + handler.setFormatter(_select_formatter(stream)) root_logger.addHandler(handler) @@ -355,10 +371,8 @@ def setup_logging(level: int | None = None) -> None: logging.getLogger("discord.http").setLevel(logging.WARNING) logger = logging.getLogger(__name__) - env_type = "production" if is_production_environment() else "local" - logger.info( - f"Logging configured for {env_type} environment at level {logging.getLevelName(level)}" - ) + formatter_name = handler.formatter.__class__.__name__ if handler.formatter else "unknown" + logger.info(f"Logging configured with {formatter_name} at level {logging.getLevelName(level)}") def log_event( From 7aa658a7f219fc6e7f1135980a7b96fe1223abda Mon Sep 17 00:00:00 2001 From: adrunkhuman <16039109+adrunkhuman@users.noreply.github.com> Date: Thu, 21 May 2026 22:04:44 +0200 Subject: [PATCH 2/4] test: assert logger output contracts --- tests/test_logger.py | 59 ++++++++++++++++++++++++++++++-------------- 1 file changed, 40 insertions(+), 19 deletions(-) diff --git a/tests/test_logger.py b/tests/test_logger.py index 31a8cea..a5680dd 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -1,6 +1,7 @@ """Tests for runtime logging formatter selection.""" import io +import json import logging import pytest @@ -35,50 +36,70 @@ def restore_logging_state(): logging.getLogger("discord.http").setLevel(discord_http_level) -def test_production_environment_uses_json_formatter(monkeypatch): +def _configure_and_emit(monkeypatch, output: io.StringIO, logger_name: str = "test.logger") -> str: + monkeypatch.setattr(logger_module.sys, "stdout", output) + + logger_module.setup_logging(logging.INFO) + logging.getLogger(logger_name).info("readable message") + + return output.getvalue().splitlines()[-1] + + +def test_production_environment_emits_json_logs(monkeypatch): monkeypatch.setenv("ENVIRONMENT", "production") monkeypatch.delenv("LOG_FORMAT", raising=False) + output = NonTtyBuffer() - formatter = logger_module._select_formatter(NonTtyBuffer()) + log_entry = json.loads(_configure_and_emit(monkeypatch, output, "test.production")) - assert isinstance(formatter, logger_module.ProductionJSONFormatter) + assert log_entry["level"] == "info" + assert log_entry["logger"] == "test.production" + assert log_entry["message"] == "readable message" -def test_non_interactive_non_production_uses_plain_formatter(monkeypatch): +def test_non_interactive_non_production_emits_plain_logs(monkeypatch): monkeypatch.setenv("ENVIRONMENT", "test") monkeypatch.delenv("LOG_FORMAT", raising=False) + output = NonTtyBuffer() - formatter = logger_module._select_formatter(NonTtyBuffer()) + log_line = _configure_and_emit(monkeypatch, output, "test.plain") - assert isinstance(formatter, logger_module.PlainFormatter) + assert "\x1b[" not in log_line + assert not log_line.startswith("{") + assert "INFO" in log_line + assert "test.plain" in log_line + assert "readable message" in log_line -def test_interactive_non_production_uses_color_formatter(monkeypatch): +def test_interactive_non_production_emits_color_logs(monkeypatch): monkeypatch.setenv("ENVIRONMENT", "development") monkeypatch.delenv("LOG_FORMAT", raising=False) + output = TtyBuffer() - formatter = logger_module._select_formatter(TtyBuffer()) + log_line = _configure_and_emit(monkeypatch, output) - assert isinstance(formatter, logger_module.LocalFormatter) + assert "\x1b[" in log_line + assert "readable message" in log_line -def test_plain_formatter_does_not_emit_ansi_sequences(monkeypatch): +def test_log_format_override_can_force_plain(monkeypatch): monkeypatch.setenv("ENVIRONMENT", "test") - monkeypatch.delenv("LOG_FORMAT", raising=False) - output = NonTtyBuffer() - monkeypatch.setattr(logger_module.sys, "stdout", output) + monkeypatch.setenv("LOG_FORMAT", "plain") + output = TtyBuffer() - logger_module.setup_logging(logging.INFO) - logging.getLogger("test.plain").info("readable message") + log_line = _configure_and_emit(monkeypatch, output) - assert "\x1b[" not in output.getvalue() - assert "[INFO ] test.plain: readable message" in output.getvalue() + assert "\x1b[" not in log_line + assert not log_line.startswith("{") + assert "readable message" in log_line def test_log_format_override_can_force_json(monkeypatch): monkeypatch.setenv("ENVIRONMENT", "test") monkeypatch.setenv("LOG_FORMAT", "json") + output = TtyBuffer() - formatter = logger_module._select_formatter(TtyBuffer()) + log_entry = json.loads(_configure_and_emit(monkeypatch, output)) - assert isinstance(formatter, logger_module.ProductionJSONFormatter) + assert log_entry["level"] == "info" + assert log_entry["message"] == "readable message" From 0bd01fd572c060d6b346bd57c5395758da4a8db6 Mon Sep 17 00:00:00 2001 From: adrunkhuman <16039109+adrunkhuman@users.noreply.github.com> Date: Thu, 21 May 2026 22:23:10 +0200 Subject: [PATCH 3/4] chore: simplify logging output --- .env.example | 4 +- AGENTS.md | 2 +- README.md | 4 +- tests/test_logger.py | 112 ++++++++------- typer_bot/utils/logger.py | 283 ++++++++++---------------------------- 5 files changed, 142 insertions(+), 263 deletions(-) diff --git a/.env.example b/.env.example index 6d30eb7..e02ec44 100644 --- a/.env.example +++ b/.env.example @@ -29,10 +29,8 @@ DISCORD_TOKEN=your_bot_token_here # Logging (optional) # Levels: DEBUG, INFO, WARNING, ERROR +# Logs are plain single-line stdout. LOG_LEVEL=INFO -# Formats: json, plain, color. Default: json in production, color for interactive -# local terminals, plain for non-interactive non-production logs. -# LOG_FORMAT=plain # Channel ID for reminders (optional) # REMINDER_CHANNEL_ID=123456789012345678 diff --git a/AGENTS.md b/AGENTS.md index b8ebec0..7a39f80 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -116,7 +116,7 @@ guild_config ( - `typer_bot/utils/config.py`: Centralized configuration (data paths via env vars). - `typer_bot/utils/prediction_parser.py`: Central logic for parsing "2-1" or "2:1" strings. - `typer_bot/utils/scoring.py`: Point calculation using season scoring rules. -- `typer_bot/utils/logger.py`: structured logging configuration for local and deployed environments. +- `typer_bot/utils/logger.py`: plain stdout logging setup with contextual fields. - `typer_bot/utils/db_backup.py`: Automatic database backup after successful score calculation. - `scripts/restore_db.py`: Manual database restore from a host or container shell. diff --git a/README.md b/README.md index 111bbe5..1224c0b 100644 --- a/README.md +++ b/README.md @@ -77,6 +77,8 @@ uv run python -m typer_bot Disposable non-production deployments can auto-seed an empty database by setting `SEED_TEST_DATA=true` and `TEST_GUILD_ID`. +Logs are plain single-line stdout; set `LOG_LEVEL=DEBUG` when troubleshooting. + Run checks: ```bash @@ -86,8 +88,6 @@ uv run ruff format --check . uv run ty check typer_bot ``` -Non-interactive preview/test deployments use plain single-line logs by default. Set `LOG_FORMAT=json`, `LOG_FORMAT=plain`, or `LOG_FORMAT=color` only when you need to override formatter selection. - ## License MIT. diff --git a/tests/test_logger.py b/tests/test_logger.py index a5680dd..9689ed3 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -1,7 +1,6 @@ -"""Tests for runtime logging formatter selection.""" +"""Tests for runtime logging setup.""" import io -import json import logging import pytest @@ -9,16 +8,6 @@ from typer_bot.utils import logger as logger_module -class TtyBuffer(io.StringIO): - def isatty(self) -> bool: - return True - - -class NonTtyBuffer(io.StringIO): - def isatty(self) -> bool: - return False - - @pytest.fixture(autouse=True) def restore_logging_state(): root_logger = logging.getLogger() @@ -26,6 +15,8 @@ def restore_logging_state(): root_level = root_logger.level discord_level = logging.getLogger("discord").level discord_http_level = logging.getLogger("discord.http").level + trace_id = logger_module.get_trace_id() + log_context = logger_module.get_log_context() yield @@ -34,6 +25,9 @@ def restore_logging_state(): root_logger.setLevel(root_level) logging.getLogger("discord").setLevel(discord_level) logging.getLogger("discord.http").setLevel(discord_http_level) + logger_module.set_trace_id(trace_id) + logger_module.clear_log_context() + logger_module.set_log_context(**log_context) def _configure_and_emit(monkeypatch, output: io.StringIO, logger_name: str = "test.logger") -> str: @@ -45,61 +39,79 @@ def _configure_and_emit(monkeypatch, output: io.StringIO, logger_name: str = "te return output.getvalue().splitlines()[-1] -def test_production_environment_emits_json_logs(monkeypatch): - monkeypatch.setenv("ENVIRONMENT", "production") - monkeypatch.delenv("LOG_FORMAT", raising=False) - output = NonTtyBuffer() - - log_entry = json.loads(_configure_and_emit(monkeypatch, output, "test.production")) - - assert log_entry["level"] == "info" - assert log_entry["logger"] == "test.production" - assert log_entry["message"] == "readable message" - - -def test_non_interactive_non_production_emits_plain_logs(monkeypatch): - monkeypatch.setenv("ENVIRONMENT", "test") - monkeypatch.delenv("LOG_FORMAT", raising=False) - output = NonTtyBuffer() +def test_setup_logging_emits_plain_logs(monkeypatch): + output = io.StringIO() log_line = _configure_and_emit(monkeypatch, output, "test.plain") assert "\x1b[" not in log_line assert not log_line.startswith("{") + assert log_line.startswith("20") assert "INFO" in log_line assert "test.plain" in log_line assert "readable message" in log_line -def test_interactive_non_production_emits_color_logs(monkeypatch): - monkeypatch.setenv("ENVIRONMENT", "development") - monkeypatch.delenv("LOG_FORMAT", raising=False) - output = TtyBuffer() +def test_setup_logging_includes_context_and_extra_fields(monkeypatch): + output = io.StringIO() + monkeypatch.setattr(logger_module.sys, "stdout", output) + + logger_module.set_trace_id("req-1") + logger_module.set_log_context(guild_id="guild-1") + logger_module.setup_logging(logging.INFO) + logging.getLogger("test.context").info( + "context message", + extra={ + "event_type": "prediction.saved", + "error_detail": "Fixture not found", + "payload": {2: "second", "token": "secret-value", "safe": "visible"}, + "token": "secret-value", + }, + ) + + log_line = output.getvalue().splitlines()[-1] + assert "context message" in log_line + assert "secret-value" not in log_line + assert 'error_detail="Fixture not found"' in log_line + assert "event_type=prediction.saved" in log_line + assert "guild_id=guild-1" in log_line + assert "payload={2:second,safe:visible,token:[REDACTED]}" in log_line + assert "token=[REDACTED]" in log_line + assert "trace_id=req-1" in log_line - log_line = _configure_and_emit(monkeypatch, output) - assert "\x1b[" in log_line - assert "readable message" in log_line +def test_setup_logging_uses_stdout(monkeypatch): + output = io.StringIO() + _configure_and_emit(monkeypatch, output) -def test_log_format_override_can_force_plain(monkeypatch): - monkeypatch.setenv("ENVIRONMENT", "test") - monkeypatch.setenv("LOG_FORMAT", "plain") - output = TtyBuffer() + assert "readable message" in output.getvalue() - log_line = _configure_and_emit(monkeypatch, output) - assert "\x1b[" not in log_line - assert not log_line.startswith("{") - assert "readable message" in log_line +def test_setup_logging_respects_level(monkeypatch): + output = io.StringIO() + monkeypatch.setattr(logger_module.sys, "stdout", output) + + logger_module.setup_logging(logging.WARNING) + logging.getLogger("test.level").info("hidden message") + logging.getLogger("test.level").warning("visible message") + logged = output.getvalue() + assert "hidden message" not in logged + assert "WARNING" in logged + assert "visible message" in logged -def test_log_format_override_can_force_json(monkeypatch): - monkeypatch.setenv("ENVIRONMENT", "test") - monkeypatch.setenv("LOG_FORMAT", "json") - output = TtyBuffer() - log_entry = json.loads(_configure_and_emit(monkeypatch, output)) +def test_setup_logging_uses_log_level_env(monkeypatch): + output = io.StringIO() + monkeypatch.setattr(logger_module.sys, "stdout", output) + monkeypatch.setenv("LOG_LEVEL", "WARNING") + + logger_module.setup_logging() + logging.getLogger("test.env_level").info("hidden message") + logging.getLogger("test.env_level").warning("visible message") - assert log_entry["level"] == "info" - assert log_entry["message"] == "readable message" + logged = output.getvalue() + assert "hidden message" not in logged + assert "WARNING" in logged + assert "visible message" in logged diff --git a/typer_bot/utils/logger.py b/typer_bot/utils/logger.py index 3f4f14a..fa0ca4d 100644 --- a/typer_bot/utils/logger.py +++ b/typer_bot/utils/logger.py @@ -1,44 +1,16 @@ -"""Logging utilities for production-compatible structured logging. - -This module provides structured logging capabilities for tracing user journeys, -timing operations, and debugging production issues. - -Event Type Naming Convention: - Event types use dot notation with the format: . or .. - - Examples: - - prediction.saved: User prediction was saved successfully - - prediction.save_failed: Error saving prediction - - prediction.parse_failed: User input couldn't be parsed - - prediction.duplicate_blocked: Race condition prevented duplicate - - fixture.created: New fixture created by admin - - results.entered: Admin entered actual scores - - fixture.created: Admin created a new fixture - - prediction.fixture_closed: Prediction rejected after a fixture closed - - transaction.begin/commit/rollback: Database transaction boundaries - - Severity Guidelines: - - DEBUG: Session lifecycle, DB timing metrics, transaction boundaries - - INFO: Business events (saved, created, entered) - - WARNING: Validation failures, parsing errors, duplicate blocks - - ERROR: Unhandled exceptions, system errors -""" +"""Logging utilities.""" import contextvars import functools -import json import logging import os import sys import time from collections.abc import Awaitable, Callable -from datetime import UTC, datetime from typing import Any, ParamSpec, TypeVar -# Global context for request trace IDs _trace_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar("trace_id", default=None) -# Global context for log context fields (user_id, fixture_id, etc.) _log_context: contextvars.ContextVar[dict[str, Any] | None] = contextvars.ContextVar( "log_context", default=None ) @@ -46,6 +18,34 @@ P = ParamSpec("P") T = TypeVar("T") +LOG_FORMAT = "%(asctime)s %(levelname)s %(name)s: %(message)s" +LOG_DATE_FORMAT = "%Y-%m-%dT%H:%M:%S" +SENSITIVE_LOG_KEYS = {"token", "password", "secret", "key", "api_key", "access_token"} +LOG_RECORD_ATTRS = { + "args", + "asctime", + "created", + "exc_info", + "exc_text", + "filename", + "funcName", + "levelname", + "levelno", + "lineno", + "message", + "module", + "msecs", + "msg", + "name", + "pathname", + "process", + "processName", + "relativeCreated", + "stack_info", + "taskName", + "thread", + "threadName", +} def set_trace_id(trace_id: str | None) -> None: @@ -91,7 +91,7 @@ def set_log_context(**kwargs: Any) -> None: fixture_id: Database fixture ID (int) guild_id: Discord guild/server ID (string) source: Where prediction came from ('dm', 'thread', 'command') - event_type: Semantic event classification (see module docstring) + event_type: Semantic event classification, e.g. "prediction.saved" operation: Function/method name being executed """ current = _log_context.get() @@ -165,189 +165,59 @@ async def async_wrapper(*args: P.args, **kwargs: P.kwargs) -> T: return decorator -class ProductionJSONFormatter(logging.Formatter): - """JSON formatter for deployed structured logging. +def _format_scalar_log_value(value: Any) -> str: + text = str(value).replace("\\", "\\\\").replace("\n", "\\n").replace('"', '\\"') + if any(char.isspace() for char in text) or "=" in text: + return f'"{text}"' + return text - Outputs single-line JSON that hosted log collectors can parse and filter. - Example: {"level": "info", "message": "...", "timestamp": "...", "logger": "...", "event_type": "..."} - """ - STANDARD_RECORD_ATTRS = { - "name", - "msg", - "args", - "levelname", - "levelno", - "pathname", - "filename", - "module", - "exc_info", - "exc_text", - "stack_info", - "lineno", - "funcName", - "created", - "msecs", - "relativeCreated", - "thread", - "threadName", - "processName", - "process", - "message", - "asctime", - "timestamp", - "logger", - "level", - "error", - "trace_id", - "event_type", - "user_id", - "fixture_id", - "source", - "operation", - "duration_ms", - "rows_affected", - "session_id", - "step", - } - - SENSITIVE_KEYS = {"token", "password", "secret", "key", "api_key", "access_token"} - - def _sanitize(self, obj: Any) -> Any: - """Recursively sanitize sensitive data from log entries. - - Scans dict keys for sensitive patterns (tokens, passwords, secrets) - and replaces their values with "[REDACTED]". Recursively processes - nested dicts and lists. - - Args: - obj: Object to sanitize (dict, list, or primitive) - - Returns: - Sanitized object with sensitive values redacted - """ - if isinstance(obj, dict): - return { - k: "[REDACTED]" if str(k).lower() in self.SENSITIVE_KEYS else self._sanitize(v) - for k, v in obj.items() - } - if isinstance(obj, list | tuple): - return type(obj)(self._sanitize(item) for item in obj) - return obj +def _format_log_value(key: str, value: Any) -> str: + if key.lower() in SENSITIVE_LOG_KEYS: + return "[REDACTED]" + if isinstance(value, dict): + return ( + "{" + + ",".join( + f"{item_key}:{_format_log_value(str(item_key), item_value)}" + for item_key, item_value in sorted(value.items(), key=lambda item: str(item[0])) + ) + + "}" + ) + if isinstance(value, list | tuple | set): + return "[" + ",".join(_format_log_value(key, item) for item in value) + "]" + return _format_scalar_log_value(value) + +class PlainFormatter(logging.Formatter): def format(self, record: logging.LogRecord) -> str: - """Format log record as production JSON. - - Use ISO8601 timestamps with timezone for stable log ordering. All - output goes to stdout so hosted runtimes do not misclassify stderr as - error-level logs regardless of content. - - Args: - record: Standard library LogRecord to format - - Returns: - Single-line JSON string for log ingestion - """ - # ISO8601 with timezone keeps ordering stable across hosts. - timestamp = datetime.fromtimestamp(record.created, tz=UTC).isoformat() - - log_entry = { - "level": record.levelname.lower(), - "message": record.getMessage(), - "timestamp": timestamp, - "logger": record.name, - } + line = super().format(record) + fields: dict[str, Any] = {} - # Add trace ID if available trace_id = get_trace_id() if trace_id: - log_entry["trace_id"] = trace_id - - # Add event_type from record if set - event_type = getattr(record, "event_type", None) - if isinstance(event_type, str) and event_type: - log_entry["event_type"] = event_type - - # Add exception info if available - if record.exc_info: - log_entry["error"] = self.formatException(record.exc_info) - - # Add context from contextvars (user_id, fixture_id, source, etc.) - context = get_log_context() - for key, value in context.items(): - if value is not None and key not in log_entry: - log_entry[key] = value - - # Add any extra fields from the record - for key, value in record.__dict__.items(): - if key not in self.STANDARD_RECORD_ATTRS and key not in log_entry: - log_entry[key] = value - - log_entry = self._sanitize(log_entry) - - return json.dumps(log_entry, ensure_ascii=False, separators=(",", ":")) - - -class LocalFormatter(logging.Formatter): - """Colorful formatter for local development.""" - - GREY = "\x1b[38;20m" - BLUE = "\x1b[34;20m" - CYAN = "\x1b[36;20m" - YELLOW = "\x1b[33;20m" - RED = "\x1b[31;20m" - BOLD_RED = "\x1b[31;1m" - RESET = "\x1b[0m" - - # [TIME] [LEVEL ] logger.name: Message - FMT = "[%(asctime)s] [%(levelname)-8s] %(name)s: %(message)s" - DATEFMT = "%H:%M:%S" - - FORMATS = { - logging.DEBUG: GREY + FMT + RESET, - logging.INFO: BLUE + FMT + RESET, - logging.WARNING: YELLOW + FMT + RESET, - logging.ERROR: RED + FMT + RESET, - logging.CRITICAL: BOLD_RED + FMT + RESET, - } - - def format(self, record: logging.LogRecord) -> str: - log_fmt = self.FORMATS.get(record.levelno, self.FMT) - formatter = logging.Formatter(log_fmt, datefmt=self.DATEFMT) - return formatter.format(record) - - -class PlainFormatter(logging.Formatter): - FMT = "[%(asctime)s] [%(levelname)-8s] %(name)s: %(message)s" - DATEFMT = "%H:%M:%S" - - def __init__(self) -> None: - super().__init__(self.FMT, datefmt=self.DATEFMT) - - -def is_production_environment() -> bool: - """Return whether ENVIRONMENT explicitly selects production.""" - return os.getenv("ENVIRONMENT", "development").lower() in ("production", "prod") - + fields["trace_id"] = trace_id + + fields.update({key: value for key, value in get_log_context().items() if value is not None}) + fields.update( + { + key: value + for key, value in record.__dict__.items() + if key not in LOG_RECORD_ATTRS and value is not None + } + ) -def _select_formatter(stream: Any) -> logging.Formatter: - log_format = os.getenv("LOG_FORMAT", "").lower() - if log_format == "json": - return ProductionJSONFormatter() - if log_format == "plain": - return PlainFormatter() - if log_format == "color": - return LocalFormatter() + if not fields: + return line - if is_production_environment(): - return ProductionJSONFormatter() - if stream.isatty(): - return LocalFormatter() - return PlainFormatter() + details = " ".join( + f"{key}={_format_log_value(key, value)}" for key, value in sorted(fields.items()) + ) + return f"{line} {details}" def setup_logging(level: int | None = None) -> None: - """Configure root logger on stdout with the selected formatter. + """Configure root logger on stdout. Forces ALL output to stdout. Some hosts treat stderr as error-level logs regardless of content, which breaks log level filtering. @@ -363,7 +233,7 @@ def setup_logging(level: int | None = None) -> None: stream = sys.stdout handler = logging.StreamHandler(stream) handler.setLevel(level) - handler.setFormatter(_select_formatter(stream)) + handler.setFormatter(PlainFormatter(LOG_FORMAT, datefmt=LOG_DATE_FORMAT)) root_logger.addHandler(handler) @@ -371,8 +241,7 @@ def setup_logging(level: int | None = None) -> None: logging.getLogger("discord.http").setLevel(logging.WARNING) logger = logging.getLogger(__name__) - formatter_name = handler.formatter.__class__.__name__ if handler.formatter else "unknown" - logger.info(f"Logging configured with {formatter_name} at level {logging.getLevelName(level)}") + logger.info("Logging configured at level %s", logging.getLevelName(level)) def log_event( @@ -398,9 +267,9 @@ def log_event( class LogTimer: """Context manager for timing operations and logging with duration. - Automatically logs operation start (DEBUG), completion (specified level), - or failure (WARNING). Duration is always recorded in milliseconds using - high-resolution monotonic clock (time.perf_counter). + Logs completion at the specified level or failure as a warning. Duration is + always recorded in milliseconds using high-resolution monotonic clock + (time.perf_counter). Args: logger: Logger instance to use for output From 9ec52714a8e636b220462300f931d5eb4ad0253a Mon Sep 17 00:00:00 2001 From: adrunkhuman <16039109+adrunkhuman@users.noreply.github.com> Date: Thu, 21 May 2026 22:29:59 +0200 Subject: [PATCH 4/4] fix: include timezone in log timestamps --- tests/test_logger.py | 3 ++- typer_bot/utils/logger.py | 8 +++++++- 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/tests/test_logger.py b/tests/test_logger.py index 9689ed3..c261c00 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -2,6 +2,7 @@ import io import logging +import re import pytest @@ -46,7 +47,7 @@ def test_setup_logging_emits_plain_logs(monkeypatch): assert "\x1b[" not in log_line assert not log_line.startswith("{") - assert log_line.startswith("20") + assert re.match(r"^20\d{2}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\+00:00\s", log_line) assert "INFO" in log_line assert "test.plain" in log_line assert "readable message" in log_line diff --git a/typer_bot/utils/logger.py b/typer_bot/utils/logger.py index fa0ca4d..0abf624 100644 --- a/typer_bot/utils/logger.py +++ b/typer_bot/utils/logger.py @@ -7,7 +7,8 @@ import sys import time from collections.abc import Awaitable, Callable -from typing import Any, ParamSpec, TypeVar +from datetime import UTC, datetime +from typing import Any, ParamSpec, TypeVar, override _trace_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar("trace_id", default=None) @@ -190,6 +191,11 @@ def _format_log_value(key: str, value: Any) -> str: class PlainFormatter(logging.Formatter): + @override + def formatTime(self, record: logging.LogRecord, datefmt: str | None = None) -> str: + _ = datefmt + return datetime.fromtimestamp(record.created, tz=UTC).isoformat(timespec="seconds") + def format(self, record: logging.LogRecord) -> str: line = super().format(record) fields: dict[str, Any] = {}