From 7f7aefe5cb13856c4027368efaa4edbccec72342 Mon Sep 17 00:00:00 2001 From: coe0718 Date: Tue, 11 Aug 2026 22:31:15 -0400 Subject: [PATCH] fix: restore complete message timestamp coverage --- agent/tool_dispatch_helpers.py | 5 +- .../test_close_interrupted_tool_sequence.py | 2 +- tests/agent/test_codex_app_server_persist.py | 5 ++ .../test_empty_tool_name_loop_dampening.py | 7 ++- tests/agent/test_model_metadata.py | 18 +++++++ tests/agent/test_tool_dispatch_helpers.py | 6 +++ tests/agent/test_turn_context.py | 19 +++++-- ...rn_finalizer_final_response_persistence.py | 52 ++++++++++++++++++- tests/cli/test_cli_interrupt_ack_race.py | 4 +- tests/cli/test_focus_view.py | 11 ++-- tests/run_agent/test_413_compression.py | 10 ++-- .../test_partial_stream_finish_reason.py | 3 ++ tests/run_agent/test_run_agent.py | 10 ++-- 13 files changed, 130 insertions(+), 22 deletions(-) diff --git a/agent/tool_dispatch_helpers.py b/agent/tool_dispatch_helpers.py index 6e76e52081..af0970accb 100644 --- a/agent/tool_dispatch_helpers.py +++ b/agent/tool_dispatch_helpers.py @@ -32,6 +32,7 @@ import re from pathlib import Path from typing import Any, Dict, List, Optional +from agent.message_metadata import stamp_message_timestamp from agent.tool_result_classification import ( FILE_MUTATING_TOOL_NAMES as _FILE_MUTATING_TOOLS, ) @@ -557,13 +558,13 @@ def make_tool_result_message( callers should compare by value, not by ``is``. """ wrapped = _maybe_wrap_untrusted(name, content) - message = { + message = stamp_message_timestamp({ "role": "tool", "name": name, "tool_name": name, "content": wrapped, "tool_call_id": tool_call_id, - } + }) try: risk_metadata = _tool_output_risk_metadata(name, content) except Exception as exc: diff --git a/tests/agent/test_close_interrupted_tool_sequence.py b/tests/agent/test_close_interrupted_tool_sequence.py index c52b4d732e..23f7295c33 100644 --- a/tests/agent/test_close_interrupted_tool_sequence.py +++ b/tests/agent/test_close_interrupted_tool_sequence.py @@ -46,6 +46,7 @@ def test_closing_makes_next_user_message_alternation_safe(): produce the ``tool → user`` shape strict providers choke on.""" messages = _tool_tail() close_interrupted_tool_sequence(messages, None) + assert isinstance(messages[-1]["timestamp"], float) follow_on = messages + [{"role": "user", "content": "they do! increase the timing"}] _assert_no_tool_then_user(follow_on) @@ -65,4 +66,3 @@ def test_user_tail_is_left_untouched(): assert close_interrupted_tool_sequence(messages, None) is False assert len(messages) == 1 - diff --git a/tests/agent/test_codex_app_server_persist.py b/tests/agent/test_codex_app_server_persist.py index 85d4a5757f..55112fa319 100644 --- a/tests/agent/test_codex_app_server_persist.py +++ b/tests/agent/test_codex_app_server_persist.py @@ -72,6 +72,7 @@ def test_codex_success_flushes_and_reports_persisted(): effective_task_id="task-1", ) assert result["completed"] is True + assert isinstance(result["messages"][-1]["timestamp"], float) # With the agent as sole persister, the gateway must SKIP its DB write. assert result["agent_persisted"] is True @@ -152,6 +153,10 @@ def test_codex_turn_persists_each_message_exactly_once(): # Exactly one user turn, exactly one assistant turn — no duplicates. assert contents.count("USER_TURN") == 1, contents assert contents.count("CODEX_ASSISTANT") == 1, contents + assistant_row = next( + row for row in rows if row["content"] == "CODEX_ASSISTANT" + ) + assert isinstance(assistant_row["timestamp"], float) # session_search can now see the codex conversation. hits = {r["session_id"] for r in db.search_messages("CODEX_ASSISTANT")} assert sid in hits diff --git a/tests/agent/test_empty_tool_name_loop_dampening.py b/tests/agent/test_empty_tool_name_loop_dampening.py index 0da9d8a6aa..ab7d16d0c7 100644 --- a/tests/agent/test_empty_tool_name_loop_dampening.py +++ b/tests/agent/test_empty_tool_name_loop_dampening.py @@ -220,6 +220,12 @@ def test_mixed_batch_preserves_tool_call_result_pairing(agent_env): # and each must have exactly one matching tool result. assert set(tc_ids) == {"call_0", "call_1"} assert sorted(result_ids) == sorted(tc_ids) + assert all( + isinstance(message.get("timestamp"), float) + for message in msgs + if isinstance(message, dict) + and message.get("role") in {"user", "assistant", "tool"} + ) @@ -246,4 +252,3 @@ def test_invalid_tool_exhaustion_closes_tool_tail(agent_env): assert msgs[-1].get("role") == "assistant" assert "invalid tool call" in (msgs[-1].get("content") or "").lower() - diff --git a/tests/agent/test_model_metadata.py b/tests/agent/test_model_metadata.py index 94d281c696..3ab8dc0509 100644 --- a/tests/agent/test_model_metadata.py +++ b/tests/agent/test_model_metadata.py @@ -62,6 +62,24 @@ class TestEstimateMessagesTokensRough: assert result > 0 assert result == (len(str(msg)) + 3) // 4 + def test_persistence_timestamp_does_not_change_estimate(self): + """Durability metadata must not create artificial context pressure.""" + msg = { + "role": "assistant", + "content": "done", + "tool_calls": [ + { + "id": "call-1", + "function": {"name": "terminal", "arguments": "{}"}, + } + ], + } + stamped = {**msg, "timestamp": 1_781_976_577.123456} + + assert estimate_messages_tokens_rough([stamped]) == ( + estimate_messages_tokens_rough([msg]) + ) + def test_message_with_list_content(self): """Vision messages with multimodal content arrays. diff --git a/tests/agent/test_tool_dispatch_helpers.py b/tests/agent/test_tool_dispatch_helpers.py index f9e0eae0e1..34c0a6dda6 100644 --- a/tests/agent/test_tool_dispatch_helpers.py +++ b/tests/agent/test_tool_dispatch_helpers.py @@ -135,6 +135,12 @@ class TestUntrustedWrapping: class TestMakeToolResultMessage: + def test_message_is_timestamped_when_result_is_created(self, monkeypatch): + monkeypatch.setattr("agent.message_metadata.wall_time", lambda: 123.5) + + msg = make_tool_result_message("terminal", "ok", "call_timestamp") + + assert msg["timestamp"] == 123.5 def test_high_risk_message_content_wrapped(self): msg = make_tool_result_message("web_extract", SAMPLE_LONG_TEXT, "call_2") diff --git a/tests/agent/test_turn_context.py b/tests/agent/test_turn_context.py index 1ca237285e..9c087111ed 100644 --- a/tests/agent/test_turn_context.py +++ b/tests/agent/test_turn_context.py @@ -203,11 +203,21 @@ def test_returns_turn_context_with_user_message_appended(): assert isinstance(ctx, TurnContext) assert ctx.user_message == "hello" # The user turn was appended and indexed. - assert ctx.messages[-1] == {"role": "user", "content": "hello"} + assert ctx.messages[-1]["role"] == "user" + assert ctx.messages[-1]["content"] == "hello" + assert isinstance(ctx.messages[-1]["timestamp"], float) assert ctx.current_turn_user_idx == len(ctx.messages) - 1 assert ctx.active_system_prompt == "SYSTEM" +def test_user_message_preserves_platform_event_timestamp(): + agent = _FakeAgent() + + ctx = _build(agent, persist_user_timestamp=123.5) + + assert ctx.messages[-1]["timestamp"] == 123.5 + + # ── Trivial-prompt prefetch gate (PR #25350 salvage) ───────────────────────── # # The prologue is the ONLY place the per-turn synchronous @@ -267,7 +277,10 @@ def test_turn_start_replaces_stale_parent_history_with_compression_child(): assert agent._current_turn_id.startswith("compression-child:") log_context.assert_called_once_with("compression-child") assert ctx.conversation_history == compacted_history - assert ctx.messages == compacted_history + [{"role": "user", "content": "hello"}] + assert ctx.messages[:-1] == compacted_history + assert ctx.messages[-1]["role"] == "user" + assert ctx.messages[-1]["content"] == "hello" + assert isinstance(ctx.messages[-1]["timestamp"], float) assert all(message.get("content") != "stale parent" for message in ctx.messages) @@ -309,6 +322,7 @@ def test_pending_cli_message_uses_clean_override_for_api_local_note(): assert ctx.messages[-1] is staged assert ctx.messages[-1]["content"] == "[MODEL NOTE]\n\nclean prompt" assert ctx.messages[-1]["_db_persisted"] is True + assert isinstance(ctx.messages[-1]["timestamp"], float) assert agent._pending_cli_user_message is None @@ -438,4 +452,3 @@ def test_prologue_does_not_title_machine_driven_runs(platform): overwritten or never read. """ assert not _title_turn(platform).called - diff --git a/tests/agent/test_turn_finalizer_final_response_persistence.py b/tests/agent/test_turn_finalizer_final_response_persistence.py index 7badde20c8..52106f07fe 100644 --- a/tests/agent/test_turn_finalizer_final_response_persistence.py +++ b/tests/agent/test_turn_finalizer_final_response_persistence.py @@ -123,9 +123,57 @@ def test_final_response_closes_tool_tail_before_persistence(monkeypatch): _turn_exit_reason="fallback_prior_turn_content", ) - assert result["messages"][-1] == {"role": "assistant", "content": "Done."} + assert result["messages"][-1]["role"] == "assistant" + assert result["messages"][-1]["content"] == "Done." + assert isinstance(result["messages"][-1]["timestamp"], float) assert agent.persisted_messages is not None - assert agent.persisted_messages[-1] == {"role": "assistant", "content": "Done."} + assert agent.persisted_messages[-1] == result["messages"][-1] + + +def test_fallback_timestamp_survives_delayed_sqlite_persistence( + monkeypatch, tmp_path +): + """The durable row records message creation, not the later DB flush.""" + from hermes_state import SessionDB + + created_at = 1_781_976_577.25 + persisted_at = created_at + 600 + monkeypatch.setattr("agent.message_metadata.wall_time", lambda: created_at) + monkeypatch.setattr("hermes_state.time.time", lambda: persisted_at) + monkeypatch.setattr("hermes_cli.plugins.invoke_hook", lambda *_a, **_kw: []) + + db = SessionDB(db_path=tmp_path / "state.db") + db.create_session("sess-test", source="cli") + agent = FakeAgent() + + def persist_to_sqlite(messages, _conversation_history): + db.replace_messages(agent.session_id, messages) + agent.persisted_messages = db.get_messages_as_conversation(agent.session_id) + + agent._persist_session = persist_to_sqlite + messages = [ + {"role": "user", "content": "do it", "timestamp": created_at - 1}, + {"role": "tool", "content": "ok", "tool_call_id": "call-1"}, + ] + + finalize_turn( + agent, + final_response="Done.", + api_call_count=2, + interrupted=False, + failed=False, + messages=messages, + conversation_history=[], + effective_task_id="task", + turn_id="turn", + user_message="do it", + original_user_message="do it", + _should_review_memory=False, + _turn_exit_reason="fallback_prior_turn_content", + ) + + assert agent.persisted_messages[-1]["timestamp"] == created_at + assert agent.persisted_messages[-1]["timestamp"] != persisted_at def test_final_response_fills_pure_tool_call_tail(monkeypatch): diff --git a/tests/cli/test_cli_interrupt_ack_race.py b/tests/cli/test_cli_interrupt_ack_race.py index 0a254fb462..ee2b53b696 100644 --- a/tests/cli/test_cli_interrupt_ack_race.py +++ b/tests/cli/test_cli_interrupt_ack_race.py @@ -411,7 +411,9 @@ def test_chat_clears_previous_turn_persistence_override_before_staging(): assert agent.staged_override is None assert agent._persist_user_message_idx is None assert agent._persist_user_message_timestamp is None - assert agent.staged_message == {"role": "user", "content": "new prompt"} + assert agent.staged_message["role"] == "user" + assert agent.staged_message["content"] == "new prompt" + assert isinstance(agent.staged_message["timestamp"], float) diff --git a/tests/cli/test_focus_view.py b/tests/cli/test_focus_view.py index 7d22dcd6e2..88a5106545 100644 --- a/tests/cli/test_focus_view.py +++ b/tests/cli/test_focus_view.py @@ -323,10 +323,13 @@ class TestModelFacingMessagesUnchanged: @pytest.mark.parametrize("dispatch_mode", ["sequential", "concurrent"]) def test_model_facing_messages_identical_with_focus_on_vs_off(self, dispatch_mode): - # Focus ON == the existing tool_progress "off" suppression path. - focus_on = _run_fake_turn(FOCUS_TOOL_PROGRESS_MODE, dispatch_mode) - # Focus OFF == the default noisy display mode. - focus_off = _run_fake_turn("all", dispatch_mode) + # Creation timestamps are durable metadata, so hold the clock steady + # while comparing otherwise identical turns. + with patch("agent.message_metadata.wall_time", return_value=1_700_000_000.0): + # Focus ON == the existing tool_progress "off" suppression path. + focus_on = _run_fake_turn(FOCUS_TOOL_PROGRESS_MODE, dispatch_mode) + # Focus OFF == the default noisy display mode. + focus_off = _run_fake_turn("all", dispatch_mode) assert focus_on == focus_off, ( "focus view altered the model-facing messages — display-only " diff --git a/tests/run_agent/test_413_compression.py b/tests/run_agent/test_413_compression.py index 838817386b..fcedeca0e1 100644 --- a/tests/run_agent/test_413_compression.py +++ b/tests/run_agent/test_413_compression.py @@ -135,10 +135,12 @@ def test_current_user_turn_is_persisted_before_provider_call(agent): assert observed[0][0] == "persist" assert observed[1][0] == "provider" persisted_messages = observed[0][1] - assert persisted_messages[-1] == { - "role": "user", - "content": "new message that must survive a crash", - } + assert persisted_messages[-1]["role"] == "user" + assert ( + persisted_messages[-1]["content"] + == "new message that must survive a crash" + ) + assert isinstance(persisted_messages[-1]["timestamp"], float) class TestHTTP413Compression: diff --git a/tests/run_agent/test_partial_stream_finish_reason.py b/tests/run_agent/test_partial_stream_finish_reason.py index c3f8090135..129edeb7a7 100644 --- a/tests/run_agent/test_partial_stream_finish_reason.py +++ b/tests/run_agent/test_partial_stream_finish_reason.py @@ -608,6 +608,7 @@ class TestBuildAssistantMessageEmptyContentPad: "Builder must store textless turns as-is — wire repair is owned " "by repair_empty_non_final_messages at the send boundary." ) + assert isinstance(msg["timestamp"], float) def test_tool_call_turn_content_left_empty(self): @@ -622,6 +623,7 @@ class TestBuildAssistantMessageEmptyContentPad: ) assert msg["content"] == "" assert msg["tool_calls"] + assert isinstance(msg["timestamp"], float) def test_non_empty_content_unchanged(self): from agent.chat_completion_helpers import build_assistant_message @@ -630,6 +632,7 @@ class TestBuildAssistantMessageEmptyContentPad: agent = self._agent_for_builder() msg = build_assistant_message(agent, _mock_assistant_msg(content="hi"), "stop") assert msg["content"] == "hi" + assert isinstance(msg["timestamp"], float) class TestSendTimeEmptyAssistantPad: diff --git a/tests/run_agent/test_run_agent.py b/tests/run_agent/test_run_agent.py index 4fb43f77d7..b5caf83233 100644 --- a/tests/run_agent/test_run_agent.py +++ b/tests/run_agent/test_run_agent.py @@ -3496,10 +3496,12 @@ class TestRunConversation: # Partial reply is surfaced and persisted as an assistant turn so the # next turn remembers what the model said. assert result["final_response"] == "Sure, here's how to do it: first" - assert result["messages"][-1] == { - "role": "assistant", - "content": "Sure, here's how to do it: first", - } + assert result["messages"][-1]["role"] == "assistant" + assert ( + result["messages"][-1]["content"] + == "Sure, here's how to do it: first" + ) + assert isinstance(result["messages"][-1]["timestamp"], float) def test_redirect_during_thinking_retries_same_turn_with_context(self, agent): """A corrective follow-up does not end the turn, and displayed reasoning