Skip to content

Commit b061606

Browse files
peteski22peteski22
authored
Audit: logging and improvements (#28056)
* Add trace logging to context creation during log req/resp. Improve context sensitivity of sink nodes (file, socket), update eventlogger to include context info in error * changelog * Queue for the lock but check context immediately * fix race in test
1 parent bf0e156 commit b061606

File tree

8 files changed

+94
-17
lines changed

8 files changed

+94
-17
lines changed

‎audit/broker.go

+4
Original file line numberDiff line numberDiff line change
@@ -297,6 +297,8 @@ func (b *Broker) LogRequest(ctx context.Context, in *logical.LogInput) (retErr e
297297
tempContext, auditCancel := context.WithTimeout(context.Background(), timeout)
298298
defer auditCancel()
299299
auditContext = nshelper.ContextWithNamespace(tempContext, ns)
300+
301+
b.logger.Trace("log request requires a derived context (original context was not viable)", "namespace ID", ns.ID, "namespace path", ns.Path, "timeout", timeout)
300302
}
301303

302304
var status eventlogger.Status
@@ -379,6 +381,8 @@ func (b *Broker) LogResponse(ctx context.Context, in *logical.LogInput) (retErr
379381
tempContext, auditCancel := context.WithTimeout(context.Background(), timeout)
380382
defer auditCancel()
381383
auditContext = nshelper.ContextWithNamespace(tempContext, ns)
384+
385+
b.logger.Trace("log response requires a derived context (original context was not viable)", "namespace ID", ns.ID, "namespace path", ns.Path, "timeout", timeout)
382386
}
383387

384388
var status eventlogger.Status

‎audit/sink_metric_labeler.go

+1
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ type metricLabelerAuditSink struct{}
2424
// Failure: 'vault.audit.sink.failure'
2525
func (m metricLabelerAuditSink) Labels(_ *eventlogger.Event, err error) []string {
2626
if err != nil {
27+
// NOTE: a cancelled context would still result in an error.
2728
return metricLabelAuditSinkFailure
2829
}
2930

‎changelog/28056.txt

+3
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,3 @@
1+
```release-note:improvement
2+
audit: Adds TRACE logging to log request/response under certain circumstances, and further improvements to the audit subsystem.
3+
```

‎go.mod

+2-2
Original file line numberDiff line numberDiff line change
@@ -62,7 +62,7 @@ require (
6262
github.com/go-jose/go-jose/v3 v3.0.3
6363
github.com/go-ldap/ldap/v3 v3.4.8
6464
github.com/go-sql-driver/mysql v1.7.1
65-
github.com/go-test/deep v1.1.0
65+
github.com/go-test/deep v1.1.1
6666
github.com/go-zookeeper/zk v1.0.3
6767
github.com/gocql/gocql v1.0.0
6868
github.com/golang-jwt/jwt/v4 v4.5.0
@@ -78,7 +78,7 @@ require (
7878
github.com/hashicorp/consul-template v0.39.1
7979
github.com/hashicorp/consul/api v1.29.1
8080
github.com/hashicorp/errwrap v1.1.0
81-
github.com/hashicorp/eventlogger v0.2.9
81+
github.com/hashicorp/eventlogger v0.2.10
8282
github.com/hashicorp/go-bexpr v0.1.12
8383
github.com/hashicorp/go-cleanhttp v0.5.2
8484
github.com/hashicorp/go-discover v0.0.0-20210818145131-c573d69da192

‎go.sum

+4-12
Original file line numberDiff line numberDiff line change
@@ -1161,9 +1161,8 @@ github.com/go-task/slim-sprig v0.0.0-20210107165309-348f09dbbbc0/go.mod h1:fyg78
11611161
github.com/go-task/slim-sprig v0.0.0-20230315185526-52ccab3ef572 h1:tfuBGBXKqDEevZMzYi5KSi8KkcZtzBcTgAUUtapy0OI=
11621162
github.com/go-task/slim-sprig v0.0.0-20230315185526-52ccab3ef572/go.mod h1:9Pwr4B2jHnOSGXyyzV8ROjYa2ojvAY6HCGYYfMoC3Ls=
11631163
github.com/go-test/deep v1.0.2/go.mod h1:wGDj63lr65AM2AQyKZd/NYHGb0R+1RLqB8NKt3aSFNA=
1164-
github.com/go-test/deep v1.0.4/go.mod h1:wGDj63lr65AM2AQyKZd/NYHGb0R+1RLqB8NKt3aSFNA=
1165-
github.com/go-test/deep v1.1.0 h1:WOcxcdHcvdgThNXjw0t76K42FXTU7HpNQWHpA2HHNlg=
1166-
github.com/go-test/deep v1.1.0/go.mod h1:5C2ZWiW0ErCdrYzpqxLbTX7MG14M9iiw8DgHncVwcsE=
1164+
github.com/go-test/deep v1.1.1 h1:0r/53hagsehfO4bzD2Pgr/+RgHqhmf+k1Bpse2cTu1U=
1165+
github.com/go-test/deep v1.1.1/go.mod h1:5C2ZWiW0ErCdrYzpqxLbTX7MG14M9iiw8DgHncVwcsE=
11671166
github.com/go-zookeeper/zk v1.0.3 h1:7M2kwOsc//9VeeFiPtf+uSJlVpU66x9Ba5+8XK7/TDg=
11681167
github.com/go-zookeeper/zk v1.0.3/go.mod h1:nOB03cncLtlp4t+UAkGSV+9beXP/akpekBwL+UX1Qcw=
11691168
github.com/goccy/go-json v0.9.11/go.mod h1:6MelG93GURQebXPDq3khkgXZkazVtN9CRI+MGFi0w8I=
@@ -1391,8 +1390,8 @@ github.com/hashicorp/cronexpr v1.1.2/go.mod h1:P4wA0KBl9C5q2hABiMO7cp6jcIg96CDh1
13911390
github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
13921391
github.com/hashicorp/errwrap v1.1.0 h1:OxrOeh75EUXMY8TBjag2fzXGZ40LB6IKw45YeGUDY2I=
13931392
github.com/hashicorp/errwrap v1.1.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
1394-
github.com/hashicorp/eventlogger v0.2.9 h1:QO8hPXNngadMp72FVNTwIduLAG9fcLP7t59bSFd7gDY=
1395-
github.com/hashicorp/eventlogger v0.2.9/go.mod h1://CHt6/j+Q2lc0NlUB5af4aS2M0c0aVBg9/JfcpAyhM=
1393+
github.com/hashicorp/eventlogger v0.2.10 h1:Dddth3KVSribGE1rInGToM30tRNblvL0G1OG6N+i2pk=
1394+
github.com/hashicorp/eventlogger v0.2.10/go.mod h1:imHMTfJH4qfb8Knh9nZw4iLfL9J1bX6TJKEurSB4t+U=
13961395
github.com/hashicorp/go-bexpr v0.1.12 h1:XrdVhmwu+9iYxIUWxsGVG7NQwrhzJZ0vR6nbN5bLgrA=
13971396
github.com/hashicorp/go-bexpr v0.1.12/go.mod h1:ACktpcSySkFNpcxWSClFrut7wicd9WzisnvHuw+g9K8=
13981397
github.com/hashicorp/go-cleanhttp v0.5.0/go.mod h1:JpRdi6/HCYpAwUzNwuwqhbovhLtngrth3wmdIIUrZ80=
@@ -1456,7 +1455,6 @@ github.com/hashicorp/go-rootcerts v1.0.2 h1:jzhAVGtqPKbwpyCPELlgNWhE1znq+qwJtW5O
14561455
github.com/hashicorp/go-rootcerts v1.0.2/go.mod h1:pqUvnprVnM5bf7AOirdbb01K4ccR319Vf4pU3K5EGc8=
14571456
github.com/hashicorp/go-secure-stdlib/awsutil v0.3.0 h1:I8bynUKMh9I7JdwtW9voJ0xmHvBpxQtLjrMFDYmhOxY=
14581457
github.com/hashicorp/go-secure-stdlib/awsutil v0.3.0/go.mod h1:oKHSQs4ivIfZ3fbXGQOop1XuDfdSb8RIsWTGaAanSfg=
1459-
github.com/hashicorp/go-secure-stdlib/base62 v0.1.1/go.mod h1:EdWO6czbmthiwZ3/PUsDV+UD1D5IRU4ActiaWGwt0Yw=
14601458
github.com/hashicorp/go-secure-stdlib/base62 v0.1.2 h1:ET4pqyjiGmY09R5y+rSd70J2w45CtbWDNvGqWp/R3Ng=
14611459
github.com/hashicorp/go-secure-stdlib/base62 v0.1.2/go.mod h1:EdWO6czbmthiwZ3/PUsDV+UD1D5IRU4ActiaWGwt0Yw=
14621460
github.com/hashicorp/go-secure-stdlib/fileutil v0.1.0 h1:f2mwVgMJjXuX/+eWD6ZW30+oIRgCofL+XMWknFkB1WM=
@@ -1479,7 +1477,6 @@ github.com/hashicorp/go-secure-stdlib/plugincontainer v0.3.0 h1:KMWpBsC65ZBXDpox
14791477
github.com/hashicorp/go-secure-stdlib/plugincontainer v0.3.0/go.mod h1:qKYwSZ2EOpppko5ud+Sh9TrUgiTAZSaQCr8XWIYXsbM=
14801478
github.com/hashicorp/go-secure-stdlib/reloadutil v0.1.1 h1:SMGUnbpAcat8rIKHkBPjfv81yC46a8eCNZ2hsR2l1EI=
14811479
github.com/hashicorp/go-secure-stdlib/reloadutil v0.1.1/go.mod h1:Ch/bf00Qnx77MZd49JRgHYqHQjtEmTgGU2faufpVZb0=
1482-
github.com/hashicorp/go-secure-stdlib/strutil v0.1.1/go.mod h1:gKOamz3EwoIoJq7mlMIRBpVTAUn8qPCrEclOKKWhD3U=
14831480
github.com/hashicorp/go-secure-stdlib/strutil v0.1.2 h1:kes8mmyCpxJsI7FTwtzRqEy9CdjCtrXrXGuOpxEA7Ts=
14841481
github.com/hashicorp/go-secure-stdlib/strutil v0.1.2/go.mod h1:Gou2R9+il93BqX25LAKCLuM+y9U2T4hlwvT1yprcna4=
14851482
github.com/hashicorp/go-secure-stdlib/tlsutil v0.1.3 h1:xbrxd0U9XQW8qL1BAz2XrAjAF/P2vcqUTAues9c24B8=
@@ -1756,7 +1753,6 @@ github.com/konsorten/go-windows-terminal-sequences v1.0.2/go.mod h1:T0+1ngSBFLxv
17561753
github.com/kr/fs v0.1.0/go.mod h1:FFnZGqtBN9Gxj7eW1uZ42v5BccTP0vu6NEaFoC2HwRg=
17571754
github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
17581755
github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
1759-
github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
17601756
github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
17611757
github.com/kr/pretty v0.3.0/go.mod h1:640gp4NfQd8pI5XOwp5fnNeVWj67G7CFk/SaSQn7NBk=
17621758
github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE=
@@ -2037,7 +2033,6 @@ github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6So
20372033
github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ=
20382034
github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
20392035
github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc=
2040-
github.com/rogpeppe/go-internal v1.6.2/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc=
20412036
github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs=
20422037
github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8=
20432038
github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4=
@@ -2257,7 +2252,6 @@ go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
22572252
go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
22582253
go.uber.org/atomic v1.11.0 h1:ZvwS0R+56ePWxUNi+Atn9dWONBPp/AUETXlHW0DxSjE=
22592254
go.uber.org/atomic v1.11.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0=
2260-
go.uber.org/goleak v1.0.0/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
22612255
go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
22622256
go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto=
22632257
go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE=
@@ -2728,7 +2722,6 @@ golang.org/x/tools v0.0.0-20201124115921-2c860bdd6e78/go.mod h1:emZCQorbCU4vsT4f
27282722
golang.org/x/tools v0.0.0-20201201161351-ac6f37ff4c2a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
27292723
golang.org/x/tools v0.0.0-20201208233053-a543418bbed2/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
27302724
golang.org/x/tools v0.0.0-20201224043029-2b0845dc783e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
2731-
golang.org/x/tools v0.0.0-20210101214203-2dba1e4ea05c/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
27322725
golang.org/x/tools v0.0.0-20210105154028-b0ab187a4818/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
27332726
golang.org/x/tools v0.0.0-20210106214847-113979e3529a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
27342727
golang.org/x/tools v0.0.0-20210108195828-e2f9c7f1fc8e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
@@ -3156,7 +3149,6 @@ modernc.org/strutil v1.1.3/go.mod h1:MEHNA7PdEnEwLvspRMtWTNnp2nnyvMfkimT1NKNAGbw
31563149
modernc.org/tcl v1.13.1/go.mod h1:XOLfOwzhkljL4itZkK6T72ckMgvj0BDsnKNdZVUOecw=
31573150
modernc.org/token v1.0.0/go.mod h1:UGzOrNV1mAFSEB63lOFHIpNRUVMvYTc6yu1SMY/XTDM=
31583151
modernc.org/z v1.5.1/go.mod h1:eWFB510QWW5Th9YGZT81s+LwvaAs3Q2yr4sP0rmLkv8=
3159-
mvdan.cc/gofumpt v0.1.1/go.mod h1:yXG1r1WqZVKWbVRtBWKWX9+CxGYfA51nSomhM0woR48=
31603152
nhooyr.io/websocket v1.8.11 h1:f/qXNc2/3DpoSZkHt1DQu6rj4zGC8JmkkLkWss0MgN0=
31613153
nhooyr.io/websocket v1.8.11/go.mod h1:rN9OFWIUwuxg4fR5tELlYC04bXYowCP9GX47ivo2l+c=
31623154
rsc.io/binaryregexp v0.2.0/go.mod h1:qTv7/COck+e2FymRvadv62gMdZztPaShugOCi3I+8D8=

‎internal/observability/event/sink_file.go

+11-3
Original file line numberDiff line numberDiff line change
@@ -115,7 +115,7 @@ func (s *FileSink) Process(ctx context.Context, e *eventlogger.Event) (_ *eventl
115115
return nil, fmt.Errorf("unable to retrieve event formatted as %q: %w", s.requiredFormat, ErrInvalidParameter)
116116
}
117117

118-
err := s.log(formatted)
118+
err := s.log(ctx, formatted)
119119
if err != nil {
120120
return nil, fmt.Errorf("error writing file for sink %q: %w", s.path, err)
121121
}
@@ -189,10 +189,18 @@ func (s *FileSink) open() error {
189189
}
190190

191191
// log writes the buffer to the file.
192-
// It acquires a lock on the file to do this.
193-
func (s *FileSink) log(data []byte) error {
192+
// NOTE: We attempt to acquire a lock on the file in order to write, but will
193+
// yield if the context is 'done'.
194+
func (s *FileSink) log(ctx context.Context, data []byte) error {
195+
// Wait for the lock, but ensure we check for a cancelled context as soon as
196+
// we have it, as there's no point in continuing if we're cancelled.
194197
s.fileLock.Lock()
195198
defer s.fileLock.Unlock()
199+
select {
200+
case <-ctx.Done():
201+
return ctx.Err()
202+
default:
203+
}
196204

197205
reader := bytes.NewReader(data)
198206

‎internal/observability/event/sink_file_test.go

+55
Original file line numberDiff line numberDiff line change
@@ -4,13 +4,18 @@
44
package event
55

66
import (
7+
"context"
8+
"errors"
9+
"fmt"
710
"os"
811
"path/filepath"
12+
"sync/atomic"
913
"testing"
1014
"time"
1115

1216
"github.com/hashicorp/eventlogger"
1317
"github.com/hashicorp/vault/helper/namespace"
18+
"github.com/hashicorp/vault/helper/testhelpers/corehelpers"
1419
"github.com/stretchr/testify/require"
1520
)
1621

@@ -236,6 +241,13 @@ func TestFileSink_Process(t *testing.T) {
236241
IsErrorExpected: true,
237242
ExpectedErrorMessage: "event is nil: invalid parameter",
238243
},
244+
"happy-path": {
245+
Path: "juan.log",
246+
ShouldCreateFile: true,
247+
Format: "json",
248+
Data: "{\"foo\": \"bar\"}",
249+
IsErrorExpected: false,
250+
},
239251
}
240252

241253
for name, tc := range tests {
@@ -297,3 +309,46 @@ func TestFileSink_Process(t *testing.T) {
297309
})
298310
}
299311
}
312+
313+
// TestFileSink_log_cancelledContext tests that 'log' is context aware and won't
314+
// just wait for the lock on the file sink forever.
315+
func TestFileSink_log_cancelledContext(t *testing.T) {
316+
tempDir := t.TempDir()
317+
tempPath := filepath.Join(tempDir, "juan.log")
318+
data := []byte("{\"foo\": \"bar\"}")
319+
320+
sink, err := NewFileSink(tempPath, "json")
321+
require.NoError(t, err)
322+
require.NotNil(t, sink)
323+
324+
ctx, cancel := context.WithCancel(context.Background())
325+
t.Cleanup(func() { cancel() })
326+
327+
// Manually acquire the lock so that the 'log' method cannot.
328+
sink.fileLock.Lock()
329+
330+
var done atomic.Bool
331+
go func() {
332+
err = sink.log(ctx, data)
333+
done.Store(true)
334+
}()
335+
336+
// We shouldn't have an error as 'log' will be trying to acquire the lock.
337+
require.NoError(t, err)
338+
339+
// Manually cancel the context and unlock to let the waiting 'log' in.
340+
cancel()
341+
sink.fileLock.Unlock()
342+
343+
// Just a little bit of time to make sure that 'log' returned and err was set.
344+
corehelpers.RetryUntil(t, 3*time.Second, func() error {
345+
if done.Load() {
346+
return nil
347+
}
348+
349+
return fmt.Errorf("logging still not done")
350+
})
351+
352+
// We expect that the error now has context cancelled in it.
353+
require.True(t, errors.Is(err, context.Canceled))
354+
}

‎internal/observability/event/sink_socket.go

+14
Original file line numberDiff line numberDiff line change
@@ -86,8 +86,15 @@ func (s *SocketSink) Process(ctx context.Context, e *eventlogger.Event) (_ *even
8686
return nil, fmt.Errorf("unable to retrieve event formatted as %q: %w", s.requiredFormat, ErrInvalidParameter)
8787
}
8888

89+
// Wait for the lock, but ensure we check for a cancelled context as soon as
90+
// we have it, as there's no point in continuing if we're cancelled.
8991
s.socketLock.Lock()
9092
defer s.socketLock.Unlock()
93+
select {
94+
case <-ctx.Done():
95+
return nil, ctx.Err()
96+
default:
97+
}
9198

9299
// Try writing and return early if successful.
93100
err := s.write(ctx, formatted)
@@ -133,7 +140,14 @@ func (_ *SocketSink) Type() eventlogger.NodeType {
133140
}
134141

135142
// connect attempts to establish a connection using the socketType and address.
143+
// NOTE: connect is context aware and will not attempt to connect if the context is 'done'.
136144
func (s *SocketSink) connect(ctx context.Context) error {
145+
select {
146+
case <-ctx.Done():
147+
return ctx.Err()
148+
default:
149+
}
150+
137151
// If we're already connected, we should have disconnected first.
138152
if s.connection != nil {
139153
return nil

0 commit comments

Comments
 (0)