Repository: commanded/commanded
Pull request #340 (2020-02-16 14:44:51)

Add stacktraces to EventHandler error logging
### Issue
#303 

### Description
This PR logs the stacktrace when a user-written EventHandler raises an error. 

Note that I hacked in a test scenario, there might be a better way of doing that. I'm open to suggestions.

<img width="1649" alt="Screen Shot 2020-02-16 at 9 35 45 AM" src="https://user-images.githubusercontent.com/1019721/74606739-ef6b5680-50a0-11ea-84c8-5e2c1ae388a9.png">



Patch:
diff --git a/.tool-versions b/.tool-versions
deleted file mode 100644
index 2299dc5..0000000
--- a/.tool-versions
+++ /dev/null
@@ -1,1 +0,0 @@
-elixir 1.10.1-otp-22
diff --git a/CHANGELOG.md b/CHANGELOG.md
index 5e20a34..ec386b1 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -7,10 +7,8 @@
 - Dynamic Commanded applications ([#324](https://github.com/commanded/commanded/pull/324)).
 - Command dispatch return ([#331](https://github.com/commanded/commanded/pull/331)).
 - Log and ignore unexpected messages received by event handlers and process manager instances ([#333](https://github.com/commanded/commanded/pull/333))
-- Process manager `identity/0` function ([#334](https://github.com/commanded/commanded/pull/334)).
 - Extend `Commanded.AggregateCase` ExUnit case template to support `Commanded.Aggregate.Multi`.
 - Allow `Commanded.Aggregate.Multi` to return events as `:ok` tagged tuples.
-- Run the formatter in CI ([#341](https://github.com/commanded/commanded/pull/341)).
 
 ### Bug fixes
 
@@ -225,6 +223,7 @@ Commanded scheduler:
 - Handle custom type serialization in snapshot source type ([#165](https://github.com/commanded/commanded/pull/165)).
 - Fix compiler warnings in generated code (routers, event handlers, and process managers).
 - Add `InMemory.reset!/0` for testing purposes ([#175](https://github.com/commanded/commanded/pull/175)).
+- Process manager `indentity/0` function ([#334](https://github.com/commanded/commanded/pull/334)).
 
 ### Bug fixes
 
diff --git a/README.md b/README.md
index 6eb69c5..cb111cc 100644
--- a/README.md
+++ b/README.md
@@ -137,7 +137,6 @@ Commanded exists thanks to the following people who have contributed.
 - [Brenton Annan](https://github.com/brentonannan)
 - [Chris Brodt](https://github.com/uberbrodt)
 - [Chris Martin](https://github.com/trbngr)
-- [Dave Lucia](https://github.com/davydog187)
 - [David Carlin](https://github.com/davich)
 - [Danni Friedland](https://github.com/BlueHotDog)
 - [Fernando Mendes](https://github.com/justmendes)
diff --git a/lib/commanded/aggregates/supervisor.ex b/lib/commanded/aggregates/supervisor.ex
index 8fc9e85..e7d1020 100644
--- a/lib/commanded/aggregates/supervisor.ex
+++ b/lib/commanded/aggregates/supervisor.ex
@@ -19,7 +19,7 @@ defmodule Commanded.Aggregates.Supervisor do
 
   @doc """
   Open an aggregate instance process for the given aggregate module and unique
-  identity.
+  indentity.
 
   Returns `{:ok, aggregate_uuid}` when a process is sucessfully started, or is
   already running.
diff --git a/lib/commanded/assertions/event_assertions.ex b/lib/commanded/assertions/event_assertions.ex
index e6169a4..51265ed 100644
--- a/lib/commanded/assertions/event_assertions.ex
+++ b/lib/commanded/assertions/event_assertions.ex
@@ -70,7 +70,7 @@ defmodule Commanded.Assertions.EventAssertions do
 
   """
   def assert_receive_event(application, event_type, predicate_fn, assertion_fn) do
-    unless Code.ensure_loaded?(event_type) do
+    unless Code.ensure_compiled?(event_type) do
       raise ExUnit.AssertionError, "Event #{inspect(event_type)} not found"
     end
 
diff --git a/lib/commanded/commands/router.ex b/lib/commanded/commands/router.ex
index deab1fc..acde444 100644
--- a/lib/commanded/commands/router.ex
+++ b/lib/commanded/commands/router.ex
@@ -606,14 +606,8 @@ defmodule Commanded.Commands.Router do
 
   @doc false
   def ensure_module_exists(module) do
-    case Code.ensure_compiled(module) do
-      {:module, ^module} ->
-        :ok
-
-      {:error, _error} ->
-        raise ArgumentError,
-          message:
-            "module `#{inspect(module)}` does not exist, perhaps you forgot to `alias` the namespace"
+    unless Code.ensure_compiled?(module) do
+      raise "module `#{inspect(module)}` does not exist, perhaps you forgot to `alias` the namespace"
     end
   end
 
diff --git a/lib/commanded/event/handler.ex b/lib/commanded/event/handler.ex
index 96735c7..8f48094 100644
--- a/lib/commanded/event/handler.ex
+++ b/lib/commanded/event/handler.ex
@@ -551,7 +551,9 @@ defmodule Commanded.Event.Handler do
   @doc false
   @impl GenServer
   def handle_info(message, state) do
-    Logger.error(fn -> describe(state) <> " received unexpected message: " <> inspect(message) end)
+    Logger.error(fn ->
+      describe(state) <> " received unexpected message: " <> inspect(message, pretty: true)
+    end)
 
     {:noreply, state}
   end
@@ -622,10 +624,24 @@ defmodule Commanded.Event.Handler do
       {:error, reason} = error ->
         Logger.error(fn ->
           describe(state) <>
-            " failed to handle event #{inspect(event)} due to: #{inspect(reason)}"
+            " failed to handle event #{inspect(event, pretty: true)} due to: #{
+              inspect(reason, pretty: true)
+            }"
         end)
 
         handle_event_error(error, event, state, context)
+
+      {:error, reason, stacktrace} ->
+        Logger.error(fn ->
+          describe(state) <>
+            " failed to handle event #{inspect(event, pretty: true)} due to: #{
+              inspect(reason, pretty: true)
+            }"
+        end)
+
+        Logger.error(fn -> Exception.format(:error, reason, stacktrace) end)
+
+        handle_event_error({:error, reason}, event, state, context)
     end
   end
 
@@ -638,7 +654,7 @@ defmodule Commanded.Event.Handler do
     try do
       handler_module.handle(data, metadata)
     rescue
-      e -> {:error, e}
+      e -> {:error, e, __STACKTRACE__}
     end
   end
 
diff --git a/lib/commanded/event_store.ex b/lib/commanded/event_store.ex
index fb41e29..9b758da 100644
--- a/lib/commanded/event_store.ex
+++ b/lib/commanded/event_store.ex
@@ -181,7 +181,7 @@ defmodule Commanded.EventStore do
   def adapter(application, config) do
     {adapter, config} = Keyword.pop(config, :adapter)
 
-    unless Code.ensure_loaded?(adapter) do
+    unless Code.ensure_compiled?(adapter) do
       raise ArgumentError,
             "event store adapter " <>
               inspect(adapter) <>
diff --git a/mix.lock b/mix.lock
index 4501ba2..fca76ff 100644
--- a/mix.lock
+++ b/mix.lock
@@ -1,16 +1,16 @@
 %{
-  "benchfella": {:hex, :benchfella, "0.3.5", "b2122c234117b3f91ed7b43b6e915e19e1ab216971154acd0a80ce0e9b8c05f5", [:mix], [], "hexpm", "23f27cbc482cbac03fc8926441eb60a5e111759c17642bac005c3225f5eb809d"},
-  "dialyxir": {:hex, :dialyxir, "1.0.0-rc.7", "6287f8f2cb45df8584317a4be1075b8c9b8a69de8eeb82b4d9e6c761cf2664cd", [:mix], [{:erlex, ">= 0.2.5", [hex: :erlex, repo: "hexpm", optional: false]}], "hexpm", "506294d6c543e4e5282d4852aead19ace8a35bedeb043f9256a06a6336827122"},
-  "earmark": {:hex, :earmark, "1.4.3", "364ca2e9710f6bff494117dbbd53880d84bebb692dafc3a78eb50aa3183f2bfd", [:mix], [], "hexpm", "8cf8a291ebf1c7b9539e3cddb19e9cef066c2441b1640f13c34c1d3cfc825fec"},
-  "elixir_uuid": {:hex, :elixir_uuid, "1.2.1", "dce506597acb7e6b0daeaff52ff6a9043f5919a4c3315abb4143f0b00378c097", [:mix], [], "hexpm", "f7eba2ea6c3555cea09706492716b0d87397b88946e6380898c2889d68585752"},
-  "erlex": {:hex, :erlex, "0.2.5", "e51132f2f472e13d606d808f0574508eeea2030d487fc002b46ad97e738b0510", [:mix], [], "hexpm", "756d3e19b056339af674b715fdd752c5dac468cf9d0e2d1a03abf4574e99fbf8"},
-  "ex_doc": {:hex, :ex_doc, "0.21.3", "857ec876b35a587c5d9148a2512e952e24c24345552259464b98bfbb883c7b42", [:mix], [{:earmark, "~> 1.4", [hex: :earmark, repo: "hexpm", optional: false]}, {:makeup_elixir, "~> 0.14", [hex: :makeup_elixir, repo: "hexpm", optional: false]}], "hexpm", "0db1ee8d1547ab4877c5b5dffc6604ef9454e189928d5ba8967d4a58a801f161"},
-  "file_system": {:hex, :file_system, "0.2.8", "f632bd287927a1eed2b718f22af727c5aeaccc9a98d8c2bd7bff709e851dc986", [:mix], [], "hexpm", "97a3b6f8d63ef53bd0113070102db2ce05352ecf0d25390eb8d747c2bde98bca"},
-  "jason": {:hex, :jason, "1.1.2", "b03dedea67a99223a2eaf9f1264ce37154564de899fd3d8b9a21b1a6fd64afe7", [:mix], [{:decimal, "~> 1.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "fdf843bca858203ae1de16da2ee206f53416bbda5dc8c9e78f43243de4bc3afe"},
-  "makeup": {:hex, :makeup, "1.0.0", "671df94cf5a594b739ce03b0d0316aa64312cee2574b6a44becb83cd90fb05dc", [:mix], [{:nimble_parsec, "~> 0.5.0", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "a10c6eb62cca416019663129699769f0c2ccf39428b3bb3c0cb38c718a0c186d"},
-  "makeup_elixir": {:hex, :makeup_elixir, "0.14.0", "cf8b7c66ad1cff4c14679698d532f0b5d45a3968ffbcbfd590339cb57742f1ae", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "d4b316c7222a85bbaa2fd7c6e90e37e953257ad196dc229505137c5e505e9eff"},
-  "mix_test_watch": {:hex, :mix_test_watch, "1.0.2", "34900184cbbbc6b6ed616ed3a8ea9b791f9fd2088419352a6d3200525637f785", [:mix], [{:file_system, "~> 0.2.1 or ~> 0.3", [hex: :file_system, repo: "hexpm", optional: false]}], "hexpm", "47ac558d8b06f684773972c6d04fcc15590abdb97aeb7666da19fcbfdc441a07"},
-  "mox": {:hex, :mox, "0.5.1", "f86bb36026aac1e6f924a4b6d024b05e9adbed5c63e8daa069bd66fb3292165b", [:mix], [], "hexpm", "052346cf322311c49a0f22789f3698eea030eec09b8c47367f0686ef2634ae14"},
-  "nimble_parsec": {:hex, :nimble_parsec, "0.5.3", "def21c10a9ed70ce22754fdeea0810dafd53c2db3219a0cd54cf5526377af1c6", [:mix], [], "hexpm", "589b5af56f4afca65217a1f3eb3fee7e79b09c40c742fddc1c312b3ac0b3399f"},
-  "phoenix_pubsub": {:hex, :phoenix_pubsub, "1.1.2", "496c303bdf1b2e98a9d26e89af5bba3ab487ba3a3735f74bf1f4064d2a845a3e", [:mix], [], "hexpm", "1f13f9f0f3e769a667a6b6828d29dec37497a082d195cc52dbef401a9b69bf38"},
+  "benchfella": {:hex, :benchfella, "0.3.5", "b2122c234117b3f91ed7b43b6e915e19e1ab216971154acd0a80ce0e9b8c05f5", [:mix], [], "hexpm"},
+  "dialyxir": {:hex, :dialyxir, "1.0.0-rc.7", "6287f8f2cb45df8584317a4be1075b8c9b8a69de8eeb82b4d9e6c761cf2664cd", [:mix], [{:erlex, ">= 0.2.5", [hex: :erlex, repo: "hexpm", optional: false]}], "hexpm"},
+  "earmark": {:hex, :earmark, "1.4.2", "3aa0bd23bc4c61cf2f1e5d752d1bb470560a6f8539974f767a38923bb20e1d7f", [:mix], [], "hexpm"},
+  "elixir_uuid": {:hex, :elixir_uuid, "1.2.1", "dce506597acb7e6b0daeaff52ff6a9043f5919a4c3315abb4143f0b00378c097", [:mix], [], "hexpm"},
+  "erlex": {:hex, :erlex, "0.2.5", "e51132f2f472e13d606d808f0574508eeea2030d487fc002b46ad97e738b0510", [:mix], [], "hexpm"},
+  "ex_doc": {:hex, :ex_doc, "0.21.2", "caca5bc28ed7b3bdc0b662f8afe2bee1eedb5c3cf7b322feeeb7c6ebbde089d6", [:mix], [{:earmark, "~> 1.3.3 or ~> 1.4", [hex: :earmark, repo: "hexpm", optional: false]}, {:makeup_elixir, "~> 0.14", [hex: :makeup_elixir, repo: "hexpm", optional: false]}], "hexpm"},
+  "file_system": {:hex, :file_system, "0.2.7", "e6f7f155970975789f26e77b8b8d8ab084c59844d8ecfaf58cbda31c494d14aa", [:mix], [], "hexpm"},
+  "jason": {:hex, :jason, "1.1.2", "b03dedea67a99223a2eaf9f1264ce37154564de899fd3d8b9a21b1a6fd64afe7", [:mix], [{:decimal, "~> 1.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm"},
+  "makeup": {:hex, :makeup, "1.0.0", "671df94cf5a594b739ce03b0d0316aa64312cee2574b6a44becb83cd90fb05dc", [:mix], [{:nimble_parsec, "~> 0.5.0", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm"},
+  "makeup_elixir": {:hex, :makeup_elixir, "0.14.0", "cf8b7c66ad1cff4c14679698d532f0b5d45a3968ffbcbfd590339cb57742f1ae", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm"},
+  "mix_test_watch": {:hex, :mix_test_watch, "1.0.2", "34900184cbbbc6b6ed616ed3a8ea9b791f9fd2088419352a6d3200525637f785", [:mix], [{:file_system, "~> 0.2.1 or ~> 0.3", [hex: :file_system, repo: "hexpm", optional: false]}], "hexpm"},
+  "mox": {:hex, :mox, "0.5.1", "f86bb36026aac1e6f924a4b6d024b05e9adbed5c63e8daa069bd66fb3292165b", [:mix], [], "hexpm"},
+  "nimble_parsec": {:hex, :nimble_parsec, "0.5.2", "1d71150d5293d703a9c38d4329da57d3935faed2031d64bc19e77b654ef2d177", [:mix], [], "hexpm"},
+  "phoenix_pubsub": {:hex, :phoenix_pubsub, "1.1.2", "496c303bdf1b2e98a9d26e89af5bba3ab487ba3a3735f74bf1f4064d2a845a3e", [:mix], [], "hexpm"},
 }


Test patch:
diff --git a/test/aggregates/event_persistence_test.exs b/test/aggregates/event_persistence_test.exs
index 0ceac41..ed27cd9 100644
--- a/test/aggregates/event_persistence_test.exs
+++ b/test/aggregates/event_persistence_test.exs
@@ -163,7 +163,7 @@ defmodule Commanded.Aggregates.EventPersistenceTest do
              }
   end
 
-  test "should prefix stream UUID with aggregate identity prefix" do
+  test "should prefix stream UUID with aggregate indentity prefix" do
     aggregate_uuid = UUID.uuid4()
     prefix = "example-prefix-"
     prefixed_aggregate_uuid = prefix <> aggregate_uuid
diff --git a/test/commands/routing_commands_test.exs b/test/commands/routing_commands_test.exs
index eb95ef0..152cb6e 100644
--- a/test/commands/routing_commands_test.exs
+++ b/test/commands/routing_commands_test.exs
@@ -253,7 +253,7 @@ defmodule Commanded.Commands.RoutingCommandsTest do
   end
 
   test "should prevent registrations for a invalid command module" do
-    assert_raise ArgumentError,
+    assert_raise RuntimeError,
                  "module `UnknownCommand` does not exist, perhaps you forgot to `alias` the namespace",
                  fn ->
                    Code.eval_string("""
@@ -270,7 +270,7 @@ defmodule Commanded.Commands.RoutingCommandsTest do
   end
 
   test "should prevent registrations for an invalid command handler module" do
-    assert_raise ArgumentError,
+    assert_raise RuntimeError,
                  "module `UnknownHandler` does not exist, perhaps you forgot to `alias` the namespace",
                  fn ->
                    Code.eval_string("""
@@ -287,7 +287,7 @@ defmodule Commanded.Commands.RoutingCommandsTest do
   end
 
   test "should prevent registrations for an invalid aggregate module" do
-    assert_raise ArgumentError,
+    assert_raise RuntimeError,
                  "module `UnknownAggregate` does not exist, perhaps you forgot to `alias` the namespace",
                  fn ->
                    Code.eval_string("""
diff --git a/test/event/event_handler_subscription_test.exs b/test/event/event_handler_subscription_test.exs
index 9b3cd84..896a884 100644
--- a/test/event/event_handler_subscription_test.exs
+++ b/test/event/event_handler_subscription_test.exs
@@ -27,7 +27,7 @@ defmodule Commanded.Event.EventHandlerSubscriptionTest do
 
       shutdown_subscription(subscription)
 
-      assert_receive {:DOWN, ^ref, :process, ^handler, _reason}
+      assert_receive {:DOWN, ^ref, :process, ^handler, :normal}
     end
   end
 
diff --git a/test/event/handle_event_test.exs b/test/event/handle_event_test.exs
index 3ba8ceb..61e8e6d 100644
--- a/test/event/handle_event_test.exs
+++ b/test/event/handle_event_test.exs
@@ -10,6 +10,7 @@ defmodule Commanded.Event.HandleEventTest do
   alias Commanded.Event.UninterestingEvent
   alias Commanded.Helpers.EventFactory
   alias Commanded.Helpers.Wait
+  alias Commanded.Event.ErrorEvent
   alias Commanded.ExampleDomain.BankApp
   alias Commanded.ExampleDomain.BankAccount.AccountBalanceHandler
   alias Commanded.ExampleDomain.BankAccount.BankAccountHandler
@@ -77,6 +78,29 @@ defmodule Commanded.Event.HandleEventTest do
       assert capture_log(send_unexpected_mesage) =~
                "Commanded.ExampleDomain.BankAccount.AccountBalanceHandler received unexpected message: :unexpected_message"
     end
+
+    test "should print the stack trace on errors", %{handler: handler} do
+      import ExUnit.CaptureLog
+
+      events = [
+        %ErrorEvent{}
+      ]
+
+      ref = Process.monitor(handler)
+
+      recorded_events = EventFactory.map_to_recorded_events(events)
+
+      send_error_message = fn ->
+        send(handler, {:events, recorded_events})
+        assert_receive {:DOWN, ^ref, :process, ^handler, _}
+      end
+
+      captured = capture_log(send_error_message)
+
+      assert captured =~ "(RuntimeError) ErrorEvent occurred"
+      assert captured =~ "test/example_domain/bank_account/account_balance_handler.ex"
+      assert captured =~ "Commanded.ExampleDomain.BankAccount.AccountBalanceHandler.handle/2"
+    end
   end
 
   describe "reset event handler" do
diff --git a/test/event/support/error_event.ex b/test/event/support/error_event.ex
new file mode 100644
index 0000000..d0432a7
--- /dev/null
+++ b/test/event/support/error_event.ex
@@ -0,0 +1,4 @@
+defmodule Commanded.Event.ErrorEvent do
+  @moduledoc false
+  defstruct field: nil
+end
diff --git a/test/example_domain/bank_account/account_balance_handler.ex b/test/example_domain/bank_account/account_balance_handler.ex
index 58cbf97..a8ec2c1 100644
--- a/test/example_domain/bank_account/account_balance_handler.ex
+++ b/test/example_domain/bank_account/account_balance_handler.ex
@@ -8,6 +8,7 @@ defmodule Commanded.ExampleDomain.BankAccount.AccountBalanceHandler do
   alias Commanded.ExampleDomain.BankAccount.Events.BankAccountOpened
   alias Commanded.ExampleDomain.BankAccount.Events.MoneyDeposited
   alias Commanded.ExampleDomain.BankAccount.Events.MoneyWithdrawn
+  alias Commanded.Event.ErrorEvent
 
   def init do
     with {:ok, _pid} <- Agent.start_link(fn -> 0 end, name: __MODULE__) do
@@ -27,6 +28,10 @@ defmodule Commanded.ExampleDomain.BankAccount.AccountBalanceHandler do
     Agent.update(__MODULE__, fn _ -> balance end)
   end
 
+  def handle(%ErrorEvent{}, _metadata) do
+    raise "ErrorEvent occurred"
+  end
+
   def subscribed? do
     try do
       Agent.get(__MODULE__, fn _ -> true end)
diff --git a/test/example_domain/bank_account/bank_account.ex b/test/example_domain/bank_account/bank_account.ex
index 29fb7a8..8fb90dd 100644
--- a/test/example_domain/bank_account/bank_account.ex
+++ b/test/example_domain/bank_account/bank_account.ex
@@ -49,6 +49,11 @@ defmodule Commanded.ExampleDomain.BankAccount do
       @derive Jason.Encoder
       defstruct [:account_number]
     end
+
+    defmodule BankAccountClosed do
+      @derive Jason.Encoder
+      defstruct [:account_number]
+    end
   end
 
   alias Commands.OpenAccount
diff --git a/test/process_managers/process_manager_subscription_test.exs b/test/process_managers/process_manager_subscription_test.exs
index c69ff11..58e0ef6 100644
--- a/test/process_managers/process_manager_subscription_test.exs
+++ b/test/process_managers/process_manager_subscription_test.exs
@@ -32,7 +32,7 @@ defmodule Commanded.ProcessManagers.ProcessManagerSubscriptionTest do
 
       shutdown_subscription(subscription)
 
-      assert_receive {:DOWN, ^ref, :process, ^pm, _reason}
+      assert_receive {:DOWN, ^ref, :process, ^pm, :normal}
     end
   end