Files
meshcore-analyzer/cmd/server/clock_skew_issue1285_test.go
T
SaarlandpowerandClaude 0352c9a287 fix(clock-skew): restrict per-node skew to self-originated adverts (#1816, #1818) (#1820)
Closes #1816. Closes #1818 (confirmed duplicate of #1816 by the triage
bot).

## Root cause

`byNode` is an involvement index (`indexResolvedPathHops`,
`store.go:1696-1705`, #1558/#1352): a transmission is indexed under
every relay-hop pubkey found in an observation's `resolved_path`, not
just its originator. `getNodeClockSkewLocked` (`clock_skew.go:489`)
iterated every ADVERT transaction under a pubkey without checking who
actually signed it, so a relay inherited the clock skew of every
broken-clock node it forwarded as if it were its own.

This produced:
- Fleet-wide false `no_clock`/`bimodal_clock` classifications on healthy
relays whose only "bad" samples were adverts they merely relayed.
- Bit-identical `RecentMedianSkewSec` "clusters" across unrelated relays
that all forwarded the same broken-clock originator.
- Single relays showing a multi-day skew even though their own
self-adverts are healthy, because 1-2 relayed adverts from a broken
originator landed in the tail of their small recent-window sample (the
#1818 "island" repro from @cwichura).

## Fix

Add `txOriginatedBy(tx, pubkey)`: ADVERTs are self-signed, so
`decoded["pubKey"]` is the originator per protocol (case-insensitive
compare as a defensive measure). Apply it as a guard in both the main
skew-aggregation loop and the per-hash evidence loop in
`getNodeClockSkewLocked`. `byNode` itself is untouched — #1558/#1352
still rely on the broader involvement index for other consumers.

## Tests

- Existing `clock_skew_test.go` / `clock_skew_issue1094_test.go` /
`clock_skew_issue1285_test.go` fixtures built synthetic ADVERT
transactions without a `pubKey` field and seeded `s.byNode` directly,
bypassing the normal `indexByNode` path where every real ADVERT carries
`pubKey`. Added `pubKey` to each fixture so it reflects a
self-originated advert, which is what these tests already intended to
represent. All pre-existing tests pass unchanged in behavior.
- New `clock_skew_issue1816_test.go`:
- `TestTxOriginatedBy` — unit coverage of the new guard (self, foreign,
missing pubKey, case-insensitivity).
- `TestIssue1816_RelayDoesNotInheritOriginatorSkew` — a relay with
healthy self-adverts plus relayed adverts from a broken-clock originator
(matching the report's +100.5k s band) must report `ok` severity based
only on its own adverts.
- `TestIssue1816_PureRelaysReportNoSkew_NoBitIdenticalCluster` — five
relay pubkeys that only ever forward a broken originator's advert (never
self-advert) must report `nil`, not a bit-identical copy of the
originator's skew.
- `TestIssue1818_TwoForeignAdvertsDoNotPoisonIslandNode` — reproduces
the cwichura island scenario: 8 healthy self-adverts + 2 foreign adverts
at ~10 days skew must not flip severity or pollute
`RecentMedianSkewSec`.

Full suite: `go test ./...` passes (one pre-existing, unrelated flaky
test — `TestHandleNodePaths_PrefixCollision_1352`, an index-loading race
— reproduces intermittently on unmodified `master` too).

Operator context: running CoreScope for SaarMesh (SaarLorLux, DE/FR/LU,
800+ nodes); this bug was surfacing as fleet-wide clock-skew false
positives on our infra nodes.

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

Co-authored-by: Claude <noreply@anthropic.com>
2026-09-02 09:50:18 +02:00

130 lines
4.6 KiB
Go
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
package main
// Regression tests for #1285:
//
// Bug A: per-hash evidence's MedianCorrectedSkewSec includes 700-day RTC-reset
// outliers, dragging the displayed median into "704d 18h" garbage even
// though every recent sample is small (< 30s).
//
// Bug B: RecentBadSampleCount counts samples outside the *displayed* recent
// window (or counts against raw skew, not corrected) → "3 of last 5
// adverts had nonsense timestamps" warning fires on healthy nodes.
//
// Both must pass without disturbing the existing bimodal / no-clock logic.
import (
"testing"
"time"
)
// Synthesizes the repro from issue #1285:
// 30 healthy adverts (skew ~20s) + 1 historical advert with an RTC reset
// (advertTS = 2024-06-13, observed today → 705d skew).
// Returns the populated store.
func seedIssue1285Repro(t *testing.T) *PacketStore {
t.Helper()
ps := NewPacketStore(nil, nil)
pt := 4 // ADVERT
const pubkey = "RTCRESET"
const skewSec = int64(-20) // node clock is 20s BEHIND wall-clock
baseObs := int64(1779000000) // ~mid-2026
rtcResetAdv := int64(1718281640) // 2024-06-13 (from the issue repro)
var txs []*StoreTx
// 30 healthy adverts spanning the older end of the recent window.
for i := 0; i < 30; i++ {
obsTS := baseObs + int64(i)*60
advTS := obsTS + skewSec
tx := &StoreTx{
Hash: "healthy-" + formatInt64(int64(i)),
PayloadType: &pt,
DecodedJSON: `{"payload":{"timestamp":` + formatInt64(advTS) + `},"pubKey":"RTCRESET"}`,
Observations: []*StoreObs{
{ObserverID: "obs1", Timestamp: time.Unix(obsTS, 0).UTC().Format(time.RFC3339)},
},
}
txs = append(txs, tx)
}
// One RTC-reset packet observed MOST RECENTLY (so it sits in the
// per-hash evidence list AND is included in the recent-window count
// on master). Its advertTS is from 2024 → corrected skew ≈ -60M sec.
rtcResetObs := baseObs + int64(30*60) + 60
rtcTx := &StoreTx{
Hash: "rtc-reset-0001",
PayloadType: &pt,
DecodedJSON: `{"payload":{"timestamp":` + formatInt64(rtcResetAdv) + `},"pubKey":"RTCRESET"}`,
Observations: []*StoreObs{
{ObserverID: "obs1", Timestamp: time.Unix(rtcResetObs, 0).UTC().Format(time.RFC3339)},
},
}
txs = append(txs, rtcTx)
ps.mu.Lock()
ps.byNode[pubkey] = txs
for _, tx := range txs {
ps.byPayloadType[4] = append(ps.byPayloadType[4], tx)
}
ps.clockSkew.computeInterval = 0
ps.mu.Unlock()
return ps
}
// Bug A — per-hash evidence median must EXCLUDE the 705-day RTC-reset outlier.
// On master this asserts on the RTC-reset hash's MedianCorrectedSkewSec being
// ≈ 60M sec ("704d 18h"); after the fix the field is suppressed (0) or
// otherwise marked insufficient, never displayed as the garbage value.
func TestIssue1285_HashEvidence_OutlierExcludedFromMedian(t *testing.T) {
ps := seedIssue1285Repro(t)
r := ps.GetNodeClockSkew("RTCRESET")
if r == nil {
t.Fatal("expected clock skew result")
}
// The recent-hash evidence list is the source of the "median corrected:
// 704d 18h" string in the UI. After the fix, NO entry in this list
// should report a |median| above the 24h sanity threshold — the fix is
// to drop outlier samples (or flag the hash as insufficient-data) before
// publishing the median.
const maxSaneAbsSec = float64(24 * 3600)
for _, ev := range r.RecentHashEvidence {
if abs(ev.MedianCorrectedSkewSec) > maxSaneAbsSec {
t.Errorf("hash %s exposes outlier-dominated median %.0fs (~%.1fd); "+
"expected entry to be filtered out or marked insufficient (|median| <= %.0fs)",
ev.Hash, ev.MedianCorrectedSkewSec,
ev.MedianCorrectedSkewSec/86400, maxSaneAbsSec)
}
}
}
// Bug B — RecentBadSampleCount must be 0 when every sample in the recent
// window is healthy (<30s |corrected skew|). On master this fires because
// "recent" is computed over the wrong set (or against raw skew).
func TestIssue1285_RecentBadCount_NotPollutedByOldOutlier(t *testing.T) {
ps := seedIssue1285Repro(t)
r := ps.GetNodeClockSkew("RTCRESET")
if r == nil {
t.Fatal("expected clock skew result")
}
if r.RecentBadSampleCount != 0 {
t.Errorf("RecentBadSampleCount = %d, want 0 — recent samples are all "+
"~20s (healthy); the historical RTC-reset outlier is outside the "+
"recent window and must not be counted", r.RecentBadSampleCount)
}
if r.Severity == SkewBimodalClock || r.Severity == SkewNoClock {
t.Errorf("severity = %v, want ok/warning — recent samples are all "+
"healthy (~20s skew), one historical outlier must not flip the node "+
"to bimodal/no-clock", r.Severity)
}
}
func abs(v float64) float64 {
if v < 0 {
return -v
}
return v
}