Skip to content

Relay-only heartbeat grace + robust path-set classification - #697

Merged
michaelneale merged 7 commits into
mainfrom
micn/heartbeat-and-grammar-logs
May 27, 2026
Merged

Relay-only heartbeat grace + robust path-set classification#697
michaelneale merged 7 commits into
mainfrom
micn/heartbeat-and-grammar-logs

Conversation

@michaelneale

Copy link
Copy Markdown
Collaborator

Two small, independent fixes — one commit each.

1. Relay-only heartbeat: bigger grace, robust path detection, honest message

Observed today on the public mesh: mini's mesh-llm declared studio dead at 10:26:38 UTC after just 2 missed heartbeats, even though the relay-only policy is supposed to allow 3. The 60–90s that followed produced an HTTP 502 storm on openclaw (4 failed agent calls with Reducer failed (tried 3)), because MiniMax-M2.5 (studio) had been removed from the MoA eligible-peer set and the fallback to weaker peers also failed the reducer.

Root cause has three layers:

a. Threshold of 3 isn't enough. mini's path to studio is relay-only (mini's macOS VPN system extension blocks the LAN UDP hole-punch even though both peers are on the same Sydney subnet). Steady relay RTT is ~200ms; transient renegotiation spikes it past 10s. With 60s heartbeats and 3 misses, the grace window is ~3 min — and a single iroh relay path renegotiation can eat that. Bumped to 5 (≈5 min). Direct peers stay at 2 misses (a real network failure should still surface quickly).

b. is_relay_only detection failed silently mid-failure. The original check was selected_path_snapshot(conn).kind == Relay, but at the moment of heartbeat failure the connection is often between path selections and selected_path_snapshot returns Unknown. That made the lenient relay threshold never fire during the failures it was designed to protect against. New is_relay_only_connection looks at every advertised path: if none are IP, treat as relay-only. Also reverses the no-connection default (no live Connection object now defaults to relay-only / lenient, not strict).

c. Misleading recovery message. 💚 Heartbeat: <peer> recovered (was N/2) was hardcoded — even a relay-only peer with threshold 3 (now 5) showed /2. Now reads the real threshold from the failure policy.

Tests:

  • relay_only_peers_get_extra_heartbeat_grace (renamed; threshold now 5)
  • direct_peers_use_strict_heartbeat_threshold (new)
  • is_relay_only_path_set_classifies_correctly (new; is_relay_only_connection extracted as a thin wrapper over an iterator-based helper so it can be unit-tested without constructing an iroh Connection)

2. skippy-runtime: drop DEBUG lines from the native log callback

llama.cpp's llama_log_internal_v invokes the registered callback unconditionally with the level argument — level filtering is expected to live inside the callback. mesh-llm's callback (write_native_log) was ignoring _level and writing every line to the per-instance skippy-native.log, so LLAMA_LOG_DEBUG output ended up in the file regardless of GGML_LLAMA_LOG_LEVEL.

Observed impact: on studio today, 5,431 Grammar still awaiting trigger after token … DEBUG lines for 18 actual <minimax:tool_call> triggers — about 300× verbosity per completion. These are per-token traces of MiniMax-M2.5's reasoning phase before the tool-call regex fires.

Fix: drop ggml_log_level == DEBUG (1) unless GGML_LLAMA_LOG_LEVEL=4 (the existing opt-in set by enable_verbose_native_logs). Keep CONT (continuation) lines unconditionally so multi-line INFO/WARN messages don't get truncated.

Tests:

  • native_log_filter_drops_debug_by_default
  • native_log_filter_keeps_debug_when_verbose
  • native_log_filter_keeps_continuation_lines

Env-var tests run serially via a per-test mutex to avoid racing other env-touching tests in the same module.

Verification

  • cargo fmt --check, cargo check -p mesh-llm, cargo clippy -p mesh-llm-host-runtime -p skippy-runtime -- -D warnings all clean.
  • cargo test -p mesh-llm-host-runtime --lib and cargo test -p skippy-runtime --lib both pass for the new tests (one unrelated network-y test, owner_control_client_reuses_connection_for_sequential_requests, intermittently flakes on a busy machine; passes when re-run in isolation).
  • Not yet deployed live — but the changes are mechanical and the unit tests cover the policy/classification logic exhaustively. Live verification would require reproducing today's relay flap, which is mini-specific.

llama.cpp's llama_log_internal_v invokes the registered log callback
unconditionally with the level argument — the level filter is expected
to live inside the callback. mesh-llm's native log callback
(write_native_log) was ignoring _level and writing every line to
~/.mesh-llm/runtime/<pid>/logs/skippy-native.log, which meant
LLAMA_LOG_DEBUG output ended up in the file regardless of
GGML_LLAMA_LOG_LEVEL.

Observed impact: on studio today, ~5400 'Grammar still awaiting
trigger after token …' DEBUG lines for 18 actual tool-call grammar
triggers — roughly 300× verbosity per completion. The lines are emitted
per-token during MiniMax-M2.5's reasoning phase before the
<minimax:tool_call> regex fires.

Fix: drop ggml_log_level=DEBUG (1) unless GGML_LLAMA_LOG_LEVEL=4 (the
existing opt-in that enable_verbose_native_logs sets). Keep CONT
(continuation) lines regardless so multi-line INFO/WARN messages don't
get truncated.

Tests added in skippy-runtime::tests:
- native_log_filter_drops_debug_by_default
- native_log_filter_keeps_debug_when_verbose
- native_log_filter_keeps_continuation_lines

Env-var tests run serially via per-test mutex to avoid racing the rest
of the file's GGML_LLAMA_LOG_LEVEL-touching tests.
Three related changes to the heartbeat failure-detection path:

1) Bump relay-only failure threshold from 3 to 5.

   Observed today on the public mesh: a Sydney<->Sydney peer (mini ->
   studio) that should hole-punch a direct LAN path but doesn't (mini's
   macOS VPN system extension blocks the UDP hole-punch) is forced onto
   a relay-only path via services.iroh.computer. Steady-state relay RTT
   is ~200ms but transient renegotiation spikes it to 10s+. With 60s
   heartbeats and a 3-miss threshold, mini declared studio dead twice
   in a 25 minute window — and each declaration knocked MiniMax-M2.5
   out of the MoA reducer's eligible-peer set, causing
   'HTTP 502: Reducer failed (tried 3)' for ~90s while the fallback to
   weaker peers also failed. 5 misses = 5 min grace covers the typical
   iroh relay path-renegotiation window. Direct paths stay at 2.

