mirror of
https://github.com/Kpa-clawbot/meshcore-analyzer.git
synced 2026-06-06 18:11:37 +00:00
Marcel Verdult
498fbc0321
## Problem The ingestor stamps every stored packet with its own ingest-time `time.Now()` (`BuildPacketData` in `db.go`; channel/DM paths in `main.go`), discarding the observer receive time the uploader already puts in the MQTT envelope's `timestamp` field. `MQTTPacketMessage` had no `Timestamp` field and `handleMessage` parsed every envelope field except that one. Observers that buffer packets offline and upload hours later get every buffered packet displayed at upload time, not receive time — a 5-hour deferred upload shows packets 5 hours late. Retained messages and broker backlog hit the same skew. ## Why the envelope timestamp is trustworthy Uploaders stamp `timestamp` when the radio receives the frame and freeze it; the MQTT *message* is published late, but the `timestamp` *field* is not re-stamped at publish. A buffered packet uploaded hours late still carries its true receive time. ## Fix New `resolveRxTime` helper reads `msg["timestamp"]` and falls back to `time.Now()` only when it is missing, unparseable, or implausibly in the future. Applied to all three ingest paths (raw packet, channel, DM). No wire-format change — the field already exists. Channel/DM dedup hashes intentionally stay on ingest time, since those bridge messages carry no real packet hash and need ingest-unique input. ## Observer/node last_seen correction Packet timestamps must reflect receive time, but observer/node `last_seen` must not. `InsertTransmission` fed `data.Timestamp` (now rxTime) into `observers.last_seen` and `UpsertNode`'s `last_seen`, so a buffered upload could drag both fields backwards, and retained-message replay on MQTT reconnect could flash long-offline observers as Online. - `UpsertObserverAt` takes an explicit `lastSeen`; the status-packet and BLE companion handlers pass the resolved rxTime. `UpsertObserver` keeps its wall-clock behaviour for other callers. - All three `last_seen` writes are guarded with `MAX(MIN(existing, ingestNow), rxTime)`: `last_seen` never moves backwards from a stale retained message, and never locks in a future value. ## Naive UTC+N timestamps `resolveRxTime` rejects a timestamp only when it is >14h ahead (UTC+14 is the maximum standard offset — anything further is a genuine clock error). A timestamp that is merely in the future is soft-clamped to ingest time: a future rxTime means a live packet from a UTC+N observer whose naive local clock parses as-if UTC, not a buffered packet, so ingest time is correct and no future timestamp reaches the DB. For buffered packets from naive-clock uploaders a bounded residual offset remains (equal to the observer's UTC offset); uploaders emitting zone-aware ISO8601 everywhere would be the full cure but is a separate format change. ## Test `cmd/ingestor/rxtime_test.go` covers `parseEnvelopeTime` (zone-aware, naive, microseconds, garbage, empty) and `resolveRxTime` (plausible past used verbatim, missing/garbage/future → ingest-time fallback). The existing `TestBuildPacketData` is updated to supply an envelope timestamp and assert it propagates, since `BuildPacketData` no longer self-stamps.
81 lines
2.5 KiB
Go
81 lines
2.5 KiB
Go
package main
|
|
|
|
import (
|
|
"testing"
|
|
"time"
|
|
)
|
|
|
|
func TestParseEnvelopeTime(t *testing.T) {
|
|
cases := []struct {
|
|
name string
|
|
in string
|
|
ok bool
|
|
}{
|
|
{"rfc3339 utc", "2026-05-16T10:00:00Z", true},
|
|
{"rfc3339 offset", "2026-05-16T12:00:00+02:00", true},
|
|
{"naive iso", "2026-05-16T10:00:00", true},
|
|
{"naive iso micros", "2026-05-16T10:00:00.123456", true},
|
|
{"garbage", "not-a-time", false},
|
|
{"empty", "", false},
|
|
}
|
|
for _, c := range cases {
|
|
t.Run(c.name, func(t *testing.T) {
|
|
_, err := parseEnvelopeTime(c.in)
|
|
if (err == nil) != c.ok {
|
|
t.Fatalf("parseEnvelopeTime(%q): want ok=%v, got err=%v", c.in, c.ok, err)
|
|
}
|
|
})
|
|
}
|
|
}
|
|
|
|
func TestResolveRxTime(t *testing.T) {
|
|
now := time.Now().UTC()
|
|
|
|
mustParse := func(s string) time.Time {
|
|
t.Helper()
|
|
parsed, err := time.Parse(time.RFC3339, s)
|
|
if err != nil {
|
|
t.Fatalf("result %q is not RFC3339: %v", s, err)
|
|
}
|
|
return parsed
|
|
}
|
|
nearNow := func(s string) bool {
|
|
d := mustParse(s).Sub(now)
|
|
if d < 0 {
|
|
d = -d
|
|
}
|
|
return d <= time.Minute
|
|
}
|
|
|
|
rx := now.Add(-5 * time.Hour).Format(time.RFC3339)
|
|
if got := resolveRxTime(map[string]interface{}{"timestamp": rx}, "test"); got != rx {
|
|
t.Errorf("plausible past timestamp: got %q want %q", got, rx)
|
|
}
|
|
if got := resolveRxTime(map[string]interface{}{}, "test"); !nearNow(got) {
|
|
t.Errorf("missing timestamp: got %q, expected ~now", got)
|
|
}
|
|
if got := resolveRxTime(map[string]interface{}{"timestamp": "garbage"}, "test"); !nearNow(got) {
|
|
t.Errorf("garbage timestamp: got %q, expected ~now", got)
|
|
}
|
|
future := now.Add(48 * time.Hour).Format(time.RFC3339)
|
|
if got := resolveRxTime(map[string]interface{}{"timestamp": future}, "test"); !nearNow(got) {
|
|
t.Errorf("future timestamp: got %q, expected ~now (rejected)", got)
|
|
}
|
|
|
|
// RTC-reset node reporting a factory date — must not drag first_seen back.
|
|
factory := "2020-01-01T00:00:00Z"
|
|
if got := resolveRxTime(map[string]interface{}{"timestamp": factory}, "test"); !nearNow(got) {
|
|
t.Errorf("stale factory timestamp: got %q, expected ~now (rejected)", got)
|
|
}
|
|
// Just past the 30-day floor → rejected.
|
|
stale := now.Add(-31 * 24 * time.Hour).Format(time.RFC3339)
|
|
if got := resolveRxTime(map[string]interface{}{"timestamp": stale}, "test"); !nearNow(got) {
|
|
t.Errorf("stale timestamp >30d: got %q, expected ~now (rejected)", got)
|
|
}
|
|
// Just inside the 30-day floor → used verbatim.
|
|
recent := now.Add(-29 * 24 * time.Hour).Format(time.RFC3339)
|
|
if got := resolveRxTime(map[string]interface{}{"timestamp": recent}, "test"); got != recent {
|
|
t.Errorf("recent timestamp <30d: got %q want %q", got, recent)
|
|
}
|
|
}
|