Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Audit: logging and improvements #28056

Merged
merged 4 commits into from
Aug 12, 2024
Merged

Audit: logging and improvements #28056

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
758f2d2
Add trace logging to context creation during log req/resp. Improve co…
Aug 12, 2024
d2b7bf2
changelog
Aug 12, 2024
80101d9
Queue for the lock but check context immediately
Aug 12, 2024
c4045dc
fix race in test
Aug 12, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions audit/broker.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -297,6 +297,8 @@ func (b *Broker) LogRequest(ctx context.Context, in *logical.LogInput) (retErr e
tempContext, auditCancel := context.WithTimeout(context.Background(), timeout)
defer auditCancel()
auditContext = nshelper.ContextWithNamespace(tempContext, ns)

b.logger.Trace("log request requires a derived context (original context was not viable)", "namespace ID", ns.ID, "namespace path", ns.Path, "timeout", timeout)
}

var status eventlogger.Status
Expand Down Expand Up @@ -379,6 +381,8 @@ func (b *Broker) LogResponse(ctx context.Context, in *logical.LogInput) (retErr
tempContext, auditCancel := context.WithTimeout(context.Background(), timeout)
defer auditCancel()
auditContext = nshelper.ContextWithNamespace(tempContext, ns)

b.logger.Trace("log response requires a derived context (original context was not viable)", "namespace ID", ns.ID, "namespace path", ns.Path, "timeout", timeout)
}

