From 4e099f7940a5e2520d1e59a362968cb2236c66eb Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Fri, 5 Dec 2025 19:32:52 -0300 Subject: [PATCH 1/8] feat: properly respond to and log initialization errors --- apps/expert/lib/expert.ex | 29 ++++++++++------- apps/expert/lib/expert/engine_node.ex | 25 ++++++++++++++- apps/expert/lib/expert/port.ex | 2 +- apps/expert/lib/expert/state.ex | 12 +++---- apps/expert/test/expert/engine_node_test.exs | 31 +++++++++++++++++++ .../test/expert/project/diagnostics_test.exs | 19 +----------- .../test/expert/project/progress_test.exs | 15 +-------- apps/expert/test/expert_test.exs | 27 ++++++++++++++++ .../test/support/test/transport_support.ex | 19 ++++++++++++ 9 files changed, 126 insertions(+), 53 deletions(-) create mode 100644 apps/expert/test/expert_test.exs create mode 100644 apps/expert/test/support/test/transport_support.ex diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index 8986d4f3..1c9775e3 100644 --- a/apps/expert/lib/expert.ex +++ b/apps/expert/lib/expert.ex @@ -53,20 +53,25 @@ defmodule Expert 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) - - {:reply, response, lsp} + with {:ok, response, state} <- State.initialize(state, request), + {:ok, response} <- Expert.Protocol.Convert.to_lsp(response) do + lsp = assign(lsp, state: state) - {:error, error} -> - response = %GenLSP.ErrorResponse{ - code: GenLSP.Enumerations.ErrorCodes.invalid_request(), - message: to_string(error) - } + {:reply, response, lsp} + else + {:error, {:shutdown, {:failed_to_start_child, _, _}}} -> + {:reply, + %GenLSP.ErrorResponse{ + code: GenLSP.Enumerations.ErrorCodes.server_not_initialized(), + message: "Failed to start node" + }, lsp} - {:reply, response, lsp} + {:error, reason} -> + {:reply, + %GenLSP.ErrorResponse{ + code: GenLSP.Enumerations.ErrorCodes.server_not_initialized(), + message: to_string(reason) + }, lsp} end end diff --git a/apps/expert/lib/expert/engine_node.ex b/apps/expert/lib/expert/engine_node.ex index a3ce8730..d4f36e54 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 ] @@ -103,6 +106,19 @@ defmodule Expert.EngineNode do end 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 + + %{state | status: :stopped} + end + def maybe_reply_to_stopper(%State{stopped_by: stopped_by} = state) when is_tuple(stopped_by) do GenServer.reply(state.stopped_by, :ok) @@ -372,10 +388,17 @@ defmodule Expert.EngineNode do {:stop, :shutdown, state} end + @impl true + def handle_info({_port, {:exit_status, exit_status}}, %State{} = state) do + state = State.on_exit_status(state, exit_status) + + {:stop, :shutdown, state} + end + @impl true def handle_info({_port, {:data, message}}, %State{} = state) do Logger.debug("Node port message: #{to_string(message)}") - {:noreply, state} + {: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..c32ef90f 100644 --- a/apps/expert/lib/expert/state.ex +++ b/apps/expert/lib/expert/state.ex @@ -50,17 +50,15 @@ 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) + with {:ok, _pid} <- Project.Supervisor.start(config.project) do send(Expert, :engine_initialized) - end) + new_state = %__MODULE__{state | configuration: config, initialized?: true} + response = initialize_result() - {:ok, response, new_state} + {:ok, response, new_state} + end end def initialize(%__MODULE__{initialized?: true}, %Requests.Initialize{}) do diff --git a/apps/expert/test/expert/engine_node_test.exs b/apps/expert/test/expert/engine_node_test.exs index 623af7d1..6106072f 100644 --- a/apps/expert/test/expert/engine_node_test.exs +++ b/apps/expert/test/expert/engine_node_test.exs @@ -4,6 +4,7 @@ defmodule Expert.EngineNodeTest do import Forge.Test.EventualAssertions import Forge.Test.Fixtures + import Expert.Test.Protocol.TransportSupport use ExUnit.Case, async: false use Patch @@ -64,4 +65,34 @@ defmodule Expert.EngineNodeTest do assert_receive {:stopped, 1} 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() + + {:ok, _node_name, node_pid} = EngineNode.start(project) + + project_alive? = project |> EngineNode.name() |> Process.whereis() |> Process.alive?() + assert project_alive? + + exit_status = 127 + + send(node_pid, {nil, {:exit_status, exit_status}}) + + error_message_type = GenLSP.Enumerations.MessageType.error() + + 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) + 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..de263f3e --- /dev/null +++ b/apps/expert/test/expert_test.exs @@ -0,0 +1,27 @@ +defmodule Expert.ExpertTest do + use ExUnit.Case, async: true + use Patch + + describe "handle_request/2" do + test "it replies with server_not_initialized on initialization error" do + reason = :something_bad + + patch(Expert.State, :initialize, fn _state, _request -> + {:error, reason} + end) + + assigns = start_supervised!(GenLSP.Assigns, id: make_ref()) + GenLSP.Assigns.merge(assigns, %{state: %{}}) + + initialize_request = %GenLSP.Requests.Initialize{id: 1} + lsp = %GenLSP.LSP{mod: Expert, assigns: assigns} + + {:reply, response, _lsp} = Expert.handle_request(initialize_request, lsp) + + message = to_string(reason) + error_code = GenLSP.Enumerations.ErrorCodes.server_not_initialized() + + assert %GenLSP.ErrorResponse{code: ^error_code, data: nil, message: ^message} = response + end + 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 From dc9c8f11a8d512418c5b4114e411d8fd90e2070a Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Tue, 9 Dec 2025 04:58:58 -0300 Subject: [PATCH 2/8] 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. --- apps/expert/lib/expert.ex | 85 +++++++++++------ apps/expert/lib/expert/engine_node.ex | 43 ++++++--- apps/expert/lib/expert/state.ex | 16 +--- apps/expert/test/expert/engine_node_test.exs | 27 ++---- apps/expert/test/expert_test.exs | 99 +++++++++++++++++--- 5 files changed, 178 insertions(+), 92 deletions(-) diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index 1c9775e3..ccad9cd4 100644 --- a/apps/expert/lib/expert.ex +++ b/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 diff --git a/apps/expert/lib/expert/engine_node.ex b/apps/expert/lib/expert/engine_node.ex index d4f36e54..81a3b7d1 100644 --- a/apps/expert/lib/expert/engine_node.ex +++ b/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 diff --git a/apps/expert/lib/expert/state.ex b/apps/expert/lib/expert/state.ex index c32ef90f..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,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} diff --git a/apps/expert/test/expert/engine_node_test.exs b/apps/expert/test/expert/engine_node_test.exs index 6106072f..051e47a6 100644 --- a/apps/expert/test/expert/engine_node_test.exs +++ b/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 diff --git a/apps/expert/test/expert_test.exs b/apps/expert/test/expert_test.exs index de263f3e..8d24a24e 100644 --- a/apps/expert/test/expert_test.exs +++ b/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 From fe14474af4480224dbb87ba8e7e8a1ad9915821c Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Tue, 9 Dec 2025 16:00:56 -0300 Subject: [PATCH 3/8] 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 --- apps/expert/lib/expert.ex | 48 ++++++++++++++--- apps/expert/lib/expert/application.ex | 18 ++++--- apps/expert/lib/expert/engine_node.ex | 12 +++-- apps/expert/test/expert_test.exs | 74 ++++----------------------- 4 files changed, 69 insertions(+), 83 deletions(-) diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index ccad9cd4..7dad7117 100644 --- a/apps/expert/lib/expert.ex +++ b/apps/expert/lib/expert.ex @@ -4,6 +4,7 @@ defmodule Expert do alias Expert.Protocol.Id alias Expert.Provider.Handlers alias Expert.State + alias GenLSP.Enumerations alias GenLSP.Requests alias GenLSP.Structures @@ -55,10 +56,12 @@ defmodule Expert do with {:ok, response, state} <- State.initialize(state, request), {:ok, response} <- Expert.Protocol.Convert.to_lsp(response) do - config = state.configuration - Task.Supervisor.start_child(:expert_task_queue, fn -> - Logger.info("Starting project at uri #{config.project.root_uri}") + config = state.configuration + + start_message = "Starting project at uri #{config.project.root_uri}" + GenLSP.info(lsp, start_message) + Logger.info(start_message) start_result = Project.Supervisor.start(config.project) @@ -201,11 +204,42 @@ defmodule Expert do end def handle_info({:engine_initialized, {:error, reason}}, lsp) do - GenLSP.error(get_lsp(), initialization_error_message(reason)) + error_message = initialization_error_message(reason) + error(error_message) {:noreply, lsp} end + def info(message) do + Logger.info(message) + + log_show(message, Enumerations.MessageType.info()) + end + + def error(message) do + Logger.error(message) + + log_show(message, Enumerations.MessageType.error()) + end + + defp log_show(message, log_level) do + lsp = get_lsp() + + GenLSP.notify(lsp, %GenLSP.Notifications.WindowShowMessage{ + params: %GenLSP.Structures.ShowMessageParams{ + type: log_level, + message: message + } + }) + + GenLSP.notify(lsp, %GenLSP.Notifications.WindowLogMessage{ + params: %GenLSP.Structures.LogMessageParams{ + type: log_level, + message: message + } + }) + end + defp apply_to_state(%State{} = state, %{} = request_or_notification) do case State.apply(state, request_or_notification) do {:ok, response, new_state} -> {:ok, response, new_state} @@ -298,13 +332,13 @@ defmodule Expert 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}" + "Engine #{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}" + "Engine #{name} exit with status #{node_exit.status}, last message:\n\n#{node_exit.last_message}" reason -> - "Failed to start node #{name}: #{inspect(reason)}" + "Failed to start engine #{name}: #{inspect(reason)}" end end 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 81a3b7d1..20501f66 100644 --- a/apps/expert/lib/expert/engine_node.ex +++ b/apps/expert/lib/expert/engine_node.ex @@ -51,9 +51,9 @@ defmodule Expert.EngineNode do # everything works fine. """ node_start = Node.start(:"#{Project.node_name(state.project)}", :longnames) - #{Forge.NodePortMapper}.register() case node_start do {:ok, _} -> + #{Forge.NodePortMapper}.register() IO.puts(\"ok\") {:error, reason} -> IO.puts(\"error starting node:\n \#{inspect(reason)}\") @@ -112,16 +112,18 @@ defmodule Expert.EngineNode do end def on_exit_status(%__MODULE__{} = state, exit_status) do - Logger.debug( - "Node exited with status #{exit_status}, last message: #{to_string(state.last_message)}" - ) - stop_reason = case exit_status do 0 -> + Logger.info("Engine shutdown") + :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 diff --git a/apps/expert/test/expert_test.exs b/apps/expert/test/expert_test.exs index 8d24a24e..62898169 100644 --- a/apps/expert/test/expert_test.exs +++ b/apps/expert/test/expert_test.exs @@ -1,75 +1,11 @@ defmodule Expert.ExpertTest do - alias Forge.Test.Fixtures - - use ExUnit.Case, async: false + use ExUnit.Case, async: true use Patch - use Forge.Test.EventualAssertions require GenLSP.Test import Expert.Test.Protocol.TransportSupport - defp start_expert do - patch(System, :argv, fn -> ["--port", "0"] end) - - assert {:ok, _} = Application.ensure_all_started(:expert) - - on_exit(fn -> Application.stop(:expert) end) - end - - describe "server testing" do - setup do - start_expert() - - %{lsp: lsp} = :sys.get_state(Expert.Buffer) - {:ok, port} = :inet.port(GenLSP.Buffer.comm_state(Expert.Buffer).lsocket) - - expert = %{ - lsp: lsp, - port: port - } - - client = GenLSP.Test.client(expert) - - [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() @@ -92,5 +28,13 @@ defmodule Expert.ExpertTest do message: ^error_message } }} + + assert_receive {:transport, + %GenLSP.Notifications.WindowShowMessage{ + params: %GenLSP.Structures.ShowMessageParams{ + type: ^error_message_type, + message: ^error_message + } + }} end end From e381804dbd99fe0cbd0fbd685f13a0e5ad8c924d Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Tue, 9 Dec 2025 16:31:02 -0300 Subject: [PATCH 4/8] Reintroduce full server testing with different approach Now we start manually all application children instead of ensuring the application has started --- apps/expert/lib/expert.ex | 27 ++++-------- apps/expert/test/expert_test.exs | 74 +++++++++++++++++++++++++++++++- 2 files changed, 82 insertions(+), 19 deletions(-) diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index 7dad7117..9567ec4e 100644 --- a/apps/expert/lib/expert.ex +++ b/apps/expert/lib/expert.ex @@ -59,9 +59,7 @@ defmodule Expert do Task.Supervisor.start_child(:expert_task_queue, fn -> config = state.configuration - start_message = "Starting project at uri #{config.project.root_uri}" - GenLSP.info(lsp, start_message) - Logger.info(start_message) + log_info("Starting project at uri #{config.project.root_uri}") start_result = Project.Supervisor.start(config.project) @@ -205,39 +203,32 @@ defmodule Expert do def handle_info({:engine_initialized, {:error, reason}}, lsp) do error_message = initialization_error_message(reason) - error(error_message) + log_error(error_message) {:noreply, lsp} end - def info(message) do + def log_info(message) do Logger.info(message) - log_show(message, Enumerations.MessageType.info()) + GenLSP.log(get_lsp(), message) end - def error(message) do + # When logging errors we also notify the client to display the message + def log_error(message) do Logger.error(message) - log_show(message, Enumerations.MessageType.error()) - end - - defp log_show(message, log_level) do + log_level = Enumerations.MessageType.error() lsp = get_lsp() + GenLSP.error(lsp, message) + GenLSP.notify(lsp, %GenLSP.Notifications.WindowShowMessage{ params: %GenLSP.Structures.ShowMessageParams{ type: log_level, message: message } }) - - GenLSP.notify(lsp, %GenLSP.Notifications.WindowLogMessage{ - params: %GenLSP.Structures.LogMessageParams{ - type: log_level, - message: message - } - }) end defp apply_to_state(%State{} = state, %{} = request_or_notification) do diff --git a/apps/expert/test/expert_test.exs b/apps/expert/test/expert_test.exs index 62898169..c04707b7 100644 --- a/apps/expert/test/expert_test.exs +++ b/apps/expert/test/expert_test.exs @@ -1,11 +1,83 @@ defmodule Expert.ExpertTest do - use ExUnit.Case, async: true + alias Forge.Test.Fixtures + + use ExUnit.Case, async: false + use Forge.Test.EventualAssertions use Patch require GenLSP.Test import Expert.Test.Protocol.TransportSupport + describe "server testing" do + defp buffer_opts do + [communication: {GenLSP.Communication.TCP, [port: 0]}] + end + + defp start_application_children do + pids = + for child_spec <- Expert.Application.children(buffer: buffer_opts()) do + start_supervised!(child_spec) + end + + on_exit(fn -> + # NOTE: The test hangs for some reason without manually exiting + for pid <- pids do + Process.exit(pid, :normal) + end + end) + end + + setup do + start_application_children() + + comm_state = GenLSP.Buffer.comm_state(Expert.Buffer) + + {:ok, port} = :inet.port(comm_state.lsocket) + %{lsp: lsp} = :sys.get_state(Expert.Buffer) + + expert = %{lsp: lsp, port: port} + client = GenLSP.Test.client(expert) + + [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() From b879ac169ffef4597327d0b86e36bf4b90d44369 Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Tue, 9 Dec 2025 17:04:29 -0300 Subject: [PATCH 5/8] Remove full server testing, too problematic for now --- apps/expert/test/expert_test.exs | 74 -------------------------------- 1 file changed, 74 deletions(-) diff --git a/apps/expert/test/expert_test.exs b/apps/expert/test/expert_test.exs index c04707b7..6d910d00 100644 --- a/apps/expert/test/expert_test.exs +++ b/apps/expert/test/expert_test.exs @@ -1,83 +1,9 @@ defmodule Expert.ExpertTest do - alias Forge.Test.Fixtures - use ExUnit.Case, async: false - use Forge.Test.EventualAssertions use Patch - require GenLSP.Test - import Expert.Test.Protocol.TransportSupport - describe "server testing" do - defp buffer_opts do - [communication: {GenLSP.Communication.TCP, [port: 0]}] - end - - defp start_application_children do - pids = - for child_spec <- Expert.Application.children(buffer: buffer_opts()) do - start_supervised!(child_spec) - end - - on_exit(fn -> - # NOTE: The test hangs for some reason without manually exiting - for pid <- pids do - Process.exit(pid, :normal) - end - end) - end - - setup do - start_application_children() - - comm_state = GenLSP.Buffer.comm_state(Expert.Buffer) - - {:ok, port} = :inet.port(comm_state.lsocket) - %{lsp: lsp} = :sys.get_state(Expert.Buffer) - - expert = %{lsp: lsp, port: port} - client = GenLSP.Test.client(expert) - - [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() From d168107879c7f1b38ae63b1d6238b89e6866a176 Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Tue, 9 Dec 2025 17:18:23 -0300 Subject: [PATCH 6/8] Address a few further review concerns --- apps/expert/lib/expert.ex | 11 +++++------ apps/expert/lib/expert/engine_node.ex | 3 ++- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index 9567ec4e..3db81507 100644 --- a/apps/expert/lib/expert.ex +++ b/apps/expert/lib/expert.ex @@ -59,7 +59,7 @@ defmodule Expert do Task.Supervisor.start_child(:expert_task_queue, fn -> config = state.configuration - log_info("Starting project at uri #{config.project.root_uri}") + log_info(lsp, "Starting project at uri #{config.project.root_uri}") start_result = Project.Supervisor.start(config.project) @@ -203,23 +203,22 @@ defmodule Expert do def handle_info({:engine_initialized, {:error, reason}}, lsp) do error_message = initialization_error_message(reason) - log_error(error_message) + log_error(lsp, error_message) {:noreply, lsp} end - def log_info(message) do + def log_info(lsp \\ get_lsp(), message) do Logger.info(message) - GenLSP.log(get_lsp(), message) + GenLSP.info(lsp, message) end # When logging errors we also notify the client to display the message - def log_error(message) do + def log_error(lsp \\ get_lsp(), message) do Logger.error(message) log_level = Enumerations.MessageType.error() - lsp = get_lsp() GenLSP.error(lsp, message) diff --git a/apps/expert/lib/expert/engine_node.ex b/apps/expert/lib/expert/engine_node.ex index 20501f66..3518f4a9 100644 --- a/apps/expert/lib/expert/engine_node.ex +++ b/apps/expert/lib/expert/engine_node.ex @@ -115,7 +115,8 @@ defmodule Expert.EngineNode do stop_reason = case exit_status do 0 -> - Logger.info("Engine shutdown") + project = state.project + Logger.info("Engine for #{project.root_uri} shut down") :shutdown From d71cc76a0261deb73ce318f7ce3a4fc6ad54a77d Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Tue, 9 Dec 2025 17:25:44 -0300 Subject: [PATCH 7/8] Expert test is async safe --- apps/expert/test/expert_test.exs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/expert/test/expert_test.exs b/apps/expert/test/expert_test.exs index 6d910d00..a8f3cc11 100644 --- a/apps/expert/test/expert_test.exs +++ b/apps/expert/test/expert_test.exs @@ -1,5 +1,5 @@ defmodule Expert.ExpertTest do - use ExUnit.Case, async: false + use ExUnit.Case, async: true use Patch import Expert.Test.Protocol.TransportSupport From 5ae550e0b548b32adffab7a78c399d0683f3549e Mon Sep 17 00:00:00 2001 From: Amadeus Folego Date: Wed, 10 Dec 2025 13:21:18 -0300 Subject: [PATCH 8/8] Log project uri --- apps/expert/lib/expert.ex | 20 ++++++++++----- apps/expert/test/expert_test.exs | 43 ++++++++++++++++++++++++++++---- 2 files changed, 52 insertions(+), 11 deletions(-) diff --git a/apps/expert/lib/expert.ex b/apps/expert/lib/expert.ex index 3db81507..1d5905f4 100644 --- a/apps/expert/lib/expert.ex +++ b/apps/expert/lib/expert.ex @@ -59,7 +59,7 @@ defmodule Expert do Task.Supervisor.start_child(:expert_task_queue, fn -> config = state.configuration - log_info(lsp, "Starting project at uri #{config.project.root_uri}") + log_info(lsp, "Starting project") start_result = Project.Supervisor.start(config.project) @@ -209,22 +209,22 @@ defmodule Expert do end def log_info(lsp \\ get_lsp(), message) do - Logger.info(message) + 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 - Logger.error(message) - - log_level = Enumerations.MessageType.error() + 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: log_level, + type: Enumerations.MessageType.error(), message: message } }) @@ -331,4 +331,12 @@ defmodule Expert do "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/test/expert_test.exs b/apps/expert/test/expert_test.exs index a8f3cc11..c7539636 100644 --- a/apps/expert/test/expert_test.exs +++ b/apps/expert/test/expert_test.exs @@ -1,4 +1,7 @@ defmodule Expert.ExpertTest do + alias Expert.State + alias Forge.Test.Fixtures + use ExUnit.Case, async: true use Patch @@ -7,16 +10,14 @@ defmodule Expert.ExpertTest do 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} + project = Fixtures.project() + lsp = initialize_lsp(project) reason = :something_bad assert {:noreply, ^lsp} = Expert.handle_info({:engine_initialized, {:error, reason}}, lsp) - error_message = "Failed to initialize: #{inspect(reason)}" + error_message = "[Project #{project.root_uri}] Failed to initialize: #{inspect(reason)}" error_message_type = GenLSP.Enumerations.MessageType.error() assert_receive {:transport, @@ -35,4 +36,36 @@ defmodule Expert.ExpertTest do } }} 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