Skip to content

Bug: Intermittent truncated stdout when piping opencode export #2803

@pct-cclausen

Description

@pct-cclausen

node.js console.log is not always synchronous or asynchronours: https://nodejs.org/api/console.html#:~:text=Warning%3A%20The%20global%20console%20object%27s%20methods%20are%20neither%20consistently%20synchronous%20like%20the%20browser%20APIs%20they%20resemble%2C%20nor%20are%20they%20consistently%20asynchronous%20like%20all%20other%20Node.js%20streams.

In packages/opencode/src/cli/cmd/export.ts it uses console.log to write a potentially large json file:

export const ExportCommand = cmd({
  command: "export [sessionID]",
  describe: "export session data as JSON",
  // ...
  handler: async (args) => {
    await bootstrap(process.cwd(), async () => {
      // ... gather sessionID, fetch sessionInfo & messages ...
      const exportData = {
        info: sessionInfo,
        messages: messages.map((msg) => ({
          info: msg.info,
          parts: msg.parts,
        })),
      }

      // PROBLEM: Large pretty JSON written via console.log (no flush await)
      console.log(JSON.stringify(exportData, null, 2))
    })
  },
})

I've run some scripts where I pipe the result of export to other programs and often that fails. It truncates the resulting data to a multiple of 65536.
Very likely this happens because the program exists before all data is flushed and piping the output to some other program turns console.log into an asynchronous operation, which if it is not waited for will not necessarily be completed if the program exits.

If instead I stream the output to a file it all works fine, as file writing is handled synchronous.

So:
opencode export session > foobar.json always works.
opencode export session | jq .... fails for large jsons a lot.

Here is an AI-generated script which reproduces the issue and can be used to test for it.
It readily reproduces the issue on my system, so should be possible to use to validate a fix.

#!/usr/bin/env bash
# Reproduction script for intermittent truncated stdout when piping
# `opencode export <sessionID>`.
# It:
#  1. Runs `opencode run` with a prompt that generates a large response.
#  2. Extracts the session ID from stderr logs (looks for id=ses_... ).
#  3. Exports the session once to a file (baseline full size).
#  4. Exports the session multiple times through a pipe (| wc -c) collecting sizes.
#  5. Reports OK if all piped sizes == baseline size, else NOT OK and shows differing sizes.

set -euo pipefail

PROMPT=${PROMPT:-"Output the source code of a tetris game with lots of features. Directly output the source code in a single file of java. Do not write the file anywhere, just output it here in the console. I need this output to be large, make sure to make the code complicated, lots of boilerplate and lots of comments"}
RUN_LOG=run.log
echo "[INFO] Running opencode to create a large session..." >&2

if ! command -v opencode >/dev/null 2>&1; then
	echo "[ERROR] 'opencode' not found in PATH" >&2
	exit 1
fi

# Run and capture stdout+stderr (stderr contains structured logs with session id)
OPENCODE_ARGS=(run --agent plan --print-logs "$PROMPT")
(
	# Separate subshell so set -e in caller won't abort early if opencode exits non-zero
	set -o pipefail
	opencode "${OPENCODE_ARGS[@]}" 1>run.stdout 2>run.stderr || {
		 echo "[ERROR] opencode run failed (see run.stderr)" >&2
		 exit 1
	}
)

# Extract session ID from stderr
SESSION_ID=$(grep -oE 'id=ses_[A-Za-z0-9]+' run.stderr | head -1 | cut -d= -f2 || true)
if [[ -z "${SESSION_ID}" ]]; then
	# Fallback: scan whole stderr for pattern
	SESSION_ID=$(grep -aoE 'ses_[A-Za-z0-9]+' run.stderr | head -1 || true)
fi

if [[ -z "${SESSION_ID}" ]]; then
	echo "[ERROR] Failed to detect session ID in run.stderr" >&2
	exit 1
fi
echo "[INFO] Detected session: ${SESSION_ID}" >&2

echo "[INFO] Creating baseline export (file redirection)..." >&2
opencode export "${SESSION_ID}" > export_full.json
BASE_SIZE=$(wc -c < export_full.json | tr -d ' ')
echo "[INFO] Baseline size (redirection) = ${BASE_SIZE} bytes" >&2

# Require baseline size to be >= 131072 (2 * 65536) to ensure truncation scenario is testable.
# If smaller, iteratively continue the session adding more content until threshold reached or limit hit.
MIN_SIZE=$((2 * 65536))
LOOP_PROMPT=${LOOP_PROMPT:-"Make it cooler by adding a fancy new feature. Substantially expand the code with additional classes, utilities, verbose comments, and configuration blocks. Ensure significant growth."}
MAX_ENRICH_LOOPS=${MAX_ENRICH_LOOPS:-10}

