open/portfolio-optimiser
1
0
Fork 0
Code Issues Releases 3 Activity

feat(tracing): U14 - sporing er opt-in, og "av" betyr at MAF aldri kalles (ORDRE 20260823T165757Z)

Browse source 
PORTFOLIO_OTEL er eneste bryter, lest paa truthiness. Uten den kalles
configure_otel_providers ikke i det hele tatt: spans lages fortsatt
(ENABLE_INSTRUMENTATION defaulter True) og kastes, saa ingenting KAN forlate
prosessen. `console` skriver spans til stderr - demoens stdout er byte-identisk
med fasiten, maalt. `otlp` eksporterer over nett, og kun mot et endepunkt
operatoeren selv har navngitt.

To regler er MAALT, ikke valgt (observability.py:849 bygger exporter-lista i
fast rekkefoelge):

- enable_console_exporters sendes EKSPLISITT False i begge moduser. Overlatt til
  miljoeet faller den tilbake paa ENABLE_CONSOLE_EXPORTERS, hvis
  ConsoleSpanExporter skriver til STDOUT - nettopp det S6 maalte som oedeleggende
  for goldenen.
- `console` NEKTER naar en OTEL_EXPORTER_OTLP_*_ENDPOINT finnes: env-avledede
  exportere bygges UBETINGET og FOER vaare, saa ordet "console" ville vaert en
  usann paastand om hvor kjoeringens innhold tok veien. Validering, ALDRI
  reparasjon - vi fjerner ikke operatoerens variabel bak ryggen paa dem.

Tre kallsteder (run.main, simulation.main, hosting.main): demoen er et skriptet
bevis, ikke produktet, og en soem bare demoen naar ville latt de to inngangene en
virksomhet faktisk kjoerer vaere usporbare. tracing_notice er ENESTE renderer og
returnerer None naar sporing er av - omisjon, aldri tom rad.

IKKE bygget, med grunn: PLAN_CREATED/REPLANNED/PROGRESS_LEDGER_UPDATED hoerer til
sloeyfa U4 bygger; en emitter uten kallsted er en form gjettet i stedet for maalt.
OTLP-exporter-PAKKENE er bevisst ikke deklarert (egress + grpc/protobuf-vekt i et
publisert wheel); uttalt i README/DEPLOY/env.template.

Ny dep: opentelemetry-sdk>=1.42,<2 (operatoerbeslutning 2, 23.08). EN pakke, ikke
to - ConsoleSpanExporter bor inne i sdk-en. opentelemetry-api fulgte med
1.42.1 -> 1.44.0, maalt uskadelig.

Load-bearing MAALT (tests/test_tracing_loadbearing.py), ni mutasjoner alle roede
mot HELE suiten + groenn kontroll 943/5. Tre av de roede bor i tester som fantes
fra foer (golden-transkriptets fire-linjers stderr + portefoelje-CLI-ens stille
pass), altsaa er omisjons-regelen gatet av uavhengige vitner.

Golden ea8c534... uendret. mypy src + ruff rene.

Ordren tar ogsaa de fire operatoerbeslutningene inn i planens paragraf F.
Laasen paa orchestrations 1.0.1 er ENDELIG (operatoerbekreftelse 23.08), ikke
midlertidig: spike-ordrens "revert hvis E7 staar" er overstyrt av den senere
beslutningen, som betinget paa groenn suite - ikke paa E7.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
Kjell Tore Guttormsen 2026-08-23 20:51:46 +02:00
commit 4a19d39e63
12 changed files with 928 additions and 16 deletions
Download patch file Download diff file Expand all files Collapse all files

486
tests/test_tracing_loadbearing.py Normal file
View file

@ -0,0 +1,486 @@
"""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