diff --git a/docs/otlp-mapping.md b/docs/otlp-mapping.md index b9a059a..2576767 100644 --- a/docs/otlp-mapping.md +++ b/docs/otlp-mapping.md @@ -3,9 +3,9 @@ Initial mapping scaffold: - SessionStart -> root/task span -- UserPromptSubmit -> turn/task span -- PostToolUse -> tool span -- Stop -> llm span +- UserPromptSubmit -> in-flight turn timing state +- PostToolUse -> tool span (child of session root) +- Stop -> llm span (child of session root) - SessionEnd -> terminal task span All spans are sent via OTLP/HTTP JSON `ExportTraceServiceRequest`. diff --git a/plugins/pl-trace-claude-code/hooks/lib.sh b/plugins/pl-trace-claude-code/hooks/lib.sh index 49e49ca..5482da7 100755 --- a/plugins/pl-trace-claude-code/hooks/lib.sh +++ b/plugins/pl-trace-claude-code/hooks/lib.sh @@ -234,7 +234,6 @@ ensure_session_initialized() { set_session_state "$sid" trace_id "$trace_id" set_session_state "$sid" session_span_id "$session_span_id" set_session_state "$sid" session_start_ns "$requested_start_ns" - set_session_state "$sid" current_turn_span_id "" set_session_state "$sid" current_turn_start_ns "" set_session_state "$sid" pending_tool_calls "[]" set_session_state "$sid" session_init_source "lazy_init" diff --git a/plugins/pl-trace-claude-code/hooks/parse_stop_transcript.py b/plugins/pl-trace-claude-code/hooks/parse_stop_transcript.py index 4d90e38..48d51e6 100755 --- a/plugins/pl-trace-claude-code/hooks/parse_stop_transcript.py +++ b/plugins/pl-trace-claude-code/hooks/parse_stop_transcript.py @@ -32,6 +32,28 @@ def stringify(value): return json.dumps(value, ensure_ascii=False) +def content_to_text(content): + if isinstance(content, str): + return content + if isinstance(content, list): + parts = [] + for block in content: + if isinstance(block, dict) and block.get("type") == "text": + text = block.get("text") + if isinstance(text, str) and text: + parts.append(text) + continue + serialized = stringify(block) + if serialized: + parts.append(serialized) + return "\n".join(parts).strip() + if isinstance(content, dict) and content.get("type") == "text": + text = content.get("text") + if isinstance(text, str): + return text + return stringify(content) + + def message_text(content): if isinstance(content, str): return content @@ -106,6 +128,7 @@ def parse_transcript(transcript_path, turn_start_fallback, pending_payloads, exp llms = [] pending_tool_uses = [] pending_payload_idx = 0 + saw_human_input = False turn_start_ns = turn_start_fallback turn_end_ns = turn_start_fallback @@ -120,6 +143,16 @@ def parse_transcript(transcript_path, turn_start_fallback, pending_payloads, exp turn_end_ns = timestamp_ns rec_type = rec.get("type") + if rec_type == "queue-operation": + operation = stringify(rec.get("operation")) + if operation == "enqueue": + content = content_to_text(rec.get("content")) + if content: + history.append({"role": "user", "content": content}) + last_input_ns = timestamp_ns or last_input_ns + saw_human_input = True + continue + if rec_type == "user": content = rec.get("message", {}).get("content") if is_tool_result_user(rec): @@ -184,9 +217,10 @@ def parse_transcript(transcript_path, turn_start_fallback, pending_payloads, exp last_input_ns = timestamp_ns or last_input_ns continue - user_text = stringify(content) + user_text = content_to_text(content) history.append({"role": "user", "content": user_text}) last_input_ns = timestamp_ns or last_input_ns + saw_human_input = True continue if rec_type != "assistant": @@ -232,6 +266,11 @@ def parse_transcript(transcript_path, turn_start_fallback, pending_payloads, exp } ) + # Claude can emit intermediate assistant records that contain only + # empty thinking blocks. Those should not consume the user's prompt. + if not output_text and not tool_calls: + continue + llm_start_ns = last_input_ns or timestamp_ns or turn_start_ns llm_end_ns = timestamp_ns or llm_start_ns if llm_start_ns is None: @@ -265,9 +304,11 @@ def parse_transcript(transcript_path, turn_start_fallback, pending_payloads, exp completion_item["tool_calls"] = tool_calls flatten_indexed("gen_ai.completion", [completion_item], attrs) + span_name = "LLM Call (User)" if saw_human_input else "LLM call" + llms.append( { - "name": "LLM call", + "name": span_name, "start_ns": int(llm_start_ns), "end_ns": int(llm_end_ns), "attributes": attrs, @@ -279,6 +320,7 @@ def parse_transcript(transcript_path, turn_start_fallback, pending_payloads, exp assistant_history["tool_calls"] = tool_calls history.append(assistant_history) llm_input_cursor = len(history) + saw_human_input = False if turn_start_ns is None: turn_start_ns = int(datetime.now(timezone.utc).timestamp() * 1_000_000_000) diff --git a/plugins/pl-trace-claude-code/hooks/post_tool_use.sh b/plugins/pl-trace-claude-code/hooks/post_tool_use.sh index ee40cfc..6b40c6f 100755 --- a/plugins/pl-trace-claude-code/hooks/post_tool_use.sh +++ b/plugins/pl-trace-claude-code/hooks/post_tool_use.sh @@ -18,11 +18,9 @@ tool_output="$(echo "$input" | jq -c '.tool_response // .output // {}')" ensure_session_initialized "$session_id" trace_id="$(get_session_state "$session_id" trace_id)" -parent_span_id="$(get_session_state "$session_id" current_turn_span_id)" [[ -z "$trace_id" ]] && exit 0 -if [[ -z "$parent_span_id" ]]; then - parent_span_id="$(generate_span_id)" - set_session_state "$session_id" current_turn_span_id "$parent_span_id" +turn_start_ns="$(get_session_state "$session_id" current_turn_start_ns)" +if [[ -z "$turn_start_ns" ]]; then set_session_state "$session_id" current_turn_start_ns "$(now_ns)" fi diff --git a/plugins/pl-trace-claude-code/hooks/session_end.sh b/plugins/pl-trace-claude-code/hooks/session_end.sh index 7ed7996..03b118e 100755 --- a/plugins/pl-trace-claude-code/hooks/session_end.sh +++ b/plugins/pl-trace-claude-code/hooks/session_end.sh @@ -19,12 +19,12 @@ trace_id="$(get_session_state "$session_id" trace_id)" session_span_id="$(get_session_state "$session_id" session_span_id)" session_start_ns="$(get_session_state "$session_id" session_start_ns)" stop_in_flight="$(get_session_state "$session_id" stop_in_flight)" -current_turn_span_id="$(get_session_state "$session_id" current_turn_span_id)" +current_turn_start_ns="$(get_session_state "$session_id" current_turn_start_ns)" [[ -z "$trace_id" || -z "$session_span_id" ]] && exit 0 [[ -z "$session_start_ns" ]] && session_start_ns="$(now_ns)" [[ -z "$stop_in_flight" ]] && stop_in_flight="false" -if [[ -n "$current_turn_span_id" || "$stop_in_flight" == "true" ]]; then +if [[ -n "$current_turn_start_ns" || "$stop_in_flight" == "true" ]]; then set_session_state "$session_id" session_end_requested "true" log "INFO" "SessionEnd deferred until Stop session_id=$session_id" exit 0 @@ -43,9 +43,9 @@ acquire_session_lock "$session_id" || exit 0 trap 'release_session_lock' EXIT stop_in_flight="$(get_session_state "$session_id" stop_in_flight)" -current_turn_span_id="$(get_session_state "$session_id" current_turn_span_id)" +current_turn_start_ns="$(get_session_state "$session_id" current_turn_start_ns)" [[ -z "$stop_in_flight" ]] && stop_in_flight="false" -if [[ -n "$current_turn_span_id" || "$stop_in_flight" == "true" ]]; then +if [[ -n "$current_turn_start_ns" || "$stop_in_flight" == "true" ]]; then set_session_state "$session_id" session_end_requested "true" log "INFO" "SessionEnd deferred until Stop session_id=$session_id" exit 0 diff --git a/plugins/pl-trace-claude-code/hooks/session_start.sh b/plugins/pl-trace-claude-code/hooks/session_start.sh index f432e83..e77069d 100755 --- a/plugins/pl-trace-claude-code/hooks/session_start.sh +++ b/plugins/pl-trace-claude-code/hooks/session_start.sh @@ -38,7 +38,6 @@ start_ns="$(now_ns)" set_session_state "$session_id" trace_id "$trace_id" set_session_state "$session_id" session_span_id "$span_id" set_session_state "$session_id" session_start_ns "$start_ns" -set_session_state "$session_id" current_turn_span_id "" set_session_state "$session_id" current_turn_start_ns "" set_session_state "$session_id" pending_tool_calls "[]" set_session_state "$session_id" session_init_source "session_start_hook" diff --git a/plugins/pl-trace-claude-code/hooks/stop_hook.sh b/plugins/pl-trace-claude-code/hooks/stop_hook.sh index 967a893..fe43a27 100755 --- a/plugins/pl-trace-claude-code/hooks/stop_hook.sh +++ b/plugins/pl-trace-claude-code/hooks/stop_hook.sh @@ -42,7 +42,6 @@ acquire_session_lock "$session_id" || exit 0 ensure_session_initialized "$session_id" trace_id="$(get_session_state "$session_id" trace_id)" -turn_span_id="$(get_session_state "$session_id" current_turn_span_id)" session_span_id="$(get_session_state "$session_id" session_span_id)" turn_start_ns="$(get_session_state "$session_id" current_turn_start_ns)" pending_tool_calls="$(get_session_state "$session_id" pending_tool_calls)" @@ -55,14 +54,10 @@ session_start_ns="$(get_session_state "$session_id" session_start_ns)" [[ -z "$session_end_requested" ]] && session_end_requested="false" [[ -z "$session_start_ns" ]] && session_start_ns="$(now_ns)" -if [[ -z "$turn_span_id" ]]; then - turn_span_id="$(generate_span_id)" - turn_start_ns="$(now_ns)" -fi +[[ -z "$turn_start_ns" ]] && turn_start_ns="$(now_ns)" # Keep lock scope short: snapshot + clear turn-specific mutable state. set_session_state "$session_id" stop_in_flight "true" -set_session_state "$session_id" current_turn_span_id "" set_session_state "$session_id" current_turn_start_ns "" set_session_state "$session_id" pending_tool_calls "[]" @@ -70,10 +65,25 @@ release_session_lock emitted_root="false" +parse_transcript_with_retry() { + local attempts=0 + local parsed llm_count + while true; do + parsed="$(PL_PENDING_TOOL_CALLS="$pending_tool_calls" python3 "$SCRIPT_DIR/parse_stop_transcript.py" "$transcript_path" "$turn_start_ns" "$session_id")" + llm_count="$(echo "$parsed" | jq -r '.llms | length')" + if [[ "$llm_count" -gt 0 || $attempts -ge 10 ]]; then + echo "$parsed" + return 0 + fi + attempts=$((attempts + 1)) + sleep 0.2 + done +} + if [[ -z "$transcript_path" || ! -f "$transcript_path" ]]; then log "WARN" "Stop missing transcript session_id=$session_id" else - parsed="$(PL_PENDING_TOOL_CALLS="$pending_tool_calls" python3 "$SCRIPT_DIR/parse_stop_transcript.py" "$transcript_path" "$turn_start_ns" "$session_id")" + parsed="$(parse_transcript_with_retry)" turn_start_ns="$(echo "$parsed" | jq -r '.turn.start_ns')" turn_end_ns="$(echo "$parsed" | jq -r '.turn.end_ns')" @@ -92,9 +102,6 @@ else add_span_to_batch "$trace_id" "$session_span_id" "" "Claude Code session" "1" "$session_start_ns" "$turn_end_ns" "$session_attrs" || true emitted_root="true" - turn_attrs='{"source":"claude-code","hook":"UserPromptSubmit","node_type":"WORKFLOW"}' - add_span_to_batch "$trace_id" "$turn_span_id" "$session_span_id" "Turn" "1" "$turn_start_ns" "$turn_end_ns" "$turn_attrs" || true - while IFS= read -r tool; do [[ -z "$tool" ]] && continue span_id="$(generate_span_id)" @@ -102,7 +109,7 @@ else start_ns="$(echo "$tool" | jq -r '.start_ns')" end_ns="$(echo "$tool" | jq -r '.end_ns')" attrs="$(echo "$tool" | jq -c '.attributes')" - add_span_to_batch "$trace_id" "$span_id" "$turn_span_id" "$name" "3" "$start_ns" "$end_ns" "$attrs" || true + add_span_to_batch "$trace_id" "$span_id" "$session_span_id" "$name" "3" "$start_ns" "$end_ns" "$attrs" || true done < <(echo "$parsed" | jq -c '.tools[]?') while IFS= read -r llm; do @@ -112,7 +119,7 @@ else start_ns="$(echo "$llm" | jq -r '.start_ns')" end_ns="$(echo "$llm" | jq -r '.end_ns')" attrs="$(echo "$llm" | jq -c '.attributes')" - add_span_to_batch "$trace_id" "$span_id" "$turn_span_id" "$name" "3" "$start_ns" "$end_ns" "$attrs" || true + add_span_to_batch "$trace_id" "$span_id" "$session_span_id" "$name" "3" "$start_ns" "$end_ns" "$attrs" || true done < <(echo "$parsed" | jq -c '.llms[]?') fi @@ -135,7 +142,7 @@ if [[ "$emitted_root" == "true" ]]; then fi latest_end_requested="$(get_session_state "$session_id" session_end_requested)" -latest_turn_span_id="$(get_session_state "$session_id" current_turn_span_id)" +latest_turn_start_ns="$(get_session_state "$session_id" current_turn_start_ns)" latest_trace_id="$(get_session_state "$session_id" trace_id)" latest_session_span_id="$(get_session_state "$session_id" session_span_id)" latest_session_start_ns="$(get_session_state "$session_id" session_start_ns)" @@ -143,7 +150,7 @@ latest_session_start_ns="$(get_session_state "$session_id" session_start_ns)" [[ -z "$latest_session_start_ns" ]] && latest_session_start_ns="$(now_ns)" need_finalize_root="false" -if [[ "$latest_end_requested" == "true" && -z "$latest_turn_span_id" ]]; then +if [[ "$latest_end_requested" == "true" && -z "$latest_turn_start_ns" ]]; then need_finalize_root="true" fi @@ -158,10 +165,10 @@ if [[ "$need_finalize_root" == "true" && -n "$latest_trace_id" && -n "$latest_se fi latest_end_requested="$(get_session_state "$session_id" session_end_requested)" -latest_turn_span_id="$(get_session_state "$session_id" current_turn_span_id)" +latest_turn_start_ns="$(get_session_state "$session_id" current_turn_start_ns)" [[ -z "$latest_end_requested" ]] && latest_end_requested="false" -if [[ "$latest_end_requested" == "true" && -z "$latest_turn_span_id" ]]; then +if [[ "$latest_end_requested" == "true" && -z "$latest_turn_start_ns" ]]; then rm -f "$PL_SESSION_STATE_DIR/$session_id.json" log "INFO" "SessionEnd finalized by Stop session_id=$session_id" fi diff --git a/plugins/pl-trace-claude-code/hooks/user_prompt_submit.sh b/plugins/pl-trace-claude-code/hooks/user_prompt_submit.sh index 97087ee..f55f688 100755 --- a/plugins/pl-trace-claude-code/hooks/user_prompt_submit.sh +++ b/plugins/pl-trace-claude-code/hooks/user_prompt_submit.sh @@ -15,14 +15,11 @@ session_id="$(echo "$input" | jq -r '.session_id // empty')" ensure_session_initialized "$session_id" trace_id="$(get_session_state "$session_id" trace_id)" -parent_span_id="$(get_session_state "$session_id" session_span_id)" -[[ -z "$trace_id" || -z "$parent_span_id" ]] && exit 0 - -turn_span_id="$(generate_span_id)" +session_span_id="$(get_session_state "$session_id" session_span_id)" +[[ -z "$trace_id" || -z "$session_span_id" ]] && exit 0 start_ns="$(now_ns)" -set_session_state "$session_id" current_turn_span_id "$turn_span_id" set_session_state "$session_id" current_turn_start_ns "$start_ns" set_session_state "$session_id" pending_tool_calls "[]" -log "INFO" "UserPromptSubmit captured session_id=$session_id turn_span_id=$turn_span_id" +log "INFO" "UserPromptSubmit captured session_id=$session_id"