diff --git a/CHANGELOG.md b/CHANGELOG.md index 95fa043060..1202625ac1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -82,7 +82,10 @@ Canonical reference for changes, improvements, and bugfixes for Boundary. redacting/encrypting that data. - PRs: [update eventlogger](https://github.com/hashicorp/boundary/pull/1411), + PRs: + [log adapters](https://github.com/hashicorp/boundary/pull/1434), + [unneeded log deps](https://github.com/hashicorp/boundary/pull/1433), + [update eventlogger](https://github.com/hashicorp/boundary/pull/1411), [convert from hclog to events](https://github.com/hashicorp/boundary/pull/1409), [event filtering](https://github.com/hashicorp/boundary/pull/1404), [cloudevents node](https://github.com/hashicorp/boundary/pull/1390), diff --git a/internal/cmd/base/dev.go b/internal/cmd/base/dev.go index 6ecaec91be..fa7d7e4f93 100644 --- a/internal/cmd/base/dev.go +++ b/internal/cmd/base/dev.go @@ -6,6 +6,7 @@ import ( "fmt" "net" "net/url" + "runtime" "strings" "github.com/hashicorp/boundary/internal/auth/oidc" @@ -262,10 +263,6 @@ func (b *Server) CreateDevOidcAuthMethod(ctx context.Context) error { // Create the subject information and testing provider { - logger, err := capoidc.NewTestingLogger(b.Logger.Named("dev-oidc")) - if err != nil { - return fmt.Errorf("unable to create logger: %w", err) - } subInfo := map[string]*capoidc.TestSubject{ b.DevLoginName: { @@ -289,7 +286,7 @@ func (b *Server) CreateDevOidcAuthMethod(ctx context.Context) error { clientSecret := string(b.DevOidcSetup.clientSecret) b.DevOidcSetup.testProvider = capoidc.StartTestProvider( - logger, + &oidcLogger{}, capoidc.WithNoTLS(), capoidc.WithTestHost(b.DevOidcSetup.hostAddr), capoidc.WithTestPort(b.DevOidcSetup.oidcPort), @@ -443,3 +440,35 @@ func (b *Server) createInitialOidcAuthMethod(ctx context.Context) (*oidc.AuthMet return nil, nil } + +// oidcLogger satisfies the interface requirements for the oidc.TestProvider logger. +type oidcLogger struct { + Ctx context.Context // nil ctx is allowed/okay +} + +// Errorf will use the sys eventer to emit an error event +func (l *oidcLogger) Errorf(format string, args ...interface{}) { + event.WriteError(l.Ctx, l.caller(), fmt.Errorf(format, args...)) +} + +// Infof will use the sys eventer to emit an system event +func (l *oidcLogger) Infof(format string, args ...interface{}) { + event.WriteSysEvent(l.Ctx, l.caller(), fmt.Sprintf(format, args...)) +} + +// FailNow will panic (as required by the interface it's implementing) +func (_ *oidcLogger) FailNow() { + panic("sys eventer failed, see logs for output (if any)") +} + +func (_ *oidcLogger) caller() event.Op { + var caller event.Op + pc, _, _, ok := runtime.Caller(2) + details := runtime.FuncForPC(pc) + if ok && details != nil { + caller = event.Op(details.Name()) + } else { + caller = "unknown operation" + } + return caller +} diff --git a/internal/cmd/base/dev_test.go b/internal/cmd/base/dev_test.go new file mode 100644 index 0000000000..805a7a97de --- /dev/null +++ b/internal/cmd/base/dev_test.go @@ -0,0 +1,113 @@ +package base + +import ( + "encoding/json" + "fmt" + "io/ioutil" + "os" + "sync" + "testing" + + "github.com/hashicorp/boundary/internal/observability/event" + "github.com/hashicorp/eventlogger/formatter_filters/cloudevents" + "github.com/hashicorp/go-hclog" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func Test_oidcLogger_Errorf(t *testing.T) { + // this test and its subtests cannot be run in parallel because of it's + // dependency on the sysEventer + + c := event.TestEventerConfig(t, "TestoidcLogger_Errorf") + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + }) + require.NoError(t, event.InitSysEventer(testLogger, testLock, "use-TestoidcLogger_Errorf", event.WithEventerConfig(&c.EventerConfig))) + + tests := []struct { + name string + fmt string + args []interface{} + }{ + { + name: "no-args", + fmt: "simple", + }, + { + name: "with-args", + fmt: "%s: simple", + args: []interface{}{"error"}, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert, require := assert.New(t), require.New(t) + l := &oidcLogger{} + l.Errorf(tt.fmt, tt.args...) + sinkFileName := c.AllEvents.Name() + defer func() { _ = os.WriteFile(sinkFileName, nil, 0o666) }() + b, err := ioutil.ReadFile(sinkFileName) + require.NoError(err) + gotEvent := &cloudevents.Event{} + err = json.Unmarshal(b, gotEvent) + require.NoErrorf(err, "json: %s", string(b)) + expected := gotEvent.Data.(map[string]interface{}) + expected["error"] = fmt.Sprintf(tt.fmt, tt.args...) + assert.Equal(expected, gotEvent.Data.(map[string]interface{})) + }) + } +} + +func Test_oidcLogger_Infof(t *testing.T) { + // this test and its subtests cannot be run in parallel because of it's + // dependency on the sysEventer + + c := event.TestEventerConfig(t, "TestoidcLogger_Errorf") + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + }) + require.NoError(t, event.InitSysEventer(testLogger, testLock, "use-TestoidcLogger_Errorf", event.WithEventerConfig(&c.EventerConfig))) + + tests := []struct { + name string + fmt string + args []interface{} + }{ + { + name: "no-args", + fmt: "simple", + }, + { + name: "with-args", + fmt: "%s: simple", + args: []interface{}{"info"}, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert, require := assert.New(t), require.New(t) + l := &oidcLogger{} + l.Infof(tt.fmt, tt.args...) + sinkFileName := c.AllEvents.Name() + defer func() { _ = os.WriteFile(sinkFileName, nil, 0o666) }() + b, err := ioutil.ReadFile(sinkFileName) + require.NoError(err) + gotEvent := &cloudevents.Event{} + err = json.Unmarshal(b, gotEvent) + require.NoErrorf(err, "json: %s", string(b)) + expected := gotEvent.Data.(map[string]interface{}) + expected["msg"] = fmt.Sprintf(tt.fmt, tt.args...) + assert.Equal(expected, gotEvent.Data.(map[string]interface{})) + }) + } +} + +func Test_oidcLogger_FailNow(t *testing.T) { + l := &oidcLogger{} + assert.Panics(t, func() { l.FailNow() }, "sys eventer failed, see logs for output (if any)") +} diff --git a/internal/observability/event/eventer.go b/internal/observability/event/eventer.go index 94ad245a4a..59838de5ee 100644 --- a/internal/observability/event/eventer.go +++ b/internal/observability/event/eventer.go @@ -1,10 +1,16 @@ package event import ( + "bytes" "context" + "errors" "fmt" + "io" + "log" "net/url" "os" + "runtime" + "strings" "sync" "time" @@ -551,3 +557,129 @@ func (e *Eventer) FlushNodes(ctx context.Context) error { } return nil } + +// StandardLogger will create *log.Logger that will emit events through this +// Logger. This allows packages that require the stdlib log to emit events +// instead. +func (e *Eventer) StandardLogger(ctx context.Context, loggerName string, typ Type) (*log.Logger, error) { + const op = "event.(Eventer).StandardLogger" + if e == nil { + return nil, fmt.Errorf("%s: nil eventer: %w", op, ErrInvalidParameter) + } + if ctx == nil { + return nil, fmt.Errorf("%s: missing context: %w", op, ErrInvalidParameter) + } + if typ == "" { + return nil, fmt.Errorf("%s: missing type: %w", op, ErrInvalidParameter) + } + w, err := e.StandardWriter(ctx, typ) + if err != nil { + return nil, fmt.Errorf("%s: %w", op, err) + } + return log.New(w, loggerName, 0), nil +} + +// StandardWriter will create an io.Writer that will emit events through this +// io.Writer. +func (e *Eventer) StandardWriter(ctx context.Context, typ Type) (io.Writer, error) { + const op = "event.(Eventer).StandardErrorWriter" + if e == nil { + return nil, fmt.Errorf("%s: nil eventer: %w", op, ErrInvalidParameter) + } + if ctx == nil { + return nil, fmt.Errorf("%s: missing context: %w", op, ErrInvalidParameter) + } + if typ == "" { + return nil, fmt.Errorf("%s: missing type: %w", op, ErrInvalidParameter) + } + if err := typ.validate(); err != nil { + return nil, fmt.Errorf("%s: %w", op, err) + } + newEventer := *e + ctx, err := NewEventerContext(ctx, e) + if err != nil { + return nil, fmt.Errorf("%s: %w", op, err) + } + return &logAdapter{ + ctxWithEventer: ctx, + e: &newEventer, + emitEventType: typ, + }, nil +} + +type logAdapter struct { + ctxWithEventer context.Context + e *Eventer + emitEventType Type +} + +// Write satisfies the io.Writer interface and will take the data, infer the +// type of event and then emit an event. +func (s *logAdapter) Write(data []byte) (int, error) { + const op = "event.(stdlogAdapter).Write" + if s == nil { + return 0, fmt.Errorf("%s: nil log adapter: %w", op, ErrInvalidParameter) + } + var caller Op + pc, _, _, ok := runtime.Caller(1) + details := runtime.FuncForPC(pc) + if ok && details != nil { + caller = Op(details.Name()) + } else { + caller = "unknown operation" + } + + str := string(bytes.TrimRight(data, " \t\n")) + switch s.emitEventType { + case ErrorType, SystemType: + if err := s.send(s.emitEventType, caller, str); err != nil { + return 0, fmt.Errorf("%s: %w", op, err) + } + default: + t, str := s.pickType(str) + if err := s.send(t, caller, str); err != nil { + return 0, fmt.Errorf("%s: %w", op, err) + } + } + + return len(data), nil +} + +func (s *logAdapter) send(typ Type, caller Op, str string) error { + const op = "events.(stdlogAdapter).send" + if typ == "" { + return fmt.Errorf("%s: type is missing: %w", op, ErrInvalidParameter) + } + if caller == "" { + return fmt.Errorf("%s: missing caller: %w", op, ErrInvalidParameter) + } + switch typ { + case ErrorType: + WriteError(s.ctxWithEventer, caller, errors.New(str)) + return nil + case SystemType: + WriteSysEvent(s.ctxWithEventer, caller, str) + return nil + default: + return fmt.Errorf("%s: unsupported event type %s: %w", op, typ, ErrInvalidParameter) + } +} + +func (s *logAdapter) pickType(str string) (Type, string) { + switch { + case strings.HasPrefix(str, "[DEBUG]"): + return SystemType, strings.TrimSpace(str[7:]) + case strings.HasPrefix(str, "[TRACE]"): + return SystemType, strings.TrimSpace(str[7:]) + case strings.HasPrefix(str, "[INFO]"): + return SystemType, strings.TrimSpace(str[6:]) + case strings.HasPrefix(str, "[WARN]"): + return SystemType, strings.TrimSpace(str[6:]) + case strings.HasPrefix(str, "[ERROR]"): + return ErrorType, strings.TrimSpace(str[7:]) + case strings.HasPrefix(str, "[ERR]"): + return ErrorType, strings.TrimSpace(str[5:]) + default: + return SystemType, str + } +} diff --git a/internal/observability/event/eventer_test.go b/internal/observability/event/eventer_test.go index 27d6ae4b5f..287e2c837f 100644 --- a/internal/observability/event/eventer_test.go +++ b/internal/observability/event/eventer_test.go @@ -2,12 +2,18 @@ package event import ( "context" + "encoding/json" "fmt" + "io" + "io/ioutil" + "log" + "os" "strings" "sync" "testing" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/eventlogger/formatter_filters/cloudevents" "github.com/hashicorp/go-hclog" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -661,3 +667,347 @@ func (t *testFlushNode) FlushAll(_ context.Context) error { } return nil } + +func Test_StandardLogger(t *testing.T) { + // this test and its subtests cannot be run in parallel because of it's + // dependency on the sysEventer + + testCtx := context.Background() + c := TestEventerConfig(t, "Test_StandardLogger") + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + }) + require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig))) + + tests := []struct { + name string + eventer *Eventer + ctx context.Context + eventType Type + wantErr bool + wantErrIs error + wantErrContains string + wantLogger *log.Logger + }{ + { + name: "missing-eventer", + ctx: testCtx, + eventType: ErrorType, + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "nil eventer", + }, + { + name: "missing-ctx", + eventer: SysEventer(), + eventType: ErrorType, + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "missing context", + }, + { + name: "missing-type", + ctx: testCtx, + eventer: SysEventer(), + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "missing type", + }, + { + name: "invalid-type", + ctx: testCtx, + eventer: SysEventer(), + eventType: "invalid", + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "'invalid' is not a valid event type", + }, + { + name: "okay", + ctx: testCtx, + eventer: SysEventer(), + eventType: ErrorType, + wantLogger: func() *log.Logger { + w, err := SysEventer().StandardWriter(testCtx, ErrorType) + require.NoError(t, err) + return log.New(w, "okay", 0) + }(), + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert, require := assert.New(t), require.New(t) + e := SysEventer() + require.NotNil(e) + l, err := tt.eventer.StandardLogger(tt.ctx, tt.name, tt.eventType) + if tt.wantErr { + require.Error(err) + assert.Nil(l) + if tt.wantErrIs != nil { + assert.ErrorIs(err, tt.wantErrIs) + } + if tt.wantErrContains != "" { + assert.Contains(err.Error(), tt.wantErrContains) + } + return + } + require.NoError(err) + assert.NotNil(l) + assert.Equal(tt.wantLogger, l) + }) + } +} + +func Test_StandardWriter(t *testing.T) { + // this test and its subtests cannot be run in parallel because of it's + // dependency on the sysEventer + + c := TestEventerConfig(t, "Test_StandardLogger") + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + }) + require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig))) + + testCtx, err := NewEventerContext(context.Background(), SysEventer()) + require.NoError(t, err) + + tests := []struct { + name string + eventer *Eventer + ctx context.Context + eventType Type + wantErr bool + wantErrIs error + wantErrContains string + wantWriter io.Writer + }{ + { + name: "missing-eventer", + ctx: testCtx, + eventType: ErrorType, + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "nil eventer", + }, + { + name: "missing-ctx", + eventer: SysEventer(), + eventType: ErrorType, + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "missing context", + }, + { + name: "missing-type", + ctx: testCtx, + eventer: SysEventer(), + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "missing type", + }, + { + name: "invalid-type", + ctx: testCtx, + eventer: SysEventer(), + eventType: "invalid", + wantErr: true, + wantErrIs: ErrInvalidParameter, + wantErrContains: "'invalid' is not a valid event type", + }, + { + name: "okay", + ctx: context.Background(), + eventer: SysEventer(), + eventType: ErrorType, + wantWriter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + emitEventType: ErrorType, + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert, require := assert.New(t), require.New(t) + e := SysEventer() + require.NotNil(e) + l, err := tt.eventer.StandardWriter(tt.ctx, tt.eventType) + if tt.wantErr { + require.Error(err) + assert.Nil(l) + if tt.wantErrIs != nil { + assert.ErrorIs(err, tt.wantErrIs) + } + if tt.wantErrContains != "" { + assert.Contains(err.Error(), tt.wantErrContains) + } + return + } + require.NoError(err) + assert.NotNil(l) + assert.Equal(tt.wantWriter, l) + }) + } +} + +func Test_logAdapter_Write(t *testing.T) { + // this test and its subtests cannot be run in parallel because of it's + // dependency on the sysEventer + + c := TestEventerConfig(t, "Test_StandardLogger") + testLock := &sync.Mutex{} + testLogger := hclog.New(&hclog.LoggerOptions{ + Mutex: testLock, + Name: "test", + }) + require.NoError(t, InitSysEventer(testLogger, testLock, "Test_StandardLogger", WithEventerConfig(&c.EventerConfig))) + + testCtx, err := NewEventerContext(context.Background(), SysEventer()) + require.NoError(t, err) + + tests := []struct { + name string + adapter *logAdapter + data []byte + wantErr bool + wantIsError error + wantErrContains string + wantErrorEvent string + wantSystemEvent string + }{ + { + name: "nil-adapter", + data: []byte("nil-adapter"), + wantErr: true, + wantIsError: ErrInvalidParameter, + wantErrContains: "nil log adapter", + }, + { + name: "emit-sys-event", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + emitEventType: SystemType, + }, + data: []byte("emit-sys-event"), + wantSystemEvent: "emit-sys-event", + }, + { + name: "pick-type-DEBUG", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + }, + data: []byte("[DEBUG] pick-type-DEBUG"), + wantSystemEvent: "pick-type-DEBUG", + }, + { + name: "pick-type-TRACE", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + }, + data: []byte("[TRACE] pick-type-TRACE"), + wantSystemEvent: "pick-type-TRACE", + }, + { + name: "pick-type-INFO", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + }, + data: []byte("[INFO] pick-type-INFO"), + wantSystemEvent: "pick-type-INFO", + }, + { + name: "pick-type-WARN", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + }, + data: []byte("[WARN] pick-type-WARN"), + wantSystemEvent: "pick-type-WARN", + }, + { + name: "emit-error-event", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + emitEventType: ErrorType, + }, + data: []byte("emit-error-event"), + wantErrorEvent: "emit-error-event", + }, + { + name: "pick-type-ERR", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + }, + data: []byte("[ERR] pick-type-ERR"), + wantErrorEvent: "pick-type-ERR", + }, + { + name: "pick-type-ERROR", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + }, + data: []byte("[ERROR] pick-type-ERROR"), + wantErrorEvent: "pick-type-ERROR", + }, + { + name: "emit-every-type-event", + adapter: &logAdapter{ + ctxWithEventer: testCtx, + e: SysEventer(), + emitEventType: EveryType, + }, + data: []byte("emit-every-type-event"), + wantSystemEvent: "emit-every-type-event", + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert, require := assert.New(t), require.New(t) + + i, err := tt.adapter.Write(tt.data) + if tt.wantErr { + require.Error(err) + assert.Zero(i) + if tt.wantIsError != nil { + assert.ErrorIs(err, tt.wantIsError) + } + if tt.wantErrContains != "" { + assert.Contains(err.Error(), tt.wantErrContains) + } + return + } + require.NoError(err) + assert.Equal(len(tt.data), i) + + sinkFileName := c.AllEvents.Name() + defer func() { _ = os.WriteFile(sinkFileName, nil, 0o666) }() + b, err := ioutil.ReadFile(sinkFileName) + require.NoError(err) + gotEvent := &cloudevents.Event{} + err = json.Unmarshal(b, gotEvent) + require.NoErrorf(err, "json: %s", string(b)) + + if tt.wantErrorEvent != "" { + gotData := gotEvent.Data.(map[string]interface{}) + t.Log(tt.name, gotData) + assert.Equal(tt.wantErrorEvent, gotData["error"]) + } + if tt.wantSystemEvent != "" { + gotData := gotEvent.Data.(map[string]interface{})["data"].(map[string]interface{}) + t.Log(tt.name, gotData) + assert.Equal(tt.wantSystemEvent, gotData["msg"]) + } + }) + } +} diff --git a/internal/servers/worker/listeners.go b/internal/servers/worker/listeners.go index d27d4551f7..57983119eb 100644 --- a/internal/servers/worker/listeners.go +++ b/internal/servers/worker/listeners.go @@ -12,12 +12,22 @@ import ( "time" "github.com/hashicorp/boundary/internal/libs/alpnmux" + "github.com/hashicorp/boundary/internal/observability/event" "github.com/hashicorp/go-multierror" ) func (w *Worker) startListeners() error { + const op = "worker.(Worker).startListeners" + ctx := context.TODO() servers := make([]func(), 0, len(w.conf.Listeners)) - + e := event.SysEventer() + if e == nil { + return fmt.Errorf("%s: sys eventer not initialized", op) + } + logger, err := e.StandardLogger(ctx, "listeners", event.ErrorType) + if err != nil { + return fmt.Errorf("%s: unable to initialize std logger: %w", op, err) + } for _, ln := range w.conf.Listeners { for _, purpose := range ln.Config.Purpose { switch purpose { @@ -42,7 +52,7 @@ func (w *Worker) startListeners() error { Handler: handler, ReadHeaderTimeout: 10 * time.Second, ReadTimeout: 30 * time.Second, - ErrorLog: w.logger.StandardLogger(nil), + ErrorLog: logger, BaseContext: func(net.Listener) context.Context { return cancelCtx },