Skip to content

Commit fc96635

Browse files
peteski22kiannaquach
peteski22
authored and
kiannaquach
committed
VAULT-24013: Audit regression attempting to recover from panic (#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
1 parent f1e9db6 commit fc96635

File tree

14 files changed

+250
-59
lines changed

14 files changed

+250
-59
lines changed

‎audit/entry_formatter.go‎

Lines changed: 38 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -8,11 +8,15 @@ import (
88
"crypto/tls"
99
"errors"
1010
"fmt"
11+
"reflect"
12+
"runtime/debug"
1113
"strings"
1214
"time"
1315

1416
"github.com/go-jose/go-jose/v3/jwt"
1517
"github.com/hashicorp/eventlogger"
18+
"github.com/hashicorp/go-hclog"
19+
"github.com/hashicorp/go-multierror"
1620
"github.com/hashicorp/vault/helper/namespace"
1721
"github.com/hashicorp/vault/internal/observability/event"
1822
"github.com/hashicorp/vault/sdk/helper/jsonutil"
@@ -28,21 +32,32 @@ var (
2832

2933
// EntryFormatter should be used to format audit requests and responses.
3034
type EntryFormatter struct {
35+
config FormatterConfig
3136
salter Salter
37+
logger hclog.Logger
3238
headerFormatter HeaderFormatter
33-
config FormatterConfig
39+
name string
3440
prefix string
3541
}
3642

3743
// NewEntryFormatter should be used to create an EntryFormatter.
3844
// Accepted options: WithHeaderFormatter, WithPrefix.
39-
func NewEntryFormatter(config FormatterConfig, salter Salter, opt ...Option) (*EntryFormatter, error) {
45+
func NewEntryFormatter(name string, config FormatterConfig, salter Salter, logger hclog.Logger, opt ...Option) (*EntryFormatter, error) {
4046
const op = "audit.NewEntryFormatter"
4147

48+
name = strings.TrimSpace(name)
49+
if name == "" {
50+
return nil, fmt.Errorf("%s: name is required: %w", op, event.ErrInvalidParameter)
51+
}
52+
4253
if salter == nil {
4354
return nil, fmt.Errorf("%s: cannot create a new audit formatter with nil salter: %w", op, event.ErrInvalidParameter)
4455
}
4556

57+
if logger == nil || reflect.ValueOf(logger).IsNil() {
58+
return nil, fmt.Errorf("%s: cannot create a new audit formatter with nil logger: %w", op, event.ErrInvalidParameter)
59+
}
60+
4661
// We need to ensure that the format isn't just some default empty string.
4762
if err := config.RequiredFormat.validate(); err != nil {
4863
return nil, fmt.Errorf("%s: format not valid: %w", op, err)
@@ -54,9 +69,11 @@ func NewEntryFormatter(config FormatterConfig, salter Salter, opt ...Option) (*E
5469
}
5570

5671
return &EntryFormatter{
57-
salter: salter,
5872
config: config,
73+
salter: salter,
74+
logger: logger,
5975
headerFormatter: opts.withHeaderFormatter,
76+
name: name,
6077
prefix: opts.withPrefix,
6178
}, nil
6279
}
@@ -73,7 +90,7 @@ func (*EntryFormatter) Type() eventlogger.NodeType {
7390

7491
// Process will attempt to parse the incoming event data into a corresponding
7592
// audit Request/Response which is serialized to JSON/JSONx and stored within the event.
76-
func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (*eventlogger.Event, error) {
93+
func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (_ *eventlogger.Event, retErr error) {
7794
const op = "audit.(EntryFormatter).Process"
7895

7996
select {
@@ -95,6 +112,23 @@ func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (*ev
95112
return nil, fmt.Errorf("%s: cannot audit event (%s) with no data: %w", op, a.Subtype, event.ErrInvalidParameter)
96113
}
97114

115+
// Handle panics
116+
defer func() {
117+
r := recover()
118+
if r == nil {
119+
return
120+
}
121+
122+
f.logger.Error("panic during logging",
123+
"request_path", a.Data.Request.Path,
124+
"audit_device_path", f.name,
125+
"error", r,
126+
"stacktrace", string(debug.Stack()))
127+
128+
// Ensure that we add this error onto any pre-existing error that was being returned.
129+
retErr = multierror.Append(retErr, fmt.Errorf("%s: panic generating audit log: %q", op, f.name)).ErrorOrNil()
130+
}()
131+
98132
// Take a copy of the event data before we modify anything.
99133
data, err := a.Data.Clone()
100134
if err != nil {

‎audit/entry_formatter_test.go‎

Lines changed: 105 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,8 @@ import (
1313
"time"
1414

1515
"github.com/hashicorp/eventlogger"
16+
"github.com/hashicorp/go-hclog"
17+
"github.com/hashicorp/go-sockaddr"
1618
"github.com/hashicorp/vault/helper/namespace"
1719
"github.com/hashicorp/vault/internal/observability/event"
1820
"github.com/hashicorp/vault/sdk/helper/jsonutil"
@@ -62,49 +64,79 @@ func TestNewEntryFormatter(t *testing.T) {
6264
t.Parallel()
6365

6466
tests := map[string]struct {
67+
Name string
6568
UseStaticSalt bool
69+
Logger hclog.Logger
6670
Options []Option // Only supports WithPrefix
6771
IsErrorExpected bool
6872
ExpectedErrorMessage string
6973
ExpectedFormat format
7074
ExpectedPrefix string
7175
}{
76+
"empty-name": {
77+
Name: "",
78+
IsErrorExpected: true,
79+
ExpectedErrorMessage: "audit.NewEntryFormatter: name is required: invalid parameter",
80+
},
81+
"spacey-name": {
82+
Name: " ",
83+
IsErrorExpected: true,
84+
ExpectedErrorMessage: "audit.NewEntryFormatter: name is required: invalid parameter",
85+
},
7286
"nil-salter": {
87+
Name: "juan",
7388
UseStaticSalt: false,
7489
IsErrorExpected: true,
7590
ExpectedErrorMessage: "audit.NewEntryFormatter: cannot create a new audit formatter with nil salter: invalid parameter",
7691
},
92+
"nil-logger": {
93+
Name: "juan",
94+
UseStaticSalt: true,
95+
Logger: nil,
96+
IsErrorExpected: true,
97+
ExpectedErrorMessage: "audit.NewEntryFormatter: cannot create a new audit formatter with nil logger: invalid parameter",
98+
},
7799
"static-salter": {
100+
Name: "juan",
78101
UseStaticSalt: true,
102+
Logger: hclog.NewNullLogger(),
79103
IsErrorExpected: false,
80104
Options: []Option{
81105
WithFormat(JSONFormat.String()),
82106
},
83107
ExpectedFormat: JSONFormat,
84108
},
85109
"default": {
110+
Name: "juan",
86111
UseStaticSalt: true,
112+
Logger: hclog.NewNullLogger(),
87113
IsErrorExpected: false,
88114
ExpectedFormat: JSONFormat,
89115
},
90116
"config-json": {
117+
Name: "juan",
91118
UseStaticSalt: true,
119+
Logger: hclog.NewNullLogger(),
92120
Options: []Option{
93121
WithFormat(JSONFormat.String()),
94122
},
95123
IsErrorExpected: false,
96124
ExpectedFormat: JSONFormat,
97125
},
98126
"config-jsonx": {
127+
Name: "juan",
99128
UseStaticSalt: true,
129+
Logger: hclog.NewNullLogger(),
100130
Options: []Option{
101131
WithFormat(JSONxFormat.String()),
102132
},
103133
IsErrorExpected: false,
104134
ExpectedFormat: JSONxFormat,
105135
},
106136
"config-json-prefix": {
137+
Name: "juan",
107138
UseStaticSalt: true,
139+
Logger: hclog.NewNullLogger(),
108140
Options: []Option{
109141
WithPrefix("foo"),
110142
WithFormat(JSONFormat.String()),
@@ -114,7 +146,9 @@ func TestNewEntryFormatter(t *testing.T) {
114146
ExpectedPrefix: "foo",
115147
},
116148
"config-jsonx-prefix": {
149+
Name: "juan",
117150
UseStaticSalt: true,
151+
Logger: hclog.NewNullLogger(),
118152
Options: []Option{
119153
WithPrefix("foo"),
120154
WithFormat(JSONxFormat.String()),
@@ -137,7 +171,7 @@ func TestNewEntryFormatter(t *testing.T) {
137171

138172
cfg, err := NewFormatterConfig(tc.Options...)
139173
require.NoError(t, err)
140-
f, err := NewEntryFormatter(cfg, ss, tc.Options...)
174+
f, err := NewEntryFormatter(tc.Name, cfg, ss, tc.Logger, tc.Options...)
141175

142176
switch {
143177
case tc.IsErrorExpected:
@@ -162,7 +196,7 @@ func TestEntryFormatter_Reopen(t *testing.T) {
162196
cfg, err := NewFormatterConfig()
163197
require.NoError(t, err)
164198

165-
f, err := NewEntryFormatter(cfg, ss)
199+
f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
166200
require.NoError(t, err)
167201
require.NotNil(t, f)
168202
require.NoError(t, f.Reopen())
@@ -176,7 +210,7 @@ func TestEntryFormatter_Type(t *testing.T) {
176210
cfg, err := NewFormatterConfig()
177211
require.NoError(t, err)
178212

179-
f, err := NewEntryFormatter(cfg, ss)
213+
f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
180214
require.NoError(t, err)
181215
require.NotNil(t, f)
182216
require.Equal(t, eventlogger.NodeTypeFormatter, f.Type())
@@ -321,7 +355,7 @@ func TestEntryFormatter_Process(t *testing.T) {
321355
cfg, err := NewFormatterConfig(WithFormat(tc.RequiredFormat.String()))
322356
require.NoError(t, err)
323357

324-
f, err := NewEntryFormatter(cfg, ss)
358+
f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
325359
require.NoError(t, err)
326360
require.NotNil(t, f)
327361

@@ -386,7 +420,7 @@ func BenchmarkAuditFileSink_Process(b *testing.B) {
386420
cfg, err := NewFormatterConfig()
387421
require.NoError(b, err)
388422
ss := newStaticSalt(b)
389-
formatter, err := NewEntryFormatter(cfg, ss)
423+
formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
390424
require.NoError(b, err)
391425
require.NotNil(b, formatter)
392426

@@ -457,7 +491,7 @@ func TestEntryFormatter_FormatRequest(t *testing.T) {
457491
ss := newStaticSalt(t)
458492
cfg, err := NewFormatterConfig()
459493
require.NoError(t, err)
460-
f, err := NewEntryFormatter(cfg, ss)
494+
f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
461495
require.NoError(t, err)
462496

463497
var ctx context.Context
@@ -526,7 +560,7 @@ func TestEntryFormatter_FormatResponse(t *testing.T) {
526560
ss := newStaticSalt(t)
527561
cfg, err := NewFormatterConfig()
528562
require.NoError(t, err)
529-
f, err := NewEntryFormatter(cfg, ss)
563+
f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
530564
require.NoError(t, err)
531565

532566
var ctx context.Context
@@ -636,7 +670,7 @@ func TestEntryFormatter_Process_JSON(t *testing.T) {
636670
for name, tc := range cases {
637671
cfg, err := NewFormatterConfig(WithHMACAccessor(false))
638672
require.NoError(t, err)
639-
formatter, err := NewEntryFormatter(cfg, ss, WithPrefix(tc.Prefix))
673+
formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger(), WithPrefix(tc.Prefix))
640674
require.NoError(t, err)
641675

642676
in := &logical.LogInput{
@@ -797,7 +831,7 @@ func TestEntryFormatter_Process_JSONx(t *testing.T) {
797831
WithFormat(JSONxFormat.String()),
798832
)
799833
require.NoError(t, err)
800-
formatter, err := NewEntryFormatter(cfg, tempStaticSalt, WithPrefix(tc.Prefix))
834+
formatter, err := NewEntryFormatter("juan", cfg, tempStaticSalt, hclog.NewNullLogger(), WithPrefix(tc.Prefix))
801835
require.NoError(t, err)
802836
require.NotNil(t, formatter)
803837

@@ -913,7 +947,7 @@ func TestEntryFormatter_FormatResponse_ElideListResponses(t *testing.T) {
913947
var err error
914948

915949
format := func(t *testing.T, config FormatterConfig, operation logical.Operation, inputData map[string]any) *ResponseEntry {
916-
formatter, err = NewEntryFormatter(config, ss)
950+
formatter, err = NewEntryFormatter("juan", config, ss, hclog.NewNullLogger())
917951
require.NoError(t, err)
918952
require.NotNil(t, formatter)
919953

@@ -975,7 +1009,7 @@ func TestEntryFormatter_Process_NoMutation(t *testing.T) {
9751009
cfg, err := NewFormatterConfig()
9761010
require.NoError(t, err)
9771011
ss := newStaticSalt(t)
978-
formatter, err := NewEntryFormatter(cfg, ss)
1012+
formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
9791013
require.NoError(t, err)
9801014
require.NotNil(t, formatter)
9811015

@@ -1025,6 +1059,66 @@ func TestEntryFormatter_Process_NoMutation(t *testing.T) {
10251059
require.NotEqual(t, a2, a)
10261060
}
10271061

1062+
// TestEntryFormatter_Process_Panic tries to send data into the EntryFormatter
1063+
// which will currently cause a panic when a response is formatted due to the
1064+
// underlying hashing that is done with reflectwalk.
1065+
func TestEntryFormatter_Process_Panic(t *testing.T) {
1066+
t.Parallel()
1067+
1068+
// Create the formatter node.
1069+
cfg, err := NewFormatterConfig()
1070+
require.NoError(t, err)
1071+
ss := newStaticSalt(t)
1072+
formatter, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
1073+
require.NoError(t, err)
1074+
require.NotNil(t, formatter)
1075+
1076+
// The secret sauce, create a bad addr.
1077+
// see: https://github.com/hashicorp/vault/issues/16462
1078+
badAddr, err := sockaddr.NewSockAddr("10.10.10.2/32 10.10.10.3/32")
1079+
require.NoError(t, err)
1080+
1081+
in := &logical.LogInput{
1082+
Auth: &logical.Auth{
1083+
ClientToken: "foo",
1084+
Accessor: "bar",
1085+
EntityID: "foobarentity",
1086+
DisplayName: "testtoken",
1087+
NoDefaultPolicy: true,
1088+
Policies: []string{"root"},
1089+
TokenType: logical.TokenTypeService,
1090+
},
1091+
Request: &logical.Request{
1092+
Operation: logical.UpdateOperation,
1093+
Path: "/foo",
1094+
Connection: &logical.Connection{
1095+
RemoteAddr: "127.0.0.1",
1096+
},
1097+
WrapInfo: &logical.RequestWrapInfo{
1098+
TTL: 60 * time.Second,
1099+
},
1100+
Headers: map[string][]string{
1101+
"foo": {"bar"},
1102+
},
1103+
Data: map[string]interface{}{},
1104+
},
1105+
Response: &logical.Response{
1106+
Data: map[string]any{
1107+
"token_bound_cidrs": []*sockaddr.SockAddrMarshaler{
1108+
{SockAddr: badAddr},
1109+
},
1110+
},
1111+
},
1112+
}
1113+
1114+
e := fakeEvent(t, ResponseType, in)
1115+
1116+
e2, err := formatter.Process(namespace.RootContext(nil), e)
1117+
require.Error(t, err)
1118+
require.Contains(t, err.Error(), "audit.(EntryFormatter).Process: panic generating audit log: \"juan\"")
1119+
require.Nil(t, e2)
1120+
}
1121+
10281122
// hashExpectedValueForComparison replicates enough of the audit HMAC process on a piece of expected data in a test,
10291123
// so that we can use assert.Equal to compare the expected and output values.
10301124
func (f *EntryFormatter) hashExpectedValueForComparison(input map[string]any) map[string]any {

‎audit/types.go‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@ package audit
66
import (
77
"context"
88

9+
"github.com/hashicorp/go-hclog"
910
"github.com/hashicorp/vault/internal/observability/event"
1011
"github.com/hashicorp/vault/sdk/helper/salt"
1112
"github.com/hashicorp/vault/sdk/logical"
@@ -231,6 +232,9 @@ type BackendConfig struct {
231232

232233
// MountPath is the path where this Backend is mounted
233234
MountPath string
235+
236+
// Logger is used to emit log messages usually captured in the server logs.
237+
Logger hclog.Logger
234238
}
235239

236240
// Factory is the factory function to create an audit backend.

0 commit comments

Comments
 (0)