From 76473c3fc1d16f9174acc426a068938b925d54c5 Mon Sep 17 00:00:00 2001
From: akadusei <attakusiadusei@gmail.com>
Date: Sat, 2 Dec 2023 21:43:31 +0000
Subject: [PATCH] Fix wrong ordering of logs during task run

---
 CHANGELOG.md                      |  5 ++
 spec/mel/task/log_helpers_spec.cr | 87 +++++++++++++++++++++++++++++++
 spec/spec_helper.cr               |  1 +
 src/mel/task/log_helpers.cr       |  9 +++-
 src/worker/task.cr                |  6 +--
 5 files changed, 103 insertions(+), 5 deletions(-)
 create mode 100644 spec/mel/task/log_helpers_spec.cr

diff --git a/CHANGELOG.md b/CHANGELOG.md
index b00834b..f94ff92 100644
--- a/CHANGELOG.md
+++ b/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
diff --git a/spec/mel/task/log_helpers_spec.cr b/spec/mel/task/log_helpers_spec.cr
new file mode 100644
index 0000000..523c296
--- /dev/null
+++ b/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
diff --git a/spec/spec_helper.cr b/spec/spec_helper.cr
index d935b64..e5cecd7 100644
--- a/spec/spec_helper.cr
+++ b/spec/spec_helper.cr
@@ -1,4 +1,5 @@
 require "spec"
+require "log/spec"
 
 require "carbon"
 require "timecop"
diff --git a/src/mel/task/log_helpers.cr b/src/mel/task/log_helpers.cr
index 08f346e..252a7a4 100644
--- a/src/mel/task/log_helpers.cr
+++ b/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
diff --git a/src/worker/task.cr b/src/worker/task.cr
index 4560760..acc6077 100644
--- a/src/worker/task.cr
+++ b/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)