diff --git a/docs/api-reference/observability.md b/docs/api-reference/observability.md index 6d21b8c60cb..458c52e3525 100644 --- a/docs/api-reference/observability.md +++ b/docs/api-reference/observability.md @@ -86,6 +86,21 @@ attributes. Event payloads and state are never recorded. Pass `meter_provider=` to `instrument()` to export them (defaults to the global meter provider). +### Logs + +With JSON logging on (`REFLEX_LOG_JSON=true` or `--json`), every JSON record +Reflex writes inside a span (log records and plain console output alike) +carries that span's W3C ids, so a log line can be looked up in your tracing +backend and vice versa: + +```json +{"level": "error", "message": "...", "trace_id": "4bf92f3577b34da6a3ce929d0e0e4736", "span_id": "00f067aa0ba902b7"} +``` + +Records emitted outside a span, or while the instrumentation is off, have no +`trace_id`/`span_id` fields. For your own application loggers, use +[`opentelemetry-instrumentation-logging`](https://opentelemetry-python-contrib.readthedocs.io/en/latest/instrumentation/logging/logging.html). + ## Frontend: browser traces Add the plugin to your config to trace the browser as well: diff --git a/packages/reflex-base/news/+json-log-trace-ids.feature.md b/packages/reflex-base/news/+json-log-trace-ids.feature.md new file mode 100644 index 00000000000..9eb6b66da41 --- /dev/null +++ b/packages/reflex-base/news/+json-log-trace-ids.feature.md @@ -0,0 +1 @@ +With OpenTelemetry tracing enabled, JSON log records (`REFLEX_LOG_JSON=true`) emitted inside a span now include its `trace_id` and `span_id`, so logs can be correlated with traces. diff --git a/packages/reflex-base/src/reflex_base/otel.py b/packages/reflex-base/src/reflex_base/otel.py index 6acd96fb50f..be5728eb24d 100644 --- a/packages/reflex-base/src/reflex_base/otel.py +++ b/packages/reflex-base/src/reflex_base/otel.py @@ -269,6 +269,24 @@ def capture_context() -> Context | None: return context_api.get_current() +def trace_fields() -> dict[str, str] | None: + """W3C ids of the current span, for correlating a log record with its trace. + + Returns: + ``trace_id`` (32 hex digits) and ``span_id`` (16 hex digits) of the + current span, or None when tracing is off or no valid span is current. + """ + if not enabled: + return None + span_context = trace.get_current_span().get_span_context() + if not span_context.is_valid: + return None + return { + "trace_id": trace.format_trace_id(span_context.trace_id), + "span_id": trace.format_span_id(span_context.span_id), + } + + def attach_context(context: Context | None) -> None: """Make a captured context current for the rest of the running task. @@ -524,4 +542,5 @@ def record_connection(delta: int) -> None: "record_message_size", "record_state_acquired", "remote_context", + "trace_fields", ] diff --git a/packages/reflex-base/src/reflex_base/utils/log.py b/packages/reflex-base/src/reflex_base/utils/log.py index 725313fe889..80f8e531b63 100644 --- a/packages/reflex-base/src/reflex_base/utils/log.py +++ b/packages/reflex-base/src/reflex_base/utils/log.py @@ -42,6 +42,7 @@ from rich.errors import MarkupError from rich.text import Text +from reflex_base import otel from reflex_base.constants import LogLevel from reflex_base.constants.base import Reflex from reflex_base.utils.decorator import once @@ -255,10 +256,15 @@ def format_exception(self, record: logging.LogRecord) -> str: def _write_json(payload: dict, *, stderr: bool): """Write one JSON record to the output stream. + A record written inside an OpenTelemetry span also carries the span's + ``trace_id`` and ``span_id``. + Args: payload: The record fields. stderr: Whether the record targets stderr. """ + if (ids := otel.trace_fields()) is not None: + payload.update(ids) stream = sys.stderr if stderr or _stdout_reserved else sys.stdout stream.write(json.dumps(payload, default=str) + "\n") stream.flush() diff --git a/tests/units/reflex_base/test_otel.py b/tests/units/reflex_base/test_otel.py index 944e82c2a0c..2b4f25f9c02 100644 --- a/tests/units/reflex_base/test_otel.py +++ b/tests/units/reflex_base/test_otel.py @@ -63,6 +63,7 @@ def test_trace_points_carry_no_import_statement(): otel.record_state_acquired, otel.record_message_size, otel.record_connection, + otel.trace_fields, ) for trace_point in trace_points: opnames = {inst.opname for inst in dis.get_instructions(trace_point)} @@ -114,6 +115,24 @@ def test_capture_context_returns_current(otel_exporter: InMemorySpanExporter): assert otel_context.get_current() is not captured +def test_trace_fields_disabled(): + assert otel.trace_fields() is None + + +def test_trace_fields_without_current_span(otel_exporter: InMemorySpanExporter): + assert otel.trace_fields() is None + + +def test_trace_fields_inside_span(otel_exporter: InMemorySpanExporter): + with active_tracer().start_as_current_span("outer") as span: + fields = otel.trace_fields() + span_context = span.get_span_context() + assert fields == { + "trace_id": f"{span_context.trace_id:032x}", + "span_id": f"{span_context.span_id:016x}", + } + + def test_event_span_attributes(otel_exporter: InMemorySpanExporter): ctx = _ctx(parent_txid="parent123") event = Event(name="state.sub.handler") diff --git a/tests/units/reflex_base/utils/test_log.py b/tests/units/reflex_base/utils/test_log.py index dfdf620957e..5ed4b649dfb 100644 --- a/tests/units/reflex_base/utils/test_log.py +++ b/tests/units/reflex_base/utils/test_log.py @@ -12,10 +12,13 @@ from unittest import mock import pytest +from reflex_base import otel from reflex_base.constants import LogLevel from reflex_base.utils import console, log from rich.console import Console +from tests.units.conftest import active_tracer + logger = logging.getLogger("reflex_base.tests.logs") @@ -159,6 +162,54 @@ def test_json_mode_success_level(monkeypatch, capsys): assert json.loads(out)["level"] == "success" +def test_json_mode_adds_trace_ids(monkeypatch, capsys, otel_sdk): + """Records emitted inside a span carry the span's W3C trace and span ids.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + with active_tracer().start_as_current_span("outer") as span: + logger.info("inside") + logger.error("failed inside") + span_context = span.get_span_context() + out, err = capsys.readouterr() + for record in (json.loads(out), json.loads(err)): + assert record["trace_id"] == f"{span_context.trace_id:032x}" + assert record["span_id"] == f"{span_context.span_id:016x}" + + +def test_console_print_json_mode_adds_trace_ids(monkeypatch, capsys, otel_sdk): + """Plain console output in JSON mode carries the current span's ids too.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + with active_tracer().start_as_current_span("outer") as span: + console.print("printed inside") + span_context = span.get_span_context() + record = json.loads(capsys.readouterr().out) + assert record["message"] == "printed inside" + assert record["trace_id"] == f"{span_context.trace_id:032x}" + assert record["span_id"] == f"{span_context.span_id:016x}" + + +def test_json_mode_omits_trace_ids_outside_span(monkeypatch, capsys, otel_sdk): + """With tracing on but no current span, records carry no trace ids.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + logger.info("outside") + record = json.loads(capsys.readouterr().out) + assert "trace_id" not in record + assert "span_id" not in record + + +def test_json_mode_omits_trace_ids_when_tracing_disabled(monkeypatch, capsys): + """With tracing off, records carry no trace ids.""" + monkeypatch.setenv("REFLEX_LOG_JSON", "true") + log.configure() + assert otel.enabled is False + logger.info("untraced") + record = json.loads(capsys.readouterr().out) + assert "trace_id" not in record + assert "span_id" not in record + + def test_configure_idempotent(): """Repeated configure calls never stack handlers.""" log.configure()