events: pair every model_call_started with a model_call_finished

sdk/event_templates.py

@@ -5,7 +5,7 @@
   | { seq: number; type: "reasoning"; text: string }
   | { seq: number; type: "started"; provider: string; model: string }
   | { seq: number; type: "model_call_started"; provider: string; model: string }
-  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number }
+  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number; retried?: boolean }
   | { seq: number; type: "tool_call"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_call_started"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_rejected"; name: string; reason: "budget" | "duplicate" | string; input: Record<string, unknown>; message: string }
@@ -28,7 +28,7 @@
   | { seq: number; type: "reasoning"; text: string }
   | { seq: number; type: "started"; provider: string; model: string }
   | { seq: number; type: "model_call_started"; provider: string; model: string }
-  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number }
+  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number; retried?: boolean }
   | { seq: number; type: "tool_call"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_call_started"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_rejected"; name: string; reason: "budget" | "duplicate" | string; input: Record<string, unknown>; message: string }

sdk/ts/harness.ts

@@ -29,7 +29,7 @@ export type Event =
   | { seq: number; type: "reasoning"; text: string }
   | { seq: number; type: "started"; provider: string; model: string }
   | { seq: number; type: "model_call_started"; provider: string; model: string }
-  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number }
+  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number; retried?: boolean }
   | { seq: number; type: "tool_call"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_call_started"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_rejected"; name: string; reason: "budget" | "duplicate" | string; input: Record<string, unknown>; message: string }

sdk/ts/remote.ts

@@ -25,7 +25,7 @@ export type Event =
   | { seq: number; type: "reasoning"; text: string }
   | { seq: number; type: "started"; provider: string; model: string }
   | { seq: number; type: "model_call_started"; provider: string; model: string }
