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