[BUG] Lock contention between upgrade CLI and plugin causes writes to fail

[jlin53882]

Issue #632 - Final Analysis and Solution

Problem Confirmed

memory-upgrader.ts currently processes each entry with LLM enrichment AND store.update() inside the same lock cycle:

// Current flow (problematic)
for (const entry of batch) {
  await this.upgradeEntry(entry, noLlm);  // LLM + lock per entry
}

This causes:

1. N lock acquisitions for N entries = high contention
2. Plugin waits seconds while LLM runs between lock acquisitions
3. Cross-session lock contention between upgrade CLI and plugin

Solution: Two-Phase Approach

Separate LLM enrichment from DB writes:

// Phase 1: LLM enrichment - NO LOCK
const enriched = await Promise.all(
  batch.map(entry => this.prepareEntry(entry, noLlm))
);

// Phase 2: Single lock for ALL DB writes
await this.store.runWithFileLock(async () => {
  for (const entry of enriched) {
    await this.store.update(entry.id, {
      text: entry.l0_abstract,
      metadata: entry.metadata,
    });
  }
});

Why This Works

Phase	Lock	Plugin Impact
Phase 1 (LLM)	No	None
Phase 2 (DB writes)	Yes	Plugin waits only for DB write time (ms)

Comparison

Approach	Lock Count (batch=10)	Plugin Wait Time
Current	10	Seconds (LLM time)
Fixed	1	Milliseconds (DB write time)

Key Changes Required

1. Extract prepareEntry() - Separate LLM logic from upgradeEntry()
2. Modify upgrade() loop - Two-phase processing
3. No new API needed - Use existing store.update() in lock

Unit Tests Needed

// Test 1: Lock acquired once per batch
test("upgrade acquires lock once per batch", async () => {
  let lockCount = 0;
  store.runWithFileLock = async (fn) => {
    lockCount++;
    return fn();
  };
  await upgrader.upgrade({ batchSize: 5 });
  assert.equal(lockCount, 1);  // Not 5
});

// Test 2: LLM runs before lock
test("LLM enrichment happens before lock acquisition", async () => {
  const order = [];
  store.runWithFileLock = async (fn) => {
    order.push("lock-start");
    await fn();
    order.push("lock-end");
  };
  upgrader.prepareEntry = async () => {
    order.push("llm");
    return mockEnriched;
  };
  await upgrader.upgradeBatch([entry]);
  const llmIdx = order.indexOf("llm");
  const lockIdx = order.indexOf("lock-start");
  assert.ok(llmIdx < lockIdx, "LLM should run before lock");
});

Integration Test (Future)

Cross-session test requires real processes, not mocks:

test("cross-session: upgrade and plugin writes both succeed", async () => {
  // Requires spawning real processes
  // Verifies proper-lockfile behavior across processes
});

Implementation Plan

1. Extract prepareEntry() from upgradeEntry()
2. Modify upgrade() to use two-phase approach
3. Add unit tests
4. Test with real upgrade + plugin running concurrently

Related Issues

• [BUG] Windows: stale .memory-write.lock not released, blocks smart-extractor writes #622: Stale lock recovery (different fix area)
• [BUG] Same-instance concurrent writes竞争 lock，导致 Lock file is already being held #623: Same-instance queue (different fix area)
• [BUG] Lock contention between upgrade CLI and plugin causes writes to fail #632: Cross-session contention (this issue)

[jlin53882]

Original Error Logs

Lock Contention Errors

01:35:41 [plugins] memory-lancedb-pro: capture failed: Error: Lock file is already being held
memory-upgrader: processing batch 4/10 (10 memories)
memory-upgrader: ERROR — Failed to upgrade b95d6033-ad9c-4ec8-bcad-660abe019f31: Error: Lock file is already being held
memory-upgrader: ERROR — Failed to upgrade a85c1dfb-9f4d-45e7-9999-00b918a1934a: Error: Lock file is already being held

Impact on Store Phase

01:41:12 [plugins] memory-pro: smart-extractor: skipped [cases] Lock contention caused 94-second store phase, not embedding
01:41:15 [plugins] memory-pro: smart-extractor: skipped [cases] Lock file stale timeout is upper bound, not guaranteed delay

Full Context from Logs

