smallwebwaf/internal/requestlog/requestlog_test.go

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)
			}
		})
	}
}