Compare commits

...

4 Commits

Author SHA1 Message Date
Peter Steinberger
9b0d17c73e docs(bonjour): document gateway and iOS discovery logging 2025-12-14 04:34:26 +00:00
Peter Steinberger
0006ce1738 feat(ios): add discovery debug logs 2025-12-14 04:34:00 +00:00
Peter Steinberger
57bff61ab5 test(bonjour): cover watchdog and failure modes 2025-12-14 04:33:04 +00:00
Peter Steinberger
2ca9cad138 fix(bonjour): log advertise failures and watchdog 2025-12-14 04:33:00 +00:00
7 changed files with 488 additions and 11 deletions

View File

@ -8,6 +8,7 @@ import SwiftUI
final class BridgeConnectionController: ObservableObject {
@Published private(set) var bridges: [BridgeDiscoveryModel.DiscoveredBridge] = []
@Published private(set) var discoveryStatusText: String = "Idle"
@Published private(set) var discoveryDebugLog: [BridgeDiscoveryModel.DebugLogEntry] = []
private let discovery = BridgeDiscoveryModel()
private weak var appModel: NodeAppModel?
@ -19,6 +20,8 @@ final class BridgeConnectionController: ObservableObject {
self.appModel = appModel
BridgeSettingsStore.bootstrapPersistence()
self.discovery.setDebugLoggingEnabled(
UserDefaults.standard.bool(forKey: "bridge.discovery.debugLogs"))
self.discovery.$bridges
.sink { [weak self] newValue in
@ -32,11 +35,18 @@ final class BridgeConnectionController: ObservableObject {
self.discovery.$statusText
.assign(to: &self.$discoveryStatusText)
self.discovery.$debugLog
.assign(to: &self.$discoveryDebugLog)
if startDiscovery {
self.discovery.start()
}
}
func setDiscoveryDebugLoggingEnabled(_ enabled: Bool) {
self.discovery.setDebugLoggingEnabled(enabled)
}
func setScenePhase(_ phase: ScenePhase) {
switch phase {
case .background:

View File

@ -0,0 +1,69 @@
import SwiftUI
import UIKit
struct BridgeDiscoveryDebugLogView: View {
@EnvironmentObject private var bridgeController: BridgeConnectionController
@AppStorage("bridge.discovery.debugLogs") private var debugLogsEnabled: Bool = false
var body: some View {
List {
if !self.debugLogsEnabled {
Text("Enable “Discovery Debug Logs” to start collecting events.")
.foregroundStyle(.secondary)
}
if self.bridgeController.discoveryDebugLog.isEmpty {
Text("No log entries yet.")
.foregroundStyle(.secondary)
} else {
ForEach(self.bridgeController.discoveryDebugLog) { entry in
VStack(alignment: .leading, spacing: 2) {
Text(Self.formatTime(entry.ts))
.font(.caption)
.foregroundStyle(.secondary)
Text(entry.message)
.font(.callout)
.textSelection(.enabled)
}
.padding(.vertical, 4)
}
}
}
.navigationTitle("Discovery Logs")
.toolbar {
ToolbarItem(placement: .topBarTrailing) {
Button("Copy") {
UIPasteboard.general.string = self.formattedLog()
}
.disabled(self.bridgeController.discoveryDebugLog.isEmpty)
}
}
}
private func formattedLog() -> String {
self.bridgeController.discoveryDebugLog
.map { "\(Self.formatISO($0.ts)) \($0.message)" }
.joined(separator: "\n")
}
private static let timeFormatter: DateFormatter = {
let formatter = DateFormatter()
formatter.dateFormat = "HH:mm:ss"
return formatter
}()
private static let isoFormatter: ISO8601DateFormatter = {
let formatter = ISO8601DateFormatter()
formatter.formatOptions = [.withInternetDateTime, .withFractionalSeconds]
return formatter
}()
private static func formatTime(_ date: Date) -> String {
self.timeFormatter.string(from: date)
}
private static func formatISO(_ date: Date) -> String {
self.isoFormatter.string(from: date)
}
}

View File

@ -4,6 +4,12 @@ import Network
@MainActor
final class BridgeDiscoveryModel: ObservableObject {
struct DebugLogEntry: Identifiable, Equatable {
var id = UUID()
var ts: Date
var message: String
}
struct DiscoveredBridge: Identifiable, Equatable {
var id: String { self.stableID }
var name: String
@ -14,11 +20,26 @@ final class BridgeDiscoveryModel: ObservableObject {
@Published var bridges: [DiscoveredBridge] = []
@Published var statusText: String = "Idle"
@Published private(set) var debugLog: [DebugLogEntry] = []
private var browser: NWBrowser?
private var debugLoggingEnabled = false
private var lastStableIDs = Set<String>()
func setDebugLoggingEnabled(_ enabled: Bool) {
let wasEnabled = self.debugLoggingEnabled
self.debugLoggingEnabled = enabled
if !enabled {
self.debugLog = []
} else if !wasEnabled {
self.appendDebugLog("debug logging enabled")
self.appendDebugLog("snapshot: status=\(self.statusText) bridges=\(self.bridges.count)")
}
}
func start() {
if self.browser != nil { return }
self.appendDebugLog("start()")
let params = NWParameters.tcp
params.includePeerToPeer = true
let browser = NWBrowser(
@ -31,16 +52,25 @@ final class BridgeDiscoveryModel: ObservableObject {
switch state {
case .setup:
self.statusText = "Setup"
self.appendDebugLog("state: setup")
case .ready:
self.statusText = "Searching…"
self.appendDebugLog("state: ready")
case let .failed(err):
self.statusText = "Failed: \(err)"
self.appendDebugLog("state: failed (\(err))")
self.browser?.cancel()
self.browser = nil
case .cancelled:
self.statusText = "Stopped"
self.appendDebugLog("state: cancelled")
self.browser = nil
case let .waiting(err):
self.statusText = "Waiting: \(err)"
self.appendDebugLog("state: waiting (\(err))")
@unknown default:
self.statusText = "Unknown"
self.appendDebugLog("state: unknown")
}
}
}
@ -48,7 +78,7 @@ final class BridgeDiscoveryModel: ObservableObject {
browser.browseResultsChangedHandler = { [weak self] results, _ in
Task { @MainActor in
guard let self else { return }
self.bridges = results.compactMap { result -> DiscoveredBridge? in
let next = results.compactMap { result -> DiscoveredBridge? in
switch result.endpoint {
case let .service(name, _, _, _):
let decodedName = BonjourEscapes.decode(name)
@ -67,6 +97,16 @@ final class BridgeDiscoveryModel: ObservableObject {
}
}
.sorted { $0.name.localizedCaseInsensitiveCompare($1.name) == .orderedAscending }
let nextIDs = Set(next.map(\.stableID))
let added = nextIDs.subtracting(self.lastStableIDs)
let removed = self.lastStableIDs.subtracting(nextIDs)
if !added.isEmpty || !removed.isEmpty {
self.appendDebugLog(
"results: total=\(next.count) added=\(added.count) removed=\(removed.count)")
}
self.lastStableIDs = nextIDs
self.bridges = next
}
}
@ -75,12 +115,21 @@ final class BridgeDiscoveryModel: ObservableObject {
}
func stop() {
self.appendDebugLog("stop()")
self.browser?.cancel()
self.browser = nil
self.bridges = []
self.statusText = "Stopped"
}
private func appendDebugLog(_ message: String) {
guard self.debugLoggingEnabled else { return }
self.debugLog.append(DebugLogEntry(ts: Date(), message: message))
if self.debugLog.count > 200 {
self.debugLog.removeFirst(self.debugLog.count - 200)
}
}
private static func prettifyInstanceName(_ decodedName: String) -> String {
let normalized = decodedName.split(whereSeparator: \.isWhitespace).joined(separator: " ")
let stripped = normalized.replacingOccurrences(of: " (Clawdis)", with: "")

View File

@ -24,6 +24,7 @@ struct SettingsTab: View {
@AppStorage("bridge.manual.enabled") private var manualBridgeEnabled: Bool = false
@AppStorage("bridge.manual.host") private var manualBridgeHost: String = ""
@AppStorage("bridge.manual.port") private var manualBridgePort: Int = 18790
@AppStorage("bridge.discovery.debugLogs") private var discoveryDebugLogsEnabled: Bool = false
@StateObject private var connectStatus = ConnectStatusStore()
@State private var connectingBridgeID: String?
@State private var localIPAddress: String?
@ -151,6 +152,15 @@ struct SettingsTab: View {
+ "The bridge runs on the gateway (default port 18790).")
.font(.footnote)
.foregroundStyle(.secondary)
Toggle("Discovery Debug Logs", isOn: self.$discoveryDebugLogsEnabled)
.onChange(of: self.discoveryDebugLogsEnabled) { _, newValue in
self.bridgeController.setDiscoveryDebugLoggingEnabled(newValue)
}
NavigationLink("Discovery Logs") {
BridgeDiscoveryDebugLogView()
}
}
}
}

View File

@ -44,6 +44,27 @@ Useful built-in tools:
If browsing shows instances but resolving fails, youre usually hitting a LAN policy / multicast issue.
## Debugging in Gateway logs
The Gateway writes a rolling log file (printed on startup as `gateway log file: ...`).
Look for `bonjour:` lines, especially:
- `bonjour: advertise failed ...` (probing/announce failure)
- `bonjour: ... name conflict resolved` / `hostname conflict resolved`
- `bonjour: watchdog detected non-announced service; attempting re-advertise ...` (self-heal attempt after sleep/interface churn)
## Debugging on iOS (Iris)
Iris discovers bridges via `NWBrowser` browsing `_clawdis-bridge._tcp`.
To capture what the browser is doing:
- Settings → Bridge → Advanced → enable **Discovery Debug Logs**
- Settings → Bridge → Advanced → open **Discovery Logs** → reproduce the “Searching…” / “No bridges found” case → **Copy**
The log includes browser state transitions (`ready`, `waiting`, `failed`, `cancelled`) and result-set changes (added/removed counts).
## Common failure modes
- **Bonjour doesnt cross networks**: London/Vienna style setups require Tailnet (MagicDNS/IP) or SSH.

View File

@ -5,6 +5,26 @@ import { afterEach, describe, expect, it, vi } from "vitest";
const createService = vi.fn();
const shutdown = vi.fn();
const logWarn = vi.fn();
const logDebug = vi.fn();
const getLoggerInfo = vi.fn();
vi.mock("../logger.js", () => {
return {
logWarn: (message: string) => logWarn(message),
logDebug: (message: string) => logDebug(message),
logInfo: vi.fn(),
logError: vi.fn(),
logSuccess: vi.fn(),
};
});
vi.mock("../logging.js", () => {
return {
getLogger: () => ({ info: (...args: unknown[]) => getLoggerInfo(...args) }),
};
});
vi.mock("@homebridge/ciao", () => {
return {
Protocol: { TCP: "tcp" },
@ -34,8 +54,13 @@ describe("gateway bonjour advertiser", () => {
for (const [key, value] of Object.entries(prevEnv)) {
process.env[key] = value;
}
createService.mockReset();
shutdown.mockReset();
logWarn.mockReset();
logDebug.mockReset();
getLoggerInfo.mockReset();
vi.useRealTimers();
vi.restoreAllMocks();
});
@ -53,7 +78,19 @@ describe("gateway bonjour advertiser", () => {
setTimeout(resolve, 250);
}),
);
createService.mockReturnValue({ advertise, destroy });
createService.mockImplementation((options: Record<string, unknown>) => {
return {
advertise,
destroy,
serviceState: "announced",
on: vi.fn(),
getFQDN: () =>
`${String(options.type ?? "service")}.${String(options.domain ?? "local")}.`,
getHostname: () => String(options.hostname ?? "unknown"),
getPort: () => Number(options.port ?? -1),
};
});
const started = await startGatewayBonjourAdvertiser({
gatewayPort: 18789,
@ -96,6 +133,141 @@ describe("gateway bonjour advertiser", () => {
expect(shutdown).toHaveBeenCalledTimes(1);
});
it("attaches conflict listeners for services", async () => {
// Allow advertiser to run in unit tests.
delete process.env.VITEST;
process.env.NODE_ENV = "development";
vi.spyOn(os, "hostname").mockReturnValue("test-host");
const destroy = vi.fn().mockResolvedValue(undefined);
const advertise = vi.fn().mockResolvedValue(undefined);
const onCalls: Array<{ event: string }> = [];
createService.mockImplementation((options: Record<string, unknown>) => {
const on = vi.fn((event: string) => {
onCalls.push({ event });
});
return {
advertise,
destroy,
serviceState: "announced",
on,
getFQDN: () =>
`${String(options.type ?? "service")}.${String(options.domain ?? "local")}.`,
getHostname: () => String(options.hostname ?? "unknown"),
getPort: () => Number(options.port ?? -1),
};
});
const started = await startGatewayBonjourAdvertiser({
gatewayPort: 18789,
sshPort: 2222,
bridgePort: 18790,
});
// 2 services × 2 listeners each
expect(onCalls.map((c) => c.event)).toEqual([
"name-change",
"hostname-change",
"name-change",
"hostname-change",
]);
await started.stop();
});
it("logs advertise failures and retries via watchdog", async () => {
// Allow advertiser to run in unit tests.
delete process.env.VITEST;
process.env.NODE_ENV = "development";
vi.useFakeTimers();
vi.spyOn(os, "hostname").mockReturnValue("test-host");
const destroy = vi.fn().mockResolvedValue(undefined);
const advertise = vi
.fn()
.mockRejectedValueOnce(new Error("boom")) // initial advertise fails
.mockResolvedValue(undefined); // watchdog retry succeeds
createService.mockImplementation((options: Record<string, unknown>) => {
return {
advertise,
destroy,
serviceState: "unannounced",
on: vi.fn(),
getFQDN: () =>
`${String(options.type ?? "service")}.${String(options.domain ?? "local")}.`,
getHostname: () => String(options.hostname ?? "unknown"),
getPort: () => Number(options.port ?? -1),
};
});
const started = await startGatewayBonjourAdvertiser({
gatewayPort: 18789,
sshPort: 2222,
bridgePort: 0,
});
// initial advertise attempt happens immediately
expect(advertise).toHaveBeenCalledTimes(1);
// allow promise rejection handler to run
await Promise.resolve();
expect(logWarn).toHaveBeenCalledWith(
expect.stringContaining("advertise failed"),
);
// watchdog should attempt re-advertise at the 60s interval tick
await vi.advanceTimersByTimeAsync(60_000);
expect(advertise).toHaveBeenCalledTimes(2);
await started.stop();
await vi.advanceTimersByTimeAsync(120_000);
expect(advertise).toHaveBeenCalledTimes(2);
});
it("handles advertise throwing synchronously", async () => {
// Allow advertiser to run in unit tests.
delete process.env.VITEST;
process.env.NODE_ENV = "development";
vi.spyOn(os, "hostname").mockReturnValue("test-host");
const destroy = vi.fn().mockResolvedValue(undefined);
const advertise = vi.fn(() => {
throw new Error("sync-fail");
});
createService.mockImplementation((options: Record<string, unknown>) => {
return {
advertise,
destroy,
serviceState: "unannounced",
on: vi.fn(),
getFQDN: () =>
`${String(options.type ?? "service")}.${String(options.domain ?? "local")}.`,
getHostname: () => String(options.hostname ?? "unknown"),
getPort: () => Number(options.port ?? -1),
};
});
const started = await startGatewayBonjourAdvertiser({
gatewayPort: 18789,
sshPort: 2222,
bridgePort: 0,
});
expect(advertise).toHaveBeenCalledTimes(1);
expect(logWarn).toHaveBeenCalledWith(
expect.stringContaining("advertise threw"),
);
await started.stop();
});
it("normalizes hostnames with domains for service names", async () => {
// Allow advertiser to run in unit tests.
delete process.env.VITEST;
@ -105,7 +277,18 @@ describe("gateway bonjour advertiser", () => {
const destroy = vi.fn().mockResolvedValue(undefined);
const advertise = vi.fn().mockResolvedValue(undefined);
createService.mockReturnValue({ advertise, destroy });
createService.mockImplementation((options: Record<string, unknown>) => {
return {
advertise,
destroy,
serviceState: "announced",
on: vi.fn(),
getFQDN: () =>
`${String(options.type ?? "service")}.${String(options.domain ?? "local")}.`,
getHostname: () => String(options.hostname ?? "unknown"),
getPort: () => Number(options.port ?? -1),
};
});
const started = await startGatewayBonjourAdvertiser({
gatewayPort: 18789,

View File

@ -1,5 +1,8 @@
import os from "node:os";
import { logDebug, logWarn } from "../logger.js";
import { getLogger } from "../logging.js";
export type GatewayBonjourAdvertiser = {
stop: () => Promise<void>;
};
@ -32,8 +35,45 @@ function prettifyInstanceName(name: string) {
type BonjourService = {
advertise: () => Promise<void>;
destroy: () => Promise<void>;
getFQDN: () => string;
getHostname: () => string;
getPort: () => number;
on: (event: string, listener: (...args: unknown[]) => void) => unknown;
serviceState: string;
};
function formatBonjourError(err: unknown): string {
if (err instanceof Error) {
const msg = err.message || String(err);
return err.name && err.name !== "Error" ? `${err.name}: ${msg}` : msg;
}
return String(err);
}
function serviceSummary(label: string, svc: BonjourService): string {
let fqdn = "unknown";
let hostname = "unknown";
let port = -1;
try {
fqdn = svc.getFQDN();
} catch {
// ignore
}
try {
hostname = svc.getHostname();
} catch {
// ignore
}
try {
port = svc.getPort();
} catch {
// ignore
}
const state =
typeof svc.serviceState === "string" ? svc.serviceState : "unknown";
return `${label} fqdn=${fqdn} host=${hostname} port=${port} state=${state}`;
}
export async function startGatewayBonjourAdvertiser(
opts: GatewayBonjourAdvertiseOpts,
): Promise<GatewayBonjourAdvertiser> {
@ -72,7 +112,7 @@ export async function startGatewayBonjourAdvertiser(
txtBase.tailnetDns = opts.tailnetDns.trim();
}
const services: BonjourService[] = [];
const services: Array<{ label: string; svc: BonjourService }> = [];
// Master beacon: used for discovery (auto-fill SSH/direct targets).
// We advertise a TCP service so clients can resolve the host; the port itself is informational.
@ -88,7 +128,10 @@ export async function startGatewayBonjourAdvertiser(
sshPort: String(opts.sshPort ?? 22),
},
});
services.push(master);
services.push({
label: "master",
svc: master as unknown as BonjourService,
});
// Optional bridge beacon (same type used by Iris/iOS today).
if (typeof opts.bridgePort === "number" && opts.bridgePort > 0) {
@ -104,21 +147,113 @@ export async function startGatewayBonjourAdvertiser(
transport: "bridge",
},
});
services.push(bridge);
services.push({
label: "bridge",
svc: bridge as unknown as BonjourService,
});
}
logDebug(
`bonjour: starting (hostname=${hostname}, instance=${JSON.stringify(
safeServiceName(instanceName),
)}, gatewayPort=${opts.gatewayPort}, bridgePort=${opts.bridgePort ?? 0}, sshPort=${
opts.sshPort ?? 22
})`,
);
for (const { label, svc } of services) {
try {
svc.on("name-change", (name: unknown) => {
const next = typeof name === "string" ? name : String(name);
logWarn(
`bonjour: ${label} name conflict resolved; newName=${JSON.stringify(next)}`,
);
});
svc.on("hostname-change", (nextHostname: unknown) => {
const next =
typeof nextHostname === "string"
? nextHostname
: String(nextHostname);
logWarn(
`bonjour: ${label} hostname conflict resolved; newHostname=${JSON.stringify(next)}`,
);
});
} catch (err) {
logDebug(
`bonjour: failed to attach listeners for ${label}: ${String(err)}`,
);
}
}
// Do not block gateway startup on mDNS probing/announce. Advertising can take
// multiple seconds depending on network state; the gateway should come up even
// if Bonjour is slow or fails.
for (const svc of services) {
void svc.advertise().catch(() => {
/* ignore */
});
for (const { label, svc } of services) {
try {
void svc
.advertise()
.then(() => {
// Keep this out of stdout/stderr (menubar + tests) but capture in the rolling log.
getLogger().info(`bonjour: advertised ${serviceSummary(label, svc)}`);
})
.catch((err) => {
logWarn(
`bonjour: advertise failed (${serviceSummary(label, svc)}): ${formatBonjourError(err)}`,
);
});
} catch (err) {
logWarn(
`bonjour: advertise threw (${serviceSummary(label, svc)}): ${formatBonjourError(err)}`,
);
}
}
// Watchdog: if we ever end up in an unannounced state (e.g. after sleep/wake or
// interface churn), try to re-advertise instead of requiring a full gateway restart.
const lastRepairAttempt = new Map<string, number>();
const watchdog = setInterval(() => {
for (const { label, svc } of services) {
const stateUnknown = (svc as { serviceState?: unknown }).serviceState;
if (typeof stateUnknown !== "string") continue;
if (stateUnknown === "announced" || stateUnknown === "announcing")
continue;
let key = label;
try {
key = `${label}:${svc.getFQDN()}`;
} catch {
// ignore
}
const now = Date.now();
const last = lastRepairAttempt.get(key) ?? 0;
if (now - last < 30_000) continue;
lastRepairAttempt.set(key, now);
logWarn(
`bonjour: watchdog detected non-announced service; attempting re-advertise (${serviceSummary(
label,
svc,
)})`,
);
try {
void svc.advertise().catch((err) => {
logWarn(
`bonjour: watchdog advertise failed (${serviceSummary(label, svc)}): ${formatBonjourError(err)}`,
);
});
} catch (err) {
logWarn(
`bonjour: watchdog advertise threw (${serviceSummary(label, svc)}): ${formatBonjourError(err)}`,
);
}
}
}, 60_000);
watchdog.unref?.();
return {
stop: async () => {
for (const svc of services) {
clearInterval(watchdog);
for (const { svc } of services) {
try {
await svc.destroy();
} catch {