fix(anubis): store the challenge method in the store (#924)

* fix(lib): reduce challenge string size

Signed-off-by: Xe Iaso <me@xeiaso.net>

* fix(internal): add host, method, and path to request logs

Signed-off-by: Xe Iaso <me@xeiaso.net>

* fix(anubis): log when challenges explicitly fail

Signed-off-by: Xe Iaso <me@xeiaso.net>

* fix(lib): make challenge validation fully deterministic

Signed-off-by: Xe Iaso <me@xeiaso.net>

* fix(anubis): nuke challengeFor function

Signed-off-by: Xe Iaso <me@xeiaso.net>

* docs: update changelog

Signed-off-by: Xe Iaso <me@xeiaso.net>

---------

Signed-off-by: Xe Iaso <me@xeiaso.net>

docs/docs/CHANGELOG.md

@@ -16,6 +16,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - 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

@@ -28,6 +28,9 @@ func InitSlog(level string) {
 
 func GetRequestLogger(r *http.Request) *slog.Logger {
 	return slog.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

@@ -90,41 +90,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 &chall, err
-			return s.issueChallenge(r.Context(), r)
 }
 
-		return nil, err
+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")
 	}
 
-	return &chall, nil
-}
-
-func (s *Server) issueChallenge(ctx context.Context, r *http.Request) (*challenge.Challenge, error) {
 	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 +136,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
 }
 
@@ -185,21 +185,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 +208,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 +216,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 +224,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
 	}
 
@@ -346,7 +346,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)
@@ -436,19 +436,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 +468,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
 			}
 		}
 	}

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/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 {
@@ -125,17 +125,20 @@ func (s *Server) RenderIndex(w http.ResponseWriter, r *http.Request, rule *polic
 	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})