feat(log): unified CASAN_LOG_LEVEL across Boss, agent step, harness wrapper
Add a shared log taxonomy (error<warn<info<debug<trace, default info) wired through all three layers, plus a machine-readable per-step run log. - scripts/casan-log.mjs + .specify/scripts/bash/casan-log.sh: shared logger ([LEVEL] ts [component] msg), stderr-only so stdout contracts and exit codes are byte-identical. Node side includes trace-level redaction (secret/PII). - run-casan-pipeline.mjs: per-STEP info line, loop-activation warnings (BACK-TO-PLAN, FAIL->STEP6), 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 <noreply@anthropic.com>
This commit is contained in:
thanhnv
co-authored by
Claude Opus 4.8
Claude Opus 4.8
parent
2f06662f5d
commit
1b61d7f381
@@ -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<warn<info<debug<trace via CASAN_LOG_LEVEL).
|
||||
# debug shows each harness phase with its rc; stderr only, stdout untouched.
|
||||
# shellcheck source=casan-log.sh
|
||||
source "$SCRIPT_DIR/casan-log.sh"
|
||||
|
||||
# Optional machine-readable phase report (one JSON object per invocation).
|
||||
# The Boss orchestrator sets CASAN_PHASE_REPORT per step so it can log per-
|
||||
# harness rc at debug level and persist them into pipeline-run.jsonl.
|
||||
PHASE_REPORT="${CASAN_PHASE_REPORT:-}"
|
||||
PHASE_LOG=""
|
||||
CACHE_STATUS="none"
|
||||
|
||||
record_phase() { # <phase-name> <rc>
|
||||
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() { # <phase-name> <command...> — 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 <<EOF > "$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"
|
||||
|
||||
@@ -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 <level> <component> <message...>
|
||||
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
|
||||
}
|
||||
@@ -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');
|
||||
}
|
||||
@@ -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',
|
||||
|
||||
@@ -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,12 +106,71 @@ 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],
|
||||
@@ -72,32 +182,159 @@ function runHarness({ id, agent, step, attempt = '1' }) {
|
||||
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 });
|
||||
appendBoss(`END ${id} verdict ${verdictFromOutput(output)} trace ${trace.traceId}`);
|
||||
return { output, verdict: verdictFromOutput(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}`, '--', 'bash', '-c', stubCmd],
|
||||
{
|
||||
cwd: root,
|
||||
stdio: 'inherit',
|
||||
env: {
|
||||
...process.env,
|
||||
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 });
|
||||
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);
|
||||
|
||||
Reference in New Issue
Block a user