Add ability to pre/post-date audit events

When a sidekiq job creates an audit event
during its running, it'll create the event
when the job was executed, not enqueued.

When this happens, we should allow the creating
service to override the value.

This commit adds the ability to set a specific
time for when an audit event was created. By default
this will default to Time.zone.now (the current
behaviour) so there is no breaking change.

Changelog: fixed

app/services/audit_event_service.rb

@@ -14,14 +14,16 @@ class AuditEventService
   # @param [Hash] details extra data of audit event
   # @param [Symbol] save_type the type to save the event
   #   Can be selected from the following, :database, :stream, :database_and_stream .
+  # @params [DateTime] created_at the time the action occured
   #
   # @return [AuditEventService]
-  def initialize(author, entity, details = {}, save_type = :database_and_stream)
+  def initialize(author, entity, details = {}, save_type = :database_and_stream, created_at = DateTime.current)
     @author = build_author(author)
     @entity = entity
     @details = details
     @ip_address = resolve_ip_address(@author)
     @save_type = save_type
+    @created_at = created_at
   end
 
   # Builds the @details attribute for authentication
@@ -79,7 +81,8 @@ class AuditEventService
       author_id: @author.id,
       author_name: @author.name,
       entity_id: @entity.id,
-      entity_type: @entity.class.name
+      entity_type: @entity.class.name,
+      created_at: @created_at
     }
   end
 

doc/development/audit_event_guide/index.md

@@ -18,13 +18,14 @@ actions performed across the application.
 
 To instrument an audit event, the following attributes should be provided:
 
-| Attribute    | Type                 | Required? | Description                                         |
-|:-------------|:---------------------|:----------|:----------------------------------------------------|
-| `name`       | String               | false     | Action name to be audited. Used for error tracking  |
-| `author`     | User                 | true      | User who authors the change                         |
-| `scope`      | User, Project, Group | true      | Scope which the audit event belongs to              |
-| `target`     | Object               | true      | Target object being audited                         |
-| `message`    | String               | true      | Message describing the action                       |
+| Attribute    | Type                 | Required? | Description                                                      |
+|:-------------|:---------------------|:----------|:-----------------------------------------------------------------|
+| `name`       | String               | false     | Action name to be audited. Used for error tracking               |
+| `author`     | User                 | true      | User who authors the change                                      |
+| `scope`      | User, Project, Group | true      | Scope which the audit event belongs to                           |
+| `target`     | Object               | true      | Target object being audited                                      |
+| `message`    | String               | true      | Message describing the action                                    |
+| `created_at` | DateTime             | false     | The time when the action occured. Defaults to `DateTime.current` |
 
 ## How to instrument new Audit Events
 
@@ -97,7 +98,8 @@ if merge_approval_rule.save
     author: current_user,
     scope: project_alpha,
     target: merge_approval_rule,
-    message: 'Created a new approval rule'
+    message: 'Created a new approval rule',
+    created_at: DateTime.current # Useful for pre-dating an audit event when created asynchronously.
   }
 
   ::Gitlab::Audit::Auditor.audit(audit_context)

ee/app/services/audit_events/build_service.rb

@@ -8,7 +8,7 @@ module AuditEvents
     # @raise [MissingAttributeError] when required attributes are blank
     #
     # @return [BuildService]
-    def initialize(author:, scope:, target:, message:)
+    def initialize(author:, scope:, target:, message:, created_at: DateTime.current)
       raise MissingAttributeError if missing_attribute?(author, scope, target, message)
 
       @author = build_author(author)
@@ -16,6 +16,7 @@ module AuditEvents
       @target = build_target(target)
       @ip_address = build_ip_address
       @message = build_message(message)
+      @created_at = created_at
     end
 
     # Create an instance of AuditEvent
@@ -52,7 +53,7 @@ module AuditEvents
         author_name: @author.name,
         entity_id: @scope.id,
         entity_type: @scope.class.name,
-        created_at: DateTime.current
+        created_at: @created_at
       }
     end
 

ee/lib/gitlab/audit/auditor.rb

@@ -11,6 +11,7 @@ module Gitlab
       # @option context [User, Project, Group] :scope the scope which audit event belongs to
       # @option context [Object] :target the target object being audited
       # @option context [String] :message the message describing the action
+      # @option context [Time] :created_at the time that the event occurred (defaults to the current time)
       #
       # @example Using block (useful when events are emitted deep in the call stack)
       #   i.e. multiple audit events
@@ -56,6 +57,7 @@ module Gitlab
         @author = @context.fetch(:author)
         @scope = @context.fetch(:scope)
         @target = @context.fetch(:target)
+        @created_at = @context.fetch(:created_at, DateTime.current)
         @message = @context.fetch(:message, '')
       end
 
@@ -88,6 +90,7 @@ module Gitlab
           author: @author,
           scope: @scope,
           target: @target,
+          created_at: @created_at,
           message: message
         ).execute
       end

ee/spec/lib/gitlab/audit/auditor_spec.rb

