Skip to content

perf(harness-ops): run the per-session event log hook in the background #6628

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
kyle-sexton merged 1 commit into from
Oct 8, 2026
Merged

perf(harness-ops): run the per-session event log hook in the background #6628

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 7 additions & 0 deletions .changes/harness-ops/perf-harness-ops-async-logging-hook-e102d63f.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
---
bump: patch
---

### Changed

- **The per-session event log runs in the background.** Every `session-event-log.sh` row except SessionEnd's now sets `async: true`, so the log write no longer holds up prompt submission or the other events; the `UserPromptSubmit` row had timed out at 5 seconds on a slow machine. Per the hooks reference ("Run hooks in the background") an async command hook is not awaited and its exit code and output are not read, which suits a row that only records. The SessionEnd row stays synchronous: its hooks share a 1.5-second teardown budget. The audit and telemetry rows are unchanged.
81 changes: 54 additions & 27 deletions plugins/harness-ops/hooks/hooks.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -28,7 +28,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the StopFailure event..."
"statusMessage": "Logging the StopFailure event...",
"async": true
}
]
}
Expand Down Expand Up @@ -61,7 +62,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the ConfigChange event..."
"statusMessage": "Logging the ConfigChange event...",
"async": true
}
]
}
Expand Down Expand Up @@ -93,7 +95,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the InstructionsLoaded event..."
"statusMessage": "Logging the InstructionsLoaded event...",
"async": true
}
]
}
Expand Down Expand Up @@ -125,7 +128,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PermissionDenied event..."
"statusMessage": "Logging the PermissionDenied event...",
"async": true
}
]
}
Expand Down Expand Up @@ -157,7 +161,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PreCompact event..."
"statusMessage": "Logging the PreCompact event...",
"async": true
}
]
}
Expand Down Expand Up @@ -206,7 +211,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the UserPromptExpansion event..."
"statusMessage": "Logging the UserPromptExpansion event...",
"async": true
}
]
}
Expand Down Expand Up @@ -239,7 +245,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PostToolUseFailure event..."
"statusMessage": "Logging the PostToolUseFailure event...",
"async": true
}
]
}
Expand Down Expand Up @@ -268,7 +275,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the Stop event..."
"statusMessage": "Logging the Stop event...",
"async": true

@chatgpt-codex-connector chatgpt-codex-connector Bot Oct 8, 2026

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Keep terminal event logging synchronous in print mode

When session_event_log_enabled is used with claude -p, this Stop hook—and the analogous StopFailure hook—can be terminated before writing its row. The official hooks reference says that print mode “kills any async hook still running at teardown”; this is particularly likely on the slow host or during the lock contention that motivated the change. The synchronous SessionEnd hook records only SessionEnd, so the terminal turn event is permanently missing, contradicting the advertised one-line-per-observable-event contract and skewing session timelines. Keep these terminal event rows synchronous or hand their payloads off durably before teardown.

