"""U14 (økt 55) — the tracing seam: opt-in OpenTelemetry, and no silent egress. **Why the seam exists.** The exploration loop this program is building hands a manager the freedom to decide what to look at next. The programme's load-bearing ordering rule is that *nothing which gives the manager more freedom lands before we can see what it did with it* — a loop without a trace is a black box, and a black box is not something an organisation can be asked to trust. The measured starting point (spike S6, økt 54) is that MAF's own Magentic code emits **zero** spans of its own, while ``ENABLE_INSTRUMENTATION`` defaults to ``True``, so spans are already being *made* today and thrown away for want of a provider. This seam is the provider — nothing more. **What is measured here, and what is deliberately not.** * Measured: that tracing is OFF unless asked for (and then MAF is never called at all), that console mode writes to **stderr** so the pinned demo transcript stays byte-identical, that a console run cannot silently also ship spans over the wire, and that the OTLP mode refuses to pretend when no endpoint was declared. * Not built: the ``PLAN_CREATED`` / ``REPLANNED`` / ``PROGRESS_LEDGER_UPDATED`` events the plan names. They belong to a loop that does not exist yet (U4, økt 56-57). An emitter with no call site is a shape guessed instead of measured, and this repo has paid for that guess before. **The measurement that shaped the code, not a preference.** ``configure_otel_providers`` composes its exporter list in a fixed order (``observability.py:849``): (1) exporters derived from the standard ``OTEL_EXPORTER_OTLP_*`` environment variables, **unconditionally**, (2) exporters passed in, (3) a ``ConsoleSpanExporter()`` — whose default sink is **stdout** — if ``enable_console_exporters`` is true, from the argument *or* from ``ENABLE_CONSOLE_EXPORTERS`` in the environment. Two consequences drive two of the tests below: 1. ``enable_console_exporters`` must be passed **explicitly False**, in both modes. Left to the environment, an operator with ``ENABLE_CONSOLE_EXPORTERS=true`` exported gets a stdout span dump — which is precisely the thing S6 measured as destroying the golden transcript. 2. Console mode must **refuse** when an OTLP endpoint variable is set, because step (1) would add a network exporter that the word "console" promises is not there. Validation, NEVER repair: we do not unset the operator's environment behind their back (the ``write_concept_file`` rule). **The subprocess arm is the measurement; the spy arms only prove wiring.** Every unit test here injects a recorder in place of ``configure_otel_providers``, and a suite made only of those would prove that we call *something* named right — the exact vacuity 4b's credential tests were rewritten to escape. So the real arm runs the actual demo as a subprocess under ``PORTFOLIO_OTEL=console`` and reads what came out: at least one ``workflow.run`` span on stderr, and stdout byte-identical to ``tests/golden/demo-transcript.stdout``. Its control runs the same demo with the variable absent and requires **no** span — without that control, "spans appeared" could not be attributed to the variable rather than to something the demo does anyway. """ from __future__ import annotations import io import os import re import subprocess import sys from pathlib import Path from typing import Any import pytest from portfolio_optimiser import tracing _GOLDEN_STDOUT = Path(__file__).resolve().parent / "golden" / "demo-transcript.stdout" class _ConfigureRecorder: """Stand-in for ``agent_framework.observability.configure_otel_providers``. Records every call verbatim. The point of recording rather than counting is that the two keyword arguments carry the whole safety property: which exporters were handed over, and whether the console (stdout) exporters were left to the environment to decide. """ def __init__(self) -> None: self.calls: list[dict[str, Any]] = [] def __call__(self, **kwargs: Any) -> None: self.calls.append(kwargs) # --------------------------------------------------------------------------------------------- # OFF by default — and "off" means MAF is never called, not called-with-nothing # --------------------------------------------------------------------------------------------- def test_absent_variable_configures_nothing_at_all() -> None: """T1: no ``PORTFOLIO_OTEL`` → mode ``None`` and ``configure_otel_providers`` is NEVER called. The distinction matters: a call with an empty exporter list would still install global providers and re-read every ``OTEL_EXPORTER_OTLP_*`` variable in the ambient environment. Not calling is the only shape under which "tracing is off" also means "nothing can leave". """ spy = _ConfigureRecorder() setup = tracing.configure_tracing(env={}, configure=spy) assert setup.mode is None assert setup.endpoints == () assert spy.calls == [] @pytest.mark.parametrize("raw", ["", " ", "\t\n"]) def test_variable_is_read_on_truthiness_not_presence(raw: str) -> None: """T2: an exported-but-empty ``PORTFOLIO_OTEL`` is a shell accident, not a request. Same rule as ``FOUNDRY_HOSTING_ENVIRONMENT`` (Fase 4b) and ``PORT`` (Fase 4d). Reading this on presence would turn ``export PORTFOLIO_OTEL=`` into a fail-fast on an unknown mode. """ spy = _ConfigureRecorder() setup = tracing.configure_tracing(env={tracing.TRACING_ENV: raw}, configure=spy) assert setup.mode is None assert spy.calls == [] # --------------------------------------------------------------------------------------------- # console mode — spans to stderr, stdout untouched # --------------------------------------------------------------------------------------------- def test_console_mode_exports_to_the_given_stream_and_never_to_stdout() -> None: """T3: console mode hands MAF exactly one exporter, writing to the stream we chose. ``ConsoleSpanExporter``'s default sink is ``sys.stdout``; S6 measured that letting it take that default destroys the pinned transcript. So the exporter is constructed explicitly against the stream, and ``enable_console_exporters`` is pinned False so that the environment cannot add a second, stdout-bound one behind it. """ from opentelemetry.sdk.trace.export import ConsoleSpanExporter stream = io.StringIO() spy = _ConfigureRecorder() setup = tracing.configure_tracing( env={tracing.TRACING_ENV: "console"}, stream=stream, configure=spy ) assert setup.mode == tracing.MODE_CONSOLE assert len(spy.calls) == 1 call = spy.calls[0] assert call["enable_console_exporters"] is False exporters = call["exporters"] assert len(exporters) == 1 exporter = exporters[0] assert isinstance(exporter, ConsoleSpanExporter) assert exporter.out is stream @pytest.mark.parametrize( "endpoint_var", [ "OTEL_EXPORTER_OTLP_ENDPOINT", "OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "OTEL_EXPORTER_OTLP_METRICS_ENDPOINT", "OTEL_EXPORTER_OTLP_LOGS_ENDPOINT", ], ) def test_console_mode_refuses_when_the_environment_declares_a_network_exporter( endpoint_var: str, ) -> None: """T4: ``console`` + any OTLP endpoint variable → ``TracingConfigError``, and MAF is not called. This is the no-silent-egress test. ``_configure`` adds env-derived exporters unconditionally and BEFORE ours, so the word "console" would have been a lie about where the spans went. Refusal names the offending variable, because the operator has to be able to find it; it does NOT unset it (validation, never repair). """ spy = _ConfigureRecorder() env = {tracing.TRACING_ENV: "console", endpoint_var: "http://collector.example:4317"} with pytest.raises(tracing.TracingConfigError) as excinfo: tracing.configure_tracing(env=env, configure=spy) assert endpoint_var in str(excinfo.value) assert spy.calls == [] # --------------------------------------------------------------------------------------------- # otlp mode — egress, and only when it was asked for by name # --------------------------------------------------------------------------------------------- def test_otlp_mode_without_a_declared_endpoint_is_refused() -> None: """T5: ``otlp`` with no endpoint variable → refusal, not a provider that exports nowhere. ``configure_otel_providers()`` with nothing to export to succeeds silently and installs providers whose spans go into the void. An operator who typed ``PORTFOLIO_OTEL=otlp`` asked to see the run somewhere; answering with a working-looking no-op is the failure mode this repo calls "a gate that can only be green". """ spy = _ConfigureRecorder() with pytest.raises(tracing.TracingConfigError) as excinfo: tracing.configure_tracing(env={tracing.TRACING_ENV: "otlp"}, configure=spy) assert "OTEL_EXPORTER_OTLP_ENDPOINT" in str(excinfo.value) assert spy.calls == [] def test_otlp_mode_leaves_the_exporter_to_maf_and_still_pins_the_console_flag() -> None: """T6: ``otlp`` + a declared endpoint → MAF builds the network exporter from the environment. We pass no exporters of our own: MAF's step (1) already reads the standard variables, and a second, hand-rolled OTLP exporter would be the duplicate free to drift from the spec. What we still pin is ``enable_console_exporters=False`` — otherwise an operator running OTLP with ``ENABLE_CONSOLE_EXPORTERS`` exported also gets a stdout dump. """ spy = _ConfigureRecorder() env = { tracing.TRACING_ENV: "otlp", "OTEL_EXPORTER_OTLP_ENDPOINT": "http://collector.example:4317", } setup = tracing.configure_tracing(env=env, configure=spy) assert setup.mode == tracing.MODE_OTLP assert setup.endpoints == (("OTEL_EXPORTER_OTLP_ENDPOINT", "http://collector.example:4317"),) assert len(spy.calls) == 1 assert spy.calls[0]["enable_console_exporters"] is False assert spy.calls[0]["exporters"] is None def test_an_unknown_mode_is_refused_by_name() -> None: """T7: a typo is a refusal that lists the closed set, never a silent fallback to off. Falling back to off would mean an operator who asked for tracing and mistyped gets a run with no trace and no complaint — the black box the seam exists to remove, arrived at by accident. """ spy = _ConfigureRecorder() with pytest.raises(tracing.TracingConfigError) as excinfo: tracing.configure_tracing(env={tracing.TRACING_ENV: "jaeger"}, configure=spy) message = str(excinfo.value) assert "jaeger" in message assert tracing.MODE_CONSOLE in message and tracing.MODE_OTLP in message assert spy.calls == [] # --------------------------------------------------------------------------------------------- # The announcement — one renderer, and omission rather than an empty row # --------------------------------------------------------------------------------------------- def test_notice_is_omitted_when_tracing_is_off() -> None: """T8a: no tracing → no line at all (``mandate.announce``'s rule). The same rule ``cost_baseline_notice`` and ``skipped_links_notice`` follow, and it is load-bearing beyond style here: the pinned demo stderr is four lines, and a "tracing: off" row would have made it five. """ assert tracing.tracing_notice(tracing.TracingSetup(mode=None, endpoints=())) is None def test_notice_names_the_sink_for_console_and_the_endpoint_for_otlp() -> None: """T8b: the announcement names where spans go, BEFORE the first one is emitted. Same discipline as the MCP announcement (``mcp_tools``): every destination is named up front, so there is no undeclared egress. The OTLP line names the *variable* as well as the value, because that is what the operator edits. """ console = tracing.tracing_notice(tracing.TracingSetup(mode=tracing.MODE_CONSOLE, endpoints=())) assert console is not None and "stderr" in console otlp = tracing.tracing_notice( tracing.TracingSetup( mode=tracing.MODE_OTLP, endpoints=(("OTEL_EXPORTER_OTLP_ENDPOINT", "http://collector.example:4317"),), ) ) assert otlp is not None assert "http://collector.example:4317" in otlp assert "OTEL_EXPORTER_OTLP_ENDPOINT" in otlp # --------------------------------------------------------------------------------------------- # The real arm: the actual demo, in a subprocess, with nothing patched # --------------------------------------------------------------------------------------------- _SPAN_MARKER = re.compile(r'"name": "workflow\.run"') def _run_demo(extra_env: dict[str, str]) -> subprocess.CompletedProcess[str]: """Run the real demo the same way the golden-transcript module does. The ``-m`` form (no PATH assumption) and a pinned ``PYTHONIOENCODING`` — without the latter the stdout comparison would be measuring the operator's locale rather than the program. """ proc = subprocess.run( [sys.executable, "-m", "portfolio_optimiser.simulation"], capture_output=True, text=True, encoding="utf-8", env={**os.environ, "PYTHONIOENCODING": "utf-8", **extra_env}, check=False, ) assert proc.returncode == 0, proc.stderr return proc @pytest.fixture(scope="module") def traced_demo() -> subprocess.CompletedProcess[str]: return _run_demo({tracing.TRACING_ENV: "console"}) @pytest.fixture(scope="module") def untraced_demo() -> subprocess.CompletedProcess[str]: return _run_demo({tracing.TRACING_ENV: ""}) def test_traced_demo_emits_workflow_run_spans_on_stderr( traced_demo: subprocess.CompletedProcess[str], ) -> None: """T9a: the plan's U14 criterion, half one — ``PORTFOLIO_OTEL=console`` produces real spans. ``workflow.run`` is asserted specifically rather than "some span": it is the span that says a workflow was executed, which is the thing a reader of the trace is looking for. S6 measured two of them for this demo; the assertion is ``>= 1`` because the count is a property of the demo's scripted script, not of the seam. """ assert len(_SPAN_MARKER.findall(traced_demo.stderr)) >= 1 def test_traced_demo_leaves_stdout_byte_identical_to_the_golden_transcript( traced_demo: subprocess.CompletedProcess[str], ) -> None: """T9b: the plan's U14 criterion, half two — turning tracing ON does not move one byte of stdout. This is what makes the seam safe to ship: the operator can trace a live run on stage without the transcript they rehearsed against changing under them. It is also the test that fails if the exporter is ever allowed to take its stdout default. """ assert traced_demo.stdout == _GOLDEN_STDOUT.read_text(encoding="utf-8") def test_untraced_demo_emits_no_spans_at_all( untraced_demo: subprocess.CompletedProcess[str], ) -> None: """T9c (control): without the variable there is NO span — so T9a measured the variable. Without this, "spans on stderr" would be consistent with a demo that emits them regardless, and the seam would be unproven while looking proven. """ assert _SPAN_MARKER.findall(untraced_demo.stderr) == [] def test_traced_demo_announces_where_the_spans_go( traced_demo: subprocess.CompletedProcess[str], ) -> None: """T9d: the announcement reaches the operator, not just the renderer's return value. The wiring half of T8: a renderer nobody prints is the silent-success shape this repo keeps finding. Only a subprocess run can catch a detached ``print`` in ``main()`` (the P4 precedent). """ assert "PORTFOLIO_OTEL" in traced_demo.stderr # --------------------------------------------------------------------------------------------- # The other two process entries — the CLI and the hosted service # --------------------------------------------------------------------------------------------- # # The demo is a scripted proof, not the product. Wiring the seam only there would leave the two # entries an organisation actually runs — `portfolio-optimiser` on a terminal and `python main.py` # in a container — untraceable, which is the state U14 exists to end. Both are exercised as # SUBPROCESSES for the P4 reason: a detached call inside a `main()` is invisible to every in-process # test, because no in-process test calls `main()`. def _run_cli(argv: list[str], extra_env: dict[str, str]) -> subprocess.CompletedProcess[str]: """Drive the CLI's refusal path — the cheapest argv that reaches past ``parse_args``. ``--json`` without ``--report`` is an existing, documented rc-1 refusal. It is used here as a carrier, not as the thing under test: it proves that the tracing seam is resolved BEFORE any branch of the CLI can return, which is what "call once at startup" requires. No model is contacted and no workflow is built, so the arm stays free. """ return subprocess.run( [sys.executable, "-m", "portfolio_optimiser.run", *argv], capture_output=True, text=True, encoding="utf-8", env={**os.environ, "PYTHONIOENCODING": "utf-8", **extra_env}, check=False, ) def test_cli_announces_tracing_before_it_refuses_anything() -> None: """T10: ``run.main`` resolves and announces the seam, ahead of every other branch. RED if the call is detached from ``main()`` or moved below a ``return``. """ proc = _run_cli(["--json"], {tracing.TRACING_ENV: "console"}) assert proc.returncode == 1, proc.stderr assert "PORTFOLIO_OTEL=console" in proc.stderr assert "run refused: --json requires --report" in proc.stderr def test_cli_says_nothing_about_tracing_when_it_is_off() -> None: """T10 control: the same argv without the variable prints the refusal and NOTHING else. Without this, T10 could not distinguish an announcement caused by the variable from a banner the CLI prints unconditionally — and an unconditional banner would have changed every existing stderr expectation in the suite. """ proc = _run_cli(["--json"], {tracing.TRACING_ENV: ""}) assert proc.returncode == 1 assert "PORTFOLIO_OTEL" not in proc.stderr def test_cli_refuses_an_unusable_tracing_request_as_a_run_refusal() -> None: """T11: a malformed ``PORTFOLIO_OTEL`` exits through the CLI's own rc-1 refusal surface. Not a traceback: this repo's CLI contract is that a refusal is a printed line and rc 1, and a configuration the operator can fix belongs there. The measured content matters too — the line must name the variable, since the operator is looking for something they exported, not for a flag they typed. """ proc = _run_cli(["--json"], {tracing.TRACING_ENV: "jaeger"}) assert proc.returncode == 1 assert "run refused" in proc.stderr assert "PORTFOLIO_OTEL" in proc.stderr assert proc.stderr.count("Traceback") == 0 def test_hosted_entrypoint_announces_tracing_on_stderr() -> None: """T12: ``python main.py`` — the ONE start command DEPLOY.md prints — carries the seam too. The hosted flate is where "an enterprise must be able to see what the run did" is actually cashed: a container's stderr is its log. Served, then stopped with SIGTERM exactly as the existing entrypoint test does, so this measures the real process rather than an import. """ import socket import time import urllib.error import urllib.request with socket.socket() as probe: probe.bind(("127.0.0.1", 0)) port = probe.getsockname()[1] repo_root = Path(__file__).resolve().parents[1] proc = subprocess.Popen( [sys.executable, str(repo_root / "main.py")], env={**os.environ, "PORT": str(port), tracing.TRACING_ENV: "console"}, cwd=repo_root, stdout=subprocess.DEVNULL, stderr=subprocess.PIPE, text=True, encoding="utf-8", ) try: deadline = time.monotonic() + 60 up = False while time.monotonic() < deadline: try: with urllib.request.urlopen( f"http://127.0.0.1:{port}/readiness", timeout=5 ) as resp: if resp.status == 200: up = True break except (urllib.error.URLError, OSError): time.sleep(0.2) assert up, "main.py never served /readiness" import signal as _signal proc.send_signal(_signal.SIGTERM) stderr = proc.communicate(timeout=15)[1] assert proc.returncode == 0 finally: if proc.poll() is None: proc.kill() proc.wait() assert "PORTFOLIO_OTEL=console" in stderr def test_console_mode_survives_an_operator_who_exported_enable_console_exporters() -> None: """T13: ``ENABLE_CONSOLE_EXPORTERS=true`` in the environment does NOT reach stdout. The behavioural half of ``enable_console_exporters=False``. Asserting only the keyword argument (T3, T6) proves what we passed, never what it prevents — and what it prevents is MAF's step (3) adding a second ``ConsoleSpanExporter()`` whose default sink is stdout, which is the exact shape S6 measured as destroying the pinned transcript. Left as ``None``, the flag falls back to this variable, so this run is the one that would break. """ proc = _run_demo({tracing.TRACING_ENV: "console", "ENABLE_CONSOLE_EXPORTERS": "true"}) assert proc.stdout == _GOLDEN_STDOUT.read_text(encoding="utf-8") assert len(_SPAN_MARKER.findall(proc.stderr)) >= 1