Files
fleet/server/errorstore/errors_test.go
T
Nico b0dc97006c Dedupe network errors so usage_statistics cron stops failing (#45142)
**Related issue:** Resolves #42613

Dedupes errors that report HTTP 408 (request timeouts). As of now, I
believe this only fires for timeouts on the
**/api/v1/osquery/distributed/write** endpoint.
This is so that we have a unique error hash with an incrementing count,
instead of thousands of entries each with count: 1, which produces a
huge JSON payload when passed to
https://fleetdm.com/api/v1/webhooks/receive-usage-analytics for
processing.

Trade-off:
- Before: every occurrence got its own Redis entry so thousands of
near-identical examples coexisted.
- After: they collapse into one entry whose :json value still contains a
representative example, but we'd only keep the last IP+Port instead of
all of them.

# Checklist for submitter

- [x] Changes file added for user-visible changes in `changes/`,
`orbit/changes/` or `ee/fleetd-chrome/changes`.
See [Changes
files](https://github.com/fleetdm/fleet/blob/main/docs/Contributing/guides/committing-changes.md#changes-files)
for more information.

## Testing

- [x] Added/updated automated tests

- [x] QA'd all new/changed functionality manually

Build a ~5 MB JSON body in a temporary file:

```bash
{ printf '{"node_key":"'; head -c 5000000 /dev/zero | tr '\0' 'x'; printf '"}'; } > /tmp/distwrite-body.json
```

Clear out redis:

```bash
docker exec fleet-redis-1 redis-cli FLUSHDB
```

Send a dummy request and throttle the upload at 100 KB/s → ~50s to send,
read timeout fires at 25s.
I sent this 3 times and got the "request body read error" error back
after each request.

```bash
curl -sk --limit-rate 100K -X POST -H 'Content-Type: application/json' --data-binary @/tmp/distwrite-body.json https://127.0.0.1:8080/api/v1/osquery/distributed/write

{
  "error": "request body read error: i/o timeout",
  "uuid": "95937f50-1008-4625-9423-bc19c7be6818"
}
```

Count the error keys containing "request body read error" as the value. 

```bash
docker exec fleet-redis-1 sh -c 'for k in $(redis-cli --scan --pattern "error:*:json"); do v=$(redis-cli GET "$k"); echo "$v" | grep -q "request body read error" && echo "$k count=$(redis-cli GET "${k%:json}:count")"; done'\

error:{Cco_JmAdBVVVJI9k0XjNNUCmG0z1IKguMQD4VDaejfc=}:json count=3
```

Notice the single entry and count=3 (since I ran the dummy request 3
times).

Running this on main outputs three entries each with count=1.


<!-- This is an auto-generated comment: release notes by coderabbit.ai
-->

## Summary by CodeRabbit

* **Bug Fixes**
* Network error deduplication for request-timeout errors now normalizes
socket addresses, preventing the usage statistics cron from failing when
many similar network errors accumulate.

[![Review Change
Stack](https://storage.googleapis.com/coderabbit_public_assets/review-stack-in-coderabbit-ui.svg)](https://app.coderabbit.ai/change-stack/fleetdm/fleet/pull/45142)

<!-- end of auto-generated comment: release notes by coderabbit.ai -->
2026-05-11 22:21:57 +02:00

490 lines
15 KiB
Go

package errorstore
import (
"context"
"database/sql"
"encoding/json"
"errors"
"fmt"
"io"
"log/slog"
"net/http"
"net/http/httptest"
"os"
"regexp"
"sort"
"strings"
"sync/atomic"
"testing"
"time"
"github.com/fleetdm/fleet/v4/server/contexts/ctxerr"
"github.com/fleetdm/fleet/v4/server/datastore/redis/redistest"
"github.com/fleetdm/fleet/v4/server/fleet"
pkgErrors "github.com/pkg/errors" //nolint:depguard
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
var (
eh = ctxerr.MockHandler{}
ctxb = context.Background()
ctx = ctxerr.NewContext(ctxb, eh)
)
func alwaysErrors() error { return pkgErrors.New("always errors") }
func alwaysCallsAlwaysErrors() error { return alwaysErrors() }
func alwaysFleetErrors() error { return ctxerr.New(ctx, "always fleet errors") }
func alwaysNewError(eh *Handler) error {
err := ctxerr.New(ctx, "always new errors")
eh.Store(err)
return err
}
func alwaysNewErrorTwo(eh *Handler) error {
err := ctxerr.New(ctx, "always new errors two")
eh.Store(err)
return err
}
func alwaysWrappedErr() error { return ctxerr.Wrap(ctx, io.EOF, "always EOF") }
// statusErr is a test fixture that implements the statusCoder interface
// hashError checks against, so we can exercise the request-timeout-only
// normalization path without importing service.OsqueryError (which would
// be a circular import).
type statusErr struct {
msg string
status int
}
func (e *statusErr) Error() string { return e.msg }
func (e *statusErr) Status() int { return e.status }
func TestHashErr(t *testing.T) {
t.Run("without stack trace, same error is same hash", func(t *testing.T) {
err1 := alwaysErrors()
err2 := alwaysCallsAlwaysErrors()
assert.Equal(t, hashError(err1), hashError(err2))
})
t.Run("different location, same error is different hash", func(t *testing.T) {
err1 := alwaysFleetErrors()
err2 := alwaysFleetErrors()
assert.NotEqual(t, hashError(err1), hashError(err2))
})
t.Run("same error, wrapped, same hash", func(t *testing.T) {
ferror1 := alwaysFleetErrors()
w1, w2 := fmt.Errorf("wrap: %w", ferror1), pkgErrors.Wrap(ferror1, "wrap")
h1, h2 := hashError(w1), hashError(w2)
assert.Equal(t, h1, h2)
})
t.Run("generates json", func(t *testing.T) {
var m []interface{}
generatedErr := pkgErrors.New("some err")
res, jsonBytes, err := hashAndMarshalError(generatedErr)
require.NoError(t, err)
assert.Equal(t, "mWoqz7iS1IPOZXGhpzHLl_DVQOyemWxCmvkpLz8uEZk=", res)
require.NoError(t, json.Unmarshal([]byte(jsonBytes), &m))
generatedErr2 := pkgErrors.New("some other err")
res, jsonBytes, err = hashAndMarshalError(generatedErr2)
require.NoError(t, err)
assert.Equal(t, "8AXruOzQmQLF4H3SrzLxXSwFQgZ8DcbkoF1owo0RhTs=", res)
require.NoError(t, json.Unmarshal([]byte(jsonBytes), &m))
})
}
func TestHashErrFleetError(t *testing.T) {
t.Run("Marshal", func(t *testing.T) {
var m []interface{}
generatedErr := ctxerr.New(ctx, "some err")
res, jsonBytes, err := hashAndMarshalError(generatedErr)
require.NoError(t, err)
assert.NotEmpty(t, res)
require.NoError(t, json.Unmarshal([]byte(jsonBytes), &m))
})
t.Run("HashWrapped", func(t *testing.T) {
// hashing a fleet error that wraps a root error hashes to the same
// value if it is from the same location, even if wrapped differently
// afterwards.
err := alwaysWrappedErr()
werr1, werr2 := pkgErrors.Wrap(err, "wrap pkg"), fmt.Errorf("wrap fmt: %w", err)
wantHash := hashError(err)
h1, h2 := hashError(werr1), hashError(werr2)
assert.Equal(t, wantHash, h1)
assert.Equal(t, wantHash, h2)
})
t.Run("HashNew", func(t *testing.T) {
err := alwaysFleetErrors()
werr := ctxerr.Wrap(ctx, err, "wrap ctxterr")
werr1, werr2 := pkgErrors.Wrap(err, "wrap pkg"), fmt.Errorf("wrap fmt: %w", err)
wantHash := hashError(err)
h0, h1, h2 := hashError(werr), hashError(werr1), hashError(werr2)
assert.Equal(t, wantHash, h0)
assert.Equal(t, wantHash, h1)
assert.Equal(t, wantHash, h2)
})
t.Run("HashSameRootDifferentLocation", func(t *testing.T) {
err1 := alwaysWrappedErr()
err2 := func() error { return ctxerr.Wrap(ctx, io.EOF, "always EOF") }()
err3 := func() error { return ctxerr.Wrap(ctx, io.EOF, "always EOF") }()
h1, h2, h3 := hashError(err1), hashError(err2), hashError(err3)
assert.NotEqual(t, h1, h2)
assert.NotEqual(t, h1, h3)
assert.NotEqual(t, h2, h3)
})
t.Run("request-timeout errors use the same hash if their content differs only by the socket address (IPv4)", func(t *testing.T) {
err1 := &statusErr{msg: "read tcp 10.10.3.44:8080->10.10.11.251:55732: i/o timeout", status: http.StatusRequestTimeout}
err2 := &statusErr{msg: "read tcp 10.10.3.44:8080->10.10.11.251:61204: i/o timeout", status: http.StatusRequestTimeout}
err3 := &statusErr{msg: "read tcp 10.10.3.44:8080->10.10.11.251:38891: i/o timeout", status: http.StatusRequestTimeout}
h1, h2, h3 := hashError(err1), hashError(err2), hashError(err3)
assert.Equal(t, h1, h2)
assert.Equal(t, h1, h3)
})
t.Run("request-timeout errors use the same hash if their content differs only by the socket address (IPv6)", func(t *testing.T) {
err1 := &statusErr{msg: "read tcp [::1]:8080->[fe80::1]:55732: i/o timeout", status: http.StatusRequestTimeout}
err2 := &statusErr{msg: "read tcp [::1]:8080->[fe80::1]:61204: i/o timeout", status: http.StatusRequestTimeout}
assert.Equal(t, hashError(err1), hashError(err2))
})
t.Run("request-timeout errors use different hashes if the non-socket-address content differs", func(t *testing.T) {
err1 := &statusErr{msg: "read tcp 10.0.0.1:80->10.0.0.2:55732: i/o timeout", status: http.StatusRequestTimeout}
err2 := &statusErr{msg: "read tcp 10.0.0.1:80->10.0.0.2:55732: context deadline exceeded", status: http.StatusRequestTimeout}
assert.NotEqual(t, hashError(err1), hashError(err2))
})
t.Run("non-timeout errors are NOT normalized by socket address", func(t *testing.T) {
err1 := &statusErr{msg: "read tcp 10.0.0.1:80->10.0.0.2:55732: connection refused", status: http.StatusInternalServerError}
err2 := &statusErr{msg: "read tcp 10.0.0.1:80->10.0.0.2:61204: connection refused", status: http.StatusInternalServerError}
assert.NotEqual(t, hashError(err1), hashError(err2))
})
t.Run("errors without a Status() method are NOT normalized by socket address", func(t *testing.T) {
err1 := errors.New("read tcp 10.0.0.1:80->10.0.0.2:55732: i/o timeout")
err2 := errors.New("read tcp 10.0.0.1:80->10.0.0.2:61204: i/o timeout")
assert.NotEqual(t, hashError(err1), hashError(err2))
})
}
func TestUnwrapAll(t *testing.T) {
root := sql.ErrNoRows
werr := pkgErrors.Wrap(root, "pkg wrap")
gerr := fmt.Errorf("fmt wrap: %w", werr)
eerr := ctxerr.Wrap(ctx, gerr, "fleet wrap")
eerr2 := ctxerr.Wrap(ctx, eerr, "fleet wrap 2")
uw := ctxerr.Cause(eerr2)
assert.Equal(t, uw, root)
assert.Nil(t, ctxerr.Cause(nil))
}
func TestErrorHandler(t *testing.T) {
t.Run("works if the error handler is down", func(t *testing.T) {
ctx, cancel := context.WithCancel(context.Background())
cancel() // cancel immediately
eh := newTestHandler(ctx, nil, slog.New(slog.DiscardHandler), time.Minute, nil, nil)
doneCh := make(chan struct{})
go func() {
eh.Store(pkgErrors.New("test"))
close(doneCh)
}()
// should not even block in the call to Store as there is no handler running
ticker := time.NewTicker(1 * time.Second)
select {
case <-doneCh:
case <-ticker.C:
t.FailNow()
}
})
t.Run("works if the error storage is disabled", func(t *testing.T) {
eh := newTestHandler(context.Background(), nil, slog.New(slog.DiscardHandler), -1, nil, nil)
doneCh := make(chan struct{})
go func() {
eh.Store(pkgErrors.New("test"))
close(doneCh)
}()
// should not even block in the call to Store as there is no handler running
ticker := time.NewTicker(1 * time.Second)
select {
case <-doneCh:
case <-ticker.C:
t.FailNow()
}
})
wd, err := os.Getwd()
require.NoError(t, err)
wd = regexp.QuoteMeta(wd)
t.Run("standalone", func(t *testing.T) {
pool := redistest.SetupRedis(t, "error:", false, false, false)
t.Run("collects errors", func(t *testing.T) { testErrorHandlerCollectsErrors(t, pool, wd, false) })
t.Run("collects different errors", func(t *testing.T) { testErrorHandlerCollectsDifferentErrors(t, pool, wd, false) })
})
t.Run("cluster", func(t *testing.T) {
pool := redistest.SetupRedis(t, "error:", true, true, false)
t.Run("collects errors", func(t *testing.T) { testErrorHandlerCollectsErrors(t, pool, wd, false) })
t.Run("collects different errors", func(t *testing.T) { testErrorHandlerCollectsDifferentErrors(t, pool, wd, false) })
})
}
func testErrorHandlerCollectsErrors(t *testing.T, pool fleet.RedisPool, wd string, flush bool) {
ctx, cancelFunc := context.WithCancel(context.Background())
defer cancelFunc()
chGo, chDone := make(chan struct{}), make(chan struct{})
var storeCalls int32 = 3
testOnStart := func() {
close(chGo)
}
testOnStore := func(err error) {
require.NoError(t, err)
if atomic.AddInt32(&storeCalls, -1) == 0 {
close(chDone)
}
}
eh := newTestHandler(ctx, pool, slog.New(slog.DiscardHandler), time.Minute, testOnStart, testOnStore)
<-chGo
for i := 0; i < 3; i++ {
alwaysNewError(eh) //nolint:errcheck
}
<-chDone
errors, err := eh.Retrieve(flush)
require.NoError(t, err)
require.Len(t, errors, 1)
assert.Regexp(t, regexp.MustCompile(`\[
\{
"message": "always new errors",
"data": \{
"timestamp": ".+"
\},
"stack": \[
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.alwaysNewError \(errors_test\.go\:\d+\)",
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.testErrorHandlerCollectsErrors \(errors_test\.go\:\d+\)",
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.TestErrorHandler\.func\d\.\d \(errors_test\.go\:\d+\)",
".+",
".+"
\]
\}
\]`), string(errors[0].Chain))
errors, err = eh.Retrieve(flush)
require.NoError(t, err)
if flush {
assert.Len(t, errors, 0)
} else {
assert.Len(t, errors, 1)
}
// ensure we clear errors before returning
_, err = eh.Retrieve(true)
require.NoError(t, err)
}
func testErrorHandlerCollectsDifferentErrors(t *testing.T, pool fleet.RedisPool, wd string, flush bool) {
ctx, cancelFunc := context.WithCancel(context.Background())
defer cancelFunc()
var storeCalls int32 = 5
chGo, chDone := make(chan struct{}), make(chan struct{})
testOnStart := func() {
close(chGo)
}
testOnStore := func(err error) {
require.NoError(t, err)
if atomic.AddInt32(&storeCalls, -1) == 0 {
close(chDone)
}
}
eh := newTestHandler(ctx, pool, slog.New(slog.DiscardHandler), time.Minute, testOnStart, testOnStore)
<-chGo
// those two errors are different because from a different strack trace
// (different line)
alwaysNewError(eh) //nolint:errcheck
alwaysNewError(eh) //nolint:errcheck
// while those two are the same, only one gets store
for i := 0; i < 2; i++ {
alwaysNewError(eh) //nolint:errcheck
}
alwaysNewErrorTwo(eh) //nolint:errcheck
<-chDone
errors, err := eh.Retrieve(flush)
require.NoError(t, err)
require.Len(t, errors, 4)
// order is not guaranteed by scan keys
for _, jsonErr := range errors {
msg := string(jsonErr.Chain)
if strings.Contains(msg, "new errors two") {
assert.Regexp(t, regexp.MustCompile(`\[
\{
"message": "always new errors two",
"data": \{
"timestamp": ".+"
\},
"stack": \[
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.alwaysNewErrorTwo \(errors_test\.go\:\d+\)",
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.testErrorHandlerCollectsDifferentErrors \(errors_test\.go\:\d+\)",
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.TestErrorHandler\.func\d\.\d \(errors_test\.go\:\d+\)",
".+",
".+"
\]
\}
\]`), msg)
} else {
assert.Regexp(t, regexp.MustCompile(`\[
\{
"message": "always new errors",
"data": \{
"timestamp": ".+"
\},
"stack": \[
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.alwaysNewError \(errors_test\.go\:\d+\)",
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.testErrorHandlerCollectsDifferentErrors \(errors_test\.go\:\d+\)",
"github\.com\/fleetdm\/fleet\/v4\/server\/errorstore\.TestErrorHandler\.func\d.\d \(errors_test\.go\:\d+\)",
".+",
".+"
\]
\}
\]`), msg)
}
}
// ensure we clear errors before returning
_, err = eh.Retrieve(true)
require.NoError(t, err)
}
func TestHttpHandler(t *testing.T) {
setupTest := func(t *testing.T) *Handler {
pool := redistest.SetupRedis(t, "error:", false, false, false)
ctx, cancelFunc := context.WithCancel(context.Background())
defer cancelFunc()
var storeCalls int32 = 3
chGo, chDone := make(chan struct{}), make(chan struct{})
testOnStart := func() {
close(chGo)
}
testOnStore := func(err error) {
require.NoError(t, err)
if atomic.AddInt32(&storeCalls, -1) == 0 {
close(chDone)
}
}
eh := newTestHandler(ctx, pool, slog.New(slog.DiscardHandler), time.Minute, testOnStart, testOnStore)
<-chGo
// simulate two errors, one happening twice
err1 := ctxerr.New(ctx, "err1")
err2 := ctxerr.New(ctx, "err2")
eh.Store(err1)
eh.Store(err2)
eh.Store(err1)
<-chDone
return eh
}
type errResp struct {
Count int
Chain []struct{ Message string }
}
var errs []errResp
sortByCount := func(errs []errResp) {
sort.Slice(errs, func(i, j int) bool {
return errs[i].Count > errs[j].Count
})
}
t.Run("retrieves errors", func(t *testing.T) {
eh := setupTest(t)
req := httptest.NewRequest("GET", "/", nil)
res := httptest.NewRecorder()
eh.ServeHTTP(res, req)
require.Equal(t, res.Code, 200)
require.NoError(t, json.Unmarshal(res.Body.Bytes(), &errs))
require.Len(t, errs, 2)
require.NotEmpty(t, errs[0].Chain[0].Message)
require.NotEmpty(t, errs[1].Chain[0].Message)
sortByCount(errs)
require.Equal(t, 2, errs[0].Count)
require.Equal(t, 1, errs[1].Count)
})
t.Run("flushes errors after retrieving if the flush flag is true", func(t *testing.T) {
eh := setupTest(t)
req := httptest.NewRequest("GET", "/?flush=true", nil)
res := httptest.NewRecorder()
eh.ServeHTTP(res, req)
require.Equal(t, res.Code, 200)
require.NoError(t, json.Unmarshal(res.Body.Bytes(), &errs))
require.Len(t, errs, 2)
require.NotEmpty(t, errs[0].Chain[0].Message)
require.NotEmpty(t, errs[1].Chain[0].Message)
sortByCount(errs)
require.Equal(t, 2, errs[0].Count)
require.Equal(t, 1, errs[1].Count)
req = httptest.NewRequest("GET", "/?flush=true", nil)
res = httptest.NewRecorder()
eh.ServeHTTP(res, req)
require.NoError(t, json.Unmarshal(res.Body.Bytes(), &errs))
require.Len(t, errs, 0)
})
t.Run("fails with correct status code if the flush flag is invalid", func(t *testing.T) {
eh := setupTest(t)
req := httptest.NewRequest("GET", "/?flush=invalid", nil)
res := httptest.NewRecorder()
eh.ServeHTTP(res, req)
require.Equal(t, res.Code, 400)
})
}