fix: properly log when engine fails to initialize (#244)

* feat: properly respond to and log initialization errors

* Allow the engine to start asynchronously

It can take many seconds until the engine is available, hence editors
might time out the initialization.

We still at least send an error $window/logMessage with the
initialization error when it happens.

* Address review concerns

- Also show errors in the client via window/showMessage
- Improve logging cases
- Only register with nodemapper when node started ok
- For now do not introduce full expert test

* Reintroduce full server testing with different approach

Now we start manually all application children instead of ensuring the
application has started

* Remove full server testing, too problematic for now

* Address a few further review concerns

* Expert test is async safe

* Log project uri

Author: badosu

apps/expert/lib/expert.ex

@@ -1,8 +1,10 @@
 defmodule Expert do
+  alias Expert.Project
   alias Expert.Protocol.Convert
   alias Expert.Protocol.Id
   alias Expert.Provider.Handlers
   alias Expert.State
+  alias GenLSP.Enumerations
   alias GenLSP.Requests
   alias GenLSP.Structures
 
@@ -51,19 +53,33 @@ defmodule Expert do
 
   def handle_request(%GenLSP.Requests.Initialize{} = request, lsp) do
     state = assigns(lsp).state
-    Process.send_after(self(), :default_config, :timer.seconds(5))
 
-    case State.initialize(state, request) do
-      {:ok, response, state} ->
-        lsp = assign(lsp, state: state)
-        {:ok, response} = Expert.Protocol.Convert.to_lsp(response)
+    with {:ok, response, state} <- State.initialize(state, request),
+         {:ok, response} <- Expert.Protocol.Convert.to_lsp(response) do
+      Task.Supervisor.start_child(:expert_task_queue, fn ->
+        config = state.configuration
 
-        {:reply, response, lsp}
+        log_info(lsp, "Starting project")
+
+        start_result = Project.Supervisor.start(config.project)
 
-      {:error, error} ->
+        send(Expert, {:engine_initialized, start_result})
+      end)
+
+      {:reply, response, assign(lsp, state: state)}
+    else
+      {:error, :already_initialized} ->
         response = %GenLSP.ErrorResponse{
           code: GenLSP.Enumerations.ErrorCodes.invalid_request(),
-          message: to_string(error)
+          message: "Already initialized"
+        }
+
+        {:reply, response, lsp}
+
+      {:error, reason} ->
+        response = %GenLSP.ErrorResponse{
+          code: GenLSP.Enumerations.ErrorCodes.server_not_initialized(),
+          message: "Failed to initialize: #{inspect(reason)}"
         }
 
         {:reply, response, lsp}
@@ -173,7 +189,7 @@ defmodule Expert do
     end
   end
 
-  def handle_info(:engine_initialized, lsp) do
+  def handle_info({:engine_initialized, {:ok, _pid}}, lsp) do
     state = assigns(lsp).state
 
     new_state = %{state | engine_initialized?: true}
@@ -185,20 +201,33 @@ defmodule Expert do
     {:noreply, lsp}
   end
 
-  def handle_info(:default_config, lsp) do
-    state = assigns(lsp).state
+  def handle_info({:engine_initialized, {:error, reason}}, lsp) do
+    error_message = initialization_error_message(reason)
+    log_error(lsp, error_message)
 
-    if state.configuration == nil do
-      Logger.warning(
-        "Did not receive workspace/didChangeConfiguration notification after 5 seconds. " <>
-          "Using default settings."
-      )
+    {:noreply, lsp}
+  end
 
-      {:ok, config} = State.default_configuration(state)
-      {:noreply, assign(lsp, state: %{state | configuration: config})}
-    else
-      {:noreply, lsp}
-    end
+  def log_info(lsp \\ get_lsp(), message) do
+    message = log_prepend_project_root(message, assigns(lsp).state)
+
+    Logger.info(message)
+    GenLSP.info(lsp, message)
+  end
+
+  # When logging errors we also notify the client to display the message
+  def log_error(lsp \\ get_lsp(), message) do
+    message = log_prepend_project_root(message, assigns(lsp).state)
+
+    Logger.error(message)
+    GenLSP.error(lsp, message)
+
+    GenLSP.notify(lsp, %GenLSP.Notifications.WindowShowMessage{
+      params: %GenLSP.Structures.ShowMessageParams{
+        type: Enumerations.MessageType.error(),
+        message: message
+      }
+    })
   end
 
   defp apply_to_state(%State{} = state, %{} = request_or_notification) do
@@ -273,4 +302,41 @@ defmodule Expert do
       register_options: %Structures.DidChangeWatchedFilesRegistrationOptions{watchers: watchers}
     }
   end
