Audit: Timestamps on sink entries should match the creation time of the audit event (#26088)

* Sync timestamps in sinks to the creation time of the audit entry (event)

* changelog

audit/entry_formatter.go

@@ -30,6 +30,12 @@ var (
 	_ eventlogger.Node = (*EntryFormatter)(nil)
 )
 
+// timeProvider offers a way to supply a pre-configured time.
+type timeProvider interface {
+	// formatTime provides the pre-configured time in a particular format.
+	formattedTime() string
+}
+
 // EntryFormatter should be used to format audit requests and responses.
 type EntryFormatter struct {
 	config          FormatterConfig
@@ -162,9 +168,9 @@ func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (_ *
 
 	switch a.Subtype {
 	case RequestType:
-		entry, err = f.FormatRequest(ctx, data)
+		entry, err = f.FormatRequest(ctx, data, a)
 	case ResponseType:
-		entry, err = f.FormatResponse(ctx, data)
+		entry, err = f.FormatResponse(ctx, data, a)
 	default:
 		return nil, fmt.Errorf("%s: unknown audit event subtype: %q", op, a.Subtype)
 	}
@@ -219,7 +225,7 @@ func (f *EntryFormatter) Process(ctx context.Context, e *eventlogger.Event) (_ *
 }
 
 // FormatRequest attempts to format the specified logical.LogInput into a RequestEntry.
-func (f *EntryFormatter) FormatRequest(ctx context.Context, in *logical.LogInput) (*RequestEntry, error) {
+func (f *EntryFormatter) FormatRequest(ctx context.Context, in *logical.LogInput, provider timeProvider) (*RequestEntry, error) {
 	switch {
 	case in == nil || in.Request == nil:
 		return nil, errors.New("request to request-audit a nil request")
@@ -342,14 +348,15 @@ func (f *EntryFormatter) FormatRequest(ctx context.Context, in *logical.LogInput
 	}
 
 	if !f.config.OmitTime {
-		reqEntry.Time = time.Now().UTC().Format(time.RFC3339Nano)
+		// Use the time provider to supply the time for this entry.
+		reqEntry.Time = provider.formattedTime()
 	}
 
 	return reqEntry, nil
 }
 
 // FormatResponse attempts to format the specified logical.LogInput into a ResponseEntry.
-func (f *EntryFormatter) FormatResponse(ctx context.Context, in *logical.LogInput) (*ResponseEntry, error) {
+func (f *EntryFormatter) FormatResponse(ctx context.Context, in *logical.LogInput, provider timeProvider) (*ResponseEntry, error) {
 	switch {
 	case f == nil:
 		return nil, errors.New("formatter is nil")
@@ -562,7 +569,8 @@ func (f *EntryFormatter) FormatResponse(ctx context.Context, in *logical.LogInpu
 	}
 
 	if !f.config.OmitTime {
-		respEntry.Time = time.Now().UTC().Format(time.RFC3339Nano)
+		// Use the time provider to supply the time for this entry.
+		respEntry.Time = provider.formattedTime()
 	}
 
 	return respEntry, nil

audit/entry_formatter_test.go

@@ -59,6 +59,15 @@ const testFormatJSONReqBasicStrFmt = `
 }
 `
 
+// testTimeProvider is just a test struct used to imitate an AuditEvent's ability
+// to provide a formatted time.
+type testTimeProvider struct{}
+
+// formattedTime always returns the same value for 22nd March 2024 at 10:00:05 (and 10 nanos).
+func (p *testTimeProvider) formattedTime() string {
+	return time.Date(2024, time.March, 22, 10, 0o0, 5, 10, time.UTC).UTC().Format(time.RFC3339Nano)
+}
+
 // TestNewEntryFormatter ensures we can create new EntryFormatter structs.
 func TestNewEntryFormatter(t *testing.T) {
 	t.Parallel()
@@ -455,6 +464,7 @@ func TestEntryFormatter_FormatRequest(t *testing.T) {
 
 	tests := map[string]struct {
 		Input                *logical.LogInput
+		ShouldOmitTime       bool
 		IsErrorExpected      bool
 		ExpectedErrorMessage string
 		RootNamespace        bool
@@ -480,6 +490,11 @@ func TestEntryFormatter_FormatRequest(t *testing.T) {
 			IsErrorExpected: false,
 			RootNamespace:   true,
 		},
+		"omit-time": {
+			Input:          &logical.LogInput{Request: &logical.Request{ID: "123"}},
+			ShouldOmitTime: true,
+			RootNamespace:  true,
+		},
 	}
 
 	for name, tc := range tests {
@@ -489,7 +504,7 @@ func TestEntryFormatter_FormatRequest(t *testing.T) {
 			t.Parallel()
 
 			ss := newStaticSalt(t)
-			cfg, err := NewFormatterConfig()
+			cfg, err := NewFormatterConfig(WithOmitTime(tc.ShouldOmitTime))
 			require.NoError(t, err)
 			f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
 			require.NoError(t, err)
@@ -502,16 +517,22 @@ func TestEntryFormatter_FormatRequest(t *testing.T) {
 				ctx = context.Background()
 			}
 
-			entry, err := f.FormatRequest(ctx, tc.Input)
+			entry, err := f.FormatRequest(ctx, tc.Input, &testTimeProvider{})
 
 			switch {
 			case tc.IsErrorExpected:
 				require.Error(t, err)
 				require.EqualError(t, err, tc.ExpectedErrorMessage)
 				require.Nil(t, entry)
+			case tc.ShouldOmitTime:
+				require.NoError(t, err)
+				require.NotNil(t, entry)
+				require.Zero(t, entry.Time)
 			default:
 				require.NoError(t, err)
 				require.NotNil(t, entry)
+				require.NotZero(t, entry.Time)
+				require.Equal(t, "2024-03-22T10:00:05.00000001Z", entry.Time)
 			}
 		})
 	}
@@ -524,6 +545,7 @@ func TestEntryFormatter_FormatResponse(t *testing.T) {
 
 	tests := map[string]struct {
 		Input                *logical.LogInput
+		ShouldOmitTime       bool
 		IsErrorExpected      bool
 		ExpectedErrorMessage string
 		RootNamespace        bool
@@ -549,6 +571,12 @@ func TestEntryFormatter_FormatResponse(t *testing.T) {
 			IsErrorExpected: false,
 			RootNamespace:   true,
 		},
+		"omit-time": {
+			Input:           &logical.LogInput{Request: &logical.Request{ID: "123"}},
+			ShouldOmitTime:  true,
+			IsErrorExpected: false,
+			RootNamespace:   true,
+		},
 	}
 
 	for name, tc := range tests {
@@ -558,7 +586,7 @@ func TestEntryFormatter_FormatResponse(t *testing.T) {
 			t.Parallel()
 
 			ss := newStaticSalt(t)
-			cfg, err := NewFormatterConfig()
+			cfg, err := NewFormatterConfig(WithOmitTime(tc.ShouldOmitTime))
 			require.NoError(t, err)
 			f, err := NewEntryFormatter("juan", cfg, ss, hclog.NewNullLogger())
 			require.NoError(t, err)
@@ -571,16 +599,22 @@ func TestEntryFormatter_FormatResponse(t *testing.T) {
 				ctx = context.Background()
 			}
 
-			entry, err := f.FormatResponse(ctx, tc.Input)
+			entry, err := f.FormatResponse(ctx, tc.Input, &testTimeProvider{})
 
 			switch {
 			case tc.IsErrorExpected:
 				require.Error(t, err)
 				require.EqualError(t, err, tc.ExpectedErrorMessage)
 				require.Nil(t, entry)
+			case tc.ShouldOmitTime:
+				require.NoError(t, err)
+				require.NotNil(t, entry)
+				require.Zero(t, entry.Time)
 			default:
 				require.NoError(t, err)
 				require.NotNil(t, entry)
+				require.NotZero(t, entry.Time)
+				require.Equal(t, "2024-03-22T10:00:05.00000001Z", entry.Time)
 			}
 		})
 	}
@@ -956,7 +990,7 @@ func TestEntryFormatter_FormatResponse_ElideListResponses(t *testing.T) {
 			Response: &logical.Response{Data: inputData},
 		}
 
-		resp, err := formatter.FormatResponse(ctx, in)
+		resp, err := formatter.FormatResponse(ctx, in, &testTimeProvider{})
 		require.NoError(t, err)
 
 		return resp

audit/event.go

@@ -26,6 +26,9 @@ const (
 	JSONxFormat format = "jsonx"
 )
 
+// Check AuditEvent implements the timeProvider at compile time.
+var _ timeProvider = (*AuditEvent)(nil)
+
 // AuditEvent is the audit event.
 type AuditEvent struct {
 	ID        string            `json:"id"`
@@ -154,3 +157,9 @@ func (t subtype) String() string {
 
 	return string(t)
 }
+
+// formattedTime returns the UTC time the AuditEvent was created in the RFC3339Nano
+// format (which removes trailing zeros from the seconds field).
+func (a *AuditEvent) formattedTime() string {
+	return a.Timestamp.UTC().Format(time.RFC3339Nano)
+}

audit/event_test.go

@@ -368,3 +368,13 @@ func TestAuditEvent_Subtype_String(t *testing.T) {
 		})
 	}
 }
+
+// TestAuditEvent_formattedTime is used to check the output from the formattedTime
+// method returns the correct format.
+func TestAuditEvent_formattedTime(t *testing.T) {
+	theTime := time.Date(2024, time.March, 22, 10, 0o0, 5, 10, time.UTC)
+	a, err := NewEvent(ResponseType, WithNow(theTime))
+	require.NoError(t, err)
+	require.NotNil(t, a)
+	require.Equal(t, "2024-03-22T10:00:05.00000001Z", a.formattedTime())
+}

audit/types.go

@@ -52,9 +52,9 @@ type Salter interface {
 // It is recommended that you pass data through Hash prior to formatting it.
 type Formatter interface {
 	// FormatRequest formats the logical.LogInput into an RequestEntry.
-	FormatRequest(context.Context, *logical.LogInput) (*RequestEntry, error)
+	FormatRequest(context.Context, *logical.LogInput, timeProvider) (*RequestEntry, error)
 	// FormatResponse formats the logical.LogInput into an ResponseEntry.
-	FormatResponse(context.Context, *logical.LogInput) (*ResponseEntry, error)
+	FormatResponse(context.Context, *logical.LogInput, timeProvider) (*ResponseEntry, error)
 }
 
 // HeaderFormatter is an interface defining the methods of the

changelog/26088.txt

@@ -0,0 +1,3 @@
+```release-note:improvement
+audit: timestamps across multiple audit devices for an audit entry will now match.
+```