Trace a failed connection by correlation ID and request ID

Setup

1. Choose Lab Photos as the lab tenant and press Start.

2. Create lab-tmp-printer-test again as in Implementing a client Setup, with its redirect URI http://127.0.0.1:8765/test/callback, and read -rs PRINTER_TEST_SECRET; export PRINTER_TEST_SECRET. Update client_id in ~/lab-printer-client/test.json.

3. Work in ~/lab-printer-client. The module logs one JSON line per stage with the attempt's correlation ID and, for token requests, the tenant's X-Request-ID, but never the code, verifier, secret or token. Send its output to a file you can search: append | tee -a trace.log to each command below.

4. Save a driver that starts two attempts in one session four seconds apart, as a double click would, then completes only the first. Save it as double.mjs:

import fs from 'node:fs'; import { pathToFileURL } from 'node:url';
const [modulePath, configFile] = process.argv.slice(2);
const { createClient } = await import(pathToFileURL(modulePath).href);
const client = await createClient(JSON.parse(fs.readFileSync(configFile, 'utf8')));
const first = await client.begin('ava', 'ref-7f3');
await new Promise(resolve => setTimeout(resolve, 4000));   // the second click
await client.begin('ava', 'ref-7f3');
console.log('Open only the FIRST address:\n' + first);
await client.callback(await client.awaitCallback(), 'ref-7f3').then(() => console.log('connected'), e => console.log('connection failed:', e.message));

Walkthrough

1. Introduce the lesson's bug in a copy. Run cp printer-oauth.mjs printer-oauth-buggy.mjs and make two edits in the copy, so it keeps one verifier per session instead of one per attempt:

   • after transactions.set(t.state, t); in begin, add lastVerifier.set(session, t.verifier);, and declare const lastVerifier = new Map(); beside transactions

   • in callback, change code_verifier: t.verifier to code_verifier: lastVerifier.get(session)

2. Reproduce the failure: node double.mjs ./printer-oauth-buggy.mjs test.json | tee -a trace.log. Open the first address and sign in as Ava. It prints connection failed: exchange refused: invalid_grant.

3. Read your trace like the lesson's engineer:

jq -c '{at, stage, corr, status, request_id, result, issuer}' trace.log | tail -8

Two connect_start lines share session ref-7f3, four seconds apart. The callback for the first corr arrived seconds after it began (not expired), and it made the attempt's first and only token request (not reused). That leaves the verifier. Take the request_id from the 400 response to Audit and open that event: oauth.token rejected with reason pkce_failed.

Why it matters: the authorization server says little in its errors on purpose. Your own records, joined to its request ID, are what separate one cause from another.

4. Remove the bug. Run the same driver against the real module: node double.mjs ./printer-oauth.mjs test.json | tee -a trace.log. With one transaction per attempt, the first attempt keeps its own verifier and connects.

5. Reproduce three more rows of the lesson's table and note what each looks like from the outside:

   • Redirect URI. Copy test.json to slash.json with redirect_uri ending in /test/callback/, run node printer.mjs slash.json connect ava, and open the address: the tenant's own error page, and the browser never returns. Press Ctrl+C.

   • Unknown scope. Copy test.json to scope.json with "scope": "photos.read albums.everything" and connect: the callback carries error=invalid_scope.

   • Wrong secret. Run PRINTER_TEST_SECRET=wrong-secret-wrong-secret-wrong-secret-0 node printer.mjs test.json race ava: 401 invalid_client.

6. Find a server-side failure by reference ID. In Access Token Management, create lab-tmp-broken (Signed JWT) with this Advanced issuance policy, which returns a field the tenant does not accept, save it even if the test reports the problem, and assign it to lab-tmp-printer-test:

return { allow: true, claims: {}, colour: 'blue' };

Run node printer.mjs test.json race ava. The token request returns 500 with error=server_error and a reference_id. In Logs, search for that ID: the failed oauth.token request appears with its reason.

Why it matters: a reference ID is what a support team asks for first, and it finds the failure without anyone sharing a token.

Restore: assign Default access tokens back to lab-tmp-printer-test, then delete lab-tmp-broken.

7. Read a rejected token against a configuration. Reconnect Ava, then decode her access token locally and compare it with your API's settings:

btl-lab decode "$(jq -r .access_token ~/lab-printer-oauth/*/ava.json | head -1)" | grep -E '"(iss|aud|kid|iat|exp|jti)"'

Compare iss and aud with what btl-lab resource expects, kid with the key set, and iat and exp with your clock. Run btl-lab resource --mode jwt --clock-offset 3720 (a clock an hour and two minutes ahead, past the default one-hour lifetime), call it with the token, and find the decision line by jti: expired, though the token is fine.

Why it matters: decoding is reading, not validating, and for comparing a token with a configuration, reading is exactly what is needed. It happens on your machine; nothing is pasted into a public decoder.

8. Look without leaking. In developer tools, Network, turn on Preserve log, connect once more, and export a HAR file. Open it in a text editor and list what must be redacted before it goes into a ticket: the callback URL's code, every Cookie and Set-Cookie header, and any token response. Then delete the HAR file.

Break it

Steps 1, 5 and 6 are the deliberate failures. The bug lives only in printer-oauth-buggy.mjs, and the broken policy is restored in step 6.

Check your work

Press Check my progress before Cleanup, because Cleanup deletes the test client. The checks look for, in order: pkce_failed from the double click, the fixed connection, invalid_scope for the unknown scope, invalid_client for the wrong secret, and the failed token request behind the reference ID.

Your trace.log should contain stages, correlation IDs, statuses and request IDs, and no code, verifier, secret or token: grep -c -E 'eyJ|code_verifier' trace.log prints 0.

Cleanup

1. Confirm lab-tmp-broken is deleted and no client uses it.

2. Delete the bug copy, the trace and stored tokens: rm printer-oauth-buggy.mjs slash.json scope.json trace.log; rm -rf ~/lab-printer-oauth.

3. Delete the client lab-tmp-printer-test. Run unset PRINTER_TEST_SECRET.