From 03b7b4d45a730c5b8ab4c91e8b11bc7cc915a8b7 Mon Sep 17 00:00:00 2001
From: Rick Carlino <rick.carlino@gmail.com>
Date: Wed, 15 Jan 2020 08:17:57 -0600
Subject: [PATCH] Reduce verbosity of scheduler logs. Fixes #1114

---
 VERSION                                       |  2 +-
 .../lib/farmbot_celery_script/scheduler.ex    | 44 ++++++++++++++-----
 2 files changed, 33 insertions(+), 13 deletions(-)

diff --git a/VERSION b/VERSION
index 3beeadd423..346a3dfc64 100644
--- a/VERSION
+++ b/VERSION
@@ -1 +1 @@
-9.0.2
+9.0.3-rc1
diff --git a/farmbot_celery_script/lib/farmbot_celery_script/scheduler.ex b/farmbot_celery_script/lib/farmbot_celery_script/scheduler.ex
index 31823db280..9e88377045 100644
--- a/farmbot_celery_script/lib/farmbot_celery_script/scheduler.ex
+++ b/farmbot_celery_script/lib/farmbot_celery_script/scheduler.ex
@@ -67,7 +67,12 @@ defmodule FarmbotCeleryScript.Scheduler do
   Calls are executed in a first in first out buffer, with things being added
   by `execute/2` taking priority.
   """
-  @spec schedule(GenServer.server(), AST.t() | [Compiler.compiled()], DateTime.t(), map()) ::
+  @spec schedule(
+          GenServer.server(),
+          AST.t() | [Compiler.compiled()],
+          DateTime.t(),
+          map()
+        ) ::
           {:ok, reference()}
   def schedule(scheduler_pid \\ __MODULE__, celery_script, at, data)
 
@@ -147,12 +152,15 @@ defmodule FarmbotCeleryScript.Scheduler do
     case DateTime.diff(DateTime.utc_now(), at, :millisecond) do
       # now is before the next date
       diff_ms when diff_ms < 0 ->
-        from_now =
-          DateTime.utc_now()
-          |> DateTime.add(abs(diff_ms), :millisecond)
-          |> Timex.from_now()
-
-        Logger.info("Next execution is still #{diff_ms}ms too early (#{from_now})")
+        # Commented out for now.
+        # See this issue for more info:
+        # https://github.com/FarmBot/farmbot_os/issues/1114
+        # from_now =
+        #   DateTime.utc_now()
+        #   |> DateTime.add(abs(diff_ms), :millisecond)
+        #   |> Timex.from_now()
+        # msg = "Next execution is still #{diff_ms}ms too early (#{from_now})"
+        # Logger.info(msg)
 
         state
         |> schedule_next_checkup(abs(diff_ms))
@@ -171,7 +179,9 @@ defmodule FarmbotCeleryScript.Scheduler do
 
       # now is late, but less than the grace period late
       diff_ms when diff_ms >= 0 when diff_ms <= @grace_period_ms ->
-        Logger.info("Next execution is ready for execution: #{Timex.from_now(at)}")
+        Logger.info(
+          "Next execution is ready for execution: #{Timex.from_now(at)}"
+        )
 
         state
         |> execute_next()
@@ -179,8 +189,15 @@ defmodule FarmbotCeleryScript.Scheduler do
     end
   end
 
-  def handle_info({:step_complete, {scheduled_at, executed_at, pid}, result}, state) do
-    send(pid, {FarmbotCeleryScript, {:scheduled_execution, scheduled_at, executed_at, result}})
+  def handle_info(
+        {:step_complete, {scheduled_at, executed_at, pid}, result},
+        state
+      ) do
+    send(
+      pid,
+      {FarmbotCeleryScript,
+       {:scheduled_execution, scheduled_at, executed_at, result}}
+    )
 
     state
     |> pop_next()
@@ -194,7 +211,9 @@ defmodule FarmbotCeleryScript.Scheduler do
     scheduler_pid = self()
 
     scheduled_pid =
-      spawn(fn -> StepRunner.step(scheduler_pid, {at, DateTime.utc_now(), pid}, compiled) end)
+      spawn(fn ->
+        StepRunner.step(scheduler_pid, {at, DateTime.utc_now(), pid}, compiled)
+      end)
 
     %{state | scheduled_pid: scheduled_pid}
   end
@@ -291,7 +310,8 @@ defmodule FarmbotCeleryScript.Scheduler do
     %{state | monitors: monitors}
   end
 
-  @spec add(state(), compiled_ast(), DateTime.t(), data :: map(), pid()) :: state()
+  @spec add(state(), compiled_ast(), DateTime.t(), data :: map(), pid()) ::
+          state()
   defp add(state, compiled, at, data, pid) do
     %{state | compiled: [{compiled, at, data, pid} | state.compiled]}
     |> index_next()