[api][runtime][python] Add Agent Trace recording to Event Log - #924
[api][runtime][python] Add Agent Trace recording to Event Log#924joeyutong wants to merge 9 commits into
Conversation
There was a problem hiding this comment.
Thanks for taking this on. One thing worth surfacing: the Python Event.id switch to a per-occurrence uuid4 also fixes a real collision. chat_model_action.py keys sensory-memory dicts on the request event's id, so two identical ChatRequestEvents on the same key used to collapse into one and splice their conversations together. The PR body frames it as identity-semantics alignment, so you may want to update the description to match what the code actually does.
A few questions inline, plus one below that spans files.
The description mentions this complements the Event lineage work in #923. Going through both diffs, I think there may be an interaction worth checking before either lands.
The new serializer writes the Event's attributes map rather than the Event itself: EventLogRecordJsonSerializer.java:86 emits eventAttributes via the helper at :90-91, where the version it replaces did mapper.valueToTree(event). #923 adds upstreamEventId and upstreamActionName as fields on Event with getters, not as attribute entries.
If I'm reading that right, those two fields wouldn't reach the Event Log once the flat shape lands, which is the artifact #841 set out to populate. The same applies to tools/reconstruct_trace_tree.py, which reads record["event"] and would hit a KeyError with no event key present. Nothing in a merge would surface either one, since Event.java isn't touched here.
More generally, should framework-owned metadata on Event have a home in the flat record? upstreamEventId and upstreamActionName read like the same family as executionId, so a top-level slot would seem consistent, but is there a reason to keep them out?
| chatAsync | ||
| ? ctx.durableExecuteAsync(callable) | ||
| : ctx.durableExecute(callable); | ||
| ExecutionReporters.started(ctx, ExecutionReporter.EntityTypes.LLM, model); |
There was a problem hiding this comment.
started here and succeeded at :389 bracket ctx.durableExecute(...), but on replay that returns the cached result and short-circuits (RunnerContextImpl.java:383-385) while the action body still re-runs. Your own testEarlierCheckpointReplayKeepsDurableState:1039 pins that: DURABLE_CALL_COUNTER stays at 1 while the output is produced again.
So after a fine-grained recovery the log gets a complete started plus succeeded pair, with a fresh executionId, for a model call that never happened. ToolCallAction has the same shape. Since counting LLM calls is the first thing anyone does with this log, cost dashboards would over-report spend and under-report latency.
What makes me read this as unintended: the Action level already has ExecutionLifecycleEvents.executionReused() for exactly this case, but nothing below Action can emit it, since ExecutionReporter has no such method.
Could a cached durable result surface a reused signal that the reporters emit instead of started/succeeded? Or does the reporting want to move inside the durable boundary? And if it's out of scope here, would naming it in the monitoring doc be enough for now?
There was a problem hiding this comment.
Good catch. Child durable-cache reuse remains out of scope because the current durable boundary does not expose cache-hit state to ExecutionReporter. I documented that cached LLM/Tool results may currently appear as new successful executions; a reused child signal is follow-up work.
| JsonNode eventNode = rootNode.get("event"); | ||
| if (eventNode instanceof ObjectNode) { | ||
| boolean truncated = truncator.truncate((ObjectNode) eventNode); | ||
| JsonNode attributesNode = rootNode.get("eventAttributes"); |
There was a problem hiding this comment.
Passing rootNode.get("eventAttributes") into truncator.truncate(...) narrows truncation in two ways. Same block at Slf4jEventLogger.java:179-181, so both loggers are affected.
The protections now point at the wrong names. JsonTruncator is untouched by this PR and still skips PROTECTED_FIELDS = {eventType, id, attributes} at isTopLevel (:55-56, :117-119). Those were envelope names; under the flat shape they are user attribute names, so an attribute called id escapes event-log.standard.max-string-length at STANDARD. JsonTruncatorTest.testProtectedFields:136-161 still pins the old shape and passes, so CI won't catch it. Worth noting #923 adds upstreamEventId and upstreamActionName to that same set, which won't take effect under the flat shape either.
Separately, entityMetadata sits as a sibling of eventAttributes (EventLogRecordJsonSerializer.java:73), so the truncator never sees it. It's fed by the public ToolExecutionMetadataProvider hook, and LoadSkillTool.java:68-80 copies the model-supplied name and path straight in, so an LLM-controlled value lands unbounded.
Would running the truncator over the whole record, with the new framework field names protected, close both at once? That was my first instinct, though I may be missing why the narrowing was deliberate. Either way, would testProtectedFields want re-pointing at what the production path now passes in?
There was a problem hiding this comment.
Thanks, the protected-name mismatch was a bug. Truncation remains scoped to eventAttributes; JsonTruncator now treats its entire input as payload, and the regression test covers eventType, id, and attributes as ordinary payload keys. I am keeping entityMetadata size policy separate rather than truncating the whole record.
There was a problem hiding this comment.
Protected names are settled, thanks. The test side is the part I'm still unsure about.
The guarantee now lives in the two call sites (FileEventLogger.java:212, Slf4jEventLogger.java:179) rather than in JsonTruncator, and I couldn't find a test that pins it. Flipping rootNode.get("eventAttributes") back to rootNode would fail none of the six candidate tests: the logger tests assert only eventAttributes.customData, the Python e2e one only that "truncatedString" appears somewhere in the line, and the JsonTruncatorTest units never see a record. eventId is a 36-char UUID that would be wrapped at max-string-length=10 and nothing checks it.
That leaves the promise at monitoring.md:219 ("Truncation only applies to large nested content under eventAttributes") resting on review rather than CI. Is one assertion in FileEventLoggerTest.testStandardLevelTruncation enough to close it, checking eventId is still textual at max-string-length=10?
There was a problem hiding this comment.
Yes. I added an assertion to FileEventLoggerTest.testStandardLevelTruncation that, with max-string-length=10, the top-level eventId still exactly matches the original UUID while the payload field is truncated. This pins the truncation boundary at eventAttributes.
Treat eventAttributes as the payload root and document durable replay limitations. Co-Authored-By: Codex <noreply@openai.com> AI-Model: gpt-5 AI-Contributed/Feature: 59/59 AI-Contributed/UT: 28/28
| outputEvents = actionTaskResult.getOutputEvents(); | ||
| generatedActionTaskOpt = actionTaskResult.getGeneratedActionTask(); | ||
| notifyFinished = isFinished; | ||
| } catch (Exception e) { |
There was a problem hiding this comment.
Could the Action lifecycle guarantee cover the remaining failure paths here?
This catch (Exception) misses a raw Error, including one now unwrapped by JavaFunction.java:114. Before this PR that body was just return getMethod().invoke(null, args);, so every user throwable arrived wrapped in InvocationTargetException. A tool throwing AssertionError used to be caught at ToolCallAction.java:174 and reported via ExecutionReporters.failed at :179. Now it skips this catch too and fails the task at :306's catch (Throwable t), leaving _execution_started_event with no terminal Event.
Separately, processEvent(...) at :434 can throw after maybePersistTaskResult at :411 but before notifyActionFinished at :437. This catch has already closed at :429 and the finally at :439 only calls completeActionExecution, so that produces the same incomplete lifecycle, with the result persisted.
Would catching Throwable long enough to report and clean up before rethrowing, or emitting finished right after successful invocation and persistence, keep every started Action terminal without changing which failures stop the task?
There was a problem hiding this comment.
Good catch. I now catch Throwable around Action invocation so raw errors emit failed before propagating, and emit finished immediately after a completed result is persisted, before processing output Events. This keeps the Action lifecycle paired without attributing listener or routing failures to the Action. I added regression tests for both paths.
| try { | ||
| eventLogger.append(eventContext, event, traceContext); | ||
| eventLogger.flush(); | ||
| } catch (Exception logError) { |
There was a problem hiding this comment.
Best-effort writes look intentional, but this also changes what an append or flush failure does. At the merge base (6f020c50) the work sat in EventRouter.notifyEventProcessed (EventRouter.java:233-242), which had no try/catch and declared throws Exception, so a failure propagated and failed the task. Was making it non-fatal the intent, or a side effect of the move?
Either way, what would you want an operator to see when a write is dropped? BuiltInMetrics declares and registers eventLogTruncatedEvents (:40, :53) but has no equivalent for failed writes, so an operator whose disk filled gets a log that just stops while the job stays green. A first-failure WARN plus an eventLogWriteFailures counter next to the truncation one is the shape I had in mind, though you may be weighing log noise against it.
Smaller thing in the same block: flush() at :108 is skipped when append at :107 throws, so a partial line can sit in the PrintWriter buffer.
There was a problem hiding this comment.
Making Event Log writes non-fatal is intentional. Event Log is an observability side channel, now including Trace, so a logging backend failure should not change Event processing or job success. I split append and flush into independent best-effort steps, so flush is still attempted after an append failure. Each failed write attempt increments eventLogWriteFailures once even if both steps fail; the first failure is logged at WARN and subsequent failures at DEBUG. FileEventLogger now also surfaces I/O errors otherwise swallowed by PrintWriter, and the compatibility change is documented.
| visited.add(id(current)) | ||
| cause = current.__cause__ | ||
| if cause is None and not current.__suppress_context__: | ||
| cause = current.__context__ |
There was a problem hiding this comment.
_root_cause follows __cause__ then __context__ when __suppress_context__ is false (:71-73), while Java walks only getCause() (ExecutionLifecycleEvents.java:100-107). __context__ is set implicitly by any raise inside an except block, where getCause() is set only when a cause is passed explicitly.
So a MyError raised inside except JSONDecodeError records errorType: json.decoder.JSONDecodeError where Java records MyError. Same wrapped failure, two errorType values in one log file, and a cross-language query on that field splits. AGENTS.md asks that "Public API changes must keep Java, Python, and YAML APIs semantically aligned".
Is following __context__ deliberate? Restricting to __cause__ would match Java, though it may be buying something I can't see. Either way test_failed_execution_reports_deepest_cause wires only __cause__ (test_flink_runner_context_trace.py:39), so that branch is unexercised on both sides.
There was a problem hiding this comment.
Good catch. The previous test covered only explicit __cause__, so the Python-only implicit __context__ branch remained unaligned. I removed that fallback: Python now follows only explicitly chained causes, matching Java Throwable.getCause(), and added a regression test confirming implicit context is not used.
| ### Per-event-type log levels | ||
|
|
||
| You can override the level for individual event types using the `event-log.type.<EVENT_TYPE>.level` config key, where `<EVENT_TYPE>` is the event's routing type string (the same string that appears as `eventType` in the JSON log). Built-in events use short snake-cased names such as: | ||
| You can override the level for individual event types using the `event-log.type.<EVENT_TYPE>.level` config key, where `<EVENT_TYPE>` is the event's routing type string (the same string that appears as `eventType` in the JSON log). Although the field name uses camelCase, built-in Event type values remain snake-cased: |
There was a problem hiding this comment.
Would it help to list the four _execution_* routing types in the per-event-type table, with a note on how they compose with event-log.trace.enabled?
Since this line says the per-type key is the event's routing type string, Trace can be enabled while event-log.type._execution_started_event.level: OFF still removes the started Events. That interaction isn't visible from the table today, and the four lifecycle types aren't listed in it at all.
There was a problem hiding this comment.
Agreed. I added all four execution lifecycle routing types to the per-event-type table and documented the composition explicitly: event-log.trace.enabled controls whether lifecycle Events are produced, while the normal per-type level resolution still applies once Trace is enabled. Setting an _execution_* type to OFF therefore suppresses that lifecycle Event and may make the recorded Trace incomplete.
| @@ -291,4 +302,6 @@ Other per-type levels from `config.yaml` are preserved — the `-D` flag only ov | |||
| ### Compatibility Notes | |||
There was a problem hiding this comment.
nit: could the Compatibility Notes name the actual rewrites, event removed, event.id → eventId, event.attributes → eventAttributes, and mention that Python Event IDs changed from content-derived to per-occurrence UUIDs?
eventType was already top-level, so the current wording names the one field that didn't move, and a reader can't derive the rest. Grepping docs/ for content-hash or uuid4 returns nothing, so the Python change lives only in event.py, and anything relying on content-hash id equality or dedup behaves differently after upgrade.
There was a problem hiding this comment.
Agreed. The Compatibility Notes now name the exact record-shape changes: the nested event object is removed, event.id becomes top-level eventId, event.attributes becomes top-level eventAttributes, and top-level eventType remains where it was. I also documented that Python Event IDs changed from content-derived IDs to per-occurrence UUID4 values, so payload equality must no longer be used for ID-based deduplication.
Report raw Action errors as failed and emit successful Action completion before processing emitted Events. Co-Authored-By: Codex <noreply@openai.com> AI-Model: gpt-5 AI-Contributed/Feature: 3/3 AI-Contributed/UT: 0/0
a5b2c0e to
fbd15b5
Compare
Keep Event Log writes best-effort while exposing failures through a counter and a first-failure warning. Attempt flush independently after append failures and surface PrintWriter I/O errors. Co-Authored-By: Codex <noreply@openai.com> AI-Model: gpt-5 AI-Contributed/Feature: 57/57 AI-Contributed/UT: 43/43
Document execution lifecycle event level overrides, the flat Event Log field migration, and Python per-occurrence Event IDs. Co-Authored-By: Codex <noreply@openai.com> AI-Model: gpt-5 AI-Contributed/Feature: 11/11 AI-Contributed/UT: 0/0
Follow only explicitly chained Python causes so failure attribution matches Java Throwable.getCause semantics. Co-Authored-By: Codex <noreply@openai.com> AI-Model: gpt-5 AI-Contributed/Feature: 2/2 AI-Contributed/UT: 29/29
Assert that STANDARD payload truncation leaves the top-level Event ID unchanged. Co-Authored-By: Codex <noreply@openai.com> AI-Model: gpt-5 AI-Contributed/Feature: 0/0 AI-Contributed/UT: 4/4
Linked discussion: #900
Related: #710, #841, #923
Purpose of change
This PR implements the recording side of Agent Trace proposed in #900.
The existing Event Log records business Events but does not provide enough runtime context to identify one input run, distinguish concrete Action/LLM/Parser/Tool executions, reconstruct nested execution relationships, or attribute execution failures.
This PR adds execution identity and lifecycle recording to the existing Event Log path. It complements the business Event lineage implemented in #923 rather than defining another Event-to-Action lineage field:
executionId, connecting the two models.API and trace model
ExecutionTraceContextcarries run identity, execution hierarchy, entity identity, and entity metadata.ExecutionLifecycleEventsdefinesstarted,finished,failed, andreusedlifecycle Events.ExecutionReporterandExecutionReportersprovide an optional, best-effort capability for reporting nested executions.ToolExecutionMetadataProviderallows Tools to contribute small structured execution metadata.EventLoggeraccepts an optionalExecutionTraceContext; its default overload preserves compatibility with existing implementations.AgentPlancarries the Agent name used by trace records.event-log.trace.enabledcontrols Trace persistence and defaults tofalse.Runtime integration
ActionExecutionOperatorcreates one run context per processed input and one execution context per Action invocation.ActionTaskcarries the Action execution context and started-event marker across continuations and Flink state restoration.ActionTaskContextManagerkeeps child-execution start/terminal pairing transient and scoped by Action execution id across live continuation tasks.reusedwhen completed Action state is reused.EventRouter.ExecutionEventSinkwithout automatically submitting them to the business Event routing path.RunnerContextImplimplementsExecutionReporter, creates child execution contexts, and pairs start and terminal reports.ExecutionEventLoggersends Execution Events to the sharedEventLogWriter.EventLogWriterowns logger open, append, flush, and close operations; write failures remain best-effort.Action and resource instrumentation
ChatModelActionrecords one LLM execution per framework model invocation.ToolCallActionrecords one Tool execution per concrete tool call, including error responses and thrown exceptions.load_skillcalls record the loaded Skill as Tool execution metadata.Python alignment
ExecutionReportercapability and entity/problem vocabulary as Java.ChatRequestEventoccurrences from colliding in sensory-memory correlation.Event Log format and compatibility
EventLogRecordcombinesEventContext, optionalExecutionTraceContext, andEvent.The JSONL representation is flattened for querying and aggregation. Framework-owned fields retain the existing camelCase convention, including
eventType,eventAttributes,inputRunId, andexecutionId. The record includes Event occurrence fields, run identity, execution hierarchy, entity information, lifecycle status, failure category, and Event attributes.The framework deserializer continues to read the previous nested Event Log format. Existing external consumers that parse the raw JSON shape must migrate to the normalized field names.
Trace persistence is disabled by default. When disabled, business Events continue to be logged without trace context and Execution Events are not persisted.
A restored
ActionTaskretains its run and execution identities. A source-replayed input not represented by restored Action state starts a new run.Fine-grained recovery currently records a cached durable LLM or Tool result as a new successful execution because cache reuse is not exposed to execution reporting. Distinguishing reused child executions is follow-up work.
This PR changes the pending
ActionTaskstate schema. Restoring savepoints containing that state from before this change would require a versionedActionTaskstate serializer, which is outside this PR.Tests
mvn -pl runtime -am -DskipITs testAPI
This PR introduces the public Trace APIs described above and extends
EventLoggerwith a backward-compatible default overload accepting optional trace context.The normalized raw Event Log JSON shape is a compatibility change for external consumers. Legacy records remain readable through the framework deserializer.
Documentation
doc-neededdoc-not-neededdoc-included