diff --git a/tools/marmot-interop/lib.sh b/tools/marmot-interop/lib.sh index aaa04bfae..4194d3e24 100644 --- a/tools/marmot-interop/lib.sh +++ b/tools/marmot-interop/lib.sh @@ -175,21 +175,45 @@ jq_group_id() { # wait_for_invite # Echoes the first new group_id that appears in `wn groups invites --json`. # Returns 1 on timeout. +# +# Also prints a heartbeat every ~10s with: +# - elapsed/remaining time +# - current count of pending welcomes (should be 0 until it isn't) +# - last relevant line of wnd stderr (grep for welcome/giftwrap/subscribe/error) +# so a stalled poll gives the operator something to forward. wait_for_invite() { - local who="$1" timeout="${2:-60}" deadline gid - deadline=$(( $(date +%s) + timeout )) + local who="$1" timeout="${2:-60}" deadline gid start last_hb + local wnfn data_dir + if [[ "$who" == "B" ]]; then wnfn=wn_b; data_dir="$B_DIR" + else wnfn=wn_c; data_dir="$C_DIR"; fi + start=$(date +%s) + deadline=$(( start + timeout )) + last_hb=$start while [[ $(date +%s) -lt $deadline ]]; do - if [[ "$who" == "B" ]]; then - gid=$(wn_b_json groups invites 2>/dev/null \ - | jq -c '.[0] // empty' 2>/dev/null | jq_group_id || true) - else - gid=$(wn_c_json groups invites 2>/dev/null \ - | jq -c '.[0] // empty' 2>/dev/null | jq_group_id || true) - fi + gid=$("$wnfn" --json groups invites 2>/dev/null \ + | jq -c '.[0] // empty' 2>/dev/null | jq_group_id || true) if [[ -n "${gid:-}" ]]; then printf '%s\n' "$gid" return 0 fi + + # Heartbeat every ~10s. + local now=$(date +%s) + if (( now - last_hb >= 10 )); then + local elapsed=$(( now - start )) remaining=$(( deadline - now )) + local pending + pending=$("$wnfn" --json groups invites 2>/dev/null \ + | jq 'length' 2>/dev/null || echo "?") + local recent="" + if [[ -f "$data_dir/logs/stderr.log" ]]; then + recent=$(tail -n 200 "$data_dir/logs/stderr.log" 2>/dev/null \ + | grep -iE 'welcome|giftwrap|gift_wrap|mls|subscribe|1059|444|error|warn' \ + | tail -n 1 || true) + fi + info "$who wait_for_invite +${elapsed}s (remaining ${remaining}s) pending=$pending tail: ${recent:-}" + last_hb=$now + fi + sleep 2 done return 1 @@ -297,6 +321,98 @@ load_state() { grep "^${key}=" "$STATE_FILE_RUNTIME" 2>/dev/null | tail -n1 | cut -d= -f2- } +# ------- daemon diagnostics -------------------------------------------------- +# Dumps everything we know about a daemon's state. Called before polling for +# invites (baseline) and on every invite-poll failure so the operator can +# forward a single log file that explains what the daemon saw (or didn't). +# +# Output is tee'd to both stderr (for live viewing) and $LOG_FILE (for forward). +dump_daemon_diagnostics() { + local who="$1" tag="${2:-diagnostics}" data_dir socket wnfn npub hex + if [[ "$who" == "B" ]]; then + data_dir="$B_DIR"; socket="$B_SOCKET"; wnfn=wn_b + npub="${B_NPUB:-?}"; hex="${B_HEX:-?}" + else + data_dir="$C_DIR"; socket="$C_SOCKET"; wnfn=wn_c + npub="${C_NPUB:-?}"; hex="${C_HEX:-?}" + fi + + printf '\n%s%s---- [%s] %s daemon diagnostics ----%s\n' \ + "$C_BOLD" "$C_CYAN" "$tag" "$who" "$C_RESET" >&2 + printf '\n==== [%s] %s daemon diagnostics ====\n' "$tag" "$who" >>"$LOG_FILE" + + info "$who identity npub=$npub" + info "$who identity hex =$hex" + info "$who socket $socket" + + # Relay list grouped by type — this is the critical bit for invite + # debugging. whitenoise-rs subscribes to kind:1059 on Inbox relays only, + # so if Amethyst doesn't see $B_NPUB's kind:10050 list pointing at these + # URLs, the gift wrap will never reach B. + step "$who relays (per type):" + for t in nip65 inbox key_package; do + local raw urls + raw=$("$wnfn" --json relays list --type "$t" 2>/dev/null || true) + urls=$(printf '%s' "$raw" \ + | jq -r '(.result // .) | .[]? | (.url // .relay.url // empty)' 2>/dev/null \ + | paste -sd',' -) + info " $t: ${urls:-}" + printf ' %s %s raw: %s\n' "$who" "$t" "$raw" >>"$LOG_FILE" + done + + # Connection status per relay — shows which sockets are actually live. + step "$who relay connection status:" + "$wnfn" --json relays list 2>/dev/null \ + | jq -r '(.result // .)[]? | " \(.url // .relay.url // "?") [\(.type // "?")] [\(.status // .connection_status // "?")]"' 2>/dev/null \ + | tee -a "$LOG_FILE" >&2 || true + + # Daemon-level subscription health. + step "$who wn debug health:" + local health + health=$("$wnfn" --json debug health 2>/dev/null || "$wnfn" debug health 2>/dev/null || true) + printf ' %s\n' "${health:-}" | tee -a "$LOG_FILE" >&2 + + # Relay-control state (subscriptions, filters, planes). Truncated to keep + # stderr readable; full copy still goes to $LOG_FILE. + step "$who wn debug relay-control-state (truncated to stderr; full in $LOG_FILE):" + local rcs + rcs=$("$wnfn" --json debug relay-control-state 2>/dev/null || "$wnfn" debug relay-control-state 2>/dev/null || true) + printf '%s\n' "${rcs:-}" | head -n 20 | sed 's/^/ /' >&2 + printf '%s wn debug relay-control-state FULL:\n%s\n' "$who" "${rcs:-}" >>"$LOG_FILE" + + # Pending welcomes already decrypted by the daemon. Non-empty here while + # wait_for_invite is polling would be a race worth noticing. + step "$who pending invites:" + local inv + inv=$("$wnfn" --json groups invites 2>/dev/null || true) + printf ' %s\n' "${inv:-}" | tee -a "$LOG_FILE" >&2 + + # Tail of daemon stderr — contains the live 1059/welcome processing logs. + step "$who wnd stderr (last 80 lines from $data_dir/logs/stderr.log):" + if [[ -f "$data_dir/logs/stderr.log" ]]; then + tail -n 80 "$data_dir/logs/stderr.log" 2>/dev/null | sed 's/^/ /' | tee -a "$LOG_FILE" >&2 || true + else + info " (no stderr log at $data_dir/logs/stderr.log)" + fi + + printf '%s%s---- end %s diagnostics ----%s\n\n' \ + "$C_BOLD" "$C_CYAN" "$who" "$C_RESET" >&2 + printf '==== end [%s] %s diagnostics ====\n\n' "$tag" "$who" >>"$LOG_FILE" +} + +# Asks the operator to capture Amethyst's MarmotDbg logcat so the script log +# ends up with both sides of the pipe in one place. +prompt_amethyst_logcat() { + local note="${1:-paste below}" + prompt_human "On the host running adb, capture Amethyst's Marmot logs: + + adb logcat -d -v time | grep -E 'MarmotDbg|Marmot |MlsWelcome|GiftWrap' \\ + | tail -n 200 > /tmp/amethyst-marmot.log + +Then paste /tmp/amethyst-marmot.log contents here so the failure report has +both the Amethyst-side publish log and the wn-side subscription log ($note)." +} + # ------- group cleanup ------------------------------------------------------- cleanup_group() { local gid="$1" who="${2:-B}" diff --git a/tools/marmot-interop/marmot-interop.sh b/tools/marmot-interop/marmot-interop.sh index a7c60e96f..132ec3012 100755 --- a/tools/marmot-interop/marmot-interop.sh +++ b/tools/marmot-interop/marmot-interop.sh @@ -318,16 +318,30 @@ test_01_keypackage_discovery() { test_02_amethyst_creates_group() { banner "Test 02 — Amethyst creates group, invites B" + # Baseline dump BEFORE the human triggers the publish in Amethyst. + # If this diagnostic shows B has no inbox relays (or the inbox relays + # differ from the ones Amethyst has cached for B's kind:10050 list), + # the welcome gift wrap will never reach B no matter how correctly + # Amethyst sends it. + dump_daemon_diagnostics B "pre-invite baseline" + prompt_human "In Amethyst: 1. Tap '+' -> Create Group 2. Name: Interop-02 3. Add member: $B_NPUB - 4. Tap Create / Send Invite" + 4. Tap Create / Send Invite - step "polling B's daemon for invite (60s)" +Tip: watch the Android logcat for tag 'MarmotDbg' — you should see +'publishing welcome gift wrap id=… kind:1059 → N relay(s): [...]' listing +the same relays as B's inbox above. If the list is empty or different, +that's the bug." + + step "polling B's daemon for invite (60s, heartbeat every ~10s)" local gid if ! gid=$(wait_for_invite B 60); then fail_msg "no invite arrived at B" + dump_daemon_diagnostics B "post-timeout (test_02)" + prompt_amethyst_logcat "test_02 timeout" record_result "02 Amethyst->B create+invite" fail "invite never arrived" return fi @@ -431,14 +445,18 @@ test_04_three_member_group() { fi info "using group $gid" + dump_daemon_diagnostics C "pre-invite baseline (test_04)" + prompt_human "In Amethyst, open the group from Test 02 (or 'Interop-04-bootstrap'). Group Info -> Add Member -> paste: $C_NPUB Confirm the invite is sent." - step "polling C for invite (60s)" + step "polling C for invite (60s, heartbeat every ~10s)" local c_gid if ! c_gid=$(wait_for_invite C 60); then fail_msg "C never received invite" + dump_daemon_diagnostics C "post-timeout (test_04)" + prompt_amethyst_logcat "test_04 timeout" record_result "04 3-member add-after-create" fail "invite to C missing" return fi @@ -865,6 +883,15 @@ main() { ensure_identity C prompt_for_a_npub configure_relays + + # Baseline dump after relays are configured but before any tests run. + # This is the single most useful log to forward when Test 02 fails — + # it shows whether B's kind:10050 (inbox) relay list actually landed + # on the relays Amethyst will look at for the giftwrap delivery target. + banner "Post-configure baseline diagnostics" + dump_daemon_diagnostics B "post-configure" + dump_daemon_diagnostics C "post-configure" + instruct_amethyst_setup test_01_keypackage_discovery