smallwebwaf/internal/requestlog/requestlog.go

// Package requestlog writes the lines smallwebwaf prints on stdout: one
// JSON object per request, marked "type":"request", and the process's own
// messages as JSON lines marked "type":"process".
package requestlog

import (
	"encoding/json"
	"fmt"
	"io"
	"log/slog"
	"time"

	"sneak.berlin/go/smallwebwaf/internal/ratelimit"
)

// The action a request line names: what smallwebwaf did with the
// request.
const (
	// ActionForward is a request passed to the app.
	ActionForward = "forward"
	// ActionTooLarge is a request or response over its size limit.
	ActionTooLarge = "too_large"
	// ActionTimedOut is a request or response that ran out of time.
	ActionTimedOut = "timed_out"
	// ActionUpstreamError is a request the app could not be reached
	// for, or whose answer could not be passed on.
	ActionUpstreamError = "upstream_error"
	// ActionRateLimited is a request refused because it took its client
	// over a rate limit, which bans the client.
	ActionRateLimited = "rate_limited"
	// ActionBanned is a request refused because a ban covers its client,
	// or because it matched a ban rule, which bans the client.
	ActionBanned = "banned"
	// ActionRuleBlocked is a request refused because it matched a block
	// rule.
	ActionRuleBlocked = "rule_blocked"
	// ActionDenied is a request refused because its client is in
	// SWWAF_DENY_NETS.
	ActionDenied = "denied"
	// ActionCountryDenied is a request refused for its client's country.
	ActionCountryDenied = "country_denied"
	// ActionAdmin is a request smallwebwaf answered at one of its own
	// endpoints, under /_smallwebwaf/.
	ActionAdmin = "admin"
)

// OffenceLimit is the offence a request line names for a request that
// broke a rate limit.
const OffenceLimit = "limit"

// timeLayout is RFC 3339 with milliseconds.
const timeLayout = "2006-01-02T15:04:05.000Z07:00"

// Line is one request's line in the request log. The field names, and
// their order, are those of the "Request log" section of SPEC.md. A field
// that may not apply to a request is left out of its line when it does
// not.
//
//nolint:tagliatelle // SPEC.md's request log names its fields in snake_case
type Line struct {
	Type string `json:"type"`

	// The standard web log fields. Scheme is how the client reached
	// smallwebwaf, or the trusted proxy in front of it.
	Time          string `json:"time"`
	Instance      string `json:"instance"`
	ClientIP      string `json:"client_ip"`
	Method        string `json:"method"`
	Scheme        string `json:"scheme"`
	Host          string `json:"host"`
	Path          string `json:"path"`
	Query         string `json:"query"`
	Protocol      string `json:"protocol"`
	Status        int    `json:"status"`
	RequestBytes  int64  `json:"request_bytes"`
	ResponseBytes int64  `json:"response_bytes"`
	Referer       string `json:"referer"`
	UserAgent     string `json:"user_agent"`

	// Request detail. RequestID is the X-Request-ID a trusted proxy sent,
	// or a new one, and is sent on to the app. ForwardedFor is the
	// X-Forwarded-For header as received. ClientGroup is the netblock the
	// client is counted as.
	RequestID    string `json:"request_id"`
	PeerIP       string `json:"peer_ip"`
	ForwardedFor string `json:"forwarded_for,omitempty"`
	ClientGroup  string `json:"client_group"`
	Country      string `json:"country"`
	ContentType  string `json:"content_type,omitempty"`
	// ContentLength is the length of its body the request announced.
	ContentLength int64 `json:"content_length,omitempty"`
	// RequestHeaders are the headers SWWAF_LOG_REQUEST_HEADERS names that
	// the request carried, by name in lower case.
	RequestHeaders   map[string]string `json:"request_headers,omitempty"`
	HasAuthorization bool              `json:"has_authorization,omitempty"`
	HasCookie        bool              `json:"has_cookie,omitempty"`
	// Websocket is true when the connection was upgraded, as for a
	// WebSocket.
	Websocket bool `json:"websocket,omitempty"`

	// Response detail, from the headers of the answer: the app's, as
	// passed on, or those of smallwebwaf's own. Aborted is true when the
	// client went away early.
	ResponseContentType string `json:"response_content_type,omitempty"`
	UpstreamStatus      int    `json:"upstream_status,omitempty"`
	CacheControl        string `json:"cache_control,omitempty"`
	Location            string `json:"location,omitempty"`
	Aborted             bool   `json:"aborted,omitempty"`

	// The decision.
	Action string `json:"action"`
	// WouldAction is, in observe mode, the action enforce mode would have
	// taken with a request it would have refused: ActionDenied,
	// ActionBanned, ActionCountryDenied, ActionRateLimited or
	// ActionRuleBlocked.
	WouldAction string `json:"would_action,omitempty"`
	// Counts are the client's requests as the rate limits counted them
	// with this one, for a request they counted.
	Counts ratelimit.Counts `json:"counts,omitzero"`
	// RuleIDs are the ids of the rule file rules the request matched.
	RuleIDs []string `json:"rule_ids,omitempty"`
	// LimitHit is the window whose rate limit the request went over:
	// minute, hour or day.
	LimitHit string `json:"limit_hit,omitempty"`
	// Offence is the offence the request was held as, OffenceLimit.
	Offence string `json:"offence,omitempty"`
	// BanExpires is when the ban the request made, or was refused under,
	// ends: a time, or "permanent".
	BanExpires string `json:"ban_expires,omitempty"`

	// The timings, in milliseconds. DurationChecks is the time until the
	// checks were done. DurationUpstreamConnect, DurationUpstreamFirstByte
	// and DurationUpstreamTotal run from when the request was handed to the
	// app: until there was a connection to it, until the first byte of its
	// answer arrived, and until the end. Each but DurationTotal is nil for
	// a request that did not get that far.
	DurationTotal             float64  `json:"duration_total"`
	DurationChecks            *float64 `json:"duration_checks,omitempty"`
	DurationUpstreamConnect   *float64 `json:"duration_upstream_connect,omitempty"`
	DurationUpstreamFirstByte *float64 `json:"duration_upstream_first_byte,omitempty"`
	DurationUpstreamTotal     *float64 `json:"duration_upstream_total,omitempty"`
}

// Write writes line to w as one JSON line marked "type":"request".
func Write(w io.Writer, line *Line) error {
	line.Type = "request"

	encoded, err := json.Marshal(line)
	if err != nil {
		return fmt.Errorf("encode the request log line: %w", err)
	}

	_, err = w.Write(append(encoded, '\n'))
	if err != nil {
		return fmt.Errorf("write the request log line: %w", err)
	}

	return nil
}

// FormatTime formats t for a line's time field: RFC 3339 in UTC, with
// milliseconds.
func FormatTime(t time.Time) string {
	return t.UTC().Format(timeLayout)
}

// Milliseconds is d in milliseconds, to the microsecond.
func Milliseconds(d time.Duration) float64 {
	return float64(d.Microseconds()) / float64(time.Millisecond/time.Microsecond)
}

// NewProcessLogger returns the logger for the process's own messages:
// JSON lines on w, marked "type":"process", with the time in the same form
// as a request line's.
func NewProcessLogger(w io.Writer) *slog.Logger {
	handler := slog.NewJSONHandler(w, &slog.HandlerOptions{
		ReplaceAttr: func(groups []string, attr slog.Attr) slog.Attr {
			if attr.Key == slog.TimeKey && len(groups) == 0 {
				return slog.String(slog.TimeKey, FormatTime(attr.Value.Time()))
			}

			return attr
		},
	})

	return slog.New(handler).With("type", "process")
}