f662b1a0c8
* 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".
395 lines
12 KiB
TypeScript
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");
|
|
}
|