From ce2b7124ec21bc2777e4dbf68615a21abfb34635 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 09:23:49 -0800 Subject: [PATCH 01/11] use slogger on local server, add span_id id to logs, add kolide session id to logs --- ee/localserver/krypto-ec-middleware.go | 72 +++++++++++++++---- ee/localserver/krypto-ec-middleware_test.go | 21 ++++-- ee/localserver/request-controlservice_test.go | 3 + ee/localserver/request-id_test.go | 2 + ee/localserver/request-query_test.go | 3 + ee/localserver/server.go | 2 +- ee/localserver/server_test.go | 2 + pkg/log/multislogger/multislogger.go | 10 ++- 8 files changed, 93 insertions(+), 22 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index c776a4e3d..e144b8e64 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -2,21 +2,22 @@ package localserver import ( "bytes" + "context" "crypto" "crypto/ecdsa" "encoding/base64" "encoding/json" "fmt" "io" + "log/slog" "net/http" "net/url" "strings" "time" - "github.com/go-kit/kit/log" - "github.com/go-kit/kit/log/level" "github.com/kolide/krypto" "github.com/kolide/krypto/pkg/challenge" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/kolide/launcher/pkg/traces" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" @@ -60,15 +61,15 @@ func (cmdReq v2CmdRequestType) CallbackReq() (*http.Request, error) { type kryptoEcMiddleware struct { localDbSigner, hardwareSigner crypto.Signer counterParty ecdsa.PublicKey - logger log.Logger + slogger *slog.Logger } -func newKryptoEcMiddleware(logger log.Logger, localDbSigner, hardwareSigner crypto.Signer, counterParty ecdsa.PublicKey) *kryptoEcMiddleware { +func newKryptoEcMiddleware(slogger *slog.Logger, localDbSigner, hardwareSigner crypto.Signer, counterParty ecdsa.PublicKey) *kryptoEcMiddleware { return &kryptoEcMiddleware{ localDbSigner: localDbSigner, hardwareSigner: hardwareSigner, counterParty: counterParty, - logger: log.With(logger, "keytype", "ec"), + slogger: slogger.With("keytype", "ec"), } } @@ -99,9 +100,13 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS if req == nil { return } + b, err := json.Marshal(data) if err != nil { - level.Debug(e.logger).Log("msg", "unable to marshal callback data", "err", err) + e.slogger.Log(req.Context(), slog.LevelDebug, + "unable to marshal callback data", + "err", err, + ) } req.Body = io.NopCloser(bytes.NewReader(b)) @@ -113,7 +118,10 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS resp, err := client.Do(req) if err != nil { - level.Debug(e.logger).Log("msg", "got error in callback", "err", err) + e.slogger.Log(req.Context(), slog.LevelDebug, + "got error in callback", + "err", err, + ) return } @@ -121,12 +129,16 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS resp.Body.Close() } - level.Debug(e.logger).Log("msg", "Finished callback", "response-status", resp.Status) + e.slogger.Log(req.Context(), slog.LevelDebug, "finished callback", + "response-status", resp.Status, + ) } func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // TODO: add trace id to ctx or figure out what otel puts in there ctx, span := traces.StartSpan(r.Context()) + ctx = context.WithValue(ctx, multislogger.SpanIdKey, span.SpanContext().SpanID().String()) defer span.End() if r.Body != nil { @@ -136,14 +148,24 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { challengeBox, err := extractChallenge(r) if err != nil { traces.SetError(span, err) - level.Debug(e.logger).Log("msg", "failed to extract box from request", "err", err, "path", r.URL.Path, "query_params", r.URL.RawQuery) + e.slogger.Log(ctx, slog.LevelDebug, + "failed to extract box from request", + "err", err, + "path", r.URL.Path, + "query_params", r.URL.RawQuery, + ) + w.WriteHeader(http.StatusUnauthorized) return } if err := challengeBox.Verify(e.counterParty); err != nil { traces.SetError(span, err) - level.Debug(e.logger).Log("msg", "unable to verify signature", "err", err) + e.slogger.Log(ctx, slog.LevelDebug, + "unable to verify signature", + "err", err, + ) + w.WriteHeader(http.StatusUnauthorized) return } @@ -153,18 +175,32 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { var cmdReq v2CmdRequestType if err := json.Unmarshal(challengeBox.RequestData(), &cmdReq); err != nil { traces.SetError(span, err) - level.Debug(e.logger).Log("msg", "unable to unmarshal cmd request", "err", err) + e.slogger.Log(ctx, slog.LevelDebug, + "unable to unmarshal cmd request", + "err", err, + ) + w.WriteHeader(http.StatusUnauthorized) return } + // set the kolide session id if it exists, this also the saml session id + kolideSessionId, ok := cmdReq.CallbackHeaders[multislogger.KolideSessionIdKey] + if ok && len(kolideSessionId) > 0 { + span.SetAttributes(attribute.String(multislogger.KolideSessionIdKey, kolideSessionId[0])) + ctx = context.WithValue(ctx, multislogger.KolideSessionIdKey, kolideSessionId[0]) + } + // Setup callback URLs and data. This is a pointer, so it can be adjusted before the defer triggers callbackData := &callbackDataStruct{ Time: time.Now().Unix(), UserAgent: r.Header.Get("User-Agent"), } if callbackReq, err := cmdReq.CallbackReq(); err != nil { - level.Debug(e.logger).Log("msg", "unable to create callback req", "err", err) + e.slogger.Log(ctx, slog.LevelDebug, + "unable to create callback req", + "err", err, + ) } else if callbackReq != nil { defer func() { go e.sendCallback(callbackReq, callbackData) }() } @@ -175,8 +211,11 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { if timestampDelta > timestampValidityRange || timestampDelta < -timestampValidityRange { span.SetAttributes(attribute.Int64("timestamp_delta", timestampDelta)) span.SetStatus(codes.Error, "timestamp is out of range") + e.slogger.Log(ctx, slog.LevelDebug, + "timestamp is out of range", + "delta", timestampDelta, + ) - level.Debug(e.logger).Log("msg", "timestamp is out of range", "delta", timestampDelta) w.WriteHeader(http.StatusUnauthorized) callbackData.Error = timeOutOfRangeErr return @@ -197,7 +236,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { newReq.Body = io.NopCloser(bytes.NewBuffer(cmdReq.Body)) } - level.Debug(e.logger).Log("msg", "Successful challenge. Proxying") + e.slogger.Log(ctx, slog.LevelDebug, "successful challenge, proxying") span.AddEvent("challenge_success") // bhr contains the data returned by the request defined above @@ -216,7 +255,10 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { if err != nil { traces.SetError(span, err) - level.Debug(e.logger).Log("msg", "failed to respond", "err", err) + e.slogger.Log(ctx, slog.LevelDebug, + "failed to respond", + "err", err, + ) w.WriteHeader(http.StatusUnauthorized) callbackData.Error = responseFailureErr return diff --git a/ee/localserver/krypto-ec-middleware_test.go b/ee/localserver/krypto-ec-middleware_test.go index abcc302b3..b720da439 100644 --- a/ee/localserver/krypto-ec-middleware_test.go +++ b/ee/localserver/krypto-ec-middleware_test.go @@ -8,6 +8,7 @@ import ( "encoding/base64" "encoding/json" "io" + "log/slog" "math/big" "net/http" "net/http/httptest" @@ -16,11 +17,11 @@ import ( "testing" "time" - "github.com/go-kit/kit/log" "github.com/kolide/kit/ulid" "github.com/kolide/krypto/pkg/challenge" "github.com/kolide/krypto/pkg/echelper" "github.com/kolide/launcher/pkg/agent/keys" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -34,11 +35,16 @@ func TestKryptoEcMiddleware(t *testing.T) { challengeId := []byte(ulid.New()) challengeData := []byte(ulid.New()) + koldieSessionId := ulid.New() + cmdReqCallBackHeaders := map[string][]string{ + multislogger.KolideSessionIdKey: {koldieSessionId}, + } cmdReqBody := []byte(randomStringWithSqlCharacters(t, 100000)) cmdReq := mustMarshal(t, v2CmdRequestType{ - Path: "whatevs", - Body: cmdReqBody, + Path: "whatevs", + Body: cmdReqBody, + CallbackHeaders: cmdReqCallBackHeaders, }) var tests = []struct { @@ -155,9 +161,12 @@ func TestKryptoEcMiddleware(t *testing.T) { t.Parallel() var logBytes bytes.Buffer + slogger := multislogger.New(slog.NewTextHandler(&logBytes, &slog.HandlerOptions{ + Level: slog.LevelDebug, + })).Logger // set up middlewares - kryptoEcMiddleware := newKryptoEcMiddleware(log.NewLogfmtLogger(&logBytes), tt.localDbKey, tt.hardwareKey, counterpartyKey.PublicKey) + kryptoEcMiddleware := newKryptoEcMiddleware(slogger, tt.localDbKey, tt.hardwareKey, counterpartyKey.PublicKey) require.NoError(t, err) // give our middleware with the test handler to the determiner @@ -172,6 +181,10 @@ func TestKryptoEcMiddleware(t *testing.T) { return } + require.Contains(t, logBytes.String(), multislogger.KolideSessionIdKey) + require.Contains(t, logBytes.String(), koldieSessionId) + require.Contains(t, logBytes.String(), multislogger.SpanIdKey) + require.Equal(t, http.StatusOK, rr.Code) require.NotEmpty(t, rr.Body.String()) diff --git a/ee/localserver/request-controlservice_test.go b/ee/localserver/request-controlservice_test.go index 6b50134c2..e5a237e96 100644 --- a/ee/localserver/request-controlservice_test.go +++ b/ee/localserver/request-controlservice_test.go @@ -12,6 +12,7 @@ import ( storageci "github.com/kolide/launcher/pkg/agent/storage/ci" "github.com/kolide/launcher/pkg/agent/types" "github.com/kolide/launcher/pkg/agent/types/mocks" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/stretchr/testify/require" ) @@ -23,6 +24,7 @@ func Test_localServer_requestAccelerateControlFunc(t *testing.T) { m := mocks.NewKnapsack(t) m.On("ConfigStore").Return(storageci.NewStore(t, log.NewNopLogger(), storage.ConfigStore.String())) m.On("KolideServerURL").Return("localhost") + m.On("Slogger").Return(multislogger.New().Logger) return m } @@ -47,6 +49,7 @@ func Test_localServer_requestAccelerateControlFunc(t *testing.T) { m.On("ConfigStore").Return(storageci.NewStore(t, log.NewNopLogger(), storage.ConfigStore.String())) m.On("KolideServerURL").Return("localhost") m.On("SetControlRequestIntervalOverride", 250*time.Millisecond, 1*time.Second) + m.On("Slogger").Return(multislogger.New().Logger) return m }, }, diff --git a/ee/localserver/request-id_test.go b/ee/localserver/request-id_test.go index 3a1d55c5d..0e99d974a 100644 --- a/ee/localserver/request-id_test.go +++ b/ee/localserver/request-id_test.go @@ -15,6 +15,7 @@ import ( storageci "github.com/kolide/launcher/pkg/agent/storage/ci" "github.com/kolide/launcher/pkg/agent/types" typesMocks "github.com/kolide/launcher/pkg/agent/types/mocks" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/kolide/launcher/pkg/osquery" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -26,6 +27,7 @@ func Test_localServer_requestIdHandler(t *testing.T) { mockKnapsack := typesMocks.NewKnapsack(t) mockKnapsack.On("ConfigStore").Return(storageci.NewStore(t, log.NewNopLogger(), storage.ConfigStore.String())) mockKnapsack.On("KolideServerURL").Return("localhost") + mockKnapsack.On("Slogger").Return(multislogger.New().Logger) var logBytes bytes.Buffer server := testServer(t, mockKnapsack, &logBytes) diff --git a/ee/localserver/request-query_test.go b/ee/localserver/request-query_test.go index 1a16b670e..0666f18fd 100644 --- a/ee/localserver/request-query_test.go +++ b/ee/localserver/request-query_test.go @@ -14,6 +14,7 @@ import ( "github.com/kolide/launcher/pkg/agent/storage" storageci "github.com/kolide/launcher/pkg/agent/storage/ci" typesMocks "github.com/kolide/launcher/pkg/agent/types/mocks" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/osquery/osquery-go/plugin/distributed" "github.com/stretchr/testify/require" ) @@ -57,6 +58,7 @@ func Test_localServer_requestQueryHandler(t *testing.T) { mockKnapsack := typesMocks.NewKnapsack(t) mockKnapsack.On("ConfigStore").Return(storageci.NewStore(t, log.NewNopLogger(), storage.ConfigStore.String())) mockKnapsack.On("KolideServerURL").Return("localhost") + mockKnapsack.On("Slogger").Return(multislogger.New().Logger) //go:generate mockery --name Querier // https://github.com/vektra/mockery <-- cli tool to generate mocks for usage with testify @@ -222,6 +224,7 @@ func Test_localServer_requestRunScheduledQueryHandler(t *testing.T) { mockKnapsack := typesMocks.NewKnapsack(t) mockKnapsack.On("ConfigStore").Return(storageci.NewStore(t, log.NewNopLogger(), storage.ConfigStore.String())) mockKnapsack.On("KolideServerURL").Return("localhost") + mockKnapsack.On("Slogger").Return(multislogger.New().Logger) // set up mock querier mockQuerier := mocks.NewQuerier(t) diff --git a/ee/localserver/server.go b/ee/localserver/server.go index d9f5b7501..f987ac76b 100644 --- a/ee/localserver/server.go +++ b/ee/localserver/server.go @@ -97,7 +97,7 @@ func New(k types.Knapsack, opts ...LocalServerOption) (*localServer, error) { } ls.myKey = privateKey - ecKryptoMiddleware := newKryptoEcMiddleware(ls.logger, ls.myLocalDbSigner, ls.myLocalHardwareSigner, *ls.serverEcKey) + ecKryptoMiddleware := newKryptoEcMiddleware(k.Slogger(), ls.myLocalDbSigner, ls.myLocalHardwareSigner, *ls.serverEcKey) ecAuthedMux := http.NewServeMux() ecAuthedMux.HandleFunc("/", http.NotFound) ecAuthedMux.Handle("/acceleratecontrol", ls.requestAccelerateControlHandler()) diff --git a/ee/localserver/server_test.go b/ee/localserver/server_test.go index fb881e94e..9f98e9d3c 100644 --- a/ee/localserver/server_test.go +++ b/ee/localserver/server_test.go @@ -9,6 +9,7 @@ import ( "github.com/kolide/launcher/pkg/agent/storage" storageci "github.com/kolide/launcher/pkg/agent/storage/ci" "github.com/kolide/launcher/pkg/agent/types/mocks" + "github.com/kolide/launcher/pkg/log/multislogger" "github.com/kolide/launcher/pkg/osquery" "github.com/stretchr/testify/require" ) @@ -23,6 +24,7 @@ func TestInterrupt_Multiple(t *testing.T) { k := mocks.NewKnapsack(t) k.On("KolideServerURL").Return("localserver") k.On("ConfigStore").Return(c) + k.On("Slogger").Return(multislogger.New().Logger) ls, err := New(k) require.NoError(t, err) diff --git a/pkg/log/multislogger/multislogger.go b/pkg/log/multislogger/multislogger.go index 363edeb19..9d7e42f95 100644 --- a/pkg/log/multislogger/multislogger.go +++ b/pkg/log/multislogger/multislogger.go @@ -8,6 +8,12 @@ import ( slogmulti "github.com/samber/slog-multi" ) +const ( + // KolideSessionIdKey this the also the saml session id + KolideSessionIdKey = "X-Kolide-Session" + SpanIdKey = "span_id" +) + type MultiSlogger struct { *slog.Logger handlers []slog.Handler @@ -50,8 +56,8 @@ func utcTimeMiddleware(ctx context.Context, record slog.Record, next func(contex } var ctxValueKeysToAdd = []string{ - "span_id", - "saml_session_id", + SpanIdKey, + KolideSessionIdKey, } func ctxValuesMiddleWare(ctx context.Context, record slog.Record, next func(context.Context, slog.Record) error) error { From d40514e8ad8664959d5f5cb76c3349e992bbbd47 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 09:50:42 -0800 Subject: [PATCH 02/11] use request context --- ee/localserver/krypto-ec-middleware.go | 40 +++++++++++++++----------- 1 file changed, 24 insertions(+), 16 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index e144b8e64..3561ec3fd 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -36,7 +36,7 @@ type v2CmdRequestType struct { CallbackHeaders map[string][]string } -func (cmdReq v2CmdRequestType) CallbackReq() (*http.Request, error) { +func (cmdReq v2CmdRequestType) CallbackReq(ctx context.Context) (*http.Request, error) { if cmdReq.CallbackUrl == "" { return nil, nil } @@ -46,6 +46,7 @@ func (cmdReq v2CmdRequestType) CallbackReq() (*http.Request, error) { return nil, fmt.Errorf("making http request: %w", err) } + req = req.WithContext(ctx) req.Header.Set("Content-Type", "application/json") // Iterate and deep copy @@ -103,7 +104,7 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS b, err := json.Marshal(data) if err != nil { - e.slogger.Log(req.Context(), slog.LevelDebug, + e.slogger.Log(req.Context(), slog.LevelError, "unable to marshal callback data", "err", err, ) @@ -118,7 +119,7 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS resp, err := client.Do(req) if err != nil { - e.slogger.Log(req.Context(), slog.LevelDebug, + e.slogger.Log(req.Context(), slog.LevelError, "got error in callback", "err", err, ) @@ -136,9 +137,10 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - // TODO: add trace id to ctx or figure out what otel puts in there - ctx, span := traces.StartSpan(r.Context()) - ctx = context.WithValue(ctx, multislogger.SpanIdKey, span.SpanContext().SpanID().String()) + + spanCtx, span := traces.StartSpan(r.Context()) + r = r.WithContext(context.WithValue(spanCtx, multislogger.SpanIdKey, span.SpanContext().SpanID().String())) + defer span.End() if r.Body != nil { @@ -148,7 +150,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { challengeBox, err := extractChallenge(r) if err != nil { traces.SetError(span, err) - e.slogger.Log(ctx, slog.LevelDebug, + e.slogger.Log(r.Context(), slog.LevelDebug, "failed to extract box from request", "err", err, "path", r.URL.Path, @@ -161,7 +163,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { if err := challengeBox.Verify(e.counterParty); err != nil { traces.SetError(span, err) - e.slogger.Log(ctx, slog.LevelDebug, + e.slogger.Log(r.Context(), slog.LevelDebug, "unable to verify signature", "err", err, ) @@ -175,7 +177,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { var cmdReq v2CmdRequestType if err := json.Unmarshal(challengeBox.RequestData(), &cmdReq); err != nil { traces.SetError(span, err) - e.slogger.Log(ctx, slog.LevelDebug, + e.slogger.Log(r.Context(), slog.LevelError, "unable to unmarshal cmd request", "err", err, ) @@ -188,7 +190,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { kolideSessionId, ok := cmdReq.CallbackHeaders[multislogger.KolideSessionIdKey] if ok && len(kolideSessionId) > 0 { span.SetAttributes(attribute.String(multislogger.KolideSessionIdKey, kolideSessionId[0])) - ctx = context.WithValue(ctx, multislogger.KolideSessionIdKey, kolideSessionId[0]) + r = r.WithContext(context.WithValue(r.Context(), multislogger.KolideSessionIdKey, kolideSessionId[0])) } // Setup callback URLs and data. This is a pointer, so it can be adjusted before the defer triggers @@ -196,8 +198,9 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { Time: time.Now().Unix(), UserAgent: r.Header.Get("User-Agent"), } - if callbackReq, err := cmdReq.CallbackReq(); err != nil { - e.slogger.Log(ctx, slog.LevelDebug, + + if callbackReq, err := cmdReq.CallbackReq(r.Context()); err != nil { + e.slogger.Log(r.Context(), slog.LevelError, "unable to create callback req", "err", err, ) @@ -211,7 +214,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { if timestampDelta > timestampValidityRange || timestampDelta < -timestampValidityRange { span.SetAttributes(attribute.Int64("timestamp_delta", timestampDelta)) span.SetStatus(codes.Error, "timestamp is out of range") - e.slogger.Log(ctx, slog.LevelDebug, + e.slogger.Log(r.Context(), slog.LevelError, "timestamp is out of range", "delta", timestampDelta, ) @@ -229,14 +232,19 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { Path: cmdReq.Path, }, } - newReq = newReq.WithContext(ctx) // allows the trace to continue to the inner request + + // setting the newReq context to the current request context context + // allows the trace to continue to the inner request, + // maintains the same lifetime as the original request, + // allows same ctx values such as session id to be passed to the inner request + newReq = newReq.WithContext(r.Context()) // the body of the cmdReq become the body of the next http request if cmdReq.Body != nil && len(cmdReq.Body) > 0 { newReq.Body = io.NopCloser(bytes.NewBuffer(cmdReq.Body)) } - e.slogger.Log(ctx, slog.LevelDebug, "successful challenge, proxying") + e.slogger.Log(r.Context(), slog.LevelDebug, "successful challenge, proxying") span.AddEvent("challenge_success") // bhr contains the data returned by the request defined above @@ -255,7 +263,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { if err != nil { traces.SetError(span, err) - e.slogger.Log(ctx, slog.LevelDebug, + e.slogger.Log(r.Context(), slog.LevelError, "failed to respond", "err", err, ) From 2079f9d7977990f750b9a27eb0f41da6f7855b95 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 10:12:02 -0800 Subject: [PATCH 03/11] update multislogger context keys to use types --- ee/localserver/krypto-ec-middleware.go | 4 ++-- ee/localserver/krypto-ec-middleware_test.go | 6 +++--- pkg/log/multislogger/multislogger.go | 15 +++++++++++---- pkg/log/multislogger/multislogger_test.go | 6 +++--- 4 files changed, 19 insertions(+), 12 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index 3561ec3fd..c5b5d0b0b 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -187,9 +187,9 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { } // set the kolide session id if it exists, this also the saml session id - kolideSessionId, ok := cmdReq.CallbackHeaders[multislogger.KolideSessionIdKey] + kolideSessionId, ok := cmdReq.CallbackHeaders[multislogger.KolideSessionIdKey.String()] if ok && len(kolideSessionId) > 0 { - span.SetAttributes(attribute.String(multislogger.KolideSessionIdKey, kolideSessionId[0])) + span.SetAttributes(attribute.String(multislogger.KolideSessionIdKey.String(), kolideSessionId[0])) r = r.WithContext(context.WithValue(r.Context(), multislogger.KolideSessionIdKey, kolideSessionId[0])) } diff --git a/ee/localserver/krypto-ec-middleware_test.go b/ee/localserver/krypto-ec-middleware_test.go index b720da439..2d4631065 100644 --- a/ee/localserver/krypto-ec-middleware_test.go +++ b/ee/localserver/krypto-ec-middleware_test.go @@ -37,7 +37,7 @@ func TestKryptoEcMiddleware(t *testing.T) { koldieSessionId := ulid.New() cmdReqCallBackHeaders := map[string][]string{ - multislogger.KolideSessionIdKey: {koldieSessionId}, + multislogger.KolideSessionIdKey.String(): {koldieSessionId}, } cmdReqBody := []byte(randomStringWithSqlCharacters(t, 100000)) @@ -181,9 +181,9 @@ func TestKryptoEcMiddleware(t *testing.T) { return } - require.Contains(t, logBytes.String(), multislogger.KolideSessionIdKey) + require.Contains(t, logBytes.String(), multislogger.KolideSessionIdKey.String()) require.Contains(t, logBytes.String(), koldieSessionId) - require.Contains(t, logBytes.String(), multislogger.SpanIdKey) + require.Contains(t, logBytes.String(), multislogger.SpanIdKey.String()) require.Equal(t, http.StatusOK, rr.Code) require.NotEmpty(t, rr.Body.String()) diff --git a/pkg/log/multislogger/multislogger.go b/pkg/log/multislogger/multislogger.go index 9d7e42f95..82c54a646 100644 --- a/pkg/log/multislogger/multislogger.go +++ b/pkg/log/multislogger/multislogger.go @@ -8,10 +8,16 @@ import ( slogmulti "github.com/samber/slog-multi" ) +type contextKey string + +func (c contextKey) String() string { + return string(c) +} + const ( // KolideSessionIdKey this the also the saml session id - KolideSessionIdKey = "X-Kolide-Session" - SpanIdKey = "span_id" + KolideSessionIdKey contextKey = "X-Kolide-Session" + SpanIdKey contextKey = "span_id" ) type MultiSlogger struct { @@ -55,7 +61,7 @@ func utcTimeMiddleware(ctx context.Context, record slog.Record, next func(contex return next(ctx, record) } -var ctxValueKeysToAdd = []string{ +var ctxValueKeysToAdd = []contextKey{ SpanIdKey, KolideSessionIdKey, } @@ -64,10 +70,11 @@ func ctxValuesMiddleWare(ctx context.Context, record slog.Record, next func(cont for _, key := range ctxValueKeysToAdd { if v := ctx.Value(key); v != nil { record.AddAttrs(slog.Attr{ - Key: key, + Key: key.String(), Value: slog.AnyValue(v), }) } } + return next(ctx, record) } diff --git a/pkg/log/multislogger/multislogger_test.go b/pkg/log/multislogger/multislogger_test.go index a0aac633d..7bc0fe4e6 100644 --- a/pkg/log/multislogger/multislogger_test.go +++ b/pkg/log/multislogger/multislogger_test.go @@ -54,14 +54,14 @@ func TestMultiSlogger(t *testing.T) { // ensure that span_id gets added as an attribute when present in context spanId := ulid.New() - ctx := context.WithValue(context.Background(), "span_id", spanId) + ctx := context.WithValue(context.Background(), SpanIdKey, spanId) multislogger.Logger.Log(ctx, slog.LevelDebug, "info_with_interesting_ctx_value") require.Contains(t, debugLogBuf.String(), "info_with_interesting_ctx_value", "should be in debug log since it's debug level") - requireContainsAttribute(t, &debugLogBuf, "span_id", spanId) + requireContainsAttribute(t, &debugLogBuf, SpanIdKey.String(), spanId) require.Contains(t, shipperBuf.String(), "info_with_interesting_ctx_value", "should now be in shipper log since it's new handler was set to debug level") - requireContainsAttribute(t, &shipperBuf, "span_id", spanId) + requireContainsAttribute(t, &shipperBuf, SpanIdKey.String(), spanId) clearBufsFn() } From c27961380c5977663bb0386cd24077a0495d716b Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 10:12:40 -0800 Subject: [PATCH 04/11] fix comment --- ee/localserver/krypto-ec-middleware.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index c5b5d0b0b..cc6676b41 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -233,7 +233,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { }, } - // setting the newReq context to the current request context context + // setting the newReq context to the current request context // allows the trace to continue to the inner request, // maintains the same lifetime as the original request, // allows same ctx values such as session id to be passed to the inner request From 933701b0d0fb27d502be8e366850341265493e3c Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 10:19:00 -0800 Subject: [PATCH 05/11] add launche run id to knapsack logger --- pkg/agent/knapsack/knapsack.go | 4 ++++ pkg/log/multislogger/multislogger.go | 4 +++- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/pkg/agent/knapsack/knapsack.go b/pkg/agent/knapsack/knapsack.go index 04b4a6681..00cda2c90 100644 --- a/pkg/agent/knapsack/knapsack.go +++ b/pkg/agent/knapsack/knapsack.go @@ -7,6 +7,7 @@ import ( "log/slog" "github.com/go-kit/kit/log" + "github.com/kolide/kit/ulid" "github.com/kolide/launcher/pkg/agent/flags/keys" "github.com/kolide/launcher/pkg/agent/storage" "github.com/kolide/launcher/pkg/agent/types" @@ -30,6 +31,7 @@ type knapsack struct { db *bbolt.DB slogger, systemSlogger *multislogger.MultiSlogger + launcherRunId string // This struct is a work in progress, and will be iteratively added to as needs arise. // Some potential future additions include: @@ -43,6 +45,7 @@ func New(stores map[storage.Store]types.KVStore, flags types.Flags, db *bbolt.DB stores: stores, slogger: slogger, systemSlogger: systemSlogger, + launcherRunId: ulid.New(), } return k @@ -59,6 +62,7 @@ func (k *knapsack) SystemSlogger() *slog.Logger { func (k *knapsack) AddSlogHandler(handler ...slog.Handler) { k.slogger.AddHandler(handler...) + k.slogger.Logger = k.slogger.Logger.With("launcher_run_id", k.launcherRunId) // also send system logs to the same handlers k.systemSlogger.AddHandler(handler...) diff --git a/pkg/log/multislogger/multislogger.go b/pkg/log/multislogger/multislogger.go index 82c54a646..0b1b7cc52 100644 --- a/pkg/log/multislogger/multislogger.go +++ b/pkg/log/multislogger/multislogger.go @@ -42,7 +42,9 @@ func New(h ...slog.Handler) *MultiSlogger { return ms } -// AddHandler adds a handler to the multislogger +// AddHandler adds a handler to the multislogger, this creates a branch new +// slog.Logger under the the hood, mean any attributes added with +// Logger.With will be lost func (m *MultiSlogger) AddHandler(handler ...slog.Handler) { m.handlers = append(m.handlers, handler...) From 53e0c704975ee792d4b2a15da1e5631b6f3d6c06 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 10:35:29 -0800 Subject: [PATCH 06/11] add span_id to ctx in start span --- ee/localserver/krypto-ec-middleware.go | 2 +- pkg/traces/traces.go | 5 ++++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index cc6676b41..af80b3b7b 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -139,7 +139,7 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { spanCtx, span := traces.StartSpan(r.Context()) - r = r.WithContext(context.WithValue(spanCtx, multislogger.SpanIdKey, span.SpanContext().SpanID().String())) + r = r.WithContext(spanCtx) defer span.End() diff --git a/pkg/traces/traces.go b/pkg/traces/traces.go index 1afa79e0c..ab2776d21 100644 --- a/pkg/traces/traces.go +++ b/pkg/traces/traces.go @@ -6,6 +6,7 @@ import ( "path/filepath" "runtime" + "github.com/kolide/launcher/pkg/log/multislogger" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" @@ -48,7 +49,9 @@ func StartSpan(ctx context.Context, keyVals ...interface{}) (context.Context, tr opts = append(opts, trace.WithAttributes(buildAttributes(callerFile, keyVals...)...)) - return otel.Tracer(instrumentationPkg).Start(ctx, spanName, opts...) + spanCtx, span := otel.Tracer(instrumentationPkg).Start(ctx, spanName, opts...) + spanCtx = context.WithValue(spanCtx, multislogger.SpanIdKey, span.SpanContext().SpanID().String()) + return spanCtx, span } // SetError records the error on the span and sets the span's status to error. From e4c09ed93fef7d4d6bc8e5ecb22b2e5cf5e10544 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 10:56:08 -0800 Subject: [PATCH 07/11] dont reuse context in call back func --- ee/localserver/krypto-ec-middleware.go | 14 +++++++++---- pkg/agent/flags/flag_controller.go | 29 +++++++++++++------------- 2 files changed, 25 insertions(+), 18 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index af80b3b7b..cc7f77482 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -36,7 +36,7 @@ type v2CmdRequestType struct { CallbackHeaders map[string][]string } -func (cmdReq v2CmdRequestType) CallbackReq(ctx context.Context) (*http.Request, error) { +func (cmdReq v2CmdRequestType) CallbackReq() (*http.Request, error) { if cmdReq.CallbackUrl == "" { return nil, nil } @@ -46,7 +46,6 @@ func (cmdReq v2CmdRequestType) CallbackReq(ctx context.Context) (*http.Request, return nil, fmt.Errorf("making http request: %w", err) } - req = req.WithContext(ctx) req.Header.Set("Content-Type", "application/json") // Iterate and deep copy @@ -199,13 +198,20 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { UserAgent: r.Header.Get("User-Agent"), } - if callbackReq, err := cmdReq.CallbackReq(r.Context()); err != nil { + if callbackReq, err := cmdReq.CallbackReq(); err != nil { e.slogger.Log(r.Context(), slog.LevelError, "unable to create callback req", "err", err, ) } else if callbackReq != nil { - defer func() { go e.sendCallback(callbackReq, callbackData) }() + defer func() { + callbackReq = callbackReq.WithContext( + // adding the current request context will cause this to be cancelled before it sends + // so just add the session id manually + context.WithValue(callbackReq.Context(), multislogger.KolideSessionIdKey, kolideSessionId[0]), + ) + go e.sendCallback(callbackReq, callbackData) + }() } // Check the timestamp, this prevents people from saving a challenge and then diff --git a/pkg/agent/flags/flag_controller.go b/pkg/agent/flags/flag_controller.go index 4e2bdd93f..b72d37ee4 100644 --- a/pkg/agent/flags/flag_controller.go +++ b/pkg/agent/flags/flag_controller.go @@ -2,7 +2,6 @@ package flags import ( "errors" - "strings" "sync" "time" @@ -491,19 +490,21 @@ func (fc *FlagController) SetLogShippingLevel(level string) error { return fc.setControlServerValue(keys.LogShippingLevel, []byte(level)) } func (fc *FlagController) LogShippingLevel() string { - return NewStringFlagValue( - WithDefaultString("error"), - WithSanitizer(func(value string) string { - value = strings.ToLower(value) - - switch value { - case "debug", "warn", "error": - return value - default: - return "info" - } - }), - ).get(fc.getControlServerValue(keys.LogShippingLevel)) + + return "debug" + // return NewStringFlagValue( + // WithDefaultString("error"), + // WithSanitizer(func(value string) string { + // value = strings.ToLower(value) + + // switch value { + // case "debug", "warn", "error": + // return value + // default: + // return "info" + // } + // }), + // ).get(fc.getControlServerValue(keys.LogShippingLevel)) } func (fc *FlagController) SetTraceIngestServerURL(url string) error { From 81a0cb3a71c3fa8ae6b35a4853709796a9e327f8 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 10:57:12 -0800 Subject: [PATCH 08/11] set log shipping level back to normal --- pkg/agent/flags/flag_controller.go | 29 ++++++++++++++--------------- 1 file changed, 14 insertions(+), 15 deletions(-) diff --git a/pkg/agent/flags/flag_controller.go b/pkg/agent/flags/flag_controller.go index b72d37ee4..4e2bdd93f 100644 --- a/pkg/agent/flags/flag_controller.go +++ b/pkg/agent/flags/flag_controller.go @@ -2,6 +2,7 @@ package flags import ( "errors" + "strings" "sync" "time" @@ -490,21 +491,19 @@ func (fc *FlagController) SetLogShippingLevel(level string) error { return fc.setControlServerValue(keys.LogShippingLevel, []byte(level)) } func (fc *FlagController) LogShippingLevel() string { - - return "debug" - // return NewStringFlagValue( - // WithDefaultString("error"), - // WithSanitizer(func(value string) string { - // value = strings.ToLower(value) - - // switch value { - // case "debug", "warn", "error": - // return value - // default: - // return "info" - // } - // }), - // ).get(fc.getControlServerValue(keys.LogShippingLevel)) + return NewStringFlagValue( + WithDefaultString("error"), + WithSanitizer(func(value string) string { + value = strings.ToLower(value) + + switch value { + case "debug", "warn", "error": + return value + default: + return "info" + } + }), + ).get(fc.getControlServerValue(keys.LogShippingLevel)) } func (fc *FlagController) SetTraceIngestServerURL(url string) error { From 7af8aa69ff42e88711ea2cd6f6264d5dc43c8013 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 11:00:50 -0800 Subject: [PATCH 09/11] check session id for nil before adding to ctx --- ee/localserver/krypto-ec-middleware.go | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index cc7f77482..a13a84313 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -136,7 +136,6 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - spanCtx, span := traces.StartSpan(r.Context()) r = r.WithContext(spanCtx) @@ -205,11 +204,13 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { ) } else if callbackReq != nil { defer func() { - callbackReq = callbackReq.WithContext( - // adding the current request context will cause this to be cancelled before it sends - // so just add the session id manually - context.WithValue(callbackReq.Context(), multislogger.KolideSessionIdKey, kolideSessionId[0]), - ) + if kolideSessionId != nil && len(kolideSessionId) > 0 { + callbackReq = callbackReq.WithContext( + // adding the current request context will cause this to be cancelled before it sends + // so just add the session id manually + context.WithValue(callbackReq.Context(), multislogger.KolideSessionIdKey, kolideSessionId[0]), + ) + } go e.sendCallback(callbackReq, callbackData) }() } From 86ec89f43caae655b054725b8d25f7f00c93d9f7 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 11:43:00 -0800 Subject: [PATCH 10/11] use underscore --- ee/localserver/krypto-ec-middleware.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index a13a84313..4c58bc768 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -129,8 +129,9 @@ func (e *kryptoEcMiddleware) sendCallback(req *http.Request, data *callbackDataS resp.Body.Close() } - e.slogger.Log(req.Context(), slog.LevelDebug, "finished callback", - "response-status", resp.Status, + e.slogger.Log(req.Context(), slog.LevelDebug, + "finished callback", + "response_status", resp.Status, ) } From 960fe541f3ea347ad277395bf1e7e9ece8ea9561 Mon Sep 17 00:00:00 2001 From: james pickett Date: Tue, 7 Nov 2023 12:21:06 -0800 Subject: [PATCH 11/11] dont use header key as ctx attribute, convert ctx keys to iotas --- ee/localserver/krypto-ec-middleware.go | 5 +++-- ee/localserver/krypto-ec-middleware_test.go | 2 +- pkg/log/multislogger/multislogger.go | 15 +++++++++++---- 3 files changed, 15 insertions(+), 7 deletions(-) diff --git a/ee/localserver/krypto-ec-middleware.go b/ee/localserver/krypto-ec-middleware.go index 4c58bc768..0ba1ed9f9 100644 --- a/ee/localserver/krypto-ec-middleware.go +++ b/ee/localserver/krypto-ec-middleware.go @@ -27,6 +27,7 @@ const ( timestampValidityRange = 150 kolideKryptoEccHeader20230130Value = "2023-01-30" kolideKryptoHeaderKey = "X-Kolide-Krypto" + kolideSessionIdHeaderKey = "X-Kolide-Session" ) type v2CmdRequestType struct { @@ -186,9 +187,9 @@ func (e *kryptoEcMiddleware) Wrap(next http.Handler) http.Handler { } // set the kolide session id if it exists, this also the saml session id - kolideSessionId, ok := cmdReq.CallbackHeaders[multislogger.KolideSessionIdKey.String()] + kolideSessionId, ok := cmdReq.CallbackHeaders[kolideSessionIdHeaderKey] if ok && len(kolideSessionId) > 0 { - span.SetAttributes(attribute.String(multislogger.KolideSessionIdKey.String(), kolideSessionId[0])) + span.SetAttributes(attribute.String(kolideSessionIdHeaderKey, kolideSessionId[0])) r = r.WithContext(context.WithValue(r.Context(), multislogger.KolideSessionIdKey, kolideSessionId[0])) } diff --git a/ee/localserver/krypto-ec-middleware_test.go b/ee/localserver/krypto-ec-middleware_test.go index 2d4631065..aa367ce91 100644 --- a/ee/localserver/krypto-ec-middleware_test.go +++ b/ee/localserver/krypto-ec-middleware_test.go @@ -37,7 +37,7 @@ func TestKryptoEcMiddleware(t *testing.T) { koldieSessionId := ulid.New() cmdReqCallBackHeaders := map[string][]string{ - multislogger.KolideSessionIdKey.String(): {koldieSessionId}, + kolideSessionIdHeaderKey: {koldieSessionId}, } cmdReqBody := []byte(randomStringWithSqlCharacters(t, 100000)) diff --git a/pkg/log/multislogger/multislogger.go b/pkg/log/multislogger/multislogger.go index 0b1b7cc52..776ef983d 100644 --- a/pkg/log/multislogger/multislogger.go +++ b/pkg/log/multislogger/multislogger.go @@ -8,16 +8,23 @@ import ( slogmulti "github.com/samber/slog-multi" ) -type contextKey string +type contextKey int func (c contextKey) String() string { - return string(c) + switch c { + case KolideSessionIdKey: + return "kolide_session_id" + case SpanIdKey: + return "span_id" + default: + return "unknown" + } } const ( // KolideSessionIdKey this the also the saml session id - KolideSessionIdKey contextKey = "X-Kolide-Session" - SpanIdKey contextKey = "span_id" + KolideSessionIdKey contextKey = iota + SpanIdKey ) type MultiSlogger struct {