package alerts_test import ( "bytes" "context" "encoding/json" "fmt" "io" "log/slog" "net/http" "net/http/httptest" "net/netip" "net/url" "reflect" "slices" "strings" "sync" "testing" "testing/synctest" "time" "sneak.berlin/go/smallwebwaf/internal/alerts" ) // The tests run in a synctest bubble, where the time package runs on a // clock of the test's own, which starts at 2000-01-01T00:00:00Z, the start // of an hour: a wait lasts exactly as long as it should, however slowly // the test process runs, and synctest.Wait returns once the queue has // done all it can before time passes. The stand-in for the webhook // answers without the network, since a request waiting on the network // would keep that clock from moving on. const ( // webhookURL is where the alerts are posted. webhookURL = "https://alerts.example/smallwebwaf?team=ops" // instance is the instance name every alert gives. instance = "fsn1app1/gitea" // started is when each test starts, as an alert gives it, and // anHourOn an hour later. started = "2000-01-01T00:00:00Z" anHourOn = "2000-01-01T01:00:00Z" // cooldown is the cooldown of most tests, the default. cooldown = 15 * time.Minute ) func TestAlertIsPostedAsJSONWithItsFieldsAndTheHeaders(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.WebhookHeaders = http.Header{ "Authorization": {"Bearer 0123456789abcdef"}, "X-Team": {"ops"}, } webhook, q := start(t, params) q.Raise(alerts.Alert{ Event: alerts.EventBan, Client: netip.MustParseAddr("203.0.113.9"), Netblock: netip.MustParsePrefix("203.0.113.0/24"), Country: "DE", Reason: "requests per minute over the limit of 1000", Detail: map[string]any{"cause": "limit", "ban_expires": anHourOn}, }) synctest.Wait() got := webhook.received() if len(got) != 1 { t.Fatalf("the webhook had %d requests, want 1", len(got)) } if got[0].method != http.MethodPost || got[0].url != webhookURL { t.Errorf("request %s %s, want POST %s", got[0].method, got[0].url, webhookURL) } for name, want := range map[string]string{ "Content-Type": "application/json", "Authorization": "Bearer 0123456789abcdef", "X-Team": "ops", } { if got[0].header.Get(name) != want { t.Errorf("header %s is %q, want %q", name, got[0].header.Get(name), want) } } wantAlert(t, got[0].alert, map[string]any{ "instance": instance, "time": started, "event": "ban", "client": "203.0.113.9", "netblock": "203.0.113.0/24", "asn": "", "as_name": "", "country": "DE", "reason": "requests per minute over the limit of 1000", "detail": map[string]any{"cause": "limit", "ban_expires": anHourOn}, "suppressed_repeats": float64(0), }) wantCounts(t, q, 1, 0, 0, 0) }) } func TestOnlyTheChosenEventsAreSent(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.Events = []string{alerts.EventSourceFailure, alerts.EventFileError} webhook, q := start(t, params) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) q.Raise(alerts.Alert{Event: alerts.EventFileError, Reason: "a file error"}) q.Raise(alerts.Alert{Event: alerts.EventPermanentBan, Netblock: netblock(1)}) synctest.Wait() wantEvents(t, webhook, alerts.EventFileError) wantCounts(t, q, 1, 0, 0, 0) }) } func TestWouldSendOnlyForTheChosenEvents(t *testing.T) { t.Parallel() params := newParams() params.Events = []string{alerts.EventSourceFailure, alerts.EventFileError} q := alerts.New(params) if q.WouldSend(alerts.EventBan, netblock(1)) || q.WouldSend(alerts.EventPermanentBan, netblock(1)) { t.Error("a ban alert would be sent, though SWWAF_ALERT_EVENTS leaves it out") } if !q.WouldSend(alerts.EventFileError, netip.Prefix{}) { t.Error("a file_error alert would not be sent") } } func TestNothingIsQueuedWithoutAWebhook(t *testing.T) { t.Parallel() params := newParams() params.WebhookURL = nil q := alerts.New(params) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) if waiting := q.Snapshot().Waiting; len(waiting) != 0 { t.Errorf("%d alerts wait, want none", len(waiting)) } } func TestWouldSendNothingWithoutAWebhook(t *testing.T) { t.Parallel() params := newParams() params.WebhookURL = nil q := alerts.New(params) if q.WouldSend(alerts.EventBan, netblock(1)) { t.Error("an alert would be sent with no webhook set") } } func TestRepeatWithinTheCooldownIsHeldBackAndCountedInTheNext(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { webhook, q := start(t, newParams()) raise := func(event string, n int) { q.Raise(alerts.Alert{Event: event, Netblock: netblock(n)}) } raise(alerts.EventBan, 1) // The same event on the same netblock is a repeat; another netblock // or another event is not. time.Sleep(time.Minute) raise(alerts.EventBan, 1) raise(alerts.EventBan, 2) raise(alerts.EventPermanentBan, 1) time.Sleep(cooldown - time.Minute - time.Nanosecond) raise(alerts.EventBan, 1) // Once the cooldown has run out, the next one is sent with the // count of those held back. time.Sleep(time.Nanosecond) raise(alerts.EventBan, 1) // And starts the cooldown again. time.Sleep(time.Minute) raise(alerts.EventBan, 1) synctest.Wait() got := webhook.received() wantEvents(t, webhook, alerts.EventBan, alerts.EventBan, alerts.EventPermanentBan, alerts.EventBan) for i, want := range []struct { netblock int repeats float64 }{{1, 0}, {2, 0}, {1, 0}, {1, 2}} { alert := got[i].alert if alert["netblock"] != netblock(want.netblock).String() || alert["suppressed_repeats"] != want.repeats { t.Errorf("alert %d is for %v with %v repeats, want %s with %v", i, alert["netblock"], alert["suppressed_repeats"], netblock(want.netblock), want.repeats) } } wantCounts(t, q, 4, 0, 3, 0) }) } func TestFileErrorAndSourceFailureRepeatOnlyForTheSameFileOrSource(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() webhook, q := start(t, params) fileError := func(file string) alerts.Alert { return alerts.Alert{ Event: alerts.EventFileError, Detail: map[string]any{"file": file, "error": "line 2: an error"}, } } sourceFailure := func(source string) alerts.Alert { return alerts.Alert{ Event: alerts.EventSourceFailure, Detail: map[string]any{"source": source}, } } // Another file, or another source, is no repeat. q.Raise(fileError("/rules.d/50-a.rules")) q.Raise(fileError("/rules.d/50-b.rules")) q.Raise(fileError("/rules.d/50-a.rules")) q.Raise(sourceFailure("geojs")) q.Raise(sourceFailure("abuseipdb")) q.Raise(sourceFailure("geojs")) synctest.Wait() // Each alert is named by its file, or its source. got := make([]string, 0, len(webhook.received())) for _, request := range webhook.received() { detail, _ := request.alert["detail"].(map[string]any) file, _ := detail["file"].(string) source, _ := detail["source"].(string) got = append(got, file+source) } want := []string{ "/rules.d/50-a.rules", "/rules.d/50-b.rules", "geojs", "abuseipdb", } if !slices.Equal(got, want) { t.Errorf("the webhook was sent alerts for %v, want %v", got, want) } wantCounts(t, q, 4, 0, 2, 0) // alerts.json keeps each file's cooldown: a new queue holds back // the next for the first file, and sends the one for a third. after := alerts.New(params) after.Load(roundTrip(t, q.Snapshot())) after.Raise(fileError("/rules.d/50-a.rules")) after.Raise(fileError("/rules.d/50-c.rules")) waiting := after.Snapshot().Waiting if len(waiting) != 1 || waiting[0].Detail["file"] != "/rules.d/50-c.rules" { t.Errorf("after loading, alerts wait %+v, want the one for 50-c.rules", waiting) } }) } func TestNoCooldownSendsEveryRepeat(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.Cooldown = 0 webhook, q := start(t, params) for range 3 { q.Raise(alerts.Alert{Event: alerts.EventFileError}) time.Sleep(time.Minute) } synctest.Wait() wantEvents(t, webhook, alerts.EventFileError, alerts.EventFileError, alerts.EventFileError) wantCounts(t, q, 3, 0, 0, 0) }) } func TestAlertsPastTheHourlyLimitAreRolledIntoOneSummary(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.MaxPerHour = 2 webhook, q := start(t, params) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(2)}) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(3)}) q.Raise(alerts.Alert{Event: alerts.EventPermanentBan, Netblock: netblock(4)}) q.Raise(alerts.Alert{Event: alerts.EventFileError}) // The summary is sent as the hour ends, and not before. time.Sleep(time.Hour - time.Nanosecond) synctest.Wait() wantEvents(t, webhook, alerts.EventBan, alerts.EventBan) time.Sleep(time.Nanosecond) synctest.Wait() wantEvents(t, webhook, alerts.EventBan, alerts.EventBan, alerts.EventSummary) summary := webhook.received()[2].alert wantAlert(t, summary, map[string]any{ "instance": instance, "time": anHourOn, "event": "summary", "client": "", "netblock": "", "asn": "", "as_name": "", "country": "", "reason": "3 alerts held back in the hour from 2000-01-01T00:00:00Z, " + "past the 2 an hour SWWAF_ALERT_MAX_PER_HOUR allows", "detail": map[string]any{ "hour": started, "count": float64(3), "events": map[string]any{ "ban": float64(1), "permanent_ban": float64(1), "file_error": float64(1), }, }, "suppressed_repeats": float64(0), }) // The next hour sends alerts again, and, with none held back, ends // without a summary. q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(5)}) time.Sleep(time.Hour) synctest.Wait() wantEvents(t, webhook, alerts.EventBan, alerts.EventBan, alerts.EventSummary, alerts.EventBan) wantCounts(t, q, 4, 0, 3, 0) }) } func TestRepeatsBeforeAnAlertPastTheHourlyLimitAreGivenByTheNextSent(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.MaxPerHour = 1 webhook, q := start(t, params) raise := func() { q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) } // The hour's one alert, and two repeats the cooldown holds back. raise() raise() raise() // Once the cooldown has run out, the next is past the hourly limit. time.Sleep(cooldown) raise() // The next hour's first alert gives the two repeats, and the summary // the alert past the limit. time.Sleep(time.Hour - cooldown) synctest.Wait() raise() synctest.Wait() wantEvents(t, webhook, alerts.EventBan, alerts.EventSummary, alerts.EventBan) got := webhook.received() if len(got) == 3 { detail, _ := got[1].alert["detail"].(map[string]any) repeats := got[2].alert["suppressed_repeats"] if detail["count"] != float64(1) || repeats != float64(2) { t.Errorf("the summary counts %v alerts, and the last alert gives %v "+ "repeats, want 1 and 2", detail["count"], repeats) } } wantCounts(t, q, 3, 0, 3, 0) }) } func TestFailedRequestIsSentAgainWithBackoff(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() log := &lockedBuffer{} params.ProcessLog = slog.New(slog.NewJSONHandler(log, nil)) webhook, q := start(t, params) webhook.set(failing) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) // A second after the first failure, then twice as long after each // further one, up to a minute. time.Sleep(200 * time.Second) synctest.Wait() after := make([]time.Duration, 0, len(webhook.received())) for _, request := range webhook.received() { after = append(after, request.at.Sub(midnight())) } want := []time.Duration{ 0, time.Second, 3 * time.Second, 7 * time.Second, 15 * time.Second, 31 * time.Second, 63 * time.Second, 123 * time.Second, 183 * time.Second, } if !slices.Equal(after, want) { t.Errorf("requests at %v, want %v", after, want) } wantCounts(t, q, 0, int64(len(want)), 0, 0) if !strings.Contains(log.String(), `"msg":"sending an alert to SWWAF_ALERT_WEBHOOK_URL failed"`) { t.Errorf("process log %q names no failure", log.String()) } // Once the webhook answers, the alert is sent, and leaves the // queue. webhook.set(answering) time.Sleep(time.Minute) synctest.Wait() got := webhook.received() if last := got[len(got)-1]; !last.answered || last.alert["netblock"] != netblock(1).String() { t.Errorf("the last request was not the alert, answered") } wantCounts(t, q, 1, int64(len(want)), 0, 0) if waiting := q.Snapshot().Waiting; len(waiting) != 0 { t.Errorf("%d alerts still wait, want none", len(waiting)) } }) } func TestRefusedAlertIsGivenUpAndTheNextSent(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() log := &lockedBuffer{} params.ProcessLog = slog.New(slog.NewJSONHandler(log, nil)) webhook, q := start(t, params) // 429 and 408 are failures, and the alert is sent again; 400 refuses // it, and it is given up. webhook.set(http.StatusTooManyRequests) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) synctest.Wait() webhook.set(http.StatusRequestTimeout) time.Sleep(time.Second) synctest.Wait() webhook.set(refusing) time.Sleep(2 * time.Second) synctest.Wait() // The next alert is sent at once. webhook.set(answering) q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(2)}) time.Sleep(time.Minute) synctest.Wait() // Each request, by when it was sent, and the netblock of its alert. got := make([]string, 0, len(webhook.received())) for _, request := range webhook.received() { block, _ := request.alert["netblock"].(string) got = append(got, request.at.Sub(midnight()).String()+" "+block) } want := []string{ "0s " + netblock(1).String(), "1s " + netblock(1).String(), "3s " + netblock(1).String(), "3s " + netblock(2).String(), } if !slices.Equal(got, want) { t.Errorf("requests %v, want %v", got, want) } wantCounts(t, q, 1, 3, 0, 1) if !strings.Contains(log.String(), `"msg":"gave up an alert SWWAF_ALERT_WEBHOOK_URL refused"`) { t.Errorf("process log %q names no alert given up", log.String()) } }) } func TestFailedRequestIsLoggedWithoutTheURL(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() log := &lockedBuffer{} params.ProcessLog = slog.New(slog.NewJSONHandler(log, nil)) webhook, q := start(t, params) webhook.set(hanging) // The request is abandoned after 10 seconds, with an error from the // HTTP client, which names the URL. q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) time.Sleep(11 * time.Second) synctest.Wait() logged := log.String() if !strings.Contains(logged, `"msg":"sending an alert to SWWAF_ALERT_WEBHOOK_URL failed"`) || strings.Contains(logged, "alerts.example") || strings.Contains(logged, "team=ops") { t.Errorf("process log %q names no failure, or names the URL", logged) } }) } func TestFullQueueDropsTheOldestAndRaiseNeverWaits(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.MaxPerHour = 0 webhook, q := start(t, params) webhook.set(hanging) // The webhook does not answer the first alert, while one more alert // than the queue holds is raised: none waits, and the oldest, the // one the webhook was sent, is dropped. for n := range alerts.QueueSize + 1 { q.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(n)}) if n == 0 { synctest.Wait() } } if took := time.Since(midnight()); took != 0 { t.Errorf("raising the alerts took %s, want no time", took) } wantCounts(t, q, 0, 0, 0, 1) waiting := q.Snapshot().Waiting if len(waiting) != alerts.QueueSize || waiting[0].Netblock != netblock(1) { t.Fatalf("%d alerts wait, the first for %s, want %d, the first for %s", len(waiting), waiting[0].Netblock, alerts.QueueSize, netblock(1)) } // The request is abandoned after 10 seconds, and the webhook, which // answers again, is sent the others, in order, a second later. webhook.set(answering) time.Sleep(11 * time.Second) synctest.Wait() got := webhook.received() if len(got) != alerts.QueueSize+1 || got[0].alert["netblock"] != netblock(0).String() { t.Fatalf("the webhook had %d requests, want %d, the first for %s", len(got), alerts.QueueSize+1, netblock(0)) } for i, request := range got[1:] { if request.alert["netblock"] != netblock(i+1).String() { t.Fatalf("request %d is for %v, want %s", i+1, request.alert["netblock"], netblock(i+1)) } } wantCounts(t, q, alerts.QueueSize, 1, 0, 1) }) } func TestStateLoadedIntoANewQueueCarriesOn(t *testing.T) { t.Parallel() synctest.Test(t, func(t *testing.T) { params := newParams() params.MaxPerHour = 1 before := alerts.New(params) // Not sent: Run is not running. The repeat is held back by the // cooldown, and the file error past the hourly limit. before.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) before.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) before.Raise(alerts.Alert{Event: alerts.EventFileError}) time.Sleep(time.Minute) webhook, after := start(t, params) after.Load(roundTrip(t, before.Snapshot())) // The new queue sends the alert waiting, holds back the repeat as // the cooldown still runs, and sends the summary of the hour. after.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) synctest.Wait() wantEvents(t, webhook, alerts.EventBan) time.Sleep(time.Hour) synctest.Wait() wantEvents(t, webhook, alerts.EventBan, alerts.EventSummary) detail, _ := webhook.received()[1].alert["detail"].(map[string]any) if detail["count"] != float64(1) { t.Errorf("the summary counts %v alerts, want 1", detail["count"]) } // The cooldown has run out, and the next one gives both repeats. after.Raise(alerts.Alert{Event: alerts.EventBan, Netblock: netblock(1)}) synctest.Wait() got := webhook.received() if repeats := got[len(got)-1].alert["suppressed_repeats"]; repeats != float64(2) { t.Errorf("the last alert gives %v repeats, want 2", repeats) } }) } // How the stand-in for the webhook answers: with a status, or, hanging, // not at all, until the request is abandoned. const ( answering = http.StatusNoContent failing = http.StatusServiceUnavailable refusing = http.StatusBadRequest hanging = 0 ) // standIn is a stand-in for the webhook. It notes each request it is // sent. type standIn struct { mu sync.Mutex answers int requests []post } // post is a request the webhook was sent: when, its method, URL and // headers, the alert it carried, and whether the webhook answered it with // a 2xx status. type post struct { at time.Time method string url string header http.Header alert map[string]any answered bool } // RoundTrip has the stand-in answer req, in place of the network. A // request abandoned before the stand-in answers fails, as over the // network. func (s *standIn) RoundTrip(req *http.Request) (*http.Response, error) { answer := httptest.NewRecorder() s.ServeHTTP(answer, req) _ = req.Body.Close() err := req.Context().Err() if err != nil { return nil, err } return answer.Result(), nil } // ServeHTTP notes the request, and answers it as the stand-in is set to. func (s *standIn) ServeHTTP(w http.ResponseWriter, r *http.Request) { body, _ := io.ReadAll(r.Body) var alert map[string]any _ = json.Unmarshal(body, &alert) s.mu.Lock() answers := s.answers s.requests = append(s.requests, post{ at: time.Now(), method: r.Method, url: r.URL.String(), header: r.Header.Clone(), alert: alert, answered: answers == answering, }) s.mu.Unlock() if answers == hanging { <-r.Context().Done() } else { w.WriteHeader(answers) } } // set sets how the stand-in answers: with the status answers, or hanging. func (s *standIn) set(answers int) { s.mu.Lock() defer s.mu.Unlock() s.answers = answers } // received returns the requests the stand-in has been sent so far. func (s *standIn) received() []post { s.mu.Lock() defer s.mu.Unlock() return slices.Clone(s.requests) } // lockedBuffer is a buffer the process log can write to while the test // reads it. type lockedBuffer struct { mu sync.Mutex buf bytes.Buffer } // Write adds p to the buffer. func (b *lockedBuffer) Write(p []byte) (int, error) { b.mu.Lock() defer b.mu.Unlock() return b.buf.Write(p) } // String returns what was written. func (b *lockedBuffer) String() string { b.mu.Lock() defer b.mu.Unlock() return b.buf.String() } // newParams returns the Params of most tests: the webhook at webhookURL, // every event, the default cooldown and hourly limit, and the bubble's // clock in UTC. func newParams() alerts.Params { webhook, err := url.Parse(webhookURL) if err != nil { panic(err) } return alerts.Params{ WebhookURL: webhook, Events: alerts.Events(), Cooldown: cooldown, MaxPerHour: 60, Instance: instance, Now: func() time.Time { return time.Now().UTC() }, ProcessLog: slog.New(slog.DiscardHandler), } } // start returns a stand-in for the webhook that answers, and a Queue that // sends to it, run until the test ends. func start(t *testing.T, params alerts.Params) (*standIn, *alerts.Queue) { t.Helper() webhook := &standIn{answers: answering} q := alerts.New(params) q.SetTransport(webhook) ctx, stop := context.WithCancel(t.Context()) stopped := make(chan struct{}) go func() { q.Run(ctx) close(stopped) }() t.Cleanup(func() { stop() <-stopped }) return webhook, q } // midnight is when each test starts. func midnight() time.Time { return time.Date(2000, 1, 1, 0, 0, 0, 0, time.UTC) } // netblock returns the n-th netblock of a test, counted from 0. func netblock(n int) netip.Prefix { return netip.MustParsePrefix(fmt.Sprintf("203.0.%d.%d/32", 113+n/256, n%256)) } // roundTrip returns state once written as JSON and read back, as // alerts.json carries it from one start to the next. func roundTrip(t *testing.T, state alerts.State) alerts.State { t.Helper() data, err := json.Marshal(state) if err != nil { t.Fatalf("encode: %v", err) } var read alerts.State err = json.Unmarshal(data, &read) if err != nil { t.Fatalf("decode: %v", err) } return read } // wantAlert checks every field of an alert the webhook was sent. func wantAlert(t *testing.T, got, want map[string]any) { t.Helper() if !reflect.DeepEqual(got, want) { t.Errorf("alert %v, want %v", got, want) } } // wantEvents checks the events of the alerts the webhook was sent, in // order. func wantEvents(t *testing.T, webhook *standIn, want ...string) { t.Helper() got := make([]string, 0, len(webhook.received())) for _, request := range webhook.received() { event, _ := request.alert["event"].(string) got = append(got, event) } if !slices.Equal(got, want) { t.Errorf("the webhook was sent %v, want %v", got, want) } } // wantCounts checks the alerts q counts as sent, the requests it counts as // failed, and the alerts it counts as held back and as dropped. func wantCounts( t *testing.T, q *alerts.Queue, sent, failed, suppressed, dropped int64, ) { t.Helper() if q.Sent() != sent || q.Failed() != failed || q.Suppressed() != suppressed || q.Dropped() != dropped { t.Errorf("counts sent %d, failed %d, suppressed %d and dropped %d, "+ "want %d, %d, %d and %d", q.Sent(), q.Failed(), q.Suppressed(), q.Dropped(), sent, failed, suppressed, dropped) } }