fix: capture thought timestamp at cycle start, not after LLM call (#590)

Co-authored-by: Kimi Agent <kimi@timmy.local>
Co-committed-by: Kimi Agent <kimi@timmy.local>

src/timmy/agents/base.py

@@ -149,12 +149,18 @@ class BaseAgent(ABC):
                 return result.content if hasattr(result, "content") else str(result)
             except self._TRANSIENT as exc:
                 self._handle_retry_or_raise(
-                    exc, attempt, max_retries, transient=True,
+                    exc,
+                    attempt,
+                    max_retries,
+                    transient=True,
                 )
                 await asyncio.sleep(min(2**attempt, 16))
             except Exception as exc:
                 self._handle_retry_or_raise(
-                    exc, attempt, max_retries, transient=False,
+                    exc,
+                    attempt,
+                    max_retries,
+                    transient=False,
                 )
                 await asyncio.sleep(min(2 ** (attempt - 1), 8))
         # Unreachable — _handle_retry_or_raise raises on last attempt.
@@ -162,19 +168,27 @@ class BaseAgent(ABC):
 
     @staticmethod
     def _handle_retry_or_raise(
-        exc: Exception, attempt: int, max_retries: int, *, transient: bool,
+        exc: Exception,
+        attempt: int,
+        max_retries: int,
+        *,
+        transient: bool,
     ) -> None:
         """Log a retry warning or raise after exhausting attempts."""
         if attempt < max_retries:
             if transient:
                 logger.warning(
                     "Ollama contention on attempt %d/%d: %s. Waiting before retry...",
-                    attempt, max_retries, type(exc).__name__,
+                    attempt,
+                    max_retries,
+                    type(exc).__name__,
                 )
             else:
                 logger.warning(
                     "Agent run failed on attempt %d/%d: %s. Retrying...",
-                    attempt, max_retries, exc,
+                    attempt,
+                    max_retries,
+                    exc,
                 )
         else:
             label = "Ollama unreachable" if transient else "Agent run failed"

src/timmy/thinking.py

@@ -341,6 +341,11 @@ class ThinkingEngine:
             )
             return None
 
+        # Capture arrival time *before* the LLM call so the thought
+        # timestamp reflects when the cycle started, not when the
+        # (potentially slow) generation finished.  Fixes #582.
+        arrived_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 +357,7 @@ class ThinkingEngine:
         if not content:
             return None
 
-        thought = self._store_thought(content, seed_type)
+        thought = self._store_thought(content, seed_type, arrived_at=arrived_at)
         self._last_thought_id = thought.id
 
         await self._process_thinking_result(thought)
@@ -1173,14 +1178,25 @@ 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:
-        """Persist a thought to SQLite."""
+    def _store_thought(
+        self,
+        content: str,
+        seed_type: str,
+        *,
+        arrived_at: str | None = None,
+    ) -> Thought:
+        """Persist a thought to SQLite.
+
+        Args:
+            arrived_at: ISO-8601 timestamp captured when the thinking cycle
+                started.  Falls back to now() for callers that don't supply it.
+        """
         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=arrived_at or datetime.now(UTC).isoformat(),
         )
 
         with _get_conn(self._db_path) as conn:

tests/timmy/test_agents_base.py

@@ -369,7 +369,10 @@ class TestHandleRetryOrRaise:
         BaseAgent = _make_base_class()
         with pytest.raises(ValueError, match="boom"):
             BaseAgent._handle_retry_or_raise(
-                ValueError("boom"), attempt=3, max_retries=3, transient=False,
+                ValueError("boom"),
+                attempt=3,
+                max_retries=3,
+                transient=False,
             )
 
     def test_raises_on_last_attempt_transient(self):
@@ -377,21 +380,30 @@ class TestHandleRetryOrRaise:
         exc = httpx.ConnectError("down")
         with pytest.raises(httpx.ConnectError):
             BaseAgent._handle_retry_or_raise(
-                exc, attempt=3, max_retries=3, transient=True,
+                exc,
+                attempt=3,
+                max_retries=3,
+                transient=True,
             )
 
     def test_no_raise_on_early_attempt(self):
         BaseAgent = _make_base_class()
         # Should return None (no raise) on non-final attempt
         result = BaseAgent._handle_retry_or_raise(
-            ValueError("retry me"), attempt=1, max_retries=3, transient=False,
+            ValueError("retry me"),
+            attempt=1,
+            max_retries=3,
+            transient=False,
         )
         assert result is None
 
     def test_no_raise_on_early_transient(self):
         BaseAgent = _make_base_class()
         result = BaseAgent._handle_retry_or_raise(
-            httpx.ReadTimeout("busy"), attempt=2, max_retries=3, transient=True,
+            httpx.ReadTimeout("busy"),
+            attempt=2,
+            max_retries=3,
+            transient=True,
         )
         assert result is None