package requestlog_test import ( "bytes" "encoding/json" "log/slog" "slices" "strings" "testing" "time" "sneak.berlin/go/smallwebwaf/internal/requestlog" ) func TestWriteWritesOneJSONLineMarkedRequest(t *testing.T) { t.Parallel() var out bytes.Buffer err := requestlog.Write(&out, &requestlog.Line{ Time: requestlog.FormatTime(time.Date(2026, 10, 3, 12, 0, 0, 0, time.UTC)), ClientIP: "203.0.113.9", Status: 200, Action: requestlog.ActionForward, DurationTotal: requestlog.Milliseconds(1500 * time.Microsecond), }) if err != nil { t.Fatalf("write: %v", err) } text := out.String() if strings.Count(text, "\n") != 1 || !strings.HasSuffix(text, "\n") { t.Fatalf("wrote %q, want one line", text) } var fields map[string]any err = json.Unmarshal(out.Bytes(), &fields) if err != nil { t.Fatalf("decode %q: %v", text, err) } want := map[string]any{ "type": "request", "time": "2026-10-03T12:00:00.000Z", "client_ip": "203.0.113.9", "status": 200.0, "action": "forward", "duration_total": 1.5, } for name, value := range want { if fields[name] != value { t.Errorf("%s is %v, want %v", name, fields[name], value) } } unset := []string{ "forwarded_for", "content_type", "content_length", "request_headers", "has_authorization", "has_cookie", "websocket", "response_content_type", "upstream_status", "cache_control", "location", "aborted", "counts", "limit_hit", "offence", "ban_expires", "duration_checks", "duration_upstream_connect", "duration_upstream_first_byte", "duration_upstream_total", } for _, name := range unset { _, present := fields[name] if present { t.Errorf("%s is there with no value to give", name) } } } func TestProcessLinesAreMarkedProcessAndGiveTheInstance(t *testing.T) { t.Parallel() var out bytes.Buffer requestlog.NewProcessLogger(&out, "fsn1app1/gitea", slog.LevelInfo).Info("starting", "version", "v1") var fields map[string]any err := json.Unmarshal(out.Bytes(), &fields) if err != nil { t.Fatalf("decode %q: %v", out.String(), err) } if fields["type"] != "process" || fields["instance"] != "fsn1app1/gitea" || fields["msg"] != "starting" || fields["level"] != "INFO" || fields["version"] != "v1" { t.Errorf("process line %v", fields) } timeText, _ := fields["time"].(string) logged, err := time.Parse(time.RFC3339, timeText) if err != nil || !strings.HasSuffix(timeText, "Z") || len(timeText) != len("2006-01-02T15:04:05.000Z") || time.Since(logged) > time.Minute { t.Errorf("process line time %q, want now in UTC with milliseconds", timeText) } } func TestProcessLoggerWritesTheMessagesAtItsLevelOrMoreSevere(t *testing.T) { t.Parallel() levels := []slog.Level{ slog.LevelDebug, slog.LevelInfo, slog.LevelWarn, slog.LevelError, } for i, level := range levels { t.Run(level.String(), func(t *testing.T) { t.Parallel() var out bytes.Buffer processLog := requestlog.NewProcessLogger(&out, "fsn1app1/gitea", level) for _, at := range levels { processLog.Log(t.Context(), at, "message") } var got, want []string for line := range strings.Lines(out.String()) { var fields struct { Level string `json:"level"` } err := json.Unmarshal([]byte(line), &fields) if err != nil { t.Fatalf("decode %q: %v", line, err) } got = append(got, fields.Level) } for _, written := range levels[i:] { want = append(want, written.String()) } if !slices.Equal(got, want) { t.Errorf("lines at %v, want %v", got, want) } }) } }