Something went wrong. Try again.
Something went wrong. Try again.
123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379#!/usr/bin/env bash# Host-only regression tests for device-log.sh. The fake adb answers only the read-only# commands the script may send and rejects everything else; nothing here is device evidence.set -eEuo pipefailroot=$(cd -- "$(dirname -- "${BASH_SOURCE[0]}")/.." && pwd)tmp=$(mktemp -d)background='' current=setuptrap '[[ -z "$background" ]] || kill "$background" 2>/dev/null || true; rm -rf -- "$tmp"' EXITtrap 'echo "FAIL: $current (line $LINENO)" >&2' ERRmkdir "$tmp/bin"export ADB_LOG="$tmp/adb.log" FAKE_DIR="$tmp/fake"unset HZZ_ADB HZZ_LOG_FILE HZZ_PACKAGE FAKE_OLD_ADB
cat > "$tmp/bin/adb" <<'FAKE'#!/usr/bin/env bashset -euo pipefailprintf '%s\n' "$*" >> "$ADB_LOG"case "$*" in 'logcat -d -v raw -s hzz') calls=0 [[ ! -e "$FAKE_DIR/calls" ]] || calls=$(< "$FAKE_DIR/calls") calls=$((calls + 1)) echo "$calls" > "$FAKE_DIR/calls" # The buffer is the file `buffer`, or with a `script` directory the file named after # the number of this read. Without that file the device is unreachable. buffer=$FAKE_DIR/buffer [[ ! -d "$FAKE_DIR/script" ]] || buffer=$FAKE_DIR/script/$calls [[ -e "$buffer" ]] || { echo 'error: device offline' >&2; exit 1; } printf '%s\r\n' '--------- beginning of main' while IFS= read -r line; do printf '%s\r\n' "$line"; done < "$buffer" ;; 'shell run-as dev.hzz.streamer.debug ls files/event-log') [[ -d "$FAKE_DIR/device" ]] || { echo 'ls: files/event-log: No such file or directory' >&2; exit 1; } for path in "$FAKE_DIR"/device/*; do printf '%s\r\n' "${path##*/}"; done ;; 'shell run-as dev.hzz.streamer.debug cat files/event-log/events.'[0-9]'.log') cat -- "$FAKE_DIR/device/${5##*/}" ;; 'shell run-as dev.hzz.streamer ls files/event-log') # An older adb passes the device's message on as output and reports success. [[ -z "${FAKE_OLD_ADB:-}" ]] || { echo 'run-as: package not debuggable: dev.hzz.streamer'; exit 0; } echo 'run-as: package not debuggable: dev.hzz.streamer' >&2 exit 1 ;; 'shell run-as dev.hzz.absent ls files/event-log') echo 'run-as: unknown package: dev.hzz.absent' >&2 exit 1 ;; *) echo 'FORBIDDEN adb command' >&2; exit 99 ;;esacFAKEcat > "$tmp/bin/remote" <<'FAKE'#!/usr/bin/env bash# Stands in for adb reached through a remote shell: permits only the adb subcommands# devices, shell, logcat and install, then has a second shell parse the joined arguments.set -euo pipefail[[ "$1" == HOST_ALIAS && "$2" == adb ]] || exit 97case "$3" in devices|shell|logcat|install) ;; *) echo 'refused adb subcommand' >&2; exit 98 ;;esacshiftexec bash -c "$*"FAKEchmod +x "$tmp/bin/adb" "$tmp/bin/remote"export PATH="$tmp/bin:$PATH"script="$root/scripts/device-log.sh"
# ev SEQ MINUTE:SECOND LEVEL 'EVENT [FIELDS]' prints one line in the app's format.ev() { printf 'seq=%s wall=2026-10-05T14:%s.000Z mono=%s level=%s event=%s\n' "$1" "$2" "$1" "$3" "$4"; }same() { cmp -s -- "$1" "$2" && return 0 { echo "FAIL: $current: $2 differs"; echo '--- expected'; cat -- "$1"; echo '--- actual'; cat -- "$2"; } >&2 exit 1}expect_failure() { if bash "$script" "$@" > "$tmp/stdout" 2> "$tmp/stderr" < /dev/null; then echo "FAIL: $current: expected failure: $*" >&2; exit 1 fi}refute() { # A bare `! command` never fails a `set -e` script, so say it with a function. if "$@"; then echo "FAIL: $current: must not succeed: $*" >&2; exit 1; fi}once() { bash "$script" follow --once "$@" 2> "$tmp/stderr"; }wait_for() { local i for ((i = 0; i < 100; i++)); do if "$@" 2> /dev/null; then return 0; fi sleep 0.2 done echo "FAIL: $current: timed out waiting for: $*" >&2; exit 1}stop_background() { kill "$background" 2> /dev/null || true wait "$background" 2> /dev/null || true background=''}run_test() { current=$1 rm -rf -- "$FAKE_DIR" "$ADB_LOG" mkdir "$FAKE_DIR" "$1" # Every command that reached adb is one of the three read-only ones. if [[ -e "$ADB_LOG" ]]; then refute grep -v -E -q '^(logcat -d -v raw -s hzz|shell run-as dev\.hzz\.[a-z.]+ (ls files/event-log|cat files/event-log/events\.[0-9]\.log))$' "$ADB_LOG" fi echo "ok $1"}
for n in 1 2 3 4 5 6 7 8 9; do line[n]=$(ev "$n" "03:0$n" info 'lab_request method=GET route=STATUS query=NONE status=200')donelines() { local n; for n in "$@"; do printf '%s\n' "${line[n]}"; done; }
usage_errors_never_call_adb() { expect_failure expect_failure bogus expect_failure follow expect_failure follow --file expect_failure follow --file "$tmp/a.log" --interval 0 expect_failure follow --file "$tmp/a.log" --output-dir "$tmp/x" expect_failure pull expect_failure pull --output-dir "$tmp/x" --package 'bad;name' expect_failure pull --output-dir "$tmp/x" --file "$tmp/a.log" expect_failure watch expect_failure watch --file - --silence 0 [[ ! -e "$ADB_LOG" && ! -e "$tmp/a.log" && ! -e "$tmp/x" ]]}
writing_inside_a_git_work_tree_is_refused() { mkdir -p "$tmp/repo/.git" "$tmp/repo/logs" ln -s "$tmp/repo/logs" "$tmp/link" lines 1 2 > "$FAKE_DIR/buffer" local path for path in "$tmp/repo/logs/device.log" "$tmp/repo/new/device.log" "$tmp/link/device.log" "$root/scripts/device.log"; do expect_failure follow --once --file "$path" grep -q 'git work tree' "$tmp/stderr" [[ ! -e "$path" ]] done HZZ_LOG_FILE="$tmp/repo/logs/device.log" expect_failure follow --once grep -q 'git work tree' "$tmp/stderr" expect_failure pull --output-dir "$tmp/repo/pulled" grep -q 'git work tree' "$tmp/stderr" [[ ! -e "$ADB_LOG" && ! -e "$tmp/repo/logs/device.log" && ! -e "$tmp/repo/pulled" && ! -e "$tmp/repo/new" ]]}
follow_reconnects_without_duplicates() { local out="$tmp/follow one.log" lines 1 2 3 > "$FAKE_DIR/buffer" once --file "$out" same "$FAKE_DIR/buffer" "$out" # Unreachable: the read fails and the file is untouched. mv "$FAKE_DIR/buffer" "$FAKE_DIR/held" expect_failure follow --once --file "$out" grep -q 'not reachable: error: device offline' "$tmp/stderr" same "$FAKE_DIR/held" "$out" # Reachable again: the buffer lost its oldest line and gained two. lines 2 3 4 5 > "$FAKE_DIR/buffer" once --file "$out" lines 1 2 3 4 5 > "$tmp/expected" same "$tmp/expected" "$out" # Nothing new, then a buffer holding only the last saved line, then an empty one. once --file "$out" lines 5 > "$FAKE_DIR/buffer" once --file "$out" : > "$FAKE_DIR/buffer" HZZ_LOG_FILE="$out" once same "$tmp/expected" "$out"}
follow_reports_a_gap_with_one_line() { local out="$tmp/follow-gap.log" lines 1 2 3 > "$FAKE_DIR/buffer" once --file "$out" # The buffer rolled past line 3 while unreachable: lines 4 and 5 are gone. lines 6 7 > "$FAKE_DIR/buffer" once --file "$out" grep -q 'gap line written' "$tmp/stderr" { lines 1 2 3 echo 'gap after_seq=3 after_wall=2026-10-05T14:03:03.000Z before_seq=6 before_wall=2026-10-05T14:03:06.000Z' lines 6 7 } > "$tmp/expected" same "$tmp/expected" "$out" # The same buffer again, then one more line: no second gap line. once --file "$out" lines 6 7 8 > "$FAKE_DIR/buffer" once --file "$out" lines 8 >> "$tmp/expected" same "$tmp/expected" "$out" # Without the last saved line in the buffer nothing proves that line 9 came straight # after line 8, so that is reported too. lines 9 > "$FAKE_DIR/buffer" once --file "$out" echo 'gap after_seq=8 after_wall=2026-10-05T14:03:08.000Z before_seq=9 before_wall=2026-10-05T14:03:09.000Z' >> "$tmp/expected" lines 9 >> "$tmp/expected" same "$tmp/expected" "$out"}
follow_keeps_the_lines_of_a_restarted_process() { local out="$tmp/follow-restart.log" n # The second process numbers its lines from 1 again; only wall tells them apart. for n in 1 2 3; do ev "$n" "03:0$n" info 'lab_connection_opened active=1'; done > "$tmp/first" for n in 1 2 3 4; do ev "$n" "05:0$n" info 'lab_connection_opened active=1'; done > "$tmp/second" # The process restarted while unreachable, and its third line has the sequence number of # the last saved line. Everything after the saved line itself is new. cat "$tmp/first" > "$FAKE_DIR/buffer" once --file "$out" { grep -E '^seq=[23] ' "$tmp/first"; cat "$tmp/second"; } > "$FAKE_DIR/buffer" once --file "$out" cat "$tmp/first" "$tmp/second" > "$tmp/expected" same "$tmp/expected" "$out" # The same restart with the saved line rolled out of the buffer: the new process's third # line is not mistaken for it, and the gap is reported. out="$tmp/follow-restart-gap.log" cat "$tmp/first" > "$FAKE_DIR/buffer" once --file "$out" grep -E '^seq=[23] ' "$tmp/second" > "$FAKE_DIR/buffer" once --file "$out" { cat "$tmp/first" echo 'gap after_seq=3 after_wall=2026-10-05T14:03:03.000Z before_seq=2 before_wall=2026-10-05T14:05:02.000Z' cat "$FAKE_DIR/buffer" } > "$tmp/expected" same "$tmp/expected" "$out"}
follow_keeps_running_while_the_device_is_unreachable() { local out="$tmp/follow-loop.log" mkdir "$FAKE_DIR/script" lines 1 2 3 > "$FAKE_DIR/script/1" # read 2 has no file: unreachable lines 2 3 4 5 > "$FAKE_DIR/script/3" HZZ_ADB='remote HOST_ALIAS adb' HZZ_LOG_FILE="$out" bash "$script" follow --interval 1 2> "$tmp/follow.err" & background=$! wait_for grep -q '^seq=5 ' "$out" stop_background lines 1 2 3 4 5 > "$tmp/expected" same "$tmp/expected" "$out" grep -q 'not reachable' "$tmp/follow.err"}
pull_copies_the_files_of_a_debug_build() { mkdir "$FAKE_DIR/device" lines 1 2 3 | while IFS= read -r text; do printf '%s\r\n' "$text"; done > "$FAKE_DIR/device/events.1.log" lines 4 5 > "$FAKE_DIR/device/events.0.log" bash "$script" pull --adb 'remote HOST_ALIAS adb' --output-dir "$tmp/pulled" > "$tmp/stdout" lines 1 2 3 > "$tmp/expected" same "$tmp/expected" "$tmp/pulled/events.1.log" same "$FAKE_DIR/device/events.0.log" "$tmp/pulled/events.0.log" [[ "$(cd "$tmp/pulled" && echo *)" == 'events.0.log events.1.log' ]] grep -q 'Copied 2 file' "$tmp/stdout" # An earlier copy is never overwritten. expect_failure pull --output-dir "$tmp/pulled" same "$tmp/expected" "$tmp/pulled/events.1.log" # A file that holds anything but event lines marks the copy unusable. echo 'cat: files/event-log/events.0.log: Permission denied' > "$FAKE_DIR/device/events.0.log" expect_failure pull --output-dir "$tmp/pulled-bad" [[ -f "$tmp/pulled-bad/INCOMPLETE.txt" ]]}
pull_is_refused_for_a_release_build() { mkdir "$FAKE_DIR/device" lines 1 > "$FAKE_DIR/device/events.0.log" expect_failure pull --package dev.hzz.streamer --output-dir "$tmp/release" grep -q 'release build' "$tmp/stderr" grep -q 'debug builds only' "$tmp/stderr" FAKE_OLD_ADB=1 HZZ_PACKAGE=dev.hzz.streamer expect_failure pull --output-dir "$tmp/release" grep -q 'debug builds only' "$tmp/stderr" expect_failure pull --package dev.hzz.absent --output-dir "$tmp/release" grep -q 'not installed' "$tmp/stderr" # A debug build that has never run has no directory to list. rm -r "$FAKE_DIR/device" expect_failure pull --output-dir "$tmp/release" grep -q 'has not run' "$tmp/stderr" [[ ! -e "$tmp/release" ]] refute grep -q ' cat ' "$ADB_LOG"}
watch_stays_quiet_and_reports() { local start stop failed crash restart start=$(ev 3 03:03 info 'lab_run_started generation=1 entry=TAILNET transport=NETTY_EVALUATION') stop=$(ev 11 03:21 info 'lab_run_stopped generation=1 reason=RUN_LIFETIME_EXPIRED elapsed_ms=900000') failed=$(ev 12 03:30 error 'lab_start_failed generation=2 entry=TAILNET transport=NETTY_EVALUATION reason=BIND_FAILED stage=BIND cause_1=IO') crash=$(ev 13 03:31 error 'uncaught_exception category=ILLEGAL_STATE') restart=$(ev 1 04:00 info 'process_start version_code=1 pid=4300 build=DEBUG') { ev 1 03:01 info 'process_start version_code=1 pid=4242 build=DEBUG' ev 2 03:02 info 'lab_start_requested generation=1 entry=TAILNET transport=NETTY_EVALUATION' echo "$start" ev 4 03:04 info 'lab_connection_opened active=1' ev 5 03:05 info 'lab_request method=GET route=PAGE query=QR_TOKEN status=200' ev 6 03:06 info 'lab_pair_succeeded credential=QR_TOKEN' ev 7 03:07 info 'lab_page_report step=POLL seconds=12 attempt=0 status=HTTP_200 pass=true' ev 8 03:08 info 'lab_connection_closed active=0' ev 9 03:09 warning 'lab_pair_failed credential=CODE reason=INVALID_CODE' } > "$tmp/part1" { ev 10 03:20 info 'lab_request method=GET route=STATUS query=NONE status=200' echo "$stop" } > "$tmp/part2" { echo "$failed" echo "$crash" ev 14 03:40 info 'lab_run_started generation=3 entry=TAILNET transport=NETTY_EVALUATION' ev 15 03:41 warning 'lab_run_stopped generation=3 reason=ADDRESS_UNAVAILABLE elapsed_ms=1000' ev 16 03:42 info 'lab_run_started generation=4 entry=TAILNET transport=NETTY_EVALUATION' echo "$restart" echo 'gap after_seq=1 after_wall=2026-10-05T14:04:00.000Z before_seq=40 before_wall=2026-10-05T14:09:00.000Z' ev 40 09:00 info 'lab_session_revoked' } > "$tmp/part3" # A run is open during the first pause and closed during the second. The last line # arrives in two pieces more than the silence apart. { cat "$tmp/part1"; sleep 3 cat "$tmp/part2"; sleep 3 cat "$tmp/part3" printf 'seq=41 wall=2026-10-05T14:09:01.000Z mono=41 level=warning eve'; sleep 2 printf 'nt=log_events_dropped count=3\n' } | bash "$script" watch --file - --silence 1 > "$tmp/watch.out" { echo 'process-start: seq=1 wall=2026-10-05T14:03:01.000Z mono=1 level=info event=process_start version_code=1 pid=4242 build=DEBUG' echo "run-started: $start" echo 'warning: seq=9 wall=2026-10-05T14:03:09.000Z mono=9 level=warning event=lab_pair_failed credential=CODE reason=INVALID_CODE' echo 'silence: no line for 1 s while a run is open; last was seq=9 wall=2026-10-05T14:03:09.000Z event=lab_pair_failed' echo "run-stopped: $stop" echo "start-failed: $failed" echo "error: $crash" echo 'run-started: seq=14 wall=2026-10-05T14:03:40.000Z mono=14 level=info event=lab_run_started generation=3 entry=TAILNET transport=NETTY_EVALUATION' echo 'run-stopped: seq=15 wall=2026-10-05T14:03:41.000Z mono=15 level=warning event=lab_run_stopped generation=3 reason=ADDRESS_UNAVAILABLE elapsed_ms=1000' echo 'run-started: seq=16 wall=2026-10-05T14:03:42.000Z mono=16 level=info event=lab_run_started generation=4 entry=TAILNET transport=NETTY_EVALUATION' echo "process-start: $restart (a run was open and has no stop line)" echo 'gap: after_seq=1 after_wall=2026-10-05T14:04:00.000Z before_seq=40 before_wall=2026-10-05T14:09:00.000Z' echo 'warning: seq=41 wall=2026-10-05T14:09:01.000Z mono=41 level=warning event=log_events_dropped count=3' } > "$tmp/expected" same "$tmp/expected" "$tmp/watch.out"}
watch_reads_a_growing_file() { local log="$tmp/watched.log" stop gap='after_seq=3 after_wall=2026-10-05T14:03:03.000Z before_seq=7 before_wall=2026-10-05T14:03:07.000Z' stop=$(ev 7 03:07 info 'lab_run_stopped generation=1 reason=OPERATOR_STOP elapsed_ms=900') { ev 1 03:01 info 'process_start version_code=1 pid=4242 build=DEBUG' ev 2 03:02 info 'lab_run_started generation=1 entry=LOOPBACK transport=NETTY_EVALUATION' ev 3 03:03 info 'lab_request method=GET route=STATUS query=NONE status=200' } > "$log" # What the file already holds is not printed, but it leaves a run open. bash "$script" watch --file "$log" --silence 1 > "$tmp/watch.out" & background=$! wait_for grep -q '^silence: ' "$tmp/watch.out" { echo "gap $gap"; echo "$stop"; } >> "$log" wait_for grep -q '^run-stopped: ' "$tmp/watch.out" sleep 2.5 # no run is open now, so no further silence line stop_background { echo 'silence: no line for 1 s while a run is open; last was seq=3 wall=2026-10-05T14:03:03.000Z event=lab_request' echo "gap: $gap" echo "run-stopped: $stop" } > "$tmp/expected" same "$tmp/expected" "$tmp/watch.out" HZZ_LOG_FILE="$log" bash "$script" watch --from-start > "$tmp/watch.out" & background=$! wait_for grep -q '^run-stopped: ' "$tmp/watch.out" stop_background { echo 'process-start: seq=1 wall=2026-10-05T14:03:01.000Z mono=1 level=info event=process_start version_code=1 pid=4242 build=DEBUG' echo 'run-started: seq=2 wall=2026-10-05T14:03:02.000Z mono=2 level=info event=lab_run_started generation=1 entry=LOOPBACK transport=NETTY_EVALUATION' echo "gap: $gap" echo "run-stopped: $stop" } > "$tmp/expected" same "$tmp/expected" "$tmp/watch.out"}
run_test usage_errors_never_call_adbrun_test writing_inside_a_git_work_tree_is_refusedrun_test follow_reconnects_without_duplicatesrun_test follow_reports_a_gap_with_one_linerun_test follow_keeps_the_lines_of_a_restarted_processrun_test follow_keeps_running_while_the_device_is_unreachablerun_test pull_copies_the_files_of_a_debug_buildrun_test pull_is_refused_for_a_release_buildrun_test watch_stays_quiet_and_reportsrun_test watch_reads_a_growing_fileecho 'PASS: device-log follow, pull and watch tests (fake adb only)'