dnsforward: fix misreported upstream response times - #8522
Conversation
Sil3ntVip3r
left a comment
There was a problem hiding this comment.
I found three blocking problems in the new upstream wrapper. The affected
package suites themselves pass under -race, but a disposable concurrency
regression exposes the race below.
1. Ignored clients are now included in upstream statistics
Severity: Medium. Confidence: High.
statsUpstream.Exchange records every successful exchange through
UpdateUpstream, before processQueryLogsAndStats asks ShouldCount whether
the client should be ignored. UpstreamEntry contains no client identity, so
UpdateUpstream can only apply the ignored-domain list.
The exact trigger is any DNS request from a persistent client with
ignore_statistics enabled. On master, ShouldCount rejects the complete
stats.Entry, including its UpstreamStats; this change still adds that
client's upstream address and duration. This both changes the documented
ignore behavior and biases the metrics the PR is fixing.
The smallest safe design needs to retain client attribution for foreground
requests (or otherwise run their samples through ShouldCount) while adding
only the unattributed background refresh samples separately, without double
counting. Please add an end-to-end regression where an ignored client reaches
a real upstream and assert that neither upstream response counts nor times
change.
Relevant paths: internal/dnsforward/upstreamstats.go:42-52,
internal/dnsforward/stats.go:47-65, and internal/stats/stats.go:318-337.
2. Lazy custom-upstream wrapping races with DNS configuration updates
Severity: Medium. Confidence: High; reproduced with the race detector.
wrapUpstreams reads s.conf.UpstreamTimeout without serverLock.
WrapUpstreamConfig is also called lazily from the client upstream manager,
which does not hold that lock. A concurrent /control/dns_config timeout
update writes the same field while holding serverLock.
A disposable regression repeatedly performed that protected write concurrently
with WrapUpstreamConfig; go test -race reported the write against the read
at internal/dnsforward/upstreamstats.go:153 and failed.
Please avoid reading mutable Server.conf from the wrapper. Passing the
actual immutable timeout alongside each parsed upstream configuration (the
client manager already has CommonUpstreamConfig.UpstreamTimeout) removes the
race and also enables the next correction. A corresponding concurrent
-race regression should be retained.
3. Private-rDNS retries use the wrong threshold
Severity: Medium. Confidence: High.
Private reverse-DNS upstreams are built with defaultLocalTimeout (one second)
in prepareLocalResolvers, but WrapUpstreamConfig stores the general
s.conf.UpstreamTimeout (normally ten seconds) in every wrapper. If a local
upstream drops the first request and its retry succeeds after about one second,
the new dur >= timeout filter compares that duration with ten seconds and
records it as an ordinary response. That reintroduces the same inflated retry
sample this PR intends to remove, now through newly counted internal/private
lookups.
Make wrapping accept the timeout actually used to construct each upstream;
pass defaultLocalTimeout for the private-rDNS configuration and the configured
timeout for main, fallback, and per-client upstreams. Add a private-rDNS
regression whose first packet is dropped and assert that the retried duration is
not sampled.
Validation I ran on the published head:
go test -race -count=1 ./internal/stats ./internal/dnsforward ./internal/client ./internal/home
ok (all four packages)
go test -race -count=1 -run '^TestReviewWrapUpstreamConfigTimeoutRace$' ./internal/dnsforward
FAIL: DATA RACE at upstreamstats.go:153 (expected review reproducer)
git diff --check
clean
The disposable review test was removed afterward; the PR worktree remains at
the exact published two-commit head. The unrelated cache-success notification
would also be easier to review as a separate PR, but that is a scope suggestion,
not one of the defects above.
|
@Sil3ntVip3r |
Sil3ntVip3r
left a comment
There was a problem hiding this comment.
Thanks for the follow-up work. I re-reviewed exact head
fd3759f39f3eb3a25a6e3607e21cae28f63bf0d1. The timeout plumbing,
optimistic-refresh collection, affected-package race tests, and frontend checks
look sound, but there is still one functional blocker in the ignored-request
attribution.
markIgnoredReq stores the original *dns.Msg as the key
(internal/dnsforward/upstreamstats.go:81-84), and statsUpstream later looks
up the request pointer it receives (upstreamstats.go:113). In parallel mode,
however, dnsproxy copies the request once per upstream before calling the
wrappers (dnsproxy/upstream/parallel.go:35-43). Fastest-address mode has the
same behavior through ExchangeAll (parallel.go:118-125). None of those
copied pointers can match the original key, so ignore_statistics is bypassed
in these supported modes.
I reproduced this against the exact head by changing only the existing
TestServer_updateStats_ignoredClient fixture to start two upstreams with the
same handler, configure both addresses with UpstreamModeParallel, and expect
two samples for the counted case. Then I ran:
go test -race -count=1 -run '^TestServer_updateStats_ignoredClient$/ignored$' ./internal/dnsforward
The ignored case failed deterministically:
Error: Should be empty, but was [0xc00032a3f0 0xc000190390]
FAIL github.com/AdguardTeam/AdGuardHome/internal/dnsforward
Impact: queries from clients or domains excluded from statistics still add
upstream response counts and durations in parallel mode, and likewise for
A/AAAA queries in fastest-address mode with multiple upstreams. This both
violates the ignore setting and biases the new aggregate this PR is intended to
correct.
The smallest safe direction is to avoid using *dns.Msg identity as request
attribution. The ignore decision/correlation must survive dns.Msg.Copy() and
remain valid for every exchange it fans out to. Note that merely changing the
map key is insufficient: ExchangeParallel returns after the first successful
response while the other exchange goroutines may still be running, and
processUpstream currently removes the marker when Resolve returns. A
robust fix should either propagate exchange-scoped metadata through dnsproxy,
or keep the existing client-attributed foreground collection and add
optimistic background-refresh samples through a separate explicit path. A
content- or DNS-ID-based map key would be unsafe under concurrent
identical/colliding requests.
Please add a table-driven regression covering load-balance, parallel, and
fastest-address with at least two upstreams. For each applicable mode, an
ignored client/domain must add zero samples and a counted query must add the
expected number; include a delayed parallel upstream so attribution remains
valid after the first response returns.
There is also a repository-gate failure on this head:
make go-check
...
gocognit: 12 dnsforward TestStatsUpstream_Exchange internal/dnsforward/upstreamstats_internal_test.go:24:1
make: *** [go-lint] Error 1
Splitting that test or extracting its per-case helper should bring it under the
test complexity limit without changing coverage.
Validation performed on the clean exact head:
PASS: focused new dnsforward tests under -race
PASS: go test -race -count=1 ./internal/stats ./internal/dnsforward ./internal/client ./internal/home
PASS: make go-test (full Go suite with race/coverage)
PASS: NODE_OPTIONS=--no-experimental-webstorage npm run check (ESLint, tsc, 58 files / 619 tests)
PASS: git diff --check
FAIL: make go-check (gocognit finding above)
EXPECTED FAIL: parallel ignored-client reproducer above
The reproducer was removed afterward; the disposable checkout is clean at the
exact head.
|
@Sil3ntVip3r you're right on all three counts, and the parallel-mode hole is fatal to the approach rather than a bug in it. I verified it in dnsproxy rather than only from the report:
So a wrapper cannot identify the request an exchange belongs to. It can apply neither the ignore lists nor tell a background refresh from a client's query, and as you say, a content- or ID-based key is unsafe under concurrent identical requests. There is no in-tree fix; the wrapper approach is a dead end. Taking the first of the two directions you named. I opened AdguardTeam/dnsproxy#520, which adds an optional That removes the attribution problem entirely rather than working around it: foreground exchanges go back to being collected from This PR is blocked on that one. Once it lands and a release is cut, I'll rebase here: drop I have that rebase prepared locally and it passes, including a retry regression across load-balance, parallel and fastest-address that fails in all three without the filter. I'm holding it back rather than pushing a version that can't compile against a released dnsproxy. The gocognit finding is fixed in Two notes on the rest. Once the rebase lands there is no wrapper left, so the ignore-list regression you asked for reduces to master's existing |
|
Thanks for tracing this through dnsproxy and for confirming the request-wrapper approach cannot preserve attribution across copied/fanned-out exchanges. I reviewed Holding this PR until that dependency is merged and released is the right sequence. I will re-review the rebased AdGuard Home head once it drops the wrapper/request-marking path and splits the cache-success notification as described. |
|
Pushed the rebase onto AdguardTeam/dnsproxy#520. dnsproxy#520 has to be merged and released before this can be merged. The dependency is now stated at the top of the description as well.
Regressions, each verified to fail against the unfixed implementation: the retry filter in load-balance, parallel, and fastest-address mode, and the refresh collection against an entry that expires mid-test. Separately, for #8498 — @Sil3ntVip3r, I ran the controlled A/B you asked for in #8491 (comment): That run is on WSL2/glibc/x86_64, so it isolates A-vs-B cleanly but is still not the OpenWrt device evidence you also asked for. The harness is self-contained and POSIX-ish, so the same protocol can run on the router. |
b909005 to
4cacde0
Compare
Sil3ntVip3r
left a comment
There was a problem hiding this comment.
I re-reviewed exact AdGuard Home head
4cacde05d0c6f732570c864b33ed7def57f77c7a together with exact dependency
head AdguardTeam/dnsproxy@858999ba4ce11ea3a96ab4633e2b59448f4f5f8d.
The redesign fixes the three earlier architectural blockers: foreground
statistics retain the existing client-attributed QueryStatistics path,
optimistic refreshes use the explicit dnsproxy callback, and the retry filter
uses the actual per-configuration timeout. I found two remaining blockers in
the new head.
1. The global upstream average combines two independently truncated sets
Severity: Medium. Confidence: High; reproduced on the exact head.
unit.serialize independently keeps only the top maxUpstreams (100)
entries in UpstreamsResponses and UpstreamsTimeSum
(internal/stats/unit.go:292-300). avgUpstreamResponseTime then sums those
two persisted slices as if they represented the same complete population
(unit.go:652-668). They need not contain the same upstreams.
The exact trigger is a statistics unit with more than 100 upstream addresses
where the top response-count set differs from the top total-duration set. A
disposable deterministic regression used:
- 100 count-heavy upstreams: 100 responses and 1 us total each;
- 100 time-heavy upstreams: 99 responses and 99 us total each.
The true global average is about 0.5025 us. The published head serialized the
count-heavy response denominators and the time-heavy duration numerators and
returned 0.99 us, nearly twice the real value:
want 5.025125628140703e-07 seconds
got 9.9e-07 seconds
FAIL TestReviewAvgUpstreamResponseTimeTruncation
Impact: the new dashboard headline can still be materially wrong on
installations that have used more than 100 distinct upstream addresses within
a persisted unit, including configurations with changing/custom upstreams.
The smallest safe fix is to maintain and persist an exact total successful
response count and exact total upstream duration before the bounded top lists
are produced, and use those totals for the global average. The existing
bounded slices should remain for per-upstream ranking. Because unitDB is
GOB-encoded, add new fields without changing existing names or types, and fall
back to summing the old slices when decoding older records whose new totals
are absent. Keep a regression with more than maxUpstreams addresses and
deliberately different count/time rankings.
I prototyped that four-part change locally (in-memory totals, persisted totals,
old-record fallback, and the regression). The initial prototype was correctly
rejected by fieldalignment; after moving the new scalar fields behind the
pointer fields, the complete make go-check gate passed, including the full
race suite, lint, vet, gosec, and govulncheck.
2. The new retry test reads testStats.lastEntry concurrently with Update
Severity: Low (test/CI reliability). Confidence: High; reproduced by
the race detector on the exact head.
testStats.Update writes lastEntry under testStats.mu
(internal/dnsforward/stats_internal_test.go:85-88), but the
retried_not_counted test reads it directly without that lock at lines
311-312. The UDP response may reach the test before the server's asynchronous
statistics path finishes.
go test -race -count=3 ./internal/dnsforward \
-run '^TestServer_stats_upstreamTimes$/retried_not_counted/'
WARNING: DATA RACE
read stats_internal_test.go:311
write stats_internal_test.go:88
FAIL
Add a locked accessor returning the latest entry and wait for a non-nil entry
with require.Eventually before asserting its contents. With that minimal
test fix, the focused test passed under -race -count=10, the four affected
packages passed under -race -count=3, and the full prototype passed
make go-check.
The unreleased dnsproxy dependency remains an acknowledged sequencing gate,
not an additional defect in this review. The cache-success notification also
remains in this branch despite the earlier plan to split it; I am treating that
as a scope/maintainer choice rather than a correctness blocker.
No review-only files remain in the clean exact-head checkout. I did not
commit, push, or modify either published branch.
|
Both fixed in 1. The global average combined two independently truncated sets. You're right, and the reproduction matches yours exactly. The exact totals are now counted as responses arrive, before any truncation, and the average uses those. They are persisted as two new
2. The racy read. Fixed as you suggested: a locked accessor, and Worth flagging: writing this up, the existing On the two non-blockers: the sequencing gate on AdguardTeam/dnsproxy#520 stands, and this branch deliberately carries no |
Sil3ntVip3r
left a comment
There was a problem hiding this comment.
Re-reviewed exact AdGuard Home head b20f6dddd4b8759b0e18547cfbda0b4a49f51a00 together with exact dependency head AdguardTeam/dnsproxy@858999ba4ce11ea3a96ab4633e2b59448f4f5f8d in an isolated Go workspace.
Both blockers from my previous review are fixed. The global average now uses exact response-count and duration totals recorded before the two top-100 lists are independently truncated; the totals are persisted through additive GOB fields, and older records fall back to their retained bounded data. The retry regression now reads the statistics entry through the same mutex used by its writer and waits for the asynchronous update.
Validation performed on the clean exact head:
go test -race -count=20 ./internal/stats
PASS: truncation, old-record fallback, and deserialize tests
go test -race -count=20 ./internal/dnsforward
PASS: retried_not_counted across supported modes
go test -race -count=3 ./internal/stats ./internal/dnsforward ./internal/client ./internal/home
PASS
make go-check
PASS: full race suite, lint, vet, gosec, and govulncheck; 0 reachable vulnerabilities
git diff --check
PASS
An independent adversarial pass found no remaining blocker in the new commit. Building with GOWORK=off fails only at the expected unreleased proxy.Config.OnOptimisticRefresh field, confirming that dnsproxy #520 still must merge and be released before this PR can build and merge normally. That is a sequencing gate, not a defect in this head.
I found no remaining correctness or compatibility blocker and approve this exact head. The cache-success notification remains a separable scope choice for the maintainers.
b20f6dd to
220836e
Compare
The dashboard's upstream response times were wrong in four independent
ways: inflated by roughly 2-4x whenever optimistic caching was enabled,
far higher than the actual network latency to the upstream servers, shown
against a headline figure that measured something else entirely, and
averaged over time incorrectly.
1. The response times were taken from the per-request
proxy.DNSContext.QueryStatistics, and the entries marked as served from
the cache were skipped. An optimistic cache hit is answered from the
cache right away while dnsproxy refreshes the expired entry in a
background goroutine that uses a cloned DNSContext, whose statistics are
discarded. Popular domain names are therefore never sampled at all, and
the average ends up being based on cache misses alone, which are skewed
towards the rare domain names that upstreams resolve slower.
Collect the response times from a *statsUpstream decorator wrapping every
upstream.Upstream instead. It sits below dnsproxy, so it observes every
exchange, foreground and background alike, and it becomes the single
source of truth: stats.Entry.UpstreamStats is removed so that nothing is
counted twice. The decorator is applied to the general, private-rDNS,
fallback, and per-client custom upstream configurations.
2. A plain DNS upstream retries once when an attempt times out, for
example when a UDP datagram is lost, and the retried exchange succeeds.
Its duration is then at least the whole upstream timeout, which defaults
to ten seconds, even though the successful attempt itself took about a
millisecond. Averaged in as an ordinary response, a single such sample
outweighs a hundred normal ones several times over, which is what made
the reported times bear no relation to the round-trip time. Skip the
exchanges whose duration reaches the timeout, since a single attempt
cannot take that long, so their duration describes the retry policy and
the configured timeout rather than the speed of the upstream.
3. The "Average upstream response time" panel showed avg_processing_time
as its headline, which is the time AdGuard Home itself takes and covers
every request, including the ones answered from the cache or blocked by a
filter. Those take almost no time, so the headline was typically an
order of magnitude lower than every upstream listed right below it. Add
an avg_upstream_response_time property to GET /control/stats, averaged
over the responses of the upstream servers, and show that instead.
4. The average processing time was the unweighted mean of the per-hour
means, so an hour with a handful of requests weighed as much as an hour
with tens of thousands of them. Weight it by the number of requests, the
way the upstream response times already were.
Two things constrain the implementation:
- The wrapping is done in place on s.conf.UpstreamConfig rather than on
a copy handed to the proxy, because several tests assign mock
upstreams to it after Prepare and rely on the proxy sharing that
pointer.
- The decorator must not acquire Server.serverLock. Server.Resolve
holds it for reading while driving the internal proxy over the same
upstreams, so a nested RLock would deadlock whenever a writer queues
between the two. Hence Server.upstreamStats, which is set once in
NewServer and never reset.
Note that the metric now also counts the internal proxy's lookups (client
rDNS, updater) and DNS64 sub-queries, and that the statistics "ignored
clients" list no longer applies to upstream timings, since a background
refresh has no client to attribute it to. The ignored *domains* list is
still honoured.
Closes AdguardTeam#8435.
Closes AdguardTeam#8457.
Accepting the "Clear cache?" dialog gave no feedback at all on success, so there was no way to tell whether it had worked. clearDnsCache awaited cacheClear and only reported failures, leaving the success path silent. The previous user interface did show a notification, so this is a regression in the rewrite rather than a missing feature. Show one, using the new dns_cache_cleared string.
Three defects in the upstream wrapper. The ignore lists were bypassed. statsUpstream recorded every successful exchange, while ShouldCount is only consulted afterwards, in processQueryLogsAndStats, and an UpstreamEntry carries no client identity for UpdateUpstream to check. A query from a client with ignored statistics therefore still contributed its upstream address and duration, which both contradicts the documented behaviour and biases the averages this collection exists to report. The first commit called that an accepted consequence; it is not. An exchange cannot be attributed to a client from inside a wrapper, so record the verdict where the client is still known: processUpstream now marks the request of an ignored query for the duration of its resolution, and the wrappers skip the exchanges of a marked request. Only ignored queries are stored, so the map stays empty on a server that ignores nothing. Exchanges belonging to no request at all, such as the background refreshes of the optimistic cache, are never marked and remain counted, which is the point of collecting them here in the first place. The timeout was read from mutable state. wrapUpstreams took it from Server.conf, which is written under serverLock by a /control/dns_config update, while WrapUpstreamConfig is also called lazily by the client upstream manager without that lock. Take the timeout as an argument instead; the client manager already has it in CommonUpstreamConfig. The private rDNS wrappers held the wrong threshold. Those upstreams are built with defaultLocalTimeout, one second, but every wrapper stored the configured timeout, normally ten seconds. A one-second retried exchange with a local resolver was therefore compared against ten and recorded as an ordinary response, reintroducing the inflated sample this change removes. Passing the timeout explicitly lets each configuration carry the one its upstreams were constructed with. Each is covered by a test that fails against the previous implementation: an end-to-end query from an ignored client, a concurrent wrap against a protected timeout write under -race, and the thresholds stored for the main and private rDNS configurations.
gocognit reports TestStatsUpstream_Exchange at 12, over the limit of 10 that go-lint.sh applies to this package. Extract the per-case body into a helper; coverage is unchanged.
Replace the upstream wrapper with the callback added in AdguardTeam/dnsproxy#520. The wrapper could not work. An exchange has to be attributed to the request it belongs to, both so that the statistics ignore lists apply and so that a background refresh can be told from a foreground query, and an upstream.Upstream is given no way to do it: Exchange takes only a *dns.Msg and no context, and ExchangeParallel and ExchangeAll copy the request once per upstream before calling it, so no identity of the original survives. The request-pointer key therefore missed in parallel and fastest-address mode with more than one upstream, and queries from clients with ignored statistics were counted after all. Only the single-upstream path skips the copy, which is why the first regression passed. Foreground exchanges go back to being collected from proxy.DNSContext.QueryStatistics, which is client-attributed and already gated by ShouldCount, so the ignore lists behave exactly as they did before this branch. Background refreshes arrive through proxy.Config.OnOptimisticRefresh, which fires once the optimistic cache has refreshed an expired entry; they belong to no client by construction, so there is nothing to attribute and nothing to double count. A retried exchange is still left out, but the check moved to where the statistics entry is built, and compares against the timeout the upstreams of that request were constructed with: defaultLocalTimeout for private rDNS, the configured one otherwise. Both are covered end to end, and both regressions fail against the unfixed implementation: the retry filter in load-balance, parallel, and fastest-address mode, and the refresh collection against an entry that expires while the test runs.
Two defects from the review of the previous head. The global upstream average divided one bounded list by another. unit.serialize keeps only the top maxUpstreams entries of upstreamsResponses and of upstreamsTimeSum, and it ranks each of them independently, so a unit that has seen more upstreams than that persists the counts of one set and the durations of another. avgUpstreamResponseTime then summed the two as though they described the same population. With 100 upstreams answering often and quickly and 100 answering rarely and slowly, the true average of 0.5025us was reported as 0.99us, nearly twice over. Count the exact totals as the responses arrive, before any truncation, and average those. They are persisted as two new unitDB fields; GOB decodes them as zero in the records written before they existed, and for those the bounded lists are still summed, which is what this used to do and remains the best answer available for such a record. The bounded lists keep their present meaning, which is the per-upstream ranking on the dashboard. The retry test also read testStats.lastEntry without holding the mutex that Update writes it under. The client is answered before the statistics path has necessarily run, so the read raced. Add a locked accessor and wait for the entry rather than assuming it has arrived. The truncation regression fails against the previous implementation with exactly the reported numbers, and the race test passes under -race -count=3.
220836e to
efd7668
Compare
Sil3ntVip3r
left a comment
There was a problem hiding this comment.
Re-reviewed exact AdGuard Home head efd76680a60676f383d8f2ff8ec42785ac33333e with exact dependency head AdguardTeam/dnsproxy@858999ba4ce11ea3a96ab4633e2b59448f4f5f8d.
The new persisted totals correctly fix the global-average truncation defect: they are incremented before per-upstream lists are bounded, survive serialization, and older GOB records retain the bounded-list fallback. The test synchronization change also removes the race in the retry assertion.
Validation completed in a temporary two-module workspace:
go test -race -count=20 ./internal/stats: passed;go test -race -count=20 ./internal/dnsforward: passed;go test -race -count=3 ./internal/stats ./internal/dnsforward ./internal/client ./internal/home: passed;- diff and worktree checks: clean.
GOWORK=off fails only at the explicitly expected unreleased proxy.Config.OnOptimisticRefresh field in dnsproxy v0.83.2. The broader workspace gate passed every AdGuard Home package and the dependency’s relevant packages; its only failures were dnsproxy’s pre-existing live-network probes to 94.140.14.14:5353 and 9.9.9.9:853, outside this change.
dnsproxy#520 is still open and unreleased, so it remains the sole merge sequencing gate. After it lands and a release is tagged, this branch needs the ordinary dependency version update and normal CI. Subject to that prerequisite, approved.
Important
Depends on AdguardTeam/dnsproxy#520, which must be merged and released first.
This change collects the optimistic cache's background refreshes through the new
proxy.Config.OnOptimisticRefresh. That field is in no released dnsproxy, so this branch does not compile against one and CI will fail until it is.The branch deliberately carries no
replacedirective for a fork: nothing here has to be undone before merging. Once dnsproxy#520 is released it needs only the ordinary version bump.Fixes #8435.
Fixes #8457.
The dashboard's upstream response times are wrong in four independent ways. #8435 reports the average being inflated by roughly 2-4x with optimistic caching enabled; #8457 reports the per-upstream figures bearing no relation to the round-trip time. They have different causes, and two further defects are visible in the same panel.
1. Optimistic-cache refreshes are never sampled (#8435)
Response times come from the per-request
proxy.DNSContext.QueryStatistics, andunit.addskips every entry withIsCachedset. An optimistic cache hit is answered from the cache immediately while dnsproxy refreshes the expired entry in a background goroutine using a clonedDNSContext(proxycache.go), whose statistics are discarded.Popular domain names are therefore never sampled at all. The average ends up computed over cache misses alone, which are skewed towards the rare domains that upstreams resolve slower — exactly the bias the reporter describes.
Response times are now collected by a
*statsUpstreamdecorator wrapping everyupstream.Upstream. It sits below dnsproxy, so it observes every exchange, foreground and background alike, and becomes the single source of truth —stats.Entry.UpstreamStatsis removed so nothing is counted twice. It is applied to the general, private-rDNS, fallback and per-client custom upstream configurations.2. A retried exchange is recorded as an ordinary response (#8457)
plainDNS.dialExchangeretries once whenisExpectedConnErris true, and that predicate matches read timeouts, not just connection resets. So a single lost UDP datagram means the first attempt blocks for the wholeOptions.Timeout, the retry succeeds, andExchangereturns success aftertimeout + RTT.UpstreamTimeoutdefaults to ten seconds.Measured with a localhost upstream instructed to drop the first query, timeout set to 1s:
An exchange whose successful attempt took about a millisecond was recorded as 1.0016 s. With the ten-second default and 1% packet loss, 99 queries at 20 ms plus one at 10 s averages ~120 ms — a 6x inflation from one lost packet. That matches the reporter finding that removing distant resolvers "fixed" it.
A successful exchange cannot legitimately reach the per-attempt timeout, so
dur >= timeoutis a sound detector for "this one retried". Those samples are skipped and logged at debug level, since their duration describes the retry policy and the configured timeout rather than the speed of the upstream.3. The panel headline measured something else
UpstreamAvgTime.tsxrendersavg_processing_timeunder the headingaverage_upstream_response_time. That is AdGuard Home's own end-to-end time across every request, including cache hits and filter blocks, which cost microseconds — so with a high cache-hit ratio the headline collapses toward zero while the list beneath it shows real upstream latencies. A user reported 3 ms above a list of 32-82 ms upstreams.Adds
avg_upstream_response_timetoGET /control/stats, averaged over upstream responses, and points the panel at it.GeneralStatisticskeeps usingavg_processing_time, which is correct there.4. The average processing time was unweighted
dataFromUnitssummed each unit'sTimeAvgand divided by the number of non-empty units — an unweighted mean of hourly means, so an hour with five queries counted as much as an hour with fifty thousand. The upstream panel already did this correctly, so the two headline figures were computed by inconsistent methods. Now weighted by request count.Testing
go build ./...,go vet ./internal/...andgofmtare clean;stats,dnsforward,clientandhomepass, including under-race.New tests, each verified to fail against the previous implementation:
TestServer_updateStats_optimisticCache— drives a real server against a localhost upstream with a 1s cache TTL and asserts the background refresh produces a second sample.TestStatsUpstream_Exchange_timeoutRetry— a normal exchange is counted, a retried one is not.TestStatsCtx_dataFromUnits_avgProcessingTime— two units of 1000 queries at 1 ms and 10 at 100 ms give 1.98 ms weighted against 50.5 ms unweighted, a 25x error.WrapUpstreamConfig.Notes for reviewers
Two things constrained the implementation:
s.conf.UpstreamConfigrather than on a copy handed to the proxy, because several tests assign mock upstreams to it afterPrepareand rely on the proxy sharing that pointer.Server.serverLock.Server.Resolveholds it for reading while driving the internal proxy over the same upstreams, so a nestedRLockwould deadlock whenever a writer queues between the two. HenceServer.upstreamStats, set once inNewServerand never reset.Deliberate behaviour changes worth a decision:
GET /control/statsgains a property, documented inopenapi/.Review updates
Addressing @Sil3ntVip3r's review, in
fd3759f:The ignore lists were bypassed. The wrapper recorded every exchange while
ShouldCountis only consulted afterwards, so an ignored client still contributed its upstream samples. My original description called that an accepted consequence; it was not, and the reviewer is right that it also biases the very averages this PR fixes. An exchange cannot be attributed to a client from inside a wrapper, soprocessUpstreamnow marks the request of an ignored query for the duration of its resolution and the wrappers skip marked requests. Only ignored queries are stored, so the map stays empty on a server that ignores nothing, and background refreshes — which belong to no request — remain counted.The timeout was read from mutable state.
wrapUpstreamstook it fromServer.conf, written underserverLockby a/control/dns_configupdate, while the client upstream manager wraps without that lock. It is now an argument; the client manager already had it inCommonUpstreamConfig.The private rDNS wrappers held the wrong threshold. Those upstreams are built with
defaultLocalTimeout(1s) but every wrapper stored the configured timeout (normally 10s), so a retried local exchange was compared against 10s and recorded as ordinary — reintroducing the inflated sample. Each configuration now carries the timeout its upstreams were constructed with.Three regressions added, each verified to fail against the previous implementation: an end-to-end query from an ignored client, a concurrent wrap against a protected timeout write under
-race, and the thresholds stored for the main and private rDNS configurations.go test -racepasses forstats,dnsforward,clientandhome.The second commit, the DNS-cache-cleared notification, is unrelated to the response times — it is here only because it touches the same dashboard. Happy to drop it or split it out.