Skip to content

chore(canary): keep captured logs on a RED, and correct the 401's surface - #572

Merged
ffroliva merged 1 commit into
developfrom
chore/canary-capture-logs
Aug 25, 2026
Merged

ffroliva merged 1 commit into
developfrom
chore/canary-capture-logs

Conversation

@ffroliva

Copy link
Copy Markdown
Owner

Summary

Three canary REDs (2026-08-20 / 08-23 / 08-25) named the same test and preserved only a traceback. For an auth 401 that traceback is the same shape whatever the cause, and the failure reproduces only on the unattended overnight run — so every red so far has been untriageable by construction.

Two changes, both evidence-driven.

1. Keep the logs (-o junit_logging=all)

The line that decides this is already emitted on every run — client.context_cookie_state, the #222 diagnostic, which reports whether the launched browser context actually loaded the Flow session cookie:

client.context_cookie_state  context_cookie_count=59
                             flow_session_cookie_expired=False
                             flow_session_cookie_present=True
                             google_sapisid_present=True

pytest captures it and throws it away. With this flag it lands in the preserved tmp/canary-red-*.xml. Verified empirically before committing.

That boolean is the discriminator:

2. Correct which auth surface fails

The preserved JUnit from all three REDs is byte-identical:

tests/e2e/test_aisandbox_auth_live.py:69
    project = await client.create_project(...)
resp = <APIResponse url='https://labs.google/fx/api/trpc/project.createProject'
        status=401 status_text='Unauthorized'>

That is the NextAuth cookie surface. No Bearer token is involved — _aisandbox_auth_headers() is gated on is_aisandbox (client.py:1256) and never runs. The failing line is :69 (create_project), not :70 (upload_image).

#561 is titled for an uploadImage failure and its transport A/B tested a code path the failure never reaches. docs/E2E_TESTING.md repeated the same wording; corrected here so the next reader does not re-investigate the wrong host.

What this PR deliberately does NOT do

No fix. The failure is not reproducible on demand — verified today against the live denon82 profile at $0: auth status exit 0, the failing test 1 passed standalone, the full tier 18 passed. #561's own standing rule applies: no fix against a failure we cannot reproduce. This PR only makes the next occurrence readable.

Falsified along the way

A leading hypothesis was that the canary's own pre-run gflow auth status caused the RED: the session probe makes labs.google issue a rotated __Secure-next-auth.session-token via Set-Cookie, which gflow-cli discards, leaving the profile on the superseded token. Measured directly — dead:

arm result
control: createProject with on-disk token, x2 200, 200
after probe 1, same old token 200
the rotated token 200
after probe 2, old token again 200

Rotation is harmless. The canary is not causing its own red.

Test plan

  • tests/scripts/test_canary_classify.py::test_tier_run_captures_logs_into_the_junit — new, TDD (red → green)
  • Verified live that client.context_cookie_state reaches the JUnit under the flag
  • repo hygiene / doc links / website PII: pass
  • ruff check src tests + ruff format --check src tests: pass
  • pyright src: 0 errors
  • Full offline suite: 3342 passed, 5 skipped
  • website/docs mirror regenerated

Timing

The canary runs from a dedicated clone that pulls develop before each run. This needs to be on develop before 03:00 tonight or tomorrow is another blind red.

Refs #559, #561

… surface

The canary's REDs reproduce only unattended, so anything a run does not record
is unrecoverable afterwards. Three REDs (2026-08-20/23/25) named the same test
and preserved only a traceback — which for an auth 401 is the same shape
whatever the cause.

Run pytest with `-o junit_logging=all` so the preserved `tmp/canary-red-*.xml`
carries the run's structlog output. The deciding line is already emitted:
`client.context_cookie_state` (the #222 diagnostic) reports whether the launched
browser context actually loaded the Flow session cookie. That boolean separates
"the browser never got the cookie" from "the session was genuinely refused".
Verified: the line lands in the JUnit under this flag.

Also corrects docs/E2E_TESTING.md. The failure is a 401 on
`labs.google/fx/api/trpc/project.createProject` — the NextAuth cookie surface —
not the aisandbox Bearer/uploadImage path. The failing test is named for an
upload, but the traceback dies one line earlier on project creation. #561 was
recorded against the wrong host and its transport A/B tested a code path the
failure never reaches.

No behaviour change: the canary gates nothing, and the JUnit already stayed
local carrying raw tracebacks, so the sanitization contract is unaffected.

Refs #559, #561
@ffroliva
ffroliva merged commit 3064d6f into develop Aug 25, 2026
15 checks passed
@ffroliva
ffroliva deleted the chore/canary-capture-logs branch August 25, 2026 12:29
ffroliva added a commit that referenced this pull request Aug 26, 2026
…alled (#583)

`run_canary.py --pull` fast-forwards the checkout and then keeps executing the
copy Python loaded at startup, so every runner change was silently one night late.

Not theoretical. #572 added `-o junit_logging=all` so a preserved RED would carry
the `client.context_cookie_state` line that decides #561. It merged 2026-08-25
12:29 UTC; the 2026-08-26 02:00 run pulled it and produced a RED with ZERO log
output, because the pre-pull copy was running:

    git show 230200b:scripts/canary/run_canary.py | grep -c junit_logging  -> 0

Three REDs untriageable, and the failure reads as "#572 did not work" — which
invites rewriting a fix that was already correct. Confirmed #572 is fine: a manual
run on the current runner captured 40 system-out entries, 11 context_cookie_state
lines, and flow_session_cookie_present.

The runner now re-runs itself once when a successful pull changed its own source.

Two independent loop guards, either sufficient alone: GFLOW_CANARY_REEXECED in the
child env (checked first), and a content digest. An unreadable digest degrades to
"unchanged" — updating late is a nuisance, looping is an outage.

subprocess.run, never os.execv: on Windows execv does not replace the process
image, so the PID changes and Task Scheduler can read the task as finished. A
supervising process keeps that view intact and propagates the exit code. Asserted
by an AST test, since a substring search matches the module's own explanation.

The fix cannot help its own deployment — the first run after it lands is still the
old runner. It applies from the following change onward.

E2E on a scratch clone against a real profile, $0:

  control    pre-fix runner, pull brings the flag
             -> no re-exec (correct), JUnit system-out: 0   <- reproduces 02:00
  treatment  fixed runner, develop ahead with a runner change
             -> canary.reexec_after_pull: ffd32333cb9b -> fef66243ee51
             -> ran once, no loop, JUnit system-out: 42

Closes #582
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant