Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Context logging #39

Merged
merged 8 commits into from
Apr 3, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
26 changes: 24 additions & 2 deletions cmd/nanomdm/main.go
Original file line number Diff line number Diff line change
@@ -1,20 +1,24 @@
package main

import (
"context"
"crypto/subtle"
"crypto/x509"
"flag"
"fmt"
"io/ioutil"
stdlog "log"
"math/rand"
"net"
"net/http"
"os"
"time"

"github.com/micromdm/nanomdm/certverify"
"github.com/micromdm/nanomdm/cmd/cli"
mdmhttp "github.com/micromdm/nanomdm/http"
"github.com/micromdm/nanomdm/log"
"github.com/micromdm/nanomdm/log/ctxlog"
"github.com/micromdm/nanomdm/log/stdlogfmt"
"github.com/micromdm/nanomdm/push/buford"
pushsvc "github.com/micromdm/nanomdm/push/service"
Expand Down Expand Up @@ -196,6 +200,8 @@ func main() {
w.Write([]byte(`{"version":"` + version + `"}`))
})

rand.Seed(time.Now().UnixNano())

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it possible to make this configurable for testing purposes?

Also, is it possible to get a separately-seeded/used sequence, so that this will only be used for the trace-ids?

(If you need cryptographic strength here, this isn't a good enough seed, and also not a good enough package...but it doesn't look like you need it)

(looks like you can create your own source/random object... just can't be easily used concurrently)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

main.go is the "reference" nanoMDM implementation afaik. Any other implementer who uses the NanoMDM library could do this in a separate way, so I don't think this is an issue.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's a testability consideration, not anything else.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(As far as I can tell, the only security implication of UUIDs is preventing collisions. So ... any seeding is "good enough", and use of a cryptographic PRNG is unnecessary. There's no harm if someone can guess a UUID.

So I'm just asking for "creation of unit test" purposes: if you can control the PRNG seed, you can get repeatable sequences out which makes testing easier.

If this isn't where anyone would actually test this, then ... yeah. Nevermind/drop)


logger.Info("msg", "starting server", "listen", *flListen)
err = http.ListenAndServe(*flListen, simpleLog(mux, logger.With("handler", "log")))
logs := []interface{}{"msg", "server shutdown"}
Expand All @@ -219,8 +225,24 @@ func basicAuth(next http.Handler, username, password, realm string) http.Handler
}
}

type ctxKeyTraceID struct{}

// storeNewTraceID generates a new trace identifier and stores it on
// the context.
func storeNewTraceID(ctx context.Context) context.Context {
// currently this just makes a random string. this would be better
// served by e.g. https://github.com/oklog/ulid or something like
// https://opentelemetry.io/ someday.
b := make([]byte, 8)
rand.Read(b)
id := fmt.Sprintf("%x", b)
return context.WithValue(ctx, ctxKeyTraceID{}, id)
}