if [[ ${BASE_SIZE} -lt ${MIN_SIZE} ]]; then
	echo "[INFO] Session too small (${BASE_SIZE} < ${MIN_SIZE}). Entering enrichment loop." >&2
	loop=0
	while [[ ${BASE_SIZE} -lt ${MIN_SIZE} && ${loop} -lt ${MAX_ENRICH_LOOPS} ]]; do
		loop=$((loop+1))
		echo "[INFO] Enrichment loop ${loop}/${MAX_ENRICH_LOOPS}..." >&2
		# Continue same session adding more output
		if ! opencode run --print-logs -c "${LOOP_PROMPT}" 1>>run.stdout 2>>run.stderr; then
			echo "[WARN] opencode continue failed on loop ${loop}" >&2
			break
		fi
		# Re-export and measure
		opencode export "${SESSION_ID}" > export_full.json
		BASE_SIZE=$(wc -c < export_full.json | tr -d ' ')
		echo "[INFO] New size after loop ${loop}: ${BASE_SIZE}" >&2
	done
	if [[ ${BASE_SIZE} -lt ${MIN_SIZE} ]]; then
		echo "[WARN] Could not reach minimum size after ${MAX_ENRICH_LOOPS} enrichment loops (final size=${BASE_SIZE}, needed=${MIN_SIZE})." >&2
		echo "RESULT: NOT OK (session too small for reliable reproduction)" >&2
		exit 3
	fi
	echo "[INFO] Achieved target size (${BASE_SIZE} >= ${MIN_SIZE}). Proceeding with pipe tests." >&2
fi

ITERATIONS=${ITERATIONS:-50}
echo "[INFO] Piped export runs: ${ITERATIONS}" >&2

declare -A SEEN
DIFF_FLAG=0
PIPE_LOG=pipe_sizes.log
>"${PIPE_LOG}"

for i in $(seq 1 "${ITERATIONS}"); do
	tmpFile="pipe_run_${i}.json"
	# Capture piped (possibly truncated) output AND measure bytes
	BYTES=$({ opencode export "${SESSION_ID}" | tee "${tmpFile}" | wc -c; } 2>/dev/null | tr -d ' ')
	echo "PIPE_RUN ${i} ${BYTES}" | tee -a "${PIPE_LOG}" >&2
	SEEN["${BYTES}"]=1
	if [[ "${BYTES}" != "${BASE_SIZE}" ]]; then
		DIFF_FLAG=1
		# Keep first sample per differing size (actual truncated content)
		if [[ ! -f differing_sample_${BYTES}.json ]]; then
			mv "${tmpFile}" differing_sample_${BYTES}.json || cp "${tmpFile}" differing_sample_${BYTES}.json
		fi
	else
		# Remove non-differing sample to save space
		rm -f "${tmpFile}" || true
	fi
done

echo
echo "Baseline size: ${BASE_SIZE}"
echo -n "Unique pipe sizes: "
printf '%s ' "${!SEEN[@]}" | tr ' ' '\n' | sort -n | tr '\n' ' '
echo

if [[ ${DIFF_FLAG} -eq 0 ]]; then
	echo "RESULT: OK (all piped exports match baseline)"
	exit 0
else
	echo "RESULT: NOT OK (piped exports inconsistent)" >&2
	echo "See pipe_sizes.log and differing_sample_*.json for examples." >&2
	exit 2
fi

Proposed fix by AI. I did not validate this, but it looks like a reasonable start to try to fix it.
Advantage of fixing it in this location by flushing all streams before the program exits is that it does not need to modify all the CLI commands, as export is probably the worst offender (it easily produces large jsons), but other CLI commands might also suffer from this.
If for some reason this does not work you'd need to wait for the writes to stdout, instead of just using console.log

// in bootstrap.ts do something like this:

import { once } from "events"
import { InstanceBootstrap } from "../project/bootstrap"
import { Instance } from "../project/instance"

async function flushStream(stream: NodeJS.WritableStream) {
  if (stream.writableEnded || stream.destroyed) return
  // Write a zero-length chunk to get a callback; if backpressure, await 'drain'
  await new Promise<void>((resolve, reject) => {
    stream.write("", (err) => err ? reject(err) : resolve())
  })
  if (stream.writableNeedDrain) {
    await once(stream, "drain").catch(() => {})
  }
}

export async function bootstrap<T>(directory: string, cb: () => Promise<T>) {
  return Instance.provide({
    directory,
    init: InstanceBootstrap,
    fn: async () => {
      const result = await cb()
      // Flush stdout/stderr before teardown
      await flushStream(process.stdout)
      await flushStream(process.stderr)
      await Instance.dispose()
      // Defensive: one more microtask turn so any console.log after cb() gets queued
      await new Promise(r => setImmediate(r))
      await flushStream(process.stdout)
      await flushStream(process.stderr)
      return result
    },
  })
}

Metadata

Metadata

Assignees

Labels

No labels
No labels

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions