diff --git a/audit/broker.go b/audit/broker.go index 7d3f58abb6ab..c6f9d0e3de22 100644 --- a/audit/broker.go +++ b/audit/broker.go @@ -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 @@ -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 diff --git a/audit/sink_metric_labeler.go b/audit/sink_metric_labeler.go index 1bd24be5a2f0..a433fe325781 100644 --- a/audit/sink_metric_labeler.go +++ b/audit/sink_metric_labeler.go @@ -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 } diff --git a/changelog/28056.txt b/changelog/28056.txt new file mode 100644 index 000000000000..f39fbe2921c5 --- /dev/null +++ b/changelog/28056.txt @@ -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. +``` \ No newline at end of file diff --git a/go.mod b/go.mod index c2cf7f8943ca..301f101cb692 100644 --- a/go.mod +++ b/go.mod @@ -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 @@ -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 diff --git a/go.sum b/go.sum index d1b74ae26392..5401cf0b244f 100644 --- a/go.sum +++ b/go.sum @@ -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= @@ -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= @@ -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= @@ -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= @@ -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= @@ -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= @@ -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= @@ -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= @@ -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= diff --git a/internal/observability/event/sink_file.go b/internal/observability/event/sink_file.go index ea2047e9eb73..5385eac1df0f 100644 --- a/internal/observability/event/sink_file.go +++ b/internal/observability/event/sink_file.go @@ -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) } @@ -189,10 +189,18 @@ 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 { +// 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 { + // Wait for the lock, but ensure we check for a cancelled context as soon as + // we have it, as there's no point in continuing if we're cancelled. s.fileLock.Lock() defer s.fileLock.Unlock() + select { + case <-ctx.Done(): + return ctx.Err() + default: + } reader := bytes.NewReader(data) diff --git a/internal/observability/event/sink_file_test.go b/internal/observability/event/sink_file_test.go index 4018bfd474a9..6f4b721b07d8 100644 --- a/internal/observability/event/sink_file_test.go +++ b/internal/observability/event/sink_file_test.go @@ -4,13 +4,18 @@ package event import ( + "context" + "errors" + "fmt" "os" "path/filepath" + "sync/atomic" "testing" "time" "github.com/hashicorp/eventlogger" "github.com/hashicorp/vault/helper/namespace" + "github.com/hashicorp/vault/helper/testhelpers/corehelpers" "github.com/stretchr/testify/require" ) @@ -236,6 +241,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 { @@ -297,3 +309,46 @@ 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() + + var done atomic.Bool + go func() { + err = sink.log(ctx, data) + done.Store(true) + }() + + // We shouldn't have an error as 'log' will be trying to acquire the lock. + require.NoError(t, err) + + // Manually cancel the context and unlock to let the waiting 'log' in. + cancel() + sink.fileLock.Unlock() + + // Just a little bit of time to make sure that 'log' returned and err was set. + corehelpers.RetryUntil(t, 3*time.Second, func() error { + if done.Load() { + return nil + } + + return fmt.Errorf("logging still not done") + }) + + // We expect that the error now has context cancelled in it. + require.True(t, errors.Is(err, context.Canceled)) +} diff --git a/internal/observability/event/sink_socket.go b/internal/observability/event/sink_socket.go index 0761a46be886..dc88a78b7109 100644 --- a/internal/observability/event/sink_socket.go +++ b/internal/observability/event/sink_socket.go @@ -86,8 +86,15 @@ 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) } + // Wait for the lock, but ensure we check for a cancelled context as soon as + // we have it, as there's no point in continuing if we're cancelled. s.socketLock.Lock() defer s.socketLock.Unlock() + select { + case <-ctx.Done(): + return nil, ctx.Err() + default: + } // Try writing and return early if successful. err := s.write(ctx, formatted) @@ -133,7 +140,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