Fix wrong ordering of logs during task run

CHANGELOG.md

@@ -5,6 +5,11 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](http://semver.org/spec/v2.0.0.html).
 
+## [Unreleased] - 
+
+### Fixed
+- Fix wrong ordering of logs during task run
+
 ## [0.17.0] - 2023-12-01
 
 ### Added

spec/mel/task/log_helpers_spec.cr

@@ -0,0 +1,87 @@
+require "../../spec_helper"
+
+describe Mel::Task::LogHelpers do
+  it "logs successful instant task" do
+    id = "1"
+
+    Log.capture(Mel.log.source) do |logs|
+      SendEmailJob.run(id: id, address: "aa@bb.cc", retries: 1)
+
+      Mel.sync Mel::InstantTask.find(id, delete: true)
+
+      logs.check(:info, /Enqueueing task/)
+      logs.check(:info, /Task enqueued/)
+      logs.check(:info, /Running task/)
+      logs.check(:info, /Task completed/)
+      logs.check(:info, /Dequeueing task/)
+      logs.check(:info, /Task dequeued/)
+    end
+  end
+
+  it "logs failed instant task" do
+    id = "1"
+
+    Log.capture(Mel.log.source) do |logs|
+      FailedJob.run(id: id, retries: 1)
+
+      Mel.sync Mel::InstantTask.find(id)
+      Mel.sync Mel::InstantTask.find(id, delete: true)
+
+      logs.check(:info, /Enqueueing task/)
+      logs.check(:info, /Task enqueued/)
+      logs.check(:info, /Running task/)
+      logs.check(:warn, /Task errored/)
+      logs.check(:info, /Enqueueing task/)
+      logs.check(:info, /Task enqueued/)
+      logs.check(:info, /Running task/)
+      logs.check(:warn, /Task errored/)
+      logs.check(:error, /Task failed/)
+      logs.check(:info, /Dequeueing task/)
+      logs.check(:info, /Task dequeued/)
+    end
+  end
+
+  it "logs successful recurring task" do
+    id = "1"
+
+    Log.capture(Mel.log.source) do |logs|
+      SendEmailJob.run_every(1.hour, id: id, address: "aa@bb.cc", retries: 1)
+
+      Timecop.travel(1.hour.from_now) do
+        Mel.sync Mel::PeriodicTask.find(id, delete: true)
+      end
+
+      logs.check(:info, /Enqueueing task/)
+      logs.check(:info, /Task enqueued/)
+      logs.check(:info, /Running task/)
+      logs.check(:info, /Task completed/)
+      logs.check(:info, /Recheduling recurring task/)
+      logs.check(:info, /Recurring task rescheduled/)
+    end
+  end
+
+  it "logs failed recurring task" do
+    id = "1"
+
+    Log.capture(Mel.log.source) do |logs|
+      FailedJob.run_every(1.hour, id: id, retries: 1)
+
+      Timecop.travel(1.hour.from_now) do
+        Mel.sync Mel::PeriodicTask.find(id)
+        Mel.sync Mel::PeriodicTask.find(id, delete: true)
+      end
+
+      logs.check(:info, /Enqueueing task/)
+      logs.check(:info, /Task enqueued/)
+      logs.check(:info, /Running task/)
+      logs.check(:warn, /Task errored/)
+      logs.check(:info, /Enqueueing task/)
+      logs.check(:info, /Task enqueued/)
+      logs.check(:info, /Running task/)
+      logs.check(:warn, /Task errored/)
+      logs.check(:error, /Task failed/)
+      logs.check(:info, /Recheduling recurring task/)
+      logs.check(:info, /Recurring task rescheduled/)
+    end
+  end
+end

spec/spec_helper.cr

@@ -1,4 +1,5 @@
 require "spec"
+require "log/spec"
 
 require "carbon"
 require "timecop"

src/mel/task/log_helpers.cr

@@ -30,7 +30,7 @@ abstract class Mel::Task
       end
 
       private def log_ran : Nil
-        Mel.log.info &.emit("Task complete", **log_args)
+        Mel.log.info &.emit("Task completed successfully", **log_args)
       end
 
       private def log_errored(error) : Nil
@@ -41,7 +41,12 @@ abstract class Mel::Task
       end
 
       private def log_failed : Nil
-        Mel.log.error &.emit("Task failed after #{attempts} attempts", **log_args)
+        attempts_str = 1 == attempts ? "attempt" : "attempts"
+
+        Mel.log.error &.emit(
+          "Task failed after #{attempts} #{attempts_str}",
+          **log_args
+        )
       end
 
       private def log_scheduling : Nil

src/worker/task.cr

@@ -11,11 +11,11 @@ abstract class Mel::Task
       log_running
       job.run
     rescue error
-      retry_failed_task(error)
       log_errored(error)
+      retry_failed_task(error)
     else
-      schedule_next
       log_ran
+      schedule_next
       do_after_run(true)
     end
   end
@@ -41,8 +41,8 @@ abstract class Mel::Task
   end
 
   private def fail_task(error) : Nil
-    schedule_next
     log_failed
+    schedule_next
 
     handle_error(error)
     do_after_run(false)