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.

Author: badosu

apps/expert/lib/expert.ex

@@ -1,4 +1,5 @@
 defmodule Expert do
+  alias Expert.Project
   alias Expert.Protocol.Convert
   alias Expert.Protocol.Id
   alias Expert.Provider.Handlers
@@ -51,27 +52,36 @@ 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))
 
     with {:ok, response, state} <- State.initialize(state, request),
          {:ok, response} <- Expert.Protocol.Convert.to_lsp(response) do
-      lsp = assign(lsp, state: state)
+      config = state.configuration
 
-      {:reply, response, lsp}
+      Task.Supervisor.start_child(:expert_task_queue, fn ->
+        Logger.info("Starting project at uri #{config.project.root_uri}")
+
+        start_result = Project.Supervisor.start(config.project)
+
+        send(Expert, {:engine_initialized, start_result})
+      end)
+
+      {:reply, response, assign(lsp, state: state)}
     else
-      {:error, {:shutdown, {:failed_to_start_child, _, _}}} ->
-        {:reply,
-         %GenLSP.ErrorResponse{
-           code: GenLSP.Enumerations.ErrorCodes.server_not_initialized(),
-           message: "Failed to start node"
-         }, lsp}
+      {:error, :already_initialized} ->
+        response = %GenLSP.ErrorResponse{
+          code: GenLSP.Enumerations.ErrorCodes.invalid_request(),
+          message: "Already initialized"
+        }
+
+        {:reply, response, lsp}
 
       {:error, reason} ->
-        {:reply,
-         %GenLSP.ErrorResponse{
-           code: GenLSP.Enumerations.ErrorCodes.server_not_initialized(),
-           message: to_string(reason)
-         }, lsp}
+        response = %GenLSP.ErrorResponse{
+          code: GenLSP.Enumerations.ErrorCodes.server_not_initialized(),
+          message: "Failed to initialize: #{inspect(reason)}"
+        }
+
+        {:reply, response, lsp}
     end
   end
 
@@ -178,7 +188,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}
@@ -190,20 +200,10 @@ defmodule Expert do
     {:noreply, lsp}
   end
 
-  def handle_info(:default_config, lsp) do
-    state = assigns(lsp).state
-
-    if state.configuration == nil do
-      Logger.warning(
-        "Did not receive workspace/didChangeConfiguration notification after 5 seconds. " <>
-          "Using default settings."
-      )
+  def handle_info({:engine_initialized, {:error, reason}}, lsp) do
+    GenLSP.error(get_lsp(), initialization_error_message(reason))
 
-      {:ok, config} = State.default_configuration(state)
-      {:noreply, assign(lsp, state: %{state | configuration: config})}
-    else
-      {:noreply, lsp}
-    end
+    {:noreply, lsp}
   end
 
   defp apply_to_state(%State{} = state, %{} = request_or_notification) do
@@ -278,4 +278,33 @@ 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}} ->
+        "Node #{name} shutdown with error:\n\n#{message}"
+
+      {:shutdown, {:node_exit, node_exit}} ->
+        "Node #{name} exit with status #{node_exit.status}, last message:\n\n#{node_exit.last_message}"
+
+      reason ->
+        "Failed to start node #{name}: #{inspect(reason)}"
+    end
+  end
 end

apps/expert/lib/expert/engine_node.ex

@@ -50,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)
+          node_start = Node.start(:"#{Project.node_name(state.project)}", :longnames)
           #{Forge.NodePortMapper}.register()
