From 06323242c23142dae63b920f38028000c8f5187e Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 10:36:48 -0500 Subject: [PATCH 1/9] Add Helpers.wait_for(pid). Remove :noop call --- .../lib/farmbot_ext/api/image_uploader.ex | 2 -- .../farmbot_ext/api/image_uploader_test.exs | 14 ++++++++-- farmbot_ext/test/test_helper.exs | 26 +++++++++++++++++++ 3 files changed, 38 insertions(+), 4 deletions(-) diff --git a/farmbot_ext/lib/farmbot_ext/api/image_uploader.ex b/farmbot_ext/lib/farmbot_ext/api/image_uploader.ex index b77f7fe7..2755adeb 100644 --- a/farmbot_ext/lib/farmbot_ext/api/image_uploader.ex +++ b/farmbot_ext/lib/farmbot_ext/api/image_uploader.ex @@ -44,8 +44,6 @@ defmodule FarmbotExt.API.ImageUploader do end def handle_continue([], state), do: {:noreply, state, @checkup_time_ms} - # This only exists to flush handle_cast's. I think. -RC - def handle_call(:noop, _, s), do: {:reply, :ok, s} # the meta here is likely inaccurate here because of pulling the location data # from the cache instead of from the firmware directly. It's close enough and diff --git a/farmbot_ext/test/farmbot_ext/api/image_uploader_test.exs b/farmbot_ext/test/farmbot_ext/api/image_uploader_test.exs index a139d8e4..41c788b0 100644 --- a/farmbot_ext/test/farmbot_ext/api/image_uploader_test.exs +++ b/farmbot_ext/test/farmbot_ext/api/image_uploader_test.exs @@ -1,4 +1,5 @@ defmodule FarmbotExt.API.ImageUploaderTest do + require Helpers use ExUnit.Case, async: false use Mimic alias FarmbotExt.API.ImageUploader @@ -22,12 +23,21 @@ defmodule FarmbotExt.API.ImageUploaderTest do end) expect(FarmbotExt.API, :upload_image, 4, fn - "/tmp/images/d.gif", _meta -> {:ok, %{status: 401, body: %{}}} + "/tmp/images/d.gif", _meta -> {:error, %{status: 401, body: %{}}} _image_filename, _meta -> {:ok, %{status: 201, body: %{}}} end) + err_msg = + "Upload Error (/tmp/images/d.gif): " <> + "{:error, %{body: %{}, status: 401}}" + + Helpers.expect_log("Uploaded image: /tmp/images/a.jpg") + Helpers.expect_log("Uploaded image: /tmp/images/b.jpeg") + Helpers.expect_log("Uploaded image: /tmp/images/c.png") + Helpers.expect_log(err_msg) + ImageUploader.force_checkup() send(pid, :timeout) - :ok = GenServer.call(pid, :noop) + Helpers.wait_for(pid) end end diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index a6112427..c4a98d2c 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -19,6 +19,32 @@ System.put_env("LOG_SILENCE", "true") ExUnit.start(assert_receive_timeout: String.to_integer(timeout)) defmodule Helpers do + # Maybe I don't need this? + # Maybe I could use `start_supervised`? + # https://hexdocs.pm/ex_unit/ExUnit.Callbacks.html#start_supervised/2 + + # Base case: We have a pid + def wait_for(pid) when is_pid(pid), do: continue_waiting(pid) + # Failure case: We failed to find a pid for a module. + def wait_for(nil), do: raise("Attempted to wait on bad module/pid") + # Edge case: We have a module and need to try finding its pid. + def wait_for(mod), do: wait_for(Process.whereis(mod)) + + defp continue_waiting(pid) do + wait(pid, Process.info(pid, :message_queue_len)) + end + + defp wait(_pid, {:message_queue_len, 0}), do: :ok + + defp wait(pid, {:message_queue_len, n}) when n < 20 do + Process.sleep(100) + continue_waiting(pid) + end + + defp wait(pid, {:message_queue_len, n}) do + raise "No longer waiting on #{inspect(pid)} after #{n} attempts" + end + defmacro expect_log(message) do quote do expect(FarmbotCore.LogExecutor, :execute, fn log -> From aa6f3f4ad1b9b72dc58550a5bf46929628ee0956 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 10:58:40 -0500 Subject: [PATCH 2/9] Race condition fix (probably) --- farmbot_ext/test/test_helper.exs | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index c4a98d2c..f425c329 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -23,6 +23,7 @@ defmodule Helpers do # Maybe I could use `start_supervised`? # https://hexdocs.pm/ex_unit/ExUnit.Callbacks.html#start_supervised/2 + @wait_time 25 # Base case: We have a pid def wait_for(pid) when is_pid(pid), do: continue_waiting(pid) # Failure case: We failed to find a pid for a module. @@ -34,17 +35,13 @@ defmodule Helpers do wait(pid, Process.info(pid, :message_queue_len)) end - defp wait(_pid, {:message_queue_len, 0}), do: :ok + defp wait(_pid, {:message_queue_len, 0}), do: Process.sleep(@wait_time) - defp wait(pid, {:message_queue_len, n}) when n < 20 do - Process.sleep(100) + defp wait(pid, {:message_queue_len, _n}) do + Process.sleep(@wait_time) continue_waiting(pid) end - defp wait(pid, {:message_queue_len, n}) do - raise "No longer waiting on #{inspect(pid)} after #{n} attempts" - end - defmacro expect_log(message) do quote do expect(FarmbotCore.LogExecutor, :execute, fn log -> From e5a29361d225bd89b89e3964b42223e3d7764514 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 11:09:56 -0500 Subject: [PATCH 3/9] :clap: Race conditions arre gone from test suite --- farmbot_ext/test/test_helper.exs | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index f425c329..378b7f50 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -23,24 +23,24 @@ defmodule Helpers do # Maybe I could use `start_supervised`? # https://hexdocs.pm/ex_unit/ExUnit.Callbacks.html#start_supervised/2 - @wait_time 25 + @wait_time 13 # Base case: We have a pid - def wait_for(pid) when is_pid(pid), do: continue_waiting(pid) + def wait_for(pid) when is_pid(pid), do: check_on_mbox(pid) # Failure case: We failed to find a pid for a module. def wait_for(nil), do: raise("Attempted to wait on bad module/pid") # Edge case: We have a module and need to try finding its pid. def wait_for(mod), do: wait_for(Process.whereis(mod)) - defp continue_waiting(pid) do + # Enter recursive loop + defp check_on_mbox(pid) do + Process.sleep(@wait_time) wait(pid, Process.info(pid, :message_queue_len)) end - defp wait(_pid, {:message_queue_len, 0}), do: Process.sleep(@wait_time) - - defp wait(pid, {:message_queue_len, _n}) do - Process.sleep(@wait_time) - continue_waiting(pid) - end + # Exit recursive loop + defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time) + # Continue recursive loop + defp wait(pid, {:message_queue_len, _n}), do: check_on_mbox(pid) defmacro expect_log(message) do quote do From 04c74b28f2ef3a031e606050d12522ffd537fe86 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 11:37:23 -0500 Subject: [PATCH 4/9] Replace Process.sleep() with Helpers.wait_for(pid) --- .../test/farmbot_ext/amqp/auto_sync_channel_test.exs | 4 ++-- farmbot_ext/test/test_helper.exs | 9 ++++++--- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_channel_test.exs b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_channel_test.exs index a9c17719..9edcb60e 100644 --- a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_channel_test.exs +++ b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_channel_test.exs @@ -55,7 +55,7 @@ defmodule AutoSyncChannelTest do expect(Preloader, :preload_all, 1, fn -> :ok end) pid = generate_pid() send(pid, msg) - Process.sleep(5) + Helpers.wait_for(pid) end test "basic_cancel", do: ensure_response_to({:basic_cancel, :anything}) @@ -153,6 +153,6 @@ defmodule AutoSyncChannelTest do :ok end) - Process.sleep(1200) + Helpers.wait_for(pid) end end diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index 378b7f50..9b5bff4c 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -23,7 +23,7 @@ defmodule Helpers do # Maybe I could use `start_supervised`? # https://hexdocs.pm/ex_unit/ExUnit.Callbacks.html#start_supervised/2 - @wait_time 13 + @wait_time 15 # Base case: We have a pid def wait_for(pid) when is_pid(pid), do: check_on_mbox(pid) # Failure case: We failed to find a pid for a module. @@ -37,8 +37,11 @@ defmodule Helpers do wait(pid, Process.info(pid, :message_queue_len)) end - # Exit recursive loop - defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time) + # Exit recursive loop (mbox is clear) + defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time * 3) + # Exit recursive loop (pid is dead) + defp wait(_, nil), do: Process.sleep(@wait_time * 3) + # Continue recursive loop defp wait(pid, {:message_queue_len, _n}), do: check_on_mbox(pid) From 431e05284af8d7e6feceb4059d92344c58d50a28 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 11:49:46 -0500 Subject: [PATCH 5/9] [farmbot_ext: 12.1%] AutoSyncAssetHandler test for when auto_sync?() is enabled --- .../farmbot_ext/amqp/auto_sync_asset_handler_test.exs | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs index 384a8cd5..ac80ac79 100644 --- a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs +++ b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs @@ -9,6 +9,7 @@ defmodule AutoSyncAssetHandlerTest do alias FarmbotCore.{Asset, BotState, Leds} def auto_sync_off, do: expect(Asset.Query, :auto_sync?, fn -> false end) + def auto_sync_on, do: expect(Asset.Query, :auto_sync?, fn -> true end) def expect_sync_status_to_be(status), do: expect(BotState, :set_sync_status, fn ^status -> :ok end) @@ -22,4 +23,13 @@ defmodule AutoSyncAssetHandlerTest do expect_green_leds(:slow_blink) AutoSyncAssetHandler.handle_asset("Point", 23, nil) end + + test "handling of deleted assets when auto_sync is enabled" do + auto_sync_on() + expect_sync_status_to_be("syncing") + expect_sync_status_to_be("synced") + expect_green_leds(:really_fast_blink) + expect_green_leds(:solid) + AutoSyncAssetHandler.handle_asset("Point", 32, nil) + end end From 78e44eeb817969e8fbdb8d8474533d1403a55fbf Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 11:53:18 -0500 Subject: [PATCH 6/9] Increase wait times to account for slowness of CI? --- farmbot_ext/test/test_helper.exs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index 9b5bff4c..57554e4d 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -23,7 +23,7 @@ defmodule Helpers do # Maybe I could use `start_supervised`? # https://hexdocs.pm/ex_unit/ExUnit.Callbacks.html#start_supervised/2 - @wait_time 15 + @wait_time 30 # Base case: We have a pid def wait_for(pid) when is_pid(pid), do: check_on_mbox(pid) # Failure case: We failed to find a pid for a module. @@ -38,9 +38,9 @@ defmodule Helpers do end # Exit recursive loop (mbox is clear) - defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time * 3) + defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time * 4) # Exit recursive loop (pid is dead) - defp wait(_, nil), do: Process.sleep(@wait_time * 3) + defp wait(_, nil), do: Process.sleep(@wait_time * 4) # Continue recursive loop defp wait(pid, {:message_queue_len, _n}), do: check_on_mbox(pid) From 1aac649e9bd3d905ef9f718fe1e9d135e24ca425 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 14:15:25 -0500 Subject: [PATCH 7/9] Test case: AutoSyncHnadler Handles @no_cache_kinds --- .../farmbot_ext/amqp/auto_sync_asset_handler_test.exs | 10 ++++++++++ farmbot_ext/test/test_helper.exs | 6 +++--- 2 files changed, 13 insertions(+), 3 deletions(-) diff --git a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs index ac80ac79..b4210edd 100644 --- a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs +++ b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs @@ -24,6 +24,16 @@ defmodule AutoSyncAssetHandlerTest do AutoSyncAssetHandler.handle_asset("Point", 23, nil) end + test "Handles @no_cache_kinds" do + id = 64 + params = %{} + kind = ~w(Device FbosConfig FirmwareConfig FarmwareEnv FarmwareInstallation) + |> Enum.shuffle + |> Enum.at(0) + expect(Asset.Command, :update, 1, fn ^kind, ^id, ^params -> :ok end) + assert :ok = AutoSyncAssetHandler.cache_sync(kind, id, params) + end + test "handling of deleted assets when auto_sync is enabled" do auto_sync_on() expect_sync_status_to_be("syncing") diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index 57554e4d..db51a065 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -23,7 +23,7 @@ defmodule Helpers do # Maybe I could use `start_supervised`? # https://hexdocs.pm/ex_unit/ExUnit.Callbacks.html#start_supervised/2 - @wait_time 30 + @wait_time 60 # Base case: We have a pid def wait_for(pid) when is_pid(pid), do: check_on_mbox(pid) # Failure case: We failed to find a pid for a module. @@ -38,9 +38,9 @@ defmodule Helpers do end # Exit recursive loop (mbox is clear) - defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time * 4) + defp wait(_, {:message_queue_len, 0}), do: Process.sleep(@wait_time * 3) # Exit recursive loop (pid is dead) - defp wait(_, nil), do: Process.sleep(@wait_time * 4) + defp wait(_, nil), do: Process.sleep(@wait_time * 3) # Continue recursive loop defp wait(pid, {:message_queue_len, _n}), do: check_on_mbox(pid) From 53f28daefea05fb7bf46b2d7a090dc28688b7255 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 14:45:14 -0500 Subject: [PATCH 8/9] Finish testing AutoSyncAssetHandler --- farmbot_ext/config/test.exs | 1 + .../amqp/auto_sync_asset_handler_test.exs | 27 ++++++++++++++++-- farmbot_ext/test/test_helper.exs | 28 +++++++++++-------- 3 files changed, 41 insertions(+), 15 deletions(-) diff --git a/farmbot_ext/config/test.exs b/farmbot_ext/config/test.exs index a6cd3dfe..54a47b28 100644 --- a/farmbot_ext/config/test.exs +++ b/farmbot_ext/config/test.exs @@ -1,6 +1,7 @@ use Mix.Config if Mix.env() == :test do + config :ex_unit, capture_logs: true mapper = fn mod -> config :farmbot_ext, mod, children: [] end list = [ diff --git a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs index b4210edd..3f619a28 100644 --- a/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs +++ b/farmbot_ext/test/farmbot_ext/amqp/auto_sync_asset_handler_test.exs @@ -1,4 +1,5 @@ defmodule AutoSyncAssetHandlerTest do + require Helpers use ExUnit.Case, async: false use Mimic @@ -8,6 +9,8 @@ defmodule AutoSyncAssetHandlerTest do alias FarmbotExt.AMQP.AutoSyncAssetHandler alias FarmbotCore.{Asset, BotState, Leds} + import ExUnit.CaptureLog + def auto_sync_off, do: expect(Asset.Query, :auto_sync?, fn -> false end) def auto_sync_on, do: expect(Asset.Query, :auto_sync?, fn -> true end) @@ -27,9 +30,12 @@ defmodule AutoSyncAssetHandlerTest do test "Handles @no_cache_kinds" do id = 64 params = %{} - kind = ~w(Device FbosConfig FirmwareConfig FarmwareEnv FarmwareInstallation) - |> Enum.shuffle - |> Enum.at(0) + + kind = + ~w(Device FbosConfig FirmwareConfig FarmwareEnv FarmwareInstallation) + |> Enum.shuffle() + |> Enum.at(0) + expect(Asset.Command, :update, 1, fn ^kind, ^id, ^params -> :ok end) assert :ok = AutoSyncAssetHandler.cache_sync(kind, id, params) end @@ -42,4 +48,19 @@ defmodule AutoSyncAssetHandlerTest do expect_green_leds(:solid) AutoSyncAssetHandler.handle_asset("Point", 32, nil) end + + test "cache sync" do + id = 64 + params = %{} + kind = "Point" + # Helpers.expect_log("Autocaching sync #{kind} #{id} #{inspect(params)}") + changeset = %{ab: :cd} + changesetfaker = fn ^kind, ^id, ^params -> changeset end + expect(FarmbotCore.Asset.Command, :new_changeset, 1, changesetfaker) + expect(FarmbotExt.API.EagerLoader, :cache, 1, fn ^changeset -> :ok end) + expect_sync_status_to_be("sync_now") + expect_green_leds(:slow_blink) + do_it = fn -> AutoSyncAssetHandler.cache_sync(kind, id, params) end + assert capture_log(do_it) =~ "Autocaching sync Point 64 %{}" + end end diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index db51a065..afe7455f 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -1,17 +1,21 @@ Application.ensure_all_started(:farmbot) -Mimic.copy(AMQP.Channel) -Mimic.copy(FarmbotCeleryScript.SysCalls.Stubs) -Mimic.copy(FarmbotCore.Asset.Command) -Mimic.copy(FarmbotCore.Asset.Query) -Mimic.copy(FarmbotCore.BotState) -Mimic.copy(FarmbotCore.Leds) -Mimic.copy(FarmbotCore.LogExecutor) -Mimic.copy(FarmbotExt.AMQP.ConnectionWorker) -Mimic.copy(FarmbotExt.API.EagerLoader.Supervisor) -Mimic.copy(FarmbotExt.API.Preloader) -Mimic.copy(FarmbotExt.API) -Mimic.copy(FarmbotExt.AMQP.AutoSyncAssetHandler) +[ + AMQP.Channel, + FarmbotCeleryScript.SysCalls.Stubs, + FarmbotCore.Asset.Command, + FarmbotCore.Asset.Query, + FarmbotCore.BotState, + FarmbotCore.Leds, + FarmbotCore.LogExecutor, + FarmbotExt.AMQP.AutoSyncAssetHandler, + FarmbotExt.AMQP.ConnectionWorker, + FarmbotExt.API, + FarmbotExt.API.EagerLoader, + FarmbotExt.API.EagerLoader.Supervisor, + FarmbotExt.API.Preloader, +] +|> Enum.map(&Mimic.copy/1) timeout = System.get_env("EXUNIT_TIMEOUT") || "5000" System.put_env("LOG_SILENCE", "true") From 0c4b14eb1bec8d466fbb815bfd7ee13b0b2d8c91 Mon Sep 17 00:00:00 2001 From: Rick Carlino Date: Tue, 31 Mar 2020 14:49:24 -0500 Subject: [PATCH 9/9] mix format --- farmbot_ext/test/test_helper.exs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/farmbot_ext/test/test_helper.exs b/farmbot_ext/test/test_helper.exs index afe7455f..40f2c1b8 100644 --- a/farmbot_ext/test/test_helper.exs +++ b/farmbot_ext/test/test_helper.exs @@ -13,7 +13,7 @@ Application.ensure_all_started(:farmbot) FarmbotExt.API, FarmbotExt.API.EagerLoader, FarmbotExt.API.EagerLoader.Supervisor, - FarmbotExt.API.Preloader, + FarmbotExt.API.Preloader ] |> Enum.map(&Mimic.copy/1)