+
+  defp initialization_error_message({:shutdown, {:failed_to_start_child, child, {reason, _}}}) do
+    case child do
+      {Project.Node, node_name} ->
+        node_initialization_message(node_name, reason)
+
+      child ->
+        "Failed to start child #{inspect(child)}: #{inspect(reason)}"
+    end
+  end
+
+  defp initialization_error_message(reason) do
+    "Failed to initialize: #{inspect(reason)}"
+  end
+
+  defp node_initialization_message(name, reason) do
+    case reason do
+      # NOTE:
+      # ** (Mix.Error) httpc request failed with: ... Could not install Hex because Mix could not download metadata ...
+      {:shutdown, {:error, :normal, message}} ->
+        "Engine #{name} shutdown with error:\n\n#{message}"
+
+      {:shutdown, {:node_exit, node_exit}} ->
+        "Engine #{name} exit with status #{node_exit.status}, last message:\n\n#{node_exit.last_message}"
+
+      reason ->
+        "Failed to start engine #{name}: #{inspect(reason)}"
+    end
+  end
+
+  defp log_prepend_project_root(message, %State{
+         configuration: %Expert.Configuration{project: %Forge.Project{} = project}
+       }) do
+    "[Project #{project.root_uri}] #{message}"
+  end
+
+  defp log_prepend_project_root(message, _state), do: message
 end

apps/expert/lib/expert/application.ex

@@ -66,7 +66,18 @@ defmodule Expert.Application do
 
     ensure_epmd_module!()
 
-    children = [
+    LogFilter.hook_into_logger()
+
+    children_spec = children(buffer: buffer_opts)
+    opts = [strategy: :one_for_one, name: Expert.Supervisor]
+
+    Supervisor.start_link(children_spec, opts)
+  end
+
+  def children(opts) do
+    buffer_opts = Keyword.fetch!(opts, :buffer)
+
+    [
       {Forge.NodePortMapper, []},
       document_store_child_spec(),
       {DynamicSupervisor, Expert.Project.DynamicSupervisor.options()},
@@ -81,11 +92,6 @@ defmodule Expert.Application do
        dynamic_supervisor: Expert.DynamicSupervisor,
        assigns: Expert.Assigns}
     ]
-
-    LogFilter.hook_into_logger()
-
-    opts = [strategy: :one_for_one, name: Expert.Supervisor]
-    Supervisor.start_link(children, opts)
   end
 
   @doc false

apps/expert/lib/expert/engine_node.ex

@@ -5,13 +5,16 @@ defmodule Expert.EngineNode do
   use Expert.Project.Progress.Support
 
   defmodule State do
+    require Logger
+
     defstruct [
       :project,
       :port,
       :cookie,
       :stopped_by,
       :stop_timeout,
       :started_by,
+      :last_message,
       :status
     ]
 
@@ -47,9 +50,14 @@ defmodule Expert.EngineNode do
           # If we start distribution manually after all the code is loaded,
           # everything works fine.
           """
-          {:ok, _} = Node.start(:"#{Project.node_name(state.project)}", :longnames)
-          #{Forge.NodePortMapper}.register()
-          IO.puts(\"ok\")
+          node_start = Node.start(:"#{Project.node_name(state.project)}", :longnames)
+          case node_start do
+            {:ok, _} ->
+              #{Forge.NodePortMapper}.register()
+              IO.puts(\"ok\")
+            {:error, reason} ->
+              IO.puts(\"error starting node:\n  \#{inspect(reason)}\")
+          end
           """
           | path_append_arguments(paths)
         ]
@@ -103,6 +111,28 @@ defmodule Expert.EngineNode do
       end
     end
 
+    def on_exit_status(%__MODULE__{} = state, exit_status) do
+      stop_reason =
+        case exit_status do
+          0 ->
+            project = state.project
+            Logger.info("Engine for #{project.root_uri} shut down")
+
+            :shutdown
+
+          _error_status ->
+            Logger.error(
+              "Engine shut down unexpectedly, node exited with status #{exit_status}). Last message: #{state.last_message}"
+            )
+
+            {:shutdown, {:node_exit, %{status: exit_status, last_message: state.last_message}}}
+        end
+
+      new_state = %{state | status: :stopped}
+
+      {stop_reason, new_state}
+    end
+
     def maybe_reply_to_stopper(%State{stopped_by: stopped_by} = state)
         when is_tuple(stopped_by) do
       GenServer.reply(state.stopped_by, :ok)
@@ -373,9 +403,18 @@ defmodule Expert.EngineNode do
   end
 
   @impl true
-  def handle_info({_port, {:data, message}}, %State{} = state) do
-    Logger.debug("Node port message: #{to_string(message)}")
-    {:noreply, state}
+  def handle_info({_port, {:exit_status, exit_status}}, %State{} = state) do
+    {stop_reason, state} = State.on_exit_status(state, exit_status)
+
+    {:stop, stop_reason, state}
+  end
+
+  @impl true
+  def handle_info({_port, {:data, data}}, %State{} = state) do
+    message = to_string(data)
+    Logger.debug("Node port message: #{message}")
+
+    {:noreply, %{state | last_message: message}}
   end
 
   @impl true

