Skip to content

Commit

Permalink
VAULT-24013: Audit regression attempting to recover from panic (hashi…
Browse files Browse the repository at this point in the history 
…corp#25605)

* Add Logger to BackendConfig

* EntryFormatter use logger and recover panics

* Added TODO to consider

* Add 'name' to entry formatter

* Add test for the panic

* Fix NoopAudit with update params

* emit counter metric even when 0

* Fix vault package tests

* changelog

* Remove old comment during test writing
  • Loading branch information
Peter Wilson authored Feb 26, 2024
1 parent 273ba49 commit 67c1634
Show file tree
Hide file tree
Showing 14 changed files with 250 additions and 59 deletions.
42 changes: 38 additions & 4 deletions audit/entry_formatter.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -28,21 +32,32 @@ var (

// EntryFormatter should be used to format audit requests and responses.
type EntryFormatter struct {
config FormatterConfig
salter Salter
logger hclog.Logger
headerFormatter HeaderFormatter
config FormatterConfig
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)
Expand All @@ -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
}
Expand All @@ -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 {
Expand All @@ -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 {
Expand Down
116 changes: 105 additions & 11 deletions audit/entry_formatter_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -62,49 +64,79 @@ 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()),
},
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()),
},
IsErrorExpected: false,
ExpectedFormat: JSONFormat,
},
"config-jsonx": {
Name: "juan",
UseStaticSalt: true,
Logger: hclog.NewNullLogger(),
Options: []Option{
WithFormat(JSONxFormat.String()),
},
IsErrorExpected: false,
ExpectedFormat: JSONxFormat,
},
"config-json-prefix": {
Name: "juan",
UseStaticSalt: true,
Logger: hclog.NewNullLogger(),
Options: []Option{
WithPrefix("foo"),
WithFormat(JSONFormat.String()),
Expand All @@ -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()),
Expand All @@ -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:
Expand All @@ -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())
Expand All @@ -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())
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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{
Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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)

Expand Down Expand Up @@ -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 {
Expand Down
4 changes: 4 additions & 0 deletions audit/types.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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.
Expand Down
Loading

0 comments on commit 67c1634

Please sign in to comment.