Probing failures spam console.log every 2s (breaks quiet-console consumers)

[steve02081504]

Problem

When probing fails with socket errors, @homebridge/ciao logs repeatedly via console.log:

[fount._http._tcp.local.] failed probing with reason: Error: Probing failed as of socket errors!. Trying again in 2 seconds!

Source: lib/Responder.js (around the failed probing with reason path). The same pattern exists for announcing (failed announcing with reason).

There is no documented way for consumers to:

1. suppress or redirect these operational retry logs, or
2. distinguish transient probe retries from fatal advertise failures without scraping console.log.

Why this matters

fount (https://github.com/steve02081504/fount) advertises an HTTP service with ciao on default fount server starts. Our live regression asserts that a fresh default start produces no console output for 10s. On Windows (and likely other hosts where multicast/UDP bind is flaky), ciao's retry console.log fails that invariant even though the HTTP server itself is healthy and we already handle advertise rejection via advertise().catch(...).

Expected

Prefer one of:

• route operational retries through a pluggable logger / debug flag (default quiet or debug-level),
• emit a typed event for probe/announce retries instead of (or in addition to) console.log,
• rate-limit / log-once for repeated identical socket probe failures.

Environment

• @homebridge/ciao 1.3.10 (also seen on 1.3.9)
• Windows 10 / Deno consumers importing npm:@homebridge/ciao
• Message text: Probing failed as of socket errors!

Ask

Is there an existing quiet/logger API we missed? If not, would you accept a PR to stop spamming console.log on transient probe retries?

[steve02081504]

Downstream impact (fount)

Repo: https://github.com/steve02081504/fount

How we use ciao today

src/server/web_server/mdns.mjs imports npm:@homebridge/ciao, getResponder().createService(...), then advertise(). On advertise rejection we fall back to bonjour-service. Under FOUNT_TEST we already listen to name-change / hostname-change to avoid unhandled-event warnings — that does not silence probe-retry console.logs.

Broken check

src/server/test/live/console_quiet.test.mjs launches a real default-start node and asserts node.takeOutput() === '' after 10s. Transient ciao probe retries fail server:live, which then blocks all shell frontend/integration suites that dependsOn: server:live (Chat / Social / Cabinet Playwright, etc.).

After a fix lands

1. Bump @homebridge/ciao in fount (Deno URL/npm: import — no lockfile).
2. Re-run fount test --force --no-parallel server:live.
3. Confirm no failed probing with reason lines in the live log; then re-run blocked shell frontend suites.

No fount code change should be required if retries become quiet-by-default or event-based; if a logger flag is required, wire it in mdns.mjs only.

[steve02081504]

Hit again (2026-07-31)

fount test --no-parallel shells/social:frontend pulled server:live after a server error-handler change. console_quiet failed within 10s with repeated:

```n
Still blocks Social/Chat/Cabinet frontend via `dependsOn: server:live`. No fount workaround applied — waiting on a quiet probe-retry path in ciao (see prior comment for post-fix steps).

[bwp91]

Good catch, and you're right that this is the wrong level. A probe retry is self-healing — ciao tries again in 2 seconds and usually succeeds — so it isn't something you can act on, and putting it on the console every 2 seconds forever is just noise.

No quiet/logger API that you missed, sorry. ciao already uses the debug package internally, so that's where these have gone rather than adding new configuration.

Changed in @homebridge/ciao@1.3.11-beta.1:

• failed probing with reason: ... → debug
• failed announcing with reason: ... → debug
• the underlying Failed to send probe queries / Failed to send announcement requests → debug (those were reporting the same failure a second time)

Terminal failures still go to the console, so this isn't trading spam for silence — giving up advertising after retry and the FATAL handlers are untouched. DEBUG=ciao:* brings all the retry detail back when you want it.

One thing worth checking your end: if the underlying socket problem surfaces, MDNSServer will still report it — Encountered MDNS socket error on socket '...' or Warning: no IPv4 address available on .... That's on purpose, since a genuinely broken socket is worth knowing about, and it fires once rather than every 2 seconds. If console_quiet still trips on one of those on Windows, let me know which line and I'll look again — a one-shot message needs a different answer to the retry loop.

Could you give the beta a go?

npm install @homebridge/ciao@1.3.11-beta.1

No PR needed for this, but thanks for offering. If you'd still like to contribute, the more interesting gap is the one you hinted at — a typed event for advertise failure, so consumers can react rather than scrape logs. That's a bigger API question, but I'd happily read a proposal.

[steve02081504]

Thanks — confirmed on our side with @homebridge/ciao@1.3.11-beta.1 (Windows / Deno npm: import).

What we checked

• Source: probe/announce retry paths (failed probing…, failed announcing…, and the matching Failed to send probe/announcement… lines) are on debug, while giving up advertising after retry stays on console.error. Matches what you described.
• Live advertise for ~12s: no console.log spam for those retries. In this run probing actually succeeded (no socket-error retry loop today), and we also did not see the one-shot Encountered MDNS socket error… / Warning: no IPv4 address… lines.

Beta caveat for quiet-console consumers
Beta builds still auto-enable ciao:* in printInitInfo() when version.includes("beta"), so stderr is full of ciao debug even with DEBUG unset. That would still trip our console_quiet live check if we pinned the beta as-is. Fine for this beta — we'll bump on the stable release (or once that auto-enable is beta-only and gone from the shipped version).

No need for a PR from us on the retry noise. A typed advertise-failure event is still interesting for reacting without log scraping; happy to sketch a proposal later if useful. Appreciate the quick fix.

[bwp91]

Thanks for going through it properly, and for the beta caveat — you're right, and it's worse than you put it.

That auto-enable at the top of index.ts turns on ciao:* wholesale, which includes the very namespaces the retry messages just moved to. So on a beta build those lines still reach stderr. Your run was quiet because probing genuinely succeeded, not because the change suppressed anything — if you had hit the socket-error loop on 1.3.11-beta.1, you would have seen the same chatter as before, just on stderr rather than stdout.

Which makes that block actively unhelpful: it renders the quiet path untestable on exactly the builds people test with. Not what I want.

The other half of the problem is that there is no way to decline it. The check is if (!debug), and an empty string is falsy, so DEBUG= reads identically to DEBUG being unset — you get the full firehose either way. I'll make an explicitly-set-but-empty DEBUG mean "no thanks", which gives you a way to pin a beta and stay quiet without me having to strip the auto-enable altogether (it earns its keep when someone reports a beta problem and the useful log is already there).

Waiting for the stable is a perfectly sensible call in the meantime — the retry fix behaves as described on any build whose version doesn't contain beta.

And yes, please do sketch the typed advertise-failure event when you have a moment. Reacting to a failure without scraping logs is the right shape for it; the part I'd want to get right is what the consumer is expected to do with it, given ciao retries on its own and there's currently no terminal "this will never work" state for probing.

[steve02081504]

Thanks — tried @homebridge/ciao@1.3.11-beta.2 (Windows, both Deno npm: and Node).

Retry → debug looks good. No more console.log probe/announce spam on the old path. Terminal failures still go to console as described.

DEBUG= opt-out does not work yet. Reproduced on Node and Deno:

1. Start with DEBUG= (explicit empty) or process.env.DEBUG = "" before loading ciao.
2. index.js does require("debug") / import createDebug from "debug" before reading process.env.DEBUG for prereleaseDebugNamespaces.
3. debug initializes with createDebug.enable(createDebug.load()). Empty DEBUG is falsy, so save("") deletes process.env.DEBUG (debug/src/node.js).
4. Ciao then sees DEBUG as unset → enables ciao:* anyway.

Probe at the decision site under Node with DEBUG= set:

{ "__dbgType": "undefined", "__dbgHas": false, "prereleaseNamespaces": "ciao:*" }

The helper itself is fine ("" → null); the value is gone by the time it runs.

Likely fix: snapshot before loading debug:

const debugEnv = process.env.DEBUG; // capture before debug deletes empty
import createDebug from "debug";
// ...
prereleaseDebugNamespaces(version, debugEnv, !!process.env.BCT);

(Or a dedicated opt-out like CIAO_DEBUG=0 / DEBUG=-ciao, which survives debug's empty-env cleanup.)

Until that lands, waiting for stable remains the right call for quiet-console consumers — stable has no beta auto-enable, so the retry-on-debug change is enough.

Typed advertise-failure event (sketch, consumer side): for fount we do not need per-retry events. ciao already self-heals probes; we only need a signal when advertise is no longer worth waiting on so we can fall back (we already advertise().catch(...) → bonjour-service). Useful shape would be a terminal-ish event (or a rejected/settled advertise path) with { reason, serviceName, willRetry: false } — not every 2s probe miss. If probing has no true terminal state today, even a rate-limited advertise-degraded after N consecutive socket failures would beat log scraping; we would treat that as "try fallback / surface once," not as a hard kill of the HTTP server.

[bwp91]

Spot on, and thanks for the probe output — that made it obvious. I reproduced it here before changing anything:

before require, DEBUG is ""
after  require, DEBUG is "ciao:*"
is ciao:* enabled -> true

Your chain is exactly right. debug's save() does delete process.env.DEBUG for any falsy value, that runs as debug initialises, and the import of debug is hoisted above the code that reads the variable. The helper never saw "" — it was already gone.

One thing worth flagging: the fix as you sketched it wouldn't have worked either. A const debugEnv = process.env.DEBUG written above the import still ends up below it, because TypeScript emits all the requires first regardless of where the statement sits. It has to be a separate module that is imported earlier — which is what 1.3.11-beta.3 now does.

You can unblock right now, without waiting for anything

debug's own negation syntax survives all of this, because a non-empty value never gets deleted. All three of these already worked on beta-2:

DEBUG=-ciao*
DEBUG=-ciao:*

Both leave every ciao namespace disabled. If that suits your console_quiet check, you don't need a new release at all.

Fixed properly in 1.3.11-beta.3

Verified against the published package rather than the source:

DEBUG	ciao debug
unset	enabled — beta reports still carry their logs
empty	disabled
express:*	ciao enabled and express enabled — appended, not replaced

The fix hangs on one import sitting above another, which nothing in a test suite would normally notice, so there's now a test asserting that ordering directly. It looks like an odd test; it exists because this bug is exactly what happens when it slips.

On the event

That's a much more useful shape than I was expecting, and the willRetry: false framing is the part that helps. You're right that per-retry events are noise — you want "stop waiting for this", not "another probe missed".

The honest problem is that the state you want doesn't exist yet: probing recurses every 2s forever, so there's nothing that currently decides advertising has failed for good. So it isn't a case of exposing something internal, it's deciding what "given up" means — and advertise-degraded after N consecutive socket failures is a reasonable answer, precisely because it doesn't require inventing a hard terminal state.

Happy to take a proposal on that whenever suits. No rush, and thanks for testing each of these so thoroughly — it has caught two real things now.

[steve02081504]

Confirmed on @homebridge/ciao@1.3.11-beta.3 and 1.3.11-beta.4 (Windows, Node + Deno npm:).

DEBUG= opt-out

DEBUG	ciao:init
unset	enabled (beta auto-enable)
empty	disabled
-ciao* / -ciao:*	disabled
express:*	express:*,ciao:* (appended)

Matches your table. The separate early-capture module is the right shape — importing debug before ciao in a probe script re-creates the old “empty looks unset” failure, which is a good reminder of why that import-order test exists.

Advertise quiet

With DEBUG= (and separately DEBUG=-ciao*), a 5s advertise on beta.4 produced no console.log / console.error / console.warn lines on our side (probe/announce retries stay on debug as intended).

Downstream

For fount we still prefer bumping on the stable release (no beta auto-enable in the default path). DEBUG=-ciao* / DEBUG= are enough if we ever need to pin a beta for a quiet-console check. Deno’s default 24h minimum dependency age also blocks brand-new npm publishes until they age in — not a ciao bug, just noting it so a “couldn’t resolve beta.N” report from a Deno consumer isn’t mistaken for a registry miss.

Event

Agreed on advertise-degraded after N consecutive socket failures as the practical “stop waiting / try fallback” signal without inventing a hard terminal probe state. Happy to sketch that when useful; no rush — quiet retries already unblock us.

[bwp91]

That table is exactly what I wanted to see, thank you — particularly the express:* row, since the append behaviour is the one people trip over when they only ever set DEBUG for something unrelated.

Good catch on the probe script too. Importing debug before ciao reproducing the old "empty looks unset" failure is precisely why the early capture lives in its own module with an import-order test around it — it is the kind of thing that regresses silently the moment someone tidies the imports.

On timing: staying on stable for fount is the right call, and there is no beta auto-enable in that path, so there is nothing to work around. The Deno 24-hour minimum dependency age is genuinely useful to know. I would not have connected a "couldn't resolve beta.N" report to that, so thanks for writing it down somewhere it will be found.

On advertise-degraded — I think you have the shape right. A hard terminal probe state would be wrong, because probing legitimately retries for a long time on a busy network, whereas "N consecutive socket failures" is an observation rather than a verdict, and an observation is what a consumer actually needs in order to decide whether to fall back.

Two things I would want to settle before committing to it: what N should be, and whether the event carries the underlying error or just the count. So I am not promising it for this release. A sketch would be welcome whenever you feel like writing one, with no urgency at all, given the quiet retries already unblock you.