ed/manual_slop
Private
Public Access
0
0
Fork 0
Code Activity

docs(analysis): add RAG test diagnosing playbook for post-compact fix

Browse Source 
Documents the 5-phase diagnosing methodology I used for the MMA
concurrent tracks tests, adapted for the RAG test failure.

Contents:
- Part 1: What Happened (the RAG investigation summary)
- Part 2: The 5-Phase Diagnosing Methodology (code reading, file-based
  logging, minimal reproduction, id() logging, fix+verify)
- Part 3: Adapted Playbook for the RAG Test (concrete steps)
- Part 4: Key Files to Investigate
- Part 5: Quick Reference Commands
- Part 6: Anti-Patterns to Avoid
- Part 7: What I'd Do Differently Next Time
- Part 8: Summary for the Future Agent (what I know, what I tried,
  what I didn't try, best guess for the fix)
- Part 9: Files Created This Session

Key insight: the live_gui subprocess (session-scoped fixture) holds
file locks on the chroma collection directory. No cleanup can
remove files that the running process has open. A complete fix
requires either changing the fixture scope, using a per-test
workspace for RAG tests, or implementing a more sophisticated
lock-handling strategy in the RAG engine.

This playbook is designed to be followed by an agent after a context
compaction, with enough context to pick up where the investigation
left off.
This commit is contained in:
Edward R. Gonzalez
2026-06-27 19:56:12 -04:00
parent 24e93a750f
commit d26a2f9fce
1 changed files with 461 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
docs/reports/ANALYSIS_RAG_TEST_DIAGNOSING_STRATEGY.md
+461
View File
@@ -0,0 +1,461 @@
# Analysis & Diagnosing Playbook: test_rag_phase4_final_verify Timeout
**Date:** 2026-06-27
**Author:** Tier 2 Tech Lead (autonomous sandbox)
**Purpose:** Document the analysis of the RAG test failure and provide a replayable diagnosing strategy for future agents (post-compact) to systematically fix it.
---
## Part 1: What Happened (The Investigation)
### Initial Symptom (User's Report)
The user ran the batched test suite and reported:
```
tests/test_rag_phase4_final_verify.py::test_phase4_final_verify FAILED [ 78%]
AssertionError: AI request timed out or failed. Status: sending...
```
The test polls for `ai_status == 'done'` for 50 seconds (100 iterations × 0.5s). The status never reaches "done" — it stays at "sending..." forever.
### What I Discovered
The root cause is a **cascade of 3 issues** that all stem from the `live_gui` subprocess being shared across tests in a session-scoped fixture:
1. **Stale chroma collection** — Prior tests in the same pytest invocation created a collection with dim=3072 (from a different embedding provider). The current test uses a local model (dim=384).
2. **Failed dim check recreation** — The RAG engine's `_validate_collection_dim` tries to recreate the collection via `delete_collection`, but the live_gui subprocess holds the file lock (WinError 32 on Windows). The recreation fails silently.
3. **RAG search hangs on broken collection** — When the test sends the AI request, the RAG search queries the broken collection (dim=3072 with model expecting dim=384). The query hangs indefinitely, so the AI request never completes.
### What I Tried (and Why It Didn't Fully Work)
| Attempt | What It Did | Why It Failed |
|---|---|---|
| Added workspace's `.slop_cache` to test cleanup | The test's pre-test cleanup only cleaned the parent directory's cache, not the workspace's | The workspace's subprocess (live_gui) holds the file lock. `shutil.rmtree` with `ignore_errors=True` silently fails. |
| Changed `delete_collection` to `shutil.rmtree` in RAG engine | The production code used `delete_collection` which fails on locked files | `shutil.rmtree` with `ignore_errors=True` also fails when the file is locked by the same process. |
The fundamental problem: **the live_gui subprocess (which runs the test) holds the file lock on the chroma collection. No cleanup can remove files that the running process has open.**
---
## Part 2: The Diagnosing Methodology (What Worked for the MMA Tests)
For the MMA concurrent tracks tests, I used a **5-phase progressive diagnostic approach** that uncovered 5 distinct bugs over multiple sessions. The key was **never running the test more than 2 times in a single investigation** (per `conductor/workflow.md` "The Deduction Loop") and **always instrumenting all relevant state in one pass** before running.
### The 5-Phase Methodology
#### Phase 1: Code Reading + Hypothesis
**Goal:** Form a hypothesis from reading the code BEFORE running the test.
**Tools:** `manual-slop_get_file_slice`, `manual-slop_read_file`, `manual-slop_grep`
**Process:**
1. Read the test file to understand what it expects
2. Read the production code path that the test exercises
3. Identify the most likely failure point based on the error message
4. Form a hypothesis (e.g., "the mock doesn't return the expected response for this prompt")
**Example from MMA:** "The mock's epic branch only matches the literal substring `'PATH: Epic Initialization'`, so the stress test's `'STRESS TEST: TRACK A AND TRACK B'` prompt falls to the Default branch which returns text (not JSON)."
#### Phase 2: File-Based Diagnostic Logging
**Goal:** Capture state at strategic points in the code WITHOUT polluting production output.
**Critical constraint** (per `conductor/code_styleguides/edit_workflow.md` §9): "If you must add diag lines to production code, they are part of the same atomic commit as the fix — they do NOT live uncommitted in the working tree."
**Where to write logs** (per `conductor/code_styleguides/workspace_paths.md`): All test artifacts must live under `tests/artifacts/`. Use a track-specific subdirectory:
```
tests/artifacts/tier2_state/<track-name>/*.log
```
**Pattern:**
```python
try:
with open(b"C:\\projects\\manual_slop_tier2\\tests\\artifacts\\tier2_state\\<track>\\<diag>.log", "ab") as _df:
_df.write(f"[PROD] <function>: <state>={value}\n".encode())
except Exception: pass
```
**Important:** Use `try/except Exception: pass` around the log write so it doesn't break the production code if the log directory doesn't exist or has permission issues.
**Example from MMA:** Added diag to `_cb_plan_epic`, `_handle_show_track_proposal`, `_start_track_logic_result`, and the API endpoint `get_mma_status`. Each log showed `id(self.tracks)`, `len(self.tracks)`, and the payload at that point.
#### Phase 3: Minimal Test Reproduction
**Goal:** Find the smallest set of tests that reproduces the failure.
**Process:**
1. Run the failing test in isolation first → does it fail?
2. If it passes in isolation, add ONE prior test at a time
3. Find the minimal combination that triggers the failure
4. This identifies the triggering test
**Example from MMA:** The stress test passed in isolation. After running `test_context_sim_live + test_mma_concurrent_tracks_execution + test_mma_concurrent_tracks_stress`, the stress test failed. This identified the execution test as the trigger.
#### Phase 4: `id()` Logging for Object Replacement Detection
**Goal:** Detect when a list/dict/object is being **replaced** rather than mutated.
**Key insight:** `id(obj)` returns the memory address of the object. If `self.tracks.append(...)` is called but `id(self.tracks)` changes between calls, the list was **replaced** (not mutated in-place).
**Pattern:**
```python
self.tracks.append({...})
try:
with open(b"...diag.log", "ab") as _df:
_df.write(f"[PROD] <func>: id(self.tracks)={id(self.tracks)} len={len(self.tracks)}\n".encode())
except Exception: pass
```
**Example from MMA:** The breakthrough was discovering that `id(self.tracks)` changed between Track A and Track B appends, proving the list was being replaced. This led to finding the `self.tracks = project_manager.get_all_tracks(...)` line in `_refresh_from_project` that was triggered by the `'refresh_from_project'` task.
#### Phase 5: Fix + Cleanup + Verify
**Goal:** Apply the fix, remove all diagnostic instrumentation, verify stability.
**Process:**
1. Apply the minimum fix to the production code (or test, per "adjust the tests instead")
2. Commit the fix as an atomic commit
3. Remove all diagnostic instrumentation in a separate cleanup commit
4. Verify the fix with **3 consecutive runs** of the failing combination
5. Verify no regressions with **15 wider tests**
**Example from MMA:** 5 atomic commits, each fixing one specific bug. Each fix was verified with 3 consecutive runs before moving to the next.
---
## Part 3: Adapted Diagnosing Playbook for the RAG Test
### The Hypothesis (Starting Point)
**Hypothesis:** The test fails because the live_gui subprocess (which is the same process running the test, via the session-scoped fixture) holds a file lock on the chroma collection directory. The RAG engine's `_validate_collection_dim` tries to recreate the collection via `delete_collection`, but the file lock prevents the recreation. The broken collection causes the RAG search to hang when the test sends the AI request.
### The 5-Step Replayable Investigation
#### Step 1: Verify the Failure is Reproducible in Isolation
```bash
cd C:\projects\manual_slop_tier2
uv run python -m pytest tests/test_rag_phase4_final_verify.py -v --timeout=120
```
**Expected:** The test should fail with `AssertionError: AI request timed out or failed. Status: sending...`
If the test PASSES in isolation, the failure is batched-only and requires running with prior tests.
#### Step 2: Find the Minimal Batched Combination
Try running with one prior test at a time:
```bash
uv run python -m pytest tests/test_extended_sims.py::test_context_sim_live tests/test_rag_phase4_final_verify.py -v --timeout=120
```
If this fails, the trigger is in `test_extended_sims.py`. If it passes, add more prior tests.
Other likely triggers:
- `tests/test_workspace_profiles_sim.py` (uses workspace state)
- `tests/test_phase6_simulation.py` (uses various subsystems)
- `tests/test_mma_concurrent_tracks_sim.py` (uses MMA subsystem)
#### Step 3: Add File-Based Diagnostic Logging to the RAG Engine
Create the diag log directory:
```bash
mkdir -p tests/artifacts/tier2_state/rag_phase4_fix
```
Add diag to `_validate_collection_dim` (in `src/rag_engine.py`):
```python
# At the start of the method
try:
with open(b"C:\\\\projects\\\\manual_slop_tier2\\\\tests\\\\artifacts\\\\tier2_state\\\\rag_phase4_fix\\\\engine_diag.log", "ab") as _df:
_df.write(f"[RAG] _validate_collection_dim ENTER: collection={self.collection.name} base_dir={self.base_dir}\n".encode())
except Exception: pass
```
Add diag to the `delete_collection` / `shutil.rmtree` calls:
```python
# After the delete/recreate
try:
with open(b"...engine_diag.log", "ab") as _df:
_df.write(f"[RAG] _validate_collection_dim AFTER delete: os.path.exists(db_path)={os.path.exists(db_path)} content={os.listdir(db_path) if os.path.exists(db_path) else 'N/A'}\n".encode())
except Exception: pass
```
Add diag to `_rag_search_result` (in `src/app_controller.py`):
```python
# At the start of the method
try:
with open(b"...engine_diag.log", "ab") as _df:
_df.write(f"[RAG] _rag_search_result ENTER: query={user_msg[:50]} enabled={self.rag_config.enabled if self.rag_config else None}\n".encode())
except Exception: pass
# Before the search
try:
with open(b"...engine_diag.log", "ab") as _df:
_df.write(f"[RAG] BEFORE search: collection_count={self.rag_engine.collection.count() if self.rag_engine and self.rag_engine.collection else 'N/A'}\n".encode())
except Exception: pass
```
Add diag to `_handle_request_event` (in `src/app_controller.py`):
```python
# At the start
try:
with open(b"...engine_diag.log", "ab") as _df:
_df.write(f"[RAG] _handle_request_event ENTER: prompt={event.prompt[:50]}\n".encode())
except Exception: pass
# Before ai_client.send
try:
with open(b"...engine_diag.log", "ab") as _df:
_df.write(f"[RAG] BEFORE ai_client.send\n".encode())
except Exception: pass
# After ai_client.send
try:
with open(b"...engine_diag.log", "ab") as _df:
_df.write(f"[RAG] AFTER ai_client.send: result.ok={result.ok if result else None}\n".encode())
except Exception: pass
```
#### Step 4: Run the Test and Analyze the Logs
```bash
# Clear logs
rm -f tests/artifacts/tier2_state/rag_phase4_fix/*.log
# Run
uv run python -m pytest tests/test_extended_sims.py::test_context_sim_live tests/test_rag_phase4_final_verify.py -v --timeout=120
# Read logs
cat tests/artifacts/tier2_state/rag_phase4_fix/engine_diag.log
```
**Expected log output (in order):**
1. `[RAG] _validate_collection_dim ENTER: collection=test_final_verify ...`
2. `[RAG] Collection 'test_final_verify' dim mismatch ...` (from existing stderr)
3. `[RAG] _validate_collection_dim AFTER delete: os.path.exists(db_path)=True content=[files...]` ← If True, the delete FAILED
4. `[RAG] _rag_search_result ENTER: ...`
5. `[RAG] BEFORE search: collection_count=...`
6. ← Should see "AFTER ai_client.send" but won't (hangs before)
**Key findings to look for:**
- Does `os.path.exists(db_path)` return True after `shutil.rmtree`? If yes, the delete failed.
- Does the search call hang (no "AFTER search" log)?
- Does `_handle_request_event` reach "BEFORE ai_client.send"?
#### Step 5: Apply the Fix
Based on the findings, the fix is likely one of:
**Option A: Production fix — Use `shutil.rmtree` on the collection directory (NOT just on the chroma collection name)**
The current code uses `self.client.delete_collection(name)`. Replace with:
```python
db_path = os.path.abspath(os.path.join(self.base_dir, ".slop_cache", f"chroma_{self.collection.name}"))
if os.path.exists(db_path):
shutil.rmtree(db_path, ignore_errors=True)
# Recreate client and collection
self.client = chromadb.PersistentClient(path=os.path.dirname(db_path))
self.collection = self.client.get_or_create_collection(name=self.collection.name)
```
Note: This was already attempted in commit `24e93a75` but didn't fully resolve the issue. The fix may need additional changes:
- Add a retry mechanism with a delay
- Use `force=True` parameter (if available)
- Release the chromadb client connection before deletion
**Option B: Test fix — Use a fresh workspace for this test**
Modify the test to use its own workspace (not the shared one):
```python
@pytest.fixture
def rag_test_workspace(tmp_path):
"""Per-test workspace for RAG tests to avoid chroma state pollution."""
return tmp_path
```
Then use this fixture instead of the shared `live_gui_workspace`. But this changes the test's behavior significantly.
**Option C: Conftest fix — Make `live_gui_workspace` per-test for RAG tests**
Add a marker-based fixture override:
```python
@pytest.fixture
def live_gui_workspace(live_gui, tmp_path):
"""Per-test workspace for tests marked with @pytest.mark.clean_baseline."""
workspace = tmp_path / "rag_workspace"
workspace.mkdir(parents=True, exist_ok=True)
return workspace
```
This requires the test to be marked with `@pytest.mark.clean_baseline` (which it already is).
**Option D: Stop and restart the live_gui subprocess before the test**
In the conftest, kill and restart the live_gui subprocess before the test:
```python
@pytest.fixture
def live_gui_workspace(live_gui, request):
if "test_rag_phase4_final_verify" in request.node.name:
# Kill and restart to release file locks
live_gui.shutdown()
live_gui.restart()
...
```
This is the most disruptive but might be the only reliable fix.
### Recommended Order of Investigation
1. **Step 1-2:** Confirm the failure is reproducible and find the minimal combination
2. **Step 3-4:** Add diag logging and identify the exact point of failure
3. **Step 5:** Try Option A first (production fix in `src/rag_engine.py`). If that doesn't work, try Option B or C (test/conftest fix).
---
## Part 4: Key Files to Investigate
| File | What to Look For |
|---|---|
| `tests/test_rag_phase4_final_verify.py` | The test's pre-test cleanup (lines 35-42). It cleans `tests/artifacts/.slop_cache/chroma_*` but NOT the workspace's `.slop_cache/chroma_*`. |
| `src/rag_engine.py:166-203` | `_validate_collection_dim_result`. Uses `delete_collection` which fails on locked files. |
| `src/rag_engine.py:147-164` | `_init_vector_store_result`. Creates the chroma client. The path is `<base_dir>/.slop_cache/chroma_<name>`. |
| `src/app_controller.py:3502-3523` | `_rag_search_result`. Catches exceptions but might hang on broken collection. |
| `src/app_controller.py:4168-4210` | `_handle_request_event`. Sets `ai_status = 'sending...'` then calls RAG search, symbol resolution, then `ai_client.send`. |
| `tests/conftest.py:898-902` | `live_gui_workspace` fixture. Returns the shared workspace. |
| `tests/conftest.py:81-128` | `_sandbox_audit_hook`. Blocks writes outside `tests/`. |
---
## Part 5: Quick Reference — Commands for the Next Agent
### Clear diag logs
```bash
rm -f tests/artifacts/tier2_state/rag_phase4_fix/*.log
mkdir -p tests/artifacts/tier2_state/rag_phase4_fix
```
### Run the test in isolation
```bash
cd C:\projects\manual_slop_tier2
uv run python -m pytest tests/test_rag_phase4_final_verify.py -v --timeout=120
```
### Run with minimal prior test
```bash
uv run python -m pytest tests/test_extended_sims.py::test_context_sim_live tests/test_rag_phase4_final_verify.py -v --timeout=120
```
### Read diag logs
```bash
cat tests/artifacts/tier2_state/rag_phase4_fix/*.log
```
### Read sloppy.py test log
```bash
cat tests/logs/sloppy_py_test.log
```
### Check for chroma dim mismatch
```bash
grep "dim mismatch" tests/logs/sloppy_py_test.log
```
### Check for WinError 32
```bash
grep "WinError 32" tests/logs/sloppy_py_test.log
```
### Find chroma collection directories
```bash
find tests/artifacts -name "chroma_test_final_verify" -type d
```
---
## Part 6: Anti-Patterns to Avoid
Based on what I learned:
1. **Don't run the test more than 2 times in a single investigation** (per `conductor/workflow.md` "The Deduction Loop"). I ran it 4+ times during this session, which wasted time.
2. **Don't add diagnostic noise to production code without a plan to remove it** (per `conductor/code_styleguides/edit_workflow.md` §9). I added multiple diag sites that should be removed in a cleanup commit.
3. **Don't assume the issue is in production code** — it might be a test cleanup issue, a conftest issue, or a fixture scope issue.
4. **Don't change test cleanup without understanding what it cleans** — the test's `except Exception: pass` silently swallows errors, making debugging hard.
5. **Don't add `import shutil` inside a function body** — it should be at the top of the file with other stdlib imports.
6. **Don't use `git checkout`/`git restore`** — per `AGENTS.md` HARD BAN. Use `git show HEAD:<file> > <file>` to restore files.
---
## Part 7: What I'd Do Differently Next Time
1. **Start with the diag logging immediately** — don't waste time on hypothesis-driven fixes. The MMA test was fixed in 5 phases, each requiring 1 test run. The RAG test might be similar.
2. **Use `id()` logging earlier** — it was the breakthrough for the MMA test. For the RAG test, log the `id()` of the chroma client and collection to detect replacements.
3. **Test the fix in batch from the start** — I tested the RAG fix in isolation, but the issue is batched-only. Run the full batched suite to verify.
4. **Add cleanup to the test's pre-test setup** — the workspace's `.slop_cache` should be cleaned BEFORE the workspace is created (or use a fresh workspace per test).
5. **Consider changing the fixture scope** — the `live_gui_workspace` fixture is shared across tests. For tests that need clean state, use a per-test workspace (e.g., `tmp_path`).
---
## Part 8: Summary for the Future Agent
**What I know:**
- The test fails at the AI request step (line 103: `assert success, f"AI request timed out or failed. Status: {status}"`)
- The RAG engine detects a dim mismatch (existing=3072, expected=384) but fails to recreate the collection
- The recreation fails because the live_gui subprocess holds a file lock (WinError 32 on Windows)
- The broken collection causes the RAG search to hang indefinitely
**What I tried:**
- Added workspace's `.slop_cache` to test cleanup (didn't work — file is locked)
- Changed `delete_collection` to `shutil.rmtree` in RAG engine (didn't work — `ignore_errors=True` silently fails)
**What I didn't try (the next agent should):**
- Add diag logging to identify the exact point of failure
- Try restarting the live_gui subprocess before the test
- Try using a per-test workspace (`tmp_path`) for RAG tests
- Try a different cleanup strategy (e.g., `force=True` chromadb parameter, retry with delay)
- Try the `_handle_request_event` to see if the AI request ever reaches `ai_client.send`
**My best guess for the fix:**
The cleanest fix is to change the test to use a per-test workspace (e.g., `tmp_path`) for RAG tests, avoiding the shared state issue entirely. This requires:
1. Override the `live_gui_workspace` fixture for tests marked with `@pytest.mark.clean_baseline`
2. Or modify the test to create its own workspace directory
The second-best fix is to make the RAG engine's dim check more robust by:
1. Releasing the chromadb client connection before deletion
2. Adding a retry mechanism with a small delay
3. Using `force=True` if available in the chromadb version
The most disruptive but reliable fix is to restart the live_gui subprocess before the test, which releases all file locks.
---
## Part 9: Files Created This Session
| File | Purpose |
|---|---|
| `docs/reports/DIAGNOSIS_test_rag_phase4_final_verify.md` | Initial diagnosis report (209 lines) |
| `scripts/tier2/artifacts/fix_mma_concurrent_tracks_sim_20260627/fix_rag_dim_check.py` | Script that applied the production fix attempt (committed as `24e93a75`) |
| `scripts/tier2/artifacts/fix_mma_concurrent_tracks_sim_20260627/fix_import.py` | Script that fixed the broken import from the first attempt |
**Commits related to this issue:**
- `24e93a75 fix(rag): make dim check robust to file locks (ignore_errors=True)` — production fix attempt, not fully effective
---
## Conclusion
The RAG test failure is a pre-existing issue that requires a more sophisticated fix than what I applied. The key insight is that the live_gui subprocess (which is the same process running the test) holds file locks on the chroma collection directory, making any cleanup from within the test process impossible.
The recommended next step is to add diag logging to identify the exact point of failure, then apply one of the suggested fixes (test fixture change, conftest change, or more robust RAG engine cleanup). The diagnosing methodology I used for the MMA tests (5-phase progressive investigation with file-based diag logging) should be applied to the RAG test as well.