var status eventlogger.Status
Expand Down
1 change: 1 addition & 0 deletions audit/sink_metric_labeler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ type metricLabelerAuditSink struct{}
// Failure: 'vault.audit.sink.failure'
func (m metricLabelerAuditSink) Labels(_ *eventlogger.Event, err error) []string {
if err != nil {
// NOTE: a cancelled context would still result in an error.
return metricLabelAuditSinkFailure
}

Expand Down
3 changes: 3 additions & 0 deletions changelog/28056.txt
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,3 @@
```release-note:improvement
audit: Adds TRACE logging to log request/response under certain circumstances, and further improvements to the audit subsystem.
```
4 changes: 2 additions & 2 deletions go.mod
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ require (
github.com/go-jose/go-jose/v3 v3.0.3
github.com/go-ldap/ldap/v3 v3.4.8
github.com/go-sql-driver/mysql v1.7.1
github.com/go-test/deep v1.1.0
github.com/go-test/deep v1.1.1
github.com/go-zookeeper/zk v1.0.3
github.com/gocql/gocql v1.0.0
github.com/golang-jwt/jwt/v4 v4.5.0
Expand All @@ -78,7 +78,7 @@ require (
github.com/hashicorp/consul-template v0.39.1
github.com/hashicorp/consul/api v1.29.1
github.com/hashicorp/errwrap v1.1.0
github.com/hashicorp/eventlogger v0.2.9
github.com/hashicorp/eventlogger v0.2.10
github.com/hashicorp/go-bexpr v0.1.12
github.com/hashicorp/go-cleanhttp v0.5.2
github.com/hashicorp/go-discover v0.0.0-20210818145131-c573d69da192
Expand Down
16 changes: 4 additions & 12 deletions go.sum
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1161,9 +1161,8 @@ github.com/go-task/slim-sprig v0.0.0-20210107165309-348f09dbbbc0/go.mod h1:fyg78
github.com/go-task/slim-sprig v0.0.0-20230315185526-52ccab3ef572 h1:tfuBGBXKqDEevZMzYi5KSi8KkcZtzBcTgAUUtapy0OI=
github.com/go-task/slim-sprig v0.0.0-20230315185526-52ccab3ef572/go.mod h1:9Pwr4B2jHnOSGXyyzV8ROjYa2ojvAY6HCGYYfMoC3Ls=
github.com/go-test/deep v1.0.2/go.mod h1:wGDj63lr65AM2AQyKZd/NYHGb0R+1RLqB8NKt3aSFNA=
github.com/go-test/deep v1.0.4/go.mod h1:wGDj63lr65AM2AQyKZd/NYHGb0R+1RLqB8NKt3aSFNA=
github.com/go-test/deep v1.1.0 h1:WOcxcdHcvdgThNXjw0t76K42FXTU7HpNQWHpA2HHNlg=
github.com/go-test/deep v1.1.0/go.mod h1:5C2ZWiW0ErCdrYzpqxLbTX7MG14M9iiw8DgHncVwcsE=
github.com/go-test/deep v1.1.1 h1:0r/53hagsehfO4bzD2Pgr/+RgHqhmf+k1Bpse2cTu1U=
github.com/go-test/deep v1.1.1/go.mod h1:5C2ZWiW0ErCdrYzpqxLbTX7MG14M9iiw8DgHncVwcsE=
github.com/go-zookeeper/zk v1.0.3 h1:7M2kwOsc//9VeeFiPtf+uSJlVpU66x9Ba5+8XK7/TDg=
github.com/go-zookeeper/zk v1.0.3/go.mod h1:nOB03cncLtlp4t+UAkGSV+9beXP/akpekBwL+UX1Qcw=
github.com/goccy/go-json v0.9.11/go.mod h1:6MelG93GURQebXPDq3khkgXZkazVtN9CRI+MGFi0w8I=
Expand Down Expand Up @@ -1391,8 +1390,8 @@ github.com/hashicorp/cronexpr v1.1.2/go.mod h1:P4wA0KBl9C5q2hABiMO7cp6jcIg96CDh1
github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
github.com/hashicorp/errwrap v1.1.0 h1:OxrOeh75EUXMY8TBjag2fzXGZ40LB6IKw45YeGUDY2I=
github.com/hashicorp/errwrap v1.1.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
github.com/hashicorp/eventlogger v0.2.9 h1:QO8hPXNngadMp72FVNTwIduLAG9fcLP7t59bSFd7gDY=
github.com/hashicorp/eventlogger v0.2.9/go.mod h1://CHt6/j+Q2lc0NlUB5af4aS2M0c0aVBg9/JfcpAyhM=
github.com/hashicorp/eventlogger v0.2.10 h1:Dddth3KVSribGE1rInGToM30tRNblvL0G1OG6N+i2pk=
github.com/hashicorp/eventlogger v0.2.10/go.mod h1:imHMTfJH4qfb8Knh9nZw4iLfL9J1bX6TJKEurSB4t+U=
github.com/hashicorp/go-bexpr v0.1.12 h1:XrdVhmwu+9iYxIUWxsGVG7NQwrhzJZ0vR6nbN5bLgrA=
github.com/hashicorp/go-bexpr v0.1.12/go.mod h1:ACktpcSySkFNpcxWSClFrut7wicd9WzisnvHuw+g9K8=
github.com/hashicorp/go-cleanhttp v0.5.0/go.mod h1:JpRdi6/HCYpAwUzNwuwqhbovhLtngrth3wmdIIUrZ80=
Expand Down Expand Up @@ -1456,7 +1455,6 @@ github.com/hashicorp/go-rootcerts v1.0.2 h1:jzhAVGtqPKbwpyCPELlgNWhE1znq+qwJtW5O
github.com/hashicorp/go-rootcerts v1.0.2/go.mod h1:pqUvnprVnM5bf7AOirdbb01K4ccR319Vf4pU3K5EGc8=
github.com/hashicorp/go-secure-stdlib/awsutil v0.3.0 h1:I8bynUKMh9I7JdwtW9voJ0xmHvBpxQtLjrMFDYmhOxY=
github.com/hashicorp/go-secure-stdlib/awsutil v0.3.0/go.mod h1:oKHSQs4ivIfZ3fbXGQOop1XuDfdSb8RIsWTGaAanSfg=
github.com/hashicorp/go-secure-stdlib/base62 v0.1.1/go.mod h1:EdWO6czbmthiwZ3/PUsDV+UD1D5IRU4ActiaWGwt0Yw=
github.com/hashicorp/go-secure-stdlib/base62 v0.1.2 h1:ET4pqyjiGmY09R5y+rSd70J2w45CtbWDNvGqWp/R3Ng=
github.com/hashicorp/go-secure-stdlib/base62 v0.1.2/go.mod h1:EdWO6czbmthiwZ3/PUsDV+UD1D5IRU4ActiaWGwt0Yw=
github.com/hashicorp/go-secure-stdlib/fileutil v0.1.0 h1:f2mwVgMJjXuX/+eWD6ZW30+oIRgCofL+XMWknFkB1WM=
Expand All @@ -1479,7 +1477,6 @@ github.com/hashicorp/go-secure-stdlib/plugincontainer v0.3.0 h1:KMWpBsC65ZBXDpox
github.com/hashicorp/go-secure-stdlib/plugincontainer v0.3.0/go.mod h1:qKYwSZ2EOpppko5ud+Sh9TrUgiTAZSaQCr8XWIYXsbM=
github.com/hashicorp/go-secure-stdlib/reloadutil v0.1.1 h1:SMGUnbpAcat8rIKHkBPjfv81yC46a8eCNZ2hsR2l1EI=
github.com/hashicorp/go-secure-stdlib/reloadutil v0.1.1/go.mod h1:Ch/bf00Qnx77MZd49JRgHYqHQjtEmTgGU2faufpVZb0=
github.com/hashicorp/go-secure-stdlib/strutil v0.1.1/go.mod h1:gKOamz3EwoIoJq7mlMIRBpVTAUn8qPCrEclOKKWhD3U=
github.com/hashicorp/go-secure-stdlib/strutil v0.1.2 h1:kes8mmyCpxJsI7FTwtzRqEy9CdjCtrXrXGuOpxEA7Ts=
github.com/hashicorp/go-secure-stdlib/strutil v0.1.2/go.mod h1:Gou2R9+il93BqX25LAKCLuM+y9U2T4hlwvT1yprcna4=
github.com/hashicorp/go-secure-stdlib/tlsutil v0.1.3 h1:xbrxd0U9XQW8qL1BAz2XrAjAF/P2vcqUTAues9c24B8=
Expand Down Expand Up @@ -1756,7 +1753,6 @@ github.com/konsorten/go-windows-terminal-sequences v1.0.2/go.mod h1:T0+1ngSBFLxv
github.com/kr/fs v0.1.0/go.mod h1:FFnZGqtBN9Gxj7eW1uZ42v5BccTP0vu6NEaFoC2HwRg=
github.com/kr/logfmt v0.0.0-20140226030751-b84e30acd515/go.mod h1:+0opPa2QZZtGFBFZlji/RkVcI2GknAs/DXo4wKdlNEc=
github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
github.com/kr/pretty v0.2.0/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI=
github.com/kr/pretty v0.3.0/go.mod h1:640gp4NfQd8pI5XOwp5fnNeVWj67G7CFk/SaSQn7NBk=
github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE=
Expand Down Expand Up @@ -2037,7 +2033,6 @@ github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6So
github.com/rogpeppe/fastuuid v1.2.0/go.mod h1:jVj6XXZzXRy/MSR5jhDC/2q6DgLz+nrA6LYCDYWNEvQ=
github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
github.com/rogpeppe/go-internal v1.6.1/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc=
github.com/rogpeppe/go-internal v1.6.2/go.mod h1:xXDCJY+GAPziupqXw64V24skbSoqbTEfhy4qGm1nDQc=
github.com/rogpeppe/go-internal v1.9.0/go.mod h1:WtVeX8xhTBvf0smdhujwtBcq4Qrzq/fJaraNFVN+nFs=
github.com/rogpeppe/go-internal v1.12.0 h1:exVL4IDcn6na9z1rAb56Vxr+CgyK3nn3O+epU5NdKM8=
github.com/rogpeppe/go-internal v1.12.0/go.mod h1:E+RYuTGaKKdloAfM02xzb0FW3Paa99yedzYV+kq4uf4=
Expand Down Expand Up @@ -2257,7 +2252,6 @@ go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
go.uber.org/atomic v1.11.0 h1:ZvwS0R+56ePWxUNi+Atn9dWONBPp/AUETXlHW0DxSjE=
go.uber.org/atomic v1.11.0/go.mod h1:LUxbIzbOniOlMKjJjyPfpl4v+PKK2cNJn91OQbhoJI0=
go.uber.org/goleak v1.0.0/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto=
go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE=
Expand Down Expand Up @@ -2728,7 +2722,6 @@ golang.org/x/tools v0.0.0-20201124115921-2c860bdd6e78/go.mod h1:emZCQorbCU4vsT4f
golang.org/x/tools v0.0.0-20201201161351-ac6f37ff4c2a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20201208233053-a543418bbed2/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20201224043029-2b0845dc783e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20210101214203-2dba1e4ea05c/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20210105154028-b0ab187a4818/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20210106214847-113979e3529a/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
golang.org/x/tools v0.0.0-20210108195828-e2f9c7f1fc8e/go.mod h1:emZCQorbCU4vsT4fOWvOPXz4eW1wZW4PmDk9uLelYpA=
Expand Down Expand Up @@ -3156,7 +3149,6 @@ modernc.org/strutil v1.1.3/go.mod h1:MEHNA7PdEnEwLvspRMtWTNnp2nnyvMfkimT1NKNAGbw
modernc.org/tcl v1.13.1/go.mod h1:XOLfOwzhkljL4itZkK6T72ckMgvj0BDsnKNdZVUOecw=
modernc.org/token v1.0.0/go.mod h1:UGzOrNV1mAFSEB63lOFHIpNRUVMvYTc6yu1SMY/XTDM=
modernc.org/z v1.5.1/go.mod h1:eWFB510QWW5Th9YGZT81s+LwvaAs3Q2yr4sP0rmLkv8=
mvdan.cc/gofumpt v0.1.1/go.mod h1:yXG1r1WqZVKWbVRtBWKWX9+CxGYfA51nSomhM0woR48=
nhooyr.io/websocket v1.8.11 h1:f/qXNc2/3DpoSZkHt1DQu6rj4zGC8JmkkLkWss0MgN0=
nhooyr.io/websocket v1.8.11/go.mod h1:rN9OFWIUwuxg4fR5tELlYC04bXYowCP9GX47ivo2l+c=
rsc.io/binaryregexp v0.2.0/go.mod h1:qTv7/COck+e2FymRvadv62gMdZztPaShugOCi3I+8D8=
Expand Down
22 changes: 18 additions & 4 deletions internal/observability/event/sink_file.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -115,7 +115,7 @@ func (s *FileSink) Process(ctx context.Context, e *eventlogger.Event) (_ *eventl
return nil, fmt.Errorf("unable to retrieve event formatted as %q: %w", s.requiredFormat, ErrInvalidParameter)
}

err := s.log(formatted)
err := s.log(ctx, formatted)
if err != nil {
return nil, fmt.Errorf("error writing file for sink %q: %w", s.path, err)
}
Expand Down Expand Up @@ -189,9 +189,23 @@ func (s *FileSink) open() error {
}

// log writes the buffer to the file.
// It acquires a lock on the file to do this.
func (s *FileSink) log(data []byte) error {
s.fileLock.Lock()
// NOTE: We attempt to acquire a lock on the file in order to write, but will
// yield if the context is 'done'.
func (s *FileSink) log(ctx context.Context, data []byte) error {
// Don't just wait for the lock, ignorant of the context as we could end up
// with a lot of entries queuing up for access to the sink. If our context gets
// cancelled then we should just give up and not continue to wait for our turn.
contextDoneOrLock:
for {
select {
case <-ctx.Done():
return ctx.Err()
default:
if s.fileLock.TryLock() {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should there be a small sleep in an else case here? I worry that something could get spinning in here up to 100% CPU. If the lock's not ready then this thread is super busy spinning through this loop non-stop. We had a similar bug recently in Agent/Proxy leading to high CPU usage.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This same question is true for the similar bit of code in internal/observability/event/sink_socket.go

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, it's a good point. I've pushed up some changes to just let us queue for the lock (letting Go figure it out) then check the context straight away when we get the lock (potentially just releasing the lock if we're 'done').

break contextDoneOrLock
}
}
}
defer s.fileLock.Unlock()

reader := bytes.NewReader(data)
Expand Down
45 changes: 45 additions & 0 deletions internal/observability/event/sink_file_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,8 @@
package event

import (
"context"
"errors"
"os"
"path/filepath"
"testing"
Expand Down Expand Up @@ -236,6 +238,13 @@ func TestFileSink_Process(t *testing.T) {
IsErrorExpected: true,
ExpectedErrorMessage: "event is nil: invalid parameter",
},
"happy-path": {
Path: "juan.log",
ShouldCreateFile: true,
Format: "json",
Data: "{\"foo\": \"bar\"}",
IsErrorExpected: false,
},
}

for name, tc := range tests {
Expand Down Expand Up @@ -297,3 +306,39 @@ func TestFileSink_Process(t *testing.T) {
})
}
}

// TestFileSink_log_cancelledContext tests that 'log' is context aware and won't
// just wait for the lock on the file sink forever.
func TestFileSink_log_cancelledContext(t *testing.T) {
tempDir := t.TempDir()
tempPath := filepath.Join(tempDir, "juan.log")
data := []byte("{\"foo\": \"bar\"}")

sink, err := NewFileSink(tempPath, "json")
require.NoError(t, err)
require.NotNil(t, sink)

ctx, cancel := context.WithCancel(context.Background())
t.Cleanup(func() { cancel() })

// Manually acquire the lock so that the 'log' method cannot.
sink.fileLock.Lock()

go func() {
err = sink.log(ctx, data)
}()

time.Sleep(50 * time.Millisecond)

// We shouldn't have an error as 'log' will be trying to acquire the lock.
require.NoError(t, err)

// Manually cancel the context.
cancel()

// Just a little bit of time to make sure that 'log' returned and err was set.
time.Sleep(50 * time.Millisecond)

// We expect that the error now has context cancelled in it.
require.True(t, errors.Is(err, context.Canceled))
}
22 changes: 21 additions & 1 deletion internal/observability/event/sink_socket.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,7 +86,20 @@ func (s *SocketSink) Process(ctx context.Context, e *eventlogger.Event) (_ *even
return nil, fmt.Errorf("unable to retrieve event formatted as %q: %w", s.requiredFormat, ErrInvalidParameter)
}

s.socketLock.Lock()
// Don't just wait for the lock, ignorant of the context as we could end up
// with a lot of entries queuing up for access to the sink. If our context gets
// cancelled then we should just give up and not continue to wait for our turn.
contextDoneOrLock:
for {
select {
case <-ctx.Done():
return nil, ctx.Err()
default:
if s.socketLock.TryLock() {
break contextDoneOrLock
}
}
}
defer s.socketLock.Unlock()

// Try writing and return early if successful.
Expand Down Expand Up @@ -133,7 +146,14 @@ func (_ *SocketSink) Type() eventlogger.NodeType {
}

// connect attempts to establish a connection using the socketType and address.
// NOTE: connect is context aware and will not attempt to connect if the context is 'done'.
func (s *SocketSink) connect(ctx context.Context) error {
select {
case <-ctx.Done():
return ctx.Err()
default:
}

// If we're already connected, we should have disconnected first.
if s.connection != nil {
return nil
Expand Down
Loading