@@ -52,15 +52,18 @@ RSpec.describe Gitlab::Audit::Auditor do
       end
 
       it 'logs audit events to database', :aggregate_failures do
-        audit!
-
-        audit_event = AuditEvent.last
-
-        expect(audit_event.author_id).to eq(author.id)
-        expect(audit_event.entity_id).to eq(scope.id)
-        expect(audit_event.entity_type).to eq(scope.class.name)
-        expect(audit_event.details[:target_id]).to eq(target.id)
-        expect(audit_event.details[:target_type]).to eq(target.class.name)
+        freeze_time do
+          audit!
+
+          audit_event = AuditEvent.last
+
+          expect(audit_event.author_id).to eq(author.id)
+          expect(audit_event.entity_id).to eq(scope.id)
+          expect(audit_event.entity_type).to eq(scope.class.name)
+          expect(audit_event.created_at).to eq(Time.zone.now)
+          expect(audit_event.details[:target_id]).to eq(target.id)
+          expect(audit_event.details[:target_type]).to eq(target.class.name)
+        end
       end
 
       it 'logs audit events to file' do
@@ -78,6 +81,44 @@ RSpec.describe Gitlab::Audit::Auditor do
           )
         )
       end
+
+      context 'when overriding the create datetime' do
+        let(:context) { { name: name, author: author, scope: scope, target: target, created_at: 3.weeks.ago } }
+
+        it 'logs audit events to database', :aggregate_failures do
+          freeze_time do
+            audit!
+
+            audit_event = AuditEvent.last
+
+            expect(audit_event.author_id).to eq(author.id)
+            expect(audit_event.entity_id).to eq(scope.id)
+            expect(audit_event.entity_type).to eq(scope.class.name)
+            expect(audit_event.created_at).to eq(3.weeks.ago)
+            expect(audit_event.details[:target_id]).to eq(target.id)
+            expect(audit_event.details[:target_type]).to eq(target.class.name)
+          end
+        end
+
+        it 'logs audit events to file' do
+          freeze_time do
+            expect(::Gitlab::AuditJsonLogger).to receive(:build).and_return(logger)
+
+            audit!
+
+            expect(logger).to have_received(:info).exactly(2).times.with(
+              hash_including(
+                'author_id' => author.id,
+                'author_name' => author.name,
+                'entity_id' => scope.id,
+                'entity_type' => scope.class.name,
+                'details' => kind_of(Hash),
+                'created_at' => 3.weeks.ago.iso8601(3)
+              )
+            )
+          end
+        end
+      end
     end
 
     context 'when recording single event' do

ee/spec/services/audit_events/impersonation_audit_event_service_spec.rb

@@ -22,7 +22,8 @@ RSpec.describe AuditEvents::ImpersonationAuditEventService do
                                             entity_type: "User",
                                             action: :custom,
                                             ip_address: ip_address,
-                                            custom_message: message)
+                                            custom_message: message,
+                                            created_at: anything)
 
       expect { service.security_event }.to change(AuditEvent, :count).by(1)
       security_event = AuditEvent.last

ee/spec/services/audit_events/protected_branch_audit_event_service_spec.rb

@@ -65,7 +65,8 @@ RSpec.describe AuditEvents::ProtectedBranchAuditEventService, :request_store do
             target_id: protected_branch.id,
             target_type: 'ProtectedBranch',
             custom_message: action == :add ? /Added/ : /Unprotected/,
-            ip_address: ip_address
+            ip_address: ip_address,
+            created_at: anything
           )
         end
       end

ee/spec/services/audit_events/runner_custom_audit_event_service_spec.rb

@@ -29,7 +29,8 @@ RSpec.describe AuditEvents::RunnerCustomAuditEventService do
                                             custom_message: custom_message,
                                             target_details: target_details,
                                             target_id: target_id,
-                                            target_type: target_type)
+                                            target_type: target_type,
+                                            created_at: anything)
 
       expect { service.security_event }.to change(AuditEvent, :count).by(1)
 

ee/spec/support/shared_examples/services/audit_event_logging_shared_examples.rb

@@ -48,27 +48,28 @@ RSpec.shared_examples 'logs the custom audit event' do
   end
 
   it 'creates an event and logs to a file with the provided details' do
-    expect(service).to receive(:file_logger).and_return(logger)
-    expect(logger).to receive(:info).with(author_id: user.id,
-                                          author_name: user.name,
-                                          entity_id: entity.id,
-                                          entity_type: entity_type,
-                                          action: :custom,
+    freeze_time do
+      expect(service).to receive(:file_logger).and_return(logger)
+      expect(logger).to receive(:info).with(author_id: user.id,
+                                            author_name: user.name,
+                                            entity_id: entity.id,
+                                            entity_type: entity_type,
+                                            action: :custom,
+                                            ip_address: ip_address,
+                                            custom_message: custom_message,
+                                            created_at: DateTime.current)
+
+      expect { service.security_event }.to change(AuditEvent, :count).by(1)
+      security_event = AuditEvent.last
+
+      expect(security_event.details).to eq(author_name: user.name,
+                                          custom_message: custom_message,
                                           ip_address: ip_address,
-                                          custom_message: custom_message)
-
-    expect { service.security_event }.to change(AuditEvent, :count).by(1)
-    security_event = AuditEvent.last
-
-    expect(security_event.details).to eq(
-      author_name: user.name,
-      custom_message: custom_message,
-      ip_address: ip_address,
-      action: :custom
-    )
-    expect(security_event.author_id).to eq(user.id)
-    expect(security_event.entity_id).to eq(entity.id)
-    expect(security_event.entity_type).to eq(entity_type)
+                                          action: :custom)
+      expect(security_event.author_id).to eq(user.id)
+      expect(security_event.entity_id).to eq(entity.id)
+      expect(security_event.entity_type).to eq(entity_type)
+    end
   end
 end
 
