Merge pull request #1920 from alphagov/log-more-info-about-deliveries

stephencdaly · web-flow · commit 6c353c269cd4 · 2026-02-24T16:05:06.000Z
Log more info about deliveries
diff --git a/app/jobs/application_job.rb b/app/jobs/application_job.rb
@@ -1,18 +1,22 @@
 class ApplicationJob < ActiveJob::Base
-  def set_submission_logging_attributes(submission)
+  def set_submission_logging_attributes(submission:, delivery: nil)
     CurrentJobLoggingAttributes.job_class = self.class.name
     CurrentJobLoggingAttributes.job_id = job_id
     CurrentJobLoggingAttributes.form_id = submission.form.id
     CurrentJobLoggingAttributes.form_name = submission.form.name
     CurrentJobLoggingAttributes.submission_reference = submission.reference
     CurrentJobLoggingAttributes.preview = submission.preview?
+    CurrentJobLoggingAttributes.delivery_id = delivery&.id
+    CurrentJobLoggingAttributes.delivery_reference = delivery&.delivery_reference
   end
 
-  def set_submission_batch_logging_attributes(form:, mode:)
+  def set_submission_batch_logging_attributes(form:, mode:, delivery:)
     CurrentJobLoggingAttributes.job_class = self.class.name
     CurrentJobLoggingAttributes.job_id = job_id
     CurrentJobLoggingAttributes.form_id = form.id
     CurrentJobLoggingAttributes.form_name = form.name
     CurrentJobLoggingAttributes.preview = mode.preview?
+    CurrentJobLoggingAttributes.delivery_id = delivery.id
+    CurrentJobLoggingAttributes.delivery_reference = delivery.delivery_reference
   end
 end
diff --git a/app/jobs/delete_submissions_job.rb b/app/jobs/delete_submissions_job.rb
@@ -14,7 +14,7 @@ def perform(*_args)
   end
 
   def delete_submission_data(submission)
-    set_submission_logging_attributes(submission)
+    set_submission_logging_attributes(submission:)
     delivery_status = submission&.single_submission_delivery&.status
 
     files = submission.journey.completed_file_upload_questions
diff --git a/app/jobs/receive_submission_bounces_and_complaints_job.rb b/app/jobs/receive_submission_bounces_and_complaints_job.rb
@@ -21,14 +21,14 @@ def perform
       raise "Unexpected event type:#{ses_event_type}" unless %w[Bounce Complaint].include?(ses_event_type)
 
       process_bounce(delivery, submission, ses_message) if ses_event_type == "Bounce"
-      process_complaint(submission) if ses_event_type == "Complaint"
+      process_complaint(delivery, submission) if ses_event_type == "Complaint"
     end
   end
 
 private
 
   def process_bounce(delivery, submission, ses_message)
-    set_submission_logging_attributes(submission)
+    set_submission_logging_attributes(submission:, delivery:)
 
     bounce_object = ses_message["bounce"] || {}
 
@@ -74,8 +74,8 @@ def process_bounce(delivery, submission, ses_message)
     end
   end
 
-  def process_complaint(submission)
-    set_submission_logging_attributes(submission)
+  def process_complaint(delivery, submission)
+    set_submission_logging_attributes(submission:, delivery:)
 
     EventLogger.log_form_event("submission_complaint")
   end
diff --git a/app/jobs/receive_submission_deliveries_job.rb b/app/jobs/receive_submission_deliveries_job.rb
@@ -33,7 +33,7 @@ def perform
 private
 
   def process_delivery(delivery, submission, **attributes)
-    set_submission_logging_attributes(submission)
+    set_submission_logging_attributes(submission:, delivery:)
 
     delivery.update! attributes
 
diff --git a/app/jobs/send_s3_submission_job.rb b/app/jobs/send_s3_submission_job.rb
@@ -1,12 +1,13 @@
 class SendS3SubmissionJob < SubmissionDeliveryJob
   def perform(submission)
-    set_submission_logging_attributes(submission)
+    delivery = submission.single_submission_delivery
+    set_submission_logging_attributes(submission:, delivery:)
 
-    new_delivery_attempt!(submission)
+    delivery.new_attempt!
 
     key = S3SubmissionService.new(submission:).submit
 
-    update_delivery_reference!(submission, delivery_reference: key)
+    delivery.update!(delivery_reference: key)
     record_submission_sent!
   rescue StandardError
     CloudWatchService.record_job_failure_metric(self.class.name)
diff --git a/app/jobs/send_submission_batch_job.rb b/app/jobs/send_submission_batch_job.rb
@@ -18,7 +18,8 @@ def perform(delivery:)
     form = latest_submission.form
     mode = latest_submission.mode_object
     date = latest_submission.submission_time.to_date
-    set_submission_batch_logging_attributes(form:, mode:)
+
+    set_submission_batch_logging_attributes(form:, mode:, delivery:)
 
     if form.submission_email.blank?
       if mode.preview?
@@ -36,8 +37,9 @@ def perform(delivery:)
       last_attempt_at: Time.zone.now,
     )
 
+    CurrentJobLoggingAttributes.delivery_reference = delivery.delivery_reference
     EventLogger.log_form_event("daily_batch_email_sent", {
-      mode:,
+      mode: mode.to_s,
       batch_date: date,
       number_of_submissions: submissions.count,
     })
diff --git a/app/jobs/send_submission_job.rb b/app/jobs/send_submission_job.rb
@@ -5,13 +5,14 @@ class SendSubmissionJob < SubmissionDeliveryJob
   retry_on Aws::SESV2::Errors::ServiceError, wait: :polynomially_longer, attempts: TOTAL_ATTEMPTS
 
   def perform(submission)
