diff --git a/.gitea/workflows/deploy.yml b/.gitea/workflows/deploy.yml index 15aff59..0a445db 100644 --- a/.gitea/workflows/deploy.yml +++ b/.gitea/workflows/deploy.yml @@ -125,5 +125,6 @@ jobs: -u ${{ secrets.REGISTRY_USER }} \ -p ${{ secrets.REGISTRY_TOKEN }} && docker compose -p $COMPOSE_PROJECT pull && + docker compose -p $COMPOSE_PROJECT up -d --force-recreate otel-collector && docker compose -p $COMPOSE_PROJECT up -d " diff --git a/app/runtime/logging.py b/app/runtime/logging.py index 2825e79..9a040ef 100644 --- a/app/runtime/logging.py +++ b/app/runtime/logging.py @@ -7,6 +7,7 @@ from collections.abc import Iterable from typing import Any, TextIO import structlog +from opentelemetry import trace _UVICORN_LOGGER_NAMES = ("uvicorn", "uvicorn.error", "uvicorn.access") @@ -19,7 +20,11 @@ def configure_logging( ) -> None: resolved_stream = sys.stdout if stream is None else stream formatter = structlog.stdlib.ProcessorFormatter( - foreign_pre_chain=list(_shared_processors()), + foreign_pre_chain=[ + _add_trace_context, + _render_context_in_event, + *_shared_processors(), + ], processors=[ structlog.stdlib.ProcessorFormatter.remove_processors_meta, structlog.processors.JSONRenderer(sort_keys=True, ensure_ascii=False), @@ -33,6 +38,7 @@ def configure_logging( structlog.configure( processors=[ structlog.stdlib.PositionalArgumentsFormatter(), + _add_trace_context, _render_context_in_event, *_shared_processors(), structlog.processors.StackInfoRenderer(), @@ -62,6 +68,20 @@ def _shared_processors() -> tuple[structlog.types.Processor, ...]: ) +def _add_trace_context( + _logger: Any, + _method_name: str, + event_dict: structlog.types.EventDict, +) -> structlog.types.EventDict: + span_context = trace.get_current_span().get_span_context() + if not span_context.is_valid: + return event_dict + + event_dict["trace_id"] = format(span_context.trace_id, "032x") + event_dict["span_id"] = format(span_context.span_id, "016x") + return event_dict + + def _render_context_in_event( _logger: Any, _method_name: str, @@ -71,7 +91,14 @@ def _render_context_in_event( context = " ".join( f"{key}={_serialize_log_value(value)}" for key, value in sorted(event_dict.items()) - if key not in {"event", "exc_info", "stack_info"} + if key + not in { + "event", + "exc_info", + "stack_info", + "_record", + "_from_structlog", + } ) event_dict["event"] = f"{event} {context}" if context else event return event_dict diff --git a/tests/logging/test_json_logging.py b/tests/logging/test_json_logging.py index f788c9a..c48e16e 100644 --- a/tests/logging/test_json_logging.py +++ b/tests/logging/test_json_logging.py @@ -3,6 +3,8 @@ import logging from io import StringIO import structlog +from opentelemetry import trace +from opentelemetry.trace import NonRecordingSpan, SpanContext, TraceFlags from app.runtime.logging import configure_logging @@ -20,6 +22,8 @@ def test_application_log_is_serialized_as_json() -> None: assert payload["level"] == "info" assert payload["logger"] == "app.test" assert isinstance(payload["timestamp"], str) + assert "trace_id" not in payload + assert "span_id" not in payload _reset_logging() @@ -75,6 +79,49 @@ def test_uvicorn_loggers_use_shared_json_logging_setup() -> None: _reset_logging() +def test_active_trace_context_is_added_to_structlog_and_standard_logs() -> None: + stream = StringIO() + trace_id = 0x1234567890ABCDEF1234567890ABCDEF + span_id = 0x1234567890ABCDEF + span = NonRecordingSpan( + SpanContext( + trace_id=trace_id, + span_id=span_id, + is_remote=False, + trace_flags=TraceFlags.SAMPLED, + ) + ) + + configure_logging(stream=stream) + + with trace.use_span(span, end_on_exit=False): + structlog.get_logger("app.test").info("structured_event") + logging.getLogger("app.test").info("standard_event") + + records = [json.loads(line) for line in stream.getvalue().splitlines()] + expected_trace_id = "1234567890abcdef1234567890abcdef" + expected_span_id = "1234567890abcdef" + + assert [record["trace_id"] for record in records] == [ + expected_trace_id, + expected_trace_id, + ] + assert [record["span_id"] for record in records] == [ + expected_span_id, + expected_span_id, + ] + assert records[0]["event"] == ( + f'structured_event span_id="{expected_span_id}" ' + f'trace_id="{expected_trace_id}"' + ) + assert records[1]["event"] == ( + f'standard_event span_id="{expected_span_id}" ' + f'trace_id="{expected_trace_id}"' + ) + + _reset_logging() + + def _reset_logging() -> None: structlog.reset_defaults() root_logger = logging.getLogger() diff --git a/tests/smoke/test_local_infra_stack.py b/tests/smoke/test_local_infra_stack.py index 7108674..6c9857e 100644 --- a/tests/smoke/test_local_infra_stack.py +++ b/tests/smoke/test_local_infra_stack.py @@ -6,6 +6,7 @@ import yaml PROJECT_ROOT = Path(__file__).resolve().parents[2] COMPOSE_FILE = PROJECT_ROOT / "docker-compose.yml" INFRA_README = PROJECT_ROOT / "infra" / "README.md" +DEPLOY_WORKFLOW = PROJECT_ROOT / ".gitea" / "workflows" / "deploy.yml" def _load_compose() -> dict: @@ -28,3 +29,15 @@ def test_smoke_command_sequence_is_documented() -> None: assert "docker compose config" in readme assert "docker compose up -d redis" in readme assert "docker compose ps" in readme + + +def test_deploy_recreates_collector_after_config_update() -> None: + workflow = DEPLOY_WORKFLOW.read_text(encoding="utf-8") + + recreate_command = ( + "docker compose -p $COMPOSE_PROJECT up -d --force-recreate otel-collector" + ) + application_command = "docker compose -p $COMPOSE_PROJECT up -d" + + assert recreate_command in workflow + assert workflow.index(recreate_command) < workflow.rindex(application_command)