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, + }) +}