Add logging levels and timings

cmd/away.go

@@ -54,7 +54,8 @@ func main() {
 	bindNetwork := flag.String("bind-network", "tcp", "network family to bind HTTP to, e.g. unix, tcp")
 	socketMode := flag.String("socket-mode", "0770", "socket mode (permissions) for unix domain sockets.")
 
-	slogLevel := flag.String("slog-level", "INFO", "logging level (see https://pkg.go.dev/log/slog#hdr-Levels)")
+	slogLevel := flag.String("slog-level", "WARN", "logging level (see https://pkg.go.dev/log/slog#hdr-Levels)")
+	debug := flag.Bool("debug", false, "debug mode with logs and server timings")
 
 	policyFile := flag.String("policy", "", "path to policy YAML file")
 	challengeTemplate := flag.String("challenge-template", "anubis", "name or path of the challenge template to use (anubis, forgejo)")
@@ -73,7 +74,7 @@ func main() {
 		leveler.Set(programLevel)
 
 		h := slog.NewJSONHandler(os.Stderr, &slog.HandlerOptions{
-			AddSource: true,
+			AddSource: *debug,
 			Level:     leveler,
 		})
 		slog.SetDefault(slog.New(h))
@@ -91,6 +92,7 @@ func main() {
 	}
 
 	state, err := lib.NewState(p, lib.StateSettings{
+		Debug:                  *debug,
 		PackagePath:            "git.gammaspectra.live/git/go-away/cmd",
 		ChallengeTemplate:      *challengeTemplate,
 		ChallengeTemplateTheme: *challengeTemplateTheme,

lib/challenge.go

@@ -6,6 +6,7 @@ import (
 	"crypto/sha256"
 	"encoding/binary"
 	"errors"
+	"fmt"
 	"github.com/go-jose/go-jose/v4"
 	"github.com/go-jose/go-jose/v4/jwt"
 	"github.com/tetratelabs/wazero"
@@ -117,10 +118,10 @@ func (state *State) VerifyChallengeToken(name string, expectedKey []byte, w http
 				}
 			}
 		}
+	}
 	if cookie == nil {
 		return false, err
 	}
-	}
 
 	token, err := jwt.ParseSigned(cookie.Value, []jose.SignatureAlgorithm{jose.EdDSA})
 	if err != nil {
@@ -147,14 +148,20 @@ func (state *State) VerifyChallengeToken(name string, expectedKey []byte, w http
 		return false, errors.New("key mismatch")
 	}
 
-	if c.Verify != nil && rand.Float64() < c.VerifyProbability {
+	if c.Verify != nil {
+		if rand.Float64() < c.VerifyProbability {
 			// random spot check
 			if ok, err := c.Verify(expectedKey, string(i.Result)); err != nil {
 				return false, err
 			} else if !ok {
 				return false, errors.New("failed challenge verification")
 			}
+			r.Header.Set(fmt.Sprintf("X-Away-Challenge-%s-Verify", name), "FULL")
+		} else {
+			r.Header.Set(fmt.Sprintf("X-Away-Challenge-%s-Verify", name), "BRIEF")
 		}
+	}
+	r.Header.Set(fmt.Sprintf("X-Away-Challenge-%s-Verify", name), "CHECK")
 
 	return true, nil
 }

lib/http.go

@@ -6,6 +6,7 @@ import (
 	"context"
 	"crypto/rand"
 	"encoding/base64"
+	"encoding/hex"
 	"errors"
 	"fmt"
 	go_away "git.gammaspectra.live/git/go-away"
@@ -13,12 +14,14 @@ import (
 	"git.gammaspectra.live/git/go-away/lib/policy"
 	"github.com/google/cel-go/common/types"
 	"html/template"
+	"log/slog"
 	"maps"
 	"net"
 	"net/http"
 	"net/http/httputil"
 	"net/url"
 	"path/filepath"
+	"strconv"
 	"strings"
 	"time"
 )
@@ -67,7 +70,7 @@ func initTemplate(name, data string) error {
 	return nil
 }
 
-func makeReverseProxy(target string) (http.Handler, error) {
+func makeReverseProxy(target string) (*httputil.ReverseProxy, error) {
 	u, err := url.Parse(target)
 	if err != nil {
 		return nil, fmt.Errorf("failed to parse target URL: %w", err)
@@ -95,8 +98,9 @@ func makeReverseProxy(target string) (http.Handler, error) {
 	return rp, nil
 }
 
-func (state *State) challengePage(w http.ResponseWriter, status int, challenge string, params map[string]any) error {
+func (state *State) challengePage(w http.ResponseWriter, id string, status int, challenge string, params map[string]any) error {
 	input := make(map[string]any)
+	input["Id"] = id
 	input["Random"] = cacheBust
 	input["Challenge"] = challenge
 	input["Path"] = state.UrlPath
@@ -114,7 +118,7 @@ func (state *State) challengePage(w http.ResponseWriter, status int, challenge s
 
 	err := templates["challenge-"+state.Settings.ChallengeTemplate+".gohtml"].Execute(buf, input)
 	if err != nil {
-		_ = state.errorPage(w, http.StatusInternalServerError, err)
+		_ = state.errorPage(w, id, http.StatusInternalServerError, err)
 	} else {
 		w.WriteHeader(status)
 		_, _ = w.Write(buf.Bytes())
@@ -122,12 +126,13 @@ func (state *State) challengePage(w http.ResponseWriter, status int, challenge s
 	return nil
 }
 
-func (state *State) errorPage(w http.ResponseWriter, status int, err error) error {
+func (state *State) errorPage(w http.ResponseWriter, id string, status int, err error) error {
 	w.Header().Set("Content-Type", "text/html; charset=utf-8")
 
 	buf := bytes.NewBuffer(make([]byte, 0, 8192))
 
 	err2 := templates["challenge-"+state.Settings.ChallengeTemplate+".gohtml"].Execute(buf, map[string]any{
+		"Id":          id,
 		"Random":      cacheBust,
 		"Error":       err.Error(),
 		"Path":        state.UrlPath,
@@ -145,8 +150,23 @@ func (state *State) errorPage(w http.ResponseWriter, status int, err error) erro
 	return nil
 }
 
-func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
+func (state *State) addTiming(w http.ResponseWriter, name, desc string, duration time.Duration) {
+	if state.Settings.Debug {
+		w.Header().Add("Server-Timing", fmt.Sprintf("%s;desc=%s;dur=%d", name, strconv.Quote(desc), duration.Milliseconds()))
+	}
+}
 
+func (state *State) getLogger(r *http.Request) *slog.Logger {
+	return slog.With(
+		"request_id", r.Header.Get("X-Away-Id"),
+		"remote_address", state.GetRequestAddress(r),
+		"user_agent", r.UserAgent(),
+		"host", r.Host,
+		"path", r.URL.Path,
+	)
+}
+
+func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 	host := r.Host
 
 	backend, ok := state.Backends[host]
@@ -155,6 +175,10 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
+	lg := state.getLogger(r)
+
+	start := time.Now()
+
 	//TODO better matcher! combo ast?
 	env := map[string]any{
 		"host":          host,
@@ -178,23 +202,55 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 		}(),
 	}
 
+	state.addTiming(w, "rule-env", "Setup the rule environment", time.Since(start))
+
+	var (
+		ruleEvalDuration time.Duration
+	)
+
+	serve := func() {
+		state.addTiming(w, "rule-eval", "Evaluate access rules", ruleEvalDuration)
+		backend.ServeHTTP(w, r)
+	}
+
+	fail := func(code int, err error) {
+		state.addTiming(w, "rule-eval", "Evaluate access rules", ruleEvalDuration)
+		_ = state.errorPage(w, r.Header.Get("X-Away-Id"), code, err)
+	}
+
+	setAwayState := func(rule RuleState) {
+		r.Header.Set("X-Away-Rule", rule.Name)
+		r.Header.Set("X-Away-Hash", rule.Hash)
+		r.Header.Set("X-Away-Action", string(rule.Action))
+	}
+
 	for _, rule := range state.Rules {
 		// skip rules that have host match
 		if rule.Host != nil && *rule.Host != host {
 			continue
 		}
-		if out, _, err := rule.Program.Eval(env); err != nil {
+		start = time.Now()
-			//TODO error
+		out, _, err := rule.Program.Eval(env)
+		ruleEvalDuration += time.Since(start)
+
+		if err != nil {
+			fail(http.StatusInternalServerError, err)
+			lg.Error(err.Error(), "rule", rule.Name, "rule_hash", rule.Hash)
 			panic(err)
+			return
 		} else if out != nil && out.Type() == types.BoolType {
 			if out.Equal(types.True) == types.True {
 				switch rule.Action {
 				default:
 					panic(fmt.Errorf("unknown action %s", rule.Action))
 				case policy.RuleActionPASS:
-					backend.ServeHTTP(w, r)
+					lg.Debug("request passed", "rule", rule.Name, "rule_hash", rule.Hash)
+					setAwayState(rule)
+					serve()
 					return
 				case policy.RuleActionCHALLENGE, policy.RuleActionCHECK:
+					start = time.Now()
+
 					expiry := time.Now().UTC().Add(DefaultValidity).Round(DefaultValidity)
 
 					for _, challengeName := range rule.Challenges {
@@ -209,11 +265,14 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 								goto nextRule
 							}
 							// we passed the challenge!
-							//TODO log?
+
-							backend.ServeHTTP(w, r)
+							lg.Debug("request passed", "rule", rule.Name, "rule_hash", rule.Hash, "challenge", challengeName)
+							setAwayState(rule)
+							serve()
 							return
 						}
 					}
+					state.addTiming(w, "challenge-token-check", "Verify client challenge tokens", time.Since(start))
 
 					// none matched, issue first challenge in priority
 					for _, challengeName := range rule.Challenges {
@@ -222,6 +281,7 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 							result := c.Challenge(w, r, state.GetChallengeKeyForRequest(challengeName, expiry, r), expiry)
 							switch result {
 							case ChallengeResultStop:
+								lg.Info("request challenged", "rule", rule.Name, "rule_hash", rule.Hash, "challenge", challengeName)
 								return
 							case ChallengeResultContinue:
 								continue
@@ -230,7 +290,11 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 									goto nextRule
 								}
 								// we pass the challenge early!
-								backend.ServeHTTP(w, r)
+								r.Header.Set(fmt.Sprintf("X-Away-Challenge-%s-Verify", challengeName), "PASS")
+
+								lg.Debug("request passed", "rule", rule.Name, "rule_hash", rule.Hash, "challenge", challengeName)
+								setAwayState(rule)
+								serve()
 								return
 							}
 						} else {
@@ -238,13 +302,15 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 						}
 					}
 				case policy.RuleActionDENY:
+					lg.Info("request denied", "rule", rule.Name, "rule_hash", rule.Hash)
 					//TODO: config error code
-					_ = state.errorPage(w, http.StatusForbidden, fmt.Errorf("access denied: denied by administrative rule %s", rule.Hash))
+					fail(http.StatusForbidden, fmt.Errorf("access denied: denied by administrative rule %s/%s", r.Header.Get("X-Away-Id"), rule.Hash))
 					return
 				case policy.RuleActionBLOCK:
+					lg.Info("request blocked", "rule", rule.Name, "rule_hash", rule.Hash)
 					//TODO: config error code
 					//TODO: configure block
-					_ = state.errorPage(w, http.StatusForbidden, fmt.Errorf("access denied: blocked by administrative rule %s", rule.Hash))
+					fail(http.StatusForbidden, fmt.Errorf("access denied: blocked by administrative rule %s/%s", r.Header.Get("X-Away-Id"), rule.Hash))
 					return
 				}
 			}
@@ -253,7 +319,7 @@ func (state *State) handleRequest(w http.ResponseWriter, r *http.Request) {
 	nextRule:
 	}
 
-	backend.ServeHTTP(w, r)
+	serve()
 	return
 }
 
@@ -285,13 +351,25 @@ func (state *State) setupRoutes() error {
 					key := state.GetChallengeKeyForRequest(challengeName, expiry, r)
 					result := r.FormValue("result")
 
-					if ok, err := c.Verify(key, result); err != nil {
+					requestId, err := hex.DecodeString(r.FormValue("requestId"))
+					if err == nil {
+						r.Header.Set("X-Away-Id", hex.EncodeToString(requestId))
+					}
+
+					start := time.Now()
+					ok, err := c.Verify(key, result)
+					state.addTiming(w, "challenge-verify", "Verify client challenge", time.Since(start))
+
+					if err != nil {
+						state.getLogger(r).Error(fmt.Errorf("challenge error: %w", err).Error(), "challenge", challengeName, "redirect", r.FormValue("redirect"))
 						return err
 					} else if !ok {
+						state.getLogger(r).Warn("challenge failed", "challenge", challengeName, "redirect", r.FormValue("redirect"))
 						ClearCookie(CookiePrefix+challengeName, w)
-						_ = state.errorPage(w, http.StatusForbidden, fmt.Errorf("access denied: failed challenge %s", challengeName))
+						_ = state.errorPage(w, r.Header.Get("X-Away-Id"), http.StatusForbidden, fmt.Errorf("access denied: failed challenge %s", challengeName))
 						return nil
 					}
+					state.getLogger(r).Info("challenge passed", "challenge", challengeName, "redirect", r.FormValue("redirect"))
 
 					token, err := state.IssueChallengeToken(challengeName, key, []byte(result), expiry)
 					if err != nil {
@@ -305,7 +383,7 @@ func (state *State) setupRoutes() error {
 				}()
 				if err != nil {
 					ClearCookie(CookiePrefix+challengeName, w)
-					_ = state.errorPage(w, http.StatusInternalServerError, err)
+					_ = state.errorPage(w, r.Header.Get("X-Away-Id"), http.StatusInternalServerError, err)
 					return
 				}
 			})

lib/state.go

@@ -98,6 +98,7 @@ type ChallengeState struct {
 }
 
 type StateSettings struct {
+	Debug                  bool
 	PackagePath            string
 	ChallengeTemplate      string
 	ChallengeTemplateTheme string
@@ -120,6 +121,10 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 		if err != nil {
 			return nil, fmt.Errorf("backend %s: failed to make reverse proxy: %w", k, err)
 		}
+		backend.ErrorHandler = func(w http.ResponseWriter, r *http.Request, err error) {
+			state.getLogger(r).Error(fmt.Errorf("backend %s error: %w", k, err).Error())
+			_ = state.errorPage(w, r.Header.Get("X-Away-Id"), http.StatusBadGateway, err)
+		}
 		state.Backends[k] = backend
 	}
 
@@ -166,7 +171,7 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 			}
 		}
 
-		slog.Debug("loaded network prefixes", "network", k, "count", ranger.Len())
+		slog.Info("loaded network prefixes", "network", k, "count", ranger.Len())
 
 		state.Networks[k] = ranger
 	}
@@ -218,7 +223,6 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 
 			expectedCookie := p.Parameters["http-cookie"]
 
-			//todo
 			c.Challenge = func(w http.ResponseWriter, r *http.Request, key []byte, expiry time.Time) ChallengeResult {
 				if expectedCookie != "" {
 					if cookie, err := r.Cookie(expectedCookie); err != nil || cookie == nil {
@@ -278,10 +282,11 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 				values := make(url.Values)
 				values.Set("result", hex.EncodeToString(key))
 				values.Set("redirect", r.URL.String())
+				values.Set("requestId", r.Header.Get("X-Away-Id"))
 
 				redirectUri.RawQuery = values.Encode()
 
-				_ = state.challengePage(w, http.StatusTeapot, "", map[string]any{
+				_ = state.challengePage(w, r.Header.Get("X-Away-Id"), http.StatusTeapot, "", map[string]any{
 					"Meta": map[string]string{
 						"refresh": "0; url=" + redirectUri.String(),
 					},
@@ -297,13 +302,14 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 				values := make(url.Values)
 				values.Set("result", hex.EncodeToString(key))
 				values.Set("redirect", r.URL.String())
+				values.Set("requestId", r.Header.Get("X-Away-Id"))
 
 				redirectUri.RawQuery = values.Encode()
 
 				// self redirect!
 				w.Header().Set("Refresh", "0; url="+redirectUri.String())
 
-				_ = state.challengePage(w, http.StatusTeapot, "", nil)
+				_ = state.challengePage(w, r.Header.Get("X-Away-Id"), http.StatusTeapot, "", nil)
 
 				return ChallengeResultStop
 			}
@@ -314,13 +320,14 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 
 				values := make(url.Values)
 				values.Set("result", hex.EncodeToString(key))
+				values.Set("requestId", r.Header.Get("X-Away-Id"))
 
 				redirectUri.RawQuery = values.Encode()
 
 				// self redirect!
 				w.Header().Set("Refresh", "2; url="+r.URL.String())
 
-				_ = state.challengePage(w, http.StatusTeapot, "", map[string]any{
+				_ = state.challengePage(w, r.Header.Get("X-Away-Id"), http.StatusTeapot, "", map[string]any{
 					"Tags": []template.HTML{
 						template.HTML(fmt.Sprintf("<link href=\"%s\" rel=\"stylesheet\" crossorigin=\"use-credentials\">", redirectUri.String())),
 					},
@@ -330,7 +337,7 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 			}
 		case "js":
 			c.Challenge = func(w http.ResponseWriter, r *http.Request, key []byte, expiry time.Time) ChallengeResult {
-				_ = state.challengePage(w, http.StatusTeapot, challengeName, nil)
+				_ = state.challengePage(w, r.Header.Get("X-Away-Id"), http.StatusTeapot, challengeName, nil)
 
 				return ChallengeResultStop
 			}
@@ -405,13 +412,20 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 					key := state.GetChallengeKeyForRequest(challengeName, expiry, r)
 					result := r.FormValue("result")
 
+					requestId, err := hex.DecodeString(r.FormValue("requestId"))
+					if err == nil {
+						r.Header.Set("X-Away-Id", hex.EncodeToString(requestId))
+					}
+
 					if ok, err := c.Verify(key, result); err != nil {
 						return err
 					} else if !ok {
+						state.getLogger(r).Warn("challenge failed", "challenge", challengeName, "redirect", r.FormValue("redirect"))
 						ClearCookie(CookiePrefix+challengeName, w)
-						_ = state.errorPage(w, http.StatusForbidden, fmt.Errorf("access denied: failed challenge %s", challengeName))
+						_ = state.errorPage(w, r.Header.Get("X-Away-Id"), http.StatusForbidden, fmt.Errorf("access denied: failed challenge %s", challengeName))
 						return nil
 					}
+					state.getLogger(r).Warn("challenge passed", "challenge", challengeName, "redirect", r.FormValue("redirect"))
 
 					token, err := state.IssueChallengeToken(challengeName, key, []byte(result), expiry)
 					if err != nil {
@@ -435,7 +449,7 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 				}()
 				if err != nil {
 					ClearCookie(CookiePrefix+challengeName, w)
-					_ = state.errorPage(w, http.StatusInternalServerError, err)
+					_ = state.errorPage(w, r.Header.Get("X-Away-Id"), http.StatusInternalServerError, err)
 					return
 				}
 			})
@@ -478,7 +492,7 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 					return nil
 				})
 				if err != nil {
-					_ = state.errorPage(w, http.StatusInternalServerError, err)
+					_ = state.errorPage(w, r.Header.Get("X-Away-Id"), http.StatusInternalServerError, err)
 					return
 				}
 			})
@@ -641,5 +655,10 @@ func NewState(p policy.Policy, settings StateSettings) (state *State, err error)
 }
 
 func (state *State) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	requestId := make([]byte, 16)
+	_, _ = rand.Read(requestId)
+
+	r.Header.Set("X-Away-Id", hex.EncodeToString(requestId))
+
 	state.Mux.ServeHTTP(w, r)
 }

templates/challenge-anubis.gohtml

@@ -177,6 +177,7 @@
             <summary>Why am I seeing this?</summary>
             <p>You are seeing this because the administrator of this website has set up <a href="https://git.gammaspectra.live/git/go-away">go-away</a> to protect the server against the scourge of <a href="https://thelibre.news/foss-infrastructure-is-under-attack-by-ai-companies/">AI companies aggressively scraping websites</a>. This can and does cause downtime for the websites, which makes their resources inaccessible for everyone.</p>
             <p>Please note that some challenges requires the use of modern JavaScript features and some plugins may will disable. Please disable such plugins for this domain (for example, JShelter).</p>
+            <p>If you have any issues contact the administrator and provide this request id: <em>{{ .Id }}</em></p>
         </details>
         <noscript>
             <p>
@@ -191,7 +192,7 @@
     <footer>
         <center>
             <p>
-                Protected by <a href="https://git.gammaspectra.live/git/go-away">go-away</a>
+                Protected by <a href="https://git.gammaspectra.live/git/go-away">go-away</a> :: Request Id <em>{{ .Id }}</em>
             </p>
         </center>
     </footer>

templates/challenge-forgejo.gohtml

@@ -74,6 +74,7 @@
                         <summary>Why am I seeing this?</summary>
                         <p>You are seeing this because the administrator of this website has set up <a href="https://git.gammaspectra.live/git/go-away">go-away</a> to protect the server against the scourge of <a href="https://thelibre.news/foss-infrastructure-is-under-attack-by-ai-companies/">AI companies aggressively scraping websites</a>. This can and does cause downtime for the websites, which makes their resources inaccessible for everyone.</p>
                         <p>Please note that some challenges requires the use of modern JavaScript features and some plugins may will disable. Please disable such plugins for this domain (for example, JShelter).</p>
+                        <p>If you have any issues contact the administrator and provide the request id: <em>{{ .Id }}</em></p>
                     </details>
 
 
@@ -92,7 +93,7 @@
 
 <footer class="page-footer" role="group" aria-label="">
     <div class="left-links" role="contentinfo" aria-label="">
-        Protected by <a href="https://git.gammaspectra.live/git/go-away">go-away</a>
+        Protected by <a href="https://git.gammaspectra.live/git/go-away">go-away</a> :: Request Id <em>{{ .Id }}</em>
     </div>
 </footer>
 

templates/challenge.mjs

@@ -56,6 +56,7 @@ const u = (url = "", params = {}) => {
             window.location.href = u("{{ .Path }}/verify-challenge", {
                 result: result,
                 redirect: redir,
+                requestId: "{{ .Id }}",
                 elapsedTime: t1 - t0,
             });
         }, 500);