From 1b61d7f38156fb3a7221201bef12f6b8d5c93382 Mon Sep 17 00:00:00 2001 From: thanhnv Date: Fri, 3 Jul 2026 10:04:55 +0900 Subject: [PATCH] feat(log): unified CASAN_LOG_LEVEL across Boss, agent step, harness wrapper Add a shared log taxonomy (errorSTEP6), debug harness rc + trace_id, trace payload excerpt, end-of-run 13-STEP summary table, and one JSONL line/step in .specify/logs/pipeline-run.jsonl. New --dry-run stubs all agents but keeps the real wrapper in the loop (deterministic, offline, full 13 STEP + loops). - casan-step.mjs: debug logs for judge verdict, checkpoint, rollback; logger import degrades to noop when the file is copied standalone (T1 test). - casan-harness.sh: debug-log each phase H4-in -> H5 -> [H2-gate] -> H6-exec -> H4-out with its rc; optional CASAN_PHASE_REPORT JSON for the Boss. Default level (info) keeps output close to before; behavior opt-in via env. Co-Authored-By: Claude Opus 4.8 --- .../.specify/scripts/bash/casan-harness.sh | 53 +++- .../.specify/scripts/bash/casan-log.sh | 31 ++ AINative_OKR_CASAN5/scripts/casan-log.mjs | 42 +++ AINative_OKR_CASAN5/scripts/casan-step.mjs | 27 +- .../scripts/run-casan-pipeline.mjs | 273 +++++++++++++++++- 5 files changed, 403 insertions(+), 23 deletions(-) create mode 100644 AINative_OKR_CASAN5/.specify/scripts/bash/casan-log.sh create mode 100644 AINative_OKR_CASAN5/scripts/casan-log.mjs diff --git a/AINative_OKR_CASAN5/.specify/scripts/bash/casan-harness.sh b/AINative_OKR_CASAN5/.specify/scripts/bash/casan-harness.sh index 9b138eb..5305bc2 100755 --- a/AINative_OKR_CASAN5/.specify/scripts/bash/casan-harness.sh +++ b/AINative_OKR_CASAN5/.specify/scripts/bash/casan-harness.sh @@ -27,6 +27,40 @@ TMP_DIR="$PROJECT_ROOT/.specify/logs/tmp" CACHE_DIR="$PROJECT_ROOT/.specify/logs/idempotency" mkdir -p "$TMP_DIR" "$CACHE_DIR" "$(dirname "$FINAL_OUTPUT")" +# Shared log taxonomy (error + casan_log debug harness "action=$ACTION_NAME phase=$1 rc=$2" + PHASE_LOG="${PHASE_LOG:+$PHASE_LOG,}{\"phase\":\"$1\",\"rc\":$2}" +} + +write_phase_report() { + [[ -n "$PHASE_REPORT" ]] || return 0 + printf '{"action":"%s","cache":"%s","phases":[%s]}\n' \ + "$ACTION_NAME" "$CACHE_STATUS" "$PHASE_LOG" > "$PHASE_REPORT" 2>/dev/null || true +} + +run_phase() { # — preserves the failing rc exactly + local phase="$1"; shift + local rc=0 + "$@" || rc=$? + record_phase "$phase" "$rc" + if [[ "$rc" -ne 0 ]]; then + write_phase_report + exit "$rc" + fi +} + hash_text() { if command -v sha256sum >/dev/null 2>&1; then sha256sum | awk '{print $1}' @@ -47,8 +81,9 @@ SAFE_INPUT="$TMP_DIR/security-input-$TRACE_SUFFIX.txt" APPROVED_INPUT="$TMP_DIR/governance-approved-$TRACE_SUFFIX.txt" RAW_OUTPUT="$TMP_DIR/raw-output-$TRACE_SUFFIX.txt" -"$SCRIPT_DIR/security-check.sh" "$INPUT_FILE" "$SAFE_INPUT" input -"$SCRIPT_DIR/governance-check.sh" "$SAFE_INPUT" "$APPROVED_INPUT" "$ACTION_NAME" +casan_log debug harness "action=$ACTION_NAME input=$INPUT_FILE output=$FINAL_OUTPUT key=${IDEMPOTENCY_KEY:0:12}…" +run_phase "H4-in" "$SCRIPT_DIR/security-check.sh" "$INPUT_FILE" "$SAFE_INPUT" input +run_phase "H5" "$SCRIPT_DIR/governance-check.sh" "$SAFE_INPUT" "$APPROVED_INPUT" "$ACTION_NAME" # H2 tool registry gate is in the line of fire for side-effecting actions: # it enforces idempotency key, per-agent permission, and rollback strategy @@ -56,7 +91,7 @@ RAW_OUTPUT="$TMP_DIR/raw-output-$TRACE_SUFFIX.txt" # content-addressed idempotency key above. case "$ACTION_NAME" in write_code|migration|deploy|db_write|external_api|write_file) - CASAN_IDEMPOTENCY_KEY="$IDEMPOTENCY_KEY" "$SCRIPT_DIR/tool-registry-gate.sh" "$ACTION_NAME" + run_phase "H2-gate" env CASAN_IDEMPOTENCY_KEY="$IDEMPOTENCY_KEY" "$SCRIPT_DIR/tool-registry-gate.sh" "$ACTION_NAME" ;; esac @@ -69,18 +104,18 @@ export CASAN_STEP_NAME="${CASAN_STEP_NAME:-$ACTION_NAME}" TOOL_TIMEOUT="${CASAN_TOOL_TIMEOUT_SECONDS:-30}" if [[ -f "$CACHE_META" && -f "$CACHE_OUT" ]]; then - "$SCRIPT_DIR/agent-metrics.sh" "$APPROVED_INPUT" "$RAW_OUTPUT" -- bash -c 'cp "$1" "$CASAN_OUTPUT"' _ "$CACHE_OUT" CACHE_STATUS="cached" + run_phase "H6-exec" "$SCRIPT_DIR/agent-metrics.sh" "$APPROVED_INPUT" "$RAW_OUTPUT" -- bash -c 'cp "$1" "$CASAN_OUTPUT"' _ "$CACHE_OUT" elif [[ "$#" -gt 0 ]]; then - "$SCRIPT_DIR/agent-metrics.sh" "$APPROVED_INPUT" "$RAW_OUTPUT" -- \ + CACHE_STATUS="stored" + run_phase "H6-exec" "$SCRIPT_DIR/agent-metrics.sh" "$APPROVED_INPUT" "$RAW_OUTPUT" -- \ "$SCRIPT_DIR/tool-exec.sh" "$TOOL_TIMEOUT" -- "$@" - CACHE_STATUS="stored" else - "$SCRIPT_DIR/agent-metrics.sh" "$APPROVED_INPUT" "$RAW_OUTPUT" CACHE_STATUS="stored" + run_phase "H6-exec" "$SCRIPT_DIR/agent-metrics.sh" "$APPROVED_INPUT" "$RAW_OUTPUT" fi -"$SCRIPT_DIR/security-check.sh" "$RAW_OUTPUT" "$FINAL_OUTPUT" output +run_phase "H4-out" "$SCRIPT_DIR/security-check.sh" "$RAW_OUTPUT" "$FINAL_OUTPUT" output if [[ "$CACHE_STATUS" == "stored" ]]; then cat < "$CACHE_META" @@ -95,4 +130,6 @@ EOF cp "$FINAL_OUTPUT" "$CACHE_OUT" fi +write_phase_report +casan_log debug harness "action=$ACTION_NAME complete cache=$CACHE_STATUS" echo "CASAN_HARNESS_COMPLETE cache=$CACHE_STATUS key=$IDEMPOTENCY_KEY output=$FINAL_OUTPUT" diff --git a/AINative_OKR_CASAN5/.specify/scripts/bash/casan-log.sh b/AINative_OKR_CASAN5/.specify/scripts/bash/casan-log.sh new file mode 100644 index 0000000..447f945 --- /dev/null +++ b/AINative_OKR_CASAN5/.specify/scripts/bash/casan-log.sh @@ -0,0 +1,31 @@ +#!/usr/bin/env bash +# CASAN shared log helper (source me, do not execute). +# Taxonomy (shared with scripts/casan-log.mjs): error < warn < info < debug < trace. +# CASAN_LOG_LEVEL selects the threshold (default: info). All log lines go to +# stderr so stdout contracts (CASAN_HARNESS_COMPLETE, cache=..., evidence +# .stdout files) stay byte-identical. + +casan_log_num() { + case "$1" in + error) echo 0 ;; + warn) echo 1 ;; + info) echo 2 ;; + debug) echo 3 ;; + trace) echo 4 ;; + *) echo 2 ;; + esac +} + +CASAN_LOG_LEVEL="${CASAN_LOG_LEVEL:-info}" +CASAN_LOG_THRESHOLD="$(casan_log_num "$CASAN_LOG_LEVEL")" + +# casan_log +casan_log() { + local lvl="$1" comp="$2" + shift 2 + [ "$(casan_log_num "$lvl")" -le "$CASAN_LOG_THRESHOLD" ] || return 0 + printf '[%s] %s [%s] %s\n' \ + "$(printf '%s' "$lvl" | tr '[:lower:]' '[:upper:]')" \ + "$(date -u +"%Y-%m-%dT%H:%M:%SZ")" \ + "$comp" "$*" >&2 +} diff --git a/AINative_OKR_CASAN5/scripts/casan-log.mjs b/AINative_OKR_CASAN5/scripts/casan-log.mjs new file mode 100644 index 0000000..faee488 --- /dev/null +++ b/AINative_OKR_CASAN5/scripts/casan-log.mjs @@ -0,0 +1,42 @@ +// CASAN shared log helper (Node side). +// Taxonomy (shared with .specify/scripts/bash/casan-log.sh): +// error(0) < warn(1) < info(2) < debug(3) < trace(4), default info. +// All lines go to stderr so stdout stays reserved for existing outputs. + +export const LEVELS = { error: 0, warn: 1, info: 2, debug: 3, trace: 4 }; + +const raw = (process.env.CASAN_LOG_LEVEL ?? 'info').toLowerCase(); +export const LOG_LEVEL = raw in LEVELS ? raw : 'info'; +export const LOG_THRESHOLD = LEVELS[LOG_LEVEL]; + +export function enabled(level) { + return (LEVELS[level] ?? LEVELS.info) <= LOG_THRESHOLD; +} + +export function log(level, component, message) { + if (!enabled(level)) return; + process.stderr.write( + `[${level.toUpperCase()}] ${new Date().toISOString()} [${component}] ${message}\n`, + ); +} + +// Redaction for trace-level payload excerpts. Mirrors the H4 masking families +// (email/phone/id/credit-card/secret/private-key/conn-string/AWS key) so no +// secret or PII ever reaches the terminal, even at trace. +const REDACTIONS = [ + [/-----BEGIN [A-Z ]*PRIVATE KEY-----[\s\S]*?(-----END [A-Z ]*PRIVATE KEY-----|$)/g, '[REDACTED_PRIVATE_KEY]'], + [/(API[_-]?KEY|ACCESS[_-]?TOKEN|REFRESH[_-]?TOKEN|PASSWORD|JWT[_-]?SECRET|SECRET)\s*[:=]\s*\S+/gi, '$1=[REDACTED]'], + [/(postgres|mysql|mongodb):\/\/[^@\s]+@/gi, '$1://[REDACTED]@'], + [/AKIA[0-9A-Z]{16}/g, '[REDACTED_AWS_KEY]'], + [/[A-Za-z0-9._%+-]+@[A-Za-z0-9.-]+\.[A-Za-z]{2,}/g, '***MASKED_EMAIL***'], + [/\b(?:[0-9]{4}[- ]?){3}[0-9]{4}\b/g, '***MASKED_CARD***'], + [/\b[0-9]{9,12}\b/g, '***MASKED_ID***'], + [/\+?[0-9][0-9 .-]{8,}[0-9]/g, '***MASKED_PHONE***'], +]; + +export function redact(text, maxLen = 200) { + let out = String(text ?? ''); + for (const [re, sub] of REDACTIONS) out = out.replace(re, sub); + if (out.length > maxLen) out = `${out.slice(0, maxLen)}…(+${out.length - maxLen} chars)`; + return out.replace(/\n/g, '\\n'); +} diff --git a/AINative_OKR_CASAN5/scripts/casan-step.mjs b/AINative_OKR_CASAN5/scripts/casan-step.mjs index 9c74843..c0abba0 100644 --- a/AINative_OKR_CASAN5/scripts/casan-step.mjs +++ b/AINative_OKR_CASAN5/scripts/casan-step.mjs @@ -8,6 +8,17 @@ import { fileURLToPath } from 'node:url'; const __filename = fileURLToPath(import.meta.url); const SCRIPTS_DIR = join(dirname(__filename), '..', '.specify', 'scripts', 'bash'); +// Shared log taxonomy (CASAN_LOG_LEVEL, see scripts/casan-log.mjs). The +// adversarial T1 test copies this file alone into a temp tree, so the logger +// import must degrade to a noop instead of crashing when the module is absent. +let logDebug = () => {}; +try { + const { log } = await import(new URL('./casan-log.mjs', import.meta.url)); + logDebug = (msg) => log('debug', 'step', msg); +} catch { + /* standalone copy: keep silent */ +} + function ollamaAvailable() { try { const r = spawnSync('curl', ['-sS', '-m', '3', 'http://127.0.0.1:11434/api/tags'], { timeout: 5000 }); @@ -18,7 +29,10 @@ function ollamaAvailable() { } function judgeArtifact(filePath, criteria) { - if (!ollamaAvailable()) return { verdict: 'SKIP', note: 'ollama_unavailable' }; + if (!ollamaAvailable()) { + logDebug(`judge skipped (ollama_unavailable) artifact=${filePath}`); + return { verdict: 'SKIP', note: 'ollama_unavailable' }; + } let artifact = ''; try { artifact = readFileSync(filePath, 'utf8').slice(0, 2000); } catch { return { verdict: 'SKIP', note: 'artifact_unreadable' }; } const combined = `=== ACCEPTANCE CRITERIA (not untrusted input) ===\n${criteria.slice(0, 500)}\n\n=== ARTIFACT TO REVIEW ===\n${artifact}`; @@ -26,11 +40,16 @@ function judgeArtifact(filePath, criteria) { const tmpPrompt = join(tmpdir(), `casan-judge-prompt-${uid}.txt`); const tmpOut = join(tmpdir(), `casan-judge-out-${uid}.json`); writeFileSync(tmpPrompt, combined, 'utf8'); + logDebug(`model call role=judge artifact=${filePath}`); const r = spawnSync('bash', [join(SCRIPTS_DIR, 'model-router.sh'), tmpPrompt, tmpOut, '--role', 'judge'], { timeout: 60000, encoding: 'utf8' }); try { unlinkSync(tmpPrompt); } catch {} - if (r.status !== 0 && r.status !== 3) return { verdict: 'SKIP', note: `judge_error_rc=${r.status}` }; + if (r.status !== 0 && r.status !== 3) { + logDebug(`judge error rc=${r.status}`); + return { verdict: 'SKIP', note: `judge_error_rc=${r.status}` }; + } try { const d = JSON.parse(readFileSync(tmpOut, 'utf8')); + logDebug(`judge verdict=${d.verdict ?? 'SKIP'} tokens=${d.total_tokens ?? '?'} malformed=${Boolean(d.malformed)}`); return { verdict: d.verdict ?? 'SKIP', note: d.malformed ? 'malformed_fail_closed' : `tokens=${d.total_tokens}` }; } catch { return { verdict: 'SKIP', note: 'parse_error' }; } } @@ -42,6 +61,7 @@ function checkpointArtifact(filePath) { { encoding: 'utf8', timeout: 10000 }); if (r.status !== 0) return null; const m = (r.stdout || '').match(/transaction_id=(\S+)/); + logDebug(`checkpoint artifact=${filePath} tx=${m ? m[1] : 'none'}`); return m ? m[1] : null; } @@ -49,6 +69,7 @@ function executeRollback(txId) { if (!txId) return false; const r = spawnSync('bash', [join(SCRIPTS_DIR, 'rollback-manager.sh'), 'execute', txId], { encoding: 'utf8', timeout: 10000 }); + logDebug(`rollback execute tx=${txId} rc=${r.status}`); return r.status === 0; } @@ -62,6 +83,8 @@ if (!outputPath) { throw new Error('CASAN_OUTPUT is required'); } +logDebug(`step=${step} attempt=${attempt} output=${outputPath}`); + const dirs = [ `docs/output/output_logs/${featureId}/reports`, 'docs/output/ipa-docs/srs', diff --git a/AINative_OKR_CASAN5/scripts/run-casan-pipeline.mjs b/AINative_OKR_CASAN5/scripts/run-casan-pipeline.mjs index e317079..b3d3aab 100644 --- a/AINative_OKR_CASAN5/scripts/run-casan-pipeline.mjs +++ b/AINative_OKR_CASAN5/scripts/run-casan-pipeline.mjs @@ -1,14 +1,58 @@ -import { execFileSync, execSync } from 'node:child_process'; -import { copyFileSync, mkdirSync, readFileSync, readdirSync, statSync, writeFileSync } from 'node:fs'; -import { basename, join } from 'node:path'; +import { execFileSync } from 'node:child_process'; +import { appendFileSync, copyFileSync, mkdirSync, readFileSync, readdirSync, statSync, writeFileSync } from 'node:fs'; +import { dirname, join } from 'node:path'; +import { enabled, log, redact, LOG_LEVEL } from './casan-log.mjs'; + +// --dry-run: walk the FULL 13-STEP diagram with stub agents. Every stub still +// goes through casan-harness.sh (H4-in -> H5 -> H6 -> exec -> H4-out), so log +// levels and pipeline-run.jsonl can be demonstrated deterministically offline. +const dryRun = process.argv.includes('--dry-run'); const featureId = '001-okr-web-app'; const root = process.cwd(); const logDir = `docs/output/output_logs/${featureId}`; const casanDir = `${logDir}/casan`; const reportsDir = `${logDir}/reports`; -const contextPath = `${logDir}/pipeline-context.yaml`; -const bossLog = `${logDir}/00-boss.log.md`; +const contextPath = dryRun ? `${logDir}/pipeline-context.dryrun.yaml` : `${logDir}/pipeline-context.yaml`; +const bossLog = dryRun ? `${logDir}/00-boss.dryrun.log.md` : `${logDir}/00-boss.log.md`; +const runLogPath = '.specify/logs/pipeline-run.jsonl'; +const runId = `${dryRun ? 'dry' : 'run'}-${new Date().toISOString().replace(/[:.]/g, '-')}-${process.pid}`; + +// Map casan-step keys -> STEP ids of the FULL diagram +// (optimize-docs/CASAN_PIPELINE_WORKFLOW.md section 1). STEP4/10/12/13 have no +// real agent step yet; they run as stubs in --dry-run only. +const DIAGRAM_STEP = { + '01-srs': 'STEP1', + '02-bd': 'STEP2', + '03-spec': 'STEP3', + '04-reviewspec': 'STEP5', + '05-plan': 'STEP6', + '06-reviewplan': 'STEP7', + '07-dd': 'STEP8', + '08-testkit': 'STEP8b', + '09-tasks': 'STEP9', + '10-reviewcode': 'STEP11', +}; + +const FULL_DIAGRAM = [ + ['STEP1', 'okr.srs'], + ['STEP2', 'okr.bd'], + ['STEP3', 'speckit.specify'], + ['STEP4', 'speckit.clarify'], + ['STEP5', 'okr.reviewspec'], + ['STEP6', 'speckit.plan'], + ['STEP7', 'okr.reviewplan'], + ['STEP8', 'okr.dd'], + ['STEP8b', 'okr.testkit'], + ['STEP9', 'speckit.tasks'], + ['STEP10', 'speckit.implement'], + ['STEP11', 'okr.reviewcode'], + ['STEP12', 'okr.testkit run-tests'], + ['STEP13', 'deploy'], +]; + +const summaryRows = []; +const loopsFired = []; mkdirSync(casanDir, { recursive: true }); mkdirSync(reportsDir, { recursive: true }); @@ -19,11 +63,18 @@ writeFileSync( ); writeFileSync(bossLog, `# Boss Log ${featureId}\n\n`, 'utf8'); +log('info', 'boss', `pipeline start run_id=${runId} mode=${dryRun ? 'dry-run' : 'real'} log_level=${LOG_LEVEL}`); + function appendBoss(line) { const ts = new Date().toISOString(); writeFileSync(bossLog, `${readFileSync(bossLog, 'utf8')}- ${ts} ${line}\n`, 'utf8'); } +function appendRunLog(record) { + mkdirSync(dirname(runLogPath), { recursive: true }); + appendFileSync(runLogPath, `${JSON.stringify(record)}\n`, 'utf8'); +} + function latestAgentTrace(stepName) { const traceDir = '.specify/logs/trace'; const files = readdirSync(traceDir) @@ -33,7 +84,7 @@ function latestAgentTrace(stepName) { for (const file of files) { const record = JSON.parse(readFileSync(file, 'utf8')); if (record.step === stepName) { - return { traceId: record.trace_id, path: file, status: record.status }; + return { traceId: record.trace_id, path: file, status: record.status, record }; } } throw new Error(`No trace found for ${stepName}`); @@ -55,15 +106,147 @@ function appendContext({ id, agent, output, trace }) { ); } +function readPhaseReport(path) { + try { + return JSON.parse(readFileSync(path, 'utf8')); + } catch { + return null; + } +} + +function phasesBrief(phases) { + if (!phases?.phases?.length) return 'unavailable'; + return `${phases.phases.map((p) => `${p.phase}:rc=${p.rc}`).join(' → ')} (cache=${phases.cache})`; +} + +// Shared post-execution bookkeeping for real and dry-run steps: human logs at +// info/debug, one machine-readable line per step in pipeline-run.jsonl. +function recordStep({ diagram, id, agent, attempt, verdict, ms, trace, phases, input, output, error }) { + const tokens = trace?.record?.total_tokens ?? null; + log('info', 'boss', `${diagram} · ${agent} · verdict=${verdict} · ${ms}ms · attempt=${attempt}`); + log( + 'debug', + 'boss', + `${diagram} detail id=${id} trace_id=${trace?.traceId ?? 'n/a'} status=${trace?.status ?? 'n/a'} tokens=${tokens ?? '?'} input=${input} output=${output} harness=${phasesBrief(phases)}`, + ); + appendRunLog({ + ts: new Date().toISOString(), + run_id: runId, + mode: dryRun ? 'dry-run' : 'real', + step: diagram, + id, + agent, + attempt: Number(attempt), + verdict, + error: error ?? null, + ms, + tokens, + trace_id: trace?.traceId ?? null, + harness: phases?.phases ?? null, + cache: phases?.cache ?? null, + input, + output, + }); + summaryRows.push({ diagram, id, agent, attempt, verdict, ms, tokens }); +} + +// The diagram's self-correcting loops. Logged whenever a review verdict makes +// the Boss re-run an earlier step (STEP5->STEP3, STEP7->STEP6, STEP11->STEP10, +// STEP12->STEP6). +function logLoop(fromStep, verdict, toStep, note) { + const line = `LOOP ${fromStep} verdict=${verdict} → ${toStep} (${note})`; + loopsFired.push(line); + log('warn', 'boss', line); +} + function runHarness({ id, agent, step, attempt = '1' }) { + const diagram = DIAGRAM_STEP[step] ?? step; const input = `${casanDir}/${id}-input.txt`; const output = `${casanDir}/${id}-output.md`; + const phaseReport = `${casanDir}/${id}-phases.json`; const payload = `feature ${featureId}\nstep ${id}\nagent ${agent}\nattempt ${attempt}\nsource docs/input/okr-requirement.md\n`; writeFileSync(input, payload, 'utf8'); appendBoss(`START ${id} ${agent} attempt ${attempt}`); + log('debug', 'boss', `${diagram} start agent=${agent} attempt=${attempt} action=agent_step_${id}`); + if (enabled('trace')) log('trace', 'boss', `${diagram} input payload (redacted): ${redact(payload)}`); + const startedAt = Date.now(); + try { + execFileSync( + '.specify/scripts/bash/casan-harness.sh', + [input, output, `agent_step_${id}`, '--', 'node', 'scripts/casan-step.mjs', step, attempt], + { + cwd: root, + stdio: 'inherit', + env: { + ...process.env, + CASAN_AGENT: agent, + CASAN_AGENT_NAME: agent, + CASAN_STEP_NAME: id, + CASAN_PHASE_REPORT: phaseReport, + }, + }, + ); + } catch (error) { + const ms = Date.now() - startedAt; + const phases = readPhaseReport(phaseReport); + log('error', 'boss', `${diagram} · ${agent} · FAILED rc=${error.status ?? '?'} · ${ms}ms · harness=${phasesBrief(phases)}`); + recordStep({ diagram, id, agent, attempt, verdict: 'ERROR', ms, trace: null, phases, input, output, error: `harness rc=${error.status ?? 'unknown'}` }); + throw error; + } + const ms = Date.now() - startedAt; + const trace = latestAgentTrace(id); + appendContext({ id, agent, output, trace }); + const verdict = verdictFromOutput(output); + appendBoss(`END ${id} verdict ${verdict} trace ${trace.traceId}`); + const phases = readPhaseReport(phaseReport); + recordStep({ diagram, id, agent, attempt, verdict, ms, trace, phases, input, output }); + if (enabled('trace')) log('trace', 'boss', `${diagram} output excerpt (redacted): ${redact(readFileSync(output, 'utf8'))}`); + return { output, verdict, trace }; +} + +function printSummary() { + if (!enabled('info')) return; + const lines = []; + lines.push(''); + lines.push(`═══ CASAN pipeline summary · run_id=${runId} · mode=${dryRun ? 'dry-run' : 'real'} ═══`); + lines.push('STEP | agent | verdict | attempts | last ms | tokens'); + lines.push('--------|------------------------|-----------|----------|---------|-------'); + for (const [diagram, defaultAgent] of FULL_DIAGRAM) { + const rows = summaryRows.filter((r) => r.diagram === diagram); + if (rows.length === 0) { + lines.push(`${diagram.padEnd(7)} | ${defaultAgent.padEnd(22)} | — | 0 | — | — (not in this run${dryRun ? '' : '; stub available via --dry-run'})`); + continue; + } + const last = rows[rows.length - 1]; + lines.push( + `${diagram.padEnd(7)} | ${last.agent.padEnd(22)} | ${String(last.verdict).padEnd(9)} | ${String(rows.length).padEnd(8)} | ${String(last.ms).padEnd(7)} | ${last.tokens ?? '—'}`, + ); + } + lines.push(''); + lines.push(loopsFired.length ? `Loops fired:\n${loopsFired.map((l) => ` - ${l}`).join('\n')}` : 'Loops fired: none'); + lines.push(`Machine-readable log: ${runLogPath} (jq 'select(.run_id=="${runId}")' — 1 dòng/step)`); + console.log(lines.join('\n')); +} + +// ───────────────────────────── dry-run mode ───────────────────────────── +// Stub every agent call but keep the production wrapper in the loop. The stub +// command writes a deterministic artifact containing the wanted verdict, so +// the Boss's verdict parsing, loop handling, and logging all run for real. +function runDryStep({ diagram, agent, attempt = '1', verdict = 'APPROVED', extraEnv = {} }) { + const id = `dry-${diagram}-attempt-${attempt}`; + const input = `${casanDir}/${id}-input.txt`; + const output = `${casanDir}/${id}-output.md`; + const phaseReport = `${casanDir}/${id}-phases.json`; + const payload = `feature ${featureId}\nstep ${diagram}\nagent ${agent}\nattempt ${attempt}\nmode dry-run stub\n`; + writeFileSync(input, payload, 'utf8'); + appendBoss(`START ${id} ${agent} attempt ${attempt} (dry-run stub)`); + log('debug', 'boss', `${diagram} start agent=${agent} attempt=${attempt} action=agent_step_${id} (stub agent, harness thật)`); + if (enabled('trace')) log('trace', 'boss', `${diagram} input payload (redacted): ${redact(payload)}`); + const stubCmd = `printf '# %s dry-run stub artifact\\n\\nverdict: %s\\n' '${diagram}' '${verdict}' > "$CASAN_OUTPUT"`; + const startedAt = Date.now(); execFileSync( '.specify/scripts/bash/casan-harness.sh', - [input, output, `agent_step_${id}`, '--', 'node', 'scripts/casan-step.mjs', step, attempt], + [input, output, `agent_step_${id}`, '--', 'bash', '-c', stubCmd], { cwd: root, stdio: 'inherit', @@ -72,32 +255,86 @@ function runHarness({ id, agent, step, attempt = '1' }) { CASAN_AGENT: agent, CASAN_AGENT_NAME: agent, CASAN_STEP_NAME: id, + CASAN_PHASE_REPORT: phaseReport, + ...extraEnv, }, }, ); + const ms = Date.now() - startedAt; const trace = latestAgentTrace(id); appendContext({ id, agent, output, trace }); - appendBoss(`END ${id} verdict ${verdictFromOutput(output)} trace ${trace.traceId}`); - return { output, verdict: verdictFromOutput(output), trace }; + const got = verdictFromOutput(output); + appendBoss(`END ${id} verdict ${got} trace ${trace.traceId}`); + recordStep({ diagram, id, agent, attempt, verdict: got, ms, trace, phases: readPhaseReport(phaseReport), input, output }); + return got; } +if (dryRun) { + const agentOf = Object.fromEntries(FULL_DIAGRAM); + for (const diagram of ['STEP1', 'STEP2', 'STEP3', 'STEP4', 'STEP5']) { + runDryStep({ diagram, agent: agentOf[diagram] }); + } + // STEP6 -> STEP7 with the BACK-TO-PLAN loop firing once (attempt 1 REJECTED). + runDryStep({ diagram: 'STEP6', agent: agentOf.STEP6 }); + let v = runDryStep({ diagram: 'STEP7', agent: agentOf.STEP7, verdict: 'REJECTED' }); + if (v === 'REJECTED') { + logLoop('STEP7', v, 'STEP6', 'BACK-TO-PLAN: re-plan attempt 2'); + runDryStep({ diagram: 'STEP6', agent: agentOf.STEP6, attempt: '2' }); + v = runDryStep({ diagram: 'STEP7', agent: agentOf.STEP7, attempt: '2' }); + } + for (const diagram of ['STEP8', 'STEP8b', 'STEP9', 'STEP10', 'STEP11']) { + runDryStep({ diagram, agent: agentOf[diagram] }); + } + // STEP12 run-tests with the FAIL -> STEP6 loop firing once. + v = runDryStep({ diagram: 'STEP12', agent: agentOf.STEP12, verdict: 'FAIL' }); + if (v === 'FAIL') { + logLoop('STEP12', v, 'STEP6', 'tests FAIL: re-plan then re-test'); + runDryStep({ diagram: 'STEP6', agent: agentOf.STEP6, attempt: '3' }); + v = runDryStep({ diagram: 'STEP12', agent: agentOf.STEP12, attempt: '2', verdict: 'PASS' }); + } + // STEP13's payload mentions "deploy", which H5 correctly classifies as + // high-risk → approval required. Simulate a distinct human approver so the + // dry-run walks the real approval path (separation of duties holds: + // actor=developer != approver=qa-lead). + log('debug', 'boss', 'STEP13 is high-risk (deploy): supplying human approval approver=qa-lead for the dry-run'); + runDryStep({ + diagram: 'STEP13', + agent: agentOf.STEP13, + extraEnv: { CASAN_APPROVAL_DECISION: 'approve', CASAN_APPROVER: 'qa-lead' }, + }); + printSummary(); + log('info', 'boss', `dry-run complete. Boss log: ${bossLog}. Context: ${contextPath}.`); + process.exit(0); +} + +// ───────────────────────────── real pipeline ───────────────────────────── const sequence = [ { id: '01-srs', agent: 'okr.srs', step: '01-srs' }, { id: '02-bd', agent: 'okr.bd', step: '02-bd' }, { id: '03-spec', agent: 'speckit.specify', step: '03-spec' }, { id: '04-reviewspec', agent: 'okr.reviewspec', step: '04-reviewspec' }, { id: '05-plan-attempt-1', agent: 'speckit.plan', step: '05-plan', attempt: '1' }, - { id: '06-reviewplan-attempt-1', agent: 'okr.reviewplan', step: '06-reviewplan', attempt: '1' }, ]; for (const item of sequence) { - runHarness(item); + const { verdict } = runHarness(item); + if (item.step === '04-reviewspec' && verdict === 'REJECTED') { + // Diagram loop STEP5 -> STEP3. The current sequence expects APPROVED here; + // if a rejection ever happens we surface the loop instead of hiding it. + logLoop('STEP5', verdict, 'STEP3', 'review-spec rejected; sequence continues but needs attention'); + } +} + +const reviewPlan1 = runHarness({ id: '06-reviewplan-attempt-1', agent: 'okr.reviewplan', step: '06-reviewplan', attempt: '1' }); +if (reviewPlan1.verdict === 'REJECTED') { + logLoop('STEP7', reviewPlan1.verdict, 'STEP6', 'BACK-TO-PLAN: retrying plan with missing criteria fixed'); } appendBoss('BACK-TO-PLAN triggered by reviewplan rejection; retrying plan with missing criteria fixed.'); runHarness({ id: '07-plan-attempt-2', agent: 'speckit.plan', step: '05-plan', attempt: '2' }); const fallbackOut = `${casanDir}/model-fallback-output.txt`; +log('debug', 'boss', `model-fallback invoked (real primary failure) → ${fallbackOut}`); execFileSync( '.specify/scripts/bash/model-fallback.sh', [ @@ -119,6 +356,7 @@ appendBoss(`Model fallback invoked; output ${fallbackOut}`); // independently in adversarial-harness-tests.sh (H7 drift, two different files). const driftCandidate = `${casanDir}/drift-plan-candidate.txt`; copyFileSync(fallbackOut, driftCandidate); +log('debug', 'boss', 'drift-detect: fallback output vs golden baseline'); execFileSync('.specify/scripts/bash/drift-detect.sh', [ '.specify/level5/golden-runs/okr-plan.golden.txt', driftCandidate, @@ -126,11 +364,18 @@ execFileSync('.specify/scripts/bash/drift-detect.sh', [ ], { cwd: root, stdio: 'inherit' }); appendBoss('Drift detection invoked: fallback output vs golden baseline.'); -runHarness({ id: '08-reviewplan-attempt-2', agent: 'okr.reviewplan', step: '06-reviewplan', attempt: '2' }); +const reviewPlan2 = runHarness({ id: '08-reviewplan-attempt-2', agent: 'okr.reviewplan', step: '06-reviewplan', attempt: '2' }); +if (reviewPlan2.verdict === 'REJECTED') { + logLoop('STEP7', reviewPlan2.verdict, 'STEP6', 'BACK-TO-PLAN attempt 2 still rejected'); +} runHarness({ id: '09-dd', agent: 'okr.dd', step: '07-dd' }); runHarness({ id: '10-testkit', agent: 'okr.testkit', step: '08-testkit' }); runHarness({ id: '11-tasks', agent: 'speckit.tasks', step: '09-tasks' }); -runHarness({ id: '12-reviewcode', agent: 'okr.reviewcode', step: '10-reviewcode' }); +const reviewCode = runHarness({ id: '12-reviewcode', agent: 'okr.reviewcode', step: '10-reviewcode' }); +if (reviewCode.verdict === 'REJECTED') { + // Diagram loop STEP11 -> STEP10 (implement is not an agent step yet). + logLoop('STEP11', reviewCode.verdict, 'STEP10', 'review-code rejected; implement step must be re-run'); +} const rollbackDir = 'docs/output/casan/app-evidence'; mkdirSync(rollbackDir, { recursive: true }); @@ -158,7 +403,9 @@ const execute = execFileSync('.specify/scripts/bash/rollback-manager.sh', ['exec writeFileSync(`${rollbackDir}/rollback-execute.stdout`, execute, 'utf8'); writeFileSync(`${rollbackDir}/rollback-after.txt`, readFileSync(rollbackTarget, 'utf8'), 'utf8'); appendBoss(`Rollback transaction ${tx} executed; before/changed/after evidence captured.`); +log('debug', 'boss', `rollback transaction ${tx} recorded + executed (evidence under ${rollbackDir})`); +printSummary(); const summary = `Pipeline complete. Context: ${contextPath}. Boss log: ${bossLog}. Last step artifacts under ${reportsDir}.\n`; writeFileSync(`${rollbackDir}/pipeline-summary.txt`, summary, 'utf8'); console.log(summary);