diff --git a/go.mod b/go.mod index 27a8aeb1..6e5a08a4 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index d57ef1eb..684c71c4 100644 --- a/go.sum +++ b/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= diff --git a/pkg/log/context.go b/pkg/log/context.go index a0d115b6..4a95fac3 100644 --- a/pkg/log/context.go +++ b/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) } diff --git a/pkg/log/http.go b/pkg/log/http.go new file mode 100644 index 00000000..f0b25ddb --- /dev/null +++ b/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...) + } +} diff --git a/pkg/log/trace.go b/pkg/log/trace.go new file mode 100644 index 00000000..267317a3 --- /dev/null +++ b/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 +}