|
29 | 29 | # Skip the entire module if otel extras aren't installed. |
30 | 30 | pytest.importorskip("opentelemetry.sdk.trace") |
31 | 31 |
|
32 | | -from typing import cast |
| 32 | +from typing import Any, cast |
33 | 33 |
|
34 | 34 | from opentelemetry import trace as otel_trace |
35 | 35 | from opentelemetry.sdk.trace import ReadableSpan, TracerProvider |
@@ -862,3 +862,106 @@ async def _flaky(s: _S) -> dict[str, int]: |
862 | 862 | idx = cast("int", attrs["openarmature.node.attempt_index"]) |
863 | 863 | parented_attempts.add(idx) |
864 | 864 | assert parented_attempts == {0, 1, 2} |
| 865 | + |
| 866 | + |
| 867 | +async def test_log_on_first_line_of_node_body_carries_node_span() -> None: |
| 868 | + """The load-bearing case ``prepare_sync`` exists to fix. |
| 869 | +
|
| 870 | + Without ``prepare_sync``, the engine queues the started event for |
| 871 | + async dispatch, then enters the node body — by the time the OTel |
| 872 | + observer's ``__call__`` opens the span on the worker task, the |
| 873 | + node body has already executed (or is mid-await). A log emitted |
| 874 | + on the FIRST line of the body, before any ``await``, would not |
| 875 | + see the observer's span via OTel ``get_current()``. |
| 876 | +
|
| 877 | + With ``prepare_sync``, the observer creates the span synchronously |
| 878 | + in the engine task BEFORE queueing, publishes it via |
| 879 | + ``current_active_observer_span``, and the engine attaches it to |
| 880 | + the OTel context around the node body. The first-line log picks |
| 881 | + up the right ``trace_id``/``span_id``. |
| 882 | +
|
| 883 | + This test exists in unit/ (not just buried in the conformance |
| 884 | + fixture 010 driver) so a failure here jumps straight to |
| 885 | + ``prepare_sync``-related changes during a regression hunt. |
| 886 | + """ |
| 887 | + from opentelemetry.sdk._logs import LoggerProvider |
| 888 | + from opentelemetry.sdk._logs.export import ( |
| 889 | + InMemoryLogRecordExporter, |
| 890 | + SimpleLogRecordProcessor, |
| 891 | + ) |
| 892 | + |
| 893 | + test_logger = logging.getLogger("openarmature.test.first_line_log") |
| 894 | + |
| 895 | + class _S(State): |
| 896 | + x: int = 0 |
| 897 | + |
| 898 | + async def first_line_log_node(_s: _S) -> dict[str, Any]: |
| 899 | + # FIRST line, before any ``await`` — without ``prepare_sync`` |
| 900 | + # in the engine task, OTel ``get_current()`` would return an |
| 901 | + # invalid span here and the log would have ``trace_id=0`` / |
| 902 | + # ``span_id=0``. |
| 903 | + test_logger.info("emitted before any await") |
| 904 | + return {"x": 1} |
| 905 | + |
| 906 | + span_exporter = InMemorySpanExporter() |
| 907 | + observer = OTelObserver(span_processor=SimpleSpanProcessor(span_exporter)) |
| 908 | + log_exporter = InMemoryLogRecordExporter() |
| 909 | + log_provider = LoggerProvider() |
| 910 | + log_provider.add_log_record_processor(SimpleLogRecordProcessor(log_exporter)) |
| 911 | + |
| 912 | + # Snapshot prior log state so this test doesn't bleed into others |
| 913 | + # — install_log_bridge mutates process-global ``logging`` state. |
| 914 | + root = logging.getLogger() |
| 915 | + prior_handlers = list(root.handlers) |
| 916 | + prior_filters = list(root.filters) |
| 917 | + prior_factory = logging.getLogRecordFactory() |
| 918 | + prior_test_level = test_logger.level |
| 919 | + test_logger.setLevel(logging.INFO) |
| 920 | + |
| 921 | + try: |
| 922 | + install_log_bridge(log_provider) |
| 923 | + g = ( |
| 924 | + GraphBuilder(_S) |
| 925 | + .add_node("node_a", first_line_log_node) |
| 926 | + .add_edge("node_a", END) |
| 927 | + .set_entry("node_a") |
| 928 | + .compile() |
| 929 | + ) |
| 930 | + g.attach_observer(observer) |
| 931 | + await g.invoke(_S(), correlation_id="first-line-test") |
| 932 | + await g.drain() |
| 933 | + observer.shutdown() |
| 934 | + log_provider.force_flush() |
| 935 | + |
| 936 | + records = log_exporter.get_finished_logs() |
| 937 | + ours = [r for r in records if str(r.log_record.body) == "emitted before any await"] |
| 938 | + assert len(ours) == 1, ( |
| 939 | + f"expected exactly one log record; got {len(ours)}: {[str(r.log_record.body) for r in records]}" |
| 940 | + ) |
| 941 | + log_record = ours[0].log_record |
| 942 | + |
| 943 | + spans = span_exporter.get_finished_spans() |
| 944 | + node_a_spans = [s for s in spans if s.name == "node_a"] |
| 945 | + assert len(node_a_spans) == 1, f"expected one node_a span; got {len(node_a_spans)}" |
| 946 | + node_a_span = node_a_spans[0] |
| 947 | + assert node_a_span.context is not None |
| 948 | + node_span_id = node_a_span.context.span_id |
| 949 | + node_trace_id = node_a_span.context.trace_id |
| 950 | + |
| 951 | + # Load-bearing: the prepare_sync hook attached the observer |
| 952 | + # span synchronously so the first-line log saw it via OTel |
| 953 | + # ``get_current()``. |
| 954 | + assert log_record.span_id == node_span_id, ( |
| 955 | + f"first-line log MUST carry node_a span's span_id " |
| 956 | + f"(prepare_sync attaches the span synchronously in the engine task); " |
| 957 | + f"got log span_id={log_record.span_id}, node span_id={node_span_id}" |
| 958 | + ) |
| 959 | + assert log_record.trace_id == node_trace_id, ( |
| 960 | + f"first-line log MUST carry node_a span's trace_id; " |
| 961 | + f"got log trace_id={log_record.trace_id}, node trace_id={node_trace_id}" |
| 962 | + ) |
| 963 | + finally: |
| 964 | + root.handlers[:] = prior_handlers |
| 965 | + root.filters[:] = prior_filters |
| 966 | + logging.setLogRecordFactory(prior_factory) |
| 967 | + test_logger.setLevel(prior_test_level) |
0 commit comments