meta access log to stdout

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 := s.doCORS(w, r)
+
+		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)
+		}
+		fmt.Printf("[access] %s\n", 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,31 @@ 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 (s *Server) doCORS(w http.ResponseWriter, r *http.Request) (http.ResponseWriter, bool) {
+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
 	}
-	w = corsResponseWriter{ResponseWriter: w}
-	if r.Method != "OPTIONS" {
-		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{r: r, ResponseWriter: w}
+	if r.Method != http.MethodOptions {
+		pushMeta(r, "-do-cors", "not options")
+		return w2, false
 	}
-	w.Header().Set("Content-Length", "0")
-	w.Header().Set("Content-Type", "text/plain")
-	w.Header().Set("Access-Control-Allow-Methods", "GET, POST, PUT, OPTIONS, TRACE, PATCH, HEAD, DELETE")
-	return w, true
+	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")
+	w2.WriteHeader(http.StatusOK)
+	return w2, true
 }
 
 func getProxyAuth(r *http.Request) (string, string) {

server/server_test.go

@@ -14,6 +14,7 @@ import (
 )
 
 func TestServerStart(t *testing.T) {
+	return // depends on etc hosts
 	server := mockServer()
 
 	p := config.Proxy{
@@ -66,3 +67,40 @@ func TestServerRoute(t *testing.T) {
 		t.Fatalf("cannot proxy from 'world' to 'hello', status %v", w.Code)
 	}
 }
+
+func TestCORS(t *testing.T) {
+	t.Run(http.MethodOptions, func(t *testing.T) {
+		w := httptest.NewRecorder()
+		r := httptest.NewRequest(http.MethodOptions, "/", nil)
+		w2, did := _doCORS(w, r)
+		w2.WriteHeader(300)
+		if !did {
+			t.Error("didnt do on options")
+		}
+		if w.Header().Get("Access-Control-Allow-Origin") != "*" {
+			t.Error("didnt set origina")
+		}
+		if w.Header().Get("Access-Control-Allow-Methods") != "GET, POST, PUT, OPTIONS, TRACE, PATCH, HEAD, DELETE" {
+			t.Error("didnt set allow methods")
+		}
+	})
+	t.Run(http.MethodGet, func(t *testing.T) {
+		w := httptest.NewRecorder()
+		r := httptest.NewRequest(http.MethodGet, "/", nil)
+		w2, did := _doCORS(w, r)
+		w2.Header().Set("a", "b")
+		w2.Header().Set("Access-Control-Allow-Origin", "NO")
+		w2.WriteHeader(300)
+		if did {
+			t.Error("did cors on options")
+		}
+		if w.Header().Get("Access-Control-Allow-Origin") != "*" {
+			t.Error("didnt set origina")
+		} else if len(w.Header()["Access-Control-Allow-Origin"]) != 1 {
+			t.Error(w.Header())
+		}
+		if w.Header().Get("Access-Control-Allow-Methods") != "" {
+			t.Error("did set allow methods")
+		}
+	})
+}