Merge branch 'main' into Xe/anubis-custom-logger

Signed-off-by: Xe Iaso <xe.iaso@techaro.lol>

.github/workflows/zizmor.yml

@@ -21,7 +21,7 @@ jobs:
           persist-credentials: false
 
       - name: Install the latest version of uv
-        uses: astral-sh/setup-uv@7edac99f961f18b581bbd960d59d049f04c0002f # v6.4.1
+        uses: astral-sh/setup-uv@e92bafb6253dcd438e0484186d7669ea7a8ca1cc # v6.4.3
 
       - name: Run zizmor 🌈
         run: uvx zizmor --format sarif . > results.sarif 
@@ -29,7 +29,7 @@ jobs:
           GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} 
 
       - name: Upload SARIF file
-        uses: github/codeql-action/upload-sarif@181d5eefc20863364f96762470ba6f862bdef56b # v3.29.2
+        uses: github/codeql-action/upload-sarif@4e828ff8d448a8a6e532957b1811f387a63867e8 # v3.29.4
         with:
           sarif_file: results.sarif
           category: zizmor

docs/docs/CHANGELOG.md

@@ -13,9 +13,11 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 <!-- This changes the project to: -->
 
+- Downstream consumers can change the default [log/slog#Logger](https://pkg.go.dev/log/slog#Logger) instance that Anubis uses by setting `opts.Logger` to your slog instance of choice ([#864](https://github.com/TecharoHQ/anubis/issues/864)).
 - The [Thoth client](https://anubis.techaro.lol/docs/admin/thoth) is now public in the repo instead of being an internal package.
 - [Custom-AsyncHttpClient](https://github.com/AsyncHttpClient/async-http-client)'s default User-Agent has an increased weight by default ([#852](https://github.com/TecharoHQ/anubis/issues/852)).
 - The [`segments`](./admin/configuration/expressions.mdx#segments) function was added for splitting a path into its slash-separated segments.
+- When issuing a challenge, Anubis stores information about that challenge into the store. That stored information is later used to validate challenge responses. This works around nondeterminism in bot rules. ([#917](https://github.com/TecharoHQ/anubis/issues/917))
 
 ## v1.21.3: Minfilia Warde - Echo 3
 

internal/log.go

@@ -26,8 +26,11 @@ func InitSlog(level string) {
 	slog.SetDefault(slog.New(h))
 }
 
-func GetRequestLogger(r *http.Request) *slog.Logger {
+func GetRequestLogger(base *slog.Logger, r *http.Request) *slog.Logger {
-	return slog.With(
+	return base.With(
+		"host", r.Host,
+		"method", r.Method,
+		"path", r.URL.Path,
 		"user_agent", r.UserAgent(),
 		"accept_language", r.Header.Get("Accept-Language"),
 		"priority", r.Header.Get("Priority"),

lib/anubis.go

@@ -75,6 +75,7 @@ type Server struct {
 	hs512Secret []byte
 	opts        Options
 	store       store.Interface
+	logger      *slog.Logger
 }
 
 func (s *Server) getTokenKeyfunc() jwt.Keyfunc {
@@ -90,41 +91,39 @@ func (s *Server) getTokenKeyfunc() jwt.Keyfunc {
 	}
 }
 
-func (s *Server) challengeFor(r *http.Request) (*challenge.Challenge, error) {
+func (s *Server) getChallenge(r *http.Request) (*challenge.Challenge, error) {
 	ckies := r.CookiesNamed(anubis.TestCookieName)
-
 	if len(ckies) == 0 {
-		return s.issueChallenge(r.Context(), r)
+		return nil, store.ErrNotFound
 	}
 
 	j := store.JSON[challenge.Challenge]{Underlying: s.store}
 
 	ckie := ckies[0]
 	chall, err := j.Get(r.Context(), "challenge:"+ckie.Value)
-	if err != nil {
-		if errors.Is(err, store.ErrNotFound) {
-			return s.issueChallenge(r.Context(), r)
-		}
 
-		return nil, err
+	return &chall, err
-	}
-
-	return &chall, nil
 }
 
-func (s *Server) issueChallenge(ctx context.Context, r *http.Request) (*challenge.Challenge, error) {
+func (s *Server) issueChallenge(ctx context.Context, r *http.Request, lg *slog.Logger, cr policy.CheckResult, rule *policy.Bot) (*challenge.Challenge, error) {
+	if cr.Rule != config.RuleChallenge {
+		slog.Error("this should be impossible, asked to issue a challenge but the rule is not a challenge rule", "cr", cr, "rule", rule)
+		//return nil, errors.New("[unexpected] this codepath should be impossible, asked to issue a challenge for a non-challenge rule")
+	}
+
 	id, err := uuid.NewV7()
 	if err != nil {
 		return nil, err
 	}
 
-	var randomData = make([]byte, 256)
+	var randomData = make([]byte, 64)
 	if _, err := rand.Read(randomData); err != nil {
 		return nil, err
 	}
 
 	chall := challenge.Challenge{
 		ID:         id.String(),
+		Method:     rule.Challenge.Algorithm,
 		RandomData: fmt.Sprintf("%x", randomData),
 		IssuedAt:   time.Now(),
 		Metadata: map[string]string{
@@ -138,6 +137,8 @@ func (s *Server) issueChallenge(ctx context.Context, r *http.Request) (*challeng
 		return nil, err
 	}
 
+	lg.Info("new challenge issued", "challenge", id.String())
+
 	return &chall, err
 }
 
@@ -150,7 +151,7 @@ func (s *Server) maybeReverseProxyOrPage(w http.ResponseWriter, r *http.Request)
 }
 
 func (s *Server) maybeReverseProxy(w http.ResponseWriter, r *http.Request, httpStatusOnly bool) {
-	lg := internal.GetRequestLogger(r)
+	lg := internal.GetRequestLogger(s.logger, r)
 
 	// Adjust cookie path if base prefix is not empty
 	cookiePath := "/"
@@ -158,7 +159,7 @@ func (s *Server) maybeReverseProxy(w http.ResponseWriter, r *http.Request, httpS
 		cookiePath = strings.TrimSuffix(anubis.BasePrefix, "/") + "/"
 	}
 
-	cr, rule, err := s.check(r)
+	cr, rule, err := s.check(r, lg)
 	if err != nil {
 		lg.Error("check failed", "err", err)
 		localizer := localization.GetLocalizer(r)
@@ -185,21 +186,21 @@ func (s *Server) maybeReverseProxy(w http.ResponseWriter, r *http.Request, httpS
 	if err != nil {
 		lg.Debug("cookie not found", "path", r.URL.Path)
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
 	if err := ckie.Valid(); err != nil {
 		lg.Debug("cookie is invalid", "err", err)
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
 	if time.Now().After(ckie.Expires) && !ckie.Expires.IsZero() {
 		lg.Debug("cookie expired", "path", r.URL.Path)
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
@@ -208,7 +209,7 @@ func (s *Server) maybeReverseProxy(w http.ResponseWriter, r *http.Request, httpS
 	if err != nil || !token.Valid {
 		lg.Debug("invalid token", "path", r.URL.Path, "err", err)
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
@@ -216,7 +217,7 @@ func (s *Server) maybeReverseProxy(w http.ResponseWriter, r *http.Request, httpS
 	if !ok {
 		lg.Debug("invalid token claims type", "path", r.URL.Path)
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
@@ -224,14 +225,14 @@ func (s *Server) maybeReverseProxy(w http.ResponseWriter, r *http.Request, httpS
 	if !ok {
 		lg.Debug("policyRule claim is not a string")
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
 	if policyRule != rule.Hash() {
 		lg.Debug("user originally passed with a different rule, issuing new challenge", "old", policyRule, "new", rule.Name)
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		s.RenderIndex(w, r, rule, httpStatusOnly)
+		s.RenderIndex(w, r, cr, rule, httpStatusOnly)
 		return
 	}
 
@@ -274,7 +275,7 @@ func (s *Server) checkRules(w http.ResponseWriter, r *http.Request, cr policy.Ch
 		return true
 	default:
 		s.ClearCookie(w, CookieOpts{Path: cookiePath, Host: r.Host})
-		slog.Error("CONFIG ERROR: unknown rule", "rule", cr.Rule)
+		lg.Error("CONFIG ERROR: unknown rule", "rule", cr.Rule)
 		s.respondWithError(w, r, fmt.Sprintf("%s \"maybeReverseProxy.Rules\"", localizer.T("internal_server_error")))
 		return true
 	}
@@ -310,7 +311,7 @@ func (s *Server) handleDNSBL(w http.ResponseWriter, r *http.Request, ip string,
 }
 
 func (s *Server) MakeChallenge(w http.ResponseWriter, r *http.Request) {
-	lg := internal.GetRequestLogger(r)
+	lg := internal.GetRequestLogger(s.logger, r)
 	localizer := localization.GetLocalizer(r)
 
 	redir := r.FormValue("redir")
@@ -329,7 +330,7 @@ func (s *Server) MakeChallenge(w http.ResponseWriter, r *http.Request) {
 	r.URL.Path = redir
 
 	encoder := json.NewEncoder(w)
-	cr, rule, err := s.check(r)
+	cr, rule, err := s.check(r, lg)
 	if err != nil {
 		lg.Error("check failed", "err", err)
 		w.WriteHeader(http.StatusInternalServerError)
@@ -346,7 +347,7 @@ func (s *Server) MakeChallenge(w http.ResponseWriter, r *http.Request) {
 	}
 	lg = lg.With("check_result", cr)
 
-	chall, err := s.challengeFor(r)
+	chall, err := s.issueChallenge(r.Context(), r, lg, cr, rule)
 	if err != nil {
 		lg.Error("failed to fetch or issue challenge", "err", err)
 		w.WriteHeader(http.StatusInternalServerError)
@@ -381,7 +382,7 @@ func (s *Server) MakeChallenge(w http.ResponseWriter, r *http.Request) {
 }
 
 func (s *Server) PassChallenge(w http.ResponseWriter, r *http.Request) {
-	lg := internal.GetRequestLogger(r)
+	lg := internal.GetRequestLogger(s.logger, r)
 	localizer := localization.GetLocalizer(r)
 
 	redir := r.FormValue("redir")
@@ -428,7 +429,7 @@ func (s *Server) PassChallenge(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	cr, rule, err := s.check(r)
+	cr, rule, err := s.check(r, lg)
 	if err != nil {
 		lg.Error("check failed", "err", err)
 		s.respondWithError(w, r, fmt.Sprintf("%s \"passChallenge\"", localizer.T("internal_server_error")))
@@ -436,19 +437,21 @@ func (s *Server) PassChallenge(w http.ResponseWriter, r *http.Request) {
 	}
 	lg = lg.With("check_result", cr)
 
-	impl, ok := challenge.Get(rule.Challenge.Algorithm)
+	chall, err := s.getChallenge(r)
+	if err != nil {
+		lg.Error("getChallenge failed", "err", err)
+		s.respondWithError(w, r, fmt.Sprintf("%s: %s", localizer.T("internal_server_error"), rule.Challenge.Algorithm))
+		return
+	}
+
+	impl, ok := challenge.Get(chall.Method)
 	if !ok {
 		lg.Error("check failed", "err", err)
 		s.respondWithError(w, r, fmt.Sprintf("%s: %s", localizer.T("internal_server_error"), rule.Challenge.Algorithm))
 		return
 	}
 
-	chall, err := s.challengeFor(r)
+	lg = lg.With("challenge", chall.ID)
-	if err != nil {
-		lg.Error("check failed", "err", err)
-		s.respondWithError(w, r, fmt.Sprintf("%s: %s", localizer.T("internal_server_error"), rule.Challenge.Algorithm))
-		return
-	}
 
 	in := &challenge.ValidateInput{
 		Challenge: chall,
@@ -466,9 +469,13 @@ func (s *Server) PassChallenge(w http.ResponseWriter, r *http.Request) {
 		case errors.As(err, &cerr):
 			switch {
 			case errors.Is(err, challenge.ErrFailed):
+				lg.Error("challenge failed", "err", err)
 				s.respondWithStatus(w, r, cerr.PublicReason, cerr.StatusCode)
+				return
 			case errors.Is(err, challenge.ErrInvalidFormat), errors.Is(err, challenge.ErrMissingField):
+				lg.Error("invalid challenge format", "err", err)
 				s.respondWithError(w, r, cerr.PublicReason)
+				return
 			}
 		}
 	}
@@ -503,7 +510,7 @@ func cr(name string, rule config.Rule, weight int) policy.CheckResult {
 }
 
 // Check evaluates the list of rules, and returns the result
-func (s *Server) check(r *http.Request) (policy.CheckResult, *policy.Bot, error) {
+func (s *Server) check(r *http.Request, lg *slog.Logger) (policy.CheckResult, *policy.Bot, error) {
 	host := r.Header.Get("X-Real-Ip")
 	if host == "" {
 		return decaymap.Zilch[policy.CheckResult](), nil, fmt.Errorf("[misconfiguration] X-Real-Ip header is not set")
@@ -527,7 +534,7 @@ func (s *Server) check(r *http.Request) (policy.CheckResult, *policy.Bot, error)
 			case config.RuleDeny, config.RuleAllow, config.RuleBenchmark, config.RuleChallenge:
 				return cr("bot/"+b.Name, b.Action, weight), &b, nil
 			case config.RuleWeigh:
-				slog.Debug("adjusting weight", "name", b.Name, "delta", b.Weight.Adjust)
+				lg.Debug("adjusting weight", "name", b.Name, "delta", b.Weight.Adjust)
 				weight += b.Weight.Adjust
 			}
 		}
@@ -536,7 +543,7 @@ func (s *Server) check(r *http.Request) (policy.CheckResult, *policy.Bot, error)
 	for _, t := range s.policy.Thresholds {
 		result, _, err := t.Program.ContextEval(r.Context(), &policy.ThresholdRequest{Weight: weight})
 		if err != nil {
-			slog.Error("error when evaluating threshold expression", "expression", t.Expression.String(), "err", err)
+			lg.Error("error when evaluating threshold expression", "expression", t.Expression.String(), "err", err)
 			continue
 		}
 

lib/anubis_test.go

@@ -343,7 +343,7 @@ func TestCheckDefaultDifficultyMatchesPolicy(t *testing.T) {
 
 			req.Header.Add("X-Real-Ip", "127.0.0.1")
 
-			cr, bot, err := s.check(req)
+			cr, bot, err := s.check(req, s.logger)
 			if err != nil {
 				t.Fatal(err)
 			}
@@ -583,7 +583,7 @@ func TestCloudflareWorkersRule(t *testing.T) {
 				req.Header.Add("X-Real-Ip", "127.0.0.1")
 				req.Header.Add("Cf-Worker", "true")
 
-				cr, _, err := s.check(req)
+				cr, _, err := s.check(req, s.logger)
 				if err != nil {
 					t.Fatal(err)
 				}
@@ -601,7 +601,7 @@ func TestCloudflareWorkersRule(t *testing.T) {
 
 				req.Header.Add("X-Real-Ip", "127.0.0.1")
 
-				cr, _, err := s.check(req)
+				cr, _, err := s.check(req, s.logger)
 				if err != nil {
 					t.Fatal(err)
 				}

lib/challenge/challenge.go

@@ -5,6 +5,7 @@ import "time"
 // Challenge is the metadata about a single challenge issuance.
 type Challenge struct {
 	ID         string            `json:"id"`         // UUID identifying the challenge
+	Method     string            `json:"method"`     // Challenge method
 	RandomData string            `json:"randomData"` // The random data the client processes
 	IssuedAt   time.Time         `json:"issuedAt"`   // When the challenge was issued
 	Metadata   map[string]string `json:"metadata"`   // Challenge metadata such as IP address and user agent

lib/config.go

@@ -43,6 +43,7 @@ type Options struct {
 	OpenGraph           config.OpenGraph
 	ServeRobotsTXT      bool
 	CookieSecure        bool
+	Logger              *slog.Logger
 }
 
 func LoadPoliciesOrDefault(ctx context.Context, fname string, defaultDifficulty int) (*policy.ParsedConfig, error) {
@@ -89,8 +90,12 @@ func LoadPoliciesOrDefault(ctx context.Context, fname string, defaultDifficulty
 }
 
 func New(opts Options) (*Server, error) {
+	if opts.Logger == nil {
+		opts.Logger = slog.With("subsystem", "anubis")
+	}
+
 	if opts.ED25519PrivateKey == nil && opts.HS512Secret == nil {
-		slog.Debug("opts.PrivateKey not set, generating a new one")
+		opts.Logger.Debug("opts.PrivateKey not set, generating a new one")
 		_, priv, err := ed25519.GenerateKey(rand.Reader)
 		if err != nil {
 			return nil, fmt.Errorf("lib: can't generate private key: %v", err)
@@ -108,6 +113,7 @@ func New(opts Options) (*Server, error) {
 		opts:        opts,
 		OGTags:      ogtags.NewOGTagCache(opts.Target, opts.Policy.OpenGraph, opts.Policy.Store),
 		store:       opts.Policy.Store,
+		logger:      opts.Logger,
 	}
 
 	mux := http.NewServeMux()

lib/http.go

@@ -111,7 +111,7 @@ func randomChance(n int) bool {
 	return rand.Intn(n) == 0
 }
 
-func (s *Server) RenderIndex(w http.ResponseWriter, r *http.Request, rule *policy.Bot, returnHTTPStatusOnly bool) {
+func (s *Server) RenderIndex(w http.ResponseWriter, r *http.Request, cr policy.CheckResult, rule *policy.Bot, returnHTTPStatusOnly bool) {
 	localizer := localization.GetLocalizer(r)
 
 	if returnHTTPStatusOnly {
@@ -120,22 +120,25 @@ func (s *Server) RenderIndex(w http.ResponseWriter, r *http.Request, rule *polic
 		return
 	}
 
-	lg := internal.GetRequestLogger(r)
+	lg := internal.GetRequestLogger(s.logger, r)
 
 	if !strings.Contains(r.Header.Get("Accept-Encoding"), "gzip") && randomChance(64) {
 		lg.Error("client was given a challenge but does not in fact support gzip compression")
 		s.respondWithError(w, r, localizer.T("client_error_browser"))
+		return
 	}
 
 	challengesIssued.WithLabelValues("embedded").Add(1)
-	chall, err := s.challengeFor(r)
+	chall, err := s.issueChallenge(r.Context(), r, lg, cr, rule)
 	if err != nil {
-		lg.Error("can't get challenge", "err", "err")
+		lg.Error("can't get challenge", "err", err)
 		s.ClearCookie(w, CookieOpts{Name: anubis.TestCookieName, Host: r.Host})
 		s.respondWithError(w, r, fmt.Sprintf("%s: %s", localizer.T("internal_server_error"), rule.Challenge.Algorithm))
 		return
 	}
 
+	lg = lg.With("challenge", chall.ID)
+
 	var ogTags map[string]string = nil
 	if s.opts.OpenGraph.Enabled {
 		var err error
@@ -153,7 +156,7 @@ func (s *Server) RenderIndex(w http.ResponseWriter, r *http.Request, rule *polic
 		Expiry: 30 * time.Minute,
 	})
 
-	impl, ok := challenge.Get(rule.Challenge.Algorithm)
+	impl, ok := challenge.Get(chall.Method)
 	if !ok {
 		lg.Error("check failed", "err", "can't get algorithm", "algorithm", rule.Challenge.Algorithm)
 		s.ClearCookie(w, CookieOpts{Name: anubis.TestCookieName, Host: r.Host})