2) Fix is_relay_only detection so it survives mid-failure.

   The original check was ,
   which returns  (not Relay) when no path is currently
   selected — exactly what happens during a heartbeat failure when the
   connection is between path selections. That meant the
   relay-only-grace policy *never fired during the failures it was
   designed to protect against*: every flap landed on the strict
   direct-threshold path.

   New is_relay_only_connection inspects every advertised path; if none
   is IP (i.e. only relay paths are known), treat as relay-only. Also
   fixes the no-connection case: previously a peer with no live
   Connection object got the strict direct threshold, which is
   backwards — no connection at all is the most failure-prone state.
   Now defaults to lenient.

3) Cosmetic: '💚 Heartbeat: <peer> recovered (was N/2)' was hardcoded
   '/2', misleading for relay-only peers whose actual threshold was 3
   (now 5). Read the real threshold from the policy and display it.

Tests (mesh::tests::):
- relay_only_peers_get_extra_heartbeat_grace (renamed,
  threshold updated 3 -> 5)
- direct_peers_use_strict_heartbeat_threshold (new)
- is_relay_only_path_set_classifies_correctly (new,
  exercises empty/all-relay/mixed/all-direct path sets)

is_relay_only_connection is implemented as a thin wrapper over
is_relay_only_path_set(IntoIterator<Item=bool>) so the classification
logic is unit-testable without constructing a real iroh Connection.
Copilot AI review requested due to automatic review settings May 26, 2026 20:59

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

