Completed Pi thinking can render as “Thought for 0ms”

[ryanbbrown]

Summary

Completed Pi reasoning can render as Thought for 0ms even when the assistant response took several seconds. BB loses the response start time, batches the reasoning lifecycle events, gives the full batch one storage timestamp, and then subtracts equal start and completion timestamps.

Versions and environment

• bb CLI 0.42.1 reading desktop-app thread data; reported desktop build is from the personal fork
• Current upstream main: dba32a469fd820ff6106715db0aaf6ed297d79a5
• macOS 15.7.7, Node.js 22.23.1
• Pi 0.85.1
• BB provider: pi
• Source provider/model: openai-codex/gpt-5.6-sol, reasoning level high
• Worktree environment

Steps to reproduce

1. Start a Pi thread with openai-codex/gpt-5.6-sol and high reasoning.
2. Run a tool-use task that produces several short visible reasoning summaries between tool calls.
3. Wait for the turn to complete.
4. Run bb thread log <thread-id> --all --format verbose.
5. Inspect the completed thought titles.

Captured repro thread: thr_7unpk42ev3. I did not create a public replacement thread because the captured raw and normalized events show the full timing path.

Expected vs actual

Expected: A truthful positive duration, or `Thought` if BB has no reliable duration.
Actual:
── Thought for 0ms

**Searching code for Braintrust API**

Evidence

For reasoning item da5a9e143a-i106, the normalized BB events are:

sequence 19658  item/started                  2026-09-04T02:56:18.310Z
sequence 19659  item/reasoning/textDelta      2026-09-04T02:56:18.310Z
sequence 19661  item/completed                2026-09-04T02:56:18.310Z

The corresponding raw Pi assistant message has:

assistant message timestamp: 2026-09-04T02:56:14.605Z
completed session entry:     2026-09-04T02:56:18.854Z
elapsed:                     4,249ms
provider/model:              openai-codex/gpt-5.6-sol
thinking text:               **Searching code for Braintrust API**

Across the captured thread, 637 of 1,453 completed reasoning items have an exact zero duration (43.8%). I measured this by pairing each persisted reasoning item/started with its item/completed event and subtracting their createdAt values. The first captured zero is from 2026-08-21, before PR #3066 made completed thoughts visible.

Observed code path on upstream main:

