add access log

server/server.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"crypto/tls"
 	"encoding/base64"
+	"encoding/json"
 	"errors"
 	"fmt"
 	"io"
@@ -17,9 +18,11 @@ import (
 	"net/http"
 	"net/url"
 	"path"
+	"strconv"
 	"strings"
 	"time"
 
+	"github.com/google/uuid"
 	"golang.org/x/time/rate"
 )
 
@@ -263,16 +266,23 @@ func pipe(a, b net.Conn) {
 
 func (s *Server) Pre(foo http.HandlerFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, r *http.Request) {
+		r, flush := withMeta(w, r)
+		defer flush()
+
 		ctx, can := context.WithTimeout(r.Context(), time.Duration(config.GetTimeout()))
 		defer can()
 		if err := s.limiter.Wait(ctx); err != nil {
+			pushMeta(r, "explain", "limiter exceeded")
 			w.WriteHeader(http.StatusTooManyRequests)
 			return
 		}
+
 		w, did := doCORS(w, r)
 		if did {
+			pushMeta(r, "explain", "did cors")
 			return
 		}
+
 		if s.auth.BOAuthZ {
 			logb.Verbosef("doing boauthz for request to %s", r.URL.String())
 			s.doBOAuthZ(foo)(w, r)
@@ -285,11 +295,44 @@ func (s *Server) Pre(foo http.HandlerFunc) http.HandlerFunc {
 	}
 }
 
+func withMeta(w http.ResponseWriter, r *http.Request) (*http.Request, func()) {
+	meta := map[string]string{
+		"ts":     strconv.FormatInt(time.Now().Unix(), 10),
+		"method": r.Method,
+		"url":    r.URL.String(),
+		"id":     uuid.New().String(),
+	}
+	w.Header().Set("meta-id", meta["id"])
+	ctx := r.Context()
+	ctx = context.WithValue(ctx, "meta", meta)
+	r = r.WithContext(ctx)
+	return r, func() {
+		b, err := json.Marshal(meta)
+		if err != nil {
+			panic(err)
+		}
+		log.Printf("[access] %s", b)
+	}
+}
+
+func pushMeta(r *http.Request, k, v string) {
+	got := r.Context().Value("meta")
+	if got == nil {
+		return
+	}
+	meta, ok := got.(map[string]string)
+	if !ok || meta == nil {
+		return
+	}
+	meta[k] = v
+}
+
 func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	s.Pre(s.Proxy)(w, r)
 }
 
 type corsResponseWriter struct {
+	r *http.Request
 	http.ResponseWriter
 }
 
@@ -297,21 +340,26 @@ func (cb corsResponseWriter) WriteHeader(code int) {
 	cb.Header().Set("Access-Control-Allow-Origin", "*")
 	cb.Header().Set("Access-Control-Allow-Headers", "X-Auth-Token, content-type, Content-Type")
 	cb.ResponseWriter.WriteHeader(code)
+	pushMeta(cb.r, "cors", "wrote headers")
 }
 
 func doCORS(w http.ResponseWriter, r *http.Request) (http.ResponseWriter, bool) {
 	key := mapKey(r.Host)
 	if !config.GetCORS(key) {
+		pushMeta(r, "do-cors", "not enabled for key")
 		return w, false
 	}
+	pushMeta(r, "do-cors", "enabled for key")
 	return _doCORS(w, r)
 }
 
 func _doCORS(w http.ResponseWriter, r *http.Request) (http.ResponseWriter, bool) {
-	w2 := corsResponseWriter{ResponseWriter: w}
+	w2 := corsResponseWriter{r: r, ResponseWriter: w}
 	if r.Method != http.MethodOptions {
+		pushMeta(r, "-do-cors", "not options")
 		return w2, false
 	}
+	pushMeta(r, "-do-cors", "options")
 	w2.Header().Set("Content-Length", "0")
 	w2.Header().Set("Content-Type", "text/plain")
 	w2.Header().Set("Access-Control-Allow-Methods", "GET, POST, PUT, OPTIONS, TRACE, PATCH, HEAD, DELETE")