Out-of-Order Isn't Late: What Building an IoT Ingestion Engine Taught Me About Event-Time Chaos

The scary part about a bug isn't when the numbers look wrong. It's when they look wrong in a way you can talk yourself into accepting. That's what nearly happened building ingest-sentinel, a telemetry ingestion service exploring how to preserve state correctness when sensor events arrive out of order, duplicated, or late. The Setup A FastAPI ingestion endpoint accepts timestamped events from simulated IoT devices. Three invariants must hold regardless of delivery chaos: - Deduplication: The same event ID arriving twice cannot be counted twice in running aggregates. - Out-of-order handling: An older event arriving after a newer one cannot overwrite the current "latest reading," but must still be folded into historical aggregates and chronological logs. - Late-arrival window policy: Events older than 5 minutes are deterministically rejected, counted separately, and isolated from aggregates. The Clean, Deterministic Proof I built a small 6-event ground-truth test first: a handful of valid readings, one duplicate, one out-of-order pair, and one deliberately stale event, delivered in shuffled order. Because the dataset was small, the math was verifiable by hand. The final stored state matched ground truth down to the decimal: 3 accepted readings, 2 out-of-order corrections, 1 late rejection, correct sum, correct average, and correct latest reading. Clean pass. Then I Ran It at Volume, and the Dashboard Didn't Match the Story To verify the same mechanics under continuous volume, I pointed the fleet simulator at the service: thousands of events across multiple devices, aggressive temporal jitter, and randomized delivery order. I pulled up the Grafana dashboard during the burst, and my stomach dropped. The panel tracking Ingested Events by Status showed late_rejected , drawn as a blue line, climbing straight up into the thousands, closely hugging total volume. My ground-truth design expected late rejections to be rare edge cases (about 1-2 per burst). A dashboard showing thousands of late rejections meant one of two things: either my sliding lateness window had a severe temporal drift bug, or the visualization was lying to me. The confusing initial panel: Grafana visually rendered the blue line climbing past 2,500, giving the illusion that late rejections were scaling with total traffic. The Explanation That Wasn't an Explanation My initial internal rationalization was seductive: "The accepted line and the late-rejected line trace almost the exact same path, so it's probably an artifact of the test run." That wasn't a root-cause explanation. That was just describing the visual symptom back to myself in confident language. I came dangerously close to rationalizing it away in the documentation and moving on. It didn't hold up. If two mutually exclusive categories (accepted vs. late_rejected ) are climbing along the same trajectory, that's not "fine." Either the API is dropping valid data, or the metrics pipeline is broken. Finding the Real Culprit: Prometheus vs. Grafana Instead of trusting the visualization, I bypassed Grafana and queried the raw Prometheus TSDB directly: curl -s http://127.0.0.1:9090/api/v1/query?query=telemetry_events_ingested_total | jq . The raw numbers told a completely different story: { "status": "accepted", "value": "2980" "status": "duplicate_ignored", "value": "20" "status": "late_rejected", "value": "20" } The ingestion service wasn't broken at all. accepted was sitting at 2,980, while late_rejected was exactly 20. So why did the blue line look like it was at 3,000? Two configuration traps in Grafana were working together: Series Stacking was set to Normal: Rather than plotting each line from zero on the Y-axis, Grafana was stacking them. It drew the 2,980 green accepted events first, added the 20 yellow duplicate events on top, and capped it off by drawing the 20 blue late-rejected events at the very peak (y = 3,020). Legend Formatting was set to a default placeholder ( {{label_name}} ): Because the legend didn't properly parse{{status}} , the truncated labels obscured which metric belonged to which line. The true distribution: accepted events (green) scale past 8,000, while late rejections (blue) and duplicate retries (yellow) remain flat at baseline. The visual peak was an illusion created by a 20-count series riding on top of a 3,000-count baseline. Meanwhile, the out-of-order counter actually did climb legitimately into the thousands. Out-of-order arrivals (blue) climb past 8,000 as expected, driven by full array shuffling in the simulator. The simulator generated sequential timestamps and applied random.shuffle() across the entire batch. In an array of hundreds of strictly increasing timestamps, shuffling guarantees that almost every subsequent packet arrives behind an already-seen timestamp. The service caught and handled every single out-of-order packet cleanly. Why This Mattered Fixing the dashboard took two minutes: switch Stacking to None and set the legend alias to {{status}} . The green line shot to the top, and the yellow and blue lines dropped flat to the baseline where they belonged. The takeaway isn't about Grafana quirks. It's about how easily engineers accept bad visual data when they don't audit the underlying state. A plausible-sounding rationalization is often just intellectual laziness masking a discrepancy. When your metrics contradict your domain model's invariants, never trust the graph. Query the raw datastore, find the exact mathematical ground truth, and don't accept an explanation until you can point to the mechanism that caused it. Top comments (0)