fix: capture thought timestamp at cycle start, not after LLM call

The thinking engine was recording created_at after the LLM finished
generating a response, causing up to 11 minutes of timestamp drift
(interval wait + model latency + dedup retries). Now the timestamp
is captured at the beginning of think_once() and passed through to
_store_thought(), so thoughts reflect when the cycle started.

Fixes #582

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
kimi
2026-03-20 11:26:08 -04:00
parent 48103bb076
commit c5b2809f61
2 changed files with 55 additions and 3 deletions

View File

@@ -341,6 +341,10 @@ class ThinkingEngine:
)
return None
# Capture timestamp now, before the LLM call, so the thought
# reflects when the cycle started — not when the model finished.
started_at = datetime.now(UTC).isoformat()
memory_context, system_context, recent_thoughts = self._build_thinking_context()
content, seed_type = await self._generate_novel_thought(
@@ -352,7 +356,7 @@ class ThinkingEngine:
if not content:
return None
thought = self._store_thought(content, seed_type)
thought = self._store_thought(content, seed_type, started_at)
self._last_thought_id = thought.id
await self._process_thinking_result(thought)
@@ -1173,14 +1177,16 @@ class ThinkingEngine:
raw = run.content if hasattr(run, "content") else str(run)
return _THINK_TAG_RE.sub("", raw) if raw else raw
def _store_thought(self, content: str, seed_type: str) -> Thought:
def _store_thought(
self, content: str, seed_type: str, created_at: str | None = None
) -> Thought:
"""Persist a thought to SQLite."""
thought = Thought(
id=str(uuid.uuid4()),
content=content,
seed_type=seed_type,
parent_id=self._last_thought_id,
created_at=datetime.now(UTC).isoformat(),
created_at=created_at or datetime.now(UTC).isoformat(),
)
with _get_conn(self._db_path) as conn:

View File

@@ -92,6 +92,17 @@ def test_store_and_retrieve_thought(tmp_path):
assert retrieved.content == thought.content
def test_store_thought_accepts_created_at(tmp_path):
"""_store_thought should use the provided created_at instead of now() (#582)."""
engine = _make_engine(tmp_path)
fixed_ts = "2026-01-01T00:00:00+00:00"
thought = engine._store_thought("Timestamped thought.", "freeform", created_at=fixed_ts)
assert thought.created_at == fixed_ts
retrieved = engine.get_thought(thought.id)
assert retrieved.created_at == fixed_ts
def test_store_thought_chains(tmp_path):
"""Each new thought should link to the previous one via parent_id."""
engine = _make_engine(tmp_path)
@@ -1188,3 +1199,38 @@ def test_references_real_files_blocks_mixed(tmp_path):
# Mix of real and fake files — should fail because of the fake one
text = "Fix src/timmy/thinking.py and also src/timmy/nonexistent_module.py for the memory leak."
assert ThinkingEngine._references_real_files(text) is False
# ---------------------------------------------------------------------------
# Thought timestamp accuracy (#582)
# ---------------------------------------------------------------------------
@pytest.mark.asyncio
async def test_think_once_timestamp_captured_before_llm_call(tmp_path):
"""Thought created_at must reflect cycle start, not post-LLM storage time (#582)."""
import asyncio
from datetime import UTC, datetime
engine = _make_engine(tmp_path)
pre_call_time = datetime.now(UTC)
async def slow_agent(prompt):
await asyncio.sleep(0.3) # simulate LLM latency
return "A delayed thought."
with (
patch.object(engine, "_call_agent", side_effect=slow_agent),
patch.object(engine, "_log_event"),
patch.object(engine, "_broadcast", new_callable=AsyncMock),
):
thought = await engine.think_once()
assert thought is not None
ts = datetime.fromisoformat(thought.created_at)
# The thought timestamp should be close to pre_call_time (before LLM),
# not the time after the 0.3s delay.
drift = (ts - pre_call_time).total_seconds()
assert drift < 0.2, f"Timestamp drifted {drift:.2f}s — should be captured before LLM call"