-          IO.puts(\"ok\")
+          case node_start do
+            {:ok, _} ->
+              IO.puts(\"ok\")
+            {:error, reason} ->
+              IO.puts(\"error starting node:\n  \#{inspect(reason)}\")
+          end
           """
           | path_append_arguments(paths)
         ]
@@ -107,16 +112,22 @@ defmodule Expert.EngineNode do
     end
 
     def on_exit_status(%__MODULE__{} = state, exit_status) do
-      if exit_status > 0 do
-        GenLSP.error(
-          Expert.get_lsp(),
-          "Node exited with status #{exit_status}, last message: #{to_string(state.last_message)}"
-        )
-      else
-        Logger.debug("Node exited with status 0")
-      end
+      Logger.debug(
+        "Node exited with status #{exit_status}, last message: #{to_string(state.last_message)}"
+      )
 
-      %{state | status: :stopped}
+      stop_reason =
+        case exit_status do
+          0 ->
+            :shutdown
+
+          _error_status ->
+            {: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)
@@ -390,14 +401,16 @@ defmodule Expert.EngineNode do
 
   @impl true
   def handle_info({_port, {:exit_status, exit_status}}, %State{} = state) do
-    state = State.on_exit_status(state, exit_status)
+    {stop_reason, state} = State.on_exit_status(state, exit_status)
 
-    {:stop, :shutdown, state}
+    {:stop, stop_reason, state}
   end
 
   @impl true
-  def handle_info({_port, {:data, message}}, %State{} = state) do
-    Logger.debug("Node port message: #{to_string(message)}")
+  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
 

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,25 +48,17 @@ defmodule Expert.State do
       end
 
     config = Configuration.new(event.root_uri, event.capabilities, client_name)
-    Logger.info("Starting project at uri #{config.project.root_uri}")
 
-    with {:ok, _pid} <- Project.Supervisor.start(config.project) do
-      send(Expert, :engine_initialized)
-      new_state = %__MODULE__{state | configuration: config, initialized?: true}
-      response = initialize_result()
+    response = initialize_result()
+    new_state = %__MODULE__{state | configuration: config, initialized?: true}
 
-      {:ok, response, new_state}
-    end
+    {:ok, response, new_state}
   end
 
   def initialize(%__MODULE__{initialized?: true}, %Requests.Initialize{}) 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

@@ -4,7 +4,6 @@ defmodule Expert.EngineNodeTest do
 
   import Forge.Test.EventualAssertions
   import Forge.Test.Fixtures
-  import Expert.Test.Protocol.TransportSupport
 
   use ExUnit.Case, async: false
   use Patch
@@ -66,33 +65,19 @@ defmodule Expert.EngineNodeTest do
     assert_receive {:lsp_log, "Couldn't find an elixir executable for project" <> _}
   end
 
-  test "sends a message to client if exited with error code", %{project: project} do
-    with_patched_transport()
-
+  test "shuts down with error message if exited with error code", %{project: project} do
     {:ok, _node_name, node_pid} = EngineNode.start(project)
 
-    project_alive? = project |> EngineNode.name() |> Process.whereis() |> Process.alive?()
-    assert project_alive?
+    Process.monitor(node_pid)
 
     exit_status = 127
 
     send(node_pid, {nil, {:exit_status, exit_status}})
 
-    error_message_type = GenLSP.Enumerations.MessageType.error()
+    assert_receive {:DOWN, _ref, :process, ^node_pid, exit_reason}
 
-    assert_receive {:transport,
-                    %GenLSP.Notifications.WindowLogMessage{
-                      params: %GenLSP.Structures.LogMessageParams{
-                        type: ^error_message_type,
-                        message: message
-                      }
-                    }}
-
-    assert String.starts_with?(
-             message,
-             "Node exited with status #{exit_status}, last message:"
-           )
-
-    assert_eventually Process.whereis(EngineNode.name(project)) == nil, :timer.seconds(5)
+    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_test.exs

@@ -1,27 +1,96 @@
 defmodule Expert.ExpertTest do
-  use ExUnit.Case, async: true
+  alias Forge.Test.Fixtures
+
+  use ExUnit.Case, async: false
   use Patch
+  use Forge.Test.EventualAssertions
+
+  require GenLSP.Test
+
+  import Expert.Test.Protocol.TransportSupport
 
-  describe "handle_request/2" do
-    test "it replies with server_not_initialized on initialization error" do
-      reason = :something_bad
+  defp start_expert do
+    patch(System, :argv, fn -> ["--port", "0"] end)
 
-      patch(Expert.State, :initialize, fn _state, _request ->
-        {:error, reason}
-      end)
+    assert {:ok, _} = Application.ensure_all_started(:expert)
 
-      assigns = start_supervised!(GenLSP.Assigns, id: make_ref())
-      GenLSP.Assigns.merge(assigns, %{state: %{}})
+    on_exit(fn -> Application.stop(:expert) end)
+  end
+
+  describe "server testing" do
+    setup do
+      start_expert()
 
-      initialize_request = %GenLSP.Requests.Initialize{id: 1}
-      lsp = %GenLSP.LSP{mod: Expert, assigns: assigns}
+      %{lsp: lsp} = :sys.get_state(Expert.Buffer)
+      {:ok, port} = :inet.port(GenLSP.Buffer.comm_state(Expert.Buffer).lsocket)
 
-      {:reply, response, _lsp} = Expert.handle_request(initialize_request, lsp)
+      expert = %{
+        lsp: lsp,
+        port: port
+      }
 
-      message = to_string(reason)
-      error_code = GenLSP.Enumerations.ErrorCodes.server_not_initialized()
+      client = GenLSP.Test.client(expert)
 
-      assert %GenLSP.ErrorResponse{code: ^error_code, data: nil, message: ^message} = response
+      [expert: expert, client: client]
     end
+
+    test "replies to initialize with expert info and capabilities", %{client: client} do
+      id = System.unique_integer([:positive])
+
+      project = Fixtures.project()
+
+      root_uri = project.root_uri
+      root_path = Forge.Project.root_path(project)
+
+      assert :ok ==
+               GenLSP.Test.request(client, %{
+                 "id" => id,
+                 "jsonrpc" => "2.0",
+                 "method" => "initialize",
+                 "params" => %{
+                   "rootPath" => root_path,
+                   "rootUri" => root_uri,
+                   "capabilities" => %{},
+                   "workspaceFolders" => [
+                     %{
+                       uri: root_uri,
+                       name: root_path
+                     }
+                   ]
+                 }
+               })
+
+      GenLSP.Test.assert_result(^id, result, 500)
+
+      {:ok, initialize_result} =
+        GenLSP.Requests.Initialize.result()
+        |> Schematic.dump(Expert.State.initialize_result())
+
+      assert result == initialize_result
+    end
+  end
+
+  test "sends an error message on engine initialization error" do
+    with_patched_transport()
+
+    assigns = start_supervised!(GenLSP.Assigns, id: make_ref())
+    GenLSP.Assigns.merge(assigns, %{state: %{}})
+
+    lsp = %GenLSP.LSP{mod: Expert, assigns: assigns}
+
+    reason = :something_bad
+
+    assert {:noreply, ^lsp} = Expert.handle_info({:engine_initialized, {:error, reason}}, lsp)
+
+    error_message = "Failed to initialize: #{inspect(reason)}"
+    error_message_type = GenLSP.Enumerations.MessageType.error()
+
+    assert_receive {:transport,
+                    %GenLSP.Notifications.WindowLogMessage{
+                      params: %GenLSP.Structures.LogMessageParams{
+                        type: ^error_message_type,
+                        message: ^error_message
+                      }
+                    }}
   end
 end