Skip to content

Commit b271ca0

Browse files
authored
Improve trace resilience and add subagent lifecycle spans (#10)
* Types: add stale and flush config fields * Manifest: expose stale cleanup and flush retry settings * Service: harden tracing lifecycle and add subagent spans * Tests: cover subagent hooks, flush retries, and stale config * Docs: document subagent events and advanced reliability config
1 parent 1c5235a commit b271ca0

5 files changed

Lines changed: 853 additions & 163 deletions

File tree

README.md

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,12 @@ Then confirm traces in your Opik project.
7575
"apiUrl": "https://www.comet.com/opik/api",
7676
"projectName": "openclaw",
7777
"workspaceName": "default",
78-
"tags": ["openclaw"]
78+
"tags": ["openclaw"],
79+
"staleTraceCleanupEnabled": true,
80+
"staleTraceTimeoutMs": 300000,
81+
"staleSweepIntervalMs": 60000,
82+
"flushRetryCount": 2,
83+
"flushRetryBaseDelayMs": 250
7984
}
8085
}
8186
}
@@ -105,6 +110,9 @@ Then confirm traces in your Opik project.
105110
| `llm_output` | llm span update/end | writes usage/output and closes span |
106111
| `before_tool_call` | tool span start | captures tool name + input |
107112
| `after_tool_call` | tool span update/end | captures output/error + duration |
113+
| `subagent_spawning` | subagent span start | starts subagent lifecycle span on requester trace |
114+
| `subagent_spawned` | subagent span update | enriches subagent span with run metadata |
115+
| `subagent_ended` | subagent span update/end | finalizes subagent span with outcome/error |
108116
| `agent_end` | trace finalize | closes pending spans and trace |
109117

110118
## Known limitation

openclaw.plugin.json

Lines changed: 30 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,12 @@
1414
"tags": {
1515
"type": "array",
1616
"items": { "type": "string" }
17-
}
17+
},
18+
"staleTraceCleanupEnabled": { "type": "boolean" },
19+
"staleTraceTimeoutMs": { "type": "number" },
20+
"staleSweepIntervalMs": { "type": "number" },
21+
"flushRetryCount": { "type": "number" },
22+
"flushRetryBaseDelayMs": { "type": "number" }
1823
}
1924
},
2025
"uiHints": {
@@ -44,6 +49,30 @@
4449
"tags": {
4550
"label": "Default Tags",
4651
"help": "List of tags applied to every created trace."
52+
},
53+
"staleTraceCleanupEnabled": {
54+
"label": "Stale Cleanup Enabled",
55+
"help": "When enabled, traces inactive longer than the timeout are force-closed."
56+
},
57+
"staleTraceTimeoutMs": {
58+
"label": "Stale Timeout (ms)",
59+
"placeholder": "300000",
60+
"help": "Inactivity window before stale traces are force-closed. Default is 300000."
61+
},
62+
"staleSweepIntervalMs": {
63+
"label": "Stale Sweep Interval (ms)",
64+
"placeholder": "60000",
65+
"help": "How often stale traces are scanned. Default is 60000."
66+
},
67+
"flushRetryCount": {
68+
"label": "Flush Retry Count",
69+
"placeholder": "2",
70+
"help": "Number of retry attempts after a failed flush. Default is 2."
71+
},
72+
"flushRetryBaseDelayMs": {
73+
"label": "Flush Retry Base Delay (ms)",
74+
"placeholder": "250",
75+
"help": "Base delay for exponential flush retry backoff. Default is 250."
4776
}
4877
}
4978
}

src/service.test.ts

Lines changed: 229 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -88,6 +88,11 @@ type OpikCfg = {
8888
projectName?: string;
8989
workspaceName?: string;
9090
tags?: string[];
91+
staleTraceTimeoutMs?: number;
92+
staleSweepIntervalMs?: number;
93+
staleTraceCleanupEnabled?: boolean;
94+
flushRetryCount?: number;
95+
flushRetryBaseDelayMs?: number;
9196
};
9297

