log: add trace id and http request logs.

- Added the concept of a "trace id", a unique ID which gets associated
with every log/request by default. Will eventually use
opentelemetry/opentracing, or perhaps something better... Still very
alpha quality + lots of dependencies/API surface to bring in. For the
purpose of MicroMDM, a unique identifier per request is fine.

- Added HTTP logging middleware.

go.mod

@@ -3,6 +3,7 @@ module micromdm.io/v2
 go 1.14
 
 require (
+	github.com/felixge/httpsnoop v1.0.1
 	github.com/go-kit/kit v0.10.0
 	github.com/oklog/ulid v1.3.1 // indirect
 	github.com/oklog/ulid/v2 v2.0.2

go.sum

@@ -48,6 +48,8 @@ github.com/envoyproxy/go-control-plane v0.6.9/go.mod h1:SBwIajubJHhxtWwsL9s8ss4s
 github.com/envoyproxy/go-control-plane v0.9.1-0.20191026205805-5f8ba28d4473/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4=
 github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c=
 github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5KwzbycvMj4=
+github.com/felixge/httpsnoop v1.0.1 h1:lvB5Jl89CsZtGIWuTcDM1E/vkVs49/Ml7JJe07l8SPQ=
+github.com/felixge/httpsnoop v1.0.1/go.mod h1:m8KPJKqk1gH5J9DgRY2ASl2lWCfGKXixSwevea8zH2U=
 github.com/franela/goblin v0.0.0-20200105215937-c9ffbefa60db/go.mod h1:7dvUGVsVBjqR7JHJk0brhHOZYGmfBYOrK0ZhYMEtBr4=
 github.com/franela/goreq v0.0.0-20171204163338-bcd34c9993f8/go.mod h1:ZhphrRTfi2rbfLwlschooIH4+wKKDR4Pdxhh+TRoA20=
 github.com/fsnotify/fsnotify v1.4.7/go.mod h1:jwhsz4b93w/PPRr/qN1Yymfu8t87LnFCMoQvtojpjFo=

pkg/log/context.go

@@ -20,5 +20,7 @@ func FromContext(ctx context.Context) Logger {
 		return log.NewNopLogger()
 	}
 
-	return v
+	span := traceFromContext(ctx)
+
+	return log.With(v, "trace_id", span.TraceID)
 }

pkg/log/http.go

@@ -0,0 +1,75 @@
+package log
+
+import (
+	"context"
+	"net"
+	"net/http"
+
+	"github.com/felixge/httpsnoop"
+)
+
+// HTTP returns an HTTP logging middleware using the provided base logger.
+func HTTP(l Logger) func(http.Handler) http.Handler { return handler{logger: l}.decorate }
+
+type handler struct{ logger Logger }
+
+func (h handler) decorate(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		ctx := newTraceContext(r.Context())
+		ctx = NewContext(ctx, h.logger)
+
+		// https://github.com/felixge/httpsnoop#why-this-package-exists
+		// https://github.com/golang/go/issues/18997
+		var metrics httpsnoop.Metrics
+
+		defer func() {
+			logRequest(ctx, metrics.Code, r)
+		}()
+
+		metrics = httpsnoop.CaptureMetrics(next, w, r.WithContext(ctx))
+	})
+}
+
+func logRequest(ctx context.Context, code int, r *http.Request) {
+	host, _, err := net.SplitHostPort(r.RemoteAddr)
+	if err != nil {
+		host = r.RemoteAddr
+	}
+
+	url := *r.URL
+	uri := r.RequestURI
+
+	// Requests using the CONNECT method over HTTP/2.0 must use
+	// the authority field (aka r.Host) to identify the target.
+	// Refer: https://httpwg.github.io/specs/rfc7540.html#CONNECT
+	if r.ProtoMajor == 2 && r.Method == "CONNECT" {
+		uri = r.Host
+	}
+
+	if uri == "" {
+		uri = url.RequestURI()
+	}
+
+	keyvals := []interface{}{
+		"method", r.Method,
+		"status", code,
+		"proto", r.Proto,
+		"host", host,
+		"user_agent", r.UserAgent(),
+		"path", uri,
+	}
+
+	if fwd := r.Header.Get("X-Forwarded-For"); fwd != "" {
+		keyvals = append(keyvals, "x_forwarded_for", fwd)
+	}
+
+	if referer := r.Referer(); referer != "" {
+		keyvals = append(keyvals, "referer", referer)
+	}
+
+	if code >= 500 {
+		Info(FromContext(ctx)).Log(keyvals...)
+	} else {
+		Debug(FromContext(ctx)).Log(keyvals...)
+	}
+}

pkg/log/trace.go

@@ -0,0 +1,34 @@
+package log
+
+import (
+	"context"
+
+	"micromdm.io/v2/pkg/id"
+)
+
+// TraceID return a unique ID associated with a request.
+// The trace ID can be used to identify a particular HTTP response and logged error.
+func TraceID(ctx context.Context) string {
+	return traceFromContext(ctx).TraceID
+}
+
+const traceKey key = 1
+
+// span will eventually get replaced by http://opentelemetry.io
+// or something similar.
+type span struct {
+	TraceID string
+}
+
+func newTraceContext(ctx context.Context) context.Context {
+	return context.WithValue(ctx, traceKey, span{TraceID: id.New()})
+}
+
+func traceFromContext(ctx context.Context) span {
+	v, ok := ctx.Value(traceKey).(span)
+	if !ok {
+		return span{TraceID: id.New()}
+	}
+
+	return v
+}