01:41:10 [plugins] memory-lancedb-pro: auto-recall skipped after governance filters (hits=6, dedupFiltered=0, stateFiltered=0, suppressedFiltered=6)
01:41:12 [plugins] memory-pro: smart-extractor: skipped [cases] Lock contention caused 94-second store phase, not embedding
01:41:15 [plugins] memory-pro: smart-extractor: skipped [cases] Lock file stale timeout is upper bound, not guaranteed delay
01:41:25 [agents/auth-profiles] synced openai-codex credentials from external cli
01:41:31 [plugins] memory-pro: smart-extractor: no memories extracted
01:41:31 [plugins] memory-lancedb-pro: smart extraction produced no persisted memories for agent dc-channel--1476858065914695741 (created=0, merged=0, skipped=0); falling back to regex capture
01:41:31 [plugins] memory-lancedb-pro: regex fallback found 0 capturable texts for agent dc-channel--1476858065914695741
01:41:35 [plugins] memory-pro: smart-extractor: skipped [cases] MMR diversity removal deletes neighbors before B-2 insertion
01:41:37 [plugins] memory-lancedb-pro: auto-recall skipped after governance filters (hits=6, dedupFiltered=0, stateFiltered=0, suppressedFiltered=6)

Key Observations

1. Lock contention caused 94-second store phase
2. Smart-extractor failed to process candidates due to lock
3. No memories extracted - fell back to regex capture which also found nothing
4. Governance filters suppressed all 6 auto-recall hits

These logs confirm the cross-process lock contention between upgrade CLI and plugin.

[jlin53882]

Unit Test Recommendations

Why Tests Are Needed

Without proper tests, the following scenarios can occur:

1. Lock acquired per entry - N entries = N lock acquisitions = high contention
2. Upgrade fails silently - Upgrade completes but some entries fail without error
3. No regression detection - Future changes to upgrade flow could reintroduce per-entry locking

Proposed Tests

1. Lock Acquisition Count Test

Verify that upgrade acquires lock once per batch, not once per entry.

test("upgrade batches should acquire lock once per batch", async () => {
  let lockAcquiredCount = 0;
  const originalRunWithFileLock = store.runWithFileLock.bind(store);
  store.runWithFileLock = async (fn) => {
    lockAcquiredCount++;
    return originalRunWithFileLock(fn);
  };
  
  const entries = generateTestEntries(5);
  await upgrader.upgradeBatch(entries);
  
  // Lock should be acquired once for the entire batch, not 5 times
  assert.equal(lockAcquiredCount, 1);
});

2. LLM Enrichment Before Lock Test

Verify that LLM enrichment happens BEFORE lock is acquired.

test("LLM enrichment runs before lock acquisition", async () => {
  const operationOrder = [];
  
  store.runWithFileLock = async (fn) => {
    operationOrder.push("lock-start");
    const result = await fn();
    operationOrder.push("lock-end");
    return result;
  };
  
  upgrader.prepareEntry = async () => {
    operationOrder.push("llm");
    return mockEnriched;
  };
  
  await upgrader.upgradeBatch([entry]);
  
  // LLM should run BEFORE lock-start
  const llmIndex = operationOrder.indexOf("llm");
  const lockIndex = operationOrder.indexOf("lock-start");
  assert.ok(llmIndex < lockIndex, "LLM should run before lock is acquired");
});

3. Batch DB Writes Inside Lock Test

Verify that all DB writes happen inside the single lock acquisition.

test("all DB writes happen inside the single lock", async () => {
  const writeOperations = [];
  
  store.runWithFileLock = async (fn) => {
    writeOperations.push("lock-start");
    await fn();
    writeOperations.push("lock-end");
  };
  
  // Mock update to track write operations
  store.update = async (id, updates) => {
    writeOperations.push(`write-${id}`);
  };
  
  await upgrader.upgradeBatch([entry1, entry2]);
  
  // All writes should be between lock-start and lock-end
  const lockStartIdx = writeOperations.indexOf("lock-start");
  const lockEndIdx = writeOperations.indexOf("lock-end");
  const writesBetweenLock = writeOperations.filter((op, i) => 
    i > lockStartIdx && i < lockEndIdx && op.startsWith("write-")
  );
  
  assert.equal(writesBetweenLock.length, 2, "Both writes should be inside lock");
});

Test File Location

memory-lancedb-pro/
  test/
    upgrade-batch-phase.test.mjs      # New - batch phase tests
    lock-recovery.test.mjs           # Existing - #622
    store-write-queue.test.mjs      # Existing - #623

Key Points

Test	Validates
Lock count	Lock acquired once per batch, not per entry
LLM timing	LLM enrichment happens BEFORE lock
DB writes	All writes happen INSIDE the single lock

Note on Implementation

We use existing store.update() inside a single runWithFileLock() call, no new API needed.

[jlin53882]

Unit Test Results (pushed to branch)

Test Coverage

Test	Result
Test 1: update() per entry	✅ CONFIRMED
Test 2: LLM sequential	✅ CONFIRMED
Test 3 EXTREME: 10 entries	✅ FULLY CONFIRMED
Test 4: Mock lock tracking	✅ 5 locks CONFIRMED

Test 4 Key Finding