This PR improves operational stability and observability in two places: (1) mesh peer liveness detection under relay-only connectivity, and (2) skippy-runtime’s native llama.cpp logging to prevent DEBUG-level log spam unless explicitly enabled.

Changes:

  • Increased the heartbeat failure threshold for relay-only peers (2 → 5) and added more robust relay-only classification based on advertised paths.
  • Updated the heartbeat recovery log message to display a threshold value from the failure policy instead of a hardcoded /2.
  • Added a native-log callback filter to drop DEBUG lines by default (unless GGML_LLAMA_LOG_LEVEL=4), plus unit tests (including env-var serialization).

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated 3 comments.

File Description
crates/skippy-runtime/src/lib.rs Adds should_drop_native_log_line and tests to suppress DEBUG native logs unless verbose is enabled.
crates/mesh-llm-host-runtime/src/mesh/heartbeat.rs Raises relay-only heartbeat grace, adds relay-only path-set detection helpers, and adjusts recovery messaging.
crates/mesh-llm-host-runtime/src/mesh/tests.rs Updates/extends tests for relay-only grace, strict direct threshold, and relay-only classification.

Comment thread crates/skippy-runtime/src/lib.rs Outdated
Comment on lines +688 to +697
fn should_drop_native_log_line(level: c_int) -> bool {
if level != GGML_LOG_LEVEL_DEBUG {
return false;
}
// CONT is "continuation of previous line" — never drop those because
// the previous line may have been INFO/WARN and we'd produce a
// truncated multi-line message.
if level == GGML_LOG_LEVEL_CONT {
return false;
}
Comment thread crates/skippy-runtime/src/lib.rs Outdated
Comment on lines +698 to +703
// GGML_LLAMA_LOG_LEVEL=4 (LLAMA_LOG_LEVEL_DEBUG) is the explicit opt-in
// for verbose native logs. Anything else: drop DEBUG.
!matches!(
std::env::var("GGML_LLAMA_LOG_LEVEL").as_deref(),
Ok("4") | Ok("debug") | Ok("DEBUG")
)
Comment on lines +779 to +788
// Show the actual threshold this peer was being judged
// against, not a hardcoded "/2". Relay-only peers get a
// higher threshold (see heartbeat_failure_policy_for_peer),
// so "(was 3/5)" reads correctly instead of misleading "3/2".
let (_, failure_policy) = self.heartbeat_failure_context(peer_id).await;
super::emit_mesh_info(format!(
"💚 Heartbeat: {} recovered (was {}/2)",
"💚 Heartbeat: {} recovered (was {}/{})",
peer_id.fmt_short(),
previous_failures
previous_failures,
failure_policy.failure_threshold,
Copilot AI review requested due to automatic review settings May 26, 2026 22:13

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 3 out of 3 changed files in this pull request and generated 3 comments.

Comment thread crates/skippy-runtime/src/lib.rs Outdated
Comment on lines +692 to +696
// the previous line may have been INFO/WARN and we'd produce a
// truncated multi-line message.
if level == GGML_LOG_LEVEL_CONT {
return false;
}
Comment thread crates/skippy-runtime/src/lib.rs Outdated
Comment on lines +699 to +702
!matches!(
std::env::var("GGML_LLAMA_LOG_LEVEL").as_deref(),
Ok("4") | Ok("debug") | Ok("DEBUG")
)
Comment thread crates/skippy-runtime/src/lib.rs Outdated
Comment on lines +678 to +680
/// Default: drop DEBUG (level 1). Keep CONT (level 5) so multi-line debug
/// messages don't end up half-written. Verbose mode (set via
/// [`enable_verbose_native_logs`]) keeps DEBUG so callers can opt in.
The original ordering made the CONT check dead code: the level-!=-DEBUG
guard above it already returned false for CONT (level 5), so the
explicit CONT branch could never execute. The comment claimed CONT was
being protected by that branch but the protection was incidental.

Reorder so CONT is checked first and is the real explicit pass-through,
matching the documented intent.

@i386 i386 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Two review notes from the diff:

  • [P2] crates/mesh-llm-host-runtime/src/mesh/heartbeat.rs: conn.as_ref().map(...).unwrap_or(true) now treats every peer with no current Connection as relay-only, so it gets the new 5-miss threshold. That includes non-relay/direct or transitive peers that are simply disconnected but still present in state.peers, which can keep stale model routes alive for up to 5 minutes instead of 2. I would default no-connection to strict unless the peer was previously observed as relay-only.

  • [P3] crates/skippy-runtime/src/lib.rs: the native log filter only honors GGML_LLAMA_LOG_LEVEL=4 for DEBUG, but still passes INFO/WARN/ERROR when the env is 0, 1, or 2. Since the callback is now responsible for filtering, silent, error, and warn settings remain ineffective. The filter should parse the threshold and apply it to all levels; CONT should ideally follow whether the previous base log line was emitted.

Validation note: git diff --check passed. I tried cargo test -p skippy-runtime native_log_filter, but it did not reach tests because this checkout has not prepared the llama.cpp static libraries: could not find native static library llama-common.

PR review (P2, James): when state.connections.get(peer_id) returns None
the old code in this PR defaulted is_relay_only to true, which extended
the 5-min relay grace to *any* peer without a live Connection object —
including previously-direct peers that simply got cleanly disconnected
(QUIC idle-expired, peer departed). That kept stale model routes alive
for up to 5 min instead of 2 for direct paths.

The lenient threshold exists to absorb mid-flap path renegotiation,
which only happens while iroh still owns the Connection. Once
Connection is gone, the peer should be judged by the strict (direct)
threshold so the eligible-peer set converges promptly.

Introduce classify_relay_only_for_policy(Option<bool>) so the
no-Connection default is testable in isolation. Live Connection still
gets is_relay_only_connection's path-set verdict (unchanged); only the
no-Connection fallback changes from lenient → strict.

Test: classify_relay_only_defaults_to_strict_when_no_connection covers
all three Option states.
Copilot AI review requested due to automatic review settings May 27, 2026 00:07

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Copilot reviewed 3 out of 3 changed files in this pull request and generated 3 comments.

Comment thread crates/mesh-llm-host-runtime/src/mesh/heartbeat.rs
Comment thread crates/skippy-runtime/src/lib.rs Outdated
Comment thread crates/skippy-runtime/src/lib.rs Outdated
@michaelneale
michaelneale requested a review from i386 May 27, 2026 00:45
Pulled at James's P3 feedback. The native log filter as shipped only
honors GGML_LLAMA_LOG_LEVEL=4 for DEBUG and ignores 0/1/2/3, so
values like silent / error / warn are silently ineffective. Fixing it
properly means parsing the env as a full threshold, deciding whether
to cache (Copilot's perf concern) and how CONT should behave when its
base line was filtered (James's part-b). That is a meaningful design
discussion in its own right and doesn't belong tacked onto the
heartbeat PR.

Reverts to byte-for-byte parity with main on crates/skippy-runtime/src/lib.rs
so #697 is unambiguously 'relay-only heartbeat grace + path-set
classification fix', nothing else. The log filter will land separately
once the threshold + CONT semantics are settled.

heartbeat fixes (relay-only grace bump + is_relay_only_connection
path-set classifier + classify_relay_only_for_policy strict-on-no-conn
default + recovery-message threshold) are unchanged.
@michaelneale michaelneale changed the title Relay-only heartbeat grace + skippy native DEBUG log filter Relay-only heartbeat grace + robust path-set classification May 27, 2026
@michaelneale
michaelneale merged commit fa52785 into main May 27, 2026
27 checks passed
@michaelneale
michaelneale deleted the micn/heartbeat-and-grammar-logs branch May 27, 2026 01:09
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants