fix: improve error handling for compiler diagnostics (#165)

Co-authored-by: Mitchell Hanberg <mitch@mitchellhanberg.com>

lib/next_ls/extensions/elixir_extension.ex

@@ -24,7 +24,7 @@ defmodule NextLS.ElixirExtension do
   end
 
   @impl GenServer
-  def handle_info({:compiler, diagnostics}, state) do
+  def handle_info({:compiler, diagnostics}, state) when is_list(diagnostics) do
     DiagnosticCache.clear(state.cache, :elixir)
 
     for d <- diagnostics do

lib/next_ls/runtime.ex

@@ -3,6 +3,7 @@ defmodule NextLS.Runtime do
   use GenServer
 
   @env Mix.env()
+  defguardp is_ready(state) when is_map_key(state, :node)
 
   def start_link(opts) do
     GenServer.start_link(__MODULE__, opts)
@@ -125,10 +126,10 @@ defmodule NextLS.Runtime do
           {:DOWN, ^ref, :process, ^me, reason} ->
             case reason do
               :shutdown ->
-                NextLS.Logger.log(logger, "The runtime for #{name} has successfully shutdown.")
+                NextLS.Logger.log(logger, "The runtime for #{name} has successfully shut down.")
 
               reason ->
-                NextLS.Logger.error(logger, "The runtime for #{name} has crashed with reason: #{reason}.")
+                NextLS.Logger.error(logger, "The runtime for #{name} has crashed with reason: #{inspect(reason)}")
             end
         end
       end)
@@ -144,8 +145,8 @@ defmodule NextLS.Runtime do
           |> Path.join("monkey/_next_ls_private_compiler.ex")
           |> then(&:rpc.call(node, Code, :compile_file, [&1]))
           |> tap(fn
-            {:badrpc, :EXIT, {error, _}} ->
-              NextLS.Logger.error(logger, error)
+            {:badrpc, error} ->
+              NextLS.Logger.error(logger, "Bad RPC call to node #{node}: #{inspect(error)}")
 
             _ ->
               :ok
@@ -155,9 +156,8 @@ defmodule NextLS.Runtime do
 
           send(me, {:node, node})
         else
-          _ ->
-            on_initialized.(:error)
-            send(me, :cancel)
+          error ->
+            send(me, {:cancel, error})
         end
       end)
 
@@ -180,35 +180,42 @@ defmodule NextLS.Runtime do
   end
 
   @impl GenServer
-  def handle_call(:ready?, _from, %{node: _node} = state) do
+  def handle_call(:ready?, _from, state) when is_ready(state) do
     {:reply, true, state}
   end
 
   def handle_call(:ready?, _from, state) do
     {:reply, false, state}
   end
 
+  def handle_call(_, _from, state) when not is_ready(state) do
+    {:reply, {:error, :not_ready}, state}
+  end
+
   def handle_call({:call, {m, f, a}}, _from, %{node: node} = state) do
     reply = :rpc.call(node, m, f, a)
     {:reply, {:ok, reply}, state}
   end
 
-  def handle_call({:call, _}, _from, state) do
-    {:reply, {:error, :not_ready}, state}
-  end
-
   def handle_call(:compile, from, %{node: node} = state) do
     task =
       Task.Supervisor.async_nolink(state.task_supervisor, fn ->
-        {_, errors} = :rpc.call(node, :_next_ls_private_compiler, :compile, [])
+        case :rpc.call(node, :_next_ls_private_compiler, :compile, []) do
+          {:badrpc, error} ->
+            NextLS.Logger.error(state.logger, "Bad RPC call to node #{node}: #{inspect(error)}")
+            []
 
-        Registry.dispatch(state.registry, :extensions, fn entries ->
-          for {pid, _} <- entries do
-            send(pid, {:compiler, errors})
-          end
-        end)
+          {_, diagnostics} when is_list(diagnostics) ->
+            Registry.dispatch(state.registry, :extensions, fn entries ->
+              for {pid, _} <- entries, do: send(pid, {:compiler, diagnostics})
+            end)
 
-        errors
+            diagnostics
+
+          unknown ->
+            NextLS.Logger.warning(state.logger, "Unexpected compiler response: #{inspect(unknown)}")
+            []
+        end
       end)
 
     {:noreply, %{state | compiler_ref: %{task.ref => from}}}
@@ -228,12 +235,29 @@ defmodule NextLS.Runtime do
     {:noreply, %{state | compiler_ref: nil}}
   end
 
+  def handle_info({:DOWN, _, :port, port, _}, %{port: port} = state) do
+    unless is_ready(state) do
+      state.on_initialized.({:error, :portdown})
+    end
+
+    {:stop, {:shutdown, :portdown}, state}
+  end
+
+  def handle_info({:cancel, error}, state) do
+    state.on_initialized.({:error, error})
+    {:stop, error, state}
+  end
+
   def handle_info({:node, node}, state) do
     Node.monitor(node, true)
     state.on_initialized.(:ready)
     {:noreply, Map.put(state, :node, node)}
   end
 
+  def handle_info({:nodedown, node}, %{node: node} = state) do
+    {:stop, {:shutdown, :nodedown}, state}
+  end
+
   def handle_info({port, {:data, data}}, %{port: port} = state) do
     NextLS.Logger.log(state.logger, data)
     {:noreply, state}

test/next_ls/runtime_test.exs

@@ -1,7 +1,6 @@
 defmodule NextLs.RuntimeTest do
   use ExUnit.Case, async: true
 
-  import ExUnit.CaptureLog
   import NextLS.Support.Utils
 
   alias NextLS.Runtime
@@ -23,11 +22,13 @@ defmodule NextLs.RuntimeTest do
     end
     """)
 
+    me = self()
+
     {:ok, logger} =
       Task.start_link(fn ->
         recv = fn recv ->
           receive do
-            msg -> Logger.debug(inspect(msg))
+            {:"$gen_cast", msg} -> send(me, msg)
           end
 
           recv.(recv)
@@ -36,68 +37,136 @@ defmodule NextLs.RuntimeTest do
         recv.(recv)
       end)
 
-    me = self()
+    on_init = fn msg -> send(me, msg) end
 
-    on_init = fn _ -> send(me, :ready) end
+    on_exit(&flush_messages/0)
 
     [logger: logger, cwd: Path.absname(tmp_dir), on_init: on_init]
   end
 
-  test "returns the response in an ok tuple", %{logger: logger, cwd: cwd, on_init: on_init} do
-    start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
-    tvisor = start_supervised!(Task.Supervisor)
+  describe "errors" do
+    test "emitted on crash during initialization",
+         %{tmp_dir: tmp_dir, logger: logger, cwd: cwd, on_init: on_init} do
+      # obvious syntax error
+      bad_mix_exs = String.replace(mix_exs(), "defmodule", "")
+      File.write!(Path.join(tmp_dir, "mix.exs"), bad_mix_exs)
+
+      start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+
+      tvisor = start_supervised!(Task.Supervisor)
 
-    pid =
       start_supervised!(
         {Runtime,
+         task_supervisor: tvisor,
          name: "my_proj",
          on_initialized: on_init,
-         task_supervisor: tvisor,
          working_dir: cwd,
          uri: "file://#{cwd}",
          parent: self(),
          logger: logger,
          db: :some_db,
-         registry: RuntimeTest.Registry}
+         registry: RuntimeTest.Registry},
+        restart: :temporary
       )
 
-    Process.link(pid)
+      assert_receive {:error, :portdown}
+
+      assert_receive {:log, :log, log_msg}
+      assert log_msg =~ "syntax error"
+
+      assert_receive {:log, :error, error_msg}
+      assert error_msg =~ "{:shutdown, :portdown}"
+    end
+
+    test "emitted on crash after initialization",
+         %{logger: logger, cwd: cwd, on_init: on_init} do
+      start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+
+      tvisor = start_supervised!(Task.Supervisor)
+
+      pid =
+        start_supervised!(
+          {Runtime,
+           task_supervisor: tvisor,
+           name: "my_proj",
+           on_initialized: on_init,
+           working_dir: cwd,
+           uri: "file://#{cwd}",
+           parent: self(),
+           logger: logger,
+           db: :some_db,
+           registry: RuntimeTest.Registry},
+          restart: :temporary
+        )
+
+      assert_receive :ready
 
-    assert wait_for_ready()
+      assert {:ok, {:badrpc, :nodedown}} = Runtime.call(pid, {System, :halt, [1]})
 
-    assert {:ok, "\"hi\""} = Runtime.call(pid, {Kernel, :inspect, ["hi"]})
+      assert_receive {:log, :error, error_msg}
+      assert error_msg =~ "{:shutdown, :nodedown}"
+    end
   end
 
-  test "call returns an error when the runtime is node ready", %{logger: logger, cwd: cwd, on_init: on_init} do
-    start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+  describe "call/2" do
+    test "responds with an ok tuple if the runtime has initialized",
+         %{logger: logger, cwd: cwd, on_init: on_init} do
+      start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+      tvisor = start_supervised!(Task.Supervisor)
 
-    tvisor = start_supervised!(Task.Supervisor)
+      pid =
+        start_supervised!(
+          {Runtime,
+           name: "my_proj",
+           on_initialized: on_init,
+           task_supervisor: tvisor,
+           working_dir: cwd,
+           uri: "file://#{cwd}",
+           parent: self(),
+           logger: logger,
+           db: :some_db,
+           registry: RuntimeTest.Registry}
+        )
 
-    pid =
-      start_supervised!(
-        {Runtime,
-         task_supervisor: tvisor,
-         name: "my_proj",
-         on_initialized: on_init,
-         working_dir: cwd,
-         uri: "file://#{cwd}",
-         parent: self(),
-         logger: logger,
-         db: :some_db,
-         registry: RuntimeTest.Registry}
-      )
+      Process.link(pid)
+
+      assert_receive :ready
 
-    Process.link(pid)
+      assert {:ok, "\"hi\""} = Runtime.call(pid, {Kernel, :inspect, ["hi"]})
+    end
+
+    test "responds with an error when the runtime hasn't initialized", %{logger: logger, cwd: cwd, on_init: on_init} do
+      start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+
+      tvisor = start_supervised!(Task.Supervisor)
+
+      pid =
+        start_supervised!(
+          {Runtime,
+           task_supervisor: tvisor,
+           name: "my_proj",
+           on_initialized: on_init,
+           working_dir: cwd,
+           uri: "file://#{cwd}",
+           parent: self(),
+           logger: logger,
+           db: :some_db,
+           registry: RuntimeTest.Registry}
+        )
 
-    assert {:error, :not_ready} = Runtime.call(pid, {IO, :puts, ["hi"]})
+      Process.link(pid)
+
+      assert {:error, :not_ready} = Runtime.call(pid, {IO, :puts, ["hi"]})
+    end
   end
 
-  test "compiles the code and returns diagnostics", %{logger: logger, cwd: cwd, on_init: on_init} do
-    start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+  describe "compile/1" do
+    test "compiles the project and returns diagnostics",
+         %{logger: logger, cwd: cwd, on_init: on_init} do
+      start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
 
-    tvisor = start_supervised!(Task.Supervisor)
+      tvisor = start_supervised!(Task.Supervisor)
 
-    capture_log(fn ->
       pid =
         start_link_supervised!(
           {Runtime,
@@ -112,7 +181,7 @@ defmodule NextLs.RuntimeTest do
            registry: RuntimeTest.Registry}
         )
 
-      assert wait_for_ready()
+      assert_receive :ready
 
       file = Path.join(cwd, "lib/bar.ex")
 
@@ -143,15 +212,38 @@ defmodule NextLs.RuntimeTest do
       """)
 
       assert [] == Runtime.compile(pid)
-    end) =~ "Connected to node"
+    end
+
+    test "responds with an error when the runtime isn't ready", %{logger: logger, cwd: cwd, on_init: on_init} do
+      start_supervised!({Registry, keys: :duplicate, name: RuntimeTest.Registry})
+
+      tvisor = start_supervised!(Task.Supervisor)
+
+      pid =
+        start_supervised!(
+          {Runtime,
+           task_supervisor: tvisor,
+           name: "my_proj",
+           on_initialized: on_init,
+           working_dir: cwd,
+           uri: "file://#{cwd}",
+           parent: self(),
+           logger: logger,
+           db: :some_db,
+           registry: RuntimeTest.Registry}
+        )
+
+      Process.link(pid)
+
+      assert {:error, :not_ready} = Runtime.compile(pid)
+    end
   end
 
-  defp wait_for_ready do
+  defp flush_messages do
     receive do
-      :ready -> true
+      _ -> flush_messages()
     after
-      30_000 ->
-        false
+      0 -> :ok
     end
   end
 end

test/next_ls/workspaces_test.exs

@@ -89,7 +89,7 @@ defmodule NextLS.WorkspacesTest do
       }
     })
 
-    message = "[NextLS] The runtime for #{context.module}-proj_two has successfully shutdown."
+    message = "[NextLS] The runtime for #{context.module}-proj_two has successfully shut down."
 
     assert_notification "window/logMessage", %{
       "message" => ^message