9398
function createServiceContext(
@@ -219,16 +224,19 @@ describe("opik service", () => {
219224
});
220225
});
221226

222-
test("registers 5 hooks + 1 diagnostic listener on start", async () => {
227+
test("registers lifecycle/tool/subagent hooks + 1 diagnostic listener on start", async () => {
223228
const { api } = createApi();
224229
const service = createOpikService(api as any);
225230
await service.start(createServiceContext() as any);
226231

227-
expect(api.on).toHaveBeenCalledTimes(5);
232+
expect(api.on).toHaveBeenCalledTimes(8);
228233
expect(api.on).toHaveBeenCalledWith("llm_input", expect.any(Function));
229234
expect(api.on).toHaveBeenCalledWith("llm_output", expect.any(Function));
230235
expect(api.on).toHaveBeenCalledWith("before_tool_call", expect.any(Function));
231236
expect(api.on).toHaveBeenCalledWith("after_tool_call", expect.any(Function));
237+
expect(api.on).toHaveBeenCalledWith("subagent_spawning", expect.any(Function));
238+
expect(api.on).toHaveBeenCalledWith("subagent_spawned", expect.any(Function));
239+
expect(api.on).toHaveBeenCalledWith("subagent_ended", expect.any(Function));
232240
expect(api.on).toHaveBeenCalledWith("agent_end", expect.any(Function));
233241
expect(diagnosticListeners).toHaveLength(1);
234242
});
@@ -840,7 +848,94 @@ describe("opik service", () => {
840848
});
841849

842850
// =========================================================================
843-
// 6. agent_end hook
851+
// 6. subagent hooks
852+
// =========================================================================
853+
describe("subagent hooks", () => {
854+
test("records subagent lifecycle on the requester trace", async () => {
855+
const { api, hooks } = createApi();
856+
const mockTrace = opikState.createMockTrace();
857+
const mockLlmSpan = opikState.createMockSpan();
858+
const mockSubagentSpan = opikState.createMockSpan();
859+
mockTrace.span.mockReturnValueOnce(mockLlmSpan).mockReturnValueOnce(mockSubagentSpan);
860+
mockTraceFn.mockReturnValue(mockTrace);
861+
862+
const service = createOpikService(api as any);
863+
await service.start(createServiceContext() as any);
864+
865+
invokeHook(
866+
hooks,
867+
"llm_input",
868+
{ model: "m", provider: "p", prompt: "" },
869+
agentCtx("parent-session", { agentId: "parent-agent" }),
870+
);
871+
872+
invokeHook(
873+
hooks,
874+
"subagent_spawning",
875+
{
876+
childSessionKey: "child-session",
877+
agentId: "writer",
878+
mode: "run",
879+
threadRequested: true,
880+
},
881+
{ requesterSessionKey: "parent-session", childSessionKey: "child-session", runId: "run-sub-1" },
882+
);
883+
884+
invokeHook(
885+
hooks,
886+
"subagent_spawned",
887+
{
888+
childSessionKey: "child-session",
889+
agentId: "writer",
890+
mode: "run",
891+
threadRequested: true,
892+
runId: "run-sub-1",
893+
},
894+
{ requesterSessionKey: "parent-session", childSessionKey: "child-session", runId: "run-sub-1" },
895+
);
896+
897+
invokeHook(
898+
hooks,
899+
"subagent_ended",
900+
{
901+
targetSessionKey: "child-session",
902+
targetKind: "subagent",
903+
reason: "completed",
904+
outcome: "ok",
905+
},
906+
{ requesterSessionKey: "parent-session", childSessionKey: "child-session", runId: "run-sub-1" },
907+
);
908+
909+
expect(mockTrace.span).toHaveBeenCalledWith(
910+
expect.objectContaining({
911+
name: "subagent:writer",
912+
input: expect.objectContaining({ childSessionKey: "child-session" }),
913+
}),
914+
);
915+
expect(mockSubagentSpan.update).toHaveBeenCalledWith(
916+
expect.objectContaining({
917+
metadata: expect.objectContaining({
918+
status: "spawned",
919+
childSessionKey: "child-session",
920+
runId: "run-sub-1",
921+
}),
922+
}),
923+
);
924+
expect(mockSubagentSpan.update).toHaveBeenCalledWith(
925+
expect.objectContaining({
926+
metadata: expect.objectContaining({
927+
status: "ended",
928+
targetSessionKey: "child-session",
929+
outcome: "ok",
930+
}),
931+
}),
932+
);
933+
expect(mockSubagentSpan.end).toHaveBeenCalledTimes(1);
934+
});
935+
});
936+
937+
// =========================================================================
938+
// 7. agent_end hook
844939
// =========================================================================
845940
describe("agent_end hook", () => {
846941
test("closes orphaned spans, merges costMeta into metadata, ends trace, flushes", async () => {
@@ -895,7 +990,7 @@ describe("opik service", () => {
895990
);
896991

897992
expect(mockTrace.end).toHaveBeenCalled();
898-
expect(mockFlush).toHaveBeenCalled();
993+
await vi.waitFor(() => expect(mockFlush).toHaveBeenCalled());
899994
});
900995

901996
test("includes errorInfo when event has error", async () => {
@@ -1004,6 +1099,43 @@ describe("opik service", () => {
10041099
});
10051100
});
10061101

1102+
test("preserves total-only usage in final trace metadata", async () => {
1103+
const { api, hooks } = createApi();
1104+
const mockLlmSpan = opikState.createMockSpan();
1105+
const mockTrace = opikState.createMockTrace();
1106+
mockTrace.span.mockReturnValue(mockLlmSpan);
1107+
mockTraceFn.mockReturnValue(mockTrace);
1108+
1109+
const service = createOpikService(api as any);
1110+
await service.start(createServiceContext() as any);
1111+
1112+
invokeHook(
1113+
hooks,
1114+
"llm_input",
1115+
{ model: "gpt-4", provider: "openai", prompt: "hi" },
1116+
agentCtx("s1"),
1117+
);
1118+
1119+
invokeHook(
1120+
hooks,
1121+
"llm_output",
1122+
{
1123+
model: "gpt-4",
1124+
provider: "openai",
1125+
assistantTexts: ["Hello!"],
1126+
usage: { total: 150 },
1127+
},
1128+
agentCtx("s1"),
1129+
);
1130+
1131+
invokeHook(hooks, "agent_end", { success: true, durationMs: 500 }, agentCtx("s1"));
1132+
1133+
await Promise.resolve();
1134+
1135+
const metadata = mockTrace.update.mock.calls[0][0].metadata as Record<string, unknown>;
1136+
expect(metadata.usage).toEqual(expect.objectContaining({ total: 150 }));
1137+
});
1138+
10071139
test("no-ops without active trace", async () => {
10081140
const { api, hooks } = createApi();
10091141
const service = createOpikService(api as any);
@@ -1075,7 +1207,7 @@ describe("opik service", () => {
10751207
}),
10761208
);
10771209
expect(mockTrace.end).toHaveBeenCalledTimes(1);
1078-
expect(mockFlush).toHaveBeenCalledTimes(1);
1210+
await vi.waitFor(() => expect(mockFlush).toHaveBeenCalledTimes(1));
10791211
});
10801212

10811213
test("agent_end without llm_output extracts output from messages", async () => {
@@ -1474,7 +1606,68 @@ describe("opik service", () => {
14741606
vi.advanceTimersByTime(5 * 60 * 1000 + 60 * 1000);
14751607

14761608
// After cleanup, flush should be called since activeTraces is now empty
1477-
expect(mockFlush).toHaveBeenCalled();
1609+
await vi.waitFor(() => expect(mockFlush).toHaveBeenCalled());
1610+
1611+
await service.stop?.({} as any);
1612+
});
1613+
1614+
test("can disable stale cleanup via config", async () => {
1615+
vi.useFakeTimers();
1616+
1617+
const { api, hooks } = createApi();
1618+
const mockTrace = opikState.createMockTrace();
1619+
mockTraceFn.mockReturnValue(mockTrace);
1620+
1621+
const service = createOpikService(api as any);
1622+
await service.start(
1623+
createServiceContext(true, {
1624+
enabled: true,
1625+
apiKey: "test-key",
1626+
staleTraceCleanupEnabled: false,
1627+
}) as any,
1628+
);
1629+
1630+
invokeHook(hooks, "llm_input", { model: "m", provider: "p", prompt: "" }, agentCtx("s1"));
1631+
1632+
vi.advanceTimersByTime(15 * 60 * 1000);
1633+
1634+
const staleCalls = mockTrace.update.mock.calls.filter(
1635+
(c: unknown[]) =>
1636+
(c[0] as Record<string, unknown>)?.metadata &&
1637+
((c[0] as Record<string, unknown>).metadata as Record<string, unknown>)?.staleCleanup,
1638+
);
1639+
expect(staleCalls).toHaveLength(0);
1640+
1641+
await service.stop?.({} as any);
1642+
});
1643+
1644+
test("uses configured stale timeout and sweep interval", async () => {
1645+
vi.useFakeTimers();
1646+
1647+
const { api, hooks } = createApi();
1648+
const mockTrace = opikState.createMockTrace();
1649+
mockTraceFn.mockReturnValue(mockTrace);
1650+
1651+
const service = createOpikService(api as any);
1652+
await service.start(
1653+
createServiceContext(true, {
1654+
enabled: true,
1655+
apiKey: "test-key",
1656+
staleTraceTimeoutMs: 2_000,
1657+
staleSweepIntervalMs: 1_000,
1658+
}) as any,
1659+
);
1660+
1661+
invokeHook(hooks, "llm_input", { model: "m", provider: "p", prompt: "" }, agentCtx("s1"));
1662+
1663+
vi.advanceTimersByTime(3_100);
1664+
1665+
expect(mockTrace.update).toHaveBeenCalledWith(
1666+
expect.objectContaining({
1667+
metadata: { staleCleanup: true },
1668+
errorInfo: expect.objectContaining({ exceptionType: "StaleTrace" }),
1669+
}),
1670+
);
14781671

14791672
await service.stop?.({} as any);
14801673
});
@@ -1515,6 +1708,36 @@ describe("opik service", () => {
15151708
expect(diagnosticListeners).toHaveLength(0);
15161709
});
15171710

1711+
test("retries flush with backoff when finalize flush fails", async () => {
1712+
vi.useFakeTimers();
1713+
1714+
const { api, hooks } = createApi();
1715+
const mockTrace = opikState.createMockTrace();
1716+
mockTraceFn.mockReturnValue(mockTrace);
1717+
1718+
const service = createOpikService(api as any);
1719+
const ctx = createServiceContext(true, {
1720+
enabled: true,
1721+
apiKey: "test-key",
1722+
flushRetryCount: 1,
1723+
flushRetryBaseDelayMs: 10,
1724+
}) as any;
1725+
await service.start(ctx);
1726+
1727+
mockFlush.mockRejectedValueOnce(new Error("network error")).mockResolvedValueOnce(undefined);
1728+
1729+
invokeHook(hooks, "llm_input", { model: "m", provider: "p", prompt: "" }, agentCtx("s1"));
1730+
invokeHook(hooks, "agent_end", { success: true, durationMs: 10 }, agentCtx("s1"));
1731+
1732+
await Promise.resolve();
1733+
await vi.waitFor(() => expect(mockFlush).toHaveBeenCalledTimes(1));
1734+
1735+
vi.advanceTimersByTime(10);
1736+
await Promise.resolve();
1737+
await vi.waitFor(() => expect(mockFlush).toHaveBeenCalledTimes(2));
1738+
expect(ctx.logger.warn).toHaveBeenCalledWith(expect.stringContaining("flush failed"));
1739+
});
1740+
15181741
test("does not throw when flush rejects", async () => {
15191742
const { api } = createApi();
15201743
const service = createOpikService(api as any);

0 commit comments

Comments
 (0)