add new trace logging handler

http/http.go

@@ -1,14 +1,40 @@
 // Package http includes handlers and utilties.
 package http
 
-import "net/http"
+import (
+	"crypto/subtle"
+	"net/http"
+)
 
-// JSONVersionHandler returns a simple JSON response from a version string.
-// The returned JSON is in the form of `{"version":"v0.0.1"}`.
-func JSONVersionHandler(version string) http.HandlerFunc {
+// NewJSONVersionHandler responds with JSON from version.
+// The JSON is in the form of `{"version":"v0.0.1"}`.
+// No validation is done on version; it should conform to a JSON string.
+func NewJSONVersionHandler(version string) http.HandlerFunc {
 	bodyBytes := []byte(`{"version":"` + version + `"}`)
-	return func(w http.ResponseWriter, r *http.Request) {
+	return func(w http.ResponseWriter, _ *http.Request) {
 		w.Header().Set("Content-Type", "application/json")
 		w.Write(bodyBytes)
 	}
 }
+
+// NewSimpleBasicAuthHandler is an HTTP Basic authentication middleware.
+// The returned handler verifies the the correct authentication against
+// username and password before handing off to next, or reponds with
+// an HTTP 401 setting the WWW-Authenticate header using realm.
+func NewSimpleBasicAuthHandler(next http.Handler, username, password, realm string) http.HandlerFunc {
+	// cache 1-time data
+	ubc := []byte(username)
+	pbc := []byte(password)
+	rc := `Basic realm="` + realm + `"`
+	return func(w http.ResponseWriter, r *http.Request) {
+		u, p, ok := r.BasicAuth()
+		if !ok ||
+			subtle.ConstantTimeCompare([]byte(u), ubc) != 1 ||
+			subtle.ConstantTimeCompare([]byte(p), pbc) != 1 {
+			w.Header().Set("Www-Authenticate", rc)
+			http.Error(w, http.StatusText(http.StatusUnauthorized), http.StatusUnauthorized)
+			return
+		}
+		next.ServeHTTP(w, r)
+	}
+}

http/trace/trace.go

@@ -0,0 +1,55 @@
+// Pacakge trace implements a trace logging HTTP request middleware handler.
+package trace
+
+import (
+	"context"
+	"net"
+	"net/http"
+
+	"github.com/micromdm/nanolib/log"
+	"github.com/micromdm/nanolib/log/ctxlog"
+)
+
+type ctxKeyTraceID struct{}
+
+// GetTraceID returns the trace ID from ctx.
+func GetTraceID(ctx context.Context) string {
+	id, _ := ctx.Value(ctxKeyTraceID{}).(string)
+	return id
+}
+
+// NewTraceLoggingHandler logs HTTP request details and sets up trace logging.
+// The host, method, URL path, user agent are immediately logged.
+// The "x_forwarded_for" header is also logged if present.
+// The "trace_id" key will be set on the context logger and logged if
+// traceIDFn is set.
+func NewTraceLoggingHandler(next http.Handler, logger log.Logger, traceIDFn func(*http.Request) string) http.HandlerFunc {
+	return func(w http.ResponseWriter, r *http.Request) {
+		ctx := r.Context()
+
+		if traceIDFn != nil {
+			ctx = context.WithValue(ctx, ctxKeyTraceID{}, traceIDFn(r))
+			ctx = ctxlog.AddFunc(ctx, ctxlog.SimpleStringFunc("trace_id", ctxKeyTraceID{}))
+		}
+
+		host, _, err := net.SplitHostPort(r.RemoteAddr)
+		if err != nil {
+			host = r.RemoteAddr
+		}
+
+		logs := []interface{}{
+			"addr", host,
+			"method", r.Method,
+			"path", r.URL.Path,
+			"agent", r.UserAgent(),
+		}
+
+		if fwdedFor := r.Header.Get("X-Forwarded-For"); fwdedFor != "" {
+			logs = append(logs, "x_forwarded_for", fwdedFor)
+		}
+
+		ctxlog.Logger(ctx, logger).Info(logs...)
+
+		next.ServeHTTP(w, r.WithContext(ctx))
+	}
+}

http/trace/trace_test.go

@@ -0,0 +1,68 @@
+package trace
+
+import (
+	"context"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/micromdm/nanolib/log/test"
+)
+
+type contextCapture struct {
+	body []byte
+	ctx  context.Context
+}
+
+func (c *contextCapture) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+	c.ctx = r.Context()
+	w.Write(c.body)
+}
+
+func TestHTTPCtxLog(t *testing.T) {
+	ctx := context.Background()
+
+	r, err := http.NewRequestWithContext(ctx, "GET", "/x-test-path", nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	w := httptest.NewRecorder()
+
+	logger := &test.Logger{KeepLastWith: true}
+
+	next := &contextCapture{body: []byte("x-test-body")}
+
+	handler := NewTraceLoggingHandler(next, logger, func(_ *http.Request) string { return "x-test-trace" })
+
+	handler.ServeHTTP(w, r)
+
+	if want, have := http.StatusOK, w.Code; want != have {
+		t.Errorf("http status: want: %q, have: %q", want, have)
+	}
+
+	if want, have := "x-test-body", w.Body.String(); want != have {
+		t.Errorf("body bytes: want: %q, have: %q", want, have)
+	}
+
+	// verify the trace ID is on the captured request context
+	if want, have := "x-test-trace", GetTraceID(next.ctx); want != have {
+		t.Errorf("body bytes: want: %q, have: %q", want, have)
+	}
+
+	// also check the trace ID made it through to the log line
+	logVal, _ := logger.LastKeyStringValue("trace_id")
+	if want, have := "x-test-trace", logVal; want != have {
+		t.Errorf("body bytes: want: %q, have: %q", want, have)
+	}
+
+	logVal, _ = logger.LastKeyStringValue("method")
+	if want, have := "GET", logVal; want != have {
+		t.Errorf("body bytes: want: %q, have: %q", want, have)
+	}
+
+	logVal, _ = logger.LastKeyStringValue("path")
+	if want, have := "/x-test-path", logVal; want != have {
+		t.Errorf("body bytes: want: %q, have: %q", want, have)
+	}
+}

log/test/logger.go

@@ -16,14 +16,21 @@ type Log struct {
 type Logger struct {
 	mu       sync.RWMutex
 	ctx      []interface{}
-	lastLogs []Log
+	lastLogs *[]Log
+
+	// KeepLastWith turns on keeping and sharing of the last log lines
+	// for loggers in the With() chain.
+	KeepLastWith bool
 }
 
 // Info logs using the info level appending to the test logger's stored logs.
 func (l *Logger) Info(args ...interface{}) {
 	l.mu.Lock()
 	defer l.mu.Unlock()
-	l.lastLogs = append(l.lastLogs, Log{
+	if l.lastLogs == nil {
+		l.lastLogs = &[]Log{}
+	}
+	*l.lastLogs = append(*l.lastLogs, Log{
 		Debug: false,
 		Log:   append(l.ctx, args...),
 	})
@@ -33,7 +40,10 @@ func (l *Logger) Info(args ...interface{}) {
 func (l *Logger) Debug(args ...interface{}) {
 	l.mu.Lock()
 	defer l.mu.Unlock()
-	l.lastLogs = append(l.lastLogs, Log{
+	if l.lastLogs == nil {
+		l.lastLogs = &[]Log{}
+	}
+	*l.lastLogs = append(*l.lastLogs, Log{
 		Debug: true,
 		Log:   append(l.ctx, args...),
 	})
@@ -43,17 +53,29 @@ func (l *Logger) Debug(args ...interface{}) {
 func (l *Logger) With(args ...interface{}) log.Logger {
 	l.mu.RLock()
 	defer l.mu.RUnlock()
-	return &Logger{ctx: append(l.ctx, args...)}
+	if l.lastLogs == nil {
+		l.lastLogs = &[]Log{}
+	}
+	newLogger := &Logger{ctx: append(l.ctx, args...)}
+	if l.KeepLastWith {
+		// note we copy the pointer of the lastLogs here to maintain the
+		// same log lines for any logger in this With() chain.
+		newLogger.lastLogs = l.lastLogs
+	}
+	return newLogger
 }
 
 // Last returns the last logged line.
 func (l *Logger) Last() *Log {
 	l.mu.RLock()
 	defer l.mu.RUnlock()
-	if len(l.lastLogs) < 1 {
+	if l.lastLogs == nil {
+		l.lastLogs = &[]Log{}
+	}
+	if len(*l.lastLogs) < 1 {
 		return nil
 	}
-	return &l.lastLogs[len(l.lastLogs)-1]
+	return &(*l.lastLogs)[len(*l.lastLogs)-1]
 }
 
 // LastKey returns the value at the string key in the last log line.
@@ -85,3 +107,11 @@ func (l *Logger) LastKey(key string) (last *Log, value interface{}, found bool)
 
 	return
 }
+
+// LastKeyStringValue is like LastKey but assumes you only want a string value.
+func (l *Logger) LastKeyStringValue(key string) (value string, found bool) {
+	var v interface{}
+	_, v, found = l.LastKey(key)
+	value, _ = v.(string)
+	return
+}