diff --git a/audit/entry_formatter.go b/audit/entry_formatter.go index 328c1901ce..96ec7762ba 100644 --- a/audit/entry_formatter.go +++ b/audit/entry_formatter.go @@ -8,11 +8,15 @@ import ( "crypto/tls" "errors" "fmt" + "reflect" + "runtime/debug" "strings" "time" "github.com/go-jose/go-jose/v3/jwt" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/go-multierror" "github.com/hashicorp/vault/helper/namespace" "github.com/hashicorp/vault/internal/observability/event" "github.com/hashicorp/vault/sdk/helper/jsonutil" @@ -28,21 +32,32 @@ var ( // EntryFormatter should be used to format audit requests and responses. type EntryFormatter struct { - salter Salter - headerFormatter HeaderFormatter config FormatterConfig + salter Salter + logger hclog.Logger + headerFormatter HeaderFormatter + name string prefix string } // NewEntryFormatter should be used to create an EntryFormatter. // Accepted options: WithHeaderFormatter, WithPrefix. -func NewEntryFormatter(config FormatterConfig, salter Salter, opt ...Option) (*EntryFormatter, error) { +func NewEntryFormatter(name string, config FormatterConfig, salter Salter, logger hclog.Logger, opt ...Option) (*EntryFormatter, error) { const op = "audit.NewEntryFormatter" + name = strings.TrimSpace(name) + if name == "" { + return nil, fmt.Errorf("%s: name is required: %w", op, event.ErrInvalidParameter) + } + if salter == nil { return nil, fmt.Errorf("%s: cannot create a new audit formatter with nil salter: %w", op, event.ErrInvalidParameter) } + if logger == nil || reflect.ValueOf(logger).IsNil() { + return nil, fmt.Errorf("%s: cannot create a new audit formatter with nil logger: %w", op, event.ErrInvalidParameter) + } + // We need to ensure that the format isn't just some default empty string. if err := config.RequiredFormat.validate(); err != nil { return nil, fmt.Errorf("%s: format not valid: %w", op, err) @@ -54,9 +69,11 @@ func NewEntryFormatter(config FormatterConfig, salter Salter, opt ...Option) (*E } return &EntryFormatter{ - salter: salter, config: config, + salter: salter, + logger: logger, headerFormatter: opts.withHeaderFormatter, + name: name, prefix: opts.withPrefix, }, nil } @@ -73,7 +90,7 @@ func (*EntryFormatter) Type() eventlogger.NodeType { // Process will attempt to parse the incoming event data into a corresponding // audit Request/Response which is serialized to JSON/JSONx and stored within the event. -func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (*eventlogger.Event, error) { +func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (_ *eventlogger.Event, retErr error) { const op = "audit.(EntryFormatter).Process" select { @@ -95,6 +112,23 @@ func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (*ev return nil, fmt.Errorf("%s: cannot audit event (%s) with no data: %w", op, a.Subtype, event.ErrInvalidParameter) } + // Handle panics + defer func() { + r := recover() + if r == nil { + return + } + + f.logger.Error("panic during logging", + "request_path", a.Data.Request.Path, + "audit_device_path", f.name, + "error", r, + "stacktrace", string(debug.Stack())) + + // Ensure that we add this error onto any pre-existing error that was being returned. + retErr = multierror.Append(retErr, fmt.Errorf("%s: panic generating audit log: %q", op, f.name)).ErrorOrNil() + }() + // Take a copy of the event data before we modify anything. data, err := a.Data.Clone() if err != nil { diff --git a/audit/entry_formatter_test.go b/audit/entry_formatter_test.go index a101213eef..9b5dc1ccac 100644 --- a/audit/entry_formatter_test.go +++ b/audit/entry_formatter_test.go @@ -13,6 +13,8 @@ import ( "time" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/go-sockaddr" "github.com/hashicorp/vault/helper/namespace" "github.com/hashicorp/vault/internal/observability/event" "github.com/hashicorp/vault/sdk/helper/jsonutil" @@ -62,20 +64,42 @@ func TestNewEntryFormatter(t *testing.T) { t.Parallel() tests := map[string]struct { + Name string UseStaticSalt bool + Logger hclog.Logger Options []Option // Only supports WithPrefix IsErrorExpected bool ExpectedErrorMessage string ExpectedFormat format ExpectedPrefix string }{ + "empty-name": { + Name: "", + IsErrorExpected: true, + ExpectedErrorMessage: "audit.NewEntryFormatter: name is required: invalid parameter", + }, + "spacey-name": { + Name: " ", + IsErrorExpected: true, + ExpectedErrorMessage: "audit.NewEntryFormatter: name is required: invalid parameter", + }, "nil-salter": { + Name: "juan", UseStaticSalt: false, IsErrorExpected: true, ExpectedErrorMessage: "audit.NewEntryFormatter: cannot create a new audit formatter with nil salter: invalid parameter", }, + "nil-logger": { + Name: "juan", + UseStaticSalt: true, + Logger: nil, + IsErrorExpected: true, + ExpectedErrorMessage: "audit.NewEntryFormatter: cannot create a new audit formatter with nil logger: invalid parameter", + }, "static-salter": { + Name: "juan", UseStaticSalt: true, + Logger: hclog.NewNullLogger(), IsErrorExpected: false, Options: []Option{ WithFormat(JSONFormat.String()), @@ -83,12 +107,16 @@ func TestNewEntryFormatter(t *testing.T) { ExpectedFormat: JSONFormat, }, "default": { + Name: "juan", UseStaticSalt: true, + Logger: hclog.NewNullLogger(), IsErrorExpected: false, ExpectedFormat: JSONFormat, }, "config-json": { + Name: "juan", UseStaticSalt: true, + Logger: hclog.NewNullLogger(), Options: []Option{ WithFormat(JSONFormat.String()), }, @@ -96,7 +124,9 @@ func TestNewEntryFormatter(t *testing.T) { ExpectedFormat: JSONFormat, }, "config-jsonx": { + Name: "juan", UseStaticSalt: true, + Logger: hclog.NewNullLogger(), Options: []Option{ WithFormat(JSONxFormat.String()), }, @@ -104,7 +134,9 @@ func TestNewEntryFormatter(t *testing.T) { ExpectedFormat: JSONxFormat, }, "config-json-prefix": { + Name: "juan", UseStaticSalt: true, + Logger: hclog.NewNullLogger(), Options: []Option{ WithPrefix("foo"), WithFormat(JSONFormat.String()), @@ -114,7 +146,9 @@ func TestNewEntryFormatter(t *testing.T) { ExpectedPrefix: "foo", }, "config-jsonx-prefix": { + Name: "juan", UseStaticSalt: true, + Logger: hclog.NewNullLogger(), Options: []Option{ WithPrefix("foo"), WithFormat(JSONxFormat.String()), @@ -137,7 +171,7 @@ func TestNewEntryFormatter(t *testing.T) { cfg, err := NewFormatterConfig(tc.Options...) require.NoError(t, err) - f, err := NewEntryFormatter(cfg, ss, tc.Options...) + f, err := NewEntryFormatter(tc.Name, cfg, ss, tc.Logger, tc.Options...) switch { case tc.IsErrorExpected: @@ -162,7 +196,7 @@ func TestEntryFormatter_Reopen(t *testing.T) { cfg, err := NewFormatterConfig() require.NoError(t, err) - f, err := NewEntryFormatter(cfg, ss) + f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(t, err) require.NotNil(t, f) require.NoError(t, f.Reopen()) @@ -176,7 +210,7 @@ func TestEntryFormatter_Type(t *testing.T) { cfg, err := NewFormatterConfig() require.NoError(t, err) - f, err := NewEntryFormatter(cfg, ss) + f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(t, err) require.NotNil(t, f) require.Equal(t, eventlogger.NodeTypeFormatter, f.Type()) @@ -321,7 +355,7 @@ func TestEntryFormatter_Process(t *testing.T) { cfg, err := NewFormatterConfig(WithFormat(tc.RequiredFormat.String())) require.NoError(t, err) - f, err := NewEntryFormatter(cfg, ss) + f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(t, err) require.NotNil(t, f) @@ -386,7 +420,7 @@ func BenchmarkAuditFileSink_Process(b *testing.B) { cfg, err := NewFormatterConfig() require.NoError(b, err) ss := newStaticSalt(b) - formatter, err := NewEntryFormatter(cfg, ss) + formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(b, err) require.NotNil(b, formatter) @@ -457,7 +491,7 @@ func TestEntryFormatter_FormatRequest(t *testing.T) { ss := newStaticSalt(t) cfg, err := NewFormatterConfig() require.NoError(t, err) - f, err := NewEntryFormatter(cfg, ss) + f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(t, err) var ctx context.Context @@ -526,7 +560,7 @@ func TestEntryFormatter_FormatResponse(t *testing.T) { ss := newStaticSalt(t) cfg, err := NewFormatterConfig() require.NoError(t, err) - f, err := NewEntryFormatter(cfg, ss) + f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(t, err) var ctx context.Context @@ -636,7 +670,7 @@ func TestEntryFormatter_Process_JSON(t *testing.T) { for name, tc := range cases { cfg, err := NewFormatterConfig(WithHMACAccessor(false)) require.NoError(t, err) - formatter, err := NewEntryFormatter(cfg, ss, WithPrefix(tc.Prefix)) + formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger(), WithPrefix(tc.Prefix)) require.NoError(t, err) in := &logical.LogInput{ @@ -797,7 +831,7 @@ func TestEntryFormatter_Process_JSONx(t *testing.T) { WithFormat(JSONxFormat.String()), ) require.NoError(t, err) - formatter, err := NewEntryFormatter(cfg, tempStaticSalt, WithPrefix(tc.Prefix)) + formatter, err := NewEntryFormatter("juan", cfg, tempStaticSalt, hclog.NewNullLogger(), WithPrefix(tc.Prefix)) require.NoError(t, err) require.NotNil(t, formatter) @@ -913,7 +947,7 @@ func TestEntryFormatter_FormatResponse_ElideListResponses(t *testing.T) { var err error format := func(t *testing.T, config FormatterConfig, operation logical.Operation, inputData map[string]any) *ResponseEntry { - formatter, err = NewEntryFormatter(config, ss) + formatter, err = NewEntryFormatter("juan", config, ss, hclog.NewNullLogger()) require.NoError(t, err) require.NotNil(t, formatter) @@ -975,7 +1009,7 @@ func TestEntryFormatter_Process_NoMutation(t *testing.T) { cfg, err := NewFormatterConfig() require.NoError(t, err) ss := newStaticSalt(t) - formatter, err := NewEntryFormatter(cfg, ss) + formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) require.NoError(t, err) require.NotNil(t, formatter) @@ -1025,6 +1059,66 @@ func TestEntryFormatter_Process_NoMutation(t *testing.T) { require.NotEqual(t, a2, a) } +// TestEntryFormatter_Process_Panic tries to send data into the EntryFormatter +// which will currently cause a panic when a response is formatted due to the +// underlying hashing that is done with reflectwalk. +func TestEntryFormatter_Process_Panic(t *testing.T) { + t.Parallel() + + // Create the formatter node. + cfg, err := NewFormatterConfig() + require.NoError(t, err) + ss := newStaticSalt(t) + formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger()) + require.NoError(t, err) + require.NotNil(t, formatter) + + // The secret sauce, create a bad addr. + // see: https://github.com/hashicorp/vault/issues/16462 + badAddr, err := sockaddr.NewSockAddr("10.10.10.2/32 10.10.10.3/32") + require.NoError(t, err) + + in := &logical.LogInput{ + Auth: &logical.Auth{ + ClientToken: "foo", + Accessor: "bar", + EntityID: "foobarentity", + DisplayName: "testtoken", + NoDefaultPolicy: true, + Policies: []string{"root"}, + TokenType: logical.TokenTypeService, + }, + Request: &logical.Request{ + Operation: logical.UpdateOperation, + Path: "/foo", + Connection: &logical.Connection{ + RemoteAddr: "127.0.0.1", + }, + WrapInfo: &logical.RequestWrapInfo{ + TTL: 60 * time.Second, + }, + Headers: map[string][]string{ + "foo": {"bar"}, + }, + Data: map[string]interface{}{}, + }, + Response: &logical.Response{ + Data: map[string]any{ + "token_bound_cidrs": []*sockaddr.SockAddrMarshaler{ + {SockAddr: badAddr}, + }, + }, + }, + } + + e := fakeEvent(t, ResponseType, in) + + e2, err := formatter.Process(namespace.RootContext(nil), e) + require.Error(t, err) + require.Contains(t, err.Error(), "audit.(EntryFormatter).Process: panic generating audit log: \"juan\"") + require.Nil(t, e2) +} + // hashExpectedValueForComparison replicates enough of the audit HMAC process on a piece of expected data in a test, // so that we can use assert.Equal to compare the expected and output values. func (f *EntryFormatter) hashExpectedValueForComparison(input map[string]any) map[string]any { diff --git a/audit/types.go b/audit/types.go index 78d1fac372..5c64fe3861 100644 --- a/audit/types.go +++ b/audit/types.go @@ -6,6 +6,7 @@ package audit import ( "context" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/vault/internal/observability/event" "github.com/hashicorp/vault/sdk/helper/salt" "github.com/hashicorp/vault/sdk/logical" @@ -231,6 +232,9 @@ type BackendConfig struct { // MountPath is the path where this Backend is mounted MountPath string + + // Logger is used to emit log messages usually captured in the server logs. + Logger hclog.Logger } // Factory is the factory function to create an audit backend. diff --git a/builtin/audit/file/backend.go b/builtin/audit/file/backend.go index b9f5288bb8..795aa8c300 100644 --- a/builtin/audit/file/backend.go +++ b/builtin/audit/file/backend.go @@ -6,12 +6,14 @@ package file import ( "context" "fmt" + "reflect" "strconv" "strings" "sync" "sync/atomic" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/internal/observability/event" @@ -48,10 +50,15 @@ func Factory(_ context.Context, conf *audit.BackendConfig, headersConfig audit.H if conf.SaltConfig == nil { return nil, fmt.Errorf("%s: nil salt config", op) } + if conf.SaltView == nil { return nil, fmt.Errorf("%s: nil salt view", op) } + if conf.Logger == nil || reflect.ValueOf(conf.Logger).IsNil() { + return nil, fmt.Errorf("%s: nil logger", op) + } + // The config options 'fallback' and 'filter' are mutually exclusive, a fallback // device catches everything, so it cannot be allowed to filter. var fallback bool @@ -115,7 +122,7 @@ func Factory(_ context.Context, conf *audit.BackendConfig, headersConfig audit.H audit.WithPrefix(conf.Config["prefix"]), } - err = b.configureFormatterNode(cfg, formatterOpts...) + err = b.configureFormatterNode(conf.MountPath, cfg, conf.Logger, formatterOpts...) if err != nil { return nil, fmt.Errorf("%s: error configuring formatter node: %w", op, err) } @@ -242,7 +249,7 @@ func (b *Backend) configureFilterNode(filter string) error { } // configureFormatterNode is used to configure a formatter node and associated ID on the Backend. -func (b *Backend) configureFormatterNode(formatConfig audit.FormatterConfig, opts ...audit.Option) error { +func (b *Backend) configureFormatterNode(name string, formatConfig audit.FormatterConfig, logger hclog.Logger, opts ...audit.Option) error { const op = "file.(Backend).configureFormatterNode" formatterNodeID, err := event.GenerateNodeID() @@ -250,7 +257,7 @@ func (b *Backend) configureFormatterNode(formatConfig audit.FormatterConfig, opt return fmt.Errorf("%s: error generating random NodeID for formatter node: %w", op, err) } - formatterNode, err := audit.NewEntryFormatter(formatConfig, b, opts...) + formatterNode, err := audit.NewEntryFormatter(name, formatConfig, b, logger, opts...) if err != nil { return fmt.Errorf("%s: error creating formatter: %w", op, err) } diff --git a/builtin/audit/file/backend_test.go b/builtin/audit/file/backend_test.go index a3f24ef9f2..f3e495b343 100644 --- a/builtin/audit/file/backend_test.go +++ b/builtin/audit/file/backend_test.go @@ -11,6 +11,7 @@ import ( "testing" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/internal/observability/event" "github.com/hashicorp/vault/sdk/helper/salt" @@ -37,6 +38,7 @@ func TestAuditFile_fileModeNew(t *testing.T) { MountPath: "foo/bar", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), } _, err = Factory(context.Background(), backendConfig, nil) require.NoError(t, err) @@ -68,6 +70,7 @@ func TestAuditFile_fileModeExisting(t *testing.T) { MountPath: "foo/bar", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), } _, err = Factory(context.Background(), backendConfig, nil) @@ -101,6 +104,7 @@ func TestAuditFile_fileMode0000(t *testing.T) { MountPath: "foo/bar", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), } _, err = Factory(context.Background(), backendConfig, nil) @@ -129,6 +133,7 @@ func TestAuditFile_EventLogger_fileModeNew(t *testing.T) { MountPath: "foo/bar", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), } _, err = Factory(context.Background(), backendConfig, nil) @@ -320,7 +325,7 @@ func TestBackend_configureFormatterNode(t *testing.T) { formatConfig, err := audit.NewFormatterConfig() require.NoError(t, err) - err = b.configureFormatterNode(formatConfig) + err = b.configureFormatterNode("juan", formatConfig, hclog.NewNullLogger()) require.NoError(t, err) require.Len(t, b.nodeIDList, 1) @@ -485,7 +490,7 @@ func TestBackend_configureFilterFormatterSink(t *testing.T) { err = b.configureFilterNode("path == bar") require.NoError(t, err) - err = b.configureFormatterNode(formatConfig) + err = b.configureFormatterNode("juan", formatConfig, hclog.NewNullLogger()) require.NoError(t, err) err = b.configureSinkNode("foo", "/tmp/foo", "0777", "json") @@ -533,11 +538,22 @@ func TestBackend_Factory_Conf(t *testing.T) { isErrorExpected: true, expectedErrorMessage: "file.Factory: nil salt view", }, + "nil-logger": { + backendConfig: &audit.BackendConfig{ + MountPath: "discard", + SaltConfig: &salt.Config{}, + SaltView: &logical.InmemStorage{}, + Logger: nil, + }, + isErrorExpected: true, + expectedErrorMessage: "file.Factory: nil logger", + }, "fallback-device-with-filter": { backendConfig: &audit.BackendConfig{ MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "true", "file_path": discard, @@ -552,6 +568,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "false", "file_path": discard, @@ -598,6 +615,7 @@ func TestBackend_IsFallback(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "true", "file_path": discard, @@ -610,6 +628,7 @@ func TestBackend_IsFallback(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "false", "file_path": discard, diff --git a/builtin/audit/socket/backend.go b/builtin/audit/socket/backend.go index e424fd7098..c88c922a10 100644 --- a/builtin/audit/socket/backend.go +++ b/builtin/audit/socket/backend.go @@ -6,11 +6,13 @@ package socket import ( "context" "fmt" + "reflect" "strconv" "strings" "sync" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/internal/observability/event" @@ -43,6 +45,10 @@ func Factory(_ context.Context, conf *audit.BackendConfig, headersConfig audit.H return nil, fmt.Errorf("%s: nil salt view", op) } + if conf.Logger == nil || reflect.ValueOf(conf.Logger).IsNil() { + return nil, fmt.Errorf("%s: nil logger", op) + } + address, ok := conf.Config["address"] if !ok { return nil, fmt.Errorf("%s: address is required", op) @@ -97,7 +103,7 @@ func Factory(_ context.Context, conf *audit.BackendConfig, headersConfig audit.H audit.WithPrefix(conf.Config["prefix"]), } - err = b.configureFormatterNode(cfg, opts...) + err = b.configureFormatterNode(conf.MountPath, cfg, conf.Logger, opts...) if err != nil { return nil, fmt.Errorf("%s: error configuring formatter node: %w", op, err) } @@ -225,7 +231,7 @@ func (b *Backend) configureFilterNode(filter string) error { } // configureFormatterNode is used to configure a formatter node and associated ID on the Backend. -func (b *Backend) configureFormatterNode(formatConfig audit.FormatterConfig, opts ...audit.Option) error { +func (b *Backend) configureFormatterNode(name string, formatConfig audit.FormatterConfig, logger hclog.Logger, opts ...audit.Option) error { const op = "socket.(Backend).configureFormatterNode" formatterNodeID, err := event.GenerateNodeID() @@ -233,7 +239,7 @@ func (b *Backend) configureFormatterNode(formatConfig audit.FormatterConfig, opt return fmt.Errorf("%s: error generating random NodeID for formatter node: %w", op, err) } - formatterNode, err := audit.NewEntryFormatter(formatConfig, b, opts...) + formatterNode, err := audit.NewEntryFormatter(name, formatConfig, b, logger, opts...) if err != nil { return fmt.Errorf("%s: error creating formatter: %w", op, err) } diff --git a/builtin/audit/socket/backend_test.go b/builtin/audit/socket/backend_test.go index 6dfbc1fff8..1c94e5ce6a 100644 --- a/builtin/audit/socket/backend_test.go +++ b/builtin/audit/socket/backend_test.go @@ -8,6 +8,7 @@ import ( "testing" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/internal/observability/event" "github.com/hashicorp/vault/sdk/helper/salt" @@ -196,7 +197,7 @@ func TestBackend_configureFormatterNode(t *testing.T) { formatConfig, err := audit.NewFormatterConfig() require.NoError(t, err) - err = b.configureFormatterNode(formatConfig) + err = b.configureFormatterNode("juan", formatConfig, hclog.NewNullLogger()) require.NoError(t, err) require.Len(t, b.nodeIDList, 1) @@ -317,7 +318,7 @@ func TestBackend_configureFilterFormatterSink(t *testing.T) { err = b.configureFilterNode("mount_type == kv") require.NoError(t, err) - err = b.configureFormatterNode(formatConfig) + err = b.configureFormatterNode("juan", formatConfig, hclog.NewNullLogger()) require.NoError(t, err) err = b.configureSinkNode("foo", "https://hashicorp.com", "json") @@ -365,11 +366,22 @@ func TestBackend_Factory_Conf(t *testing.T) { isErrorExpected: true, expectedErrorMessage: "socket.Factory: nil salt view", }, + "nil-logger": { + backendConfig: &audit.BackendConfig{ + MountPath: "discard", + SaltConfig: &salt.Config{}, + SaltView: &logical.InmemStorage{}, + Logger: nil, + }, + isErrorExpected: true, + expectedErrorMessage: "socket.Factory: nil logger", + }, "no-address": { backendConfig: &audit.BackendConfig{ MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{}, }, isErrorExpected: true, @@ -380,6 +392,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "address": "", }, @@ -392,6 +405,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "address": " ", }, @@ -404,6 +418,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "address": "hashicorp.com", "write_timeout": "5s", @@ -416,6 +431,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "address": "hashicorp.com", "write_timeout": "qwerty", @@ -429,6 +445,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "address": "hashicorp.com", "write_timeout": "5s", @@ -443,6 +460,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "address": "hashicorp.com", "write_timeout": "2s", @@ -491,6 +509,7 @@ func TestBackend_IsFallback(t *testing.T) { MountPath: "qwerty", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "true", "address": "hashicorp.com", @@ -504,6 +523,7 @@ func TestBackend_IsFallback(t *testing.T) { MountPath: "qwerty", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "false", "address": "hashicorp.com", diff --git a/builtin/audit/syslog/backend.go b/builtin/audit/syslog/backend.go index 413d54596e..28d2d6f59b 100644 --- a/builtin/audit/syslog/backend.go +++ b/builtin/audit/syslog/backend.go @@ -6,11 +6,13 @@ package syslog import ( "context" "fmt" + "reflect" "strconv" "strings" "sync" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/go-secure-stdlib/parseutil" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/internal/observability/event" @@ -43,6 +45,10 @@ func Factory(_ context.Context, conf *audit.BackendConfig, headersConfig audit.H return nil, fmt.Errorf("%s: nil salt view", op) } + if conf.Logger == nil || reflect.ValueOf(conf.Logger).IsNil() { + return nil, fmt.Errorf("%s: nil logger", op) + } + // Get facility or default to AUTH facility, ok := conf.Config["facility"] if !ok { @@ -94,7 +100,7 @@ func Factory(_ context.Context, conf *audit.BackendConfig, headersConfig audit.H audit.WithPrefix(conf.Config["prefix"]), } - err = b.configureFormatterNode(cfg, formatterOpts...) + err = b.configureFormatterNode(conf.MountPath, cfg, conf.Logger, formatterOpts...) if err != nil { return nil, fmt.Errorf("%s: error configuring formatter node: %w", op, err) } @@ -216,7 +222,7 @@ func (b *Backend) configureFilterNode(filter string) error { } // configureFormatterNode is used to configure a formatter node and associated ID on the Backend. -func (b *Backend) configureFormatterNode(formatConfig audit.FormatterConfig, opts ...audit.Option) error { +func (b *Backend) configureFormatterNode(name string, formatConfig audit.FormatterConfig, logger hclog.Logger, opts ...audit.Option) error { const op = "syslog.(Backend).configureFormatterNode" formatterNodeID, err := event.GenerateNodeID() @@ -224,7 +230,7 @@ func (b *Backend) configureFormatterNode(formatConfig audit.FormatterConfig, opt return fmt.Errorf("%s: error generating random NodeID for formatter node: %w", op, err) } - formatterNode, err := audit.NewEntryFormatter(formatConfig, b, opts...) + formatterNode, err := audit.NewEntryFormatter(name, formatConfig, b, logger, opts...) if err != nil { return fmt.Errorf("%s: error creating formatter: %w", op, err) } diff --git a/builtin/audit/syslog/backend_test.go b/builtin/audit/syslog/backend_test.go index 5f128f79b2..fb1e297b32 100644 --- a/builtin/audit/syslog/backend_test.go +++ b/builtin/audit/syslog/backend_test.go @@ -7,6 +7,8 @@ import ( "context" "testing" + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/eventlogger" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/internal/observability/event" @@ -196,7 +198,7 @@ func TestBackend_configureFormatterNode(t *testing.T) { formatConfig, err := audit.NewFormatterConfig() require.NoError(t, err) - err = b.configureFormatterNode(formatConfig) + err = b.configureFormatterNode("juan", formatConfig, hclog.NewNullLogger()) require.NoError(t, err) require.Len(t, b.nodeIDList, 1) @@ -299,7 +301,7 @@ func TestBackend_configureFilterFormatterSink(t *testing.T) { err = b.configureFilterNode("mount_type == kv") require.NoError(t, err) - err = b.configureFormatterNode(formatConfig) + err = b.configureFormatterNode("juan", formatConfig, hclog.NewNullLogger()) require.NoError(t, err) err = b.configureSinkNode("foo", "json") @@ -352,6 +354,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "false", "filter": "mount_type == kv", @@ -364,6 +367,7 @@ func TestBackend_Factory_Conf(t *testing.T) { MountPath: "discard", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "true", "filter": "mount_type == kv", @@ -410,6 +414,7 @@ func TestBackend_IsFallback(t *testing.T) { MountPath: "qwerty", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "true", }, @@ -421,6 +426,7 @@ func TestBackend_IsFallback(t *testing.T) { MountPath: "qwerty", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), Config: map[string]string{ "fallback": "false", }, diff --git a/changelog/25605.txt b/changelog/25605.txt new file mode 100644 index 0000000000..a152ce45c2 --- /dev/null +++ b/changelog/25605.txt @@ -0,0 +1,3 @@ +```release-note:bug +audit: Handle a potential panic while formatting audit entries for an audit log +``` diff --git a/helper/testhelpers/corehelpers/corehelpers.go b/helper/testhelpers/corehelpers/corehelpers.go index 7d3f7b39ef..8e252ac2d4 100644 --- a/helper/testhelpers/corehelpers/corehelpers.go +++ b/helper/testhelpers/corehelpers/corehelpers.go @@ -217,7 +217,11 @@ func (m *mockBuiltinRegistry) DeprecationStatus(name string, pluginType consts.P } func TestNoopAudit(t testing.T, path string, config map[string]string, opts ...audit.Option) *NoopAudit { - cfg := &audit.BackendConfig{Config: config, MountPath: path} + cfg := &audit.BackendConfig{ + Config: config, + MountPath: path, + Logger: NewTestLogger(t), + } n, err := NewNoopAudit(cfg, opts...) if err != nil { t.Fatal(err) @@ -265,7 +269,7 @@ func NewNoopAudit(config *audit.BackendConfig, opts ...audit.Option) (*NoopAudit return nil, fmt.Errorf("error generating random NodeID for formatter node: %w", err) } - formatterNode, err := audit.NewEntryFormatter(cfg, noopBackend, opts...) + formatterNode, err := audit.NewEntryFormatter(config.MountPath, cfg, noopBackend, config.Logger, opts...) if err != nil { return nil, fmt.Errorf("error creating formatter: %w", err) } diff --git a/vault/audit.go b/vault/audit.go index 9c1aaaca3f..0f0182be47 100644 --- a/vault/audit.go +++ b/vault/audit.go @@ -516,6 +516,7 @@ func (c *Core) newAuditBackend(ctx context.Context, entry *MountEntry, view logi HMACType: "hmac-sha256", Location: salt.DefaultLocation, } + auditLogger := c.baseLogger.Named("audit") be, err := f( ctx, &audit.BackendConfig{ @@ -523,6 +524,7 @@ func (c *Core) newAuditBackend(ctx context.Context, entry *MountEntry, view logi SaltConfig: saltConfig, Config: conf, MountPath: entry.Path, + Logger: auditLogger, }, c.auditedHeaders) if err != nil { @@ -532,8 +534,6 @@ func (c *Core) newAuditBackend(ctx context.Context, entry *MountEntry, view logi return nil, fmt.Errorf("nil backend returned from %q factory function", entry.Type) } - auditLogger := c.baseLogger.Named("audit") - switch entry.Type { case "file": key := "audit_file|" + entry.Path diff --git a/vault/audit_broker.go b/vault/audit_broker.go index 19438643fb..4992a24105 100644 --- a/vault/audit_broker.go +++ b/vault/audit_broker.go @@ -7,7 +7,6 @@ import ( "context" "errors" "fmt" - "runtime/debug" "strings" "sync" "time" @@ -218,23 +217,16 @@ func (a *AuditBroker) LogRequest(ctx context.Context, in *logical.LogInput) (ret } defer metrics.MeasureSince([]string{"audit", "log_request"}, time.Now()) + defer func() { + metricVal := float32(0.0) + if ret != nil { + metricVal = 1.0 + } + metrics.IncrCounter([]string{"audit", "log_request_failure"}, metricVal) + }() var retErr *multierror.Error - defer func() { - if r := recover(); r != nil { - a.logger.Error("panic during logging", "request_path", in.Request.Path, "error", r, "stacktrace", string(debug.Stack())) - retErr = multierror.Append(retErr, fmt.Errorf("panic generating audit log")) - } - - ret = retErr.ErrorOrNil() - failure := float32(0.0) - if ret != nil { - failure = 1.0 - } - metrics.IncrCounter([]string{"audit", "log_request_failure"}, failure) - }() - e, err := audit.NewEvent(audit.RequestType) if err != nil { retErr = multierror.Append(retErr, err) @@ -293,23 +285,16 @@ func (a *AuditBroker) LogResponse(ctx context.Context, in *logical.LogInput) (re } defer metrics.MeasureSince([]string{"audit", "log_response"}, time.Now()) + defer func() { + metricVal := float32(0.0) + if ret != nil { + metricVal = 1.0 + } + metrics.IncrCounter([]string{"audit", "log_response_failure"}, metricVal) + }() var retErr *multierror.Error - defer func() { - if r := recover(); r != nil { - a.logger.Error("panic during logging", "request_path", in.Request.Path, "error", r, "stacktrace", string(debug.Stack())) - retErr = multierror.Append(retErr, fmt.Errorf("panic generating audit log")) - } - - ret = retErr.ErrorOrNil() - failure := float32(0.0) - if ret != nil { - failure = 1.0 - } - metrics.IncrCounter([]string{"audit", "log_response_failure"}, failure) - }() - e, err := audit.NewEvent(audit.ResponseType) if err != nil { retErr = multierror.Append(retErr, err) diff --git a/vault/audit_broker_test.go b/vault/audit_broker_test.go index 6c890dcc69..6493f5454b 100644 --- a/vault/audit_broker_test.go +++ b/vault/audit_broker_test.go @@ -10,6 +10,7 @@ import ( "time" "github.com/hashicorp/eventlogger" + "github.com/hashicorp/go-hclog" "github.com/hashicorp/vault/audit" "github.com/hashicorp/vault/builtin/audit/file" "github.com/hashicorp/vault/builtin/audit/syslog" @@ -41,6 +42,7 @@ func testAuditBackend(t *testing.T, path string, config map[string]string) audit HMAC: sha256.New, HMACType: "hmac-sha256", }, + Logger: corehelpers.NewTestLogger(t), Config: config, MountPath: path, } @@ -283,6 +285,7 @@ func BenchmarkAuditBroker_File_Request_DevNull(b *testing.B) { MountPath: "test", SaltConfig: &salt.Config{}, SaltView: &logical.InmemStorage{}, + Logger: hclog.NewNullLogger(), } sink, err := file.Factory(context.Background(), backendConfig, nil)