Useful? React with 👍 / 👎.

}
]
}
Expand All @@ -286,7 +294,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the CwdChanged event..."
"statusMessage": "Logging the CwdChanged event...",
"async": true
}
]
}
Expand All @@ -304,7 +313,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the DirectoryAdded event..."
"statusMessage": "Logging the DirectoryAdded event...",
"async": true
}
]
}
Expand All @@ -322,7 +332,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the Elicitation event..."
"statusMessage": "Logging the Elicitation event...",
"async": true
}
]
}
Expand All @@ -340,7 +351,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the ElicitationResult event..."
"statusMessage": "Logging the ElicitationResult event...",
"async": true
}
]
}
Expand All @@ -358,7 +370,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the Notification event..."
"statusMessage": "Logging the Notification event...",
"async": true
}
]
}
Expand All @@ -376,7 +389,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PermissionRequest event..."
"statusMessage": "Logging the PermissionRequest event...",
"async": true
}
]
}
Expand All @@ -394,7 +408,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PostCompact event..."
"statusMessage": "Logging the PostCompact event...",
"async": true
}
]
}
Expand All @@ -412,7 +427,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PostModelSwitch event..."
"statusMessage": "Logging the PostModelSwitch event...",
"async": true
}
]
}
Expand All @@ -430,7 +446,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PostToolBatch event..."
"statusMessage": "Logging the PostToolBatch event...",
"async": true
}
]
}
Expand All @@ -448,7 +465,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the PreModelSwitch event..."
"statusMessage": "Logging the PreModelSwitch event...",
"async": true
}
]
}
Expand Down Expand Up @@ -499,7 +517,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the SessionStart event..."
"statusMessage": "Logging the SessionStart event...",
"async": true
}
]
},
Expand Down Expand Up @@ -528,7 +547,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the Setup event..."
"statusMessage": "Logging the Setup event...",
"async": true
}
]
}
Expand All @@ -546,7 +566,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the SubagentStart event..."
"statusMessage": "Logging the SubagentStart event...",
"async": true
}
]
}
Expand All @@ -564,7 +585,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the SubagentStop event..."
"statusMessage": "Logging the SubagentStop event...",
"async": true
}
]
}
Expand All @@ -582,7 +604,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the TaskCompleted event..."
"statusMessage": "Logging the TaskCompleted event...",
"async": true
}
]
}
Expand All @@ -600,7 +623,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the TaskCreated event..."
"statusMessage": "Logging the TaskCreated event...",
"async": true
}
]
}
Expand All @@ -618,7 +642,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the TeammateIdle event..."
"statusMessage": "Logging the TeammateIdle event...",
"async": true
}
]
}
Expand All @@ -636,7 +661,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the UserPromptSubmit event..."
"statusMessage": "Logging the UserPromptSubmit event...",
"async": true
}
]
}
Expand All @@ -654,7 +680,8 @@
"${CLAUDE_PLUGIN_ROOT}/hooks/session-event-log.sh"
],
"timeout": 5,
"statusMessage": "Logging the WorktreeRemove event..."
"statusMessage": "Logging the WorktreeRemove event...",
"async": true
}
]
}
Expand Down
3 changes: 2 additions & 1 deletion scripts/gen-hook-event-registry.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -196,7 +196,8 @@ regen_rows() {
args: ["${CLAUDE_PLUGIN_ROOT}/hooks/exec-bash.mjs", "--require-true", "SESSION_EVENT_LOG_ENABLED", $prod],
timeout: 5,
statusMessage: ("Logging the " + $event + " event...")
};
}
| if $event == "SessionEnd" then . else . + {async: true} end;
def ret_row: {
type: "command",
command: "node",
Expand Down
14 changes: 14 additions & 0 deletions scripts/gen-hook-event-registry.test.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,20 @@ while IFS= read -r ev; do
done < <(jq -r '.[] | select(.producer == "observe") | .name' "$REG")
if ((missing == 0)); then ok "every observable event has exactly one exec-form producer row"; else fail "$missing observable events lack their producer row"; fi

# The log row only records, so it runs in the background (hooks reference, "Run hooks in the
# background": an async hook does not block and its exit code and output are not read). SessionEnd is
# the exception: its hooks share a 1.5-second teardown budget, so its row stays synchronous.
unasync=0
while IFS= read -r ev; do
want=true
[[ "$ev" == SessionEnd ]] && want=false
a=$(jq -r --arg e "$ev" --arg prod "$PRODUCER" '[.hooks[$e][]? | .hooks[] | select(((.args // []) | index($prod)) != null) | (.async == true)] | all' "$HJ")
[[ "$a" == "$want" ]] || unasync=$((unasync + 1))
done < <(jq -r '.[] | select(.producer == "observe") | .name' "$REG")
if ((unasync == 0)); then ok "every producer row is async except SessionEnd's"; else fail "$unasync producer rows have the wrong async setting"; fi
gate_async=$(jq -r --arg prod "$PRODUCER" '[.hooks[][] | .hooks[] | select(((.args // []) | index($prod)) == null and .async == true)] | length' "$HJ")
if [[ "$gate_async" == 0 ]]; then ok "no row other than the event log is async"; else fail "$gate_async non-log rows are async"; fi

ret=$(jq -r --arg ret "$RETENTION" '[.hooks.SessionEnd[]? | .hooks[] | select(((.args // []) | index($ret)) != null)] | length' "$HJ")
if [[ "$ret" == 1 ]]; then ok "SessionEnd carries the retention row once"; else fail "retention rows on SessionEnd: $ret"; fi
ret_shell=$(jq -r --arg ret "$RETENTION" '.hooks.SessionEnd[] | .hooks[] | select(((.args // []) | index($ret)) != null) | has("shell")' "$HJ")
Expand Down
Loading