-    set_submission_logging_attributes(submission)
+    delivery = submission.single_submission_delivery
+    set_submission_logging_attributes(submission:, delivery:)
 
-    new_delivery_attempt!(submission)
+    delivery.new_attempt!
 
     message_id = AwsSesSubmissionService.new(submission:).submit
 
-    update_delivery_reference!(submission, delivery_reference: message_id)
+    delivery.update!(delivery_reference: message_id)
     record_submission_sent!
   rescue StandardError
     CloudWatchService.record_job_failure_metric(self.class.name)
diff --git a/app/jobs/submission_delivery_job.rb b/app/jobs/submission_delivery_job.rb
@@ -3,21 +3,6 @@ class SubmissionDeliveryJob < ApplicationJob
 
 private
 
-  def new_delivery_attempt!(submission)
-    submission.single_submission_delivery.update!(
-      last_attempt_at: Time.zone.now,
-      delivered_at: nil,
-      failed_at: nil,
-      failure_reason: nil,
-    )
-  end
-
-  def update_delivery_reference!(submission, delivery_reference:)
-    submission.single_submission_delivery.update!(
-      delivery_reference: delivery_reference,
-    )
-  end
-
   def record_submission_sent!
     milliseconds_since_scheduled = (Time.current - scheduled_at_or_enqueued_at).in_milliseconds.round
     EventLogger.log_form_event("submission_sent", { milliseconds_since_scheduled: })
diff --git a/app/models/current_job_logging_attributes.rb b/app/models/current_job_logging_attributes.rb
@@ -1,5 +1,14 @@
 class CurrentJobLoggingAttributes < ActiveSupport::CurrentAttributes
-  attribute :job_class, :job_id, :form_id, :form_name, :submission_reference, :preview, :delivery_reference, :sqs_message_id, :sns_message_timestamp
+  attribute :job_class,
+            :job_id,
+            :form_id,
+            :form_name,
+            :submission_reference,
+            :preview,
+            :delivery_id,
+            :delivery_reference,
+            :sqs_message_id,
+            :sns_message_timestamp
 
   def as_hash
     {
@@ -9,6 +18,7 @@ def as_hash
       form_name:,
       submission_reference:,
       preview: preview.to_s,
+      delivery_id:,
       delivery_reference:,
       sqs_message_id:,
       sns_message_timestamp:,
diff --git a/app/models/delivery.rb b/app/models/delivery.rb
@@ -24,4 +24,13 @@ def status
       self.status == status
     end
   end
+
+  def new_attempt!
+    update!(
+      last_attempt_at: Time.zone.now,
+      delivered_at: nil,
+      failed_at: nil,
+      failure_reason: nil,
+    )
+  end
 end
diff --git a/spec/jobs/send_submission_batch_job_spec.rb b/spec/jobs/send_submission_batch_job_spec.rb
@@ -60,39 +60,51 @@
       end
     end
 
-    context "when the form has a submission email address" do
+    context "when the form has a submission email address", :capture_logging do
+      let(:mail) { ActionMailer::Base.deliveries.last }
+
       before do
         @job_ran_at = Time.zone.now
         perform_enqueued_jobs
       end
 
       it "sends an email" do
         expect(ActionMailer::Base.deliveries.count).to eq(1)
-
-        mail = ActionMailer::Base.deliveries.last
         expect(mail.to).to include(form_document.submission_email)
       end
 
       it "updates the delivery" do
-        mail = ActionMailer::Base.deliveries.last
         expect(delivery.reload.delivery_reference).to eq(mail.message_id)
         expect(delivery.reload.last_attempt_at).to be_within(1.second).of(@job_ran_at)
       end
 
       it "attaches a csv with the expected filename" do
-        mail = ActionMailer::Base.deliveries.last
         expect(mail.attachments).not_to be_empty
 
         filenames = mail.attachments.map(&:filename)
         expect(filenames).to contain_exactly("govuk_forms_my_form_2022-12-14.csv")
       end
 
       it "attaches a csv containing header plus one line per submission" do
-        mail = ActionMailer::Base.deliveries.last
-
         csv_content = mail.attachments.first.decoded
         expect(csv_content.lines.count).to eq(submissions.count + 1)
       end
+
+      it "logs that the email was sent" do
+        expect(log_lines).to include(
+          hash_including(
+            "event" => "form_daily_batch_email_sent",
+            "form_id" => form_id,
+            "mode" => mode_string,
+            "preview" => "false",
+            "batch_date" => date.to_s,
+            "number_of_submissions" => submissions.count,
+            "delivery_reference" => mail.message_id,
+            "delivery_id" => delivery.id,
+            "job_id" => @job_id,
+          ),
+        )
+      end
     end
 
     context "when the form settings have changed between submissions" do
diff --git a/spec/models/delivery_spec.rb b/spec/models/delivery_spec.rb
@@ -84,4 +84,27 @@
       end
     end
   end
+
+  describe "#new_attempt!" do
+    let(:previous_attempt_at) { 2.hours.ago }
+    let(:delivery) do
+      create(
+        :delivery,
+        last_attempt_at: previous_attempt_at,
+        delivered_at: 3.hours.ago,
+        failed_at: 2.hours.ago,
+        failure_reason: "error",
+      )
+    end
+
+    it "updates last_attempt_at and clears delivered_at, failed_at and failure_reason" do
+      delivery.new_attempt!
+      delivery.reload
+
+      expect(delivery.last_attempt_at).to be > previous_attempt_at
+      expect(delivery.delivered_at).to be_nil
+      expect(delivery.failed_at).to be_nil
+      expect(delivery.failure_reason).to be_nil
+    end
+  end
 end