apps/expert/lib/expert/port.ex

@@ -118,7 +118,7 @@ defmodule Expert.Port do
         opts
       end
 
-    Port.open({:spawn_executable, launcher}, [:stderr_to_stdout | opts])
+    Port.open({:spawn_executable, launcher}, [:stderr_to_stdout, :exit_status] ++ opts)
   end
 
   @doc """

apps/expert/lib/expert/state.ex

@@ -35,8 +35,6 @@ defmodule Expert.State do
     %__MODULE__{}
   end
 
-  # TODO: this function has a side effect (starting the project supervisor)
-  # that i think might be better off in the calling function
   def initialize(
         %__MODULE__{initialized?: false} = state,
         %Requests.Initialize{
@@ -50,15 +48,9 @@ defmodule Expert.State do
       end
 
     config = Configuration.new(event.root_uri, event.capabilities, client_name)
-    new_state = %__MODULE__{state | configuration: config, initialized?: true}
-    Logger.info("Starting project at uri #{config.project.root_uri}")
 
     response = initialize_result()
-
-    Task.Supervisor.start_child(:expert_task_queue, fn ->
-      {:ok, _pid} = Project.Supervisor.start(config.project)
-      send(Expert, :engine_initialized)
-    end)
+    new_state = %__MODULE__{state | configuration: config, initialized?: true}
 
     {:ok, response, new_state}
   end
@@ -67,10 +59,6 @@ defmodule Expert.State do
     {:error, :already_initialized}
   end
 
-  def default_configuration(%__MODULE__{configuration: config}) do
-    Configuration.default(config)
-  end
-
   def apply(%__MODULE__{initialized?: false}, request) do
     Logger.error("Received #{request.method} before server was initialized")
     {:error, :not_initialized}

apps/expert/test/expert/engine_node_test.exs

@@ -64,4 +64,20 @@ defmodule Expert.EngineNodeTest do
     assert_receive {:stopped, 1}
     assert_receive {:lsp_log, "Couldn't find an elixir executable for project" <> _}
   end
+
+  test "shuts down with error message if exited with error code", %{project: project} do
+    {:ok, _node_name, node_pid} = EngineNode.start(project)
+
+    Process.monitor(node_pid)
+
+    exit_status = 127
+
+    send(node_pid, {nil, {:exit_status, exit_status}})
+
+    assert_receive {:DOWN, _ref, :process, ^node_pid, exit_reason}
+
+    assert {:shutdown, {:node_exit, node_exit}} = exit_reason
+    assert %{status: ^exit_status, last_message: last_message} = node_exit
+    assert is_binary(last_message)
+  end
 end

apps/expert/test/expert/project/diagnostics_test.exs

@@ -13,6 +13,7 @@ defmodule Expert.Project.DiagnosticsTest do
 
   import Forge.EngineApi.Messages
   import Forge.Test.Fixtures
+  import Expert.Test.Protocol.TransportSupport
 
   setup do
     project = project()
@@ -37,24 +38,6 @@ defmodule Expert.Project.DiagnosticsTest do
     struct(Diagnostic.Result, values)
   end
 
-  def with_patched_transport(_) do
-    test = self()
-
-    patch(GenLSP, :notify_server, fn _, message ->
-      send(test, {:transport, message})
-    end)
-
-    patch(GenLSP, :notify, fn _, message ->
-      send(test, {:transport, message})
-    end)
-
-    patch(GenLSP, :request, fn _, message ->
-      send(test, {:transport, message})
-    end)
-
-    :ok
-  end
-
   defp open_file(project, contents) do
     uri = file_uri(project, "lib/project.ex")
     :ok = Document.Store.open(uri, contents, 0)

apps/expert/test/expert/project/progress_test.exs

@@ -9,6 +9,7 @@ defmodule Expert.Project.ProgressTest do
 
   import Forge.Test.Fixtures
   import Forge.EngineApi.Messages
+  import Expert.Test.Protocol.TransportSupport
 
   use ExUnit.Case
   use Patch
@@ -44,20 +45,6 @@ defmodule Expert.Project.ProgressTest do
     project_progress(label: label, message: message, stage: stage)
   end
 
-  def with_patched_transport(_) do
-    test = self()
-
-    patch(GenLSP, :notify, fn _, message ->
-      send(test, {:transport, message})
-    end)
-
-    patch(GenLSP, :request, fn _, message ->
-      send(test, {:transport, message})
-    end)
-
-    :ok
-  end
-
   def with_work_done_progress_support(_) do
     patch(Configuration, :client_support, fn :work_done_progress -> true end)
     :ok