• Pi accepts message_start only for custom messages, so an assistant boundary and its source timestamp are ignored:

  bb/plugins/provider-pi/src/delta-translation.ts

  Lines 109 to 120 in dba32a4

  	const piCustomMessageBoundaryEventSchema = z
  	.object({
  	type: z.enum(["message_end", "message_start"]),
  	message: z
  	.object({
  	role: z.literal("custom"),
  	content: z.union([z.string(), z.array(piMessageContentBlockSchema)]),
  	display: z.boolean(),
  	})
  	.passthrough(),
  	})
  	.passthrough();

  and

  bb/plugins/provider-pi/src/delta-translation.ts

  Lines 565 to 580 in dba32a4

  	switch (eventType.data.type) {
  	case "agent_start":
  	return [{ kind: "turn.open" }];
  	case "message_end":
  	case "message_start": {
  	const piEvent = piCustomMessageBoundaryEventSchema.safeParse(event);
  	if (!piEvent.success) {
  	return [];
  	}
  	if (
  	piEvent.data.type === "message_end" ||
  	!piEvent.data.message.display
  	) {
  	return [];
  	}

• Pi maps thinking_delta and thinking_end without source time:

  bb/plugins/provider-pi/src/delta-translation.ts

  Lines 740 to 795 in dba32a4

  	return unexpectedSdkEventDeltas(event, context);
  	}
  	const assistantEvent = piEvent.data.assistantMessageEvent;
  	if (assistantEvent.type === "text_delta") {
  	const delta = assistantEvent.delta;
  	if (!delta) {
  	return [];
  	}
  	return [
  	{
  	kind: "item.textDelta",
  	key: { channel: ASSISTANT_STREAM_KEY, ...parentRefField },
  	channel: "agentMessage",
  	text: delta,
  	},
  	];
  	}
  	if (assistantEvent.type === "thinking_delta") {
  	const delta = assistantEvent.delta;
  	if (!delta) {
  	return [];
  	}
  	if (typeof assistantEvent.contentIndex !== "number") {
  	return unexpectedSdkEventDeltas(event, context);
  	}
  	return [
  	{
  	kind: "item.textDelta",
  	key: {
  	channel: thinkingStreamChannel(assistantEvent.contentIndex),
  	...parentRefField,
  	},
  	channel: "reasoningText",
  	text: delta,
  	},
  	];
  	}
  	if (assistantEvent.type === "thinking_end") {
  	const content = assistantEvent.content;
  	if (!content) {
  	return [];
  	}
  	if (typeof assistantEvent.contentIndex !== "number") {
  	return unexpectedSdkEventDeltas(event, context);
  	}
  	return [
  	{
  	kind: "item.textClose",
  	key: {
  	channel: thinkingStreamChannel(assistantEvent.contentIndex),
  	...parentRefField,
  	},
  	channel: "reasoningText",
  	text: content,
  	},
  	];

• The host daemon waits up to 100ms and posts queued events as one batch; the envelope has no event occurrence time:

  bb/apps/host-daemon/src/event-sink.ts

  Line 11 in dba32a4

  const DEFAULT_DEBOUNCE_MS = 100;

  and

  bb/apps/host-daemon/src/event-sink.ts

  Lines 214 to 261 in dba32a4

  	async function drainQueue(): Promise<void> {
  	while (queue.length > 0 && !disposed && options.isSessionOpen()) {
  	const batch = queue.slice();
  	const delivered = await deliverBatch(batch);
  	queue.splice(0, delivered);
  	if (queue.length === 0) {
  	backedUpSinceMs = null;
  	backpressureLogged = false;
  	}
  	if (delivered < batch.length) {
  	return;
  	}
  	}
  	}
  	async function flush(): Promise<void> {
  	clearScheduledFlush();
  	if (flushPromise !== null) {
  	await flushPromise;
  	return;
  	}
  	flushPromise = drainQueue();
  	try {
  	await flushPromise;
  	} finally {
  	flushPromise = null;
  	}
  	}
  	return {
  	emit(input): void {
  	if (disposed) {
  	throw new EventSinkDisposedError();
  	}
  	if (backedUpSinceMs === null) {
  	backedUpSinceMs = now();
  	}
  	queue.push({
  	threadId: input.threadId,
  	event: input.event,
  	});
  	maybeLogQueuePressure();
  	scheduleFlush(
  	shouldFlushThreadEventImmediately(input.event)
  	? 0
  	: DEFAULT_DEBOUNCE_MS,
  	);

  and

  bb/packages/host-daemon-contract/src/session.ts

  Lines 189 to 197 in dba32a4

  	const hostDaemonEventEnvelopeSchema = z
  	.object({
  	threadId: z.string().min(1),
  	event: threadEventSchema,
  	})
  	.strict();
  	export type HostDaemonEventEnvelope = z.infer<
  	typeof hostDaemonEventEnvelopeSchema
  	>;

• Persistence uses one Date.now() value for every accepted event in the batch:

  bb/packages/db/src/data/events.ts

  Lines 663 to 718 in dba32a4

  	const now = Date.now();
  	for (const [index, input] of eventInputs.entries()) {
  	const turnStartDisposition = resolveDaemonTurnStartDisposition(
  	input,
  	startedTurnKeys,
  	);
  	if (turnStartDisposition === "skip-orphan-snapshot") {
  	skippedTurnUnstartedInputIndexes.push(index);
  	continue;
  	}
  	if (turnStartDisposition === "skip-duplicate-turn-start") {
  	continue;
  	}
  	const turnId = getThreadEventScopeTurnId(input.scope) ?? null;
  	const itemLifecycleKey =
  	input.itemId === null
  	? null
  	: buildItemLifecycleKey({
  	itemId: input.itemId,
  	threadId: input.threadId,
  	});
  	if (input.type === "item/started" && itemLifecycleKey !== null) {
  	settledItemKeys.delete(itemLifecycleKey);
  	} else if (
  	isTerminalItemEventType(input.type) &&
  	itemLifecycleKey !== null
  	) {
  	if (settledItemKeys.has(itemLifecycleKey)) {
  	continue;
  	}
  	settledItemKeys.add(itemLifecycleKey);
  	}
  	const sequence = nextSequencesByThreadId.get(input.threadId);
  	if (sequence === undefined) {
  	throw new Error(`Missing event sequence for thread: ${input.threadId}`);
  	}
  	db.run(
  	sql`INSERT INTO events
  	(id, thread_id, environment_id, scope_kind, turn_id, provider_thread_id, sequence, type, item_id, item_kind, parent_tool_call_id, data, created_at)
  	VALUES (
  	${createEventId()},
  	${input.threadId},
  	${input.environmentId},
  	${input.scope.kind},
  	${turnId},
  	${input.providerThreadId},
  	${sequence},
  	${input.type},
  	${input.itemId},
  	${input.itemKind},
  	${input.parentToolCallId},
  	${input.data},
  	${now}
  	)`,

• Thread projection uses those persisted values as reasoning start/completion and formats their difference:

  bb/packages/thread-view/src/reasoning-lifecycle-projection.ts

  Lines 177 to 195 in dba32a4

  	const existingLifecycle =
  	args.state.openReasoningLifecyclesByKey.get(messageKey);
  	if (existingLifecycle) {
  	existingLifecycle.updatedAt = args.meta.createdAt;
  	existingLifecycle.updatedSeq = args.meta.seq;
  	return;
  	}
  	args.state.openReasoningLifecyclesByKey.set(messageKey, {
  	itemId: args.identity.itemId,
  	messageKey,
  	parentToolCallId: args.parentToolCallId ?? null,
  	sourceSeqStart: args.meta.seq,
  	startedAt: args.meta.createdAt,
  	threadId: args.threadId,
  	turnId: args.identity.turnId,
  	updatedAt: args.meta.createdAt,
  	updatedSeq: args.meta.seq,
  	});

  and

  bb/packages/thread-view/src/reasoning-lifecycle-projection.ts

  Lines 217 to 237 in dba32a4

  	const message: EventProjectionOperationMessage = {
  	kind: "operation",
  	id: messageId(
  	lifecycle.threadId,
  	"op",
  	`reasoning:${lifecycle.messageKey}`,
  	),
  	threadId: lifecycle.threadId,
  	sourceSeqStart: lifecycle.sourceSeqStart,
  	sourceSeqEnd: args.meta.seq,
  	createdAt: args.meta.createdAt,
  	startedAt: lifecycle.startedAt,
  	completedAt: args.meta.createdAt,
  	...eventProjectionMessageTurnScopeFields(lifecycle.turnId),
  	...(lifecycle.parentToolCallId
  	? { parentToolCallId: lifecycle.parentToolCallId }
  	: {}),
  	opType: "operation",
  	title: `Thought for ${durationToCompactString(
  	args.meta.createdAt - lifecycle.startedAt,
  	)}`,

No relevant errors appear in ~/.bb/logs; those logs show normal timeline builds and provider-session cleanup for this thread.

Suggested fix

As the smallest safe display fix, render Thought instead of Thought for 0ms when completedAt <= startedAt.

To preserve a real duration, carry event occurrence time through the provider bridge and host-daemon event envelope, then persist each event's own time instead of one database time for the full batch. For Pi reasoning returned as a completion-time summary, use the assistant message_start timestamp as the start.

What you ruled out

• This is not a duration formatter bug: it correctly receives and formats a zero difference.
• This is not Feature Request: Show Thinking #1248: that closed issue requested completed thinking display and does not cover lost timing data.
• This is not Completed thinking uses monospace text unlike active thinking #3178: that open issue covers completed-thinking typography.
• Searches of open and closed issues for Thought for 0ms, 0ms thinking, thinking duration, and reasoning timestamp found no matching report.
• The relevant files are identical in the personal fork and upstream main at dba32a469fd820ff6106715db0aaf6ed297d79a5.

Suggested priority and effort

Medium priority. It makes a visible timing claim wrong for many Pi/OpenAI Codex thoughts. Omitting an unreliable duration is a small workaround; preserving the real duration needs a cross-contract timing change.

AGENT GENERATED

[bb-slop-cop]

🚨 SLOP COP 🚨 · new-issue-autopilot

• Classification: Bug · Priority Medium · Effort Low · labels threads, provider-pi, confirmed-repro
• Report: https://get-bb.github.io/reports/issues/3219.html
• Verdict: REPRODUCED · confidence high · reproduction label confirmed-repro
• Root cause: daemon event batches share one persistence timestamp, while completed-reasoning projection always formats the resulting timestamp difference as elapsed time.
• Fix: Omit invalid completed reasoning durations #3248 renders the neutral Thought title when completion is not later than start and preserves positive durations.