Reduce native readiness probe overhead and preserve screenshot evidence

tools/ci/macos-native-readiness.sh

@@ -9,6 +9,11 @@ PROOF_LOG="$STATE_DIR/proof.log"
 RESULT="$STATE_DIR/result.json"
 EXPECTED_BYTES=68719476736
 MAX_LOG_BYTES=4194304
+MAX_OUTPUT_BYTES=524288
+TIMER_FIFO="/tmp/native-diagnostic-$PROOF_TOKEN-$$.fifo"
+PENDING_OUTPUTS=()
+ACTIVE_COMMAND=""
+ACTIVE_TIMER=""
 os_version=""
 architecture=""
 uid=-1
@@ -27,127 +32,179 @@ while [ ! -d "$STATE_DIR" ] && (( count < 120 )); do
 done
 [ -d "$STATE_DIR" ] || exit 1
 : > "$PROOF_LOG" || exit 1
+exec 3>> "$PROOF_LOG" || exit 1
 rm -f "$RESULT" "$RESULT.tmp"
-printf '[proof-token] %s\n' "$PROOF_TOKEN" >> "$PROOF_LOG"
+printf '[proof-token] %s\n' "$PROOF_TOKEN" >&3
 
 finish() {
   local success="$1" reason="$2"
-  printf '[proof-result] %s: %s\n' "$success" "$reason" >> "$PROOF_LOG"
+  flush_outputs || { success=false; reason=diagnostic_log_budget_exceeded; }
+  printf '[proof-result] %s: %s\n' "$success" "$reason" >&3
   printf '{"token":"%s","success":%s,"reason":"%s","osVersion":"%s","architecture":"%s","uid":%s,"systemExit":%s,"diskArbitrationExit":%s,"recoveryExit":%s,"diskListExit":%s,"disk":"%s","diskBytes":%s,"readOnly":false}\n' \
     "$PROOF_TOKEN" "$success" "$reason" "$os_version" "$architecture" "$uid" \
     "$system_exit" "$arbitration_exit" "$recovery_exit" "$disk_list_exit" \
     "$selected_disk" "$disk_bytes" > "$RESULT.tmp"
   /bin/mv -f "$RESULT.tmp" "$RESULT" || exit 1
+  exec 9>&-
+  [ ! -p "$TIMER_FIFO" ] || /bin/rm -f "$TIMER_FIFO"
   # Keep the service alive for the bounded host diagnostic to capture evidence.
   while :; do sleep 60; done
 }
 
