sneak
92ed102595
check / check (push) Successful in 3m40s
Log field, metric, action and event names now say what they count and, for timings, the unit. Package internal/waf is internal/coreruleset. Model: opus-5-5
312 lines
13 KiB
Go
312 lines
13 KiB
Go
// Package requestlog writes the lines sww prints on stdout: one
|
|
// JSON object per request, two from discriminator and a short one from rproxy,
|
|
// 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 discriminator did with the request.
|
|
const (
|
|
// ActionForward is a request discriminator allowed, which rproxy passes to
|
|
// the app.
|
|
ActionForward = "forward"
|
|
|
|
// ActionRequestHeaderTooLarge is a request over the header limits.
|
|
ActionRequestHeaderTooLarge = "request_header_too_large"
|
|
|
|
// ActionClientIsRateLimited is a request refused because it took its
|
|
// client over a rate limit, which bans the client.
|
|
ActionClientIsRateLimited = "client_is_rate_limited"
|
|
|
|
// ActionTemporarilyBanned is a request refused because a ban that runs
|
|
// out covers its client, or because it matched a ban rule, asked for a
|
|
// trap path or the CrowdSec decision list lists its client, and so made
|
|
// such a ban.
|
|
ActionTemporarilyBanned = "temporarily_banned"
|
|
|
|
// ActionPermanentlyBanned is a request refused because a ban that never
|
|
// runs out covers its client, or because the request made such a ban or
|
|
// made its client's ban permanent.
|
|
ActionPermanentlyBanned = "permanently_banned"
|
|
|
|
// ActionBlockedByBlockRule is a request refused because it matched a
|
|
// block rule.
|
|
ActionBlockedByBlockRule = "blocked_by_block_rule"
|
|
|
|
// ActionBlockedByCoreRuleSet is a request refused because the Core Rule
|
|
// Set scored it at or over SWW_WAF_ANOMALY_THRESHOLD.
|
|
ActionBlockedByCoreRuleSet = "blocked_by_core_rule_set"
|
|
|
|
// ActionClientDenied is a request refused because its client is in
|
|
// SWW_DENY_NETS, in a blocklist while SWW_BLOCKLIST_ACTION is deny,
|
|
// or listed by a DNSBL zone, or scored a hit by AbuseIPDB, while
|
|
// SWW_REPUTATION_ACTION is deny, or that carries a tag in SWW_TAG_DENY.
|
|
ActionClientDenied = "client_denied"
|
|
|
|
// ActionCountryDenied is a request refused because its client's country
|
|
// is not in SWW_EXCLUSIVELY_ALLOWED_COUNTRIES.
|
|
ActionCountryDenied = "country_denied"
|
|
// ActionOwnEndpoint is a request discriminator answered at one of its own
|
|
// endpoints, or a question about a path under /_sww/.
|
|
ActionOwnEndpoint = "own_endpoint"
|
|
)
|
|
|
|
// OffenceLimit is the offence a request line names for a request that
|
|
// broke a rate limit or the error burst, or whose bytes broke a byte
|
|
// limit.
|
|
const OffenceLimit = "limit"
|
|
|
|
// LimitHitMinuteRefusals is the limit_hit a request line names for a request
|
|
// that broke the error burst.
|
|
const LimitHitMinuteRefusals = "minute_refusals"
|
|
|
|
// The discriminator_line a request line names, which says which of
|
|
// discriminator's two lines about a question it is.
|
|
const (
|
|
// DiscriminatorLineDecision is discriminator's line at its decision.
|
|
DiscriminatorLineDecision = "decision"
|
|
// DiscriminatorLineReport is discriminator's line when rproxy's report
|
|
// comes, with the decision's fields and the report's together.
|
|
DiscriminatorLineReport = "report"
|
|
)
|
|
|
|
// 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 docs/request-log.md. A field that may not
|
|
// apply to a request is left out of its line when it does not.
|
|
//
|
|
//nolint:tagliatelle // docs/request-log.md names the fields in snake_case
|
|
type Line struct {
|
|
Type string `json:"type"`
|
|
// DiscriminatorLine is DiscriminatorLineDecision or DiscriminatorLineReport
|
|
// on discriminator's two lines about a question.
|
|
DiscriminatorLine string `json:"discriminator_line,omitempty"`
|
|
|
|
// The standard web log fields. Scheme is how the client reached rproxy, 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 id rproxy made for the request, or for a
|
|
// request to discriminator's own endpoints a new one. ForwardedFor is the
|
|
// X-Forwarded-For header as received. ClientGroup is the netblock the
|
|
// client is counted as. ASN, ASName and Country are the client's AS
|
|
// number, AS name and country, as looked up.
|
|
RequestID string `json:"request_id"`
|
|
PeerIP string `json:"peer_ip"`
|
|
ForwardedFor string `json:"forwarded_for,omitempty"`
|
|
ClientGroup string `json:"client_group"`
|
|
ASN string `json:"asn"`
|
|
ASName string `json:"as_name"`
|
|
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 SWW_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"`
|
|
|
|
// Response detail, of discriminator's own answer. Aborted is true when
|
|
// rproxy, or the admin's tool, went away before the answer.
|
|
ResponseContentType string `json:"response_content_type,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: ActionClientDenied,
|
|
// ActionTemporarilyBanned, ActionPermanentlyBanned, ActionCountryDenied,
|
|
// ActionClientIsRateLimited, ActionBlockedByBlockRule,
|
|
// ActionBlockedByCoreRuleSet, or, in discriminator,
|
|
// ActionRequestHeaderTooLarge for the header limits.
|
|
WouldAction string `json:"would_action,omitempty"`
|
|
// Heuristic is the name of the heuristic that refused the request, in
|
|
// observe mode too, and HeuristicFigures are the figures it acted on, by
|
|
// name.
|
|
Heuristic string `json:"heuristic,omitempty"`
|
|
HeuristicFigures map[string]any `json:"heuristic_figures,omitempty"`
|
|
// AfterAnswerHeuristic and AfterAnswerHeuristicFigures are the same for
|
|
// the heuristic that banned the client after discriminator answered the
|
|
// request.
|
|
AfterAnswerHeuristic string `json:"after_answer_heuristic,omitempty"`
|
|
AfterAnswerHeuristicFigures map[string]any `json:"after_answer_heuristic_figures,omitempty"` //nolint:lll // a struct tag cannot be split
|
|
// RateLimitPercent and RateLimitPercentSetting are, for a request the
|
|
// rate limits counted whose client a biased threshold gives a percentage
|
|
// of the rate limits below 100, that percentage and the setting that gave
|
|
// it. BytesLimitPercent and BytesLimitPercentSetting are the same for the
|
|
// byte limits.
|
|
RateLimitPercent *int64 `json:"rate_limit_percent,omitempty"`
|
|
RateLimitPercentSetting string `json:"rate_limit_percent_setting,omitempty"`
|
|
BytesLimitPercent *int64 `json:"bytes_limit_percent,omitempty"`
|
|
BytesLimitPercentSetting string `json:"bytes_limit_percent_setting,omitempty"`
|
|
// Counts are, for a request the rate limits counted, the client's
|
|
// requests as they counted them with this one, and its bytes as the
|
|
// byte limits counted them, with this request's once it has ended if
|
|
// they count them.
|
|
Counts ratelimit.Counts `json:"counts,omitzero"`
|
|
// RuleIDs are the ids of the rule file rules the request matched.
|
|
RuleIDs []string `json:"rule_ids,omitempty"`
|
|
// CoreRuleSetRuleIDs are the ids of the Core Rule Set's rules the request
|
|
// matched, and CoreRuleSetScore its anomaly score, nil for a request the
|
|
// Core Rule Set did not inspect.
|
|
CoreRuleSetRuleIDs []int `json:"core_rule_set_rule_ids,omitempty"`
|
|
CoreRuleSetScore *int `json:"core_rule_set_score,omitempty"`
|
|
// LimitHit is the window whose limit the request went over, named as
|
|
// Counts names its count: minute, hour or day for a rate limit, and
|
|
// minute_bytes, hour_bytes or day_bytes for a byte limit; or
|
|
// LimitHitMinuteRefusals for the error burst.
|
|
LimitHit string `json:"limit_hit,omitempty"`
|
|
// Reputation are the URLs of the blocklists that list the client, then
|
|
// that of the CrowdSec decision list when it does, then the DNSBL zones
|
|
// whose verdict lists it, their keys masked, then abuseipdb when its
|
|
// score is a hit.
|
|
Reputation []string `json:"reputation,omitempty"`
|
|
// Tags are the request's tags, sorted.
|
|
Tags []string `json:"tags,omitempty"`
|
|
// RouteWatchTagsMissing, while SWW_ROUTEWATCH_URL is set, says why the
|
|
// request got no tags from routewatch: no_answer_yet, request_failed or
|
|
// no_route.
|
|
RouteWatchTagsMissing string `json:"routewatch_tags_missing,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. DurationChecksMS is the time until the checks were done, and
|
|
// DurationCoreRuleSetMS the part of it the Core Rule Set took.
|
|
// DurationUpstreamTotalMS is what the report of an allowed request gives,
|
|
// from the hand-over to the app until the end of its answer. Each but
|
|
// DurationTotalMS is nil for a request that did not get that far.
|
|
DurationTotalMS float64 `json:"duration_total_ms"`
|
|
DurationChecksMS *float64 `json:"duration_checks_ms,omitempty"`
|
|
DurationCoreRuleSetMS *float64 `json:"duration_core_rule_set_ms,omitempty"`
|
|
DurationUpstreamTotalMS *float64 `json:"duration_upstream_total_ms,omitempty"`
|
|
}
|
|
|
|
// RProxyLine is rproxy's short line in the request log about one request. The
|
|
// field names, and their order, are those of docs/request-log.md. A field that
|
|
// does not apply to a request is left out of its line.
|
|
//
|
|
//nolint:tagliatelle // docs/request-log.md names the fields in snake_case
|
|
type RProxyLine struct {
|
|
Type string `json:"type"`
|
|
Time string `json:"time"`
|
|
RequestID string `json:"request_id"`
|
|
ClientIP string `json:"client_ip"`
|
|
Host string `json:"host"`
|
|
Method string `json:"method"`
|
|
Path string `json:"path"`
|
|
Query string `json:"query"`
|
|
Status int `json:"status"`
|
|
RequestBytes int64 `json:"request_bytes"`
|
|
ResponseBytes int64 `json:"response_bytes"`
|
|
// DurationRequestMS runs from the request's headers being read until the app
|
|
// has been sent the whole request, or the answer has started if that is
|
|
// sooner. DurationResponseMS runs from then until the answer ends.
|
|
DurationRequestMS float64 `json:"duration_request_ms"`
|
|
DurationResponseMS float64 `json:"duration_response_ms"`
|
|
// Disposition is the valid disposition discriminator answered or, while
|
|
// DefaultDisposition is true, the value of SWRP_DEFAULT_DISPOSITION. It is ""
|
|
// when neither gave one.
|
|
Disposition string `json:"disposition,omitempty"`
|
|
DefaultDisposition bool `json:"default_disposition,omitempty"`
|
|
}
|
|
|
|
// Write writes line to w as one JSON line marked "type":"request".
|
|
func Write(w io.Writer, line *Line) error {
|
|
line.Type = "request"
|
|
|
|
return writeJSONLine(w, line)
|
|
}
|
|
|
|
// WriteRProxyLine writes line to w as one JSON line marked "type":"request".
|
|
func WriteRProxyLine(w io.Writer, line *RProxyLine) error {
|
|
line.Type = "request"
|
|
|
|
return writeJSONLine(w, line)
|
|
}
|
|
|
|
// writeJSONLine writes line to w as one JSON line.
|
|
func writeJSONLine(w io.Writer, line any) error {
|
|
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, and instanceName, SWW_INSTANCE_NAME, as instance.
|
|
// It writes only the messages at level, SWW_LOG_LEVEL, or more severe;
|
|
// the request lines Write writes are never held back.
|
|
func NewProcessLogger(
|
|
w io.Writer,
|
|
instanceName string,
|
|
level slog.Level,
|
|
) *slog.Logger {
|
|
handler := slog.NewJSONHandler(w, &slog.HandlerOptions{
|
|
Level: level,
|
|
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", "instance", instanceName)
|
|
}
|