[Test 4] update() called: 5 times
[Test 4] runWithFileLock() called: 5 times
[Test 4] BUG CONFIRMED: 5 locks for 5 entries

Issue #632 Fully Confirmed:

• batchSize=5 → 5 lock acquisitions → Plugin waits 5 times
• After fix should be: 1 lock for entire batch

Test File

• Location: test/memory-upgrader-lock-fix.test.mjs
• Branch: fix/p2-clean-fix
• Commit: daaa35b

[jlin53882]

✅ Plan A 已實作完成

修復內容：兩階段處理

• Phase 1: LLM enrichment（無 lock）
• Phase 2: 單次 lock 寫入整批

Lock 改善：

• 10 entries: 10 locks → 1 lock (-90%)
• 25 entries: 25 locks → 3 locks (-88%)

PR：jlin53882/memory-lancedb-pro#354

---

📋 Plan B 追蹤 Issue

如需進一步優化（完全無鎖），請參考 Issue #638：
#638

[jlin53882]

✅ 單元測試已完成

測試檔案

所有測試位於：test/upgrader-phase2-extreme.test.mjs

測試結果

Test	結果	說明
Test 1: Lock Count	✅ 通過	10 entries / batch=10 → 1 lock (預期: 1)
Test 2: LLM Fallback	✅ 通過	LLM 失敗時 fallback 到 simpleEnrich
Test 3: Mixed Success	✅ 通過	混合成功和失敗正確處理
Test 4: Batch Boundary	✅ 通過	25 entries / batch=10 → 3 locks (正確)
Test 5: Stress Test	✅ 通過	100 entries 全部成功升級
Test 7: Old vs New	✅ 通過	舊實作: 5 locks → 新實作: 1 lock

Lock 改善數據

情境	舊實作	新實作	改善
10 entries / batch=10	10 locks	1 lock	-90%
25 entries / batch=10	25 locks	3 locks	-88%
100 entries / batch=10	100 locks	10 locks	-90%

測試程式碼摘要

// Test 1: Phase-2 確認 lock 次數 = 1 per batch
async function testPhase2_LockCountFixed() {
  let lockCount = 0;
  const store = {
    async list() { return Array.from({ length: 10 }, (_, i) => createLegacyEntry(`entry-${i}`, `Memory ${i}`)); },
    async update(id, patch) { return true; },
    async runWithFileLock(fn) { lockCount++; return fn(); },
  };
  
  const upgrader = createMemoryUpgraderPhase2(store, llm, { log: () => {} });
  await upgrader.upgrade({ batchSize: 10, noLlm: true });
  
  assert.equal(lockCount, 1, "Phase-2 應該只有 1 次 lock");
}

// Test 7: 舊實作 vs 新實作比較
async function testCompareOldVsNew() {
  // 舊實作：每個 entry 拿一次 lock
  let oldLockCount = 0;
  for (const entry of oldMemories) {
    oldLockCount++; // 每個 entry 都拿 lock
    await oldStore.update(entry.id, { text: "upgraded" });
  }
  
  // 新實作：一次 lock 寫入整批
  await newUpgrader.upgrade({ batchSize: 5, noLlm: true });
  
  console.log(`  舊實作 Lock 次數: ${oldLockCount} (每個 entry 1 次)`);
  console.log(`  新實作 Lock 次數: ${newLockCount} (每個 batch 1 次)`);
  console.log(`  改善: ${oldLockCount - newLockCount} 次 lock`);
}

執行測試

cd memory-lancedb-pro-test
node test/upgrader-phase2-extreme.test.mjs

輸出結果

===========================================
Memory Upgrader Phase-2 極限測試
===========================================

=== Test 1: Phase-2 確認 lock 次數 = 1 per batch ===
  Lock 次數: 1 (預期: 1)
  升級筆數: 10 (預期: 10)
  ✅ Test 1 通過

=== Test 4: Phase-2 批次邊界處理 ===
  Lock 次數: 3 (預期: 3 batches: 10+10+5)
  升級筆數: 25
  ✅ Test 4 通過

=== Test 5: Phase-2 極端並發測試 (100 entries) ===
  Lock 次數: 10 (預期: 10 batches)
  升級筆數: 100
  耗時: 1ms
  ✅ Test 5 通過

=== Test 7: 舊實作 vs 新實作 比較 ===
  舊實作 Lock 次數: 5 (每個 entry 1 次 = 5)
  新實作 Lock 次數: 1 (每個 batch 1 次)
  改善: 4 次 lock
  ✅ Test 7 通過

===========================================
All tests passed! ✅
===========================================

---

PR 位置

Branch: fix/p2-clean-fix (jlin53882/fork)
Commit: 0c7e361
檔案: src/memory-upgrader.ts

Plan B 追蹤

如需完全無鎖的解決方案，請參考 Issue #638：
#638