+init_timer_fifo() {
+  # Recovery has Bash 3.2 before any SDK is installed. Its read timeout uses
+  # alarm(), avoiding a separate sleep process for every command and grace period.
+  [ ! -e "$TIMER_FIFO" ] || exit 1
+  /usr/bin/mkfifo -m 600 "$TIMER_FIFO" || exit 1
+  exec 9<> "$TIMER_FIFO" || exit 1
+}
+
+flush_outputs() {
+  (( ${#PENDING_OUTPUTS[@]} > 0 )) || return 0
+  local started=$SECONDS sizes="/tmp/native-diagnostic-$$.sizes" proof_size output_size raw_size
+  local raw_count=0 raw_valid=1 pending_count=${#PENDING_OUTPUTS[@]}
+  local bounded="/tmp/native-diagnostic-$$.flush"
+  # One bounded native copy per group, rather than tail/stat startup per command.
+  # Keep native byte-oriented copying: Bash 3.2 read -n would read large outputs
+  # one byte per system call. Small scalar reads below have a separate tight bound.
+  /usr/bin/tail -c "$MAX_OUTPUT_BYTES" "${PENDING_OUTPUTS[@]}" > "$bounded" || return 1
+  /usr/bin/stat -f '%z' "$PROOF_LOG" "$bounded" "${PENDING_OUTPUTS[@]}" > "$sizes" || return 1
+  {
+    IFS= read -r proof_size; IFS= read -r output_size
+    while IFS= read -r raw_size; do
+      raw_count=$((raw_count + 1))
+      [[ "$raw_size" =~ ^[0-9]+$ ]] && (( raw_size <= MAX_OUTPUT_BYTES )) || raw_valid=0
+    done
+  } < "$sizes"
+  PENDING_OUTPUTS=()
+  [[ "$proof_size" =~ ^[0-9]+$ && "$output_size" =~ ^[0-9]+$ ]] || return 1
+  (( raw_valid == 1 && raw_count == pending_count )) || return 1
+  (( proof_size + output_size + 1024 <= MAX_LOG_BYTES )) || return 1
+  /bin/cat "$bounded" >&3 || return 1
+  printf '\n[proof-flush] outputs-bytes=%s elapsed=%ss\n' "$output_size" "$((SECONDS - started))" >&3
+}
+
+read_scalar() {
+  local value status
+  # All three values are short native machine/uid/version scalars. Reject excess
+  # content instead of accepting a truncated first line as a successful gate.
+  IFS= read -r -n 65 -d '' value < "$LAST_OUTPUT"; status=$?
+  # EOF is mandatory: the byte bound or a NUL delimiter must never hide a suffix.
+  (( status == 1 && ${#value} < 65 )) || return 1
+  value=${value%$'\n'}
+  [[ "$value" != *$'\n'* ]] || return 1
+  SCALAR="$value"
+}
+
+cancel_probe() {
+  trap '' TERM INT
+  if [ -n "$ACTIVE_COMMAND" ]; then
+    kill -TERM "$ACTIVE_COMMAND" 2>/dev/null || :
+    IFS= read -r -t 2 -u 9 unused || :
+    kill -KILL "$ACTIVE_COMMAND" 2>/dev/null || :
+    wait "$ACTIVE_COMMAND" 2>/dev/null || :
+  fi
+  [ -z "$ACTIVE_TIMER" ] || { kill -TERM "$ACTIVE_TIMER" 2>/dev/null || :; wait "$ACTIVE_TIMER" 2>/dev/null || :; }
+  ACTIVE_COMMAND=""; ACTIVE_TIMER=""
+  finish false probe_cancelled
+}
+
 run_command() {
   local name="$1"
   shift
-  local process timer sleeper exit_code started observer=""
+  local process timer exit_code started waited
   LAST_OUTPUT="/tmp/native-diagnostic-$name.out"
-  printf '\n[proof-command] %s:' "$name" >> "$PROOF_LOG"
-  printf ' %s' "$@" >> "$PROOF_LOG"
-  printf '\n' >> "$PROOF_LOG"
+  printf '\n[proof-command] %s:' "$name" >&3
+  printf ' %s' "$@" >&3
+  printf '\n' >&3
   started=$SECONDS
   "$@" > "$LAST_OUTPUT" 2>&1 &
   process=$!
-  printf '[proof-start] %s child=%s shell=%s parent=%s seconds=%s\n' "$name" "$process" "$$" "$PPID" "$started" >> "$PROOF_LOG"
+  ACTIVE_COMMAND="$process"
+  printf '[proof-start] %s child=%s shell=%s parent=%s seconds=%s\n' "$name" "$process" "$$" "$PPID" "$started" >&3
   (
-    trap 'kill "$sleeper" 2>/dev/null || :; exit 0' TERM INT
-    sleep 45 &
-    sleeper=$!
-    wait "$sleeper"
-    printf '[proof-timeout] %s child=%s elapsed=%ss signal=TERM\n' "$name" "$process" "$((SECONDS - started))" >> "$PROOF_LOG"
+    trap 'exit 0' TERM INT
+    IFS= read -r -t 45 -u 9 unused || :
+    printf '[proof-timeout] %s child=%s elapsed=%ss signal=TERM\n' "$name" "$process" "$((SECONDS - started))" >&3
     kill -TERM "$process" 2>/dev/null || :
-    sleep 2 & sleeper=$!; wait "$sleeper"
+    IFS= read -r -t 2 -u 9 unused || :
     kill -KILL "$process" 2>/dev/null || :
   ) &
   timer=$!
-  if [[ "$name" = platform || "$name" = platform-warm ]]; then
-    # Observers never extend the independent 45-second command deadline.
-    (
-      local sample_pid="" sample_timer="" pause_pid="" pause sample_exit
-      trap 'kill -KILL "$sample_pid" 2>/dev/null || :; kill -TERM "$sample_timer" "$pause_pid" 2>/dev/null || :; exit 0' TERM INT
-      for pause in 10 15; do
-        sleep "$pause" & pause_pid=$!; wait "$pause_pid"
-        printf '[proof-process] %s child=%s elapsed=%ss fields=pid,ppid,stat,cpu-time,elapsed,cpu-percent,wchan,comm\n' "$name" "$process" "$((SECONDS - started))" >> "$PROOF_LOG"
-        /bin/ps -p "$process" -o pid=,ppid=,stat=,time=,etime=,pcpu=,wchan=,comm= >> "$PROOF_LOG" 2>&1 &
-        sample_pid=$!
-        (
-          local sample_sleeper=""
-          trap 'kill "$sample_sleeper" 2>/dev/null || :; exit 0' TERM INT
-          sleep 5 & sample_sleeper=$!; wait "$sample_sleeper"
-          kill -KILL "$sample_pid" 2>/dev/null || :
-        ) & sample_timer=$!
-        wait "$sample_pid"; sample_exit=$?
-        kill -TERM "$sample_timer" 2>/dev/null || :; wait "$sample_timer" 2>/dev/null || :
-        printf '[proof-process-exit] %s %s\n' "$name" "$sample_exit" >> "$PROOF_LOG"
-        sample_pid=""; sample_timer=""; pause_pid=""
-      done
-    ) & observer=$!
-  fi
+  ACTIVE_TIMER="$timer"
   wait "$process"
   exit_code=$?
+  waited=$SECONDS
+  # Includes fork/exec/wait, but excludes timer cleanup and evidence copying.
+  printf '[proof-native-wait] %s child=%s elapsed=%ss exit=%s\n' "$name" "$process" "$((waited - started))" "$exit_code" >&3
   kill -TERM "$timer" 2>/dev/null || :
   wait "$timer" 2>/dev/null || :
-  if [ -n "$observer" ]; then
-    kill -TERM "$observer" 2>/dev/null || :
-    wait "$observer" 2>/dev/null || :
-  fi
-  /usr/bin/tail -c 524288 "$LAST_OUTPUT" >> "$PROOF_LOG"
-  printf '\n[proof-duration] %s child=%s elapsed=%ss\n' "$name" "$process" "$((SECONDS - started))" >> "$PROOF_LOG"
-  printf '\n[proof-exit] %s\n' "$exit_code" >> "$PROOF_LOG"
+  ACTIVE_COMMAND=""; ACTIVE_TIMER=""
+  printf '[proof-cleanup] %s child=%s elapsed=%ss total=%ss\n' "$name" "$process" "$((SECONDS - waited))" "$((SECONDS - started))" >&3
+  printf '[proof-exit] %s\n' "$exit_code" >&3
   LAST_EXIT="$exit_code"
-  local size
-  size=$(/usr/bin/stat -f '%z' "$PROOF_LOG" 2>/dev/null || printf '0')
-  (( size <= MAX_LOG_BYTES )) || finish false diagnostic_log_budget_exceeded
+  PENDING_OUTPUTS+=("$LAST_OUTPUT")
   return 0
 }
 
-# Collect cheap native identity/context before the first framework-dependent probe.
-run_command kernel /usr/bin/uname -a
-(( LAST_EXIT == 0 )) || finish false uname_failed
+diagnose_failure() {
+  run_command kernel /usr/bin/uname -a
+  run_command account /usr/bin/id
+  run_command context /usr/sbin/sysctl kern.bootargs machdep.cpu.brand_string machdep.cpu.features machdep.cpu.leaf7_features
+  run_command parent /bin/ps -p "$$" -p "$PPID" -o pid=,ppid=,comm=
+  run_command processes /bin/ps -axo pid,ppid,comm
+}
+
+fail_probe() {
+  local reason="$1"
+  flush_outputs || finish false diagnostic_log_budget_exceeded
+  diagnose_failure
+  finish false "$reason"
+}
+
+init_timer_fifo
+trap cancel_probe TERM INT
+
+# Test the required native gates before optional process/CPU diagnostics.
 run_command architecture /usr/bin/uname -m
-(( LAST_EXIT == 0 )) || finish false architecture_probe_failed
-architecture=$(cat "$LAST_OUTPUT")
-[ "$architecture" = x86_64 ] || finish false unexpected_guest_architecture
-run_command account /usr/bin/id
+(( LAST_EXIT == 0 )) || fail_probe architecture_probe_failed
+read_scalar || fail_probe architecture_output_invalid
+architecture="$SCALAR"
+[ "$architecture" = x86_64 ] || fail_probe unexpected_guest_architecture
 run_command uid /usr/bin/id -u
-(( LAST_EXIT == 0 )) || finish false uid_probe_failed
-uid=$(cat "$LAST_OUTPUT")
-[ "$uid" = 0 ] || finish false recovery_account_not_root
-run_command bootargs /usr/sbin/sysctl kern.bootargs
-run_command cpu /usr/sbin/sysctl machdep.cpu.brand_string machdep.cpu.features machdep.cpu.leaf7_features
-run_command parent /bin/ps -p "$$" -p "$PPID" -o pid=,ppid=,comm=
-run_command processes /bin/ps -axo pid,ppid,comm
+(( LAST_EXIT == 0 )) || fail_probe uid_probe_failed
+read_scalar || fail_probe uid_output_invalid
+uid="$SCALAR"
+[ "$uid" = 0 ] || fail_probe recovery_account_not_root
 run_command platform /usr/bin/sw_vers
 platform_exit="$LAST_EXIT"
-run_command system /bin/launchctl print system
-system_exit="$LAST_EXIT"
-run_command arbitration /bin/launchctl print system/com.apple.diskarbitrationd
-arbitration_exit="$LAST_EXIT"
-run_command recovery /bin/launchctl print system/com.apple.recoveryosd
-recovery_exit="$LAST_EXIT"
+flush_outputs || finish false diagnostic_log_budget_exceeded
 if (( platform_exit != 0 )); then
-  printf '[proof-retry] sw_vers once after native service context; same 45-second deadline\n' >> "$PROOF_LOG"
+  run_command system /bin/launchctl print system
+  system_exit="$LAST_EXIT"
+  run_command arbitration /bin/launchctl print system/com.apple.diskarbitrationd
+  arbitration_exit="$LAST_EXIT"
+  run_command recovery /bin/launchctl print system/com.apple.recoveryosd
+  recovery_exit="$LAST_EXIT"
+  printf '[proof-retry] sw_vers once after native service context; same 45-second deadline\n' >&3
   run_command platform-warm /usr/bin/sw_vers
   platform_exit="$LAST_EXIT"
 fi
-(( platform_exit == 0 )) || finish false sw_vers_failed
+(( platform_exit == 0 )) || fail_probe sw_vers_failed
 run_command version /usr/bin/sw_vers -productVersion
-(( LAST_EXIT == 0 )) || finish false product_version_failed
-os_version=$(cat "$LAST_OUTPUT")
-[[ "$os_version" =~ ^[0-9]+\.[0-9]+(\.[0-9]+)?$ ]] || finish false product_version_invalid
-(( ${os_version%%.*} >= 14 )) || finish false unsupported_macos_version
+(( LAST_EXIT == 0 )) || fail_probe product_version_failed
+read_scalar || fail_probe product_version_invalid
+os_version="$SCALAR"
+[[ "$os_version" =~ ^[0-9]+\.[0-9]+(\.[0-9]+)?$ ]] || fail_probe product_version_invalid
+(( ${os_version%%.*} >= 14 )) || fail_probe unsupported_macos_version
+flush_outputs || finish false diagnostic_log_budget_exceeded
 
 # Bound readiness independently of the host's 40-minute overall deadline.
 readiness_start=$SECONDS
 attempt=0
 while (( SECONDS - readiness_start < 600 )); do
   attempt=$((attempt + 1))
-  printf '\n[readiness-attempt] %s\n' "$attempt" >> "$PROOF_LOG"
+  printf '\n[readiness-attempt] %s\n' "$attempt" >&3
   run_command disks /usr/sbin/diskutil list physical
   disk_list_exit="$LAST_EXIT"
   if (( disk_list_exit == 0 )); then
@@ -168,9 +225,9 @@ while (( SECONDS - readiness_start < 600 )); do
       candidates=$((candidates + 1))
       selected_disk="/dev/$disk"
       disk_bytes="$size"
-      printf '[writable-target] %s %s bytes\n' "$selected_disk" "$disk_bytes" >> "$PROOF_LOG"
+      printf '[writable-target] %s %s bytes\n' "$selected_disk" "$disk_bytes" >&3
     done < <(printf '%s\n' "$disk_list" | sed -nE 's#^/dev/(disk[0-9]+).*#\1#p')
-    (( candidates <= 1 )) || finish false ambiguous_writable_64g_disks
+    (( candidates <= 1 )) || fail_probe ambiguous_writable_64g_disks
     if (( candidates == 1 )); then
       # Re-probe live launchd domains after disk readiness, preserving native exits.
       run_command system_ready /bin/launchctl print system
@@ -179,10 +236,11 @@ while (( SECONDS - readiness_start < 600 )); do
       arbitration_exit="$LAST_EXIT"
       run_command recovery_ready /bin/launchctl print system/com.apple.recoveryosd
       recovery_exit="$LAST_EXIT"
-      (( system_exit == 0 && arbitration_exit == 0 && recovery_exit == 0 )) || finish false service_domain_not_ready
+      (( system_exit == 0 && arbitration_exit == 0 && recovery_exit == 0 )) || fail_probe service_domain_not_ready
       finish true native_recovery_and_writable_64g_disk_ready
     fi
   fi
-  sleep 5
+  flush_outputs || finish false diagnostic_log_budget_exceeded
+  IFS= read -r -t 5 -u 9 unused || :
 done
-finish false disk_management_or_writable_target_not_ready
+fail_probe disk_management_or_writable_target_not_ready