From 27196f9d73e3f5dbd4789b17835e8edb1377b9ad Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Wed, 24 Apr 2024 10:36:57 +0100 Subject: [PATCH 1/6] add context timeout to audit request --- audit/broker.go | 20 ++++++++++++++++++-- 1 file changed, 18 insertions(+), 2 deletions(-) diff --git a/audit/broker.go b/audit/broker.go index 4fd039ee618a..6cb08bc7eaa0 100644 --- a/audit/broker.go +++ b/audit/broker.go @@ -276,9 +276,25 @@ func (b *Broker) LogRequest(ctx context.Context, in *logical.LogInput) (ret erro e.Data = in + // In cases where we are trying to audit the response, we detach + // ourselves from the original context (keeping only the namespace). + // This is so that we get a fair run at writing audit entries if Vault + // has taken up a lot of time handling the request before audit (response) + // is triggered. Pipeline nodes and the eventlogger.Broker may check for a + // cancelled context and refuse to process the nodes further. + ns, err := namespace.FromContext(ctx) + if err != nil { + retErr = multierror.Append(retErr, fmt.Errorf("namespace missing from context: %w", err)) + return retErr.ErrorOrNil() + } + + auditContext, auditCancel := context.WithTimeout(context.Background(), 5*time.Second) + defer auditCancel() + auditContext = namespace.ContextWithNamespace(auditContext, ns) + var status eventlogger.Status if hasAuditPipelines(b.broker) { - status, err = b.broker.Send(ctx, event.AuditType.AsEventType(), e) + status, err = b.broker.Send(auditContext, event.AuditType.AsEventType(), e) if err != nil { retErr = multierror.Append(retErr, multierror.Append(err, status.Warnings...)) return retErr.ErrorOrNil() @@ -297,7 +313,7 @@ func (b *Broker) LogRequest(ctx context.Context, in *logical.LogInput) (ret erro } // Handle any additional audit that is required (Enterprise/CE dependant). - err = b.handleAdditionalAudit(ctx, e) + err = b.handleAdditionalAudit(auditContext, e) if err != nil { retErr = multierror.Append(retErr, err) } From 6fc6a28d9a949ab6b1275abb50145e1f2d39347e Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Wed, 24 Apr 2024 10:38:28 +0100 Subject: [PATCH 2/6] changelog --- changelog/26616.txt | 3 +++ 1 file changed, 3 insertions(+) create mode 100644 changelog/26616.txt diff --git a/changelog/26616.txt b/changelog/26616.txt new file mode 100644 index 000000000000..106ce102190d --- /dev/null +++ b/changelog/26616.txt @@ -0,0 +1,3 @@ +```release-note:bug +core/audit: Audit logging a Vault request will now use a 5 second context timeout, separate from the original request. +``` \ No newline at end of file From 52564710ee8b56d0fad0d8d0adc7b1406b90e972 Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Tue, 30 Apr 2024 11:09:16 +0100 Subject: [PATCH 3/6] Ensure 'minimum' timeout for contexts when attempting to send audit entries to the broker --- audit/broker.go | 98 +++++++++++++++++++++++++++++++------------- audit/broker_test.go | 49 ++++++++++++++++++++++ 2 files changed, 119 insertions(+), 28 deletions(-) diff --git a/audit/broker.go b/audit/broker.go index 6cb08bc7eaa0..5be7975da912 100644 --- a/audit/broker.go +++ b/audit/broker.go @@ -21,6 +21,11 @@ import ( "github.com/hashicorp/vault/sdk/logical" ) +const ( + // timeout is the duration which should be used for context related timeouts. + timeout = 5 * time.Second +) + var ( _ Registrar = (*Broker)(nil) _ Auditor = (*Broker)(nil) @@ -276,21 +281,28 @@ func (b *Broker) LogRequest(ctx context.Context, in *logical.LogInput) (ret erro e.Data = in - // In cases where we are trying to audit the response, we detach - // ourselves from the original context (keeping only the namespace). - // This is so that we get a fair run at writing audit entries if Vault - // has taken up a lot of time handling the request before audit (response) - // is triggered. Pipeline nodes and the eventlogger.Broker may check for a - // cancelled context and refuse to process the nodes further. - ns, err := namespace.FromContext(ctx) - if err != nil { - retErr = multierror.Append(retErr, fmt.Errorf("namespace missing from context: %w", err)) - return retErr.ErrorOrNil() - } + // Evaluate whether we need a new context for auditing. + var auditContext context.Context + if isContextViable(ctx) { + auditContext = ctx + } else { + // In cases where we are trying to audit the request, and the existing + // context is not viable due to a short deadline, we detach ourselves from + // the original context (keeping only the namespace). + // This is so that we get a fair run at writing audit entries if Vault + // has taken up a lot of time handling the request before audit (response) + // is triggered. Pipeline nodes and the eventlogger.Broker may check for a + // cancelled context and refuse to process the nodes further. + ns, err := namespace.FromContext(ctx) + if err != nil { + retErr = multierror.Append(retErr, fmt.Errorf("namespace missing from context: %w", err)) + return retErr.ErrorOrNil() + } - auditContext, auditCancel := context.WithTimeout(context.Background(), 5*time.Second) - defer auditCancel() - auditContext = namespace.ContextWithNamespace(auditContext, ns) + tempContext, auditCancel := context.WithTimeout(context.Background(), 5*time.Second) + defer auditCancel() + auditContext = namespace.ContextWithNamespace(tempContext, ns) + } var status eventlogger.Status if hasAuditPipelines(b.broker) { @@ -351,21 +363,28 @@ func (b *Broker) LogResponse(ctx context.Context, in *logical.LogInput) (ret err e.Data = in - // In cases where we are trying to audit the response, we detach - // ourselves from the original context (keeping only the namespace). - // This is so that we get a fair run at writing audit entries if Vault - // has taken up a lot of time handling the request before audit (response) - // is triggered. Pipeline nodes and the eventlogger.Broker may check for a - // cancelled context and refuse to process the nodes further. - ns, err := namespace.FromContext(ctx) - if err != nil { - retErr = multierror.Append(retErr, fmt.Errorf("namespace missing from context: %w", err)) - return retErr.ErrorOrNil() - } + // Evaluate whether we need a new context for auditing. + var auditContext context.Context + if isContextViable(ctx) { + auditContext = ctx + } else { + // In cases where we are trying to audit the response, and the existing + // context is not viable due to a short deadline, we detach ourselves from + // the original context (keeping only the namespace). + // This is so that we get a fair run at writing audit entries if Vault + // has taken up a lot of time handling the request before audit (response) + // is triggered. Pipeline nodes and the eventlogger.Broker may check for a + // cancelled context and refuse to process the nodes further. + ns, err := namespace.FromContext(ctx) + if err != nil { + retErr = multierror.Append(retErr, fmt.Errorf("namespace missing from context: %w", err)) + return retErr.ErrorOrNil() + } - auditContext, auditCancel := context.WithTimeout(context.Background(), 5*time.Second) - defer auditCancel() - auditContext = namespace.ContextWithNamespace(auditContext, ns) + tempContext, auditCancel := context.WithTimeout(context.Background(), timeout) + defer auditCancel() + auditContext = namespace.ContextWithNamespace(tempContext, ns) + } var status eventlogger.Status if hasAuditPipelines(b.broker) { @@ -440,3 +459,26 @@ func (b *Broker) IsRegistered(name string) bool { return b.isRegisteredByName(name) } + +// isContextViable examines the supplied context to see if its own deadline would +// occur later than a newly created context with a specific timeout. +// If the existing context is viable it can be used 'as-is', if not, the caller +// should consider creating a new context with the relevant deadline and associated +// context values (e.g. namespace) in order to reduce the likelihood that the +// audit system believes there is a failure in audit (and updating its metrics) +// when the root cause is elsewhere. +func isContextViable(ctx context.Context) bool { + if ctx == nil { + return false + } + + deadline, hasDeadline := ctx.Deadline() + + // If there's no deadline on the context then we don't need to worry about + // it being cancelled due to a timeout. + if !hasDeadline { + return true + } + + return deadline.After(time.Now().Add(timeout)) +} diff --git a/audit/broker_test.go b/audit/broker_test.go index dd7df8b91a46..fea236bfe2cc 100644 --- a/audit/broker_test.go +++ b/audit/broker_test.go @@ -158,3 +158,52 @@ func BenchmarkAuditBroker_File_Request_DevNull(b *testing.B) { } }) } + +// TestBroker_isContextViable_basics checks the expected result of isContextViable +// for basic inputs such as nil and a never-ending context. +func TestBroker_isContextViable_basics(t *testing.T) { + t.Parallel() + + require.False(t, isContextViable(nil)) + require.False(t, isContextViable(context.Background())) +} + +// TestBroker_isContextViable_timeouts checks the expected result of isContextViable +// for various timeout durations. +func TestBroker_isContextViable_timeouts(t *testing.T) { + t.Parallel() + + tests := map[string]struct { + timeout time.Duration + expected bool + }{ + "2s-smaller-deadline": { + timeout: timeout - 2*time.Second, + expected: false, + }, + "same-deadline": { + timeout: timeout, + expected: false, // Expected as a near miss + }, + "same-deadline-plus": { + timeout: timeout + 5*time.Millisecond, + expected: true, + }, + "2x-longer-deadline": { + timeout: timeout * 2, + expected: true, + }, + } + + for name, tc := range tests { + name := name + tc := tc + t.Run(name, func(t *testing.T) { + t.Parallel() + + ctx, cancel := context.WithTimeout(context.Background(), tc.timeout) + t.Cleanup(func() { cancel() }) + require.Equal(t, tc.expected, isContextViable(ctx)) + }) + } +} From 81c2212ab3847bc5d1cb7effab110bfaeaea61b1 Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Tue, 30 Apr 2024 11:10:15 +0100 Subject: [PATCH 4/6] response/request typo --- audit/broker.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/audit/broker.go b/audit/broker.go index 5be7975da912..15d096cfb0b9 100644 --- a/audit/broker.go +++ b/audit/broker.go @@ -290,7 +290,7 @@ func (b *Broker) LogRequest(ctx context.Context, in *logical.LogInput) (ret erro // context is not viable due to a short deadline, we detach ourselves from // the original context (keeping only the namespace). // This is so that we get a fair run at writing audit entries if Vault - // has taken up a lot of time handling the request before audit (response) + // has taken up a lot of time handling the request before audit (request) // is triggered. Pipeline nodes and the eventlogger.Broker may check for a // cancelled context and refuse to process the nodes further. ns, err := namespace.FromContext(ctx) From d91cd7b41b3b0d0201fb595b5a4616d0e291660a Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Tue, 30 Apr 2024 11:14:27 +0100 Subject: [PATCH 5/6] updated changelog --- changelog/26616.txt | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/changelog/26616.txt b/changelog/26616.txt index 106ce102190d..af8e85e91940 100644 --- a/changelog/26616.txt +++ b/changelog/26616.txt @@ -1,3 +1,5 @@ ```release-note:bug -core/audit: Audit logging a Vault request will now use a 5 second context timeout, separate from the original request. +core/audit: Audit logging a Vault request/response will now use a minimum 5 second context timeout. +If the existing context deadline occurs later than 5s in the future, it will be used, otherwise a +new context, separate from the original will be used. ``` \ No newline at end of file From 90e9c91c1c393d81dc493b89d41fb40057c06908 Mon Sep 17 00:00:00 2001 From: Peter Wilson Date: Tue, 30 Apr 2024 11:57:55 +0100 Subject: [PATCH 6/6] Correct assertion --- audit/broker_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/audit/broker_test.go b/audit/broker_test.go index fea236bfe2cc..c2d80b92fccf 100644 --- a/audit/broker_test.go +++ b/audit/broker_test.go @@ -165,7 +165,7 @@ func TestBroker_isContextViable_basics(t *testing.T) { t.Parallel() require.False(t, isContextViable(nil)) - require.False(t, isContextViable(context.Background())) + require.True(t, isContextViable(context.Background())) } // TestBroker_isContextViable_timeouts checks the expected result of isContextViable