Skip to content

Commit d58e35d

Browse files
authored
feat(errortracking): add core error-tracking package (#52485)
> **Stacked PR 1/4** — part of [#50607](#50607). Review this slice before stack 2. ### What does this PR do? Introduces `pkg/util/log/errortracking/`, the foundational package for forwarding Agent `ERROR` logs to internal telemetry. This package is self-contained (stdlib-only) and defines the vocabulary used by the rest of the stack: - `ErrorLog` — value-typed snapshot of an error log record (time, level, message, PC, attrs) - `Submitter` — atomically-loaded callback type; non-blocking on the hot path - `Handler` — `slog.Handler` that filters `Level >= Error`, builds an `ErrorLog`, and calls the installed `Submitter`. No queueing, no batching, no retry. - `Bouncer` — deduplication/windowing logic that collapses repeated error stacks within a configurable time window ### Motivation Part of AGTHEAL-15: Datadog Engineers need to monitor Agent error patterns at scale. Error log payloads drop the message to avoid leaking sensitive data and collect the full Go call stack. ### Stack 1. **This PR** — core `pkg/util/log/errortracking/` package 2. [stack-2] Agent telemetry component extensions + sender refactor 3. [stack-3] Config, log-setup wiring, agent run command 4. [stack-4] FakeIntake infrastructure + E2E tests + CI Co-authored-by: paola.ducolin <paola.ducolin@datadoghq.com>
1 parent 62b2921 commit d58e35d

7 files changed

Lines changed: 1144 additions & 0 deletions

File tree

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
load("@rules_go//go:def.bzl", "go_library", "go_test")
2+
3+
go_library(
4+
name = "errortracking",
5+
srcs = [
6+
"bouncer.go",
7+
"doc.go",
8+
"handler.go",
9+
"types.go",
10+
],
11+
importpath = "github.com/DataDog/datadog-agent/pkg/util/log/errortracking",
12+
visibility = ["//visibility:public"],
13+
)
14+
15+
go_test(
16+
name = "errortracking_test",
17+
srcs = [
18+
"bouncer_test.go",
19+
"handler_test.go",
20+
],
21+
embed = [":errortracking"],
22+
gotags = ["test"],
23+
deps = [
24+
"@com_github_stretchr_testify//assert",
25+
"@com_github_stretchr_testify//require",
26+
],
27+
)
Lines changed: 155 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,155 @@
1+
// Unless explicitly stated otherwise all files in this repository are licensed
2+
// under the Apache License Version 2.0.
3+
// This product includes software developed at Datadog (https://www.datadoghq.com/).
4+
// Copyright 2016-present Datadog, Inc.
5+
6+
package errortracking
7+
8+
import (
9+
"sync"
10+
"time"
11+
)
12+
13+
// Bouncer is a per-key first-sighting deduplicator with a sliding time
14+
// window. The first time a given key is observed inside a window,
15+
// Observe returns suppressed=false with count=1 and the observation
16+
// time as firstSeen. Subsequent observations of the same key inside the
17+
// same window are suppressed (return suppressed=true) and the count is
18+
// incremented. After the window elapses, the next observation returns
19+
// suppressed=false carrying the suppressed count of the prior window
20+
// (priorTotal-1, since the first sighting was already delivered), then
21+
// resets the entry to a fresh count=1. If no sightings were suppressed
22+
// (priorTotal==1), the rollover is silent and the next observation is
23+
// treated as a fresh first sighting (count=1).
24+
//
25+
// The key is an opaque uint64 — the caller is responsible for choosing
26+
// it. Today's caller (Handler.Handle) hashes the captured stack PCs
27+
// with FNV-1a so two distinct stacks reaching the same terminal
28+
// function are NOT collapsed into the same bouncer entry.
29+
//
30+
// The 15-minute default at the agent call site
31+
// (agent_telemetry.errortracking.bouncer_window_seconds) was chosen so a hot
32+
// bug path collapses to one record per quarter-hour — long enough to avoid
33+
// flooding the wire, short enough that operators see new error patterns
34+
// promptly. A hot bug path with N sightings per window ships Count=1 at
35+
// first sighting, then Count=N-1 on rollover (the suppressed portion).
36+
// Summing both gives N without double-counting the first sighting.
37+
//
38+
// Bouncer is purpose-built rather than reusing the global
39+
// rate.Sometimes wrapper in pkg/util/log/log_limit.go — that primitive
40+
// is keyless (one Limit per call site), whereas we need per-key state
41+
// and need to expose the per-key count. The implementation is a small
42+
// mutex-protected map with a periodic prune to bound memory; total
43+
// entries are capped so a pathological input cannot blow up memory.
44+
//
45+
// The zero value is NOT usable; construct via NewBouncer. Observe is
46+
// safe for concurrent use.
47+
type Bouncer struct {
48+
window time.Duration
49+
maxEntries int
50+
51+
mu sync.Mutex
52+
entries map[uint64]*bouncerEntry
53+
}
54+
55+
type bouncerEntry struct {
56+
firstSeen time.Time
57+
lastSeen time.Time
58+
count uint32
59+
}
60+
61+
// NewBouncer returns a Bouncer with the given sliding-window duration
62+
// and a soft cap on tracked entries. A non-positive window disables
63+
// dedup (Observe always returns suppressed=false with count=1); a
64+
// non-positive maxEntries falls back to a sane default (4096).
65+
func NewBouncer(window time.Duration, maxEntries int) *Bouncer {
66+
if maxEntries <= 0 {
67+
maxEntries = 4096
68+
}
69+
return &Bouncer{
70+
window: window,
71+
maxEntries: maxEntries,
72+
entries: make(map[uint64]*bouncerEntry),
73+
}
74+
}
75+
76+
// Observe records a sighting of the given key at now and returns
77+
// whether the caller should suppress the record, the count to attach to
78+
// the next delivered record (≥ 1), and the firstSeen time of the
79+
// current window.
80+
//
81+
// The first sighting of a key in a window returns suppressed=false,
82+
// count=1, firstSeen=now. Subsequent sightings inside the same window
83+
// return suppressed=true with an incrementing count and the original
84+
// firstSeen. When the window elapses since firstSeen, the next
85+
// sighting returns suppressed=false with count=priorSuppressed (the
86+
// number of sightings that were suppressed in the elapsed window, i.e.
87+
// priorTotal-1), then resets the entry to a fresh count=1. If no
88+
// sightings were suppressed (priorTotal==1), the rollover is silent:
89+
// Observe returns suppressed=false, count=1, as though it were a fresh
90+
// first sighting, avoiding a Count=0 delivery.
91+
//
92+
// This design ensures consumers can sum Count fields without
93+
// double-counting: the first delivery carries Count=1, and the rollover
94+
// carries the remainder.
95+
//
96+
// When window is non-positive, Observe is a pass-through: returns
97+
// suppressed=false, count=1, firstSeen=now.
98+
func (b *Bouncer) Observe(key uint64, now time.Time) (suppressed bool, count uint32, firstSeen time.Time) {
99+
if b.window <= 0 {
100+
return false, 1, now
101+
}
102+
103+
b.mu.Lock()
104+
defer b.mu.Unlock()
105+
106+
if e, ok := b.entries[key]; ok {
107+
if now.Sub(e.firstSeen) > b.window {
108+
// Window elapsed. Deliver the suppressed portion of the prior
109+
// window (priorTotal-1) so callers can sum without
110+
// double-counting the first sighting already delivered.
111+
// When nothing was suppressed (priorTotal==1), skip the
112+
// rollover and treat this as a fresh first sighting.
113+
priorCount := e.count
114+
e.firstSeen = now
115+
e.lastSeen = now
116+
e.count = 1
117+
if priorCount <= 1 {
118+
return false, 1, now
119+
}
120+
return false, priorCount - 1, now
121+
}
122+
e.lastSeen = now
123+
e.count++
124+
return true, e.count, e.firstSeen
125+
}
126+
127+
// New key. Prune opportunistically if at the cap so the map doesn't
128+
// grow unboundedly under pathological churn (many unique keys, each
129+
// appearing once). Re-check after pruning: if all entries are still
130+
// within the window, pruneLocked removes nothing and the cap must be
131+
// enforced by dropping the new key (pass-through, not suppressed).
132+
if len(b.entries) >= b.maxEntries {
133+
b.pruneLocked(now)
134+
if len(b.entries) >= b.maxEntries {
135+
return false, 1, now
136+
}
137+
}
138+
b.entries[key] = &bouncerEntry{
139+
firstSeen: now,
140+
lastSeen: now,
141+
count: 1,
142+
}
143+
return false, 1, now
144+
}
145+
146+
// pruneLocked drops entries whose firstSeen is older than the window.
147+
// Caller MUST hold b.mu. Linear in entry count; runs only on
148+
// near-capacity insert, so amortized cost is bounded.
149+
func (b *Bouncer) pruneLocked(now time.Time) {
150+
for key, e := range b.entries {
151+
if now.Sub(e.firstSeen) > b.window {
152+
delete(b.entries, key)
153+
}
154+
}
155+
}
Lines changed: 177 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,177 @@
1+
// Unless explicitly stated otherwise all files in this repository are licensed
2+
// under the Apache License Version 2.0.
3+
// This product includes software developed at Datadog (https://www.datadoghq.com/).
4+
// Copyright 2016-present Datadog, Inc.
5+
6+
//go:build test
7+
8+
package errortracking
9+
10+
import (
11+
"sync"
12+
"testing"
13+
"time"
14+
15+
"github.com/stretchr/testify/assert"
16+
)
17+
18+
func TestBouncer_FirstSightingNotSuppressed(t *testing.T) {
19+
b := NewBouncer(15*time.Minute, 0)
20+
now := time.Now()
21+
suppressed, count, firstSeen := b.Observe(0xCAFE, now)
22+
assert.False(t, suppressed, "first sighting must NOT be suppressed")
23+
assert.Equal(t, uint32(1), count, "first sighting count")
24+
assert.True(t, firstSeen.Equal(now), "first sighting firstSeen = %v, want %v", firstSeen, now)
25+
}
26+
27+
func TestBouncer_SecondSightingSuppressedInsideWindow(t *testing.T) {
28+
b := NewBouncer(15*time.Minute, 0)
29+
t0 := time.Now()
30+
b.Observe(0xCAFE, t0)
31+
32+
t1 := t0.Add(time.Minute)
33+
suppressed, count, firstSeen := b.Observe(0xCAFE, t1)
34+
assert.True(t, suppressed, "second sighting inside window MUST be suppressed")
35+
assert.Equal(t, uint32(2), count, "second sighting count")
36+
assert.True(t, firstSeen.Equal(t0), "firstSeen drifted: got %v, want original %v", firstSeen, t0)
37+
}
38+
39+
func TestBouncer_ResetsAfterWindow(t *testing.T) {
40+
b := NewBouncer(15*time.Minute, 0)
41+
t0 := time.Now()
42+
b.Observe(0xCAFE, t0) // count=1
43+
b.Observe(0xCAFE, t0.Add(time.Minute)) // count=2 (suppressed)
44+
45+
// Step past the window — next sighting MUST NOT be suppressed and
46+
// MUST carry the suppressed count of the prior window (1 = total-1)
47+
// rather than the full total, to avoid double-counting the first
48+
// sighting already delivered. The entry is then reset to a fresh
49+
// window internally.
50+
t2 := t0.Add(16 * time.Minute)
51+
suppressed, count, firstSeen := b.Observe(0xCAFE, t2)
52+
assert.False(t, suppressed, "sighting after window MUST NOT be suppressed")
53+
assert.Equal(t, uint32(1), count, "post-window count (want suppressed-only: total-1)")
54+
assert.True(t, firstSeen.Equal(t2), "post-window firstSeen = %v, want %v", firstSeen, t2)
55+
}
56+
57+
// TestBouncer_WindowElapseCarriesPriorCount exercises the
58+
// suppressed-count carry-forward contract end-to-end: a hot bug path
59+
// with N sightings per window must deliver Count=1 at first sighting
60+
// and Count=N-1 on rollover (the suppressed sightings), so consumers
61+
// summing both get N without double-counting the first sighting.
62+
func TestBouncer_WindowElapseCarriesPriorCount(t *testing.T) {
63+
b := NewBouncer(15*time.Minute, 0)
64+
var key uint64 = 0xABCDEF
65+
66+
t0 := time.Now()
67+
68+
// First sighting — delivered, count=1.
69+
suppressed, count, _ := b.Observe(key, t0)
70+
assert.False(t, suppressed, "first sighting must NOT be suppressed")
71+
assert.Equal(t, uint32(1), count, "first sighting count")
72+
73+
// Two more sightings within the window — both suppressed.
74+
suppressed, count, _ = b.Observe(key, t0.Add(5*time.Minute))
75+
assert.True(t, suppressed, "sighting inside window MUST be suppressed")
76+
assert.Equal(t, uint32(2), count, "second sighting count")
77+
78+
suppressed, count, _ = b.Observe(key, t0.Add(10*time.Minute))
79+
assert.True(t, suppressed, "sighting inside window MUST be suppressed")
80+
assert.Equal(t, uint32(3), count, "third sighting count")
81+
82+
// Window elapses; next sighting delivers the suppressed count of the
83+
// prior window (2 = total(3) - first-already-delivered(1)).
84+
suppressed, count, _ = b.Observe(key, t0.Add(20*time.Minute))
85+
assert.False(t, suppressed, "window elapsed; sighting must be delivered")
86+
assert.Equal(t, uint32(2), count, "rollover count (want suppressed-only: total-1)")
87+
88+
// Subsequent sighting in the new window — suppressed, count starts
89+
// from the post-reset 1 and increments to 2.
90+
suppressed, count, _ = b.Observe(key, t0.Add(21*time.Minute))
91+
assert.True(t, suppressed, "sighting inside fresh window MUST be suppressed")
92+
assert.Equal(t, uint32(2), count, "post-reset sighting count")
93+
}
94+
95+
func TestBouncer_PerPCIndependent(t *testing.T) {
96+
b := NewBouncer(15*time.Minute, 0)
97+
now := time.Now()
98+
b.Observe(0xCAFE, now)
99+
// A different PC must NOT see the suppression state of 0xCAFE.
100+
suppressed, count, _ := b.Observe(0xBEEF, now)
101+
assert.False(t, suppressed, "different PC must NOT be suppressed by another PC's sighting")
102+
assert.Equal(t, uint32(1), count, "different PC count")
103+
}
104+
105+
func TestBouncer_DisabledWindowPassesThrough(t *testing.T) {
106+
b := NewBouncer(0, 0)
107+
now := time.Now()
108+
for i := 0; i < 5; i++ {
109+
suppressed, count, _ := b.Observe(0xCAFE, now.Add(time.Duration(i)*time.Second))
110+
assert.False(t, suppressed, "disabled window must never suppress (i=%d)", i)
111+
assert.Equal(t, uint32(1), count, "disabled window count (i=%d)", i)
112+
}
113+
}
114+
115+
func TestBouncer_RaceFree_ConcurrentObserve(t *testing.T) {
116+
b := NewBouncer(15*time.Minute, 1024)
117+
const goroutines = 32
118+
const perGoroutine = 1000
119+
120+
var wg sync.WaitGroup
121+
wg.Add(goroutines)
122+
for g := 0; g < goroutines; g++ {
123+
g := g
124+
go func() {
125+
defer wg.Done()
126+
now := time.Now()
127+
for i := 0; i < perGoroutine; i++ {
128+
pc := uint64(g*1000 + i%50) // some overlap to exercise the suppress path
129+
b.Observe(pc, now)
130+
}
131+
}()
132+
}
133+
wg.Wait()
134+
// Survived without -race detecting anything; this is the
135+
// observable for the test (the race detector flags concurrent
136+
// map access or counter races at the failure site, not here).
137+
t.Log("concurrent observe completed without race violation")
138+
}
139+
140+
func TestBouncer_PrunesNearCap(t *testing.T) {
141+
b := NewBouncer(time.Minute, 4)
142+
t0 := time.Now()
143+
// Fill the cap with entries that are about to expire.
144+
for pc := uint64(1); pc <= 4; pc++ {
145+
b.Observe(pc, t0)
146+
}
147+
// All entries are well past their window when we insert one more.
148+
t1 := t0.Add(2 * time.Minute)
149+
b.Observe(uint64(5), t1)
150+
151+
b.mu.Lock()
152+
defer b.mu.Unlock()
153+
assert.LessOrEqual(t, len(b.entries), b.maxEntries, "entries exceeded cap after prune")
154+
}
155+
156+
// TestBouncer_CapEnforced_WhenAllWithinWindow verifies that when the cap
157+
// is reached and pruneLocked removes nothing (all entries still within the
158+
// window), new keys are dropped rather than growing the map past maxEntries.
159+
// The dropped observation is returned as a pass-through (suppressed=false,
160+
// count=1) so the record still reaches the consumer without dedup tracking.
161+
func TestBouncer_CapEnforced_WhenAllWithinWindow(t *testing.T) {
162+
b := NewBouncer(time.Hour, 4) // large window: no entries expire
163+
t0 := time.Now()
164+
for pc := uint64(1); pc <= 4; pc++ {
165+
b.Observe(pc, t0)
166+
}
167+
168+
// New unique key inserted while all existing entries are still within window.
169+
t1 := t0.Add(time.Minute)
170+
suppressed, count, _ := b.Observe(uint64(5), t1)
171+
assert.False(t, suppressed, "dropped key must not be reported as suppressed")
172+
assert.Equal(t, uint32(1), count, "dropped key must return count=1 (pass-through)")
173+
174+
b.mu.Lock()
175+
defer b.mu.Unlock()
176+
assert.LessOrEqual(t, len(b.entries), b.maxEntries, "map must not exceed maxEntries")
177+
}

0 commit comments

Comments
 (0)