diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index 8986d4f3..1d5905f4 100644 --- a/apps/expert/lib/expert.ex +++ b/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 diff --git a/apps/expert/lib/expert/application.ex b/apps/expert/lib/expert/application.ex index fc9b81f1..fd41bf96 100644 --- a/apps/expert/lib/expert/application.ex +++ b/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 diff --git a/apps/expert/lib/expert/engine_node.ex b/apps/expert/lib/expert/engine_node.ex index a3ce8730..3518f4a9 100644 --- a/apps/expert/lib/expert/engine_node.ex +++ b/apps/expert/lib/expert/engine_node.ex @@ -5,6 +5,8 @@ defmodule Expert.EngineNode do use Expert.Project.Progress.Support defmodule State do + require Logger + defstruct [ :project, :port, @@ -12,6 +14,7 @@ defmodule Expert.EngineNode do :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 diff --git a/apps/expert/lib/expert/port.ex b/apps/expert/lib/expert/port.ex index cffb0e62..48790643 100644 --- a/apps/expert/lib/expert/port.ex +++ b/apps/expert/lib/expert/port.ex @@ -112,7 +112,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 """ diff --git a/apps/expert/lib/expert/state.ex b/apps/expert/lib/expert/state.ex index 655d2ca8..2ba810b4 100644 --- a/apps/expert/lib/expert/state.ex +++ b/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} diff --git a/apps/expert/test/expert/engine_node_test.exs b/apps/expert/test/expert/engine_node_test.exs index 623af7d1..051e47a6 100644 --- a/apps/expert/test/expert/engine_node_test.exs +++ b/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 diff --git a/apps/expert/test/expert/project/diagnostics_test.exs b/apps/expert/test/expert/project/diagnostics_test.exs index 6115d656..44e3b556 100644 --- a/apps/expert/test/expert/project/diagnostics_test.exs +++ b/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) diff --git a/apps/expert/test/expert/project/progress_test.exs b/apps/expert/test/expert/project/progress_test.exs index 45725893..520245d2 100644 --- a/apps/expert/test/expert/project/progress_test.exs +++ b/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_supports?, fn :work_done_progress -> true end) :ok diff --git a/apps/expert/test/expert_test.exs b/apps/expert/test/expert_test.exs new file mode 100644 index 00000000..c7539636 --- /dev/null +++ b/apps/expert/test/expert_test.exs @@ -0,0 +1,71 @@ +defmodule Expert.ExpertTest do + alias Expert.State + alias Forge.Test.Fixtures + + use ExUnit.Case, async: true + use Patch + + import Expert.Test.Protocol.TransportSupport + + test "sends an error message on engine initialization error" do + with_patched_transport() + + project = Fixtures.project() + lsp = initialize_lsp(project) + + reason = :something_bad + + assert {:noreply, ^lsp} = Expert.handle_info({:engine_initialized, {:error, reason}}, lsp) + + error_message = "[Project #{project.root_uri}] 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 + } + }} + + assert_receive {:transport, + %GenLSP.Notifications.WindowShowMessage{ + params: %GenLSP.Structures.ShowMessageParams{ + type: ^error_message_type, + message: ^error_message + } + }} + end + + defp initialize_lsp(project) do + assigns = start_supervised!(GenLSP.Assigns, id: make_ref()) + + {:ok, _response, state} = State.initialize(State.new(), initialize_request(project)) + GenLSP.Assigns.merge(assigns, %{state: state}) + + %GenLSP.LSP{mod: Expert, assigns: assigns} + end + + defp initialize_request(project) do + root_uri = project.root_uri + root_path = Forge.Project.root_path(project) + + %GenLSP.Requests.Initialize{ + id: 1, + jsonrpc: "2.0", + method: "initialize", + params: %GenLSP.Structures.InitializeParams{ + capabilities: %GenLSP.Structures.ClientCapabilities{}, + process_id: "", + root_uri: root_uri, + root_path: root_path, + workspace_folders: [ + %GenLSP.Structures.WorkspaceFolder{ + name: root_path, + uri: root_uri + } + ] + } + } + end +end diff --git a/apps/expert/test/support/test/transport_support.ex b/apps/expert/test/support/test/transport_support.ex new file mode 100644 index 00000000..ecb74833 --- /dev/null +++ b/apps/expert/test/support/test/transport_support.ex @@ -0,0 +1,19 @@ +defmodule Expert.Test.Protocol.TransportSupport do + def with_patched_transport(_ \\ nil) do + test = self() + + Patch.patch(GenLSP, :notify_server, fn _, message -> + send(test, {:transport, message}) + end) + + Patch.patch(GenLSP, :notify, fn _, message -> + send(test, {:transport, message}) + end) + + Patch.patch(GenLSP, :request, fn _, message -> + send(test, {:transport, message}) + end) + + :ok + end +end