Skip to content

fix: keep re-querying unresolved instances while browsing (#493) - #494

Open
keepsimple1 wants to merge 2 commits into
mainfrom
fix/issue-493
Open

fix: keep re-querying unresolved instances while browsing (#493)#494
keepsimple1 wants to merge 2 commits into
mainfrom
fix/issue-493

Conversation

@keepsimple1

Copy link
Copy Markdown
Owner

Fixes #493

Suspected cause:

Resolution of a found instance is driven by a per-instance Command::Resolve retry chain that fires every 500 ms but gives up after max_try (3) tries (~1.5 s). The only remaining path to resolution is an unsolicited or browse-elicited cache update.

Fix:

Drive follow-up SRV/address queries off the browse retransmission cycle instead of relying solely on the fast-path chain:

Also clear pending_resolves when the fast-path Resolve chain ends (resolved or gave up), so the set honestly means "a Resolve chain is in flight" and the fast path can re-arm if new partial records arrive.

When a service type has many instances, ServiceFound fires for all of
them immediately but many were never resolved: the per-instance
Command::Resolve retry chain gives up after max_try (3) tries, and
because the instance stayed in `pending_resolves`, add_pending_resolve
would never re-arm it. The only remaining resolution path was an
unsolicited/browse-elicited cache update, which trickles in about one
instance per query cycle on a lossy or IPv6-only network. Instances
whose SRV/address answers were lost during those first ~1.5s could stay
unresolved indefinitely.

Fix: drive follow-up SRV/address queries off the browse retransmission
cycle. `query_unresolved_instances` sweeps the PTR cache for the type
(minus already-resolved instances) and re-queries each, so a pending
instance keeps being queried for as long as the browse is active. This
inherits the browse's exponential backoff, so it never stalls yet also
never becomes a fixed-interval query storm.

Also clear `pending_resolves` when the fast-path Resolve chain ends
(resolved or gave up), so the set honestly means "a Resolve chain is in
flight" and the fast path can re-arm if new partial records arrive.

Adds test_unresolved_instance_not_stranded: a hand-rolled responder
announces PTR+SRV with a separate SRV target hostname, withholds the
address, and only answers after more than max_try address queries have
arrived. Before the fix the daemon goes silent after 3 tries and the
instance is never resolved; after the fix the browse cycle keeps
querying and it resolves.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
@hemanpa

hemanpa commented Aug 20, 2026

Copy link
Copy Markdown

Thanks for the quick turnaround — the diagnosis matches what we saw exactly (resolutions arriving right after a SearchStarted, i.e. only via browse-elicited cache updates once the fast-path chain had given up).

What I can and can't give you: I don't have the failing network. The report came from a downstream user of ours (phunapps/matter-rust#113) whose LAN has ~18 instances of one service type; on mine everything resolves in well under a second, so I can only offer no-regression evidence, not confirmation of the fix. He's away until next week and I've asked him to build against the branch — his run is the one that actually tests it.

Tested fix/issue-493 @ abf910f8 on a healthy network

Raspberry Pi, Debian, avahi-daemon also running, 16 _matter._tcp instances on the LAN (a mix of IPv4/IPv6 and IPv6-only Thread devices behind a border router).

Before (0.20.2) and after the patch, identical results:

unpatched fix/issue-493
base-type browse, 15 s 16 resolved 16 resolved
subtype browse alone, 12 s 1 resolved 1 resolved
subtype + base concurrently 1 / 16 1 / 16

Also exercised through our full stack rather than just a probe: a real Matter controller resolving an operational record and reconnecting to a Thread device, then a 204-attribute read over that session — both fine.

So: no regression observed, and nothing got slower.

Two incidental notes that might be useful:

  • I had to bump our requirement from 0.20 to 0.21 for the [patch.crates-io] to apply, so this also exercised 0.21 against our adapter. It compiled and behaved identically — no changes needed on our side for the packet-size or re-exported-error-type changes.
  • One thing we discovered while working around this, in case it's relevant to the fix's shape: browsing a subtype resolves promptly on the affected network (~266 ms for 3 instances) while the base type stalls, but opening both concurrently re-stalls it — consistent with the bottleneck being per-instance resolution work shared across browses rather than anything per-browse. If your fix makes that distinction disappear, that'd be a good confirmation signal.

Happy to run anything else here, and I'll relay the result from the affected network as soon as I have it.

@qwandor

qwandor commented Aug 25, 2026

Copy link
Copy Markdown

This doesn't seem to fix the issue for me; the services still aren't resolved. Output from the example with this patch:

$ cargo run --example query _matter._tcp
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.08s
     Running `target/debug/examples/query _matter._tcp`
At 322.876µs: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 13.792422ms: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 224.930145ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000006EC96BF5._matter._tcp.local.")
At 225.091947ms: Resolved a new service: 2C755BDFDBFDF8A2-000000006EC96BF5._matter._tcp.local.
 host: ECDA3B081E84.local.
 port: 5540
 Address: fe80::eeda:3bff:fe08:1e84%wlp170s0
 Address: 192.168.86.28
 Address: fd96:7000:b73c:b0d9:eeda:3bff:fe08:1e84
 Property: SII=5000
 Property: SAI=300
 Property: T=1
At 424.536303ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-0000000000840C83._matter._tcp.local.")
At 424.738403ms: Resolved a new service: 2C755BDFDBFDF8A2-0000000000840C83._matter._tcp.local.
 host: 14C14EDFB074.local.
 port: 5540
 Address: 192.168.86.80
 Address: fd96:7000:b73c:b0d9:f0ad:7509:cc30:7540
 Address: fd96:7000:b73c:b0d9:1015:5f20:59ee:7c33
 Address: fd96:7000:b73c:b0d9:daad:d595:6447:661e
 Address: fe80::4de2:ea09:ee05:7dda%wlp170s0
At 429.779238ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.")
At 429.815353ms: Resolved a new service: 2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.
 host: F4F5D8C0DCE6.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:514b:d2cc:dd6b:1f47
At 429.989705ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000DFCB37CC._matter._tcp.local.")
At 430.25769ms: Resolved a new service: 2C755BDFDBFDF8A2-00000000DFCB37CC._matter._tcp.local.
 host: 3C8D20E19E8E.local.
 port: 5540
 Address: 192.168.86.78
 Address: fd96:7000:b73c:b0d9:ad84:5968:6560:c59e
 Address: fd96:7000:b73c:b0d9:8672:ffad:c05e:da64
 Address: fe80::2425:600b:ae14:e74f%wlp170s0
 Address: fd96:7000:b73c:b0d9:702d:5ec1:c633:fb04
 Address: fd96:7000:b73c:b0d9:858e:3c93:fe2:2ce
At 1.014615104s: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 1.245053545s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000F25EF2E4._matter._tcp.local.")
At 1.245089656s: ServiceFound("_matter._tcp.local.", "9B5791331E047398-000000000000012C._matter._tcp.local.")
At 1.24530232s: Resolved a new service: 9B5791331E047398-000000000000012C._matter._tcp.local.
 host: ECDA3BA61A1C.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:eeda:3bff:fea6:1a1c
 Address: 192.168.86.35
 Address: fe80::eeda:3bff:fea6:1a1c%wlp170s0
 Property: SII=5000
 Property: SAI=300
 Property: T=1
At 1.245385057s: Resolved a new service: 2C755BDFDBFDF8A2-00000000F25EF2E4._matter._tcp.local.
 host: ECDA3BA61A1C.local.
 port: 5540
 Address: 192.168.86.35
 Address: fd96:7000:b73c:b0d9:eeda:3bff:fea6:1a1c
 Address: fe80::eeda:3bff:fea6:1a1c%wlp170s0
 Property: SII=5000
 Property: SAI=300
 Property: T=1
At 3.015204352s: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 7.017296384s: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 15.017860472s: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 15.17547225s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000AAB08AA7._matter._tcp.local.")
At 15.1755166s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000056BB72A._matter._tcp.local.")
At 15.175522847s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000000BD7BD08._matter._tcp.local.")
At 15.175528484s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-0000000077A6EFB7._matter._tcp.local.")
At 15.175533448s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000009B2EEF43._matter._tcp.local.")
At 15.175537853s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000004D852B21._matter._tcp.local.")
At 15.175542609s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000642B4839._matter._tcp.local.")
At 15.175547271s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-FFFF000000000000._matter._tcp.local.")
At 15.175551993s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-0000000061817431._matter._tcp.local.")
At 15.175564314s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000004192B362._matter._tcp.local.")
At 15.175573986s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000F8CD79FE._matter._tcp.local.")
At 15.175586781s: ServiceFound("_matter._tcp.local.", "9B5791331E047398-000000000000012D._matter._tcp.local.")
At 15.175596404s: ServiceFound("_matter._tcp.local.", "9B5791331E047398-000000000000012E._matter._tcp.local.")
At 15.175605421s: ServiceFound("_matter._tcp.local.", "F52AC107C954E38E-0000000000000002._matter._tcp.local.")
At 15.175614766s: ServiceFound("_matter._tcp.local.", "F52AC107C954E38E-0000000000000003._matter._tcp.local.")
At 15.175624377s: ServiceFound("_matter._tcp.local.", "F52AC107C954E38E-0000000000000004._matter._tcp.local.")
At 15.175633707s: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000007D343903._matter._tcp.local.")
At 31.018788961s: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")
At 63.019268572s: SearchStarted("_matter._tcp.local. on 2 interfaces [wlp170s0 (2), lo (1)]")

@keepsimple1

Copy link
Copy Markdown
Owner Author

@qwandor Thanks for running the test! I couldn't pin down what was not working. I've updated the diff to have a better backoff timer for the fast path query.

Could you please try it again with the latest diff and also enable debugs? something like:
RUST_LOG=mdns_sd=debug cargo run --example query _matter._tcp

@qwandor

qwandor commented Aug 26, 2026

Copy link
Copy Markdown

Sure, here you go, on b255dde:

$ RUST_LOG=mdns_sd=debug cargo run --example query _matter._tcp
   Compiling mdns-sd v0.21.0 (/home/andrew/src/mdns-sd)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1.18s
     Running `target/debug/examples/query _matter._tcp`
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] join multicast group V4 on lo addr 127.0.0.1
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] join multicast group V4 on wlp170s0 addr 192.168.86.185
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] join multicast group V6 on lo addr ::1 with index 1
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] join multicast group V6 on wlp170s0 addr fd96:7000:b73c:b0d9:3091:b46b:8cfe:8896 with index 2
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] join multicast group V6 on wlp170s0 addr fd96:7000:b73c:b0d9:37ee:516:88ef:822 with index 2
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] failed to join multicast: fd96:7000:b73c:b0d9:37ee:516:88ef:822: PKT join multicast group on addr fd96:7000:b73c:b0d9:37ee:516:88ef:822: Address already in use (os error 98). Skipped.
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] join multicast group V6 on wlp170s0 addr fe80::bdf0:3a9d:f58e:c8fc with index 2
[2026-08-26T08:41:34.792Z DEBUG mdns_sd::service_daemon] failed to join multicast: fe80::bdf0:3a9d:f58e:c8fc: PKT join multicast group on addr fe80::bdf0:3a9d:f58e:c8fc: Address already in use (os error 98). Skipped.
At 345.497µs: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
At 15.52842ms: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.312389ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000AAB08AA7._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.347922ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000000BD7BD08._matter._tcp.local.")
At 141.3551ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-0000000077A6EFB7._matter._tcp.local.")
At 141.360796ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000009B2EEF43._matter._tcp.local.")
At 141.367134ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000004D852B21._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.372812ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000642B4839._matter._tcp.local.")
At 141.378888ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-FFFF000000000000._matter._tcp.local.")
At 141.384657ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-0000000061817431._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.394687ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000004192B362._matter._tcp.local.")
At 141.40339ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000F8CD79FE._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.44334ms: ServiceFound("_matter._tcp.local.", "9B5791331E047398-000000000000012D._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.466775ms: ServiceFound("_matter._tcp.local.", "9B5791331E047398-000000000000012E._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.497495ms: ServiceFound("_matter._tcp.local.", "F52AC107C954E38E-0000000000000002._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.522232ms: ServiceFound("_matter._tcp.local.", "F52AC107C954E38E-0000000000000003._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.548054ms: ServiceFound("_matter._tcp.local.", "F52AC107C954E38E-0000000000000004._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 141.578297ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000007D343903._matter._tcp.local.")
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-000000007D343903._matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-000000007D343903._matter._tcp.local.
[2026-08-26T08:41:34.933Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: F52AC107C954E38E-0000000000000004._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: F52AC107C954E38E-0000000000000004._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: F52AC107C954E38E-0000000000000003._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: F52AC107C954E38E-0000000000000003._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: F52AC107C954E38E-0000000000000002._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: F52AC107C954E38E-0000000000000002._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 9B5791331E047398-000000000000012E._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 9B5791331E047398-000000000000012E._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 9B5791331E047398-000000000000012D._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 9B5791331E047398-000000000000012D._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000F8CD79FE._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-00000000F8CD79FE._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-000000004192B362._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-000000004192B362._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-0000000061817431._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-0000000061817431._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-FFFF000000000000._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-FFFF000000000000._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000642B4839._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-00000000642B4839._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-000000004D852B21._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-000000004D852B21._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-000000009B2EEF43._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-000000009B2EEF43._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-0000000077A6EFB7._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-0000000077A6EFB7._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-000000000BD7BD08._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-000000000BD7BD08._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000AAB08AA7._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-00000000AAB08AA7._matter._tcp.local.
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 142.622527ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-000000006EC96BF5._matter._tcp.local.")
[2026-08-26T08:41:34.934Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-000000006EC96BF5._matter._tcp.local.
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] call queriers to resolve 2C755BDFDBFDF8A2-000000006EC96BF5._matter._tcp.local.
At 142.76391ms: Resolved a new service: 2C755BDFDBFDF8A2-000000006EC96BF5._matter._tcp.local.
 host: ECDA3B081E84.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:eeda:3bff:fe08:1e84
 Address: 192.168.86.28
 Address: fe80::eeda:3bff:fe08:1e84%wlp170s0
 Property: SII=5000
 Property: SAI=300
 Property: T=1
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 142.911188ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000F25EF2E4._matter._tcp.local.")
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 142.943298ms: ServiceFound("_matter._tcp.local.", "9B5791331E047398-000000000000012C._matter._tcp.local.")
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 9B5791331E047398-000000000000012C._matter._tcp.local.
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] call queriers to resolve 9B5791331E047398-000000000000012C._matter._tcp.local.
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000F25EF2E4._matter._tcp.local.
[2026-08-26T08:41:34.935Z DEBUG mdns_sd::service_daemon] call queriers to resolve 2C755BDFDBFDF8A2-00000000F25EF2E4._matter._tcp.local.
At 143.208874ms: Resolved a new service: 9B5791331E047398-000000000000012C._matter._tcp.local.
 host: ECDA3BA61A1C.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:eeda:3bff:fea6:1a1c
 Address: fe80::eeda:3bff:fea6:1a1c%wlp170s0
 Address: 192.168.86.35
 Property: SII=5000
 Property: SAI=300
 Property: T=1
At 143.279799ms: Resolved a new service: 2C755BDFDBFDF8A2-00000000F25EF2E4._matter._tcp.local.
 host: ECDA3BA61A1C.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:eeda:3bff:fea6:1a1c
 Address: 192.168.86.35
 Address: fe80::eeda:3bff:fea6:1a1c%wlp170s0
 Property: SII=5000
 Property: SAI=300
 Property: T=1
[2026-08-26T08:41:35.138Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
[2026-08-26T08:41:35.138Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.
[2026-08-26T08:41:35.138Z DEBUG mdns_sd::service_daemon] Resolved service is not valid: 2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.
At 346.630609ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.")
[2026-08-26T08:41:35.139Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 347.271523ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-00000000DFCB37CC._matter._tcp.local.")
[2026-08-26T08:41:35.139Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000DFCB37CC._matter._tcp.local.
[2026-08-26T08:41:35.139Z DEBUG mdns_sd::service_daemon] call queriers to resolve 2C755BDFDBFDF8A2-00000000DFCB37CC._matter._tcp.local.
At 347.520854ms: Resolved a new service: 2C755BDFDBFDF8A2-00000000DFCB37CC._matter._tcp.local.
 host: 3C8D20E19E8E.local.
 port: 5540
 Address: fe80::2425:600b:ae14:e74f%wlp170s0
 Address: fd96:7000:b73c:b0d9:ad84:5968:6560:c59e
 Address: fd96:7000:b73c:b0d9:8672:ffad:c05e:da64
 Address: 192.168.86.78
 Address: fd96:7000:b73c:b0d9:858e:3c93:fe2:2ce
[2026-08-26T08:41:35.139Z DEBUG mdns_sd::service_daemon] calling listener with service found: _matter._tcp.local.
At 347.727834ms: ServiceFound("_matter._tcp.local.", "2C755BDFDBFDF8A2-0000000000840C83._matter._tcp.local.")
[2026-08-26T08:41:35.140Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-0000000000840C83._matter._tcp.local.
[2026-08-26T08:41:35.140Z DEBUG mdns_sd::service_daemon] call queriers to resolve 2C755BDFDBFDF8A2-0000000000840C83._matter._tcp.local.
At 348.119792ms: Resolved a new service: 2C755BDFDBFDF8A2-0000000000840C83._matter._tcp.local.
 host: 14C14EDFB074.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:daad:d595:6447:661e
 Address: fd96:7000:b73c:b0d9:f0ad:7509:cc30:7540
 Address: fe80::4de2:ea09:ee05:7dda%wlp170s0
 Address: fd96:7000:b73c:b0d9:91f5:39c1:4899:91e
 Address: fd96:7000:b73c:b0d9:1015:5f20:59ee:7c33
 Address: 192.168.86.80
[2026-08-26T08:41:35.140Z DEBUG mdns_sd::service_daemon] resolve_updated_instances: from cache: 2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.
[2026-08-26T08:41:35.140Z DEBUG mdns_sd::service_daemon] call queriers to resolve 2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.
At 348.302604ms: Resolved a new service: 2C755BDFDBFDF8A2-00000000F141DDE6._matter._tcp.local.
 host: F4F5D8C0DCE6.local.
 port: 5540
 Address: fd96:7000:b73c:b0d9:a5a7:1503:3658:2f55
At 1.015477297s: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
At 3.01588792s: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
At 7.016287948s: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
At 15.016298575s: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
At 31.017623863s: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")
[2026-08-26T08:42:10.157Z DEBUG mdns_sd::service_daemon] calling listener with service found: _googlezone._tcp.local.
At 63.017903284s: SearchStarted("_matter._tcp.local. on 2 interfaces [lo (1), wlp170s0 (2)]")

@hemanpa

hemanpa commented Aug 26, 2026

Copy link
Copy Markdown

I dug through @qwandor's debug log against the 0.21.0 source, and I don't think this is a pacing problem — which would explain why the improved backoff didn't move it.

What the log shows

Counting his run: 6 instances resolved, 17 did not. Every one of the 6 resolved inside the first 350 ms. The run then continued for 63 seconds through browse re-queries at 1 s, 3 s, 7 s, 15 s and 31 s, and produced zero further resolutions. So it isn't "one per cycle" — it's a fast initial batch and then a hard stop.

The repeated line for the other 17 is Resolved service is not valid, and that predicate is (service_info.rs:1447):

pub fn is_valid(&self) -> bool {
    let some_missing = self.ty_domain.is_empty()
        || self.fullname.is_empty()
        || self.host.is_empty()
        || self.addresses.is_empty();
    !some_missing
}

Those instances have PTR, SRV and TXT — hostname and port are present. What they lack is A/AAAA for the SRV target host.

Why they never recover

query_unresolved does the right thing (queries A + AAAA for srv.host() when get_addr misses), and exec_command_resolve retries it — but capped:

let max_try = 3;

at RESOLVE_WAIT_IN_MILLIS = 500 ms, so that chain is spent ~1.5 s in. After that, the only remaining route back to an instance is resolve_updated_instances, which begins:

let instance = dns_ptr.alias();
if !updated_instances.contains(instance) {
    continue;
}

and updated_instances is populated purely from cache modifications. A browse re-query that returns byte-identical PTR/SRV records produces no modification, so the instance never re-enters that set, and its A/AAAA are never asked for again. The address-less instance is also dropped from self.resolved in the not-valid branch, so nothing else is tracking it.

Net effect: once an instance is found but its address records don't arrive within the 3-try window, it is stuck for the lifetime of the browse, no matter how many times the PTR is re-queried. That matches the log exactly — 17 stuck, 63 s, 5 re-queries, nothing.

It isn't random which ones stall

Grouping the instances by fabric prefix, the split is completely stable across the run:

  • resolved: 2C755BDFDBFDF8A2-… (5) and 9B5791331E047398-… (1)
  • never resolved: F52AC107C954E38E-0000000000000002, …0003, …0004, among others

So it's specific hosts whose address records aren't landing, not round-robin starvation across the set. (The F52AC107C954E38E three are the devices in the downstream report — IPv6-only Thread nodes behind a border router, whose addresses come from the advertising proxy rather than the device itself. Worth noting they're the ones that lose, though I wouldn't want to over-read one capture.)

Suggestion

Track found-but-address-less instances per active browse and re-issue A/AAAA for their SRV targets on the browse's own re-query schedule, decoupled from updated_instances and not bounded by max_try. The current design assumes a missing address is a transient loss worth 3 quick retries; on a busy link it can outlast that window, and there's currently no path back afterwards.

Happy to test any diff — and I can reproduce something adjacent here (16 instances, mixed IPv4/IPv6 plus IPv6-only Thread devices), though my link resolves everything promptly, so @qwandor's network remains the real test.

For what it's worth downstream: we worked around this by browsing the Matter compressed-fabric subtype rather than the base type, which narrows the query from ~18 instances to 3 and resolves in ~266 ms on his network. That sidesteps the stall rather than fixing it, and it's consistent with the above — fewer instances, so the address queries land inside the retry window.

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.

ServiceResolved arrives for only ~1 instance per query cycle when a service type has many instances

3 participants