From 7ab7c8eaf45c6d1309e8507da5a432563218986a Mon Sep 17 00:00:00 2001 From: Jeff Mitchell Date: Mon, 11 Jul 2022 16:12:02 -0400 Subject: [PATCH] Have fallback eventing use json format (#2216) * Have fallback eventing use json format The server will initialize a logger via InitFallbackLogger(...) after setting up the server's logging (and honoring the related cmd flags). This fallback logger will be used if when no eventer is initialized. If no fallback logger is initialized, then a event.defaultLogger() will be used if no eventer is defined. Co-authored-by: Jim --- internal/cmd/base/servers.go | 16 +++-- internal/cmd/commands/dev/dev.go | 2 +- internal/cmd/commands/server/server.go | 4 +- internal/observability/event/context.go | 8 +-- internal/observability/event/context_test.go | 52 +++++---------- internal/observability/event/eventer.go | 50 ++++++++++++++- .../observability/event/eventer_gate_test.go | 7 +-- .../observability/event/eventer_retry_test.go | 6 +- internal/observability/event/eventer_test.go | 63 ++++++------------- internal/observability/event/testing.go | 9 +++ 10 files changed, 110 insertions(+), 107 deletions(-) diff --git a/internal/cmd/base/servers.go b/internal/cmd/base/servers.go index 32257fcc9..9c94a826a 100644 --- a/internal/cmd/base/servers.go +++ b/internal/cmd/base/servers.go @@ -81,7 +81,6 @@ type Server struct { GatedWriter *gatedwriter.Writer Logger hclog.Logger CombineLogs bool - LogLevel hclog.Level StderrLock *sync.Mutex Eventer *event.Eventer @@ -253,6 +252,9 @@ func (b *Server) AddEventerToContext(ctx context.Context) (context.Context, erro return e, nil } +// SetupLogging sets up the command's logger. This is mostly historical at this +// point since we switched to eventing; however, logging is still used as a +// fallback when events are unable to be sent. func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, configLogFormat string) error { b.logOutput = os.Stderr if b.CombineLogs { @@ -268,12 +270,16 @@ func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, confi b.Logger = hclog.New(&hclog.LoggerOptions{ Output: b.GatedWriter, Level: logLevel, - // Note that if logFormat is either unspecified or standard, then - // the resulting logger's format will be standard. - JSONFormat: logFormat == logging.JSONFormat, + // Note that if logFormat is either unspecified or json, then + // the resulting logger's format will be json. + JSONFormat: logFormat != logging.StandardFormat, Mutex: b.StderrLock, }) + if err := event.InitFallbackLogger(b.Logger); err != nil { + return err + } + // create GRPC logger namedGRPCLogFaker := b.Logger.Named("grpclogfaker") grpclog.SetLogger(&GRPCLogFaker{ @@ -284,8 +290,6 @@ func (b *Server) SetupLogging(flagLogLevel, flagLogFormat, configLogLevel, confi b.Info["log level"] = logLevel.String() b.InfoKeys = append(b.InfoKeys, "log level") - b.LogLevel = logLevel - // log proxy settings // TODO: It would be good to show this but Vault has, or will soon, address // the fact that this can log users/passwords if they are part of the proxy diff --git a/internal/cmd/commands/dev/dev.go b/internal/cmd/commands/dev/dev.go index fc8ef4368..b984aa511 100644 --- a/internal/cmd/commands/dev/dev.go +++ b/internal/cmd/commands/dev/dev.go @@ -300,7 +300,7 @@ func (c *Command) Flags() *base.FlagSets { Name: "event-format", Target: &c.flagEventFormat, Completion: complete.PredictSet("cloudevents-json", "cloudevents-text", "hclog-text", "hclog-json"), - Usage: `Event format. Supported values are "cloudevents-json" and "cloudevents-text".`, + Usage: `Event format. Supported values are "cloudevents-json", "cloudevents-text", "hclog-json", and "hclog-text".`, }) f.StringVar(&base.StringVar{ Name: "observation-events", diff --git a/internal/cmd/commands/server/server.go b/internal/cmd/commands/server/server.go index 243772635..dbc5eccd7 100644 --- a/internal/cmd/commands/server/server.go +++ b/internal/cmd/commands/server/server.go @@ -113,7 +113,7 @@ func (c *Command) Flags() *base.FlagSets { Target: &c.flagLogLevel, EnvVar: "BOUNDARY_LOG_LEVEL", Completion: complete.PredictSet("trace", "debug", "info", "warn", "err"), - Usage: "Log verbosity level. Supported values (in order of more detail to less) are " + + Usage: "Log verbosity level, mostly as a fallback for events. Supported values (in order of more detail to less) are " + "\"trace\", \"debug\", \"info\", \"warn\", and \"err\".", }) @@ -121,7 +121,7 @@ func (c *Command) Flags() *base.FlagSets { Name: "log-format", Target: &c.flagLogFormat, Completion: complete.PredictSet("standard", "json"), - Usage: `Log format. Supported values are "standard" and "json".`, + Usage: `Log format, mostly as a fallback for events. Supported values are "standard" and "json".`, }) return set diff --git a/internal/observability/event/context.go b/internal/observability/event/context.go index ac9763165..e788b7dc5 100644 --- a/internal/observability/event/context.go +++ b/internal/observability/event/context.go @@ -6,8 +6,6 @@ import ( "os" "runtime" "time" - - "github.com/hashicorp/go-hclog" ) var ci bool @@ -136,8 +134,7 @@ func WriteError(ctx context.Context, caller Op, e error, opt ...Option) { eventer = SysEventer() if eventer == nil { if !ci { - logger := hclog.New(nil) - logger.Error(fmt.Sprintf("%s: no eventer available to write error: %v", op, e)) + fallbackLogger().Error(fmt.Sprintf("%s: no eventer available to write error: %v", op, e)) } return } @@ -286,8 +283,7 @@ func WriteSysEvent(ctx context.Context, caller Op, msg string, args ...interface if !ok { eventer = SysEventer() if eventer == nil { - logger := hclog.New(nil) - logger.Error(fmt.Sprintf("%s: no eventer available to write sysevent: (%s) %+v", op, caller, info)) + fallbackLogger().Error(fmt.Sprintf("%s: no eventer available to write sysevent: (%s) %+v", op, caller, info)) return } } diff --git a/internal/observability/event/context_test.go b/internal/observability/event/context_test.go index 69990ea29..98fa2726e 100644 --- a/internal/observability/event/context_test.go +++ b/internal/observability/event/context_test.go @@ -156,10 +156,7 @@ func Test_RequestInfoFromContext(t *testing.T) { func Test_NewEventerContext(t *testing.T) { testSetup := event.TestEventerConfig(t, "Test_NewEventerContext") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) testEventer, err := event.NewEventer(testLogger, testLock, "Test_NewEventerContext", testSetup.EventerConfig) require.NoError(t, err) tests := []struct { @@ -213,10 +210,7 @@ func Test_EventerFromContext(t *testing.T) { testSetup := event.TestEventerConfig(t, "Test_EventerFromContext") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) testEventer, err := event.NewEventer(testLogger, testLock, "Test_EventerFromContext", testSetup.EventerConfig) require.NoError(t, err) @@ -267,10 +261,7 @@ func Test_WriteObservation(t *testing.T) { c := event.TestEventerConfig(t, "WriteObservation") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) e, err := event.NewEventer(testLogger, testLock, "Test_WriteObservation", c.EventerConfig) require.NoError(t, err) @@ -479,10 +470,6 @@ func Test_WriteObservation(t *testing.T) { c := event.TestEventerConfig(t, "WriteObservation") c.EventerConfig.ObservationsEnabled = false testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) e, err := event.NewEventer(testLogger, testLock, "not-enabled", c.EventerConfig) require.NoError(err) @@ -504,10 +491,7 @@ func Test_WriteObservation(t *testing.T) { func Test_Filtering(t *testing.T) { testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) tests := []struct { name string allow []string @@ -634,10 +618,7 @@ func Test_WriteAudit(t *testing.T) { c := event.TestEventerConfig(t, "WriteAudit") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) e, err := event.NewEventer(testLogger, testLock, "Test_WriteAudit", c.EventerConfig) require.NoError(t, err) @@ -945,10 +926,6 @@ func Test_WriteAudit(t *testing.T) { c := event.TestEventerConfig(t, "WriteAudit") c.EventerConfig.AuditEnabled = false testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) e, err := event.NewEventer(testLogger, testLock, "not-enabled", c.EventerConfig) require.NoError(err) @@ -971,10 +948,7 @@ func Test_WriteError(t *testing.T) { c := event.TestEventerConfig(t, "WriteAudit") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) e, err := event.NewEventer(testLogger, testLock, "Test_WriteError", c.EventerConfig, event.WithNow(now)) require.NoError(t, err) @@ -1141,10 +1115,7 @@ func Test_WriteSysEvent(t *testing.T) { ctx := context.Background() c := event.TestEventerConfig(t, "Test_WriteSysEvent") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) tests := []struct { name string @@ -1297,3 +1268,12 @@ type testIntKeyWithStringer int func (ti testIntKeyWithStringer) String() string { return fmt.Sprint("*", int(ti), "*") } + +func testLogger(t *testing.T, testLock hclog.Locker) hclog.Logger { + t.Helper() + return hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + JSONFormat: true, + }) +} diff --git a/internal/observability/event/eventer.go b/internal/observability/event/eventer.go index 0cc6962f8..0c7c1944b 100644 --- a/internal/observability/event/eventer.go +++ b/internal/observability/event/eventer.go @@ -97,10 +97,45 @@ type pipeline struct { } var ( - sysEventer *Eventer // sysEventer is the system-wide Eventer - sysEventerLock sync.RWMutex // sysEventerLock allows the sysEventer to safely be written concurrently. + sysEventer *Eventer // sysEventer is the system-wide Eventer + sysEventerLock sync.RWMutex // sysEventerLock allows the sysEventer to safely be written concurrently. + sysFallbackLogger struct { + mu sync.RWMutex + logger hclog.Logger + } ) +func defaultLogger() hclog.Logger { + opts := hclog.DefaultOptions + opts.JSONFormat = true + return hclog.New(opts) +} + +// fallbackLogger returns the current fallback logger for eventing. If there's +// no current fallback logger, then a default logger is returned. +func fallbackLogger() hclog.Logger { + sysFallbackLogger.mu.RLock() + defer sysFallbackLogger.mu.RUnlock() + if sysFallbackLogger.logger == nil { + return defaultLogger() + } + return sysFallbackLogger.logger +} + +// InitFallbackLogger will initialize the fallback logger for eventing +func InitFallbackLogger(l hclog.Logger) error { + const op = "event.InitFallbackLogger" + if isNil(l) { + return fmt.Errorf("%s: missing logger: %w", op, ErrInvalidParameter) + } + + sysFallbackLogger.mu.Lock() + defer sysFallbackLogger.mu.Unlock() + sysFallbackLogger.logger = l + + return nil +} + // InitSysEventer provides a mechanism to initialize a "system wide" eventer // singleton for Boundary. Support the options of: WithEventer(...) and // WithEventerConfig(...) @@ -884,3 +919,14 @@ func (s *logAdapter) pickType(str string) (Type, string) { return SystemType, str } } + +func isNil(i interface{}) bool { + if i == nil { + return true + } + switch reflect.TypeOf(i).Kind() { + case reflect.Ptr, reflect.Map, reflect.Array, reflect.Chan, reflect.Slice: + return reflect.ValueOf(i).IsNil() + } + return false +} diff --git a/internal/observability/event/eventer_gate_test.go b/internal/observability/event/eventer_gate_test.go index 092850523..5ef178a92 100644 --- a/internal/observability/event/eventer_gate_test.go +++ b/internal/observability/event/eventer_gate_test.go @@ -8,7 +8,6 @@ import ( "sync" "testing" - "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/strutil" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -36,10 +35,8 @@ func TestEventer_Gating(t *testing.T) { }, } testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) + eventer, err := NewEventer( testLogger, testLock, diff --git a/internal/observability/event/eventer_retry_test.go b/internal/observability/event/eventer_retry_test.go index e593bf23d..bc257aebc 100644 --- a/internal/observability/event/eventer_retry_test.go +++ b/internal/observability/event/eventer_retry_test.go @@ -8,7 +8,6 @@ import ( "testing" "github.com/hashicorp/eventlogger" - "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-multierror" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -21,9 +20,8 @@ func TestEventer_retrySend(t *testing.T) { testConfig := TestEventerConfig(t, "TestEventer_retrySend") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - }) + testLogger := testLogger(t, testLock) + eventer, err := NewEventer(testLogger, testLock, "TestEventer_retrySend", testConfig.EventerConfig) require.NoError(t, err) diff --git a/internal/observability/event/eventer_test.go b/internal/observability/event/eventer_test.go index 35f0354c9..c0a4b81f9 100644 --- a/internal/observability/event/eventer_test.go +++ b/internal/observability/event/eventer_test.go @@ -27,7 +27,8 @@ func Test_InitSysEventer(t *testing.T) { testConfig := TestEventerConfig(t, "InitSysEventer") testLock := &sync.Mutex{} testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, + Mutex: testLock, + JSONFormat: true, }) testEventer, err := NewEventer(testLogger, testLock, "Test_InitSysEventer", testConfig.EventerConfig) require.NoError(t, err) @@ -164,9 +165,8 @@ func TestEventer_writeObservation(t *testing.T) { ctx := context.Background() testSetup := TestEventerConfig(t, "TestEventer_writeObservation") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - }) + testLogger := testLogger(t, testLock) + eventer, err := NewEventer(testLogger, testLock, "TestEventer_writeObservation", testSetup.EventerConfig) require.NoError(t, err) @@ -219,11 +219,7 @@ func TestEventer_writeObservation(t *testing.T) { c := EventerConfig{ ObservationsEnabled: true, } - testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + // with no defined config, it will default to a stderr sink e, err := NewEventer(testLogger, testLock, "e2e-test", c) require.NoError(err) @@ -244,10 +240,7 @@ func TestEventer_writeAudit(t *testing.T) { ctx := context.Background() testSetup := TestEventerConfig(t, "Test_NewEventer") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) eventer, err := NewEventer(testLogger, testLock, "TestEventer_writeAudit", testSetup.EventerConfig) require.NoError(t, err) @@ -304,10 +297,8 @@ func TestEventer_writeError(t *testing.T) { ctx := context.Background() testSetup := TestEventerConfig(t, "Test_NewEventer") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) + eventer, er := NewEventer(testLogger, testLock, "TestEventer_writeError", testSetup.EventerConfig) require.NoError(t, er) @@ -363,10 +354,7 @@ func Test_NewEventer(t *testing.T) { testHclogSetup := TestEventerConfig(t, "Test_NewEventer", testWithSinkFormat(t, TextHclogSinkFormat)) testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) twrapper := testWrapper(t) @@ -772,10 +760,7 @@ func TestEventer_Reopen(t *testing.T) { assert, require := assert.New(t), require.New(t) testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) e, err := NewEventer(testLogger, testLock, "TestEventer_Reopen", EventerConfig{}) require.NoError(err) @@ -794,10 +779,7 @@ func TestEventer_FlushNodes(t *testing.T) { t.Run("simple", func(t *testing.T) { assert, require := assert.New(t), require.New(t) testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) e, err := NewEventer(testLogger, testLock, "TestEventer_FlushNodes", EventerConfig{}) require.NoError(err) @@ -832,10 +814,8 @@ func Test_StandardLogger(t *testing.T) { testCtx := context.Background() c := TestEventerConfig(t, "Test_StandardLogger") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) + require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig))) tests := []struct { @@ -923,10 +903,8 @@ func Test_StandardWriter(t *testing.T) { c := TestEventerConfig(t, "Test_StandardLogger") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) + require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig))) testCtx, err := NewEventerContext(context.Background(), SysEventer()) @@ -1017,10 +995,8 @@ func Test_logAdapter_Write(t *testing.T) { c := TestEventerConfig(t, "Test_StandardLogger") testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) + require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig))) testCtx, err := NewEventerContext(context.Background(), SysEventer()) @@ -1177,10 +1153,7 @@ func TestEventer_RotateAuditWrapper(t *testing.T) { hclogConfig := TestEventerConfig(t, "TestEventer_RotateAuditWrapper", testWithSinkFormat(t, JSONHclogSinkFormat)) testLock := &sync.Mutex{} - testLogger := hclog.New(&hclog.LoggerOptions{ - Mutex: testLock, - Name: "test", - }) + testLogger := testLogger(t, testLock) testCtx := context.Background() tests := []struct { diff --git a/internal/observability/event/testing.go b/internal/observability/event/testing.go index a0922ddb0..1ee10b096 100644 --- a/internal/observability/event/testing.go +++ b/internal/observability/event/testing.go @@ -315,3 +315,12 @@ func (b *testMockBroker) SetSuccessThreshold(t eventlogger.EventType, successThr b.successThresholds[t] = successThreshold return nil } + +func testLogger(t *testing.T, testLock hclog.Locker) hclog.Logger { + t.Helper() + return hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + JSONFormat: true, + }) +}