func simpleLog(next http.Handler, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
ctx := storeNewTraceID(r.Context())
ctx = ctxlog.AddFunc(ctx, ctxlog.SimpleStringFunc("trace_id", ctxKeyTraceID{}))
host, _, err := net.SplitHostPort(r.RemoteAddr)
if err != nil {
host = r.RemoteAddr
Expand All @@ -234,7 +256,7 @@ func simpleLog(next http.Handler, logger log.Logger) http.HandlerFunc {
if fwdedFor := r.Header.Get("X-Forwarded-For"); fwdedFor != "" {
logs = append(logs, "real_ip", fwdedFor)
}
logger.Info(logs...)
next.ServeHTTP(w, r)
ctxlog.Logger(ctx, logger).Info(logs...)
next.ServeHTTP(w, r.WithContext(ctx))
}
}
4 changes: 4 additions & 0 deletions http/api.go
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ import (

"github.com/micromdm/nanomdm/cryptoutil"
"github.com/micromdm/nanomdm/log"
"github.com/micromdm/nanomdm/log/ctxlog"
"github.com/micromdm/nanomdm/mdm"
"github.com/micromdm/nanomdm/push"
"github.com/micromdm/nanomdm/storage"
Expand Down Expand Up @@ -45,6 +46,7 @@ type apiResult struct {
// users.
func PushHandlerFunc(pusher push.Pusher, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
ids := strings.Split(r.URL.Path, ",")
output := apiResult{
Status: make(enrolledAPIResults),
Expand Down Expand Up @@ -88,6 +90,7 @@ func PushHandlerFunc(pusher push.Pusher, logger log.Logger) http.HandlerFunc {
// for "API" users.
func RawCommandEnqueueHandler(enqueuer storage.CommandEnqueuer, pusher push.Pusher, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
b, err := ReadAllAndReplaceBody(r)
if err != nil {
logger.Info("msg", "reading body", "err", err)
Expand Down Expand Up @@ -169,6 +172,7 @@ func RawCommandEnqueueHandler(enqueuer storage.CommandEnqueuer, pusher push.Push
// upload our push certs.
func StorePushCertHandlerFunc(storage storage.PushCertStore, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
b, err := ReadAllAndReplaceBody(r)
if err != nil {
logger.Info("msg", "reading body", "err", err)
Expand Down
3 changes: 3 additions & 0 deletions http/mdm.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"strings"

"github.com/micromdm/nanomdm/log"
"github.com/micromdm/nanomdm/log/ctxlog"
"github.com/micromdm/nanomdm/mdm"
"github.com/micromdm/nanomdm/service"
)
Expand All @@ -26,6 +27,7 @@ func mdmReqFromHTTPReq(r *http.Request) *mdm.Request {
// CheckinHandlerFunc decodes an MDM check-in request and adapts it to service.
func CheckinHandlerFunc(svc service.Checkin, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
bodyBytes, err := ReadAllAndReplaceBody(r)
if err != nil {
logger.Info("msg", "reading body", "err", err)
Expand All @@ -49,6 +51,7 @@ func CheckinHandlerFunc(svc service.Checkin, logger log.Logger) http.HandlerFunc
// CommandAndReportResultsHandlerFunc decodes an MDM command request and adapts it to service.
func CommandAndReportResultsHandlerFunc(svc service.CommandAndReportResults, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
bodyBytes, err := ReadAllAndReplaceBody(r)
if err != nil {
logger.Info("msg", "reading body", "err", err)
Expand Down
12 changes: 10 additions & 2 deletions http/mdm_cert.go
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ import (

"github.com/micromdm/nanomdm/cryptoutil"
"github.com/micromdm/nanomdm/log"
"github.com/micromdm/nanomdm/log/ctxlog"
)

type contextKeyCert struct{}
Expand All @@ -21,6 +22,7 @@ type contextKeyCert struct{}
// similar header could be used, of course.
func CertExtractPEMHeaderMiddleware(next http.Handler, header string, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
escapedCert := r.Header.Get(header)
if escapedCert == "" {
logger.Debug("msg", "empty header", "header", header)
Expand Down Expand Up @@ -50,7 +52,9 @@ func CertExtractPEMHeaderMiddleware(next http.Handler, header string, logger log
func CertExtractTLSMiddleware(next http.Handler, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
if r.TLS == nil || len(r.TLS.PeerCertificates) < 1 {
logger.Debug("msg", "no TLS peer certificate")
ctxlog.Logger(r.Context(), logger).Debug(
"msg", "no TLS peer certificate",
)
next.ServeHTTP(w, r)
return
}
Expand All @@ -69,6 +73,7 @@ func CertExtractTLSMiddleware(next http.Handler, logger log.Logger) http.Handler
// verification fails.
func CertExtractMdmSignatureMiddleware(next http.Handler, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
logger := ctxlog.Logger(r.Context(), logger)
mdmSig := r.Header.Get("Mdm-Signature")
if mdmSig == "" {
logger.Debug("msg", "empty Mdm-Signature header")
Expand Down Expand Up @@ -112,7 +117,10 @@ type CertVerifier interface {
func CertVerifyMiddleware(next http.Handler, verifier CertVerifier, logger log.Logger) http.HandlerFunc {
return func(w http.ResponseWriter, r *http.Request) {
if err := verifier.Verify(GetCert(r.Context())); err != nil {
logger.Info("msg", "error verifying MDM certificate", "err", err)
ctxlog.Logger(r.Context(), logger).Info(
"msg", "error verifying MDM certificate",
"err", err,
)
http.Error(w, http.StatusText(http.StatusBadRequest), http.StatusBadRequest)
return
}
Expand Down
72 changes: 72 additions & 0 deletions log/ctxlog/ctxlog.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,72 @@
// Package ctxlog allows logging data stored with a context.
package ctxlog

import (
"context"
"sync"

"github.com/micromdm/nanomdm/log"
)

// CtxKVFunc creates logger key-value pairs from a context.
// CtxKVFuncs should aim to be be as efficient as possible—ideally only
// doing the minimum to read context values and generate KV pairs. Each
// associated CtxKVFunc is called every time we adapt a logger with
// Logger.
type CtxKVFunc func(context.Context) []interface{}

// ctxKeyFuncs is the context key for storing and retriveing
// a funcs{} struct on a context.
type ctxKeyFuncs struct{}

// funcs holds the associated CtxKVFunc functions to run.
type funcs struct {
sync.RWMutex
funcs []CtxKVFunc
}

// AddFunc associates a new CtxKVFunc function to a context.
func AddFunc(ctx context.Context, f CtxKVFunc) context.Context {
if ctx == nil {
return ctx
}
ctxFuncs, ok := ctx.Value(ctxKeyFuncs{}).(*funcs)
if !ok || ctxFuncs == nil {
ctxFuncs = &funcs{}
}
ctxFuncs.Lock()
ctxFuncs.funcs = append(ctxFuncs.funcs, f)
ctxFuncs.Unlock()
return context.WithValue(ctx, ctxKeyFuncs{}, ctxFuncs)
}

// Logger runs the associated CtxKVFunc functions and returns a new
// logger with the results.
func Logger(ctx context.Context, logger log.Logger) log.Logger {
if ctx == nil {
return logger
}

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

...

Do you have benchmarks for how long it takes (on average) to log a line? This seems expensive for logging, and I'm wondering if this can be precalculated

ctxFuncs, ok := ctx.Value(ctxKeyFuncs{}).(*funcs)
if !ok || ctxFuncs == nil {
return logger
}
var acc []interface{}
ctxFuncs.RLock()
for _, f := range ctxFuncs.funcs {

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Similarly in the annals of "premature optimization", is it possible to avoid doing this if the message won't actually be logged because the current log level is too high for the message? (or am I totally missing how this is implemented?)

acc = append(acc, f(ctx)...)
}
ctxFuncs.RUnlock()
return logger.With(acc...)
}

// SimpleStringFunc is a helper that generates a simple CtxKVFunc that
// returns a key-value pair if found on the context.
func SimpleStringFunc(logKey string, ctxKey interface{}) CtxKVFunc {
return func(ctx context.Context) (out []interface{}) {
v, _ := ctx.Value(ctxKey).(string)
if v != "" {
out = []interface{}{logKey, v}
}
return
}
}
15 changes: 12 additions & 3 deletions push/service/service.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ import (
"sync"

"github.com/micromdm/nanomdm/log"
"github.com/micromdm/nanomdm/log/ctxlog"
"github.com/micromdm/nanomdm/mdm"
"github.com/micromdm/nanomdm/push"
"github.com/micromdm/nanomdm/storage"
Expand Down Expand Up @@ -64,7 +65,10 @@ func (s *PushService) getProvider(ctx context.Context, topic string) (push.PushP
if err != nil {
return nil, fmt.Errorf("retrieving push cert for topic %q: %w", topic, err)
}
s.logger.Info("msg", "retrieved push cert", "topic", topic)
ctxlog.Logger(ctx, s.logger).Info(
"msg", "retrieved push cert",
"topic", topic,
)
newProvider, err := s.providerFactory.NewPushProvider(cert)
if err != nil {
return nil, fmt.Errorf("creating new push provider: %w", err)
Expand Down Expand Up @@ -114,7 +118,10 @@ func (s *PushService) pushMulti(ctx context.Context, pushInfos []*mdm.Push) (map
for topic, pushInfos := range topicToPushInfos {
prov, err := s.getProvider(ctx, topic)
if err != nil {
s.logger.Info("msg", "get provider", "err", err)
ctxlog.Logger(ctx, s.logger).Info(
"msg", "get provider",
"err", err,
)
finalErr = err
continue
}
Expand Down Expand Up @@ -191,7 +198,9 @@ func (s *PushService) Push(ctx context.Context, ids []string) (map[string]*push.
for token, resp := range tokenToResponse {
id, ok := tokenToId[token]
if !ok {
s.logger.Info("msg", "could not find id by token")
ctxlog.Logger(ctx, s.logger).Info(
"msg", "could not find id by token",
)
continue
}
idToResponse[id] = resp
Expand Down
15 changes: 9 additions & 6 deletions service/certauth/certauth.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ import (
"fmt"

"github.com/micromdm/nanomdm/log"
"github.com/micromdm/nanomdm/log/ctxlog"
"github.com/micromdm/nanomdm/mdm"
"github.com/micromdm/nanomdm/service"
"github.com/micromdm/nanomdm/storage"
Expand Down Expand Up @@ -110,6 +111,7 @@ func (s *CertAuth) associateNewEnrollment(r *mdm.Request) error {
if err := r.EnrollID.Validate(); err != nil {
return err
}
logger := ctxlog.Logger(r.Context, s.logger)
hash := hashCert(r.Certificate)
if hasHash, err := s.storage.HasCertHash(r, hash); err != nil {
return err
Expand All @@ -124,7 +126,7 @@ func (s *CertAuth) associateNewEnrollment(r *mdm.Request) error {
} else if isAssoc {
return nil
}
s.logger.Info(
logger.Info(
"msg", "cert hash exists",
"enrollment", "new",
"id", r.ID,
Expand All @@ -138,7 +140,7 @@ func (s *CertAuth) associateNewEnrollment(r *mdm.Request) error {
if err := s.storage.AssociateCertHash(r, hash); err != nil {
return err
}
s.logger.Info(
logger.Info(
"msg", "cert associated",
"enrollment", "new",
"id", r.ID,
Expand All @@ -154,14 +156,15 @@ func (s *CertAuth) validateAssociateExistingEnrollment(r *mdm.Request) error {
if err := r.EnrollID.Validate(); err != nil {
return err
}
logger := ctxlog.Logger(r.Context, s.logger)
hash := hashCert(r.Certificate)
if isAssoc, err := s.storage.IsCertHashAssociated(r, hash); err != nil {
return err
} else if isAssoc {
return nil
}
if !s.allowRetroactive {
s.logger.Info(
logger.Info(
"msg", "no cert association",
"enrollment", "existing",
"id", r.ID,
Expand All @@ -178,7 +181,7 @@ func (s *CertAuth) validateAssociateExistingEnrollment(r *mdm.Request) error {
if hasHash, err := s.storage.EnrollmentHasCertHash(r, hash); err != nil {
return err
} else if hasHash {
s.logger.Info(
logger.Info(
"msg", "enrollment cannot have associated cert hash",
"enrollment", "existing",
"id", r.ID,
Expand All @@ -195,7 +198,7 @@ func (s *CertAuth) validateAssociateExistingEnrollment(r *mdm.Request) error {
if hasHash, err := s.storage.HasCertHash(r, hash); err != nil {
return err
} else if hasHash {
s.logger.Info(
logger.Info(
"msg", "cert hash exists",
"enrollment", "existing",
"id", r.ID,
Expand All @@ -211,7 +214,7 @@ func (s *CertAuth) validateAssociateExistingEnrollment(r *mdm.Request) error {
if err := s.storage.AssociateCertHash(r, hash); err != nil {
return err
}
s.logger.Info(
logger.Info(
"msg", "cert associated",
"enrollment", "existing",
"id", r.ID,
Expand Down
Loading