-  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number }
+  | { seq: number; type: "model_call_finished"; provider: string; model: string; ok: boolean; ms: number; retried?: boolean }
   | { seq: number; type: "tool_call"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_call_started"; name: string; input: Record<string, unknown> }
   | { seq: number; type: "tool_rejected"; name: string; reason: "budget" | "duplicate" | string; input: Record<string, unknown>; message: string }

src/agent_request.zig

@@ -216,6 +216,8 @@ pub fn request(self: *Agent, tools_in: ?[]const u8) !std.json.ObjectMap {
     const max_openai404_retries: usize = 2;
     var gw_retry = policy.GatewayRetryState{}; // #gateway-artifact state (agent_gateway_retry.zig)
     @import("cache_ttl.zig").begin(self); // #1320: before request_started moves
+    var call: @import("model_call.zig").Call = .{}; // #1665: pairs every started attempt
+    errdefer call.fail(self, false);
     rebuild: while (true) {
         if (@import("agent_async_tools.zig").started(self)) return error.AsyncToolStreamFailed;
         const live = self.usesLiveTransport();
@@ -241,7 +243,7 @@ pub fn request(self: *Agent, tools_in: ?[]const u8) !std.json.ObjectMap {
         const t0: Io.Timestamp = .now(self.io, .awake);
         self.request_started = t0;
         self.first_token_traced = false;
-        if (main_mod.json_mode and !self.sub) self.emit(.{ .type = "model_call_started", .provider = self.provider.id, .model = self.provider.model });
+        call.start(self);
         // HTTP calls are flaky: a kept-alive connection the server closed
         // (HttpConnectionClosing), a reset, a truncated TLS read. Retry a
         // few times with a fresh connection; on persistent failure surface
@@ -424,7 +426,7 @@ pub fn request(self: *Agent, tools_in: ?[]const u8) !std.json.ObjectMap {
                         continue :rebuild;
                     }
                     if (self.tracer) |tr| tr.api(self.label, self.sub, self.provider.model, ms, body.len, resp_body.len, self.last_context_tokens, self.last_cache_read, false);
-                    if (main_mod.json_mode and !self.sub) self.emit(.{ .type = "model_call_finished", .provider = self.provider.id, .model = self.provider.model, .ok = true, .ms = ms });
+                    call.finish(self, ms);
                     try @import("agent_model_loop.zig").checkResponse(self, obj);
                     return obj;
                 },
@@ -513,7 +515,7 @@ pub fn request(self: *Agent, tools_in: ?[]const u8) !std.json.ObjectMap {
                 if (recoverBehavioralOverflow(self, root, &context_retried)) continue; // #414: silent overflow / upstream truncation → trim + retry
                 if (!self.compaction_request) self.compact_transport_failures = 0;
                 if (self.tracer) |tr| tr.api(self.label, self.sub, self.provider.model, ms, body.len, resp_body.len, self.last_context_tokens, self.last_cache_read, false);
-                if (main_mod.json_mode and !self.sub) self.emit(.{ .type = "model_call_finished", .provider = self.provider.id, .model = self.provider.model, .ok = true, .ms = ms });
+                call.finish(self, ms);
                 try @import("agent_model_loop.zig").checkResponse(self, root);
                 return root;
             }
@@ -587,7 +589,7 @@ pub fn request(self: *Agent, tools_in: ?[]const u8) !std.json.ObjectMap {
         if (recoverBehavioralOverflow(self, root, &context_retried)) continue; // #414: same, on the non-streamed body
         if (!self.compaction_request) self.compact_transport_failures = 0;
         if (self.tracer) |tr| tr.api(self.label, self.sub, self.provider.model, ms, body.len, resp_body.len, self.last_context_tokens, self.last_cache_read, false);
-        if (main_mod.json_mode and !self.sub) self.emit(.{ .type = "model_call_finished", .provider = self.provider.id, .model = self.provider.model, .ok = true, .ms = ms });
+        call.finish(self, ms);
         try @import("agent_model_loop.zig").checkResponse(self, root);
         return root;
     }

src/main.zig

@@ -573,7 +573,7 @@ test { // ── Unit tests (`zig build test`): pull in tests from imported modu
     _ = .{ @import("compact_status.zig"), @import("compact_mix.zig") }; // compact status + GRAFF_COMPACT_MIX mixture arm
     _ = .{ @import("agent_clef_compact.zig"), @import("agent_clef_compact_tests.zig"), @import("agent_clef_archive.zig") }; // gateway /v1/compact client (Clef pruning) + archive mode
     _ = @import("agent_compact_recover.zig"); // compaction last-resort recovery (split for the ceiling)
-    _ = @import("agent_request_search_tests.zig");
+    _ = .{ @import("agent_request_search_tests.zig"), @import("model_call.zig") }; // #1665: model-call event pairing
     _ = @import("agent_ws_steer.zig");
     _ = @import("agent_ws_signal.zig");
     _ = .{ @import("agent_ws_prewarm.zig"), @import("agent_ws_headers.zig") };

src/model_call.zig

@@ -0,0 +1,67 @@
+//! #1665: JSON model-call lifecycle. Every `model_call_started` pairs with one
+//! `model_call_finished`. A request rebuilt before its response (a WebSocket
+//! reanchor, a stream reconnect, a steer, a recovered overflow) closes the
+//! attempt with ok=false and retried=true before the next one starts; an
+//! attempt that ends the request with an error closes with ok=false.
+
+const main_mod = @import("main.zig");
+const Agent = @import("agent.zig").Agent;
+
+pub const Call = struct {
+    open: bool = false,
+
+    fn on(self: *Agent) bool {
+        return main_mod.json_mode and !self.sub;
+    }
+
+    pub fn start(c: *Call, self: *Agent) void {
+        if (!on(self)) return;
+        if (c.open) c.fail(self, true);
+        self.emit(.{ .type = "model_call_started", .provider = self.provider.id, .model = self.provider.model });
+        c.open = true;
+    }
+
+    pub fn finish(c: *Call, self: *Agent, ms: i64) void {
+        if (!c.open) return;
+        c.open = false;
+        self.emit(.{ .type = "model_call_finished", .provider = self.provider.id, .model = self.provider.model, .ok = true, .ms = ms });
+    }
+
+    /// The attempt ended without a usable response. `retried`: the request
+    /// goes out again as a new attempt.
+    pub fn fail(c: *Call, self: *Agent, retried: bool) void {
+        if (!c.open) return;
+        c.open = false;
+        const ms: i64 = if (self.request_started) |t0| t0.untilNow(self.io, .awake).toMilliseconds() else 0;
+        self.emit(.{ .type = "model_call_finished", .provider = self.provider.id, .model = self.provider.model, .ok = false, .ms = ms, .retried = retried });
+    }
+};
+
+test "every started model call pairs with one finished event" {
+    const std = @import("std");
+    var arena_state = std.heap.ArenaAllocator.init(std.testing.allocator);
+    defer arena_state.deinit();
+    var agent = try @import("agent_request_body_responses.zig").testAgentFor(arena_state.allocator(), "codex", .responses, "gpt-5");
+    var buf: [4096]u8 = undefined;
+    var w: std.Io.Writer = .fixed(&buf);
+    agent.out = &w;
+    const was_json = main_mod.json_mode;
+    main_mod.json_mode = true;
+    defer main_mod.json_mode = was_json;
+
+    var call: Call = .{};
+    call.start(&agent); // first attempt
+    call.start(&agent); // rebuilt after a reanchor: closes the first
+    call.finish(&agent, 12);
+    call.finish(&agent, 12); // already closed: no second event
+    call.start(&agent);
+    call.fail(&agent, false); // the request ended with an error
+    call.fail(&agent, false);
+
+    const out = w.buffered();
+    try std.testing.expectEqual(@as(usize, 3), std.mem.count(u8, out, "\"model_call_started\""));
+    try std.testing.expectEqual(@as(usize, 3), std.mem.count(u8, out, "\"model_call_finished\""));
+    try std.testing.expectEqual(@as(usize, 1), std.mem.count(u8, out, "\"retried\":true"));
+    try std.testing.expectEqual(@as(usize, 1), std.mem.count(u8, out, "\"retried\":false"));
+    try std.testing.expectEqual(@as(usize, 1), std.mem.count(u8, out, "\"ok\":true"));
+}

src/schema_protocol.zig

@@ -45,7 +45,7 @@ pub const json =
     \\    {"type": "reasoning", "text": "reasoning/thinking delta (GUI shows a collapsible Thinking block)"},
     \\    {"type": "started", "provider": "provider", "model": "model"},
     \\    {"type": "model_call_started", "provider": "provider", "model": "model"},
-    \\    {"type": "model_call_finished", "provider": "provider", "model": "model", "ok": true, "ms": 0},
+    \\    {"type": "model_call_finished", "provider": "provider", "model": "model", "ok": true, "ms": 0, "retried": "present only when ok is false: true when the request goes out again as a new attempt (pairs every model_call_started)"},
     \\    {"type": "tool_call", "name": "tool", "input": {}, "id": "sa-… when a correlated tool call is available; pairs with tool_result/agent_usage"},
     \\    {"type": "tool_call_started", "name": "tool", "input": {}},
     \\    {"type": "tool_rejected", "name": "tool", "reason": "budget|duplicate", "input": {}, "message": "..."},