@@ -88,33 +89,34 @@ RSpec.shared_examples 'logs the release audit event' do
     stub_licensed_features(audit_events: true)
   end
 
-  it 'logs the event to file' do
-    expect(service).to receive(:file_logger).and_return(logger)
-    expect(logger).to receive(:info).with(author_id: user.id,
-                                          author_name: user.name,
-                                          entity_id: entity.id,
-                                          entity_type: entity_type,
-                                          ip_address: ip_address,
-                                          custom_message: custom_message,
-                                          target_details: target_details,
-                                          target_id: target_id,
-                                          target_type: target_type)
-
-    expect { service.security_event }.to change(AuditEvent, :count).by(1)
-
-    security_event = AuditEvent.last
-
-    expect(security_event.details).to eq(
-      author_name: user.name,
-      custom_message: custom_message,
-      ip_address: ip_address,
-      target_details: target_details,
-      target_id: target_id,
-      target_type: target_type
-    )
-
-    expect(security_event.author_id).to eq(user.id)
-    expect(security_event.entity_id).to eq(entity.id)
-    expect(security_event.entity_type).to eq(entity_type)
+  it 'logs the event to file', :aggregate_failures do
+    freeze_time do
+      expect(service).to receive(:file_logger).and_return(logger)
+      expect(logger).to receive(:info).with(author_id: user.id,
+                                            author_name: user.name,
+                                            entity_id: entity.id,
+                                            entity_type: entity_type,
+                                            ip_address: ip_address,
+                                            custom_message: custom_message,
+                                            target_details: target_details,
+                                            target_id: target_id,
+                                            target_type: target_type,
+                                            created_at: DateTime.current)
+
+      expect { service.security_event }.to change(AuditEvent, :count).by(1)
+
+      security_event = AuditEvent.last
+
+      expect(security_event.details).to eq(author_name: user.name,
+                                           custom_message: custom_message,
+                                           ip_address: ip_address,
+                                           target_details: target_details,
+                                           target_id: target_id,
+                                           target_type: target_type)
+
+      expect(security_event.author_id).to eq(user.id)
+      expect(security_event.entity_id).to eq(entity.id)
+      expect(security_event.entity_type).to eq(entity_type)
+    end
   end
 end

spec/services/audit_event_service_spec.rb

@@ -17,7 +17,8 @@ RSpec.describe AuditEventService do
                                             author_name: user.name,
                                             entity_id: project.id,
                                             entity_type: "Project",
-                                            action: :destroy)
+                                            action: :destroy,
+                                            created_at: anything)
 
       expect { service.security_event }.to change(AuditEvent, :count).by(1)
     end
@@ -39,7 +40,8 @@ RSpec.describe AuditEventService do
                                             from: 'true',
                                             to: 'false',
                                             action: :create,
-                                            target_id: 1)
+                                            target_id: 1,
+                                            created_at: anything)
 
       expect { service.security_event }.to change(AuditEvent, :count).by(1)
 
@@ -50,6 +52,25 @@ RSpec.describe AuditEventService do
       expect(details[:target_id]).to eq(1)
     end
 
+    context 'when defining created_at manually' do
+      let(:service) { described_class.new(user, project, { action: :destroy }, :database, 3.weeks.ago) }
+
+      it 'is overridden successfully' do
+        freeze_time do
+          expect(service).to receive(:file_logger).and_return(logger)
+          expect(logger).to receive(:info).with(author_id: user.id,
+                                                author_name: user.name,
+                                                entity_id: project.id,
+                                                entity_type: "Project",
+                                                action: :destroy,
+                                                created_at: 3.weeks.ago)
+
+          expect { service.security_event }.to change(AuditEvent, :count).by(1)
+          expect(AuditEvent.last.created_at).to eq(3.weeks.ago)
+        end
+      end
+    end
+
     context 'authentication event' do
       let(:audit_service) { described_class.new(user, user, with: 'standard') }
 
@@ -110,7 +131,8 @@ RSpec.describe AuditEventService do
                                             author_name: user.name,
                                             entity_type: 'Project',
                                             entity_id: project.id,
-                                            action: :destroy)
+                                            action: :destroy,
+                                            created_at: anything)
 
       service.log_security_event_to_file
     end