Files
shockbot/utils/log.ts
T
Colin McDonnell f662b1a0c8 unify per-run token + cost accounting + persist to WorkflowRun (#547)
* unify per-run token + cost accounting across agents

every agent harness now logs the same 5-column (or 6 with cost) table and
populates the same AgentUsage contract, regardless of agent or upstream
provider. previously OpenCode and the Claude fallback path emitted a 3-col
table whose "Input Tokens" was actually only the non-cached delta, silently
dropping cache read/write — real runs were being reported at ~0.4% of their
true input (e.g. one baseline showed Input=30 while step_finish events
summed to cache_read=724,753).

changes:
- add logTokenTable helper in action/agents/shared.ts with stable columns:
  Input | Cache Read | Cache Write | Output | Total | Cost ($). cost
  column renders only when a value is known.
- action/agents/opencode.ts: accumulate step_finish.part.tokens AND
  step_finish.part.cost (sourced from models.dev inside opencode —
  confirmed working across Anthropic, OpenAI, Google, xAI, DeepSeek,
  Moonshot, and OpenRouter). drop the event.stats.total_tokens fallback
  since that payload has no cache breakdown.
- action/agents/claude.ts: success-path now treats input_tokens as the
  non-cached field (matching OpenCode semantics), carries
  cache_read_input_tokens / cache_creation_input_tokens separately, and
  captures total_cost_usd from the final result event. the per-message
  fallback accumulator now captures cache fields too so it's no longer
  lossy when the result event never fires.
- formatUsageSummary gains a Cost ($) column that matches the stdout
  table row-for-row; missing values render as "—".
- scripts/token-usage.ts parses all three historical formats (new 5-col,
  legacy 4-col Claude success, legacy 3-col lossy) and explicitly flags
  the lossy runs instead of averaging misleading values.

validation (pnpm play --local, identical "say hello" prompt):

  agent+model                           Input  CacheR  CacheW  Output  Total   Cost
  OpenCode + Anthropic Sonnet 4.6           4  41,177  20,735     129  62,045  $0.0921
  Claude CLI  + Anthropic Sonnet 4.6        9  80,133  11,611     389  92,142  $0.0766
  OpenCode + OpenAI codex-mini         10,893  46,976       0     606  58,475  $0.0059
  OpenCode + Google Gemini 3 Flash         —       —       —       —       —  $0.0114
  OpenCode + xAI Grok 4 Fast                —       —       —       —       —  $0.0035
  OpenCode + DeepSeek Chat             18,854       0       0       1  18,855  $0.0053
  OpenCode + Moonshot Kimi K2.5             —       —       —       —       —  $0.0106
  OpenCode + OpenRouter→Anthropic           —       —       —       —       —  $0.0617
  OpenCode + OpenRouter→OpenAI              —       —       —       —       —  $0.0038

* isolate play.ts from developer gitconfig

play.ts is a CI-emulator but inherits the developer's user- and system-scope
gitconfig. a common local convenience — url."git@github.com:".insteadOf
"https://github.com/" to force SSH auth — gets applied at read time on every
git call inside the temp repo, causing `git remote get-url --push origin`
to return an SSH URL instead of the stored HTTPS one. pullfrog_push_branch's
validatePushDestination (correctly) treats that as tampering and blocks the
push. the agent then burns the full MAX_COMMIT_RETRIES budget trying
workarounds that can't beat a user-scope insteadOf rule, turning a trivial
"say hello" run into a 1.35M-token session.

point GIT_CONFIG_GLOBAL and GIT_CONFIG_SYSTEM at /dev/null inside run() so
the play process and its spawned agent see the same empty gitconfig that
a real CI runner would. CI has no rewrites, so this is a no-op there; dev
machines get CI-identical git state. SSH client config (~/.ssh/config and
keys) is separate from gitconfig and is unaffected, so setupTestRepo's SSH
clone still works locally. setupGit only writes --local scope, so nothing
downstream depends on user-scope values.

verification: with the scratch repo cleaned up and this isolation in place,
OpenCode + Anthropic on the same "say hello" prompt goes from 1,349,654
tokens / $2.00+ to 62,045 tokens / $0.0921 — no retry loop, no push blocks.

* persist aggregated token + cost usage to WorkflowRun

AgentUsage has been memory-only — rendered into the GitHub step summary
and then discarded when the runner tears down. that made questions like
"avg cost per customer per day" require log-spelunking. persist it:

- add Int? columns for inputTokens / outputTokens / cacheReadTokens /
  cacheWriteTokens and a Decimal? costUsd column on workflow_runs.
  Int4's 2.1B ceiling is ~200x larger than any realistic run so BigInt
  would be overkill. costUsd uses the same default Decimal precision
  as existing money columns (accounts.usageUsd, proxy_keys.hwmUsage).

- extend PATCH /api/workflow-run/[runId] to accept the new numeric
  fields alongside the existing artifact strings. per-field type
  validation ensures the allowlist stays scalar-safe and rejects
  negative / non-finite values.

- generalize patchWorkflowRunFields in the action so it accepts a
  mixed string/number payload, and add an aggregateUsage(entries)
  helper that sums per-agent AgentUsage records into a single patch.

- call the reporter from main.ts's outer finally block, gated on
  toolContext. this is the shared cleanup path that every agent
  implementation flows through — claude.ts, opencode.ts, and any
  future harness all push their AgentUsage into toolState.usageEntries
  via the same line 468, so one finally-block call covers them all.
  running in finally also means partial usage gets persisted even
  when the agent errored out mid-run.

* anneal token + cost accounting

follow-up polish from a review pass:

- aggregate usage across commit-retry iterations inside each agent harness.
  previously runClaude / runOpenCode returned only the final retry's usage,
  so any run that hit the dirty-tree retry loop under-counted tokens and
  cost in both the stdout table and the WorkflowRun row. added a shared
  mergeAgentUsage helper in agents/shared.ts; both harnesses now fold each
  iteration's usage into a running total and return the sum.

- scripts/token-usage.ts now handles the unified format with or without
  the Cost ($) column. previously the int-only number regex rejected
  decimals and the 5-cell length check rejected 6-cell rows, so logs
  from post-cost-tracking runs fell through to "no token table". the
  parser now accepts both 5- and 6-cell unified rows, splits int vs
  decimal cells, and averages reported Cost alongside the tokens.

- PATCH /api/workflow-run/[runId] now rejects INT field values above
  INT4_MAX (2_147_483_647) so a malformed payload gets a clean 400
  instead of propagating a Prisma error. also defends against a
  compromised runner sending a deliberately huge value.

- clarifying comments: opencode.ts documents that step_finish.part.cost
  is a per-step delta (empirically verified), main.ts explains that
  toolState.usageEntries already carries merged per-retry usage so
  aggregateUsage just sums entries (one per agent.run()).

- tests for aggregateUsage and mergeAgentUsage — 12 new cases covering
  empty / partial / multi-agent inputs and the "keep undefined" semantic
  that prevents spurious zeros from being persisted.

- drop `as number` cast in logTokenTable — narrow via const instead.

* anneal: clamp INT overflow + guarantee mergeAgentUsage immutability

second review pass surfaced two defensive gaps:

- a single token field exceeding INT4_MAX would pass the client but be
  rejected by the server's per-field validator, writing a partial row
  with some NULLs where sums belonged. clamp in aggregateUsage so the
  wire payload is always self-consistent across all numeric columns,
  with a loud warning so the clamp doesn't silently swallow weirdness.

- mergeAgentUsage's single-sided branches returned the input reference.
  callers treat AgentUsage as immutable but future callers might not;
  always return a fresh shallow copy instead. two new tests guarantee
  the no-mutation-leak property.

no behavior change in the happy path — INT4_MAX is ~200x the largest
realistic per-run token count.

* anneal: resilient usage persistence + cross-platform null device

third review pass surfaced three small issues:

- main.ts finally block: writeGitHubUsageSummaryToFile throwing would
  skip the WorkflowRun usage PATCH. both are independent best-effort
  cleanup tasks — wrap the former in catch so a filesystem failure
  doesn't block DB persistence.

- AgentUsage.inputTokens had no jsdoc explaining that it's the full
  billable input (cached + non-cached). the same word "Input" means
  "non-cached only" in the stdout/markdown tables (derived by
  subtraction). document the semantic so dashboards querying
  WorkflowRun.inputTokens don't misinterpret it.

- play.ts gitconfig isolation was hard-coded to "/dev/null" which
  doesn't exist on Windows. use `os.devNull` for cross-platform
  parity (resolves to `\\.\nul` on win32). the project is Linux-only
  in CI so this only helps local Windows contributors, but it's a
  zero-cost swap.

also updated the finally-block caveat comment: usage is only pushed
to toolState.usageEntries when agent.run() returns an AgentResult,
not when the timeout race rejects — so timed-out runs don't
persist partial usage. documented instead of trying to thread state
through Promise.race.

* anneal: NaN-guard cost accumulators + clarify inputTokens docs

final polish from review round 4:

- guard both cost accumulators (opencode step_finish.part.cost and claude
  result.total_cost_usd) with Number.isFinite. `typeof x === "number"`
  accepts NaN, and one NaN `+=` would poison the running total for the
  whole session.

- reword prisma schema comment on WorkflowRun usage fields to call out
  that cacheReadTokens / cacheWriteTokens are SUB-totals within
  inputTokens (not additional tokens on top). prevents future dashboards
  from double-counting by ~2x when summing "total tokens used".
2026-04-20 21:27:54 +00:00

395 lines
12 KiB
TypeScript

/**
* Logging utilities that work well in both local and GitHub Actions environments
*/
import { AsyncLocalStorage } from "node:async_hooks";
import * as core from "@actions/core";
import { table } from "table";
import { type AgentUsage, formatCostUsd } from "../agents/shared.ts";
import { isGitHubActions, isInsideDocker } from "./globals.ts";
// --- log prefix via AsyncLocalStorage ---
type LogContext = { prefix: string };
const logContext = new AsyncLocalStorage<LogContext>();
const MAGENTA = "\x1b[35m";
const RESET = "\x1b[0m";
/** run `fn` with every log line prefixed by `prefix` (e.g. "[task-label]") in magenta */
export function withLogPrefix<T>(prefix: string, fn: () => Promise<T>): Promise<T> {
return logContext.run({ prefix }, fn);
}
function prefixLines(message: string): string {
const ctx = logContext.getStore();
if (!ctx) return message;
const colored = `${MAGENTA}${ctx.prefix}${RESET} `;
return message
.split("\n")
.map((line) => `${colored}${line}`)
.join("\n");
}
/** plain-text prefix (no ANSI) for GitHub Actions group names */
function prefixPlain(name: string): string {
const ctx = logContext.getStore();
if (!ctx) return name;
return `${ctx.prefix} ${name}`;
}
const isRunnerDebugEnabled = () => core.isDebug();
const isLocalDebugEnabled = () =>
process.env.LOG_LEVEL === "debug" || process.env.ACTIONS_STEP_DEBUG === "true";
const isDebugEnabled = () => isLocalDebugEnabled() || isRunnerDebugEnabled();
/** timestamp prefix for debug mode — empty string when debug is off */
function ts(): string {
return isDebugEnabled() ? `[${new Date().toISOString()}] ` : "";
}
/**
* Format arguments into a single string for logging
*/
function formatArgs(args: unknown[]): string {
return args
.map((arg) => {
if (typeof arg === "string") return arg;
if (arg instanceof Error) return `${arg.message}\n${arg.stack}`;
return JSON.stringify(arg);
})
.join(" ");
}
/**
* Start a collapsed group (GitHub Actions) or regular group (local)
*/
function startGroup(name: string): void {
const prefixed = prefixPlain(name);
if (isGitHubActions) {
core.startGroup(prefixed);
} else {
console.group(prefixed);
}
}
/**
* End a collapsed group
*/
function endGroup(): void {
if (isGitHubActions) {
core.endGroup();
} else {
console.groupEnd();
}
}
/**
* Run a callback within a collapsed group
*/
function group(name: string, fn: () => void): void {
startGroup(name);
fn();
endGroup();
}
/**
* Print a formatted box with text (for console output)
*/
function boxString(
text: string,
options?: {
title?: string;
maxWidth?: number;
indent?: string;
padding?: number;
}
): string {
const { title, maxWidth = 80, indent = "", padding = 1 } = options || {};
const lines = text.trim().split("\n");
const wrappedLines: string[] = [];
for (const line of lines) {
if (line.length <= maxWidth - padding * 2) {
wrappedLines.push(line);
} else {
const words = line.split(" ");
let currentLine = "";
for (const word of words) {
const testLine = currentLine ? `${currentLine} ${word}` : word;
if (testLine.length <= maxWidth - padding * 2) {
currentLine = testLine;
} else {
if (currentLine) {
wrappedLines.push(currentLine);
currentLine = "";
}
// wrap long words by breaking them into chunks
const maxLineLength = maxWidth - padding * 2;
let remainingWord = word;
while (remainingWord.length > maxLineLength) {
wrappedLines.push(remainingWord.substring(0, maxLineLength));
remainingWord = remainingWord.substring(maxLineLength);
}
currentLine = remainingWord;
}
}
if (currentLine) {
wrappedLines.push(currentLine);
}
}
}
const maxLineLength = Math.max(...wrappedLines.map((line) => line.length));
const contentBoxWidth = maxLineLength + padding * 2;
// ensure box width is at least as wide as the title line when title exists
const titleLineLength = title ? ` ${title} `.length : 0;
const boxWidth = Math.max(contentBoxWidth, titleLineLength);
let result = "";
if (title) {
const titleLine = ` ${title} `;
const titlePadding = Math.max(0, boxWidth - titleLine.length);
result += `${indent}${titleLine}${"─".repeat(titlePadding)}\n`;
}
if (!title) {
result += `${indent}${"─".repeat(boxWidth)}\n`;
}
for (const line of wrappedLines) {
const paddedLine = line.padEnd(maxLineLength);
result += `${indent}${" ".repeat(padding)}${paddedLine}${" ".repeat(padding)}\n`;
}
result += `${indent}${"─".repeat(boxWidth)}`;
return result;
}
/**
* Print a formatted box with text
*/
function box(
text: string,
options?: {
title?: string;
maxWidth?: number;
}
): void {
const boxContent = boxString(text, options);
core.info(prefixLines(boxContent));
}
/**
* Overwrite the job summary with the given text.
* Skips if:
* - Not in GitHub Actions
* - Running inside Docker (CI tests inherit host env vars but can't access host paths)
* - GITHUB_STEP_SUMMARY not set
*/
export async function writeSummary(text: string): Promise<void> {
if (!isGitHubActions) return;
// CI tests run in Docker with GITHUB_ACTIONS=true inherited from host,
// but the GITHUB_STEP_SUMMARY path points to a host filesystem location
// that doesn't exist inside the container
if (isInsideDocker) return;
if (!process.env.GITHUB_STEP_SUMMARY) return;
await core.summary.addRaw(text).write({ overwrite: true });
}
/**
* Print a formatted table using the table package
*/
function printTable(
rows: Array<Array<{ data: string; header?: boolean } | string>>,
options?: {
title?: string;
}
): void {
const { title } = options || {};
// Convert rows to string arrays for the table package
const tableData = rows.map((row) =>
row.map((cell) => {
if (typeof cell === "string") {
return cell;
}
return cell.data;
})
);
const formatted = table(tableData);
if (title) {
core.info(prefixLines(`\n${title}`));
}
core.info(prefixLines(`\n${formatted}\n`));
}
/**
* Print a separator line
*/
function separator(length: number = 50): void {
const separatorText = "─".repeat(length);
core.info(prefixLines(separatorText));
}
/**
* Main logging utility object - import this once and access all utilities
*/
export const log = {
/** Print info message */
info: (...args: unknown[]): void => {
core.info(prefixLines(`${ts()}${formatArgs(args)}`));
},
/** Print a warning message. Use only for warnings that should be displayed in the job summary. */
warning: (...args: unknown[]): void => {
core.warning(prefixLines(`${ts()}${formatArgs(args)}`));
},
/** Print an error message. Use only for errors that should be displayed in the job summary. */
error: (...args: unknown[]): void => {
core.error(prefixLines(`${ts()}${formatArgs(args)}`));
},
/** Print success message */
success: (...args: unknown[]): void => {
core.info(prefixLines(`${ts()}» ${formatArgs(args)}`));
},
/** Print debug message (only when debug mode is enabled) */
debug: (...args: unknown[]): void => {
if (isRunnerDebugEnabled()) {
core.debug(prefixLines(formatArgs(args)));
return;
}
if (isLocalDebugEnabled()) {
core.info(prefixLines(`${ts()}[DEBUG] ${formatArgs(args)}`));
}
},
/** Print a formatted box with text */
box,
/** Print a formatted table using the table package */
table: printTable,
/** Print a separator line */
separator,
/** Start a collapsed group (GitHub Actions) or regular group (local) */
startGroup,
/** End a collapsed group */
endGroup,
/** Run a callback within a collapsed group */
group,
/** Log tool call information to console with formatted output */
toolCall: ({ toolName, input }: { toolName: string; input: unknown }): void => {
const inputFormatted = formatJsonValue(input);
const output = inputFormatted !== "{}" ? `» ${toolName}(${inputFormatted})` : `» ${toolName}()`;
log.info(output.trimEnd());
},
};
/**
* Format a value as JSON, using compact format for simple values and pretty-printed for complex ones
*/
export function formatJsonValue(value: unknown): string {
const compact = JSON.stringify(value);
return compact.length > 80 || compact.includes("\n") ? JSON.stringify(value, null, 2) : compact;
}
/**
* Format a multi-line string with proper indentation for tool call output
* First line has the label, subsequent lines are indented 4 spaces
*/
export function formatIndentedField(label: string, content: string): string {
if (!content.includes("\n")) {
return ` ${label}: ${content}\n`;
}
const lines = content.split("\n");
let formatted = ` ${label}: ${lines[0]}\n`;
for (let i = 1; i < lines.length; i++) {
formatted += ` ${lines[i]}\n`;
}
return formatted;
}
/**
* format aggregated usage data as a markdown table for the GitHub step summary.
*
* columns mirror the per-run stdout token table emitted by `logTokenTable`
* (Input / Cache Read / Cache Write / Output / Total / Cost ($)) so the job
* summary and the in-run logs can be compared row-for-row.
*
* notes:
* - `AgentUsage.inputTokens` is the sum of non-cached input + cache read
* + cache write (set that way by both agent harnesses' `buildUsage`),
* so the non-cached Input column is recovered by subtracting cache fields.
* - `costUsd` is sourced from models.dev (OpenCode) or `total_cost_usd`
* (Claude CLI). absent rows show `—` so per-agent coverage is obvious.
*/
export function formatUsageSummary(entries: AgentUsage[]): string {
if (entries.length === 0) return "";
const header = "| Agent | Input | Cache Read | Cache Write | Output | Total | Cost ($) |";
const separatorRow = "| --- | ---: | ---: | ---: | ---: | ---: | ---: |";
const fmt = (n: number) => n.toLocaleString("en-US");
const nonCachedInput = (e: AgentUsage): number =>
Math.max(0, e.inputTokens - (e.cacheReadTokens ?? 0) - (e.cacheWriteTokens ?? 0));
const totalFor = (e: AgentUsage): number =>
nonCachedInput(e) + (e.cacheReadTokens ?? 0) + (e.cacheWriteTokens ?? 0) + e.outputTokens;
const costCell = (e: AgentUsage): string =>
typeof e.costUsd === "number" && e.costUsd > 0 ? formatCostUsd(e.costUsd) : "—";
const rows = entries.map(
(e) =>
`| ${e.agent} | ${fmt(nonCachedInput(e))} | ${fmt(e.cacheReadTokens ?? 0)} | ${fmt(e.cacheWriteTokens ?? 0)} | ${fmt(e.outputTokens)} | ${fmt(totalFor(e))} | ${costCell(e)} |`
);
const totalsRows: string[] = [];
if (entries.length > 1) {
const totalInput = entries.reduce((sum, e) => sum + nonCachedInput(e), 0);
const totalOutput = entries.reduce((sum, e) => sum + e.outputTokens, 0);
const totalCacheRead = entries.reduce((sum, e) => sum + (e.cacheReadTokens ?? 0), 0);
const totalCacheWrite = entries.reduce((sum, e) => sum + (e.cacheWriteTokens ?? 0), 0);
const grandTotal = totalInput + totalCacheRead + totalCacheWrite + totalOutput;
const totalCostUsd = entries.reduce((sum, e) => sum + (e.costUsd ?? 0), 0);
const totalCostCell = totalCostUsd > 0 ? `**${formatCostUsd(totalCostUsd)}**` : "—";
totalsRows.push(
`| **Total** | **${fmt(totalInput)}** | **${fmt(totalCacheRead)}** | **${fmt(totalCacheWrite)}** | **${fmt(totalOutput)}** | **${fmt(grandTotal)}** | ${totalCostCell} |`
);
}
return [
"<details>",
"<summary>Usage</summary>",
"",
header,
separatorRow,
...rows,
...totalsRows,
"",
"</details>",
].join("\n");
}