From 7efb9b4ddcb75cdf4c6dd87ff117c99732120a3b Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Thu, 22 Oct 2026 18:31:19 -0400 Subject: [PATCH 01/10] Build the Console span tree and summary Peek (#996) --- console/README.md | 66 ++- console/reproductions/waterfall-fractional.py | 8 +- console/reproductions/waterfall-stage.py | 8 +- console/reproductions/waterfall-trace-axis.py | 15 +- console/tests/spans.test.cjs | 158 +++++++ console/tests/stop.test.cjs | 8 +- console/tests/waterfall.test.cjs | 62 +-- docs/code-navigation.md | 3 +- src/args.rs | 35 ++ src/console.rs | 12 + src/console/assets/console.css | 6 - src/console/assets/console.js | 28 +- src/console/assets/spans.css | 67 +++ src/console/assets/spans.js | 298 +++++++++++++ src/console/waterfall.html | 33 +- src/console/waterfall.rs | 33 +- src/logs.rs | 1 + src/logs/session.rs | 35 +- src/logs/spans.rs | 416 ++++++++++++++++++ src/logs/spans/session.rs | 361 +++++++++++++++ src/logs/status/waterfall.rs | 313 +------------ src/logs/status/waterfall/matching.rs | 16 +- src/logs/status/waterfall/trace.rs | 47 +- src/main.rs | 11 + tests/console.rs | 97 ++-- tests/console/spans.rs | 96 ++++ tests/console/waterfall.rs | 131 +++--- 27 files changed, 1810 insertions(+), 554 deletions(-) create mode 100644 console/tests/spans.test.cjs create mode 100644 src/console/assets/spans.css create mode 100644 src/console/assets/spans.js create mode 100644 src/logs/spans.rs create mode 100644 src/logs/spans/session.rs create mode 100644 tests/console/spans.rs diff --git a/console/README.md b/console/README.md index ccc3cda18..60d0aeb58 100644 --- a/console/README.md +++ b/console/README.md @@ -183,27 +183,51 @@ test checks their stage times and Usual ranges against the CLI; the Playwright time tests check scale in all windows, child selection, live ordering and 390 px. Waterfall chooses one retained Command with live, died and ended chips, keeping -its exact selection in `command=`. Runs, stages and tool calls share one axis, -including a Spec run's Ticket Runs. It pairs with `show --json` and `logs`: -stage intervals come from the Command record. For a Session trace, each tool -interval uses its span's start and end, including overlapping calls and fractions -of a second. A running call uses its start record and extends to the current time -while its Command is live. A call left open in an ended or died Command retains -its start with “Time unknown” for its duration. -Only sessions with an old Session log and no Session trace use Claude/Codex tool -summaries matched to scoped `HH:MM:SS` Command-log lines in order, across midnight. -Those estimated intervals extend to the next matched call or stage boundary and -include waiting. Unmatched legacy calls stay visible with “Time unknown” and no -bar. Session links open their retained evidence. The Waterfall browser test checks -selection, span times, running calls, scale, unknown times, escaping and phone -layout; Rust checks trace timing, legacy matching and CLI parity. -The retained Spec-review checks are `python3 console/reproductions/waterfall-fractional.py` -and `python3 console/reproductions/waterfall-stage.py` from the repo root after a build. -The Rust router test walks the registered routes and checks their CLI pairs. -The fractional Run/stage boundaries also run in the Rust integration tests. -The retained Session-trace regression is -`python3 console/reproductions/waterfall-trace-axis.py`; it checks that completed -tool spans still draw bars after a Command dies without recording its end. +its exact selection in `command=`. A span tree replaces the old Run sections: +Command → Runs → stages → Sessions → model calls, turns, tools and sub-agents. +Child Runs sit under the stage that started them; reused Sessions appear only +under their first stage. Commands, Runs and stages start expanded, Sessions +folded. Calls enter the DOM only after their Session is expanded. + +The same tree and selected span details are available from the CLI: + +```sh +thirdshift show widgets#7 --spans --json +thirdshift show widgets#7 --span --json +``` + +The tree uses the recorder's stable Command, Run and stage span IDs. Each row +has its kind, status, duration and bar on a shared axis. Errors carry their +message, running calls extend to now with a hatched bar, and estimated timings +are dotted and marked `*`. Converted Session tools keep the old scoped +Command-log estimates, including unknown times. Commands without traces still +show their Runs, stages and any retained legacy tool summaries. + +The open Slowest calls list ranks ten tool and model calls in the timeline's +window; turns and sub-agents are excluded. Selecting a call reveals its row +and summary Peek. Ancestors in the Peek select their own span. The card shows +applicable timing, usage, cost, call and error facts, relative-position bars, +input/output and attributes, plus a conversation link and Copy CLI. Conversation +links open the Session because that reader does not yet anchor individual +records. Command details opens the existing Peek with Stop, logs and the PR. + +Zoom fits a parent span or a padded window around a call. The sticky axis keeps +the zoom notice and Zoom out control visible; the slowest calls re-rank within +the window. Folds, selection, zoom and Peek disclosures survive live refresh. +On a phone, labels fill one row, bars and durations the next; revealed rows +stay between the sticky axis and the Peek bottom sheet. + +Within the tree, arrows and `j` / `k` move focus, Right expands or enters a +child, Left folds or returns to the parent, Home/End reach either end, and +Enter/Space opens the Peek. Outside the tree, the Console's usual keys apply. + +Rust route/CLI parity and timing tests live in `tests/console/spans.rs` and +`tests/console/waterfall.rs`. The Playwright span and Waterfall tests cover +folding at scale, keyboard navigation, Peek, zoom, live refresh, bar geometry, +escaping and 390 px. Retained timing checks also run with +`python3 console/reproductions/waterfall-fractional.py`, +`python3 console/reproductions/waterfall-stage.py`, and +`python3 console/reproductions/waterfall-trace-axis.py` after a build. `j` / `k` select headings and visible rows, wrapping at either end. `Space` folds a heading or toggles a row's peek; `Enter` opens that row's full Command diff --git a/console/reproductions/waterfall-fractional.py b/console/reproductions/waterfall-fractional.py index c0fbab232..fe3ddd365 100644 --- a/console/reproductions/waterfall-fractional.py +++ b/console/reproductions/waterfall-fractional.py @@ -1,4 +1,4 @@ -import json, os, pathlib, re, subprocess, tempfile, urllib.request +import json, os, pathlib, subprocess, tempfile, urllib.request binary = pathlib.Path(__file__).resolve().parents[2] / 'target/debug/thirdshift' with tempfile.TemporaryDirectory(prefix='827-spec-') as temp: @@ -19,10 +19,10 @@ server = subprocess.Popen([str(binary),'console','--no-sign-in'],env={**os.environ,'HOME':str(home)},stdout=subprocess.PIPE,text=True) try: origin = server.stdout.readline().strip() - html = urllib.request.urlopen(origin+'/waterfall?command=widgets%237').read().decode() - tools = re.findall(r'
  • ')[1:] - assigned = [re.search(r'

    ([^<]*)

    ',stage).group(1) for stage in stages if 'class="waterfall-tool"' in stage] + tree = json.load(urllib.request.urlopen(origin+'/spans?command=widgets%237')) + spans = {span['id']: span for span in tree['spans']} + assigned = [spans[span['parent_id']]['name'] for span in tree['spans'] if span['kind'] == 'tool'] print('Stage containing implement tool:',assigned,flush=True) assert assigned == ['implement'], 'Session tool must nest under implement; whole-second clock incorrectly puts it in previous Setup stage' finally: diff --git a/console/reproductions/waterfall-trace-axis.py b/console/reproductions/waterfall-trace-axis.py index bd150e167..185ae505b 100644 --- a/console/reproductions/waterfall-trace-axis.py +++ b/console/reproductions/waterfall-trace-axis.py @@ -1,5 +1,5 @@ """Retained Spec-review reproduction: measured spans survive a died Command.""" -import json, os, pathlib, re, subprocess, tempfile, urllib.request +import json, os, pathlib, subprocess, tempfile, urllib.request binary = pathlib.Path('target/debug/thirdshift').resolve() with tempfile.TemporaryDirectory(prefix='989-spec-died-') as temp: @@ -29,14 +29,11 @@ ) try: origin = server.stdout.readline().strip() - html = urllib.request.urlopen(origin + '/waterfall?command=widgets%237').read().decode() - tools = re.findall( - r'
  • ' - r'.*? 0, 'Ended tool span must draw a visible bar for a died Command' + tree = json.load(urllib.request.urlopen(origin + '/spans?command=widgets%237')) + tools = [span for span in tree['spans'] if span['kind'] == 'tool' and span['end'] is not None] + print('Retained tool timing:', tools) + assert len(tools) == 2 and all(span['end'] > span['start'] for span in tools), 'Ended tool spans must retain visible intervals for a died Command' + # console/tests/waterfall.test.cjs also checks the rendered bar widths. finally: server.terminate() server.wait(timeout=10) diff --git a/console/tests/spans.test.cjs b/console/tests/spans.test.cjs new file mode 100644 index 000000000..18347e60e --- /dev/null +++ b/console/tests/spans.test.cjs @@ -0,0 +1,158 @@ +const { test, before, after } = require('node:test'); +const assert = require('node:assert/strict'); +const { spawn, execFileSync } = require('node:child_process'); +const { once } = require('node:events'); +const { mkdtemp, mkdir, readFile, writeFile, rm } = require('node:fs/promises'); +const { tmpdir } = require('node:os'); +const { join, resolve } = require('node:path'); +const { createInterface } = require('node:readline'); +const { chromium } = require('playwright'); + +let home, server, exited, browser, origin, folder, recordPath, session; +const binary = process.env.THIRDSHIFT_BINARY ?? resolve(__dirname, '../../target/debug/thirdshift'); +const attr = (key, value) => ({ key, value: typeof value === 'boolean' ? { boolValue: value } : { stringValue: String(value) } }); +const nano = ms => String(BigInt(ms) * 1000000n); +const span = (id, parent, name, start, end, attributes = [], status) => ({ + spanId: id, parentSpanId: parent, name, startTimeUnixNano: nano(start), + endTimeUnixNano: end ? nano(end) : '0', attributes, status +}); +const ids = { session: '1111111111111111', agent: '2222222222222222', tool: '3333333333333333', model: '4444444444444444', turn: '5555555555555555' }; +before(async () => { + home = await mkdtemp(join(tmpdir(), 'thirdshift-spans-')); + folder = join(home, '.thirdshift/logs/acme/widgets/commands/issue'); + await mkdir(folder, { recursive: true }); + await writeFile(join(home, '.thirdshift/config.toml'), '[console]\nport = 0\n'); + const start = Date.parse('2026-10-01T12:00:00Z'); + session = join(folder, '99-20261001T120000+0000-implement.jsonl'); + const record = { + version: 1, kind: 'Spec run', repository: 'acme/widgets', name: 'spec-7', hostname: 'fixture', + issue: { number: 7, url: 'https://github.com/acme/widgets/issues/7', title: 'Widgets ' }, + process_id: 0, process_start: 'gone', harness: 'codex', started_at: new Date(start).toISOString(), + ended_at: new Date(start + 60000).toISOString(), outcome: 'merged', session_log: null, + stages: [{ name: 'Tickets', began_at: new Date(start).toISOString(), session_log: null }] + }; + recordPath = join(folder, '7-fixture.command.json'); + await writeFile(recordPath, JSON.stringify(record)); + await writeFile(join(folder, '7-fixture.issue-99.child.json'), JSON.stringify({ + ...record, kind: 'Run', name: 'ticket-99', issue: { ...record.issue, number: 99 }, parent_record: recordPath, + session_log: session, stages: [ + { name: 'implement', began_at: new Date(start + 1000).toISOString(), session_log: session }, + { name: 'pull request', began_at: new Date(start + 55000).toISOString(), session_log: session } + ] + })); + const spans = [ + span(ids.session, undefined, 'invoke_agent implement', start + 1000, start + 55000, [attr('gen_ai.operation.name', 'invoke_agent'), attr('thirdshift.session.prompt', 'Build '), attr('thirdshift.session.kind', 'implement')]), + span(ids.agent, ids.session, 'agent reviewer', start + 3000, start + 50000, [attr('thirdshift.type', 'subagent_started'), attr('thirdshift.description', 'Review widgets')]), + span(ids.tool, ids.agent, 'execute_tool Bash', start + 5000, start + 25000, [attr('gen_ai.operation.name', 'execute_tool'), attr('gen_ai.tool.name', 'Bash'), attr('gen_ai.tool.call.arguments', '{"command":"cargo test "}'), attr('gen_ai.tool.call.result', 'Tests failed'), attr('thirdshift.time.estimated', true)], { code: 2, message: 'test failed' }), + span(ids.model, ids.session, 'model response', start + 30000, start + 45000, [attr('gen_ai.operation.name', 'chat'), attr('gen_ai.response.model', 'test-model'), attr('gen_ai.usage.input_tokens', 100), attr('gen_ai.usage.output_tokens', 25), attr('thirdshift.cost.usd', '0.01')]), + span(ids.turn, ids.session, 'turn response', start + 1000, start + 55000, [attr('thirdshift.type', 'turn_ended')]), + ...Array.from({ length: 300 }, (_, i) => span((1000 + i).toString(16).padStart(16, '0'), ids.session, `execute_tool Read ${i}`, start + 46000, start + 46010, [attr('gen_ai.operation.name', 'execute_tool')])) + ]; + await writeFile(session.replace('.jsonl', '.logs.jsonl'), ''); + await writeFile(session.replace('.jsonl', '.spans.jsonl'), JSON.stringify({ resourceSpans: [{ scopeSpans: [{ spans }] }] }) + '\n'); + server = spawn(binary, ['console', '--no-sign-in'], { env: { ...process.env, HOME: home }, stdio: ['ignore', 'pipe', 'inherit'] }); + exited = once(server, 'exit'); + const lines = createInterface({ input: server.stdout }); + try { [origin] = await once(lines, 'line', { signal: AbortSignal.timeout(10000) }); } + finally { lines.close(); } + browser = await chromium.launch({ headless: true }); +}); +after(async () => { + await browser?.close(); + if (server && server.exitCode === null) server.kill(); + await exited; + if (home) await rm(home, { recursive: true, force: true }); +}); + +test('span tree, summary Peek, zoom and keyboard work at laptop and 390 px', async t => { + const context = await browser.newContext(); + t.after(() => context.close()); + const page = await context.newPage(); + const errors = []; + page.on('pageerror', error => errors.push(error.message)); + for (const width of [1200, 390]) { + await page.setViewportSize({ width, height: 844 }); + await page.goto(`${origin}/waterfall?command=widgets%237`); + const tree = page.getByRole('tree', { name: 'Command spans' }); + await tree.waitFor(); + assert.equal(await tree.getByRole('treeitem').count(), 7, 'calls stay out of the DOM while their session is folded'); + const sess = tree.locator(`[data-span-id="${ids.session}"]`); + assert.equal(await sess.getAttribute('aria-expanded'), 'false'); + assert.match(await sess.textContent(), /#1/); + assert.match(await sess.textContent(), /1 error/); + const slow = page.locator('#slowest-calls'); + assert.equal(await slow.locator('[data-reveal-span]').count(), 10); + assert.match(await slow.locator('[data-reveal-span]').first().textContent(), /Bash/); + assert.equal(await slow.locator(`[data-reveal-span="${ids.turn}"]`).count(), 0); + await slow.locator(`[data-reveal-span="${ids.tool}"]`).click(); + const tool = tree.locator(`[data-span-id="${ids.tool}"]`); + await page.locator('#peek-content h2').waitFor(); + assert.equal(await tool.getAttribute('aria-selected'), 'true'); + assert.match(await page.locator('#peek-content').textContent(), /cargo test /); + assert.match(await page.locator('#peek-content').textContent(), /test failed/); + assert.equal(await page.locator('#peek-content details[open] summary').textContent(), 'Input'); + const copy = page.getByRole('button', { name: 'Copy CLI', exact: true }); + assert.match(await copy.getAttribute('data-copy-cli'), /show .* --span 3333333333333333 --json/); + const data = JSON.parse(execFileSync(binary, ['show', 'widgets#7', '--span', ids.tool, '--json'], { env: { ...process.env, HOME: home }, encoding: 'utf8' })); + assert.equal(data.error, 'test failed'); + await page.getByRole('button', { name: 'Zoom timeline around this call', exact: true }).click(); + assert.match(await page.locator('#span-axis').textContent(), /Timeline zoomed around/); + assert.ok(await tree.locator('.outside-window').count() > 0); + const row = await tool.boundingBox(); + const axis = await page.locator('#span-axis').boundingBox(); + const peek = await page.locator('#peek').boundingBox(); + assert.ok(row.y >= Math.max(0, axis.y + axis.height) - 1); + assert.ok(row.y + row.height <= (width === 390 ? peek.y : 844) + 1); + assert.equal(await page.evaluate(() => document.documentElement.scrollWidth <= innerWidth), true); + assert.equal(await page.locator('#peek-content unsafe, main unsafe').count(), 0); + await page.locator('#span-axis').getByRole('button', { name: 'Zoom out to whole Command' }).click(); + await tool.focus(); + await page.keyboard.press('ArrowLeft'); + assert.equal(await page.evaluate(() => document.activeElement.dataset.spanId), ids.agent); + await page.keyboard.press('ArrowLeft'); + assert.equal(await tree.locator(`[data-span-id="${ids.agent}"]`).getAttribute('aria-expanded'), 'false'); + await page.keyboard.press('ArrowRight'); + await page.keyboard.press('ArrowRight'); + await page.keyboard.press('Enter'); + assert.equal(await tool.getAttribute('aria-selected'), 'true'); + await page.getByRole('button', { name: 'Command details', exact: true }).click(); + await page.locator('#peek-content .facts, #peek-content dl').first().waitFor(); + assert.match(await page.locator('#peek-content').textContent(), /ticket-99/); + await page.keyboard.press('Escape'); + await page.keyboard.press('1'); + await page.waitForURL('**page=inbox'); + } + assert.deepEqual(errors, []); +}); + +test('refresh preserves folds, selected span, zoom and open Peek', async t => { + const context = await browser.newContext(); + t.after(() => context.close()); + const page = await context.newPage(); + await page.goto(`${origin}/waterfall?command=widgets%237`); + await page.locator(`#slowest-calls [data-reveal-span="${ids.model}"]`).click(); + await page.getByRole('button', { name: 'Zoom timeline around this call' }).click(); + await page.locator('#peek-content details').filter({ hasText: /^Output/ }).locator('summary').click(); + const original = await readFile(recordPath, 'utf8'); + const record = JSON.parse(original); + record.issue.title = 'Widgets refreshed'; + if (process.platform === 'linux') { + const stat = await readFile(`/proc/${process.pid}/stat`, 'utf8'); + record.process_id = process.pid; + record.process_start = `${(await readFile('/proc/sys/kernel/random/boot_id', 'utf8')).trim()}:${stat.slice(stat.lastIndexOf(') ') + 2).trim().split(/\s+/)[19]}`; + record.outcome = null; + record.ended_at = null; + } else { + // The observer publishes changes in its Inbox; this old fixture otherwise + // lives only in History. Move it into the recent Done group on other OSes. + record.ended_at = new Date().toISOString(); + } + await writeFile(recordPath, JSON.stringify(record)); + await page.waitForFunction(() => document.querySelector('#span-tree')?.textContent.includes('Widgets refreshed')); + assert.equal(await page.locator(`[data-span-id="${ids.session}"]`).getAttribute('aria-expanded'), 'true'); + assert.equal(await page.locator(`[data-span-id="${ids.model}"]`).getAttribute('aria-selected'), 'true'); + assert.match(await page.locator('#span-axis').textContent(), /Timeline zoomed around/); + assert.equal(await page.locator('#peek').isVisible(), true); + assert.equal(await page.locator('#peek-content details').filter({ hasText: /^Output/ }).getAttribute('open'), ''); + await writeFile(recordPath, original); +}); diff --git a/console/tests/stop.test.cjs b/console/tests/stop.test.cjs index 66775673f..b383e8b2a 100644 --- a/console/tests/stop.test.cjs +++ b/console/tests/stop.test.cjs @@ -72,7 +72,10 @@ for (const requeue of [false, true]) { await page.locator('[data-group="working"] > summary').click(); if (!requeue) await page.getByRole('button', { name: 'Pause motion', exact: true }).click(); } - await page.locator('.peek-link').first().click(); + if (await page.locator('#span-tree').count()) { + await page.locator('.span-row').first().click(); + await page.getByRole('button', { name: 'Command details', exact: true }).click(); + } else await page.locator('.peek-link').first().click(); await page.getByRole('button', { name: 'Stop', exact: true }).waitFor(); } await page.getByRole('button', { name: 'Stop', exact: true }).click(); @@ -83,7 +86,8 @@ for (const requeue of [false, true]) { await page.goto(`${origin}/stop?command=widgets%237`); const observer = await context.newPage(); await observer.goto(`${origin}/waterfall`); - await observer.locator('.peek-link').first().click(); + await observer.locator('.span-row').first().click(); + await observer.getByRole('button', { name: 'Command details', exact: true }).click(); await observer.getByRole('button', { name: 'Stop', exact: true }).waitFor(); assert.equal((await context.request.post(`${origin}/stop`, { form: { command: 'widgets#7', confirmed: 'yes', ending: 'triage' } })).status(), 403); await page.getByRole('button', { name: requeue ? 'Requeue instead' : 'Confirm Stop', exact: true }).click(); diff --git a/console/tests/waterfall.test.cjs b/console/tests/waterfall.test.cjs index c0d118d8b..83889ba94 100644 --- a/console/tests/waterfall.test.cjs +++ b/console/tests/waterfall.test.cjs @@ -78,33 +78,41 @@ test('Waterfall draws overlapping Session-trace spans and running start records' for (const width of [1200, 390]) { await page.setViewportSize({ width, height: 844 }); await page.goto(`${origin}/waterfall?command=widgets%2310`); - const tools = page.locator('.waterfall-tool'); + await page.getByRole('button', { name: 'Every call', exact: true }).click(); + const tools = page.locator('.span-item[data-kind="tool"]'); assert.equal(await tools.count(), 4); - assert.equal(await tools.nth(0).getAttribute('data-start'), '2026-10-01T12:00:15.250+00:00'); - assert.equal(await tools.nth(0).getAttribute('data-seconds'), '3.5'); - assert.equal(await tools.nth(1).getAttribute('data-start'), '2026-10-01T12:00:16.500+00:00'); - assert.equal(await tools.nth(1).getAttribute('data-seconds'), '0.625'); - const track = await tools.nth(0).locator('.timeline').boundingBox(); - const first = await tools.nth(0).locator('.timeline rect').boundingBox(); - const second = await tools.nth(1).locator('.timeline rect').boundingBox(); + const data = await (await context.request.get(`${origin}/spans?command=widgets%2310`)).json(); + const spans = data.spans.filter(span => span.kind === 'tool').sort((a, b) => a.start - b.start); + assert.equal(spans[0].start, Date.parse('2026-10-01T12:00:15.250+00:00')); + assert.equal(spans[0].duration_ms, 3500); + assert.equal(spans[1].start, Date.parse('2026-10-01T12:00:16.500+00:00')); + assert.equal(spans[1].duration_ms, 625); + const track = await tools.nth(0).locator('.span-track').boundingBox(); + const first = await tools.nth(0).locator('.span-bar').boundingBox(); + const second = await tools.nth(1).locator('.span-bar').boundingBox(); assert.ok(Math.abs(first.width - track.width * 3.5 / 60) <= 1.01); assert.ok(Math.abs(second.width - track.width * 0.625 / 60) <= 1.01); assert.ok(Math.abs((first.x - track.x) / track.width - 15.25 / 60) < 0.002); assert.ok(first.x + first.width > second.x); - assert.equal(await tools.nth(2).getAttribute('data-start'), '2026-10-01T12:00:20.125+00:00'); - assert.equal(await tools.nth(2).getAttribute('data-seconds'), ''); + assert.equal(spans[2].start, Date.parse('2026-10-01T12:00:20.125+00:00')); + assert.equal(spans[2].duration_ms, null); assert.match(await tools.nth(2).textContent(), /Time unknown/); assert.equal(await page.locator('main script, main unsafe').count(), 0); assert.equal(await page.evaluate(() => document.documentElement.scrollWidth <= innerWidth), true); if (process.platform === 'linux') { await page.goto(`${origin}/waterfall?command=widgets%239`); - const running = page.locator('.waterfall-tool'); + await page.getByRole('button', { name: 'Every call', exact: true }).click(); + const running = page.locator('.span-item[data-kind="tool"]'); assert.equal(await running.count(), 1); assert.match(await running.textContent(), /still running/); - assert.ok(Date.parse(await running.getAttribute('data-start')) > Date.now() - 120000); - const seconds = Number(await running.getAttribute('data-seconds')); + const live = await (await context.request.get(`${origin}/spans?command=widgets%239`)).json(); + const call = live.spans.find(span => span.kind === 'tool'); + assert.ok(call.start > Date.now() - 120000); + const seconds = (Date.now() - call.start) / 1000; assert.ok(seconds >= 10 && seconds < 120, `${seconds} seconds`); - assert.ok((await running.locator('.timeline rect').boundingBox()).width > 0); + const initial = (await running.locator('.span-duration').textContent()); + await page.waitForFunction(initial => document.querySelector('.span-item[data-kind="tool"] .span-duration')?.textContent !== initial, initial); + assert.ok((await running.locator('.span-bar').boundingBox()).width > 0); } } const recordPath = join(home, '.thirdshift/logs/acme/widgets/commands/issue/10-fixture.command.json'); @@ -115,9 +123,10 @@ test('Waterfall draws overlapping Session-trace spans and running start records' for (const width of [1200, 390]) { await page.setViewportSize({ width, height: 844 }); await page.goto(`${origin}/waterfall?command=widgets%2310`); - assert.match(await page.locator('.waterfall-run h3').textContent(), /died/); + await page.getByRole('button', { name: 'Every call', exact: true }).click(); + assert.match(await page.locator('.command-chips [aria-current]').textContent(), /died/); for (const index of [0, 1]) { - assert.ok((await page.locator('.waterfall-tool .timeline rect').nth(index).boundingBox()).width > 0); + assert.ok((await page.locator('.span-item[data-kind="tool"] .span-bar').nth(index).boundingBox()).width > 0); } } }); @@ -142,15 +151,15 @@ test('Waterfall chips, nested scale and unknown tools work at desktop and 390 px assert.match(await chips.textContent(), /acme\/widgets#8 · died/); if (process.platform === 'linux') assert.match(await chips.textContent(), /acme\/widgets#9 · live/); await chips.getByRole('link', { name: 'acme/widgets#7 · merged' }).click(); - assert.equal(await page.locator('.waterfall-run').count(), 2); - const child = page.locator('.waterfall-run[data-depth="1"]'); - assert.equal(await child.locator('.waterfall-tool').count(), 3); - assert.match(await child.locator('.waterfall-tool').nth(1).textContent(), /Time unknown/); - const track = await child.locator(':scope > .timeline').boundingBox(); - const run = await child.locator(':scope > .timeline rect').boundingBox(); - const stageTrack = await child.locator('.waterfall-stage > .timeline').boundingBox(); - const toolTrack = await child.locator('.waterfall-tool .timeline').first().boundingBox(); - const first = await child.locator('.waterfall-tool .timeline rect').first().boundingBox(); + assert.equal(await page.locator('.span-item[data-kind="run"]').count(), 2); + const child = page.locator('.span-item[data-kind="run"]').nth(1); + assert.equal(await child.locator('.span-item[data-kind="tool"]').count(), 3); + assert.match(await child.locator('.span-item[data-kind="tool"]').last().textContent(), /Time unknown/); + const track = await child.locator(':scope > .span-row > .span-track').boundingBox(); + const run = await child.locator(':scope > .span-row .span-bar').boundingBox(); + const stageTrack = await child.locator('.span-item[data-kind="stage"] > .span-row > .span-track').boundingBox(); + const toolTrack = await child.locator('.span-item[data-kind="tool"] .span-track').first().boundingBox(); + const first = await child.locator('.span-item[data-kind="tool"] .span-bar').first().boundingBox(); assert.ok(Math.abs(run.width - track.width / 2) <= 1.01); assert.ok(Math.abs(first.width - track.width / 4) <= 1.01); assert.ok(Math.abs((first.x - track.x) / track.width - 0.25) < 0.002); @@ -159,7 +168,8 @@ test('Waterfall chips, nested scale and unknown tools work at desktop and 390 px assert.equal(track.width, toolTrack.width); assert.equal(await page.locator('main script, main unsafe').count(), 0); assert.equal(await page.evaluate(() => document.documentElement.scrollWidth <= innerWidth), true); - await child.locator('.peek-link').click(); + await child.locator(':scope > .span-row').click(); + await page.getByRole('button', { name: 'Command details', exact: true }).click(); await page.locator('#peek-content h2').waitFor(); assert.match(await page.locator('#peek-content').textContent(), /ticket-99/); await page.keyboard.press('Escape'); diff --git a/docs/code-navigation.md b/docs/code-navigation.md index 428064693..df0415b17 100644 --- a/docs/code-navigation.md +++ b/docs/code-navigation.md @@ -30,7 +30,8 @@ Start with the issue's terms in `GLOSSARY.md`, then use this index to find their | Silent, Slow, Usual range | `src/logs/reading/health.rs` — health observations and repository stage times; `src/config.rs` — silence threshold and safe waiting interval | `tests/run_health.rs`, `tests/ci.rs` | | Inbox, Needs you | `src/logs/reading/inbox.rs` — local grouping, ordering, clearing and failure collapse; `src/logs/status.rs` — text and JSON | `tests/status.rs`, `tests/security_run.rs` | | Console Lanes and Stages, stage times | `src/logs/status/time.rs` — time views from complete status observations; `src/console/time.rs`, `src/console/time.html` — page rendering | `tests/console.rs`, `console/tests/time.test.cjs` | -| Console Waterfall, tool-call timing | `src/logs/status/waterfall.rs` — retained Run/stage tree and scale; `src/logs/status/waterfall/trace.rs` — span times and running start records; `src/logs/status/waterfall/matching.rs` — legacy scoped Claude/Codex matching; `src/console/waterfall.rs` | `tests/console.rs`, `tests/console/waterfall.rs`, `console/tests/waterfall.test.cjs` | +| Console Waterfall, span tree and details | `src/logs/spans.rs` — shared CLI/Console tree and record-derived ancestry; `src/logs/spans/session.rs` — completed spans and live start records; `src/console/waterfall.rs`; `src/console/assets/spans.js` — folding, ranking, zoom and Peek | `tests/console/spans.rs`, `console/tests/spans.test.cjs` | +| Legacy tool-call timing | `src/logs/status/waterfall.rs` — retained stage placement and estimates; `src/logs/status/waterfall/trace.rs` — measured tool times; `src/logs/status/waterfall/matching.rs` — scoped Claude/Codex matching | `tests/console.rs`, `tests/console/waterfall.rs`, `console/tests/waterfall.test.cjs` | | Command naming, Session selection, show, logs | `src/logs/reading/selection.rs` — resolution, captured outer owner and child-refusal target, Session inventory/selection and bounded latest events, each `--session` word matched by `src/session/kind.rs` — `selects`; `src/logs/status/inspect.rs` — formatting and log streaming | `src/logs/reading/tests.rs`, `tests/show_logs.rs` | | Console Logs page, conversation, log stream, exact log inventory | `src/logs/reading/catalog.rs` — current-layout inventory shared with `logs`; `src/console/logs.rs` — pages and byte-offset SSE; `src/console/conversation.rs` — normalized rendering for all six Harnesses and legacy Claude/Codex logs | `tests/console.rs`, `tests/fixtures/console-*.jsonl`, `console/tests/logs.test.cjs` | | Console account, Console log, sign-in | `src/console/accounts.rs` — durable accounts, sessions, slowdown and account events; `src/console/auth.rs` — HTTP authorization and CSRF; `src/console/account_commands.rs` — CLI; `src/terminal.rs` — shared hidden terminal input | `src/console/accounts/tests.rs`, `tests/console/accounts.rs` | diff --git a/src/args.rs b/src/args.rs index 499887051..1022c22f7 100644 --- a/src/args.rs +++ b/src/args.rs @@ -61,6 +61,11 @@ pub enum Command { command: String, json: bool, }, + Spans { + command: String, + span: Option, + json: bool, + }, Stop { command: String, requeue: bool, @@ -398,6 +403,36 @@ pub fn parse(args: &[String]) -> Result { }); } Some("show") => { + let usage = "usage: thirdshift show [--spans | --span ] [--json]"; + if args.iter().any(|arg| arg == "--spans" || arg == "--span") { + let command = args + .get(1) + .filter(|arg| !arg.starts_with('-')) + .ok_or_else(|| anyhow::anyhow!(usage))?; + let (mut tree, mut span, mut json) = (false, None, false); + let mut flags = args[2..].iter(); + while let Some(flag) = flags.next() { + match flag.as_str() { + "--json" if !json => json = true, + "--spans" if !tree && span.is_none() => tree = true, + "--span" if !tree && span.is_none() => { + span = Some( + flags + .next() + .filter(|id| !id.starts_with('-')) + .ok_or_else(|| anyhow::anyhow!(usage))? + .clone(), + ); + } + _ => bail!(usage), + } + } + return Ok(Command::Spans { + command: command.clone(), + span, + json, + }); + } return match &args[1..] { [command] if !command.starts_with('-') => Ok(Command::Show { command: command.clone(), diff --git a/src/console.rs b/src/console.rs index d5d1905b1..527362a10 100644 --- a/src/console.rs +++ b/src/console.rs @@ -66,6 +66,7 @@ enum View { CronJobs, Inbox, Inspect, + Spans, Log, Changes, Logs, @@ -172,12 +173,22 @@ const PAGES: &[PageRoute] = &[ PageRoute { path: "/waterfall", cli: &[ + "thirdshift show widgets#7 --spans --json", "thirdshift show widgets#7 --json", "thirdshift logs widgets#7", ], method: Method::GET, view: View::Inbox, }, + PageRoute { + path: "/spans", + cli: &[ + "thirdshift show widgets#7 --spans --json", + "thirdshift show widgets#7 --span id --json", + ], + method: Method::GET, + view: View::Spans, + }, PageRoute { path: "/lanes", cli: &["thirdshift status --all --json"], @@ -350,6 +361,7 @@ fn router(no_sign_in: bool, changes: tokio::sync::watch::Receiver) -> Route (View::CronJobs, Method::GET) => get(cronjobs::show), (View::Inbox, Method::GET) => get(move |query| inbox(cli, path, query)), (View::Inspect, Method::GET) => get(inspect), + (View::Spans, Method::GET) => get(waterfall::data), (View::Log, Method::GET) => get(log), (View::Changes, Method::GET) => get(live::events), (View::Logs, Method::GET) => get(logs::index), diff --git a/src/console/assets/console.css b/src/console/assets/console.css index b30449181..d3c196fc8 100644 --- a/src/console/assets/console.css +++ b/src/console/assets/console.css @@ -116,12 +116,6 @@ header::after { content: ""; display: block; height: 4px; background: var(--acti .command-chips { display: flex; flex-wrap: wrap; gap: 8px; margin: 16px 0; } .command-chips a { border: 1px solid var(--rule); border-radius: var(--radius); padding: 6px; overflow-wrap: anywhere; } .command-chips [aria-current] { outline: 2px solid var(--head); } -.waterfall-run { border-left: 2px solid var(--rule); padding-left: 8px; margin: 16px 0; overflow-wrap: anywhere; } -.waterfall-run[data-depth="1"] > .command { padding-left: 12px; } -.waterfall-run[data-depth="2"] > .command { padding-left: 24px; } -.waterfall-stages, .waterfall-stages ol { list-style: none; padding-left: 0; } -.waterfall-stage > h4, .waterfall-stage > p { margin-left: 12px; } -.waterfall-tool > a, .waterfall-tool > p { margin-left: 24px; } .stage-grid { width: 100%; table-layout: fixed; border-collapse: collapse; margin: 20px 0; } .stage-grid caption { text-align: left; font-weight: var(--head-weight); } .stage-grid th, .stage-grid td { border: 1px solid var(--rule); padding: 8px; text-align: left; vertical-align: top; overflow-wrap: anywhere; } diff --git a/src/console/assets/console.js b/src/console/assets/console.js index 0ddff7d3f..da12312d5 100644 --- a/src/console/assets/console.js +++ b/src/console/assets/console.js @@ -1,5 +1,7 @@ import { activity, loadLook, motionAllowed } from './look.js'; import { watchCommands } from './changes.js'; +import { initSpanTree } from './spans.js'; +let spanTree; // Browser preferences are conveniences; malformed or unavailable storage hides nothing. function stored(key, fallback) { @@ -119,11 +121,14 @@ function morphTimePage(html) { async function refresh() { if (observesCommands) { - const response = await fetch(timePage ? location.href : '/', { cache: "no-store" }); - if (!response.ok) throw new Error("Inbox unavailable"); - const html = await response.text(); - if (timePage) morphTimePage(html); - else morph(html); + if (spanTree) await spanTree.refresh(); + else { + const response = await fetch(timePage ? location.href : '/', { cache: "no-store" }); + if (!response.ok) throw new Error("Inbox unavailable"); + const html = await response.text(); + if (timePage) morphTimePage(html); + else morph(html); + } } await refreshPeek(); } @@ -148,6 +153,18 @@ let selected = null; let peekCommand = null; let pendingPeek = null; +spanTree = initSpanTree({ + openDetails() { + peekCommand = null; + pendingPeek?.abort(); + pendingPeek = null; + }, + openCommand: span => { + peekCommand = null; + togglePeek({ dataset: { command: span.command, peek: span.command_url } }); + } +}); + function select(element, { scroll = true } = {}) { selected?.classList.remove('is-selected'); selected?.removeAttribute('aria-current'); @@ -158,6 +175,7 @@ function select(element, { scroll = true } = {}) { } function closePeek() { + spanTree?.closeDetails(); stopPeekUpdates(); pendingPeek?.abort(); pendingPeek = null; diff --git a/src/console/assets/spans.css b/src/console/assets/spans.css new file mode 100644 index 000000000..34cd5fecd --- /dev/null +++ b/src/console/assets/spans.css @@ -0,0 +1,67 @@ +.span-controls, .span-actions { display: flex; flex-wrap: wrap; align-items: center; gap: 6px; margin: 10px 0; } +#span-axis, .span-row { display: grid; grid-template-columns: minmax(0, 2fr) 7ch minmax(0, 3fr); gap: 8px; align-items: center; } +#span-axis { position: sticky; top: 0; z-index: 2; background: var(--bg); border-bottom: 1px solid var(--rule); padding: 8px 0; font: 11px var(--font-mono); color: var(--dim); } +#span-ticks { position: relative; height: 16px; margin-right: 2px; } +#span-ticks span { position: absolute; white-space: nowrap; transform: translateX(-50%); } +#span-ticks span:first-child { transform: none; } +#span-ticks span:last-child { transform: translateX(-100%); } +#span-zoom { grid-column: 1 / -1; display: flex; flex-wrap: wrap; gap: 6px; align-items: center; padding: 6px; border: 1px solid var(--look); color: var(--text); } +#span-zoom b { max-width: 100%; overflow: hidden; text-overflow: ellipsis; white-space: nowrap; } +.span-item { outline: none; } +.span-item:focus > .span-row { outline: 2px solid var(--head); outline-offset: -2px; } +.span-row { padding: 5px 0; border-bottom: 1px solid var(--rule); cursor: pointer; font-size: 13px; } +.span-row:hover { background: var(--panel); } +.span-label { display: flex; align-items: center; gap: 4px; min-width: 0; padding-left: calc(var(--span-depth) * 12px); white-space: nowrap; } +.span-name { min-width: 0; overflow: hidden; text-overflow: ellipsis; } +.span-kind, .span-duration, .span-rank, .span-fold-hint { font: 11px var(--font-mono); } +.span-kind { color: var(--dim); } +.span-twist { width: 16px; flex: none; text-align: center; } +.span-duration { text-align: right; } +.span-rank { border: 1px solid var(--look); padding: 0 3px; color: var(--look-text); border-radius: var(--radius); } +.span-fold-hint { color: var(--urgent-text); flex-shrink: 0; } +.span-status-error { color: var(--urgent-text); } +.span-status-running { color: var(--working-text); } +.span-track { display: block; position: relative; height: 10px; background: var(--panel-2); overflow: hidden; } +.span-bar { display: block; position: absolute; top: 0; bottom: 0; width: 0; background: var(--working); } +.span-bar.kind-model, .span-bar.kind-turn { background: var(--link); } +.span-bar.kind-agent { background: var(--look); } +.span-bar.kind-cmd, .span-bar.kind-run, .span-bar.kind-stage { background: var(--dim); } +.span-bar.span-error { background: var(--urgent); } +.span-bar.span-running { background-image: repeating-linear-gradient(120deg, transparent 0 6px, var(--bg) 6px 8px); } +.span-bar.span-estimate { border: 2px dotted var(--text); } +.span-bar.span-slow { outline: 2px solid var(--look); outline-offset: -2px; } +.outside-window { opacity: .45; } +#slowest-calls { border: 1px solid var(--rule); padding: 4px 10px; margin-bottom: 12px; border-radius: var(--radius); background: var(--panel); } +#slowest-calls summary { font-size: 14px; } +#slowest-calls ol { list-style: none; margin: 0; padding: 0; max-height: 260px; overflow: auto; } +#slowest-calls li + li { border-top: 1px solid var(--rule); } +#slowest-calls button { display: grid; grid-template-columns: auto minmax(0, 1fr) auto 7ch; align-items: baseline; gap: 2px 8px; width: 100%; text-align: left; border: 0; padding: 6px 0; background: transparent; cursor: pointer; } +.slow-name { overflow: hidden; text-overflow: ellipsis; white-space: nowrap; font-size: 13px; } +.slow-clock, .slow-duration { font: 11px var(--font-mono); } +.slow-duration { text-align: right; } +.slow-where { grid-column: 2 / -1; color: var(--dim); font-size: 12px; } +.span-path { font-size: 11px; gap: 2px 8px; margin: 4px 0; } +.span-path a + a::before { content: '› '; color: var(--dim); } +.span-card h2 { font-size: 18px; overflow-wrap: anywhere; } +.span-card pre { white-space: pre-wrap; overflow-wrap: anywhere; max-height: 40dvh; overflow: auto; padding: 8px; background: var(--bg); border: 1px solid var(--rule); } +.span-card summary { font-size: 14px; } +.span-tiles { display: grid; grid-template-columns: repeat(auto-fit, minmax(100px, 1fr)); gap: 8px; margin: 10px 0; } +.span-tile { padding: 8px; border: 1px solid var(--rule); border-radius: var(--radius); background: var(--bg); } +.span-tile b, .span-tile span { display: block; } +.span-tile b { font-size: 18px; } +.span-tile span { color: var(--dim); } +.span-position { margin: 8px 0; } +.span-overview { width: 100%; table-layout: fixed; border-collapse: collapse; } +.span-overview th, .span-overview td { text-align: left; vertical-align: top; overflow-wrap: anywhere; padding: 4px; border-bottom: 1px solid var(--rule); } +@media (max-width: 760px) { + #span-axis, .span-row { grid-template-columns: minmax(0, 1fr) 7ch; gap: 4px 6px; } + #span-axis > span { display: none; } + #span-ticks { grid-column: 1; } + .span-label { grid-column: 1 / -1; padding-left: calc(var(--span-depth) * 8px); } + .span-row > .span-track { grid-row: 2; grid-column: 1; height: 6px; } + .span-duration { grid-row: 2; grid-column: 2; } + #slowest-calls button { grid-template-columns: auto minmax(0, 1fr) 7ch; } + .slow-name { grid-column: 2 / -1; } + .slow-clock { grid-column: 2; } + .slow-duration { grid-column: 3; } +} diff --git a/src/console/assets/spans.js b/src/console/assets/spans.js new file mode 100644 index 000000000..228c857e2 --- /dev/null +++ b/src/console/assets/spans.js @@ -0,0 +1,298 @@ +// The reader shared with `show --spans` owns trace interpretation and ancestry. +function el(tag, className, text) { + const node = document.createElement(tag); + if (className) node.className = className; + if (text !== undefined) node.textContent = text; + return node; +} +function duration(ms) { + if (ms === null || !Number.isFinite(ms)) return 'Time unknown'; + if (ms < 1000) return `${Math.round(ms * 1000) / 1000} ms`; + const seconds = ms / 1000; + if (seconds < 60) return `${Math.round(seconds * 100) / 100} s`; + if (seconds < 3600) return `${Math.floor(seconds / 60)}m ${Math.floor(seconds % 60)}s`; + return `${Math.floor(seconds / 3600)}h ${Math.floor(seconds % 3600 / 60)}m`; +} +function clock(ms) { return ms === null ? 'unknown' : new Date(ms).toLocaleTimeString([], { hour12: false }); } +function pretty(text) { + if (text === null || text === undefined) return 'No text retained.'; + try { return JSON.stringify(JSON.parse(text), null, 2); } catch { return text; } +} +const quote = text => `'${text.replaceAll("'", "'\\''")}'`; +const kindName = { cmd: 'Command', run: 'Run', stage: 'stage', sess: 'session', model: 'model call', tool: 'tool call', turn: 'turn', agent: 'sub-agent' }; + +export function initSpanTree({ openCommand, openDetails }) { + const tree = document.getElementById('span-tree'); + if (!tree) return null; + let data = JSON.parse(document.getElementById('span-data').textContent); + let nodes, children, roots, axis, ranks, descendants; + const expanded = new Map(); + let selected = data.spans[0]?.id, detail = null, zoom = null; + const content = document.getElementById('peek-content'); + const peek = document.getElementById('peek'); + const header = document.getElementById('span-axis'); + const slow = document.querySelector('#slowest-calls ol'); + const status = document.getElementById('span-status'); + const end = span => span.status === 'running' ? Date.now() : span.end; + const elapsed = span => span.status === 'running' && span.start !== null ? Math.max(0, Date.now() - span.start) : span.duration_ms; + const durationText = span => `${duration(elapsed(span))}${span.estimated ? '*' : ''}`; + const rowFor = id => document.getElementById(`span-${id}`); + const isOpen = span => expanded.get(span.id) ?? ['cmd', 'run', 'stage'].includes(span.kind); + const inScope = span => span.start !== null && end(span) !== null && end(span) >= axis.start && span.start <= axis.end; + const button = (text, action) => { + const node = el('button', '', text); + node.type = 'button'; + node.addEventListener('click', action); + return node; + }; + function ancestors(span) { + const path = [], seen = new Set([span.id]); + while (nodes.has(span.parent_id) && !seen.has(span.parent_id)) { + span = nodes.get(span.parent_id); + seen.add(span.id); + path.unshift(span); + } + return path; + } + function index() { + nodes = new Map(data.spans.map(span => [span.id, span])); + children = new Map(); roots = []; + for (const span of data.spans) { + if (nodes.has(span.parent_id)) { + if (!children.has(span.parent_id)) children.set(span.parent_id, []); + children.get(span.parent_id).push(span); + } else roots.push(span); + } + for (const list of children.values()) list.sort((a, b) => (a.start ?? Infinity) - (b.start ?? Infinity)); + if (!nodes.has(selected)) selected = roots[0]?.id; + if (!nodes.has(detail)) detail = null; + if (!nodes.has(zoom)) zoom = null; + } + function wholeAxis() { + const starts = data.spans.map(span => span.start).filter(time => time !== null); + const ends = data.spans.map(span => end(span) ?? span.start).filter(time => time !== null); + const start = starts.length ? Math.min(...starts) : Date.now(); + return { start, end: Math.max(start + 1, ...ends) }; + } + function setAxis() { + axis = wholeAxis(); + const span = nodes.get(zoom); + if (!span || span.start === null) return; + const finish = end(span) ?? span.start; + if (children.has(span.id)) axis = { start: span.start, end: Math.max(finish, span.start + 1) }; + else { + const parent = nodes.get(span.parent_id), pad = Math.max(elapsed(span) ?? 0, 1000) * 1.5; + axis = { start: Math.max(parent?.start ?? axis.start, span.start - pad), end: Math.min(parent ? end(parent) ?? Date.now() : axis.end, finish + pad) }; + if (axis.end <= axis.start) axis = { start: span.start - pad, end: finish + pad }; + } + } + function rankCalls() { + const calls = data.spans.filter(span => ['tool', 'model'].includes(span.kind) && elapsed(span) !== null && inScope(span)) + .sort((a, b) => elapsed(b) - elapsed(a) || a.id.localeCompare(b.id)).slice(0, 10); + ranks = new Map(calls.map((span, i) => [span.id, i + 1])); + descendants = new Map(data.spans.map(span => [span.id, { errors: 0, ranks: [] }])); + for (const span of data.spans) for (const parent of ancestors(span)) { + const summary = descendants.get(parent.id); + if (span.error !== null) summary.errors++; + if (ranks.has(span.id)) summary.ranks.push(ranks.get(span.id)); + } + const fragment = document.createDocumentFragment(); + for (const span of calls) { + const li = el('li'), reveal = button('', () => revealSpan(span.id)); + reveal.dataset.revealSpan = span.id; + reveal.append(el('span', 'span-rank', `#${ranks.get(span.id)}`), el('span', 'slow-name', `${span.kind} · ${span.name}`), el('span', 'slow-clock', `${clock(span.start)} → ${span.status === 'running' ? 'now' : clock(span.end)}`), el('span', 'slow-duration', durationText(span))); + const parent = nodes.get(span.parent_id); + const fraction = parent && elapsed(parent) > 0 ? `${Math.round(elapsed(span) / elapsed(parent) * 100)}% of its ${kindName[parent.kind]}` : 'Parent duration unknown'; + reveal.append(el('span', 'slow-where', `${fraction}${span.run ? ` · #${span.run}` : ''}${span.session_kind ? ` · ${span.session_kind} session` : ''}`)); + li.append(reveal); fragment.append(li); + } + if (!calls.length) fragment.append(el('li', '', 'No timed tool or model calls in this window.')); + slow.replaceChildren(fragment); + } + function bar(span, range = axis) { + const track = el('span', 'span-track'); + const fill = el('i', `span-bar kind-${span.kind}${span.error !== null ? ' span-error' : ''}${span.status === 'running' ? ' span-running' : ''}${span.estimated ? ' span-estimate' : ''}${ranks.has(span.id) ? ' span-slow' : ''}`); + if (span.start !== null && end(span) !== null) { + const scale = 100 / Math.max(1, range.end - range.start); + const left = Math.min(100, Math.max(0, (span.start - range.start) * scale)); + const width = Math.min(100 - left, Math.max(0, (Math.min(end(span), range.end) - Math.max(span.start, range.start)) * scale)); + fill.style.left = `${left}%`; fill.style.width = `${width}%`; + } else fill.style.width = '0'; + track.append(fill); return track; + } + function renderTree() { + const focused = tree.contains(document.activeElement) ? document.activeElement.closest('[data-span-id]')?.dataset.spanId : null; + function item(span, depth, position, count, path) { + if (path.has(span.id)) return document.createDocumentFragment(); + const nextPath = new Set(path).add(span.id), nested = children.get(span.id) ?? [], open = isOpen(span); + const wrapper = el('div', 'span-item'); + wrapper.id = `span-${span.id}`; wrapper.dataset.spanId = span.id; wrapper.dataset.kind = span.kind; + wrapper.setAttribute('role', 'treeitem'); wrapper.setAttribute('aria-level', depth + 1); + wrapper.setAttribute('aria-labelledby', `span-label-${span.id}`); + wrapper.setAttribute('aria-posinset', position + 1); wrapper.setAttribute('aria-setsize', count); + wrapper.setAttribute('aria-selected', span.id === selected); wrapper.tabIndex = span.id === selected ? 0 : -1; + if (nested.length) wrapper.setAttribute('aria-expanded', open); + const row = el('div', `span-row${span.id === selected ? ' is-selected' : ''}${zoom && !inScope(span) ? ' outside-window' : ''}`); + const label = el('span', 'span-label'); label.id = `span-label-${span.id}`; label.style.setProperty('--span-depth', depth); + const twist = el('span', 'span-twist', nested.length ? open ? '▾' : '▸' : '·'); + twist.setAttribute('aria-hidden', 'true'); twist.dataset.discloseSpan = span.id; + label.append(twist, el('span', 'span-kind', span.kind)); + if (ranks.has(span.id)) label.append(el('span', 'span-rank', `#${ranks.get(span.id)}`)); + const name = el('span', 'span-name', span.name); name.title = span.name; label.append(name); + if (span.error !== null || span.status === 'running') { + const mark = el('span', span.error !== null ? 'span-status-error' : 'span-status-running', span.error !== null ? '✕' : '●'); + mark.title = span.error ?? 'running'; mark.setAttribute('aria-label', span.error ?? 'running'); label.append(mark); + } + if (!open && nested.length) { + const summary = descendants.get(span.id); + if (summary.errors) label.append(el('span', 'span-fold-hint', `${summary.errors} error${summary.errors === 1 ? '' : 's'}`)); + if (summary.ranks.length) label.append(el('span', 'span-fold-hint', summary.ranks.sort((a, b) => a - b).map(rank => `#${rank}`).join(' '))); + } + row.append(label, el('span', 'span-duration', durationText(span)), bar(span)); wrapper.append(row); + if (open && nested.length) { + const group = el('div', 'span-children'); group.setAttribute('role', 'group'); + nested.forEach((child, i) => group.append(item(child, depth + 1, i, nested.length, nextPath))); wrapper.append(group); + } + return wrapper; + } + tree.replaceChildren(...roots.map((span, i) => item(span, 0, i, roots.length, new Set()))); + if (focused) rowFor(focused)?.focus({ preventScroll: true }); + } + function renderAxis() { + document.getElementById('span-ticks').replaceChildren(...[0, 0.5, 1].map(fraction => { + const tick = el('span', '', `+${duration((axis.end - axis.start) * fraction)}`); tick.style.left = `${fraction * 100}%`; return tick; + })); + const notice = document.getElementById('span-zoom'); notice.hidden = !zoom; notice.replaceChildren(); + if (zoom) notice.append(el('b', '', `Timeline zoomed around ${nodes.get(zoom).name}: ${clock(axis.start)} → ${clock(axis.end)} (${duration(axis.end - axis.start)})`), button('Zoom out to whole Command', () => zoomTo(null))); + } + function render() { setAxis(); rankCalls(); renderAxis(); renderTree(); if (detail) renderDetails(); } + function centerRow(id) { + requestAnimationFrame(() => { + const row = rowFor(id)?.querySelector(':scope > .span-row'); if (!row) return; + const top = Math.max(0, header.getBoundingClientRect().bottom); + const bottom = innerWidth <= 760 && !peek.hidden ? peek.getBoundingClientRect().top : innerHeight; + const rect = row.getBoundingClientRect(); + window.scrollBy({ top: rect.top + rect.height / 2 - (top + bottom) / 2, behavior: 'instant' }); + }); + } + function choose(id, focus = true) { selected = id; renderTree(); if (focus) rowFor(id)?.focus({ preventScroll: true }); } + function revealSpan(id) { + const span = nodes.get(id); if (!span) return; + ancestors(span).forEach(parent => expanded.set(parent.id, true)); choose(id); detail = id; renderDetails(); centerRow(id); + } + function zoomTo(id) { zoom = id; render(); centerRow(selected); } + function renderDetails() { + const span = nodes.get(detail); if (!span) return; + openDetails(); + const folds = new Map([...content.querySelectorAll('details')].map(node => [node.dataset.detailSection, node.open])); + const sameSpan = content.dataset.spanId === span.id, scroll = sameSpan ? peek.scrollTop : 0; + content.dataset.spanId = span.id; + const card = el('article', 'span-card'), path = el('nav', 'span-path'); path.setAttribute('aria-label', 'Span ancestors'); + for (const parent of ancestors(span)) { + const link = el('a', '', parent.name); link.href = `#span-${parent.id}`; + link.addEventListener('click', event => { event.preventDefault(); revealSpan(parent.id); }); path.append(link); + } + card.append(path, el('h2', '', `${span.kind} · ${span.name}`), el('p', '', `${span.status}${span.error !== null ? ` · ${span.error}` : ''} · ${clock(span.start)} → ${span.status === 'running' ? 'now' : clock(span.end)}${span.estimated ? ' · estimated*' : ''}`)); + const tiles = el('div', 'span-tiles'); + const tile = (label, value) => { + if (value === null || value === undefined) return; + const node = el('div', 'span-tile'); node.append(el('b', '', String(value)), el('span', '', label)); tiles.append(node); + }; + tile('Duration', elapsed(span) === null ? null : durationText(span)); + const parent = nodes.get(span.parent_id); + if (parent && elapsed(parent) > 0 && elapsed(span) !== null) tile(`% of its ${kindName[parent.kind]}`, `${Math.round(elapsed(span) / elapsed(parent) * 100)}%`); + const attrs = span.attributes; + tile('Tokens in', attrs['gen_ai.usage.input_tokens']); tile('Tokens out', attrs['gen_ai.usage.output_tokens']); tile('Cost (USD)', attrs['thirdshift.cost.usd']); + const nested = data.spans.filter(child => ancestors(child).some(parent => parent.id === span.id)); + for (const [kind, label] of [['model', 'Model calls'], ['tool', 'Tool calls']]) { + const count = nested.filter(child => child.kind === kind).length; if (count) tile(label, count); + } + const errors = descendants.get(span.id).errors + (span.error !== null ? 1 : 0); if (errors) tile('Errors', errors); + card.append(tiles); + for (const [label, owner] of [['Within parent', parent], ['Within Command', roots[0]]]) { + if (owner && owner.start !== null && end(owner) !== null) { + const position = el('div', 'span-position', label); position.append(bar(span, { start: owner.start, end: end(owner) })); card.append(position); + } + } + const actions = el('div', 'span-actions'); + const zoomButton = button(zoom ? 'Zoom out to whole Command' : children.has(span.id) ? `Zoom timeline to this ${kindName[span.kind]}` : 'Zoom timeline around this call', () => zoomTo(zoom ? null : span.id)); + zoomButton.disabled = span.start === null; actions.append(zoomButton); + if (span.conversation_url) { const link = el('a', '', 'Open in conversation'); link.href = span.conversation_url; actions.append(link); } + const cli = `thirdshift show ${quote(data.command)} --span ${span.id} --json`; + const copy = button('Copy CLI', async () => { + try { await navigator.clipboard.writeText(cli); status.textContent = 'CLI copied.'; } catch { status.textContent = cli; } + }); + copy.dataset.copyCli = cli; actions.append(copy, button('Command details', () => { detail = null; openCommand(span); })); card.append(actions); + function section(label, body, open = false) { + const disclosure = el('details'); disclosure.dataset.detailSection = label; + disclosure.open = sameSpan ? folds.get(label) ?? open : open; + disclosure.append(el('summary', '', label), body); card.append(disclosure); + } + const noModelText = span.kind === 'model' || span.kind === 'turn'; + section('Input', el('pre', '', noModelText ? 'The text is in the conversation view.' : pretty(span.input)), true); + section('Output', el('pre', '', noModelText ? 'The text is in the conversation view.' : pretty(span.output))); + section('All attributes', el('pre', '', JSON.stringify(attrs, null, 2))); + const table = el('table', 'span-overview'), body = el('tbody'); + const overview = { Kind: kindName[span.kind], Status: span.status, Start: span.start === null ? 'unknown' : new Date(span.start).toISOString(), End: span.status === 'running' ? 'now' : span.end === null ? 'unknown' : new Date(span.end).toISOString(), Model: attrs['gen_ai.response.model'] ?? attrs['gen_ai.request.model'], Harness: attrs['thirdshift.harness'], 'Tokens in': attrs['gen_ai.usage.input_tokens'], 'Tokens out': attrs['gen_ai.usage.output_tokens'], 'Cache read': attrs['thirdshift.usage.cache_read_tokens'], 'Cache write': attrs['thirdshift.usage.cache_write_tokens'], 'Cost (USD)': attrs['thirdshift.cost.usd'], 'Span ID': span.id }; + for (const [key, value] of Object.entries(overview)) { + if (value === undefined || value === null) continue; + const row = el('tr'); row.append(el('th', '', key), el('td', '', String(value))); body.append(row); + } + table.append(body); section('Overview table', table); content.replaceChildren(card); + peek.hidden = false; document.body.classList.add('peek-open'); peek.scrollTop = scroll; + } + tree.addEventListener('click', event => { + const row = event.target.closest('.span-row'); if (!row) return; + const id = row.parentElement.dataset.spanId; + if (event.target.closest('[data-disclose-span]') && children.has(id)) { expanded.set(id, !isOpen(nodes.get(id))); choose(id); } + else revealSpan(id); + }); + tree.addEventListener('focusin', event => { + const id = event.target.closest('[data-span-id]')?.dataset.spanId; + if (id && selected !== id) { + selected = id; + for (const node of tree.querySelectorAll('[role="treeitem"]')) { + node.tabIndex = node.dataset.spanId === id ? 0 : -1; node.setAttribute('aria-selected', node.dataset.spanId === id); + node.querySelector(':scope > .span-row').classList.toggle('is-selected', node.dataset.spanId === id); + } + } + }); + tree.addEventListener('keydown', event => { + const span = nodes.get(selected); if (!span || event.altKey || event.ctrlKey || event.metaKey) return; + const visible = [...tree.querySelectorAll('[role="treeitem"]')].map(node => node.dataset.spanId), index = visible.indexOf(selected); + let target; + switch (event.key) { + case 'ArrowDown': case 'j': target = visible[Math.min(index + 1, visible.length - 1)]; break; + case 'ArrowUp': case 'k': target = visible[Math.max(0, index - 1)]; break; + case 'Home': target = visible[0]; break; + case 'End': target = visible.at(-1); break; + case 'ArrowRight': + if (children.has(selected)) { if (isOpen(span)) target = children.get(selected)[0].id; else { expanded.set(selected, true); renderTree(); } } + break; + case 'ArrowLeft': + if (children.has(selected) && isOpen(span)) { expanded.set(selected, false); renderTree(); } else target = span.parent_id; + break; + case 'Enter': case ' ': revealSpan(selected); break; + default: return; + } + event.preventDefault(); event.stopPropagation(); + if (target) { choose(target); centerRow(target); } + }); + for (const control of document.querySelectorAll('[data-expand]')) control.addEventListener('click', () => { + const level = control.dataset.expand; + for (const span of nodes.values()) expanded.set(span.id, level === 'all' || span.kind === 'cmd' || (['stage', 'sess'].includes(level) && span.kind === 'run') || (level === 'sess' && span.kind === 'stage')); + const folded = ancestors(nodes.get(selected)).find(parent => !isOpen(parent)); if (folded) selected = folded.id; + render(); + }); + index(); render(); + const timer = setInterval(() => { if (data.spans.some(span => span.status === 'running')) render(); }, 1000); + window.addEventListener('pagehide', () => clearInterval(timer), { once: true }); + return { + closeDetails() { detail = null; delete content.dataset.spanId; }, + async refresh() { + const response = await fetch(`/spans?${new URLSearchParams({ command: data.command })}`, { cache: 'no-store' }); + if (!response.ok) throw new Error('Span tree unavailable'); + data = await response.json(); index(); render(); + } + }; +} diff --git a/src/console/waterfall.html b/src/console/waterfall.html index e08e45ee7..9b6338f36 100644 --- a/src/console/waterfall.html +++ b/src/console/waterfall.html @@ -6,34 +6,27 @@ Waterfall · {{ page.hostname }} · thirdshift {% include "console/header.html" %} {% include "console/nav.html" %} -
    -

    Waterfall

    thirdshift show <command> --json · thirdshift logs <command>
    +
    +

    Waterfall

    thirdshift show <command> --spans --json · thirdshift logs <command>
    - {% if view.runs.is_empty() %}

    No Commands yet.

    {% else %} -

    Shared time axis: {{ view.start }} to {{ view.end }}. Session traces use measured tool spans; running calls extend from their start record to now. Old Session logs estimate intervals until the next matched call or stage boundary, including waiting. Unknown durations have no bar.

    - {% for run in view.runs %} -
    -

    {{ run.kind }} · {{ run.subject }} · {{ run.state }}

    {{ run.title }}

    - -

    {{ run.span.start }} · {{ run.span.text }}

    - {% if run.stages.is_empty() %}

    No stage times retained.

    {% endif %} -
      {% for stage in run.stages %} -

    1. {{ stage.name }}

      {{ stage.span.start }} · {{ stage.span.text }}

      - -
        {% for tool in stage.tools %}
      1. {{ tool.label }}

        {{ tool.span.start }} · {{ tool.span.text }}

        - -
        2. {% endfor %}
      -
      2. - {% endfor %}
    -
    - {% endfor %} + {% if view.tree.spans.is_empty() %}

    No Commands yet.

    {% else %} +

    One shared time axis. * marks estimated times. Running calls extend to now.

    +
    Slowest calls
      +
      + Expand to +
      +
      SpanDuration
      +
      +

      {% endif %} +
      {% include "console/chrome.html" %} diff --git a/src/console/waterfall.rs b/src/console/waterfall.rs index ac3a59480..c2b7558fd 100644 --- a/src/console/waterfall.rs +++ b/src/console/waterfall.rs @@ -1,28 +1,55 @@ //! One selected Command, using the same retained tree and logs as show/logs. use anyhow::Result; use askama::Template; -use axum::response::Response; +use axum::extract::RawQuery; +use axum::response::{IntoResponse, Response}; use crate::config::UserConfig; -use crate::logs::status::waterfall::{self, View}; +use crate::logs::spans::{self, View}; #[derive(Template)] #[template(path = "console/waterfall.html")] struct WaterfallPage { page: super::PageContext, view: View, + data: String, } pub(super) async fn show(query: Option) -> Response { super::page( tokio::task::spawn_blocking(move || -> Result { let config = UserConfig::load()?; + let view = spans::load(&config, &super::query_value(&query, "command"))?; + // JSON is data, never executable markup, even inside a script tag. + let data = serde_json::to_string(&view.tree)? + .replace('&', "\\u0026") + .replace('<', "\\u003c") + .replace('>', "\\u003e"); Ok(WaterfallPage { page: super::PageContext::new(&config), - view: waterfall::load(&config, &super::query_value(&query, "command"))?, + view, + data, } .render()?) }) .await, ) } + +pub(super) async fn data(RawQuery(query): RawQuery) -> Response { + match tokio::task::spawn_blocking(move || -> Result { + let view = spans::load(&UserConfig::load()?, &super::query_value(&query, "command"))?; + let selected = super::query_value(&query, "span"); + Ok(if selected.is_empty() { + serde_json::to_value(view.tree)? + } else { + serde_json::to_value(view.tree.span(&selected)?)? + }) + }) + .await + { + Ok(Ok(value)) => axum::Json(value).into_response(), + Ok(Err(error)) => (axum::http::StatusCode::BAD_REQUEST, error.to_string()).into_response(), + Err(_) => axum::http::StatusCode::INTERNAL_SERVER_ERROR.into_response(), + } +} diff --git a/src/logs.rs b/src/logs.rs index 497faeaa5..4f125016e 100644 --- a/src/logs.rs +++ b/src/logs.rs @@ -22,6 +22,7 @@ mod reading; pub(crate) use reading::catalog; mod recording; pub(crate) mod session; +pub(crate) mod spans; pub mod status; pub mod stop; pub(crate) mod trace; diff --git a/src/logs/session.rs b/src/logs/session.rs index e25c06ede..0cfa98720 100644 --- a/src/logs/session.rs +++ b/src/logs/session.rs @@ -3,7 +3,40 @@ use std::fs::File; use std::io::{self, Read, Seek, SeekFrom}; use std::path::{Path, PathBuf}; -use crate::otlp_jsonl::{AnyValue, LogRecord, Logs, Reader}; +use crate::otlp_jsonl::{AnyValue, LogRecord, Logs, Reader, Request}; + +/// A live append may expose only part of its last request. Completed malformed +/// lines remain errors; readers retry an incomplete final request on refresh. +pub(in crate::logs) fn read_requests(path: &Path) -> anyhow::Result>> { + use anyhow::Context; + let bytes = match std::fs::read(path) { + Ok(bytes) => bytes, + Err(error) if error.kind() == io::ErrorKind::NotFound => return Ok(None), + Err(error) => return Err(error).with_context(|| format!("can't read {}", path.display())), + }; + let mut reader = Reader::new(bytes.as_slice()).peekable(); + let mut requests = Vec::new(); + while let Some(result) = reader.next() { + match result { + Ok(request) => requests.push(request), + Err(error) + if !bytes.ends_with(b"\n") + && reader.peek().is_none() + && error + .get_ref() + .and_then(|error| error.downcast_ref::()) + .is_some_and(serde_json::Error::is_eof) => + { + break; + } + Err(error) => { + return Err(error) + .with_context(|| format!("can't read Session trace {}", path.display())); + } + } + } + Ok(Some(requests)) +} /// Command records may still name the old Session log during the transition. pub(crate) fn path(log: &Path) -> PathBuf { diff --git a/src/logs/spans.rs b/src/logs/spans.rs new file mode 100644 index 000000000..ad0374f38 --- /dev/null +++ b/src/logs/spans.rs @@ -0,0 +1,416 @@ +//! One retained span tree for the CLI and Console. Presentation never has to +//! recover record ancestry, match Harness events, or deduplicate Sessions. +mod session; + +use std::collections::{BTreeMap, BTreeSet}; +use std::path::PathBuf; + +use anyhow::{Context as _, Result, bail}; +use chrono::{DateTime, Local}; +use serde::Serialize; +use serde_json::Value; + +use super::reading::{Command, Entry, Observation, Snapshot}; +use super::status::{inspect, waterfall}; +use super::trace::{Context, id}; +use crate::config::UserConfig; + +#[derive(Clone, Serialize)] +pub(crate) struct Span { + pub id: String, + pub parent_id: Option, + pub kind: String, + pub name: String, + pub start: Option, + pub end: Option, + pub duration_ms: Option, + pub status: String, + pub error: Option, + pub estimated: bool, + pub attributes: BTreeMap, + pub input: Option, + pub output: Option, + pub command: String, + pub command_url: String, + pub conversation_url: Option, + pub run: Option, + pub session_kind: Option, +} + +#[derive(Serialize)] +pub(crate) struct Tree { + pub command: String, + pub spans: Vec, + pub now: f64, +} + +#[derive(Serialize)] +pub(crate) struct Choice { + pub subject: String, + pub state: String, + pub url: String, + pub selected: bool, +} + +pub(crate) struct View { + pub choices: Vec, + pub tree: Tree, +} + +pub(crate) fn show(input: &str, selected: Option<&str>, json: bool) -> Result<()> { + let view = load(&UserConfig::load()?, input)?; + if let Some(selected) = selected { + let span = view.tree.span(selected)?; + if json { + println!("{}", serde_json::to_string_pretty(span)?); + } else { + println!("{} {} · {}", span.kind, span.name, span.status); + println!("{}", serde_json::to_string_pretty(span)?); + } + } else if json { + println!("{}", serde_json::to_string_pretty(&view.tree)?); + } else { + for span in &view.tree.spans { + println!("{} {} {} · {}", span.id, span.kind, span.name, span.status); + } + } + Ok(()) +} + +impl Tree { + pub(crate) fn span(&self, selected: &str) -> Result<&Span> { + self.spans + .iter() + .find(|span| span.id == selected) + .with_context(|| format!("span {selected} is not in this Command")) + } +} + +pub(crate) fn load(config: &UserConfig, input: &str) -> Result { + let now = Local::now(); + let snapshot = Snapshot::load_with_silence(&config.logs_dir, now, config.silent_interval)?; + let mut commands: Vec<_> = snapshot + .entries() + .iter() + .filter_map(|entry| match entry { + Entry::Record(command) => Some(command.as_ref()), + _ => None, + }) + .collect(); + commands.sort_by_key(|command| { + ( + command.state != "live", + std::cmp::Reverse(time(&command.record.started_at)), + ) + }); + let (selected, owner) = if input.is_empty() { + (commands.first().copied(), commands.first().copied()) + } else { + let selection = snapshot.resolve(input)?; + match selection.observation { + Observation::Record(command) => (Some(command), selection.owner.or(Some(command))), + _ => bail!("span tree requires a Command record"), + } + }; + let selector = selected + .and_then(|command| Observation::Record(command).selector()) + .unwrap_or_default(); + let choices = commands + .iter() + .map(|command| { + let choice = Observation::Record(command).selector().unwrap_or_default(); + Choice { + subject: subject(command), + state: state(command), + url: inspect::url("/waterfall", &choice, None), + selected: choice == selector, + } + }) + .collect(); + let mut tree = Tree { + command: selector, + spans: Vec::new(), + now: now.timestamp_millis() as f64, + }; + if let (Some(command), Some(owner)) = (selected, owner) { + let context = Context::of_session(&owner.command_log); + let root = record_span(command, hex(context.command), None, "cmd", &tree.command); + tree.spans.push(root); + let mut builder = Builder { + context, + sessions: BTreeSet::new(), + log: waterfall::matching::Log::read( + &owner.command_log, + DateTime::parse_from_rfc3339(&owner.record.started_at)?, + )?, + now: now.fixed_offset(), + spans: &mut tree.spans, + }; + let mut relays = Vec::new(); + relay_path(owner, command, &mut relays); + builder.record(command, hex(builder.context.command), &relays)?; + } + Ok(View { choices, tree }) +} + +struct Builder<'a> { + context: Context, + sessions: BTreeSet, + log: waterfall::matching::Log, + now: DateTime, + spans: &'a mut Vec, +} + +impl Builder<'_> { + fn record(&mut self, command: &Command, parent: String, relays: &[u64]) -> Result<()> { + let context = self.context.for_record(&command.record); + let selector = Observation::Record(command).selector().unwrap_or_default(); + let run_id = hex(context.run); + self.spans.push(record_span( + command, + run_id.clone(), + Some(parent), + "run", + &selector, + )); + let stages: Vec<_> = command.record.stage_times(None).collect(); + for (index, timing) in stages.iter().enumerate() { + let mut span = record_span( + command, + hex(context.stage_id(timing.stage)), + Some(run_id.clone()), + "stage", + &selector, + ); + span.name = timing.stage.name.clone(); + span.start = timing.began.map(|time| time.timestamp_millis() as f64); + span.end = timing.ended.map(|time| time.timestamp_millis() as f64); + span.status = if span.end.is_some() { + "ok" + } else if command.state == "live" { + "running" + } else { + "unknown" + } + .into(); + span.error = None; + if index + 1 == stages.len() && command.record.cause.is_some() { + span.error.clone_from(&command.record.cause); + span.status = "error".into(); + } + span.duration_ms = duration(span.start, span.end); + self.spans.push(span); + } + for path in Observation::Record(command).sessions()? { + let original = super::session::original(&path); + if !self.sessions.insert(original.clone()) { + continue; + } + let stage = stages.iter().find(|timing| { + timing + .stage + .session_log + .as_deref() + .is_some_and(|reference| super::session::original(reference) == original) + }); + let parent = stage.map_or_else( + || run_id.clone(), + |timing| hex(context.stage_id(timing.stage)), + ); + let mut template = record_span(command, String::new(), Some(parent), "sess", &selector); + template.start = stage + .and_then(|timing| timing.began) + .map(|time| time.timestamp_millis() as f64) + .or(template.start); + template.input = None; + template.conversation_url = Some(inspect::url("/log", &selector, Some(&path))); + if let Some(mut spans) = session::read(&path, &context, &template)? { + if spans.iter().any(|span| { + span.attributes.get("thirdshift.migration") + == Some(&Value::String("legacy".into())) + }) { + let (calls, measured) = + waterfall::session_calls(&path, command, relays, &mut self.log)?; + let placed = waterfall::place_calls(&path, command, &calls, measured, self.now); + for span in spans.iter_mut().filter(|span| span.kind == "tool") { + let call = span + .attributes + .get("gen_ai.tool.call.id") + .and_then(Value::as_str); + let parent = span + .attributes + .get("thirdshift.parent_id") + .and_then(Value::as_str); + if let Some(timing) = placed.iter().find(|timing| { + timing.identity.as_ref().is_some_and(|(scope, id)| { + Some(id.as_str()) == call && scope.as_deref() == parent + }) + }) { + span.start = timing.start.map(|time| time.timestamp_millis() as f64); + span.end = timing.end.map(|time| time.timestamp_millis() as f64); + span.duration_ms = duration(span.start, span.end); + span.estimated = true; + } + } + } + self.spans.extend(spans); + } else { + // Old logs retain their scoped estimates without pretending to + // contain Sessions or measured model calls they never recorded. + let (calls, measured) = + waterfall::session_calls(&path, command, relays, &mut self.log)?; + for (index, call) in + waterfall::place_calls(&path, command, &calls, measured, self.now) + .into_iter() + .enumerate() + { + let mut span = template.clone(); + span.id = hex(id(&[ + &context.run.0, + original.as_os_str().as_encoded_bytes(), + &index.to_be_bytes(), + ])); + span.parent_id = call + .stage + .map(|index| hex(context.stage_id(stages[index].stage))) + .or(Some(run_id.clone())); + span.kind = "tool".into(); + span.name = call.label; + span.start = call.start.map(|time| time.timestamp_millis() as f64); + span.end = call.end.map(|time| time.timestamp_millis() as f64); + span.duration_ms = duration(span.start, span.end); + span.status = if span.end.is_some() { "ok" } else { "unknown" }.into(); + span.error = None; + span.estimated = true; + self.spans.push(span); + } + } + } + for child in command.dispatched.iter().chain(&command.children) { + let parent = stages.iter().rev().find(|timing| { + timing.began.is_some_and(|began| { + time(&child.record.started_at) + .is_some_and(|start| start >= began.timestamp_millis()) + }) + }); + let parent = parent.map_or_else( + || run_id.clone(), + |timing| hex(context.stage_id(timing.stage)), + ); + let mut child_relays = relays.to_vec(); + if command + .children + .iter() + .any(|entry| std::ptr::eq(entry, child)) + && let Some(issue) = &child.record.issue + { + child_relays.push(issue.number); + } + self.record(child, parent, &child_relays)?; + } + Ok(()) + } +} + +fn record_span( + command: &Command, + id: String, + parent_id: Option, + kind: &str, + selector: &str, +) -> Span { + let start = time(&command.record.started_at).map(|time| time as f64); + let end = command + .record + .ended_at + .as_deref() + .and_then(time) + .map(|time| time as f64); + Span { + id, + parent_id, + kind: kind.into(), + name: format!( + "{} · {}{}", + command.record.kind, + subject(command), + command + .record + .issue + .as_ref() + .and_then(|issue| issue.title.as_ref()) + .map(|title| format!(" · {title}")) + .unwrap_or_default() + ), + start, + end, + duration_ms: duration(start, end), + status: state(command), + error: command.record.cause.clone(), + estimated: false, + attributes: BTreeMap::new(), + input: None, + output: None, + command: selector.into(), + command_url: inspect::url("/peek", selector, None), + conversation_url: None, + run: command.record.issue.as_ref().map(|issue| issue.number), + session_kind: None, + } +} + +fn subject(command: &Command) -> String { + command + .record + .issue + .as_ref() + .map(|issue| format!("{}#{}", command.record.repository, issue.number)) + .unwrap_or_else(|| command.record.name.clone()) +} + +fn state(command: &Command) -> String { + command.record.outcome.clone().unwrap_or_else(|| { + if command.state == "live" { + "running" + } else { + command.state + } + .into() + }) +} + +fn relay_path(command: &Command, selected: &Command, path: &mut Vec) -> bool { + if std::ptr::eq(command, selected) { + return true; + } + for child in command.dispatched.iter().chain(&command.children) { + let length = path.len(); + if command + .children + .iter() + .any(|entry| std::ptr::eq(entry, child)) + && let Some(issue) = &child.record.issue + { + path.push(issue.number); + } + if relay_path(child, selected, path) { + return true; + } + path.truncate(length); + } + false +} + +fn time(value: &str) -> Option { + DateTime::parse_from_rfc3339(value) + .ok() + .map(|time| time.timestamp_millis()) +} +fn duration(start: Option, end: Option) -> Option { + start + .zip(end) + .and_then(|(start, end)| (end >= start).then_some(end - start)) +} +fn hex(id: crate::otlp_jsonl::SpanId) -> String { + id.0.iter().map(|byte| format!("{byte:02x}")).collect() +} diff --git a/src/logs/spans/session.rs b/src/logs/spans/session.rs new file mode 100644 index 000000000..ee62c5b1f --- /dev/null +++ b/src/logs/spans/session.rs @@ -0,0 +1,361 @@ +//! Merge ended OTLP spans with normalized start records for live Sessions. +use std::collections::{BTreeMap, HashMap}; +use std::path::Path; + +use anyhow::{Context as _, Result}; +use serde_json::Value; + +use super::{Span, duration, hex}; +use crate::logs::trace::{Context, id}; +use crate::otlp_jsonl::{AnyValue, KeyValue, Logs, Spans}; + +pub(super) fn read(path: &Path, context: &Context, template: &Span) -> Result>> { + let original = crate::logs::session::original(path); + let requests = + crate::logs::session::read_requests::(&original.with_extension("spans.jsonl"))?; + let logs = crate::logs::session::read_requests::(&original.with_extension("logs.jsonl"))?; + if requests.is_none() && logs.is_none() { + return Ok(None); + } + let mut completed = Vec::new(); + let mut resource_attrs = BTreeMap::new(); + for request in requests.into_iter().flatten() { + for resource in request.resource_spans { + let attrs = resource + .resource + .map(|resource| attributes(&resource.attributes)) + .unwrap_or_default(); + resource_attrs.extend(attrs.clone()); + for raw in resource + .scope_spans + .into_iter() + .flat_map(|scope| scope.spans) + { + let mut attrs = attrs.clone(); + attrs.extend(attributes(&raw.attributes)); + let mut span = template.clone(); + span.id = hex(raw.span_id.unwrap_or_else(|| { + id(&[ + &context.run.0, + original.as_os_str().as_encoded_bytes(), + raw.name.as_bytes(), + &raw.start_time_unix_nano.to_be_bytes(), + ]) + })); + span.parent_id = raw.parent_span_id.map(hex); + span.kind = kind(&attrs).into(); + span.name = raw.name; + span.start = millis(raw.start_time_unix_nano); + span.end = millis(raw.end_time_unix_nano); + span.duration_ms = raw + .end_time_unix_nano + .checked_sub(raw.start_time_unix_nano) + .filter(|_| raw.start_time_unix_nano != 0 && raw.end_time_unix_nano != 0) + .map(|nanos| nanos as f64 / 1_000_000.0); + span.error = raw + .status + .as_ref() + .filter(|status| status.code == 2) + .map(|status| status.message.clone()); + span.status = if span.error.is_some() { + "error" + } else if span.end.is_some() { + "ok" + } else if template.status == "running" { + "running" + } else { + "unknown" + } + .into(); + apply_attributes(&mut span, attrs); + completed.push(span); + } + } + } + let session_id = completed + .iter() + .find(|span| span.kind == "sess") + .map(|span| span.id.clone()) + .unwrap_or_else(|| { + hex(id(&[ + &context.trace.0, + b"session", + original.as_os_str().as_encoded_bytes(), + ])) + }); + let session_bytes: crate::otlp_jsonl::SpanId = + serde_json::from_value(Value::String(session_id.clone()))?; + let mut session = completed + .iter() + .find(|span| span.kind == "sess") + .cloned() + .unwrap_or_else(|| { + let mut session = template.clone(); + session.id = session_id.clone(); + session.name = "Session".into(); + session.error = None; + session + }); + // A shared Session belongs to the first stage naming it, even when an old + // trace points at the later pull-request stage that reused that Session. + session.parent_id.clone_from(&template.parent_id); + let mut calls = BTreeMap::new(); + let mut locations = HashMap::new(); + let identities: HashMap<_, _> = completed + .iter() + .filter_map(|span| { + let call = span + .attributes + .get("gen_ai.tool.call.id") + .or_else(|| span.attributes.get("thirdshift.id"))? + .as_str()?; + let parent = span + .attributes + .get("thirdshift.parent_id") + .and_then(Value::as_str); + Some(( + serde_json::to_string(&(&span.kind, parent, call)).unwrap(), + span.id.clone(), + )) + }) + .collect(); + let mut first_record = None::; + for request in logs.into_iter().flatten() { + for resource in request.resource_logs { + resource_attrs.extend( + resource + .resource + .map(|resource| attributes(&resource.attributes)) + .unwrap_or_default(), + ); + for record in resource + .scope_logs + .into_iter() + .flat_map(|scope| scope.log_records) + { + let attrs = attributes(&record.attributes); + let start = millis(record.time_unix_nano) + .or_else(|| millis(record.observed_time_unix_nano)); + first_record = match (first_record, start) { + (Some(a), Some(b)) => Some(a.min(b)), + (a, b) => a.or(b), + }; + let Some(events) = attrs.get("thirdshift.events").and_then(Value::as_str) else { + continue; + }; + let events: Vec = + serde_json::from_str(events).context("invalid Session-trace events")?; + for event in events { + let event_type = event["type"].as_str().unwrap_or_default(); + let call_kind = match event_type { + "tool_call_started" | "tool_call_ended" => "tool", + "model_call_started" | "model_call_ended" => "model", + "turn_started" | "turn_ended" => "turn", + "subagent_started" | "subagent_ended" => "agent", + _ => continue, + }; + let Some(call) = event["id"].as_str() else { + continue; + }; + let parent = event["parent_id"].as_str(); + let key = serde_json::to_string(&(call_kind, parent, call))?; + let call_id = if call_kind == "agent" && event_type.ends_with("_ended") { + locations + .get(call) + .cloned() + .unwrap_or_else(|| hex(id(&[&session_bytes.0, key.as_bytes()]))) + } else { + identities + .get(&key) + .cloned() + .unwrap_or_else(|| hex(id(&[&session_bytes.0, key.as_bytes()]))) + }; + let parent_id = parent + .and_then(|parent| locations.get(parent).cloned()) + .unwrap_or_else(|| session_id.clone()); + locations.insert(call.to_owned(), call_id.clone()); + let span = calls.entry(call_id.clone()).or_insert_with(|| { + let mut span = template.clone(); + span.id = call_id; + span.parent_id = Some(parent_id); + span.kind = call_kind.into(); + span.name = format!("{call_kind} {call}"); + span.start = start; + span.end = None; + span.duration_ms = None; + span.error = None; + span.status = if template.status == "running" { + "running" + } else { + "unknown" + } + .into(); + span.attributes.clear(); + span + }); + let mut own_attrs = resource_attrs.clone(); + own_attrs.insert("thirdshift.type".into(), Value::String(event_type.into())); + for (key, value) in event.as_object().into_iter().flatten() { + if !value.is_null() { + own_attrs.insert(format!("thirdshift.{key}"), value.clone()); + } + } + if call_kind == "tool" { + own_attrs.insert("gen_ai.tool.name".into(), event["tool"].clone()); + if !event["input"].is_null() { + own_attrs.insert( + "gen_ai.tool.call.arguments".into(), + event["input"].clone(), + ); + } + if !event["result"].is_null() { + own_attrs + .insert("gen_ai.tool.call.result".into(), event["result"].clone()); + } + } + if event["model"].is_string() { + own_attrs.insert("gen_ai.response.model".into(), event["model"].clone()); + } + if attrs.get("thirdshift.time.estimated") == Some(&Value::Bool(true)) { + own_attrs.insert("thirdshift.time.estimated".into(), Value::Bool(true)); + } + span.attributes.extend(own_attrs.clone()); + apply_attributes(span, span.attributes.clone()); + if event_type.ends_with("_ended") { + span.end = span.end.or(start); + span.duration_ms = duration(span.start, span.end); + if event["outcome"] != "succeeded" { + span.status = "error".into(); + span.error = Some( + event["outcome"] + .as_str() + .unwrap_or("call did not end") + .into(), + ); + } else { + span.status = "ok".into(); + } + } + } + } + } + } + if !completed.iter().any(|span| span.kind == "sess") { + session.start = first_record.or(session.start); + session.duration_ms = duration(session.start, session.end); + apply_attributes(&mut session, resource_attrs); + } + for mut span in completed.into_iter().filter(|span| span.kind != "sess") { + if span.parent_id.is_none() { + span.parent_id = Some(session_id.clone()); + } + calls.insert(span.id.clone(), span); + } + let mut spans = vec![session]; + for mut span in calls.into_values() { + if span.session_kind.is_none() { + span.session_kind.clone_from(&spans[0].session_kind); + } + // Broken or missing causal references should not hide retained evidence. + if span + .parent_id + .as_ref() + .is_none_or(|parent| parent == &span.id) + { + span.parent_id = Some(session_id.clone()); + } + spans.push(span); + } + let ids: std::collections::HashSet<_> = spans.iter().map(|span| span.id.clone()).collect(); + for span in spans.iter_mut().skip(1) { + if span + .parent_id + .as_ref() + .is_none_or(|parent| !ids.contains(parent)) + { + span.parent_id = Some(session_id.clone()); + } + } + Ok(Some(spans)) +} + +fn kind(attrs: &BTreeMap) -> &'static str { + match attrs.get("gen_ai.operation.name").and_then(Value::as_str) { + Some("invoke_agent") => "sess", + Some("execute_tool") => "tool", + Some("chat") => "model", + _ => match attrs + .get("thirdshift.type") + .and_then(Value::as_str) + .unwrap_or_default() + { + value if value.starts_with("subagent_") => "agent", + value if value.starts_with("turn_") => "turn", + _ => "model", + }, + } +} + +fn apply_attributes(span: &mut Span, attrs: BTreeMap) { + span.estimated = attrs + .get("thirdshift.time.estimated") + .is_some_and(|value| value == &Value::Bool(true) || value == "true"); + span.session_kind = text(&attrs, "thirdshift.session.kind").or(span.session_kind.clone()); + span.input = text(&attrs, "gen_ai.tool.call.arguments") + .or_else(|| text(&attrs, "thirdshift.session.prompt")) + .or_else(|| text(&attrs, "thirdshift.description")); + span.output = + text(&attrs, "gen_ai.tool.call.result").or_else(|| text(&attrs, "thirdshift.result")); + if span.kind == "tool" + && let Some(tool) = text(&attrs, "gen_ai.tool.name") + { + span.name = format!( + "{tool}{}", + span.input + .as_ref() + .map(|input| format!(" {input}")) + .unwrap_or_default() + ); + } + span.attributes = attrs; +} + +fn text(attrs: &BTreeMap, key: &str) -> Option { + attrs + .get(key) + .filter(|value| !value.is_null()) + .map(|value| { + value + .as_str() + .map(str::to_owned) + .unwrap_or_else(|| value.to_string()) + }) +} + +fn millis(nanos: u64) -> Option { + (nanos != 0).then_some((nanos / 1_000_000) as f64 + (nanos % 1_000_000) as f64 / 1_000_000.0) +} + +fn attributes(attrs: &[KeyValue]) -> BTreeMap { + attrs + .iter() + .filter_map(|attr| { + attr.value + .as_ref() + .map(|value| (attr.key.clone(), value_json(value))) + }) + .collect() +} + +fn value_json(value: &AnyValue) -> Value { + match value { + AnyValue::Empty => Value::Null, + AnyValue::String(value) => Value::String(value.clone()), + AnyValue::Bool(value) => Value::Bool(*value), + AnyValue::Int(value) => Value::from(*value), + AnyValue::Double(value) => Value::from(*value), + AnyValue::Array(values) => Value::Array(values.iter().map(value_json).collect()), + AnyValue::Map(values) => Value::Object(attributes(values).into_iter().collect()), + AnyValue::Bytes(value) => Value::from(value.clone()), + } +} diff --git a/src/logs/status/waterfall.rs b/src/logs/status/waterfall.rs index 7b482830a..1ab61fca1 100644 --- a/src/logs/status/waterfall.rs +++ b/src/logs/status/waterfall.rs @@ -3,54 +3,15 @@ pub(in crate::logs) mod matching; mod trace; use anyhow::Result; -use chrono::{DateTime, FixedOffset, Local}; +use chrono::{DateTime, FixedOffset}; -use crate::config::UserConfig; -use crate::logs::reading::{Command, Entry, Observation, Snapshot}; +use crate::logs::reading::Command; type Time = DateTime; -pub(crate) struct View { - pub choices: Vec, - pub runs: Vec, - pub start: String, - pub end: String, -} - -pub(crate) struct Choice { - pub subject: String, - pub state: String, - pub url: String, - pub selected: bool, -} - -pub(crate) struct Run { - pub subject: String, - pub kind: String, - pub title: String, - pub state: String, - pub selector: String, - pub peek_url: String, - pub log_url: String, - pub depth: usize, - pub span: Span, - pub stages: Vec, -} - -pub(crate) struct Stage { - pub name: String, - pub span: Span, - pub tools: Vec, -} - -pub(crate) struct Tool { - pub label: String, - pub span: Span, - pub url: String, -} - #[derive(PartialEq)] pub(in crate::logs) struct Call { + pub(in crate::logs) identity: Option<(Option, String)>, pub(in crate::logs) label: String, pub(in crate::logs) start: Option
      ") - .unwrap() - .0 - .to_owned() - }; - let old = conversation(reader()); - fs::write( - path.with_extension("logs.jsonl"), - support::session_trace::records(fixture), - ) - .unwrap(); - fs::write(&path, "Old log must not be rendered\n").unwrap(); - assert_eq!(conversation(reader()), old, "{kind}"); - fs::remove_file(&path).unwrap(); - assert_eq!(conversation(reader()), old, "trace without old log: {kind}"); - } -} - #[test] fn all_six_harness_session_traces_render_normalized_conversations() { let home = tempfile::tempdir().unwrap(); @@ -1441,8 +1236,8 @@ fn child_runs_nest_and_each_request_reads_current_records() { write_record(home.path(), 8, &child); let child_log = home .path() - .join(".thirdshift/logs/acme/widgets/commands/issue/8-fixture-implement.jsonl"); - fs::write(&child_log, "Ticket Session output\n").unwrap(); + .join(".thirdshift/logs/acme/widgets/commands/issue/8-fixture-implement.logs.jsonl"); + support::session_trace::write(&child_log, "Ticket Session output\n"); child["session_log"] = json!(child_log); write_record(home.path(), 8, &child); let console = Console::start(Path::new(env!("CARGO_BIN_EXE_thirdshift")), home.path()); @@ -1451,12 +1246,12 @@ fn child_runs_nest_and_each_request_reads_current_records() { .split("href=\"") .skip(1) .filter_map(|part| part.split_once('"')) - .find(|(_, label)| label.starts_with(">Run and Session logs")) + .find(|(_, label)| label.starts_with(">Run and Session traces")) .unwrap() .0; let parent_logs = console.get(parent_link).text().unwrap(); assert!( - parent_logs.contains("8-fixture-implement.jsonl"), + parent_logs.contains("8-fixture-implement.logs.jsonl"), "{parent_logs}" ); let nested = html.split("class=\"children\"").nth(1).expect(&html); @@ -1548,8 +1343,8 @@ fn replacing_the_binary_executes_the_replacement_with_the_original_arguments() { live["process_start"] = json!(format!("{}:{ticks}", boot.trim())); let log = home .path() - .join(".thirdshift/logs/acme/widgets/commands/issue/7-fixture-implement.jsonl"); - fs::write(&log, "initial line\n").unwrap(); + .join(".thirdshift/logs/acme/widgets/commands/issue/7-fixture-implement.logs.jsonl"); + support::session_trace::write(&log, "initial line\n"); live["session_log"] = json!(log); write_record(home.path(), 7, &live); let inventory = console.get("/logs").text().unwrap(); diff --git a/tests/console/codex_patches.rs b/tests/console/codex_patches.rs index 1046f15e8..3ce09a9ef 100644 --- a/tests/console/codex_patches.rs +++ b/tests/console/codex_patches.rs @@ -111,7 +111,7 @@ fn page(scenario: &support::Scenario) -> String { .as_array() .unwrap() .iter() - .find(|log| log["kind"] == "Session log") + .find(|log| log["kind"] == "Session trace") .unwrap()["id"] .as_str() .unwrap(); diff --git a/tests/console/spans.rs b/tests/console/spans.rs index 06b51fb38..c19061529 100644 --- a/tests/console/spans.rs +++ b/tests/console/spans.rs @@ -22,7 +22,7 @@ fn span_tree_and_details_pair_cli_with_routes_and_nest_child_runs() { let dir = home .path() .join(".thirdshift/logs/acme/widgets/commands/issue"); - let session = dir.join("99-20261001T120000+0000-implement.jsonl"); + let session = dir.join("99-20261001T120000+0000-implement.logs.jsonl"); let mut child = parent.clone(); child["kind"] = json!("Run"); child["name"] = json!("ticket-99"); @@ -38,9 +38,9 @@ fn span_tree_and_details_pair_cli_with_routes_and_nest_child_runs() { serde_json::to_vec(&child).unwrap(), ) .unwrap(); - fs::write(session.with_extension("logs.jsonl"), "").unwrap(); + fs::write(support::session_trace::artifact(&session, "logs.jsonl"), "").unwrap(); let attr = |key: &str, value: &str| json!({"key":key,"value":{"stringValue":value}}); - fs::write(session.with_extension("spans.jsonl"), serde_json::to_vec(&json!({ + fs::write(support::session_trace::artifact(&session, "spans.jsonl"), serde_json::to_vec(&json!({ "resourceSpans":[{"scopeSpans":[{"spans":[ {"spanId":"1111111111111111","name":"invoke_agent implement","startTimeUnixNano":"1790856010000000000","endTimeUnixNano":"1790856050000000000","attributes":[attr("gen_ai.operation.name","invoke_agent"),attr("thirdshift.session.prompt","Build widgets")]}, {"spanId":"2222222222222222","parentSpanId":"1111111111111111","name":"agent reviewer","startTimeUnixNano":"1790856015000000000","endTimeUnixNano":"1790856040000000000","attributes":[attr("thirdshift.type","subagent_started"),attr("thirdshift.description","Review widgets")]}, diff --git a/tests/console/waterfall.rs b/tests/console/waterfall.rs index 6265c0e83..6f589897a 100644 --- a/tests/console/waterfall.rs +++ b/tests/console/waterfall.rs @@ -16,51 +16,16 @@ fn start_console(home: &Path, value: &Value) -> Console { Console::start(Path::new(env!("CARGO_BIN_EXE_thirdshift")), home) } -#[test] -fn converted_session_keeps_its_waterfall_stage_and_duration_after_cleanup() { - let home = tempfile::tempdir().unwrap(); - let dir = home - .path() - .join(".thirdshift/logs/acme/widgets/commands/issue"); - let session = dir.join("7-20261001T120000+0000-implement.jsonl"); - let mut value = retained_command(home.path(), &session); - value["harness"] = json!("codex"); - value["stages"] = json!([ - {"name":"implement","began_at":value["started_at"],"session_log":session}, - {"name":"review","began_at":"2026-10-01T12:00:05.500Z","session_log":null} - ]); - fs::write(&session, "{\"type\":\"item.completed\",\"item\":{\"id\":\"c1\",\"type\":\"command_execution\",\"command\":\"cargo test\",\"status\":\"completed\",\"exit_code\":0}}\n").unwrap(); - fs::write(dir.join("7-fixture.log"), "thirdshift: 12:00:00 starting\nthirdshift: 12:00:05 implement: $ cargo test\nthirdshift: 12:01:00 finished\n").unwrap(); - let console = start_console(home.path(), &value); - let before = span_tree(&console, "widgets%237"); - assert_eq!(tool_spans(&before)[0]["start"], 1790856005000.0); - assert_eq!(tool_spans(&before)[0]["duration_ms"], 500.0); - for flag in ["--convert", "--remove-converted"] { - let output = Command::new(env!("CARGO_BIN_EXE_thirdshift")) - .args(["logs", flag]) - .env("HOME", home.path()) - .output() - .unwrap(); - assert!(output.status.success(), "{output:?}"); - } - assert!(!session.exists()); - let after = span_tree(&console, "widgets%237"); - assert_eq!(tool_spans(&after)[0]["start"], 1790856005000.0); - assert_eq!(tool_spans(&after)[0]["duration_ms"], 500.0); - assert_eq!(tool_spans(&after)[0]["estimated"], true); -} - #[test] fn waterfall_reads_start_records_without_spans_and_ignores_an_unfinished_tail() { let home = tempfile::tempdir().unwrap(); let dir = home .path() .join(".thirdshift/logs/acme/widgets/commands/issue"); - let session = dir.join("7-20261001T120000+0000-implement.jsonl"); + let session = dir.join("7-20261001T120000+0000-implement.logs.jsonl"); let value = retained_command(home.path(), &session); - fs::write(&session, "{\"type\":\"item.completed\",\"item\":{\"id\":\"legacy\",\"type\":\"command_execution\",\"command\":\"wrong\",\"status\":\"completed\"}}\n").unwrap(); fs::write( - session.with_extension("logs.jsonl"), + &session, format!( "{}{{\"resourceLogs\":", include_str!("../fixtures/waterfall-logs.jsonl") @@ -137,11 +102,11 @@ fn waterfall_uses_session_trace_spans_instead_of_command_log_guesses() { let dir = home .path() .join(".thirdshift/logs/acme/widgets/commands/issue"); - let session = dir.join("7-20261001T120000+0000-implement.jsonl"); + let session = dir.join("7-20261001T120000+0000-implement.logs.jsonl"); let mut value = retained_command(home.path(), &session); fs::write(&session, "").unwrap(); fs::write( - session.with_extension("spans.jsonl"), + session.with_file_name("7-20261001T120000+0000-implement.spans.jsonl"), include_str!("../fixtures/waterfall-spans.jsonl"), ) .unwrap(); @@ -171,7 +136,7 @@ fn waterfall_uses_session_trace_spans_instead_of_command_log_guesses() { spans["resourceSpans"][0]["scopeSpans"][0]["spans"][1]["endTimeUnixNano"] = json!("1790856016500500000"); fs::write( - session.with_extension("spans.jsonl"), + session.with_file_name("7-20261001T120000+0000-implement.spans.jsonl"), serde_json::to_vec(&spans).unwrap(), ) .unwrap(); diff --git a/tests/continuation.rs b/tests/continuation.rs index d5f569e97..f0d25cfcc 100644 --- a/tests/continuation.rs +++ b/tests/continuation.rs @@ -103,7 +103,7 @@ fn assert_nothing_created(scenario: &Scenario, local_branch: &str) { scenario .log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl") .is_empty(), - "a session log was created" + "a session trace was created" ); assert_ne!(scenario.launch_git(&["branch", "--list", local_branch]), ""); } diff --git a/tests/convert_logs.rs b/tests/convert_logs.rs deleted file mode 100644 index e7b9f1786..000000000 --- a/tests/convert_logs.rs +++ /dev/null @@ -1,416 +0,0 @@ -mod support; - -use std::fs; -use std::path::{Path, PathBuf}; - -use serde_json::{Value, json}; -use support::Scenario; - -const STAMP: &str = "20261001T120000+0000"; - -fn fixture(scenario: &Scenario, harness: &str, raw: &str) -> PathBuf { - let folder = scenario.path(&format!( - "home/.thirdshift/logs/acme/{harness}/commands/secure" - )); - fs::create_dir_all(&folder).unwrap(); - let session = folder.join(format!("secure-{STAMP}-security-audit.jsonl")); - let command = folder.join(format!("{STAMP}.log")); - fs::write(&session, raw).unwrap(); - fs::write(&command, "thirdshift: 12:00:00 starting\nthirdshift: 12:00:05 security-audit: $ cargo test\nthirdshift: 12:01:00 finished\n").unwrap(); - fs::write( - session.with_extension("models.json"), - serde_json::to_vec(&json!({ - "command_log":command,"kind":"security-audit","harness":harness, - "requested":null,"effort":null,"observed":[] - })) - .unwrap(), - ) - .unwrap(); - session -} - -fn report(scenario: &Scenario) -> Value { - serde_json::from_slice( - &fs::read(scenario.path("home/.thirdshift/logs/session-trace-conversion.json")).unwrap(), - ) - .unwrap() -} - -fn records(path: &Path) -> Vec { - fs::read_to_string(path) - .unwrap() - .lines() - .flat_map(|line| { - let request: Value = serde_json::from_str(line).unwrap(); - request["resourceLogs"][0]["scopeLogs"][0]["logRecords"] - .as_array() - .unwrap() - .clone() - }) - .collect() -} - -#[test] -fn converts_all_six_harnesses_with_round_trip_report_and_no_duplicates() { - let scenario = Scenario::new(); - let fixtures = [ - ("claude", include_str!("fixtures/console-claude.jsonl")), - ("codex", include_str!("fixtures/console-codex.jsonl")), - ("agy", include_str!("fixtures/normalized-agy.jsonl")), - ("grok", include_str!("fixtures/normalized-grok.jsonl")), - ("muse", include_str!("fixtures/normalized-muse.jsonl")), - ( - "opencode", - include_str!("fixtures/normalized-opencode.jsonl"), - ), - ]; - let paths: Vec<_> = fixtures - .iter() - .map(|(harness, raw)| fixture(&scenario, harness, raw)) - .collect(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let report = report(&scenario); - assert_eq!(report["sessions"].as_array().unwrap().len(), 6, "{report}"); - for entry in report["sessions"].as_array().unwrap() { - assert_eq!(entry["passed"], true, "{entry}"); - for reader in ["conversation", "waterfall", "show", "model_evidence"] { - assert_eq!(entry["readers"][reader], true, "{entry}"); - } - } - for ((_, raw), path) in fixtures.iter().zip(&paths) { - assert_eq!(fs::read_to_string(path).unwrap(), *raw); - let logs = records(&path.with_extension("logs.jsonl")); - let bodies: Vec<_> = logs - .iter() - .map(|r| r["body"]["stringValue"].as_str().unwrap()) - .collect(); - assert_eq!(bodies, raw.lines().collect::>()); - for (raw, record) in raw.lines().zip(&logs) { - let raw: Value = serde_json::from_str(raw).unwrap_or_default(); - let estimated = ["timestamp", "recorded_at", "time"] - .iter() - .all(|key| raw.get(key).is_none()); - assert!( - record["attributes"].as_array().unwrap().iter().any(|a| { - a["key"] == "thirdshift.time.estimated" && a["value"]["boolValue"] == estimated - }), - "{record}" - ); - } - assert!(path.with_extension("spans.jsonl").is_file()); - } - let before: Vec<_> = paths - .iter() - .map(|p| fs::read(p.with_extension("logs.jsonl")).unwrap()) - .collect(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!(result.stdout.contains("Converted 0"), "{}", result.stdout); - for (path, before) in paths.iter().zip(before) { - assert_eq!(fs::read(path.with_extension("logs.jsonl")).unwrap(), before); - } -} - -#[test] -fn cleanup_removes_only_passed_unchanged_originals() { - let scenario = Scenario::new(); - let raw = include_str!("fixtures/console-claude.jsonl"); - let good = fixture(&scenario, "claude", raw); - let changed = fixture(&scenario, "codex", raw); - let damaged = fixture(&scenario, "grok", raw); - let failed = fixture(&scenario, "unknown", "unrecognized old output\n"); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let report = report(&scenario); - let sessions = report["sessions"].as_array().unwrap(); - assert_eq!( - sessions.iter().filter(|s| s["passed"] == true).count(), - 3, - "{report}" - ); - assert_eq!( - sessions.iter().filter(|s| s["passed"] == false).count(), - 1, - "{report}" - ); - fs::write(&changed, "new original\n").unwrap(); - fs::write(damaged.with_extension("spans.jsonl"), "broken trace\n").unwrap(); - let result = scenario.run(&["logs", "--remove-converted"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!(result.stdout.contains("Removed 1"), "{}", result.stdout); - assert!(!good.exists()); - assert!(good.with_extension("logs.jsonl").is_file()); - assert!(good.with_extension("models.json").is_file()); - assert!(changed.is_file()); - assert!(damaged.is_file()); - assert!(failed.is_file()); - let result = scenario.run(&["logs", "--remove-converted"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!(result.stdout.contains("Removed 0"), "{}", result.stdout); -} - -fn command_record(session: &Path, harness: &str) -> PathBuf { - let command = session.parent().unwrap().join(format!("{STAMP}.log")); - let record = command.with_extension("command.json"); - fs::write(&record, serde_json::to_vec(&json!({ - "version":1,"kind":"Security run","repository":format!("acme/{harness}"), - "name":format!("secure-{STAMP}"),"issue":null,"hostname":"factory", - "process_id":0,"process_start":"gone","harness":harness,"model":null,"effort":null, - "started_at":"2026-10-01T12:00:00Z","ended_at":"2026-10-01T12:01:00Z", - "stages":[{"name":"security-audit","began_at":"2026-10-01T12:00:00Z","session_log":session}], - "session_log":session,"outcome":"done","cause":null,"issue_branch":null,"pull_request":null - })).unwrap()).unwrap(); - command -} - -#[test] -fn show_and_logs_find_one_session_after_removing_a_recorded_original() { - let scenario = Scenario::new(); - let raw = "{\"type\":\"item.completed\",\"item\":{\"id\":\"test\",\"type\":\"command_execution\",\"command\":\"cargo test\",\"status\":\"completed\",\"exit_code\":0}}\n"; - let session = fixture(&scenario, "codex", raw); - let command = command_record(&session, "codex"); - let command = command.to_str().unwrap(); - for args in [["logs", "--convert"], ["logs", "--remove-converted"]] { - let result = scenario.run(&args); - assert_eq!(result.code, Some(0), "{}", result.stderr); - } - assert!(!session.exists(), "{}", report(&scenario)); - let result = scenario.run(&["show", command, "--json"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let shown: Value = serde_json::from_str(&result.stdout).unwrap(); - assert_eq!( - shown["command"]["session_logs"], - json!([session.with_extension("logs.jsonl")]) - ); - let result = scenario.run(&["logs", command, "--session", "security-audit"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!(result.stdout.contains("resourceLogs"), "{}", result.stdout); - let logs = records(&session.with_extension("logs.jsonl")); - assert_eq!(logs[0]["timeUnixNano"], "1790856005000000000"); -} - -#[test] -fn recovers_old_codex_diffs_from_the_matching_native_session_file() { - let scenario = Scenario::new(); - let session = fixture( - &scenario, - "codex", - include_str!("fixtures/console-codex.jsonl"), - ); - let native = scenario - .path("home/.codex/sessions/2026/10/01/rollout-2026-10-01T12-00-00-made-up-thread.jsonl"); - fs::create_dir_all(native.parent().unwrap()).unwrap(); - let directory = scenario.path("work/widgets"); - let diff = "--- a/widgets.rs\n+++ b/widgets.rs\n@@ -1 +1 @@\n-old\n+new\n"; - fs::write(&native, format!("{}\n{}\n", json!({"type":"session_meta","payload":{"id":"made-up-thread","cwd":directory}}), - json!({"timestamp":"2026-10-01T12:00:40Z","type":"event_msg","payload":{ - "type":"patch_apply_end","success":true,"changes":{ - directory.join("widgets.rs").to_str().unwrap():{"type":"update","unified_diff":diff,"move_path":null} - } - }}) - )).unwrap(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let report = report(&scenario); - assert_eq!(report["sessions"][0]["passed"], true, "{report}"); - assert_eq!(report["sessions"][0]["codex_diffs"], 1, "{report}"); - let logs = records(&session.with_extension("logs.jsonl")); - let amendment: Value = logs - .iter() - .filter_map(|record| { - serde_json::from_str::(record["body"]["stringValue"].as_str()?).ok() - }) - .find(|event| event["result"]["source"] == "codex_session_file") - .unwrap(); - assert_eq!(amendment["id"], "f1"); - assert_eq!(amendment["result"]["changes"][0]["diff"], diff); - assert!(session.exists()); -} - -#[test] -fn empty_sessions_convert_but_existing_trace_files_are_never_overwritten() { - let scenario = Scenario::new(); - let empty = fixture(&scenario, "claude", ""); - let existing = fixture( - &scenario, - "codex", - include_str!("fixtures/console-codex.jsonl"), - ); - fs::write(existing.with_extension("spans.jsonl"), "existing trace\n").unwrap(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let report = report(&scenario); - let entries = report["sessions"].as_array().unwrap(); - assert_eq!( - entries - .iter() - .find(|e| e["source"].as_str().unwrap().contains("/claude/")) - .unwrap()["passed"], - true, - "{report}" - ); - assert_eq!( - fs::read_to_string(existing.with_extension("spans.jsonl")).unwrap(), - "existing trace\n" - ); - let result = scenario.run(&["logs", "--remove-converted"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!(!empty.exists()); - assert!(existing.exists()); -} - -#[test] -fn removed_tokenless_original_keeps_its_evidenced_command_owner() { - let scenario = Scenario::new(); - let session = fixture( - &scenario, - "claude", - include_str!("fixtures/console-claude.jsonl"), - ); - let legacy_command = session.parent().unwrap().join(format!("{STAMP}.log")); - let owned_command = legacy_command.with_file_name(format!("{STAMP}~owner.log")); - fs::rename(&legacy_command, &owned_command).unwrap(); - let models_path = session.with_extension("models.json"); - let mut models: Value = serde_json::from_slice(&fs::read(&models_path).unwrap()).unwrap(); - models["command_log"] = json!(owned_command); - fs::write(&models_path, serde_json::to_vec(&models).unwrap()).unwrap(); - for args in [["logs", "--convert"], ["logs", "--remove-converted"]] { - let result = scenario.run(&args); - assert_eq!(result.code, Some(0), "{}", result.stderr); - } - assert!(!session.exists(), "{}", report(&scenario)); - let result = scenario.run(&["status", "--all", "--json"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let status: Value = serde_json::from_str(&result.stdout).unwrap(); - let commands = status["commands"].as_array().unwrap(); - assert!( - commands - .iter() - .any(|c| c["command_log"] == json!(owned_command)), - "{status}" - ); - assert!( - !commands - .iter() - .any(|c| c["command_log"] == json!(legacy_command)), - "{status}" - ); -} - -#[test] -fn historical_codex_diff_belongs_to_the_original_turn_even_after_a_resume() { - let scenario = Scenario::new(); - let session = fixture( - &scenario, - "codex", - include_str!("fixtures/console-codex.jsonl"), - ); - let native = scenario - .path("home/.codex/sessions/2026/10/01/rollout-2026-10-01T12-00-00-made-up-thread.jsonl"); - fs::create_dir_all(native.parent().unwrap()).unwrap(); - let original = "--- a/widgets.rs\n+++ b/widgets.rs\n@@ -1 +1 @@\n-old\n+first-turn\n"; - let later = "--- a/widgets.rs\n+++ b/widgets.rs\n@@ -1 +1 @@\n-first-turn\n+later-resume\n"; - let mut rows = vec![ - json!({"type":"session_meta","payload":{"id":"made-up-thread","cwd":"/work/widgets"}}), - ]; - for (time, diff) in [ - ("2026-10-01T12:00:30Z", original), - ("2026-10-02T12:00:30Z", later), - ] { - rows.push(json!({"timestamp":time,"type":"event_msg","payload":{"type":"task_started"}})); - rows.push(json!({"timestamp":time,"type":"event_msg","payload":{"type":"patch_apply_end","success":true,"changes":{ - "/work/widgets/widgets.rs":{"type":"update","unified_diff":diff,"move_path":null} - }}})); - } - fs::write( - native, - rows.iter().map(|r| format!("{r}\n")).collect::(), - ) - .unwrap(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let report = report(&scenario); - assert_eq!(report["sessions"][0]["passed"], true, "{report}"); - let logs = records(&session.with_extension("logs.jsonl")); - let diffs: Vec<_> = logs - .iter() - .filter_map(|r| serde_json::from_str::(r["body"]["stringValue"].as_str()?).ok()) - .filter(|e| e["result"]["source"] == "codex_session_file") - .map(|e| e["result"]["changes"][0]["diff"].clone()) - .collect(); - assert_eq!(diffs, vec![json!(original)]); -} - -#[test] -fn converts_the_pre_repository_session_layout_and_filename() { - let scenario = Scenario::new(); - let source = scenario - .path("home/.thirdshift/logs/sessions/widgets-4-20260801T120000-0400-implement.jsonl"); - fs::create_dir_all(source.parent().unwrap()).unwrap(); - fs::write(&source, "{\"type\":\"system\",\"subtype\":\"init\"}\n").unwrap(); - fs::write(source.with_extension("models.json"), serde_json::to_vec(&json!({"harness":"claude","kind":"implement","requested":null,"effort":null,"observed":[]})).unwrap()).unwrap(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!( - source.with_extension("logs.jsonl").exists(), - "{}", - report(&scenario) - ); - assert_eq!(report(&scenario)["sessions"][0]["passed"], true); - assert!(source.exists()); - let result = scenario.run(&["logs", "--remove-converted"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert!(!source.exists()); -} - -#[test] -fn historical_session_end_includes_its_timed_events_when_the_command_log_is_missing() { - let scenario = Scenario::new(); - let raw = concat!( - "{\"timestamp\":\"2026-10-01T12:00:10Z\",\"type\":\"item.started\",\"item\":{\"id\":\"c1\",\"type\":\"command_execution\",\"command\":\"cargo test\",\"status\":\"in_progress\"}}\n", - "{\"timestamp\":\"2026-10-01T12:00:20Z\",\"type\":\"item.completed\",\"item\":{\"id\":\"c1\",\"type\":\"command_execution\",\"command\":\"cargo test\",\"status\":\"completed\",\"exit_code\":0}}\n" - ); - let session = fixture(&scenario, "codex", raw); - fs::remove_file(session.parent().unwrap().join(format!("{STAMP}.log"))).unwrap(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - assert_eq!(report(&scenario)["sessions"][0]["passed"], true); - let spans: Vec = fs::read_to_string(session.with_extension("spans.jsonl")).unwrap().lines() - .flat_map(|line| serde_json::from_str::(line).unwrap()["resourceSpans"][0]["scopeSpans"][0]["spans"].as_array().unwrap().clone()).collect(); - let session_span = spans - .iter() - .find(|s| s["name"] == "invoke_agent security-audit") - .unwrap(); - assert_eq!(session_span["endTimeUnixNano"], "1790856020000000000"); -} - -#[test] -fn timestamped_codex_patches_are_recovered_without_command_evidence() { - let scenario = Scenario::new(); - let raw = concat!( - "{\"timestamp\":\"2026-10-01T12:00:00Z\",\"type\":\"thread.started\",\"thread_id\":\"made-up-thread\"}\n", - "{\"timestamp\":\"2026-10-01T12:00:40Z\",\"type\":\"item.completed\",\"item\":{\"id\":\"f1\",\"type\":\"file_change\",\"changes\":[{\"path\":\"widgets.rs\",\"kind\":\"update\"}],\"status\":\"completed\"}}\n" - ); - let session = fixture(&scenario, "codex", raw); - fs::remove_file(session.with_extension("models.json")).unwrap(); - fs::remove_file(session.parent().unwrap().join(format!("{STAMP}.log"))).unwrap(); - let native = scenario - .path("home/.codex/sessions/2026/10/01/rollout-2026-10-01T12-00-00-made-up-thread.jsonl"); - fs::create_dir_all(native.parent().unwrap()).unwrap(); - let diff = "--- a/widgets.rs\n+++ b/widgets.rs\n@@ -1 +1 @@\n-old\n+new\n"; - fs::write(native, format!("{}\n{}\n", json!({"type":"session_meta","payload":{"id":"made-up-thread","cwd":"/work/widgets"}}), - json!({"timestamp":"2026-10-01T12:00:40Z","type":"event_msg","payload":{"type":"patch_apply_end","success":true,"changes":{ - "/work/widgets/widgets.rs":{"type":"update","unified_diff":diff,"move_path":null} - }}}))).unwrap(); - let result = scenario.run(&["logs", "--convert"]); - assert_eq!(result.code, Some(0), "{}", result.stderr); - let report = report(&scenario); - assert_eq!(report["sessions"][0]["passed"], true, "{report}"); - assert_eq!(report["sessions"][0]["codex_diffs"], 1, "{report}"); - assert!( - fs::read_to_string(session.with_extension("logs.jsonl")) - .unwrap() - .contains("codex_session_file") - ); -} diff --git a/tests/export_trace.rs b/tests/export_trace.rs index e12a502de..7eabd9aae 100644 --- a/tests/export_trace.rs +++ b/tests/export_trace.rs @@ -133,10 +133,7 @@ fn export_decodes_with_official_types_and_keeps_record_times_and_all_session_log .as_array() .unwrap() .iter() - .map(|path| { - fs::read_to_string(Path::new(path.as_str().unwrap()).with_extension("logs.jsonl")) - .unwrap() - }) + .map(|path| fs::read_to_string(path.as_str().unwrap()).unwrap()) .collect::(); assert!(!logs.is_empty()); assert_eq!(logs, source); diff --git a/tests/failed_run.rs b/tests/failed_run.rs index c0ee00d05..13dd28683 100644 --- a/tests/failed_run.rs +++ b/tests/failed_run.rs @@ -48,7 +48,7 @@ fn a_failing_session_pushes_a_failure_commit_with_the_uncommitted_work_saying_wh } /// What every Failed run shares: a non-zero exit, `stdout` (empty unless a PR -/// exists), the session log path on stderr, and nothing left behind. +/// exists), the session trace path on stderr, and nothing left behind. fn assert_failed(scenario: &Scenario, result: &RunResult, stdout: &str) { assert_eq!(result.code, Some(1), "stderr: {}", result.stderr); assert_eq!(result.stdout, stdout); diff --git a/tests/fixtures/console-claude.jsonl b/tests/fixtures/console-claude.jsonl index 5aeb3e1a6..3e97b4cac 100644 --- a/tests/fixtures/console-claude.jsonl +++ b/tests/fixtures/console-claude.jsonl @@ -1,9 +1,9 @@ -{"type":"system","subtype":"init","session_id":"made-up-session"} -{"type":"user","message":{"role":"user","content":"Make the widgets ."}} -{"type":"assistant","message":{"role":"assistant","content":[{"type":"thinking","thinking":"Consider the widget shape."},{"type":"text","text":"I will inspect the widgets."}]}} -{"type":"assistant","message":{"role":"assistant","content":[{"type":"tool_use","id":"read_1","name":"Read","input":{"file_path":"/project/widgets.rs"}}]}} -{"type":"user","message":{"role":"user","content":[{"type":"tool_result","tool_use_id":"read_1","content":"old widget"}]}} -{"type":"assistant","message":{"role":"assistant","content":[{"type":"tool_use","id":"grep_1","name":"Grep","input":{"pattern":"widget","path":"/project"}},{"type":"tool_use","id":"edit_1","name":"Edit","input":{"file_path":"widgets.rs","old_string":"old widget","new_string":"new widget"}},{"type":"tool_use","id":"bash_1","name":"Bash","input":{"command":"cargo test widgets"}},{"type":"tool_use","id":"other_1","name":"NewTool","input":{"future":"visible"}}]}} -{"type":"assistant","message":{"role":"assistant","content":[{"type":"text","text":"Widgets are ready."},{"type":"future_block","detail":"unknown block stays visible"}]}} -{"type":"future_event","detail":"unknown event stays visible "} -not JSON: retained diagnostic +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"system\",\"subtype\":\"init\",\"session_id\":\"made-up-session\"}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"user\",\"message\":{\"role\":\"user\",\"content\":\"Make the widgets .\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"assistant\",\"message\":{\"role\":\"assistant\",\"content\":[{\"type\":\"thinking\",\"thinking\":\"Consider the widget shape.\"},{\"type\":\"text\",\"text\":\"I will inspect the widgets.\"}]}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"assistant\",\"message\":{\"role\":\"assistant\",\"content\":[{\"type\":\"tool_use\",\"id\":\"read_1\",\"name\":\"Read\",\"input\":{\"file_path\":\"/project/widgets.rs\"}}]}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"user\",\"message\":{\"role\":\"user\",\"content\":[{\"type\":\"tool_result\",\"tool_use_id\":\"read_1\",\"content\":\"old widget\"}]}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"assistant\",\"message\":{\"role\":\"assistant\",\"content\":[{\"type\":\"tool_use\",\"id\":\"grep_1\",\"name\":\"Grep\",\"input\":{\"pattern\":\"widget\",\"path\":\"/project\"}},{\"type\":\"tool_use\",\"id\":\"edit_1\",\"name\":\"Edit\",\"input\":{\"file_path\":\"widgets.rs\",\"old_string\":\"old widget\",\"new_string\":\"new widget\"}},{\"type\":\"tool_use\",\"id\":\"bash_1\",\"name\":\"Bash\",\"input\":{\"command\":\"cargo test widgets\"}},{\"type\":\"tool_use\",\"id\":\"other_1\",\"name\":\"NewTool\",\"input\":{\"future\":\"visible\"}}]}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"assistant\",\"message\":{\"role\":\"assistant\",\"content\":[{\"type\":\"text\",\"text\":\"Widgets are ready.\"},{\"type\":\"future_block\",\"detail\":\"unknown block stays visible\"}]}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"future_event\",\"detail\":\"unknown event stays visible \"}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"not JSON: retained diagnostic"}}]}]}]} diff --git a/tests/fixtures/console-codex.jsonl b/tests/fixtures/console-codex.jsonl index f093e123b..8b66efdda 100644 --- a/tests/fixtures/console-codex.jsonl +++ b/tests/fixtures/console-codex.jsonl @@ -1,9 +1,9 @@ -{"type":"thread.started","thread_id":"made-up-thread"} -{"type":"item.completed","item":{"id":"r1","type":"reasoning","text":"Consider a safe edit."}} -{"type":"item.completed","item":{"id":"a1","type":"agent_message","text":"I will inspect the widgets."}} -{"type":"item.started","item":{"id":"c1","type":"command_execution","command":"cat widgets.rs","aggregated_output":"","status":"in_progress"}} -{"type":"item.completed","item":{"id":"c1","type":"command_execution","command":"cat widgets.rs","aggregated_output":"widget output ","exit_code":0,"status":"completed"}} -{"type":"item.completed","item":{"id":"f1","type":"file_change","changes":[{"path":"widgets.rs","kind":"update"}],"status":"completed"}} -{"type":"item.completed","item":{"id":"m1","type":"mcp_tool_call","server":"files","tool":"Read","arguments":{"file_path":"widgets.rs"},"result":{"content":[{"type":"text","text":"new widget"}]},"status":"completed"}} -{"type":"item.completed","item":{"id":"z1","type":"future_item","detail":"unknown Codex item visible"}} -{"type":"item.completed","item":{"id":"a2","type":"agent_message","text":"Widgets are ready."}} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"thread.started\",\"thread_id\":\"made-up-thread\"}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"r1\",\"type\":\"reasoning\",\"text\":\"Consider a safe edit.\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"a1\",\"type\":\"agent_message\",\"text\":\"I will inspect the widgets.\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.started\",\"item\":{\"id\":\"c1\",\"type\":\"command_execution\",\"command\":\"cat widgets.rs\",\"aggregated_output\":\"\",\"status\":\"in_progress\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"c1\",\"type\":\"command_execution\",\"command\":\"cat widgets.rs\",\"aggregated_output\":\"widget output \",\"exit_code\":0,\"status\":\"completed\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"f1\",\"type\":\"file_change\",\"changes\":[{\"path\":\"widgets.rs\",\"kind\":\"update\"}],\"status\":\"completed\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"m1\",\"type\":\"mcp_tool_call\",\"server\":\"files\",\"tool\":\"Read\",\"arguments\":{\"file_path\":\"widgets.rs\"},\"result\":{\"content\":[{\"type\":\"text\",\"text\":\"new widget\"}]},\"status\":\"completed\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"z1\",\"type\":\"future_item\",\"detail\":\"unknown Codex item visible\"}}"}}]}]}]} +{"resourceLogs":[{"scopeLogs":[{"logRecords":[{"body":{"stringValue":"{\"type\":\"item.completed\",\"item\":{\"id\":\"a2\",\"type\":\"agent_message\",\"text\":\"Widgets are ready.\"}}"}}]}]}]} diff --git a/tests/fresh_run.rs b/tests/fresh_run.rs index 229f9921a..c9ca92d61 100644 --- a/tests/fresh_run.rs +++ b/tests/fresh_run.rs @@ -389,15 +389,14 @@ fn logs_the_session_stream_under_the_home_directory() { assert_eq!(logs.len(), 1, "logs: {logs:?}"); let name = &logs[0]; assert!( - name.starts_with("7-") && name.ends_with("-implement.jsonl"), + name.starts_with("7-") && name.ends_with("-implement.logs.jsonl"), "log: {name}" ); - let log = std::fs::read_to_string( + let log = support::session_trace::events( scenario .path("home/.thirdshift/logs/acme/widgets/commands/issue") .join(name), - ) - .unwrap(); + ); assert!( log.contains(r#""type": "system""#) && log.contains(r#""type": "result""#), "log: {log}" diff --git a/tests/merge_run.rs b/tests/merge_run.rs index bf3ce0ffb..af2735441 100644 --- a/tests/merge_run.rs +++ b/tests/merge_run.rs @@ -1061,7 +1061,7 @@ fn a_review_repair_whose_background_work_was_killed_gets_a_resume() { let logs = scenario.log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl"); assert!( logs.iter() - .any(|log| log.ends_with("-repair-1-resume.jsonl")), + .any(|log| log.ends_with("-repair-1-resume.logs.jsonl")), "logs: {logs:?}" ); } diff --git a/tests/mergeable.rs b/tests/mergeable.rs index 24d6812b6..8151ffc4b 100644 --- a/tests/mergeable.rs +++ b/tests/mergeable.rs @@ -155,12 +155,12 @@ fn logs_the_conflict_repair_with_the_runs_shared_timestamp() { assert_eq!(logs.len(), 2, "logs: {logs:?}"); let implement = logs .iter() - .find(|name| name.ends_with("-implement.jsonl")) + .find(|name| name.ends_with("-implement.logs.jsonl")) .expect("no implement log"); - let prefix = implement.strip_suffix("implement.jsonl").unwrap(); + let prefix = implement.strip_suffix("implement.logs.jsonl").unwrap(); assert!(prefix.starts_with("7-"), "log: {implement}"); assert!( - logs.contains(&format!("{prefix}repair-1.jsonl")), + logs.contains(&format!("{prefix}repair-1.logs.jsonl")), "logs: {logs:?}" ); } diff --git a/tests/pickup_run.rs b/tests/pickup_run.rs index df00bf270..09aecd397 100644 --- a/tests/pickup_run.rs +++ b/tests/pickup_run.rs @@ -1069,7 +1069,7 @@ fn a_dispatched_run_that_fails_fails_the_pickup_run_as_a_failed_run_does() { assert_eq!(result.stdout, ""); let last = *before_command_log(&result.stderr).last().unwrap(); assert!( - last.starts_with("thirdshift: session log: ") && last.ends_with("-implement.jsonl"), + last.starts_with("thirdshift: session trace: ") && last.ends_with("-implement.logs.jsonl"), "stderr: {}", result.stderr ); @@ -1490,7 +1490,7 @@ fn the_notification_of_a_run_left_ready_for_review_is_that_runs() { Title: Sharpen the widgets\n\ Command: Pickup run, which dispatched a Run\n\ Pull request: {}\n\ - Session log: {}\n\ + Session trace: {}\n\ Command log: {}\n\ Built with claude · default model · default effort (configured)\n\ Sent by: thirdshift\n\ @@ -1548,7 +1548,7 @@ fn the_notification_of_a_failed_run_has_its_pull_request_and_its_cause() { Command: Pickup run, which dispatched a Run\n\ Pull request: {}\n\ Cause: claude exited 3\n\ - Session log: ", + Session trace: ", pr_from(&scenario, "issue-7")["url"].as_str().unwrap() )), "{text}" diff --git a/tests/progress_lines.rs b/tests/progress_lines.rs index b9300a7f6..169c88a7a 100644 --- a/tests/progress_lines.rs +++ b/tests/progress_lines.rs @@ -266,7 +266,7 @@ fn still_logs_the_whole_stream() { #[test] fn a_log_failure_still_recovers_and_reports_warnings_and_usage() { let scenario = Scenario::new(); - let pipe = scenario.path("session-log-pipe"); + let pipe = scenario.path("session-trace-pipe"); assert!( Command::new("mkfifo") .arg(&pipe) @@ -288,7 +288,7 @@ for log in "{logs}/commands/issue/"*.log; do identity_fragment=${{identity_fragment%.log}} done mkdir -p "{logs}/commands/issue" -ln -s "{pipe}" "{logs}/commands/issue/7-$identity_fragment-implement.jsonl" +ln -s "{pipe}" "{logs}/commands/issue/7-$identity_fragment-implement.logs.jsonl" touch "{ready}" "#, logs = logs.display(), @@ -331,7 +331,7 @@ exec sleep 5 let mut line = String::new(); loop { line.clear(); - if reader.read_line(&mut line).unwrap() == 0 || line == "ready-to-fail\n" { + if reader.read_line(&mut line).unwrap() == 0 || line.contains("ready-to-fail") { break; } } diff --git a/tests/run_health.rs b/tests/run_health.rs index ea9008c7f..538a44e51 100644 --- a/tests/run_health.rs +++ b/tests/run_health.rs @@ -69,7 +69,7 @@ impl LiveRun { ( { let log = PathBuf::from(self.record["session_log"].as_str().unwrap()); - let records = log.with_extension("logs.jsonl"); + let records = log.clone(); if records.is_file() { records } else { log } }, session, @@ -171,14 +171,14 @@ fn silent_requires_both_logs_and_escalates_in_status_and_show() { } #[test] -fn silent_watches_session_trace_records_and_falls_back_to_old_session_logs() { +fn silent_watches_only_session_trace_records() { use std::io::Write; let mut run = LiveRun::new(); run.stage_age(60); run.log_ages(20, 20); let session = PathBuf::from(run.record["session_log"].as_str().unwrap()); - let records = session.with_extension("logs.jsonl"); + let records = session.clone(); let event = support::session_trace::records(r#"{"type":"assistant","message":{"content":"Working"}}"#); fs::write(&records, &event).unwrap(); @@ -190,7 +190,6 @@ fn silent_watches_session_trace_records_and_falls_back_to_old_session_logs() { .unwrap() .set_times(FileTimes::new().set_modified(SystemTime::now() - Duration::from_secs(20 * 60))) .unwrap(); - fs::write(&session, "Old log grew, but the records did not\n").unwrap(); assert_eq!(run.status()["health"]["state"], "silent"); File::options() .append(true) @@ -199,11 +198,8 @@ fn silent_watches_session_trace_records_and_falls_back_to_old_session_logs() { .write_all(event.as_bytes()) .unwrap(); assert_eq!(run.status()["health"]["state"], "ok"); - fs::remove_file(&session).unwrap(); - assert_eq!(run.status()["health"]["state"], "ok"); fs::remove_file(&records).unwrap(); - fs::write(&session, "Old Session log is active\n").unwrap(); - assert_eq!(run.status()["health"]["state"], "ok"); + assert_eq!(run.status()["health"]["state"], "silent"); } #[test] diff --git a/tests/run_notification.rs b/tests/run_notification.rs index dac9c6a6d..3de0ed650 100644 --- a/tests/run_notification.rs +++ b/tests/run_notification.rs @@ -57,7 +57,7 @@ fn text(request: &Request) -> &str { request.body["text"].as_str().unwrap() } -/// The path of the one session log the Run wrote. +/// The path of the one session trace the Run wrote. fn the_one_log(scenario: &Scenario) -> String { let logs = scenario.log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl"); assert_eq!(logs.len(), 1, "logs: {logs:?}"); diff --git a/tests/security_review.rs b/tests/security_review.rs index 33ec632bb..52a33c24f 100644 --- a/tests/security_review.rs +++ b/tests/security_review.rs @@ -110,7 +110,7 @@ fi let state = scenario.gh_state(); let body = state["prs"][0]["body"].as_str().unwrap(); assert!( - body.contains("- Security review on grok failed; see Session log\n"), + body.contains("- Security review on grok failed; see Session trace\n"), "{body}" ); assert!(!body.contains("Not signed in."), "{body}"); @@ -119,7 +119,7 @@ fi let logs = scenario.log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl"); let review_log = logs .iter() - .find(|name| name.ends_with("-security-review.jsonl")) + .find(|name| name.ends_with("-security-review.logs.jsonl")) .unwrap(); let transcript = std::fs::read_to_string(scenario.path(&format!( "home/.thirdshift/logs/acme/widgets/commands/issue/{review_log}" @@ -164,7 +164,7 @@ fn security_review_failures_without_a_diagnostic_keep_the_generic_cause() { scenario.agent_does_in_session(2, script); let result = scenario.run(&[&scenario.issue_url(7), "security-review", "merge"]); assert_eq!(result.code, Some(1), "{}", result.stderr); - let cause = "Security review incomplete: session failed, ended early or omitted a valid final line; see Session log"; + let cause = "Security review incomplete: session failed, ended early or omitted a valid final line; see Session trace"; assert!( result.stderr.contains(&format!("thirdshift: {cause}\n")), "{}", @@ -272,7 +272,7 @@ fn explicit_incomplete_reviews_still_validate_the_entire_private_report() { let state = scenario.gh_state(); assert!(state["advisories"].is_null()); let body = state["prs"][0]["body"].as_str().unwrap(); - let generic = "Security review incomplete: session failed, ended early or omitted a valid final line; see Session log"; + let generic = "Security review incomplete: session failed, ended early or omitted a valid final line; see Session trace"; assert!(body.contains(generic), "{body}"); assert!(result.stderr.contains(generic), "{}", result.stderr); assert_old_finding_stays_private(body, &result); @@ -567,7 +567,7 @@ fn invalid_or_missing_final_lines_hold_self_merge_but_report_only_runs_continue( result.stderr ); assert!( - result.stderr.contains("Security review incomplete: session failed, ended early or omitted a valid final line; see Session log"), + result.stderr.contains("Security review incomplete: session failed, ended early or omitted a valid final line; see Session trace"), "{}", result.stderr ); @@ -578,7 +578,7 @@ fn invalid_or_missing_final_lines_hold_self_merge_but_report_only_runs_continue( pr["body"] .as_str() .unwrap() - .contains("Security review incomplete: session failed, ended early or omitted a valid final line; see Session log") + .contains("Security review incomplete: session failed, ended early or omitted a valid final line; see Session trace") ); } } @@ -810,17 +810,17 @@ gh fake checks "$(git rev-parse HEAD)" '[{"name":"test","conclusion":"success"}] ); // The Repair ran after the review, so it is the most recent session. assert!( - result.stderr.contains("-repair-1.jsonl"), + result.stderr.contains("-repair-1.logs.jsonl"), "{}", result.stderr ); let reported = result .stderr .lines() - .find_map(|line| line.split_once("session log: ").map(|(_, log)| log)) - .unwrap_or_else(|| panic!("no session log line: {}", result.stderr)); + .find_map(|line| line.split_once("session trace: ").map(|(_, log)| log)) + .unwrap_or_else(|| panic!("no session trace line: {}", result.stderr)); assert!( - reported.ends_with("-security-review.jsonl"), + reported.ends_with("-security-review.logs.jsonl"), "{}", result.stderr ); @@ -828,7 +828,7 @@ gh fake checks "$(git rev-parse HEAD)" '[{"name":"test","conclusion":"success"}] assert_eq!(requests.len(), 1, "{requests:?}"); let text = requests[0].body["text"].as_str().unwrap(); assert!( - text.contains(&format!("Session log: {reported}\n")), + text.contains(&format!("Session trace: {reported}\n")), "{text}" ); } @@ -866,14 +866,18 @@ gh fake checks "$(git rev-parse origin/main)" '[{"name":"test","conclusion":"suc let reported = result .stderr .lines() - .find_map(|line| line.split_once("session log: ").map(|(_, log)| log)) - .unwrap_or_else(|| panic!("no session log line: {}", result.stderr)); - assert!(reported.ends_with("-repair-1.jsonl"), "{}", result.stderr); + .find_map(|line| line.split_once("session trace: ").map(|(_, log)| log)) + .unwrap_or_else(|| panic!("no session trace line: {}", result.stderr)); + assert!( + reported.ends_with("-repair-1.logs.jsonl"), + "{}", + result.stderr + ); let requests = resend.requests(); assert_eq!(requests.len(), 1, "{requests:?}"); let text = requests[0].body["text"].as_str().unwrap(); assert!( - text.contains(&format!("Session log: {reported}\n")), + text.contains(&format!("Session trace: {reported}\n")), "{text}" ); } diff --git a/tests/security_run.rs b/tests/security_run.rs index 8a2fe5eb9..c0d16e6e2 100644 --- a/tests/security_run.rs +++ b/tests/security_run.rs @@ -202,12 +202,12 @@ printf '%s\n' '{{"type":"assistant","message":{{"model":"claude-opus-4-8","conte assert!( session_logs .iter() - .any(|name| name.ends_with("-security-audit.jsonl")) + .any(|name| name.ends_with("-security-audit.logs.jsonl")) ); assert!( session_logs .iter() - .any(|name| name.ends_with("-security-reproduction-1.jsonl")) + .any(|name| name.ends_with("-security-reproduction-1.logs.jsonl")) ); assert!( !scenario @@ -291,8 +291,8 @@ fn refused_security_reproductions_keep_the_record_and_stop_before_the_next_findi "Result: reproduction failed", "Audit: audit complete", "Reproduction: 1 refused", - "Session log:", - "security-reproduction-1.jsonl", + "Session trace:", + "security-reproduction-1.logs.jsonl", "Command log:", ] { assert!(text.contains(line), "missing {line}: {text}"); @@ -1939,7 +1939,7 @@ fn incomplete_reproductions_preserve_the_record_and_stop_before_the_next_session assert_eq!(result.code, Some(1), "{}", result.stderr); assert!(result.stderr.contains(cause), "{}", result.stderr); assert!( - result.stderr.contains("security-reproduction-1.jsonl"), + result.stderr.contains("security-reproduction-1.logs.jsonl"), "{}", result.stderr ); @@ -2834,7 +2834,7 @@ fn missing_final_line_or_invalid_reports_fail_without_recording() { "expected {cause}: {}", result.stderr ); - assert!(result.stderr.contains("session log:")); + assert!(result.stderr.contains("session trace:")); assert!(scenario.gh_state()["advisories"].is_null()); assert_eq!(scenario.entries("work"), vec![REPO]); let log = @@ -3528,7 +3528,7 @@ fn pre_audit_github_failures_report_a_safe_cause_without_claiming_an_audit_ran() ); } for absent in [ - "Session log:", + "Session trace:", "Command log:", "Reproduction:", "Session models:", @@ -3811,8 +3811,8 @@ fn a_reproduction_failure_notifies_recorded_metadata_without_private_evidence() "Result: reproduction failed", "Audit: audit complete", "Reproduction: 2 failed", - "Session log:", - "security-reproduction-2.jsonl", + "Session trace:", + "security-reproduction-2.logs.jsonl", "Command log:", ] { assert!(text.contains(line), "missing {line}: {text}"); diff --git a/tests/session_traces.rs b/tests/session_traces.rs index b3364b58c..2ed0e3c21 100644 --- a/tests/session_traces.rs +++ b/tests/session_traces.rs @@ -179,8 +179,17 @@ fn all_six_harnesses_leave_one_inventory_entry_and_both_otlp_files() { assert_eq!(request.resource_logs[0].scope_logs[0].log_records.len(), 1); } let stem = logs[0].strip_suffix(".logs.jsonl").unwrap(); - assert!(folder.join(format!("{stem}.jsonl")).exists()); + assert!(!folder.join(format!("{stem}.jsonl")).exists()); assert!(folder.join(format!("{stem}.models.json")).exists()); + let record = scenario.command_record(LOGS); + assert_eq!(record["session_log"], serde_json::json!(path)); + assert!( + record["stages"] + .as_array() + .unwrap() + .iter() + .any(|stage| { stage["session_log"] == serde_json::json!(path) }) + ); assert!( spans(&folder.join(format!("{stem}.spans.jsonl"))) .iter() diff --git a/tests/show_logs.rs b/tests/show_logs.rs index 3c542e37c..36a2aef34 100644 --- a/tests/show_logs.rs +++ b/tests/show_logs.rs @@ -21,8 +21,8 @@ fn same_stamp_session_history_keeps_legacy_and_owned_inventories_disjoint() { .unwrap(); for kind in ["implement", "implement-resume", "repair-1", "repair-2"] { fs::write( - folder.join(format!("{stem}-{kind}.jsonl")), - format!("{owner} {kind}\n"), + folder.join(format!("{stem}-{kind}.logs.jsonl")), + support::session_trace::records(&format!("{owner} {kind}\n")), ) .unwrap(); } @@ -40,7 +40,7 @@ fn same_stamp_session_history_keeps_legacy_and_owned_inventories_disjoint() { let sessions = command["session_logs"].as_array().unwrap(); assert_eq!(sessions.len(), 4, "{command}"); for kind in ["implement", "implement-resume", "repair-1", "repair-2"] { - let path = folder.join(format!("{stem}-{kind}.jsonl")); + let path = folder.join(format!("{stem}-{kind}.logs.jsonl")); assert!(sessions.contains(&serde_json::json!(path)), "{command}"); } } @@ -73,9 +73,9 @@ fn owned_and_legacy_commands_keep_exact_paths_and_record_precedence() { ), ] { let log = folder.join(format!("{stem}.log")); - let session = folder.join(format!("{stem}-implement.jsonl")); + let session = folder.join(format!("{stem}-implement.logs.jsonl")); fs::write(&log, format!("{marker} Command output\n")).unwrap(); - fs::write(&session, format!("{marker} Session output\n")).unwrap(); + support::session_trace::write(&session, format!("{marker} Session output\n")); let record = serde_json::json!({ "version": 1, "kind": "Run", "repository": "acme/widgets", "name": "acme/widgets#7", "issue": {"number": 7, "url": scenario.issue_url(7), "title": marker}, @@ -124,7 +124,7 @@ fn owned_and_legacy_commands_keep_exact_paths_and_record_precedence() { ); assert_eq!( shown["command"]["session_logs"], - serde_json::json!([folder.join("7-20261003T120000-0400~ownerB-implement.jsonl")]) + serde_json::json!([folder.join("7-20261003T120000-0400~ownerB-implement.logs.jsonl")]) ); for args in [ vec!["logs", "widgets#7"], @@ -136,7 +136,10 @@ fn owned_and_legacy_commands_keep_exact_paths_and_record_precedence() { } let session = scenario.run(&["logs", "widgets#7", "--session", "implement"]); assert_eq!(session.code, Some(0), "{}", session.stderr); - assert_eq!(session.stdout, "second Session output\n"); + assert_eq!( + session.stdout, + support::session_trace::records("second Session output\n") + ); } #[test] @@ -165,7 +168,7 @@ fn show_activity_history_lists_its_session_logs() { .unwrap() .iter() .any(|path| path.as_str() == Some(session.as_str())), - "missing Session log: {result}" + "missing Session trace: {result}" ); } @@ -187,8 +190,8 @@ printf 'Architecture review plan: %s\n' "$url" > "$FAKE_CLAUDE_FINAL_MESSAGE" let name = status["commands"][0]["name"].as_str().unwrap(); let current = std::path::Path::new(status["commands"][0]["session_log"].as_str().unwrap()); let original = std::path::PathBuf::from(current.to_string_lossy().replace( - "-architecture-review-resume.jsonl", - "-architecture-review.jsonl", + "-architecture-review-resume.logs.jsonl", + "-architecture-review.logs.jsonl", )); assert_ne!(current, original.as_path()); assert!(original.is_file(), "{}", original.display()); @@ -198,12 +201,12 @@ printf 'Architecture review plan: %s\n' "$url" > "$FAKE_CLAUDE_FINAL_MESSAGE" assert_eq!(json.code, Some(0), "{}", json.stderr); assert!( text.stdout.contains(original.to_str().unwrap()), - "original Session log missing: {}", + "original Session trace missing: {}", text.stdout ); assert!( json.stdout.contains(original.to_str().unwrap()), - "original Session log missing: {}", + "original Session trace missing: {}", json.stdout ); } @@ -488,7 +491,7 @@ fn logs_session_repair_selects_the_latest_numbered_repair() { .unwrap() .iter() .filter_map(|stage| stage["session_log"].as_str()) - .find(|path| path.ends_with("-repair-2.jsonl")) + .find(|path| path.ends_with("-repair-2.logs.jsonl")) .unwrap(); let logs = scenario.run(&["logs", "widgets#7", "--session", "repair"]); assert_eq!(logs.code, Some(0), "{}", logs.stderr); @@ -509,7 +512,7 @@ fn logs_session_selects_the_latest_implement_including_its_resume() { .unwrap() .iter() .filter_map(|stage| stage["session_log"].as_str()) - .find(|path| path.ends_with("-implement-resume.jsonl")) + .find(|path| path.ends_with("-implement-resume.logs.jsonl")) .unwrap(); let expected = fs::read_to_string(session).unwrap(); let result = scenario.run(&["logs", "widgets#7", "--session", "implement"]); @@ -518,7 +521,7 @@ fn logs_session_selects_the_latest_implement_including_its_resume() { let missing = scenario.run(&["logs", "widgets#7", "--session", "spec-review"]); assert_ne!(missing.code, Some(0)); assert!( - missing.stderr.contains("no spec-review Session log"), + missing.stderr.contains("no spec-review Session trace"), "{}", missing.stderr ); @@ -559,7 +562,7 @@ fn logs_can_read_sessions_from_activity_and_session_only_history() { #[test] fn show_reads_the_latest_live_event_from_claude_and_codex_session_tails() { - for trace in [false, true] { + { for (harness, event) in [ ( "claude", @@ -590,15 +593,7 @@ fn show_reads_the_latest_live_event_from_claude_and_codex_session_tails() { "{}\n{event}\n{{\"type\":\"future-event\"}}\nnot json\n{{\"partial\":", "x".repeat(100_000) ); - let records = std::path::Path::new(session).with_extension("logs.jsonl"); - if trace { - fs::write(&records, support::session_trace::records(&contents)).unwrap(); - // Stale dual-recorded output must not win over the Session trace. - fs::write(session, event.replace("cargo test", "stale command")).unwrap(); - } else { - fs::remove_file(records).unwrap(); - fs::write(session, contents).unwrap(); - } + fs::write(session, support::session_trace::records(&contents)).unwrap(); let result = scenario.run(&["show", "widgets#7", "--json"]); let text = scenario.run(&["show", "widgets#7"]); fs::write(scenario.path("release"), "").unwrap(); @@ -640,14 +635,13 @@ fn show_keeps_the_latest_event_when_otlp_escaping_expands_a_record_past_64_kib() "aggregated_output": "\"".repeat(quotes), "status": "completed", "exit_code": 0 }}) .to_string(); - fs::write(session, format!("{event}\n")).unwrap(); let records = support::session_trace::records(&event); if quotes == 20_000 { assert!(event.len() < 64 * 1024); } assert!(records.len() > 64 * 1024); let earlier = support::session_trace::records("Earlier diagnostic\n"); - fs::write(session.with_extension("logs.jsonl"), earlier + &records).unwrap(); + fs::write(session, earlier + &records).unwrap(); let result = scenario.run(&["show", "widgets#7", "--json"]); let text = scenario.run(&["show", "widgets#7"]); fs::write(scenario.path("release"), "").unwrap(); diff --git a/tests/spec_run.rs b/tests/spec_run.rs index 97b334cb0..90e84edee 100644 --- a/tests/spec_run.rs +++ b/tests/spec_run.rs @@ -205,7 +205,7 @@ fn status_retains_merged_children_during_spec_review() { spec["session_log"] .as_str() .unwrap() - .ends_with("-spec-review.jsonl") + .ends_with("-spec-review.logs.jsonl") ); assert!( spec["tickets"] @@ -1276,19 +1276,17 @@ fn with_base_fix_a_tickets_inherited_failure_gets_a_base_fix_into_the_spec_branc assert_eq!( sessions, [ - format!("20-{owner}-spec-review.jsonl"), - format!("21-{owner}-implement.jsonl"), - format!("22-{owner}-implement.jsonl") + format!("20-{owner}-spec-review.logs.jsonl"), + format!("21-{owner}-implement.logs.jsonl"), + format!("22-{owner}-implement.logs.jsonl") ] ); for session in sessions { let evidence: serde_json::Value = serde_json::from_slice( - &std::fs::read( - scenario - .path(folder) - .join(session) - .with_extension("models.json"), - ) + &std::fs::read(support::session_trace::artifact( + &scenario.path(folder).join(session), + "models.json", + )) .unwrap(), ) .unwrap(); @@ -1315,7 +1313,7 @@ fn a_tickets_run_offers_the_spec_runs_command_with_a_base_fix_and_the_spec_run_r assert_eq!(result.code, Some(1), "stderr: {}", result.stderr); let cause = inherited_failure(&scenario, "issue-20"); // The Ticket's Run says it on its own stderr, between its cause and its - // session log. + // session trace. assert_contains( &result.stderr, &format!( @@ -1324,11 +1322,11 @@ fn a_tickets_run_offers_the_spec_runs_command_with_a_base_fix_and_the_spec_run_r thirdshift: #21: Retry with: thirdshift {spec_url} --email me@example.com parallel 1 base-fix\n\ thirdshift: #21: Or set: base.fix = true in ~/.thirdshift/config.toml, \ to allow a Base fix for every Run on this machine\n\ - thirdshift: #21: session log: " + thirdshift: #21: session trace: " ), ); - // What the Spec run reads back is the cause and the session log, as ever. - let failed = format!("#21 failed: {cause} (session log: "); + // What the Spec run reads back is the cause and the session trace, as ever. + let failed = format!("#21 failed: {cause} (session trace: "); assert_contains(&result.stderr, &format!("thirdshift: {failed}")); let (_, text) = the_one_notification(&resend); assert_contains(&text, &failed); @@ -1741,7 +1739,7 @@ fn the_spec_review_is_logged_under_the_specs_name() { let logged = result .stderr .lines() - .find(|line| line.ends_with("-spec-review.jsonl")) + .find(|line| line.ends_with("-spec-review.logs.jsonl")) .unwrap_or_else(|| panic!("no Spec review log in: {}", result.stderr)); assert_contains(logged, "/20-"); } @@ -1764,7 +1762,7 @@ fn a_failed_spec_review_ends_the_spec_run_without_marking_the_spec_pr_ready() { "stderr: {}", result.stderr ); - assert_contains(&result.stderr, "thirdshift: session log: "); + assert_contains(&result.stderr, "thirdshift: session trace: "); } #[test] @@ -2201,10 +2199,10 @@ fn a_failed_ticket_stops_only_its_dependents_and_is_not_started_again() { .rfind(|line| line.starts_with("thirdshift: #21 failed: ")) .unwrap_or_else(|| panic!("no failed line for #21 in: {}", result.stderr)); assert!( - failed.starts_with("thirdshift: #21 failed: claude exited 1 (session log: "), + failed.starts_with("thirdshift: #21 failed: claude exited 1 (session trace: "), "{failed}" ); - let log = failed.rsplit("session log: ").next().unwrap(); + let log = failed.rsplit("session trace: ").next().unwrap(); assert!( std::path::Path::new(log.trim_end_matches(')')).exists(), "{failed}" @@ -2585,7 +2583,7 @@ fn a_failed_spec_run_sends_one_notification_with_each_tickets_outcome() { ); for part in [ "Cause: Tickets not done: #21, #22\n", - "#21 failed: claude exited 1 (session log: ", + "#21 failed: claude exited 1 (session trace: ", "#22 blocked by #21\n", "#23 landed with https://github.com/acme/widgets/pull/1\n", ] { @@ -3006,7 +3004,7 @@ fn failed_spec_review_reports_preserved_progress_and_the_same_recovery_in_notifi assert_eq!(spec_pr(&scenario)["isDraft"], true); assert_contains(notification, "#21 landed"); assert_contains(notification, "#22 landed"); - assert_contains(notification, "Session log:"); + assert_contains(notification, "Session trace:"); assert_contains(notification, "Command log:"); } @@ -3296,7 +3294,7 @@ fn failed_spec_review_reports_the_same_recovery_in_terminal_and_notification_and "Cause:", "claude exited 1", "Pull request:", - "Session log:", + "Session trace:", "Command log:", "#21 landed with", "#22 landed with", diff --git a/tests/status.rs b/tests/status.rs index e51c0f97f..82c9cc558 100644 --- a/tests/status.rs +++ b/tests/status.rs @@ -146,7 +146,7 @@ gh pr create --base main --head issue-7 --title 'Make widgets' --body 'Closes #7 command["session_log"] .as_str() .unwrap() - .ends_with("-implement.jsonl") + .ends_with("-implement.logs.jsonl") ); assert!(text.stdout.contains("Make widgets"), "{}", text.stdout); assert!(text.stdout.contains("implement ·"), "{}", text.stdout); @@ -321,7 +321,7 @@ fn a_merge_run_retains_delivery_stages_and_their_start_times() { stage["session_log"] .as_str() .unwrap() - .ends_with("-implement.jsonl") + .ends_with("-implement.logs.jsonl") ); } assert_eq!(record["outcome"], "merged"); @@ -737,8 +737,8 @@ fn tokenless_sessions_require_explicit_evidence_to_belong_to_an_owned_command() fs::rename(folder.join("7-fixture.command.json"), &record).unwrap(); let log = folder.join("7-20261003T120000-0400~ownerA.log"); fs::write(&log, "owned Command output\n").unwrap(); - let session = folder.join("7-20261003T120000-0400-implement.jsonl"); - fs::write(&session, "tokenless Session\n").unwrap(); + let session = folder.join("7-20261003T120000-0400-implement.logs.jsonl"); + support::session_trace::write(&session, "tokenless Session\n"); match evidence { "record" => { let mut facts: Value = serde_json::from_slice(&fs::read(&record).unwrap()).unwrap(); @@ -746,7 +746,7 @@ fn tokenless_sessions_require_explicit_evidence_to_belong_to_an_owned_command() fs::write(&record, serde_json::to_vec(&facts).unwrap()).unwrap(); } "models" => fs::write( - session.with_extension("models.json"), + session.with_file_name("7-20261003T120000-0400-implement.models.json"), serde_json::json!({"command_log": log}).to_string(), ) .unwrap(), @@ -883,7 +883,11 @@ fn fixture_log(scenario: &Scenario, relative: &str, contents: &str) { .path("home/.thirdshift/logs/acme/widgets") .join(relative); fs::create_dir_all(path.parent().unwrap()).unwrap(); - fs::write(path, contents).unwrap(); + if relative.ends_with(".logs.jsonl") { + support::session_trace::write(path, contents); + } else { + fs::write(path, contents).unwrap(); + } } #[test] @@ -904,7 +908,7 @@ fn status_reads_activity_starts_from_before_harness_metadata() { ); fixture_log( &scenario, - "commands/issue/7-20261004T120000-0400-implement.jsonl", + "commands/issue/7-20261004T120000-0400-implement.logs.jsonl", "{}\n", ); let result = scenario.run(&["status", "--all", "--json"]); @@ -1089,13 +1093,13 @@ fn status_fills_gaps_by_source_and_groups_only_current_layout_sessions() { ), ); for name in [ - "7-20261001T120000-0400-implement.jsonl", - "8-20261002T120000-0400-spec-review.jsonl", - "10-20261002T120000-0400-implement.jsonl", // Ticket belongs to Spec #8. - "9-20260901T120000-0400-implement.jsonl", - "9-20260901T120000-0400-implement-resume.jsonl", - "9-20260901T120000-0400-repair-1.jsonl", - "9-20260902T120000-0400-implement.jsonl", + "7-20261001T120000-0400-implement.logs.jsonl", + "8-20261002T120000-0400-spec-review.logs.jsonl", + "10-20261002T120000-0400-implement.logs.jsonl", // Ticket belongs to Spec #8. + "9-20260901T120000-0400-implement.logs.jsonl", + "9-20260901T120000-0400-implement-resume.logs.jsonl", + "9-20260901T120000-0400-repair-1.logs.jsonl", + "9-20260902T120000-0400-implement.logs.jsonl", ] { fixture_log(&scenario, &format!("commands/issue/{name}"), "{}\n"); } @@ -1106,8 +1110,8 @@ fn status_fills_gaps_by_source_and_groups_only_current_layout_sessions() { ); fixture_log(&scenario, "commands/issue/bad-name.jsonl", "{}"); for relative in [ - "sessions/widgets-4-20260801T120000-0400-implement.jsonl", - "commands/issue/5-20260801T120000-0400-implement.jsonl", + "sessions/widgets-4-20260801T120000-0400-implement.logs.jsonl", + "commands/issue/5-20260801T120000-0400-implement.logs.jsonl", ] { let path = scenario.path("home/.thirdshift/logs").join(relative); fs::create_dir_all(path.parent().unwrap()).unwrap(); @@ -1423,9 +1427,9 @@ fn repair_resume_and_security_review_keep_their_own_session_logs() { let record = scenario.command_record(LOGS); let stages = record["stages"].as_array().unwrap(); for (name, log) in [ - ("Resume", "-implement-resume.jsonl"), - ("Security review", "-security-review.jsonl"), - ("Repair", "-repair-1.jsonl"), + ("Resume", "-implement-resume.logs.jsonl"), + ("Security review", "-security-review.logs.jsonl"), + ("Repair", "-repair-1.logs.jsonl"), ] { assert!( stages.iter().any(|stage| stage["name"] == name diff --git a/tests/support/mod.rs b/tests/support/mod.rs index dbe052d00..57c95958d 100644 --- a/tests/support/mod.rs +++ b/tests/support/mod.rs @@ -1358,12 +1358,8 @@ test -f {root}/{COPY_REPLACED} self.entries(relative) .into_iter() .filter(|name| { - // Existing transcript assertions select Session logs. Trace - // files are checked explicitly in session_traces.rs. - if extension == "jsonl" - && (name.ends_with(".logs.jsonl") || name.ends_with(".spans.jsonl")) - { - return false; + if extension == "jsonl" { + return name.ends_with(".logs.jsonl"); } Path::new(name) .extension() diff --git a/tests/support/session_trace.rs b/tests/support/session_trace.rs index 7c4d7fbdc..c310be04b 100644 --- a/tests/support/session_trace.rs +++ b/tests/support/session_trace.rs @@ -1,6 +1,56 @@ //! Session-trace fixtures at the on-disk OTLP seam. use serde_json::json; +pub fn artifact(path: &std::path::Path, extension: &str) -> std::path::PathBuf { + let name = path.file_name().unwrap().to_str().unwrap(); + let stem = name + .strip_suffix(".logs.jsonl") + .or_else(|| name.strip_suffix(".spans.jsonl")); + match stem { + Some(stem) => path.with_file_name(format!("{stem}.{extension}")), + None => path.with_extension(extension), + } +} + +/// Write raw Harness fixture events only inside OTLP log records. +pub fn write(path: impl AsRef, lines: impl AsRef) { + std::fs::write(path, records(lines.as_ref())).unwrap(); +} + +/// Recover events for assertions about preserved Harness output. +pub fn events(path: impl AsRef) -> String { + std::fs::read_to_string(path) + .unwrap() + .lines() + .flat_map(|line| { + let request: serde_json::Value = serde_json::from_str(line).unwrap(); + request["resourceLogs"] + .as_array() + .unwrap() + .iter() + .flat_map(|resource| { + resource["scopeLogs"] + .as_array() + .unwrap() + .iter() + .flat_map(|scope| { + scope["logRecords"] + .as_array() + .unwrap() + .iter() + .map(|record| { + record["body"]["stringValue"].as_str().unwrap().to_owned() + }) + .collect::>() + }) + .collect::>() + }) + .collect::>() + }) + .collect::>() + .join("\n") +} + pub fn records(lines: &str) -> String { lines .lines() diff --git a/tests/user_config.rs b/tests/user_config.rs index 07614f421..66abb2a37 100644 --- a/tests/user_config.rs +++ b/tests/user_config.rs @@ -184,7 +184,7 @@ fn help_and_version_succeed_with_a_broken_config() { const AGENT_EXITS_3: &str = "exit 3\n"; /// Assert the Run failed after logging its one session in `commands/issue/` under -/// `acme/widgets/` under `dir`, a directory under the scenario, and that the "session log:" line +/// `acme/widgets/` under `dir`, a directory under the scenario, and that the "session trace:" line /// names that log. fn assert_logged_in(scenario: &Scenario, result: &RunResult, dir: &str) { assert_eq!(result.code, Some(1), "stderr: {}", result.stderr); @@ -195,7 +195,7 @@ fn assert_logged_in(scenario: &Scenario, result: &RunResult, dir: &str) { assert!( result .stderr - .contains(&format!("session log: {}", log.display())), + .contains(&format!("session trace: {}", log.display())), "stderr: {}", result.stderr ); From 57902d983b2abb1ec6e03bf88837deedf4cf3f3a Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Fri, 23 Oct 2026 05:58:16 +0000 Subject: [PATCH 06/10] Resolve review findings and complete trace fixture migration --- console/tests/inbox.test.cjs | 5 +++-- console/tests/logs.test.cjs | 3 ++- console/tests/session-trace.cjs | 8 ++++++++ console/tests/waterfall.test.cjs | 1 + docs/guide.md | 27 --------------------------- site/docs/index.html | 22 ---------------------- site/tests/docs.test.cjs | 7 +++++++ src/session.rs | 2 +- src/session/execution_tests.rs | 2 +- src/session/recording.rs | 5 +++-- src/session/trace.rs | 12 ++---------- tests/run_health.rs | 6 +----- 12 files changed, 29 insertions(+), 71 deletions(-) create mode 100644 console/tests/session-trace.cjs diff --git a/console/tests/inbox.test.cjs b/console/tests/inbox.test.cjs index d5fb4ee82..0552069fd 100644 --- a/console/tests/inbox.test.cjs +++ b/console/tests/inbox.test.cjs @@ -7,6 +7,7 @@ const { tmpdir } = require("node:os"); const { join, resolve } = require("node:path"); const { createInterface } = require("node:readline"); const { chromium } = require("playwright"); +const { record: traceRecord } = require("./session-trace.cjs"); let home, server, exited, browser, origin; before(async () => { @@ -30,7 +31,7 @@ before(async () => { const security = join(configDir, 'logs/acme/widgets/commands/secure'); await mkdir(security, { recursive: true }); const session = join(security, 'secure-fixture-security-audit.logs.jsonl'); - await writeFile(session, JSON.stringify({ resourceLogs: [{ scopeLogs: [{ logRecords: [{ body: { stringValue: 'Security Session output' } }] }] }] }) + '\n'); + await writeFile(session, traceRecord('Security Session output')); await writeFile(join(security, 'secure-fixture.log'), 'Security Command output\n'); await writeFile(join(security, 'secure-fixture.command.json'), JSON.stringify({ version: 1, kind: 'Security run', name: 'secure-fixture', repository: 'acme/widgets', @@ -383,7 +384,7 @@ for (const storage of ['blocked', 'malformed']) { const path = join(dir, '202-fixture.command.json'); const log = join(dir, '202-fixture.log'); const session = join(home, 'heartbeat-session.logs.jsonl'); - const event = text => JSON.stringify({ resourceLogs: [{ scopeLogs: [{ logRecords: [{ body: { stringValue: text } }] }] }] }) + '\n'; + const event = traceRecord; const fixture = JSON.parse(await readFile(join(dir, '1-fixture.command.json'), 'utf8')); Object.assign(fixture, { kind: 'Run', process_id: server.pid, process_start: start, outcome: null, ended_at: null, session_log: session }); fixture.issue.number = 202; diff --git a/console/tests/logs.test.cjs b/console/tests/logs.test.cjs index 72fee68ec..eb5923d53 100644 --- a/console/tests/logs.test.cjs +++ b/console/tests/logs.test.cjs @@ -7,12 +7,13 @@ const { tmpdir } = require("node:os"); const { join, resolve } = require("node:path"); const { createInterface } = require("node:readline"); const { chromium } = require("playwright"); +const { record: traceRecord } = require("./session-trace.cjs"); describe('Session trace', () => { let home, server, exited, browser, origin, folder, log, recordPath, record; const encode = event => { const raw = JSON.stringify(event); - return JSON.stringify({ resourceLogs: [{ scopeLogs: [{ logRecords: [{ body: { stringValue: raw } }] }] }] }) + '\n'; + return traceRecord(raw); }; const message = text => encode({ type: "item.completed", item: { id: text, type: "agent_message", text } }); const tool = text => encode({ type: "item.completed", item: { id: text, type: "command_execution", command: text, aggregated_output: "output", status: "completed", exit_code: 0 } }); diff --git a/console/tests/session-trace.cjs b/console/tests/session-trace.cjs new file mode 100644 index 000000000..d6c95f252 --- /dev/null +++ b/console/tests/session-trace.cjs @@ -0,0 +1,8 @@ +// Session-trace fixtures retain raw Harness events inside OTLP log records. +function record(raw) { + return JSON.stringify({ resourceLogs: [{ scopeLogs: [{ logRecords: [{ + body: { stringValue: raw } + }] }] }] }) + '\n'; +} + +module.exports = { record }; diff --git a/console/tests/waterfall.test.cjs b/console/tests/waterfall.test.cjs index cdfa849c4..b52e64ebd 100644 --- a/console/tests/waterfall.test.cjs +++ b/console/tests/waterfall.test.cjs @@ -164,6 +164,7 @@ test('Waterfall chips, nested scale and unknown tools work at desktop and 390 px assert.match(await chips.textContent(), /acme\/widgets#8 · died/); if (process.platform === 'linux') assert.match(await chips.textContent(), /acme\/widgets#9 · live/); await chips.getByRole('link', { name: 'acme/widgets#7 · merged' }).click(); + await page.getByRole('button', { name: 'Every call', exact: true }).click(); assert.equal(await page.locator('.span-item[data-kind="run"]').count(), 2); const child = page.locator('.span-item[data-kind="run"]').nth(1); assert.equal(await child.locator('.span-item[data-kind="tool"]').count(), 3); diff --git a/docs/guide.md b/docs/guide.md index edcd886da..bce422cf7 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -701,33 +701,6 @@ request left behind. ### Logs -Convert old **Session traces** under this machine's configured `logs.dir`, across -all repositories and including Security runs, in two steps: - -```sh -thirdshift logs --convert -# Read /session-trace-conversion.json before proceeding. -thirdshift logs --remove-converted -``` - -Conversion writes `.logs.jsonl` and `.spans.jsonl` beside each original, using -the live Session-trace writer. The report lists each Session and whether its -conversation, Waterfall, `show` latest event and Model evidence round-trip -without a difference. Recovered Codex diffs are intentional additions, counted -as `codex_diffs`, when Codex's matching local session file still exists. -Missing event times use scoped Command-log progress, then the preceding -estimate or Command start, and carry `thirdshift.time.estimated`. They are -estimates rather than measurements; the Waterfall preserves its old reading. - -The first step keeps every original and never overwrites an existing trace. -Rerunning it skips passed conversions. Sessions with no identifiable Harness, -live Commands, existing traces or reader differences stay in the report for -inspection. The second step removes only passed originals whose original, -trace pair, Model sidecar and Command evidence still match the report's saved -fingerprints. Changed or failed Sessions keep their originals. Sidecars and -review reports stay beside the Session. Both steps and their report stay on -the machine, including Security-run evidence. - Export a Command's whole **Trace** for another tool with: ```sh diff --git a/site/docs/index.html b/site/docs/index.html index 4844959e7..f78b79812 100644 --- a/site/docs/index.html +++ b/site/docs/index.html @@ -632,28 +632,6 @@

      Logs
      -

      Convert old Session traces under this machine's configured logs.dir, across -all repositories and including Security runs, in two steps:

      -
      thirdshift logs --convert
-# Read <logs.dir>/session-trace-conversion.json before proceeding.
-thirdshift logs --remove-converted
-
      -

      Conversion writes .logs.jsonl and .spans.jsonl beside each original, using -the live Session-trace writer. The report lists each Session and whether its -conversation, Waterfall, show latest event and Model evidence round-trip -without a difference. Recovered Codex diffs are intentional additions, counted -as codex_diffs, when Codex's matching local session file still exists. -Missing event times use scoped Command-log progress, then the preceding -estimate or Command start, and carry thirdshift.time.estimated. They are -estimates rather than measurements; the Waterfall preserves its old reading.

      -

      The first step keeps every original and never overwrites an existing trace. -Rerunning it skips passed conversions. Sessions with no identifiable Harness, -live Commands, existing traces or reader differences stay in the report for -inspection. The second step removes only passed originals whose original, -trace pair, Model sidecar and Command evidence still match the report's saved -fingerprints. Changed or failed Sessions keep their originals. Sidecars and -review reports stay beside the Session. Both steps and their report stay on -the machine, including Security-run evidence.

      Export a Command's whole Trace for another tool with:

      thirdshift logs acme/widgets#7 --export ./trace
      diff --git a/site/tests/docs.test.cjs b/site/tests/docs.test.cjs index c84214d09..d10d7bc0a 100644 --- a/site/tests/docs.test.cjs +++ b/site/tests/docs.test.cjs @@ -3,6 +3,13 @@ const assert = require("node:assert/strict"); const { readFile, stat } = require("node:fs/promises"); const { resolve, dirname } = require("node:path"); +test("Session trace documentation does not advertise retired conversion commands", async () => { + for (const file of ["../../docs/guide.md", "../docs/index.html"]) { + const source = await readFile(resolve(__dirname, file), "utf8"); + assert.doesNotMatch(source, /thirdshift logs --(?:convert|remove-converted)\b/, file); + } +}); + test("the README and manual's repository links reach files and section anchors", async () => { const { marked } = await import("marked"); const { default: GithubSlugger } = await import("github-slugger"); diff --git a/src/session.rs b/src/session.rs index b2421a41b..4644c72e3 100644 --- a/src/session.rs +++ b/src/session.rs @@ -615,7 +615,7 @@ mod tests { ); for axis in ["standards", "spec"] { assert_eq!( - fs::read_to_string(log.with_extension(axis)).unwrap(), + fs::read_to_string(logs::session::original(&log).with_extension(axis)).unwrap(), format!("{marker} {axis}") ); } diff --git a/src/session/execution_tests.rs b/src/session/execution_tests.rs index 3e56f7c41..d3ad9c887 100644 --- a/src/session/execution_tests.rs +++ b/src/session/execution_tests.rs @@ -218,7 +218,7 @@ exec sleep 5"#, let mut line = String::new(); loop { line.clear(); - if reader.read_line(&mut line).unwrap() == 0 || line == "ready-to-fail\n" { + if reader.read_line(&mut line).unwrap() == 0 || line.contains("ready-to-fail") { break; } } diff --git a/src/session/recording.rs b/src/session/recording.rs index 098af57c3..e9f4d6ced 100644 --- a/src/session/recording.rs +++ b/src/session/recording.rs @@ -122,7 +122,7 @@ impl Recording { input.stdin, stream, move |output, stream| { - let followed = follow(&kind_owned, output, stream, &streaming_trace); + let followed = follow(&kind_owned, output, &log_owned, stream, &streaming_trace); // The process owner joins this reader before returning, including // on interruption, when it deliberately suppresses state recovery. recording.keep( @@ -283,6 +283,7 @@ struct SessionModels { fn follow( kind: &str, stream: impl Read, + log: &Path, progress: &mut Interpretation, trace: &Mutex, ) -> Result<()> { @@ -303,7 +304,7 @@ fn follow( .lock() .unwrap() .record(&raw, &decoded.events) - .context("could not write the Session trace")?; + .with_context(|| format!("could not write Session trace {}", log.display()))?; for condensed in decoded.progress { progress::step(format_args!("{kind}: {condensed}")); } diff --git a/src/session/trace.rs b/src/session/trace.rs index 4c4d63eca..f65d2b31a 100644 --- a/src/session/trace.rs +++ b/src/session/trace.rs @@ -170,9 +170,7 @@ impl Trace { self.session.span_id }; for event in events { - span_id = self - .apply(event, time.unwrap_or(observed), false)? - .or(span_id); + span_id = self.apply(event, time.unwrap_or(observed))?.or(span_id); for attr in event_attributes(event, self.input_excludes_cache) { set(&mut attrs, attr); } @@ -266,7 +264,7 @@ impl Trace { Ok(()) } - fn apply(&mut self, event: &Event, time: u64, estimated: bool) -> io::Result> { + fn apply(&mut self, event: &Event, time: u64) -> io::Result> { use Event::*; let Some(fact) = Call::of(event) else { if let Usage { @@ -324,12 +322,6 @@ impl Trace { self.locations .insert(call.to_owned(), (key.clone(), span_id)); let mut attrs = event_attributes(event, self.input_excludes_cache); - if estimated { - attrs.push(KeyValue { - key: "thirdshift.time.estimated".into(), - value: Some(AnyValue::Bool(true)), - }); - } if let Some(span) = self.ended.get_mut(&key) { for attr in attrs { set(&mut span.attributes, attr); diff --git a/tests/run_health.rs b/tests/run_health.rs index 538a44e51..b3dd11fbb 100644 --- a/tests/run_health.rs +++ b/tests/run_health.rs @@ -67,11 +67,7 @@ impl LiveRun { command, ), ( - { - let log = PathBuf::from(self.record["session_log"].as_str().unwrap()); - let records = log.clone(); - if records.is_file() { records } else { log } - }, + PathBuf::from(self.record["session_log"].as_str().unwrap()), session, ), ] { From 9c8b521a7949c6d6b783c6c5878cee64f05f549a Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Fri, 23 Oct 2026 06:03:38 +0000 Subject: [PATCH 07/10] Align session prompt assertions with trace recording guidance --- tests/ci.rs | 4 ++-- tests/fresh_run.rs | 2 +- tests/mergeable.rs | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/ci.rs b/tests/ci.rs index 1fde8e233..ea705fbfe 100644 --- a/tests/ci.rs +++ b/tests/ci.rs @@ -256,7 +256,7 @@ fn red_ci_is_handed_to_a_ci_fix_repair_whose_fix_turns_it_green() { \n\ Before additional validation, each push, or any PR edit, check whether this branch's PR remains actionable, using the supplied PR URL when present. If the PR is merged or closed, stop and report its actual state; do not push, recreate its branch, or edit its body. During a Repair, if the PR has become draft, stop and report that gate; do not mark it ready again. If a Repair changes no files, create no commit, including no `--allow-empty` commit, and do not push merely to satisfy this prompt. Push when needed to publish real changes or required upstream reconciliation, after checking the PR again.\n\ \n\ - You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on.\n" + You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on. thirdshift records this session as a Session trace, with Model evidence and any review reports beside it.\n" ); assert_eq!(calls[1]["cwd"], calls[0]["cwd"]); // thirdshift pushes the fix even though the Repair didn't. @@ -1168,7 +1168,7 @@ fn with_mixed_failures_the_repair_fixes_only_the_branchs_own_and_the_run_then_fa \n\ Before additional validation, each push, or any PR edit, check whether this branch's PR remains actionable, using the supplied PR URL when present. If the PR is merged or closed, stop and report its actual state; do not push, recreate its branch, or edit its body. During a Repair, if the PR has become draft, stop and report that gate; do not mark it ready again. If a Repair changes no files, create no commit, including no `--allow-empty` commit, and do not push merely to satisfy this prompt. Push when needed to publish real changes or required upstream reconciliation, after checking the PR again.\n\ \n\ - You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on.\n" + You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on. thirdshift records this session as a Session trace, with Model evidence and any review reports beside it.\n" ); let base_commit = scenario.origin_git(&["rev-parse", "main"]); let cause = inherited_failure("test", &base_commit); diff --git a/tests/fresh_run.rs b/tests/fresh_run.rs index c9ca92d61..26e4630e0 100644 --- a/tests/fresh_run.rs +++ b/tests/fresh_run.rs @@ -234,7 +234,7 @@ fn gives_the_agent_the_fresh_prompt() { \n\ Before additional validation, each push, or any PR edit, check whether this branch's PR remains actionable, using the supplied PR URL when present. If the PR is merged or closed, stop and report its actual state; do not push, recreate its branch, or edit its body. During a Repair, if the PR has become draft, stop and report that gate; do not mark it ready again. If a Repair changes no files, create no commit, including no `--allow-empty` commit, and do not push merely to satisfy this prompt. Push when needed to publish real changes or required upstream reconciliation, after checking the PR again.\n\ \n\ - You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on.\n" + You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on. thirdshift records this session as a Session trace, with Model evidence and any review reports beside it.\n" ); } diff --git a/tests/mergeable.rs b/tests/mergeable.rs index 8151ffc4b..e3dbbde13 100644 --- a/tests/mergeable.rs +++ b/tests/mergeable.rs @@ -121,7 +121,7 @@ fn hands_a_conflicting_merge_to_a_conflict_repair_and_pushes_its_resolution() { \n\ Before additional validation, each push, or any PR edit, check whether this branch's PR remains actionable, using the supplied PR URL when present. If the PR is merged or closed, stop and report its actual state; do not push, recreate its branch, or edit its body. During a Repair, if the PR has become draft, stop and report that gate; do not mark it ready again. If a Repair changes no files, create no commit, including no `--allow-empty` commit, and do not push merely to satisfy this prompt. Push when needed to publish real changes or required upstream reconciliation, after checking the PR again.\n\ \n\ - You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on.\n" + You run headless: nobody is watching, and ending your turn ends the session. Run tests and other long commands in the foreground, raising the command's timeout if needed. If a command is moved to the background, wait for that task by its own task id or output file, never by process names or patterns (`pgrep`, `ps | grep`, and the like): other sessions on this machine run the same commands. Never end your turn while a background task you depend on is still running: ending the turn kills it. Before ending your turn, stop every background task you no longer need, by its task id (with the `TaskStop` tool, if you have it): a task still running when your turn ends is taken as work you were waiting on. thirdshift records this session as a Session trace, with Model evidence and any review reports beside it.\n" ); assert_eq!(repair["merging"], true); assert_eq!(repair["branch"], "issue-7"); From d4e802f4b3c5c6f01236e8ce3a5dbc0decea4f1d Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Fri, 23 Oct 2026 06:11:20 +0000 Subject: [PATCH 08/10] Preserve malformed Harness bytes in Session traces --- src/console/conversation.rs | 2 +- src/logs/session.rs | 11 ++++++++-- src/session/recording.rs | 2 +- src/session/trace.rs | 14 ++++++++----- tests/console.rs | 17 ++++++++++++++++ tests/grok_sessions.rs | 10 ++++------ tests/progress_lines.rs | 40 ++++++++++++++++++++++++++++++------- 7 files changed, 74 insertions(+), 22 deletions(-) diff --git a/src/console/conversation.rs b/src/console/conversation.rs index 890268e01..fa219f899 100644 --- a/src/console/conversation.rs +++ b/src/console/conversation.rs @@ -85,7 +85,7 @@ pub(crate) fn render(lines: &str, kind: Kind) -> String { } fn record_parts(record: LogRecord) -> Vec { - let Some(AnyValue::String(raw)) = record.body else { + let Some(raw) = crate::logs::session::raw_event(record.body) else { return Vec::new(); }; // Backfilled Sessions retain the presentation of their original events. diff --git a/src/logs/session.rs b/src/logs/session.rs index f74bcd955..255a9c4be 100644 --- a/src/logs/session.rs +++ b/src/logs/session.rs @@ -99,10 +99,17 @@ pub(crate) fn tail_events(log: &Path) -> io::Result> { /// A request can contain several resources, scopes and records. Keep their file /// order, preserving raw Harness events inside the OTLP bodies. pub(crate) fn events(lines: &str) -> impl Iterator + '_ { - records(lines).filter_map(|record| match record.body { + records(lines).filter_map(|record| raw_event(record.body)) +} + +/// Preserve byte bodies on disk, while displaying malformed Harness output as +/// text through the same reader used for ordinary string bodies. +pub(crate) fn raw_event(body: Option) -> Option { + match body { Some(AnyValue::String(raw)) => Some(raw), + Some(AnyValue::Bytes(raw)) => Some(String::from_utf8_lossy(&raw).into_owned()), _ => None, - }) + } } /// Keep normalized attributes available to readers that understand them. diff --git a/src/session/recording.rs b/src/session/recording.rs index e9f4d6ced..284c59e8d 100644 --- a/src/session/recording.rs +++ b/src/session/recording.rs @@ -303,7 +303,7 @@ fn follow( trace .lock() .unwrap() - .record(&raw, &decoded.events) + .record(&line, &decoded.events) .with_context(|| format!("could not write Session trace {}", log.display()))?; for condensed in decoded.progress { progress::step(format_args!("{kind}: {condensed}")); diff --git a/src/session/trace.rs b/src/session/trace.rs index f65d2b31a..0276b8640 100644 --- a/src/session/trace.rs +++ b/src/session/trace.rs @@ -127,17 +127,18 @@ impl Trace { }) } - pub fn record(&mut self, raw: &str, events: &[Event]) -> io::Result<()> { - self.record_at(raw, events, now()) + pub fn record(&mut self, raw: impl AsRef<[u8]>, events: &[Event]) -> io::Result<()> { + self.record_at(raw.as_ref(), events, now()) } pub(crate) fn record_at( &mut self, - raw: &str, + bytes: &[u8], events: &[Event], observed: u64, ) -> io::Result<()> { - let envelope: Value = serde_json::from_str(raw).unwrap_or(Value::Null); + let raw = String::from_utf8_lossy(bytes); + let envelope: Value = serde_json::from_str(&raw).unwrap_or(Value::Null); self.record_version(&envelope); let time = event_time(&envelope); let mut attrs = Vec::new(); @@ -199,7 +200,10 @@ impl Trace { log_records: vec![LogRecord { time_unix_nano: time.unwrap_or_default(), observed_time_unix_nano: observed, - body: Some(AnyValue::String(raw.trim_end_matches(['\r', '\n']).into())), + body: Some(match std::str::from_utf8(bytes) { + Ok(raw) => AnyValue::String(raw.trim_end_matches(['\r', '\n']).into()), + Err(_) => AnyValue::Bytes(bytes.to_vec()), + }), event_name: name.into(), trace_id: Some(self.context.trace), span_id, diff --git a/tests/console.rs b/tests/console.rs index 064efcda3..a7fda9475 100644 --- a/tests/console.rs +++ b/tests/console.rs @@ -963,6 +963,23 @@ fn claude_and_codex_conversations_keep_tools_thinking_and_unknown_events() { } } +#[test] +fn session_trace_byte_bodies_render_as_escaped_diagnostics() { + let home = tempfile::tempdir().unwrap(); + configure(home.path()); + let folder = home + .path() + .join(".thirdshift/logs/acme/widgets/commands/issue"); + fs::create_dir_all(&folder).unwrap(); + fs::write(folder.join("7-20261003T120000-0400-implement.logs.jsonl"), + "{\"resourceLogs\":[{\"scopeLogs\":[{\"logRecords\":[{\"body\":{\"bytesValue\":\"YmFkIP8gPHVuc2FmZT4K\"}}]}]}]}\n").unwrap(); + let console = Console::start(Path::new(env!("CARGO_BIN_EXE_thirdshift")), home.path()); + let link = console.log_link("-implement.logs.jsonl"); + let html = console.get(&link).text().unwrap(); + assert!(html.contains("bad � <unsafe>"), "{html}"); + assert!(!html.contains("")); +} + #[test] fn all_six_harness_session_traces_render_normalized_conversations() { let home = tempfile::tempdir().unwrap(); diff --git a/tests/grok_sessions.rs b/tests/grok_sessions.rs index 909fd8f94..238ebf9f0 100644 --- a/tests/grok_sessions.rs +++ b/tests/grok_sessions.rs @@ -134,11 +134,10 @@ echo '{{"type":"assistant","message":{{"content":[{{"type":"tool_use","name":"ru } scenario.assert_every_grok_session_found_the_factory_skills(); let logs = scenario.log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl"); - let log = std::fs::read_to_string(scenario.path(&format!( + let log = support::session_trace::events(scenario.path(&format!( "home/.thirdshift/logs/acme/widgets/commands/issue/{}", logs[0] - ))) - .unwrap(); + ))); assert!(log.contains("fake-grok-1")); assert!(log.contains("\"type\": \"result\"")); assert!( @@ -174,11 +173,10 @@ fn groks_error_is_in_the_failure_cause_even_when_the_cli_exits_zero() { assert_eq!(result.code, Some(1), "{}", result.stderr); assert!(result.stderr.contains(cause), "{}", result.stderr); let logs = scenario.log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl"); - let log = std::fs::read_to_string(scenario.path(&format!( + let log = support::session_trace::events(scenario.path(&format!( "home/.thirdshift/logs/acme/widgets/commands/issue/{}", logs[0] - ))) - .unwrap(); + ))); let results = log .lines() .filter_map(|line| serde_json::from_str::(line).ok()) diff --git a/tests/progress_lines.rs b/tests/progress_lines.rs index 169c88a7a..900a7aa4a 100644 --- a/tests/progress_lines.rs +++ b/tests/progress_lines.rs @@ -247,20 +247,46 @@ fn still_logs_the_whole_stream() { assert_eq!(result.code, Some(0), "{}", result.stderr); let logs = scenario.log_files("home/.thirdshift/logs/acme/widgets/commands/issue", "jsonl"); - let log = std::fs::read( + let log = std::fs::read_to_string( scenario .path("home/.thirdshift/logs/acme/widgets/commands/issue") .join(&logs[0]), ) .unwrap(); - let raw = b"not json at all\n\xffunknown\0\n{\"type\":\n"; - assert!(log.windows(raw.len()).any(|bytes| bytes == raw), "{log:?}"); - let result_event = br#""type": "result""#; + let bodies: Vec = log + .lines() + .flat_map(|line| { + let request: serde_json::Value = serde_json::from_str(line).unwrap(); + request["resourceLogs"][0]["scopeLogs"][0]["logRecords"] + .as_array() + .unwrap() + .iter() + .map(|record| record["body"].clone()) + .collect::>() + }) + .collect(); + assert!( + bodies + .iter() + .any(|body| body["stringValue"] == "not json at all") + ); + // The original invalid UTF-8 and NUL survive exactly in an OTLP byte body. assert!( - log.windows(result_event.len()) - .any(|bytes| bytes == result_event), - "{log:?}" + bodies + .iter() + .any(|body| body["bytesValue"] == "/3Vua25vd24ACg=="), + "{bodies:?}" + ); + assert!( + bodies + .iter() + .any(|body| body["stringValue"] == "{\"type\":") ); + assert!(bodies.iter().any(|body| { + body["stringValue"] + .as_str() + .is_some_and(|raw| raw.contains(r#""type": "result""#)) + })); } #[test] From 136465b8ea815573ed8a58be227ced1f24f53d60 Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Fri, 23 Oct 2026 06:19:32 +0000 Subject: [PATCH 09/10] Exercise converted record references without removing trace records --- tests/export_trace.rs | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/tests/export_trace.rs b/tests/export_trace.rs index 7eabd9aae..82d5ecb5a 100644 --- a/tests/export_trace.rs +++ b/tests/export_trace.rs @@ -149,9 +149,22 @@ fn trace_only_sessions_export_once_even_when_the_record_names_the_old_log() { assert_eq!(run.code, Some(0), "{}", run.stderr); let shown = scenario.run(&["show", "widgets#7", "--json"]); let shown: Value = serde_json::from_str(&shown.stdout).unwrap(); - for session in shown["command"]["session_logs"].as_array().unwrap() { - fs::remove_file(session.as_str().unwrap()).unwrap(); + let record_path = + Path::new(shown["command"]["command_log"].as_str().unwrap()).with_extension("command.json"); + let mut record: Value = serde_json::from_slice(&fs::read(&record_path).unwrap()).unwrap(); + // Converted records retain the former raw filename, while only the trace + // files exist. Exercise that reference without deleting the records file. + record["session_log"] = record["session_log"] + .as_str() + .unwrap() + .replace(".logs.jsonl", ".jsonl") + .into(); + for stage in record["stages"].as_array_mut().unwrap() { + if let Some(path) = stage["session_log"].as_str() { + stage["session_log"] = path.replace(".logs.jsonl", ".jsonl").into(); + } } + fs::write(record_path, serde_json::to_vec(&record).unwrap()).unwrap(); let dir = scenario.path("export"); let result = scenario.run(&["logs", "widgets#7", "--export", dir.to_str().unwrap()]); assert_eq!(result.code, Some(0), "{}", result.stderr); From bb63be85a73873ce6843c20b52263e3cd6b366af Mon Sep 17 00:00:00 2001 From: Jacob Stephens Date: Fri, 23 Oct 2026 07:09:22 +0000 Subject: [PATCH 10/10] Keep Session trace ancestry consistent across views Share dispatch-stage ancestry between the Console and OTLP export, and let dispatched Runs claim their Sessions before ancestor inventory. Retain end-to-end coverage for every span parent, migrate timing reproductions to Session traces, and correct Command-log terminology and the cutover ADR. --- console/README.md | 4 +-- console/reproductions/waterfall-fractional.py | 17 ++++++++-- console/reproductions/waterfall-stage.py | 22 ++++++++++--- ...ift-keeps-a-per-repository-activity-log.md | 2 +- docs/guide.md | 2 +- site/docs/index.html | 2 +- src/console/row.html | 2 +- src/logs/export.rs | 19 +++++------ src/logs/spans.rs | 19 ++++------- src/logs/trace.rs | 16 +++++++++ tests/console.rs | 2 +- tests/export_trace.rs | 33 +++++++++++++++++++ 12 files changed, 102 insertions(+), 38 deletions(-) diff --git a/console/README.md b/console/README.md index a0f2145a9..0b3512d8d 100644 --- a/console/README.md +++ b/console/README.md @@ -201,7 +201,7 @@ has its kind, status, duration and bar on a shared axis. Errors carry their message, running calls extend to now with a hatched bar, and estimated timings are dotted and marked `*`. Converted Session tools keep the old scoped Command-log estimates, including unknown times. Commands without traces still -show their Runs, stages and any retained legacy tool summaries. +show their Runs and stages. The open Slowest calls list ranks ten tool and model calls in the timeline's window; turns and sub-agents are excluded. Selecting a call reveals its row @@ -245,7 +245,7 @@ select a historical Command without a record; `logs --session` accepts an exact path from that Command's Session inventory as well as a session kind. Page 6, `/logs`, lists every Command log and Session trace in the current `commands/` layout, including Security logs, and marks the live ones. Every -Command row links to its Run and Session traces, including child Ticket Runs. +Command row links to its Command logs and Session traces, including child Ticket Runs. Older `sessions/` folders are not linked. The same inventory is available with `thirdshift logs` or `thirdshift logs --json`; `thirdshift logs --file ` reads an exact listed file and accepts `--follow`. diff --git a/console/reproductions/waterfall-fractional.py b/console/reproductions/waterfall-fractional.py index fe3ddd365..ef3ad6119 100644 --- a/console/reproductions/waterfall-fractional.py +++ b/console/reproductions/waterfall-fractional.py @@ -6,8 +6,18 @@ folder = home / '.thirdshift/logs/acme/widgets/commands/issue' folder.mkdir(parents=True) (home / '.thirdshift/config.toml').write_text('[console]\nport = 0\n') - session = folder / '7-20261001T120000+0000-implement.jsonl' - session.write_text(json.dumps({'type':'item.completed','item':{'id':'a','type':'command_execution','command':'rg widgets','status':'completed'}})+'\n') + session = folder / '7-20261001T120000+0000-implement.logs.jsonl' + session.write_text('') + session.with_name(session.name.replace('.logs.jsonl', '.spans.jsonl')).write_text(json.dumps({ + 'resourceSpans': [{'scopeSpans': [{'spans': [ + {'spanId': '1111111111111111', 'name': 'invoke_agent implement', + 'startTimeUnixNano': '1790856000100000000', 'endTimeUnixNano': '1790856060000000000', + 'attributes': [{'key': 'gen_ai.operation.name', 'value': {'stringValue': 'invoke_agent'}}]}, + {'spanId': '2222222222222222', 'parentSpanId': '1111111111111111', 'name': 'execute_tool shell', + 'startTimeUnixNano': '1790856000100125000', 'endTimeUnixNano': '1790856000250375000', + 'attributes': [{'key': 'gen_ai.operation.name', 'value': {'stringValue': 'execute_tool'}}]} + ]}]}] + }) + '\n') record = dict(version=1,kind='Run',repository='acme/widgets',name='run-7', issue=dict(number=7,url='https://github.com/acme/widgets/issues/7',title='Widgets'), hostname='fixture',process_id=0,process_start='gone',harness='codex', @@ -22,7 +32,8 @@ tree = json.load(urllib.request.urlopen(origin+'/spans?command=widgets%237')) tools = [span for span in tree['spans'] if span['kind'] == 'tool'] print('Rendered tool timing:',tools,flush=True) - assert len(tools)==1 and tools[0]['start']==1790856000000, 'The existing matching Command-log line must time this call; fractional record start incorrectly rejects it' + assert len(tools) == 1 and tools[0]['start'] == 1790856000100.125, 'The Session trace must retain the tool start below millisecond precision' + assert tools[0]['duration_ms'] == 150.25, 'The whole-second Command log must not replace the measured duration' finally: server.terminate() server.wait(timeout=10) diff --git a/console/reproductions/waterfall-stage.py b/console/reproductions/waterfall-stage.py index 031a52c2c..ee16fca5a 100644 --- a/console/reproductions/waterfall-stage.py +++ b/console/reproductions/waterfall-stage.py @@ -6,8 +6,18 @@ folder = home / '.thirdshift/logs/acme/widgets/commands/issue' folder.mkdir(parents=True) (home / '.thirdshift/config.toml').write_text('[console]\nport = 0\n') - session = folder / '7-20261001T120000+0000-implement.jsonl' - session.write_text(json.dumps({'type':'item.completed','item':{'id':'a','type':'command_execution','command':'rg widgets','status':'completed'}})+'\n') + session = folder / '7-20261001T120000+0000-implement.logs.jsonl' + session.write_text('') + session.with_name(session.name.replace('.logs.jsonl', '.spans.jsonl')).write_text(json.dumps({ + 'resourceSpans': [{'scopeSpans': [{'spans': [ + {'spanId': '1111111111111111', 'name': 'invoke_agent implement', + 'startTimeUnixNano': '1790856010100000000', 'endTimeUnixNano': '1790856060000000000', + 'attributes': [{'key': 'gen_ai.operation.name', 'value': {'stringValue': 'invoke_agent'}}]}, + {'spanId': '2222222222222222', 'parentSpanId': '1111111111111111', 'name': 'execute_tool shell', + 'startTimeUnixNano': '1790856010125000000', 'endTimeUnixNano': '1790856010250000000', + 'attributes': [{'key': 'gen_ai.operation.name', 'value': {'stringValue': 'execute_tool'}}]} + ]}]}] + }) + '\n') record = dict(version=1,kind='Run',repository='acme/widgets',name='run-7', issue=dict(number=7,url='https://github.com/acme/widgets/issues/7',title='Widgets'), hostname='fixture',process_id=0,process_start='gone',harness='codex', @@ -21,9 +31,13 @@ origin = server.stdout.readline().strip() tree = json.load(urllib.request.urlopen(origin+'/spans?command=widgets%237')) spans = {span['id']: span for span in tree['spans']} - assigned = [spans[span['parent_id']]['name'] for span in tree['spans'] if span['kind'] == 'tool'] + def stage_of(span): + while span['kind'] != 'stage': + span = spans[span['parent_id']] + return span['name'] + assigned = [stage_of(span) for span in tree['spans'] if span['kind'] == 'tool'] print('Stage containing implement tool:',assigned,flush=True) - assert assigned == ['implement'], 'Session tool must nest under implement; whole-second clock incorrectly puts it in previous Setup stage' + assert assigned == ['implement'], 'The Session trace must nest its tool under implement despite the fractional stage start' finally: server.terminate() server.wait(timeout=10) diff --git a/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md b/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md index 0d81b8db6..a90ef81ba 100644 --- a/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md +++ b/docs/adr/0011-thirdshift-keeps-a-per-repository-activity-log.md @@ -15,6 +15,6 @@ This replaces ADR 0009's consequence that a skip leaves only its line in the sch ## Consequences -- The repository in the path is the GitHub repository, `/`, not the name of the local checkout, so log file names drop it: `commands/pickup/41-~.log`. Command logs are exclusively allocated with an immutable random owner token, so Commands sharing a start stamp retain separate output and records. Session logs share the captured stamp and token, as `commands/pickup/41-~-implement.jsonl`, including across child Runs. Model sidecars and review reports use that Session's owned stem. Start stamps remain display and grouping facts. Existing legacy Command logs, Session logs and records remain readable without migration. +- The repository in the path is the GitHub repository, `/`, not the name of the local checkout, so log file names drop it: `commands/pickup/41-~.log`. Command logs are exclusively allocated with an immutable random owner token, so Commands sharing a start stamp retain separate output and records. Session logs share the captured stamp and token, as `commands/pickup/41-~-implement.jsonl`, including across child Runs. Model sidecars and review reports use that Session's owned stem. Start stamps remain display and grouping facts. Existing legacy Command logs and records remain readable without migration. **Amended 2026-10-23 (#700, ADR 0019):** legacy Session logs were converted on both hosts in #994 before #997 removed their reader and the conversion commands. Retained Command records may still name an original Session-log path; readers resolve that reference to its converted Session trace. - Whether the scheduler is still firing is no longer a line per pass: an idle repository's Activity log ends on one skip line. - Logs written before this, under `/sessions/` and `/commands/`, are not moved by thirdshift. diff --git a/docs/guide.md b/docs/guide.md index bce422cf7..e333d3d8e 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -218,7 +218,7 @@ thirdshift logs 'widgets#7' --session implement thirdshift logs 'widgets#7' --session repair --follow ``` -`show` includes the Runs, stage history with start times and Usual ranges, outcomes, and Command and Session trace paths. Each live Run also gets its latest event, such as `Bash: cargo test`, from the last 64 KiB of its current Session trace. It uses the Harness's stream interpretation, including Claude and Codex, and ignores malformed or unknown lines. Missing or unreadable Session traces leave the event unavailable. +`show` includes the Runs, stage history with start times and Usual ranges, outcomes, and paths to Command logs and Session traces. Each live Run also gets its latest event, such as `Bash: cargo test`, from the last 64 KiB of its current Session trace. It uses the Harness's stream interpretation, including Claude and Codex, and ignores malformed or unknown lines. Missing or unreadable Session traces leave the event unavailable. `status` and `show` describe live work as **Silent** when neither its Session trace nor its Command log has grown for `inbox.silent_minutes` (10 by default). Silence starts no earlier than the current stage. A dispatch stage is never Silent or Slow and has no Usual range: the dispatched Run or Spec run carries its own. At three times the threshold, the words escalate: `silent 45 min · past 30`. A fresh line in either log keeps the Run from being Silent. Missing logs use the stage's start time. diff --git a/site/docs/index.html b/site/docs/index.html index f78b79812..3daf67369 100644 --- a/site/docs/index.html +++ b/site/docs/index.html @@ -245,7 +245,7 @@ thirdshift logs 'widgets#7' --session implement thirdshift logs 'widgets#7' --session repair --follow -

      show includes the Runs, stage history with start times and Usual ranges, outcomes, and Command and Session trace paths. Each live Run also gets its latest event, such as Bash: cargo test, from the last 64 KiB of its current Session trace. It uses the Harness's stream interpretation, including Claude and Codex, and ignores malformed or unknown lines. Missing or unreadable Session traces leave the event unavailable.

      +

      show includes the Runs, stage history with start times and Usual ranges, outcomes, and paths to Command logs and Session traces. Each live Run also gets its latest event, such as Bash: cargo test, from the last 64 KiB of its current Session trace. It uses the Harness's stream interpretation, including Claude and Codex, and ignores malformed or unknown lines. Missing or unreadable Session traces leave the event unavailable.

      status and show describe live work as Silent when neither its Session trace nor its Command log has grown for inbox.silent_minutes (10 by default). Silence starts no earlier than the current stage. A dispatch stage is never Silent or Slow and has no Usual range: the dispatched Run or Spec run carries its own. At three times the threshold, the words escalate: silent 45 min · past 30. A fresh line in either log keeps the Run from being Silent. Missing logs use the stage's start time.

      A stage's Usual range is its 25th–75th percentile time over the repository's last 30 Command records on this machine. Completed stages supply times, with the next stage's start or the Command's end marking completion; an unfinished stage supplies none. The range appears once there are at least three stage times. Quartiles interpolate between sorted times. A live Run past the top of the range is Slow: slower than usual (12–17 min), still working. At twice the top it also shows the multiple, such as 2× usual or 3× usual. Silent takes precedence over Slow.

      Both JSON views add health to recorded Commands: {"state":"ok"}, {"state":"slow","step":1,"usual_range":{"lower_seconds":720.0,"upper_seconds":1020.0},"multiple":1}, or {"state":"silent","step":2,"seconds":2700,"threshold_seconds":600}. Step 1 is the first threshold; step 2 is the escalation. Ended or dead Commands have null health. The usual_ranges map gives each stage's range by name, for example {"implement":{"lower_seconds":720.0,"upper_seconds":1020.0}}; a stage is omitted until enough times exist. Health and ranges are reader observations, never written back to Command records.

      diff --git a/src/console/row.html b/src/console/row.html index c93f498af..4d5a5e939 100644 --- a/src/console/row.html +++ b/src/console/row.html @@ -1,7 +1,7 @@
    1. {% if row.live %}{% endif %}{{ row.state }} {% match row.subject_url %}{% when Some with (url) %}{{ row.subject }}{% when None %}{{ row.subject }}{% endmatch %} {{ row.title }}{{ row.age }}

      {{ row.now_line|linkify }}

      - Run and Session traces + Command logs and Session traces {% if !row.harness.is_empty() %}

      {{ row.harness }}

      {% endif %} {% if !row.pull_request.is_empty() %}

      {{ row.pull_request|linkify }}

      {% endif %} {% if row.count > 1 %}

      {{ row.count }} Commands with this cause: {{ row.cause|linkify }}

      {% else if !row.cause.is_empty() %}

      {{ row.cause|linkify }}

      {% endif %} diff --git a/src/logs/export.rs b/src/logs/export.rs index a6528b20b..948cf3d2f 100644 --- a/src/logs/export.rs +++ b/src/logs/export.rs @@ -171,19 +171,16 @@ fn record_spans( Observation::Record(command) .sessions()? .iter() - .map(|session| { - match session - .file_name() - .and_then(|name| name.to_str()) - .and_then(|name| name.strip_suffix(".logs.jsonl")) - { - Some(stem) => session.with_file_name(format!("{stem}.jsonl")), - None => session.clone(), - } - }), + .map(|session| super::session::original(session)), ); for child in command.dispatched.iter().chain(&command.children) { - record_spans(child, outer, context.run, spans, sessions)?; + record_spans( + child, + outer, + context.child_parent(&command.record, &child.record), + spans, + sessions, + )?; } Ok(()) } diff --git a/src/logs/spans.rs b/src/logs/spans.rs index c8ccd52b0..40aeb12d3 100644 --- a/src/logs/spans.rs +++ b/src/logs/spans.rs @@ -294,6 +294,12 @@ impl Builder<'_> { span.duration_ms = duration(span.start, span.end); self.spans.push(span); } + // Dispatchers can inventory their child's same-issue Sessions. Let + // descendants claim them first so each Session retains its actual Run. + for child in command.dispatched.iter().chain(&command.children) { + let parent = hex(context.child_parent(&command.record, &child.record)); + self.record(child, parent)?; + } for path in Observation::Record(command).sessions()? { let original = super::session::original(&path); if !self.sessions.insert(original.clone()) { @@ -327,19 +333,6 @@ impl Builder<'_> { self.spans.extend(spans); } } - for child in command.dispatched.iter().chain(&command.children) { - let parent = stages.iter().rev().find(|timing| { - timing.began.is_some_and(|began| { - time(&child.record.started_at) - .is_some_and(|start| start >= began.timestamp_millis()) - }) - }); - let parent = parent.map_or_else( - || run_id.clone(), - |timing| hex(context.stage_id(timing.stage)), - ); - self.record(child, parent)?; - } Ok(()) } } diff --git a/src/logs/trace.rs b/src/logs/trace.rs index ea7e589ac..6aee46dd7 100644 --- a/src/logs/trace.rs +++ b/src/logs/trace.rs @@ -97,6 +97,22 @@ impl Context { ]) } + /// Both retained views place a child Run in the stage that dispatched it. + pub(super) fn child_parent(&self, record: &CommandRecord, child: &CommandRecord) -> SpanId { + let started = chrono::DateTime::parse_from_rfc3339(&child.started_at).ok(); + record + .stages + .iter() + .rev() + .find(|stage| { + chrono::DateTime::parse_from_rfc3339(&stage.began_at) + .ok() + .zip(started) + .is_some_and(|(began, started)| began <= started) + }) + .map_or(self.run, |stage| self.stage_id(stage)) + } + pub(crate) fn of_owner(owner: &Owner) -> Self { let identity = owner.identity().to_string(); Self::with_identity(identity) diff --git a/tests/console.rs b/tests/console.rs index a7fda9475..6d7da879f 100644 --- a/tests/console.rs +++ b/tests/console.rs @@ -1263,7 +1263,7 @@ fn child_runs_nest_and_each_request_reads_current_records() { .split("href=\"") .skip(1) .filter_map(|part| part.split_once('"')) - .find(|(_, label)| label.starts_with(">Run and Session traces")) + .find(|(_, label)| label.starts_with(">Command logs and Session traces")) .unwrap() .0; let parent_logs = console.get(parent_link).text().unwrap(); diff --git a/tests/export_trace.rs b/tests/export_trace.rs index 82d5ecb5a..88887abc7 100644 --- a/tests/export_trace.rs +++ b/tests/export_trace.rs @@ -226,4 +226,37 @@ fn a_pickup_commands_dispatched_spec_and_tickets_export_as_one_whole_trace() { source_lines.iter().map(String::as_str).collect() ); assert_logs_belong_to_trace(&logs, &spans); + let tree = scenario.run(&[ + "show", + outer["command_log"].as_str().unwrap(), + "--spans", + "--json", + ]); + assert_eq!(tree.code, Some(0), "{}", tree.stderr); + let tree: Value = serde_json::from_str(&tree.stdout).unwrap(); + for node in tree["spans"].as_array().unwrap() { + let exported = spans + .iter() + .find(|span| { + let id: String = span + .span_id + .iter() + .map(|byte| format!("{byte:02x}")) + .collect(); + node["id"] == id + }) + .unwrap(); + let parent: String = exported + .parent_span_id + .iter() + .map(|byte| format!("{byte:02x}")) + .collect(); + assert_eq!( + node["parent_id"].as_str().unwrap_or_default(), + parent, + "export ancestry differs from the CLI/Console tree for {} {}", + node["kind"], + node["name"] + ); + } }