chore: bootstrap project scaffolding
Add architecture doc (research-wiki/ARCHITECTURE.md), CLAUDE.md with tiered SOP for Fable 5, adapted .claude skills/hooks/settings, package skeleton (src/polygateway), pyproject with import-linter contracts, Makefile, .env.example and smoke test.
This commit is contained in:
@@ -0,0 +1,56 @@
|
||||
---
|
||||
name: systematic-debugging
|
||||
description: Use when encountering any bug, test failure, or unexpected behavior, before proposing fixes - find the root cause first; symptom patches are failure
|
||||
---
|
||||
|
||||
# Systematic Debugging
|
||||
|
||||
## 边界声明
|
||||
|
||||
```
|
||||
先定位根因,再动手修。没有根因假设与证据,不提出修复。
|
||||
```
|
||||
|
||||
理由:乱试修复浪费时间且制造新 bug;症状修补会掩盖真实问题,在库场景下同时击穿所有下游项目。系统化定位对简单 bug 同样更快——简单 bug 也有根因。
|
||||
|
||||
## 定位要素(按需取用,不是仪式)
|
||||
|
||||
1. **完整读错误信息与堆栈**——它经常直接给出答案。记下行号、文件、错误码。
|
||||
2. **稳定复现**——不能复现就先收集数据,不要猜。
|
||||
3. **查最近变更**——`git diff`、新依赖、配置与环境差异。已建 graphify 图谱时,可用 `conda run -n PolyGateway graphify path/affected/explain` 追调用链与影响面,免于盲读。
|
||||
4. **多组件系统先取证再归因**——在组件边界加日志(进/出数据、配置传播),跑一次拿到"断在哪一层"的证据,再深入该层。深层调用栈用回溯法(见 `root-cause-tracing.md`):坏值从哪来,一路向上追到源头,在源头修。
|
||||
5. **查结构化运行日志**——若项目有遥测/结构化日志(如 SQLite 遥测表、`research-wiki/schemas/` 登记的表),查事件流与指标趋势,让假设有数据支撑而非纯读码猜测。
|
||||
6. **对照可工作的样例**——同库相似可用代码、`reference/` 参考实现。逐项列差异,不要跳过"这不可能有影响"的差异;参考实现要读完整,不要按印象改编。
|
||||
|
||||
## 假设与修复(纪律)
|
||||
|
||||
- 一次一个假设,写清"我认为根因是 X,因为 Y";用**最小改动**验证,一次只动一个变量。
|
||||
- 修复前先有失败的复现测试(接 `test-driven-development` 结果门);修复只针对根因,禁止"顺手"重构与打包多个改动。
|
||||
- 修完验证:该测试通过、其余测试不回归、原症状确实消失。
|
||||
|
||||
**3 次修复失败 = 停下质疑架构。** 若每次修复都在别处暴露新问题、或修复需要"大动干戈"才能实施,这不是假设错了,是架构错了——停止继续修,与人类讨论架构后再动。
|
||||
|
||||
若彻查后确属环境/时序/外部问题:记录调查过程,实现恰当的处理(重试/超时/报错),加监控埋点。但 95% 的"查无根因"是调查没做完。
|
||||
|
||||
## 红线(出现即停,回到定位)
|
||||
|
||||
- "先快速修一下,回头再查" / "改改 X 试试看" / "大概是 X,先修了再说"
|
||||
- 一次提交多个猜测性修改;注释掉测试或跳过校验让报错消失
|
||||
- 已经失败 2 次还想"再试一个修复"
|
||||
|
||||
## 附属技术
|
||||
|
||||
- `root-cause-tracing.md` — 沿调用栈回溯到源头
|
||||
- `defense-in-depth.md` — 找到根因后的多层校验
|
||||
- `condition-based-waiting.md` — 用条件轮询替代拍脑袋超时
|
||||
|
||||
## Wiki 留痕(`research-wiki/` 存在时)
|
||||
|
||||
得出值得留存的结论时(尤其影响后续任务的),记 finding:
|
||||
|
||||
```bash
|
||||
.claude/tools/research_wiki.py add_entity research-wiki/ --type finding --id <slug> --title "<问题>"
|
||||
.claude/tools/research_wiki.py rebuild_index research-wiki/
|
||||
```
|
||||
|
||||
页内记录:症状、根因、验证方法、修复、影响面;若暴露 design/plan 缺陷,加 `reveals` 边。
|
||||
@@ -0,0 +1,158 @@
|
||||
// Complete implementation of condition-based waiting utilities
|
||||
// From: Lace test infrastructure improvements (2025-10-03)
|
||||
// Context: Fixed 15 flaky tests by replacing arbitrary timeouts
|
||||
|
||||
import type { ThreadManager } from '~/threads/thread-manager';
|
||||
import type { LaceEvent, LaceEventType } from '~/threads/types';
|
||||
|
||||
/**
|
||||
* Wait for a specific event type to appear in thread
|
||||
*
|
||||
* @param threadManager - The thread manager to query
|
||||
* @param threadId - Thread to check for events
|
||||
* @param eventType - Type of event to wait for
|
||||
* @param timeoutMs - Maximum time to wait (default 5000ms)
|
||||
* @returns Promise resolving to the first matching event
|
||||
*
|
||||
* Example:
|
||||
* await waitForEvent(threadManager, agentThreadId, 'TOOL_RESULT');
|
||||
*/
|
||||
export function waitForEvent(
|
||||
threadManager: ThreadManager,
|
||||
threadId: string,
|
||||
eventType: LaceEventType,
|
||||
timeoutMs = 5000
|
||||
): Promise<LaceEvent> {
|
||||
return new Promise((resolve, reject) => {
|
||||
const startTime = Date.now();
|
||||
|
||||
const check = () => {
|
||||
const events = threadManager.getEvents(threadId);
|
||||
const event = events.find((e) => e.type === eventType);
|
||||
|
||||
if (event) {
|
||||
resolve(event);
|
||||
} else if (Date.now() - startTime > timeoutMs) {
|
||||
reject(new Error(`Timeout waiting for ${eventType} event after ${timeoutMs}ms`));
|
||||
} else {
|
||||
setTimeout(check, 10); // Poll every 10ms for efficiency
|
||||
}
|
||||
};
|
||||
|
||||
check();
|
||||
});
|
||||
}
|
||||
|
||||
/**
|
||||
* Wait for a specific number of events of a given type
|
||||
*
|
||||
* @param threadManager - The thread manager to query
|
||||
* @param threadId - Thread to check for events
|
||||
* @param eventType - Type of event to wait for
|
||||
* @param count - Number of events to wait for
|
||||
* @param timeoutMs - Maximum time to wait (default 5000ms)
|
||||
* @returns Promise resolving to all matching events once count is reached
|
||||
*
|
||||
* Example:
|
||||
* // Wait for 2 AGENT_MESSAGE events (initial response + continuation)
|
||||
* await waitForEventCount(threadManager, agentThreadId, 'AGENT_MESSAGE', 2);
|
||||
*/
|
||||
export function waitForEventCount(
|
||||
threadManager: ThreadManager,
|
||||
threadId: string,
|
||||
eventType: LaceEventType,
|
||||
count: number,
|
||||
timeoutMs = 5000
|
||||
): Promise<LaceEvent[]> {
|
||||
return new Promise((resolve, reject) => {
|
||||
const startTime = Date.now();
|
||||
|
||||
const check = () => {
|
||||
const events = threadManager.getEvents(threadId);
|
||||
const matchingEvents = events.filter((e) => e.type === eventType);
|
||||
|
||||
if (matchingEvents.length >= count) {
|
||||
resolve(matchingEvents);
|
||||
} else if (Date.now() - startTime > timeoutMs) {
|
||||
reject(
|
||||
new Error(
|
||||
`Timeout waiting for ${count} ${eventType} events after ${timeoutMs}ms (got ${matchingEvents.length})`
|
||||
)
|
||||
);
|
||||
} else {
|
||||
setTimeout(check, 10);
|
||||
}
|
||||
};
|
||||
|
||||
check();
|
||||
});
|
||||
}
|
||||
|
||||
/**
|
||||
* Wait for an event matching a custom predicate
|
||||
* Useful when you need to check event data, not just type
|
||||
*
|
||||
* @param threadManager - The thread manager to query
|
||||
* @param threadId - Thread to check for events
|
||||
* @param predicate - Function that returns true when event matches
|
||||
* @param description - Human-readable description for error messages
|
||||
* @param timeoutMs - Maximum time to wait (default 5000ms)
|
||||
* @returns Promise resolving to the first matching event
|
||||
*
|
||||
* Example:
|
||||
* // Wait for TOOL_RESULT with specific ID
|
||||
* await waitForEventMatch(
|
||||
* threadManager,
|
||||
* agentThreadId,
|
||||
* (e) => e.type === 'TOOL_RESULT' && e.data.id === 'call_123',
|
||||
* 'TOOL_RESULT with id=call_123'
|
||||
* );
|
||||
*/
|
||||
export function waitForEventMatch(
|
||||
threadManager: ThreadManager,
|
||||
threadId: string,
|
||||
predicate: (event: LaceEvent) => boolean,
|
||||
description: string,
|
||||
timeoutMs = 5000
|
||||
): Promise<LaceEvent> {
|
||||
return new Promise((resolve, reject) => {
|
||||
const startTime = Date.now();
|
||||
|
||||
const check = () => {
|
||||
const events = threadManager.getEvents(threadId);
|
||||
const event = events.find(predicate);
|
||||
|
||||
if (event) {
|
||||
resolve(event);
|
||||
} else if (Date.now() - startTime > timeoutMs) {
|
||||
reject(new Error(`Timeout waiting for ${description} after ${timeoutMs}ms`));
|
||||
} else {
|
||||
setTimeout(check, 10);
|
||||
}
|
||||
};
|
||||
|
||||
check();
|
||||
});
|
||||
}
|
||||
|
||||
// Usage example from actual debugging session:
|
||||
//
|
||||
// BEFORE (flaky):
|
||||
// ---------------
|
||||
// const messagePromise = agent.sendMessage('Execute tools');
|
||||
// await new Promise(r => setTimeout(r, 300)); // Hope tools start in 300ms
|
||||
// agent.abort();
|
||||
// await messagePromise;
|
||||
// await new Promise(r => setTimeout(r, 50)); // Hope results arrive in 50ms
|
||||
// expect(toolResults.length).toBe(2); // Fails randomly
|
||||
//
|
||||
// AFTER (reliable):
|
||||
// ----------------
|
||||
// const messagePromise = agent.sendMessage('Execute tools');
|
||||
// await waitForEventCount(threadManager, threadId, 'TOOL_CALL', 2); // Wait for tools to start
|
||||
// agent.abort();
|
||||
// await messagePromise;
|
||||
// await waitForEventCount(threadManager, threadId, 'TOOL_RESULT', 2); // Wait for results
|
||||
// expect(toolResults.length).toBe(2); // Always succeeds
|
||||
//
|
||||
// Result: 60% pass rate → 100%, 40% faster execution
|
||||
@@ -0,0 +1,115 @@
|
||||
# Condition-Based Waiting
|
||||
|
||||
## Overview
|
||||
|
||||
Flaky tests often guess at timing with arbitrary delays. This creates race conditions where tests pass on fast machines but fail under load or in CI.
|
||||
|
||||
**Core principle:** Wait for the actual condition you care about, not a guess about how long it takes.
|
||||
|
||||
## When to Use
|
||||
|
||||
```dot
|
||||
digraph when_to_use {
|
||||
"Test uses setTimeout/sleep?" [shape=diamond];
|
||||
"Testing timing behavior?" [shape=diamond];
|
||||
"Document WHY timeout needed" [shape=box];
|
||||
"Use condition-based waiting" [shape=box];
|
||||
|
||||
"Test uses setTimeout/sleep?" -> "Testing timing behavior?" [label="yes"];
|
||||
"Testing timing behavior?" -> "Document WHY timeout needed" [label="yes"];
|
||||
"Testing timing behavior?" -> "Use condition-based waiting" [label="no"];
|
||||
}
|
||||
```
|
||||
|
||||
**Use when:**
|
||||
- Tests have arbitrary delays (`setTimeout`, `sleep`, `time.sleep()`)
|
||||
- Tests are flaky (pass sometimes, fail under load)
|
||||
- Tests timeout when run in parallel
|
||||
- Waiting for async operations to complete
|
||||
|
||||
**Don't use when:**
|
||||
- Testing actual timing behavior (debounce, throttle intervals)
|
||||
- Always document WHY if using arbitrary timeout
|
||||
|
||||
## Core Pattern
|
||||
|
||||
```typescript
|
||||
// ❌ BEFORE: Guessing at timing
|
||||
await new Promise(r => setTimeout(r, 50));
|
||||
const result = getResult();
|
||||
expect(result).toBeDefined();
|
||||
|
||||
// ✅ AFTER: Waiting for condition
|
||||
await waitFor(() => getResult() !== undefined);
|
||||
const result = getResult();
|
||||
expect(result).toBeDefined();
|
||||
```
|
||||
|
||||
## Quick Patterns
|
||||
|
||||
| Scenario | Pattern |
|
||||
|----------|---------|
|
||||
| Wait for event | `waitFor(() => events.find(e => e.type === 'DONE'))` |
|
||||
| Wait for state | `waitFor(() => machine.state === 'ready')` |
|
||||
| Wait for count | `waitFor(() => items.length >= 5)` |
|
||||
| Wait for file | `waitFor(() => fs.existsSync(path))` |
|
||||
| Complex condition | `waitFor(() => obj.ready && obj.value > 10)` |
|
||||
|
||||
## Implementation
|
||||
|
||||
Generic polling function:
|
||||
```typescript
|
||||
async function waitFor<T>(
|
||||
condition: () => T | undefined | null | false,
|
||||
description: string,
|
||||
timeoutMs = 5000
|
||||
): Promise<T> {
|
||||
const startTime = Date.now();
|
||||
|
||||
while (true) {
|
||||
const result = condition();
|
||||
if (result) return result;
|
||||
|
||||
if (Date.now() - startTime > timeoutMs) {
|
||||
throw new Error(`Timeout waiting for ${description} after ${timeoutMs}ms`);
|
||||
}
|
||||
|
||||
await new Promise(r => setTimeout(r, 10)); // Poll every 10ms
|
||||
}
|
||||
}
|
||||
```
|
||||
|
||||
See `condition-based-waiting-example.ts` in this directory for complete implementation with domain-specific helpers (`waitForEvent`, `waitForEventCount`, `waitForEventMatch`) from actual debugging session.
|
||||
|
||||
## Common Mistakes
|
||||
|
||||
**❌ Polling too fast:** `setTimeout(check, 1)` - wastes CPU
|
||||
**✅ Fix:** Poll every 10ms
|
||||
|
||||
**❌ No timeout:** Loop forever if condition never met
|
||||
**✅ Fix:** Always include timeout with clear error
|
||||
|
||||
**❌ Stale data:** Cache state before loop
|
||||
**✅ Fix:** Call getter inside loop for fresh data
|
||||
|
||||
## When Arbitrary Timeout IS Correct
|
||||
|
||||
```typescript
|
||||
// Tool ticks every 100ms - need 2 ticks to verify partial output
|
||||
await waitForEvent(manager, 'TOOL_STARTED'); // First: wait for condition
|
||||
await new Promise(r => setTimeout(r, 200)); // Then: wait for timed behavior
|
||||
// 200ms = 2 ticks at 100ms intervals - documented and justified
|
||||
```
|
||||
|
||||
**Requirements:**
|
||||
1. First wait for triggering condition
|
||||
2. Based on known timing (not guessing)
|
||||
3. Comment explaining WHY
|
||||
|
||||
## Real-World Impact
|
||||
|
||||
From debugging session (2025-10-03):
|
||||
- Fixed 15 flaky tests across 3 files
|
||||
- Pass rate: 60% → 100%
|
||||
- Execution time: 40% faster
|
||||
- No more race conditions
|
||||
@@ -0,0 +1,122 @@
|
||||
# Defense-in-Depth Validation
|
||||
|
||||
## Overview
|
||||
|
||||
When you fix a bug caused by invalid data, adding validation at one place feels sufficient. But that single check can be bypassed by different code paths, refactoring, or mocks.
|
||||
|
||||
**Core principle:** Validate at EVERY layer data passes through. Make the bug structurally impossible.
|
||||
|
||||
## Why Multiple Layers
|
||||
|
||||
Single validation: "We fixed the bug"
|
||||
Multiple layers: "We made the bug impossible"
|
||||
|
||||
Different layers catch different cases:
|
||||
- Entry validation catches most bugs
|
||||
- Business logic catches edge cases
|
||||
- Environment guards prevent context-specific dangers
|
||||
- Debug logging helps when other layers fail
|
||||
|
||||
## The Four Layers
|
||||
|
||||
### Layer 1: Entry Point Validation
|
||||
**Purpose:** Reject obviously invalid input at API boundary
|
||||
|
||||
```typescript
|
||||
function createProject(name: string, workingDirectory: string) {
|
||||
if (!workingDirectory || workingDirectory.trim() === '') {
|
||||
throw new Error('workingDirectory cannot be empty');
|
||||
}
|
||||
if (!existsSync(workingDirectory)) {
|
||||
throw new Error(`workingDirectory does not exist: ${workingDirectory}`);
|
||||
}
|
||||
if (!statSync(workingDirectory).isDirectory()) {
|
||||
throw new Error(`workingDirectory is not a directory: ${workingDirectory}`);
|
||||
}
|
||||
// ... proceed
|
||||
}
|
||||
```
|
||||
|
||||
### Layer 2: Business Logic Validation
|
||||
**Purpose:** Ensure data makes sense for this operation
|
||||
|
||||
```typescript
|
||||
function initializeWorkspace(projectDir: string, sessionId: string) {
|
||||
if (!projectDir) {
|
||||
throw new Error('projectDir required for workspace initialization');
|
||||
}
|
||||
// ... proceed
|
||||
}
|
||||
```
|
||||
|
||||
### Layer 3: Environment Guards
|
||||
**Purpose:** Prevent dangerous operations in specific contexts
|
||||
|
||||
```typescript
|
||||
async function gitInit(directory: string) {
|
||||
// In tests, refuse git init outside temp directories
|
||||
if (process.env.NODE_ENV === 'test') {
|
||||
const normalized = normalize(resolve(directory));
|
||||
const tmpDir = normalize(resolve(tmpdir()));
|
||||
|
||||
if (!normalized.startsWith(tmpDir)) {
|
||||
throw new Error(
|
||||
`Refusing git init outside temp dir during tests: ${directory}`
|
||||
);
|
||||
}
|
||||
}
|
||||
// ... proceed
|
||||
}
|
||||
```
|
||||
|
||||
### Layer 4: Debug Instrumentation
|
||||
**Purpose:** Capture context for forensics
|
||||
|
||||
```typescript
|
||||
async function gitInit(directory: string) {
|
||||
const stack = new Error().stack;
|
||||
logger.debug('About to git init', {
|
||||
directory,
|
||||
cwd: process.cwd(),
|
||||
stack,
|
||||
});
|
||||
// ... proceed
|
||||
}
|
||||
```
|
||||
|
||||
## Applying the Pattern
|
||||
|
||||
When you find a bug:
|
||||
|
||||
1. **Trace the data flow** - Where does bad value originate? Where used?
|
||||
2. **Map all checkpoints** - List every point data passes through
|
||||
3. **Add validation at each layer** - Entry, business, environment, debug
|
||||
4. **Test each layer** - Try to bypass layer 1, verify layer 2 catches it
|
||||
|
||||
## Example from Session
|
||||
|
||||
Bug: Empty `projectDir` caused `git init` in source code
|
||||
|
||||
**Data flow:**
|
||||
1. Test setup → empty string
|
||||
2. `Project.create(name, '')`
|
||||
3. `WorkspaceManager.createWorkspace('')`
|
||||
4. `git init` runs in `process.cwd()`
|
||||
|
||||
**Four layers added:**
|
||||
- Layer 1: `Project.create()` validates not empty/exists/writable
|
||||
- Layer 2: `WorkspaceManager` validates projectDir not empty
|
||||
- Layer 3: `WorktreeManager` refuses git init outside tmpdir in tests
|
||||
- Layer 4: Stack trace logging before git init
|
||||
|
||||
**Result:** All 1847 tests passed, bug impossible to reproduce
|
||||
|
||||
## Key Insight
|
||||
|
||||
All four layers were necessary. During testing, each layer caught bugs the others missed:
|
||||
- Different code paths bypassed entry validation
|
||||
- Mocks bypassed business logic checks
|
||||
- Edge cases on different platforms needed environment guards
|
||||
- Debug logging identified structural misuse
|
||||
|
||||
**Don't stop at one validation point.** Add checks at every layer.
|
||||
@@ -0,0 +1,63 @@
|
||||
#!/usr/bin/env bash
|
||||
# Bisection script to find which test creates unwanted files/state
|
||||
# Usage: ./find-polluter.sh <file_or_dir_to_check> <test_pattern>
|
||||
# Example: ./find-polluter.sh '.git' 'src/**/*.test.ts'
|
||||
|
||||
set -e
|
||||
|
||||
if [ $# -ne 2 ]; then
|
||||
echo "Usage: $0 <file_to_check> <test_pattern>"
|
||||
echo "Example: $0 '.git' 'src/**/*.test.ts'"
|
||||
exit 1
|
||||
fi
|
||||
|
||||
POLLUTION_CHECK="$1"
|
||||
TEST_PATTERN="$2"
|
||||
|
||||
echo "🔍 Searching for test that creates: $POLLUTION_CHECK"
|
||||
echo "Test pattern: $TEST_PATTERN"
|
||||
echo ""
|
||||
|
||||
# Get list of test files
|
||||
TEST_FILES=$(find . -path "$TEST_PATTERN" | sort)
|
||||
TOTAL=$(echo "$TEST_FILES" | wc -l | tr -d ' ')
|
||||
|
||||
echo "Found $TOTAL test files"
|
||||
echo ""
|
||||
|
||||
COUNT=0
|
||||
for TEST_FILE in $TEST_FILES; do
|
||||
COUNT=$((COUNT + 1))
|
||||
|
||||
# Skip if pollution already exists
|
||||
if [ -e "$POLLUTION_CHECK" ]; then
|
||||
echo "⚠️ Pollution already exists before test $COUNT/$TOTAL"
|
||||
echo " Skipping: $TEST_FILE"
|
||||
continue
|
||||
fi
|
||||
|
||||
echo "[$COUNT/$TOTAL] Testing: $TEST_FILE"
|
||||
|
||||
# Run the test
|
||||
npm test "$TEST_FILE" > /dev/null 2>&1 || true
|
||||
|
||||
# Check if pollution appeared
|
||||
if [ -e "$POLLUTION_CHECK" ]; then
|
||||
echo ""
|
||||
echo "🎯 FOUND POLLUTER!"
|
||||
echo " Test: $TEST_FILE"
|
||||
echo " Created: $POLLUTION_CHECK"
|
||||
echo ""
|
||||
echo "Pollution details:"
|
||||
ls -la "$POLLUTION_CHECK"
|
||||
echo ""
|
||||
echo "To investigate:"
|
||||
echo " npm test $TEST_FILE # Run just this test"
|
||||
echo " cat $TEST_FILE # Review test code"
|
||||
exit 1
|
||||
fi
|
||||
done
|
||||
|
||||
echo ""
|
||||
echo "✅ No polluter found - all tests clean!"
|
||||
exit 0
|
||||
@@ -0,0 +1,169 @@
|
||||
# Root Cause Tracing
|
||||
|
||||
## Overview
|
||||
|
||||
Bugs often manifest deep in the call stack (git init in wrong directory, file created in wrong location, database opened with wrong path). Your instinct is to fix where the error appears, but that's treating a symptom.
|
||||
|
||||
**Core principle:** Trace backward through the call chain until you find the original trigger, then fix at the source.
|
||||
|
||||
## When to Use
|
||||
|
||||
```dot
|
||||
digraph when_to_use {
|
||||
"Bug appears deep in stack?" [shape=diamond];
|
||||
"Can trace backwards?" [shape=diamond];
|
||||
"Fix at symptom point" [shape=box];
|
||||
"Trace to original trigger" [shape=box];
|
||||
"BETTER: Also add defense-in-depth" [shape=box];
|
||||
|
||||
"Bug appears deep in stack?" -> "Can trace backwards?" [label="yes"];
|
||||
"Can trace backwards?" -> "Trace to original trigger" [label="yes"];
|
||||
"Can trace backwards?" -> "Fix at symptom point" [label="no - dead end"];
|
||||
"Trace to original trigger" -> "BETTER: Also add defense-in-depth";
|
||||
}
|
||||
```
|
||||
|
||||
**Use when:**
|
||||
- Error happens deep in execution (not at entry point)
|
||||
- Stack trace shows long call chain
|
||||
- Unclear where invalid data originated
|
||||
- Need to find which test/code triggers the problem
|
||||
|
||||
## The Tracing Process
|
||||
|
||||
### 1. Observe the Symptom
|
||||
```
|
||||
Error: git init failed in ~/project/packages/core
|
||||
```
|
||||
|
||||
### 2. Find Immediate Cause
|
||||
**What code directly causes this?**
|
||||
```typescript
|
||||
await execFileAsync('git', ['init'], { cwd: projectDir });
|
||||
```
|
||||
|
||||
### 3. Ask: What Called This?
|
||||
```typescript
|
||||
WorktreeManager.createSessionWorktree(projectDir, sessionId)
|
||||
→ called by Session.initializeWorkspace()
|
||||
→ called by Session.create()
|
||||
→ called by test at Project.create()
|
||||
```
|
||||
|
||||
### 4. Keep Tracing Up
|
||||
**What value was passed?**
|
||||
- `projectDir = ''` (empty string!)
|
||||
- Empty string as `cwd` resolves to `process.cwd()`
|
||||
- That's the source code directory!
|
||||
|
||||
### 5. Find Original Trigger
|
||||
**Where did empty string come from?**
|
||||
```typescript
|
||||
const context = setupCoreTest(); // Returns { tempDir: '' }
|
||||
Project.create('name', context.tempDir); // Accessed before beforeEach!
|
||||
```
|
||||
|
||||
## Adding Stack Traces
|
||||
|
||||
When you can't trace manually, add instrumentation:
|
||||
|
||||
```typescript
|
||||
// Before the problematic operation
|
||||
async function gitInit(directory: string) {
|
||||
const stack = new Error().stack;
|
||||
console.error('DEBUG git init:', {
|
||||
directory,
|
||||
cwd: process.cwd(),
|
||||
nodeEnv: process.env.NODE_ENV,
|
||||
stack,
|
||||
});
|
||||
|
||||
await execFileAsync('git', ['init'], { cwd: directory });
|
||||
}
|
||||
```
|
||||
|
||||
**Critical:** Use `console.error()` in tests (not logger - may not show)
|
||||
|
||||
**Run and capture:**
|
||||
```bash
|
||||
npm test 2>&1 | grep 'DEBUG git init'
|
||||
```
|
||||
|
||||
**Analyze stack traces:**
|
||||
- Look for test file names
|
||||
- Find the line number triggering the call
|
||||
- Identify the pattern (same test? same parameter?)
|
||||
|
||||
## Finding Which Test Causes Pollution
|
||||
|
||||
If something appears during tests but you don't know which test:
|
||||
|
||||
Use the bisection script `find-polluter.sh` in this directory:
|
||||
|
||||
```bash
|
||||
./find-polluter.sh '.git' 'src/**/*.test.ts'
|
||||
```
|
||||
|
||||
Runs tests one-by-one, stops at first polluter. See script for usage.
|
||||
|
||||
## Real Example: Empty projectDir
|
||||
|
||||
**Symptom:** `.git` created in `packages/core/` (source code)
|
||||
|
||||
**Trace chain:**
|
||||
1. `git init` runs in `process.cwd()` ← empty cwd parameter
|
||||
2. WorktreeManager called with empty projectDir
|
||||
3. Session.create() passed empty string
|
||||
4. Test accessed `context.tempDir` before beforeEach
|
||||
5. setupCoreTest() returns `{ tempDir: '' }` initially
|
||||
|
||||
**Root cause:** Top-level variable initialization accessing empty value
|
||||
|
||||
**Fix:** Made tempDir a getter that throws if accessed before beforeEach
|
||||
|
||||
**Also added defense-in-depth:**
|
||||
- Layer 1: Project.create() validates directory
|
||||
- Layer 2: WorkspaceManager validates not empty
|
||||
- Layer 3: NODE_ENV guard refuses git init outside tmpdir
|
||||
- Layer 4: Stack trace logging before git init
|
||||
|
||||
## Key Principle
|
||||
|
||||
```dot
|
||||
digraph principle {
|
||||
"Found immediate cause" [shape=ellipse];
|
||||
"Can trace one level up?" [shape=diamond];
|
||||
"Trace backwards" [shape=box];
|
||||
"Is this the source?" [shape=diamond];
|
||||
"Fix at source" [shape=box];
|
||||
"Add validation at each layer" [shape=box];
|
||||
"Bug impossible" [shape=doublecircle];
|
||||
"NEVER fix just the symptom" [shape=octagon, style=filled, fillcolor=red, fontcolor=white];
|
||||
|
||||
"Found immediate cause" -> "Can trace one level up?";
|
||||
"Can trace one level up?" -> "Trace backwards" [label="yes"];
|
||||
"Can trace one level up?" -> "NEVER fix just the symptom" [label="no"];
|
||||
"Trace backwards" -> "Is this the source?";
|
||||
"Is this the source?" -> "Trace backwards" [label="no - keeps going"];
|
||||
"Is this the source?" -> "Fix at source" [label="yes"];
|
||||
"Fix at source" -> "Add validation at each layer";
|
||||
"Add validation at each layer" -> "Bug impossible";
|
||||
}
|
||||
```
|
||||
|
||||
**NEVER fix just where the error appears.** Trace back to find the original trigger.
|
||||
|
||||
## Stack Trace Tips
|
||||
|
||||
**In tests:** Use `console.error()` not logger - logger may be suppressed
|
||||
**Before operation:** Log before the dangerous operation, not after it fails
|
||||
**Include context:** Directory, cwd, environment variables, timestamps
|
||||
**Capture stack:** `new Error().stack` shows complete call chain
|
||||
|
||||
## Real-World Impact
|
||||
|
||||
From debugging session (2025-10-03):
|
||||
- Found root cause through 5-level trace
|
||||
- Fixed at source (getter validation)
|
||||
- Added 4 layers of defense
|
||||
- 1847 tests passed, zero pollution
|
||||
Reference in New Issue
Block a user