Logger backend for language server and fixes for debugger (#746)

* console backend forked from elixir

* rename

* rename

* remove colors

* remove buffering

* remove device

* replace console logger

fix errors

* run formatter

* remove tests

* consistently use Logger for ordinary logging

* crash instead of warning

* use logger

* attempt to show error message before crashing

Fixes #741

* info->warn

* exit server when config changes

it will be restarted by the client

* fix tests

* use new function in debugger

* use DAP compliant output category in debugger

stdout and stderr is reserved for debuggee, console and important for debugger

* set group leader to logger backend in tests

* fix tests

apps/elixir_ls_debugger/lib/debugger.ex

@@ -4,12 +4,13 @@ defmodule ElixirLS.Debugger do
   """
 
   use Application
+  alias ElixirLS.Debugger.Output
 
   @impl Application
   def start(_type, _args) do
     # We don't start this as a worker because if the debugger crashes, we want
     # this process to remain alive to print errors
-    {:ok, _pid} = ElixirLS.Debugger.Output.start(ElixirLS.Debugger.Output)
+    {:ok, _pid} = Output.start(Output)
 
     children = [
       {ElixirLS.Debugger.Server, name: ElixirLS.Debugger.Server}
@@ -22,7 +23,7 @@ defmodule ElixirLS.Debugger do
   @impl Application
   def stop(_state) do
     if ElixirLS.Utils.WireProtocol.io_intercepted?() do
-      IO.puts(:standard_error, "ElixirLS debugger has crashed")
+      Output.debugger_important("ElixirLS debugger has crashed")
 
       :init.stop(1)
     end

apps/elixir_ls_debugger/lib/debugger/breakpoint_condition.ex

@@ -4,6 +4,7 @@ defmodule ElixirLS.Debugger.BreakpointCondition do
   """
 
   use GenServer
+  alias ElixirLS.Debugger.Output
   @range 0..99
 
   def start_link(args) do
@@ -162,7 +163,7 @@ defmodule ElixirLS.Debugger.BreakpointCondition do
         # Debug Adapter Protocol:
         # If this attribute exists and is non-empty, the backend must not 'break' (stop)
         # but log the message instead. Expressions within {} are interpolated.
-        IO.puts(interpolate(log_message, elixir_binding))
+        Output.debugger_console(interpolate(log_message, elixir_binding))
         false
       else
         result
@@ -178,7 +179,10 @@ defmodule ElixirLS.Debugger.BreakpointCondition do
       if term, do: true, else: false
     catch
       kind, error ->
-        IO.warn("Error in conditional breakpoint: " <> Exception.format_banner(kind, error))
+        Output.debugger_important(
+          "Error in conditional breakpoint: " <> Exception.format_banner(kind, error)
+        )
+
         false
     end
   end
@@ -189,7 +193,10 @@ defmodule ElixirLS.Debugger.BreakpointCondition do
       to_string(term)
     catch
       kind, error ->
-        IO.warn("Error in log message interpolation: " <> Exception.format_banner(kind, error))
+        Output.debugger_important(
+          "Error in log message interpolation: " <> Exception.format_banner(kind, error)
+        )
+
         ""
     end
   end
@@ -220,7 +227,7 @@ defmodule ElixirLS.Debugger.BreakpointCondition do
         interpolate(expression_rest, [eval_result | acc], elixir_binding)
 
       :error ->
-        IO.warn("Log message has unpaired or nested `{}`")
+        Output.debugger_important("Log message has unpaired or nested `{}`")
         acc
     end
   end

apps/elixir_ls_debugger/lib/debugger/cli.ex

@@ -3,24 +3,33 @@ defmodule ElixirLS.Debugger.CLI do
   alias ElixirLS.Debugger.{Output, Server}
 
   def main do
-    WireProtocol.intercept_output(&Output.print/1, &Output.print_err/1)
+    WireProtocol.intercept_output(&Output.debuggee_out/1, &Output.debuggee_err/1)
     Launch.start_mix()
     {:ok, _} = Application.ensure_all_started(:elixir_ls_debugger, :permanent)
 
-    IO.puts("Started ElixirLS debugger v#{Launch.debugger_version()}")
-    Launch.print_versions()
+    Output.debugger_console("Started ElixirLS Debugger v#{Launch.debugger_version()}")
+    versions = Launch.get_versions()
+
+    Output.debugger_console(
+      "ElixirLS Debugger built with elixir #{versions.compile_elixir_version} on OTP #{versions.compile_otp_version}"
+    )
+
+    Output.debugger_console(
+      "Running on elixir #{versions.current_elixir_version} on OTP #{versions.current_otp_version}"
+    )
+
     Launch.limit_num_schedulers()
     warn_if_unsupported_version()
     WireProtocol.stream_packets(&Server.receive_packet/1)
   end
 
   defp warn_if_unsupported_version do
     with {:error, message} <- ElixirLS.Utils.MinimumVersion.check_elixir_version() do
-      Output.print_err("WARNING: " <> message)
+      Output.debugger_important("WARNING: " <> message)
     end
 
     with {:error, message} <- ElixirLS.Utils.MinimumVersion.check_otp_version() do
-      Output.print_err("WARNING: " <> message)
+      Output.debugger_important("WARNING: " <> message)
     end
   end
 end

apps/elixir_ls_debugger/lib/debugger/output.ex

@@ -29,11 +29,19 @@ defmodule ElixirLS.Debugger.Output do
     GenServer.call(server, {:send_event, event, body})
   end
 
-  def print(server \\ __MODULE__, str) when is_binary(str) do
+  def debugger_console(server \\ __MODULE__, str) when is_binary(str) do
+    send_event(server, "output", %{"category" => "console", "output" => str})
+  end
+
+  def debugger_important(server \\ __MODULE__, str) when is_binary(str) do
+    send_event(server, "output", %{"category" => "important", "output" => str})
+  end
+
+  def debuggee_out(server \\ __MODULE__, str) when is_binary(str) do
     send_event(server, "output", %{"category" => "stdout", "output" => str})
   end
 
-  def print_err(server \\ __MODULE__, str) when is_binary(str) do
+  def debuggee_err(server \\ __MODULE__, str) when is_binary(str) do
     send_event(server, "output", %{"category" => "stderr", "output" => str})
   end
 

apps/elixir_ls_debugger/lib/debugger/server.ex

@@ -166,8 +166,7 @@ defmodule ElixirLS.Debugger.Server do
           0
 
         _ ->
-          IO.puts(
-            :standard_error,
+          Output.debugger_important(
             "(Debugger) Task failed because " <> Exception.format_exit(reason)
           )
 
@@ -181,8 +180,7 @@ defmodule ElixirLS.Debugger.Server do
   end
 
   def handle_info({:DOWN, _ref, :process, pid, reason}, state = %__MODULE__{}) do
-    IO.puts(
-      :standard_error,
+    Output.debugger_important(
       "debugged process #{inspect(pid)} exited with reason #{Exception.format_exit(reason)}"
     )
 
@@ -222,7 +220,7 @@ defmodule ElixirLS.Debugger.Server do
   @impl GenServer
   def terminate(reason, _state = %__MODULE__{}) do
     if reason != :normal do
-      IO.puts(:standard_error, "(Debugger) Terminating because #{Exception.format_exit(reason)}")
+      Output.debugger_important("(Debugger) Terminating because #{Exception.format_exit(reason)}")
     end
   end
 
@@ -231,17 +229,17 @@ defmodule ElixirLS.Debugger.Server do
   defp handle_request(initialize_req(_, client_info), %__MODULE__{client_info: nil} = state) do
     # linesStartAt1 is true by default and we only support 1-based indexing
     if client_info["linesStartAt1"] == false do
-      IO.warn("0-based lines are not supported")
+      Output.debugger_important("0-based lines are not supported")
     end
 
     # columnsStartAt1 is true by default and we only support 1-based indexing
     if client_info["columnsStartAt1"] == false do
-      IO.warn("0-based columns are not supported")
+      Output.debugger_important("0-based columns are not supported")
     end
 
     # pathFormat is `path` by default and we do not support other, e.g. `uri`
     if client_info["pathFormat"] not in [nil, "path"] do
-      IO.warn("pathFormat #{client_info["pathFormat"]} not supported")
+      Output.debugger_important("pathFormat #{client_info["pathFormat"]} not supported")
     end
 
     {capabilities(), %{state | client_info: client_info}}
@@ -258,16 +256,15 @@ defmodule ElixirLS.Debugger.Server do
 
   defp handle_request(launch_req(_, config) = args, state = %__MODULE__{}) do
     if args["arguments"]["noDebug"] == true do
-      IO.warn("launch with no debug is not supported")
+      Output.debugger_important("launch with no debug is not supported")
     end
 
     {_, ref} = spawn_monitor(fn -> initialize(config) end)
 
     receive do
       {:DOWN, ^ref, :process, _pid, reason} ->
         if reason != :normal do
-          IO.puts(
-            :standard_error,
+          Output.debugger_important(
             "(Debugger) Initialization failed because " <> Exception.format_exit(reason)
           )
 
@@ -337,7 +334,9 @@ defmodule ElixirLS.Debugger.Server do
           :ok
 
         {:error, :function_not_found} ->
-          IO.warn("Unable to delete function breakpoint on #{inspect({m, f, a})}")
+          Output.debugger_important(
+            "Unable to delete function breakpoint on #{inspect({m, f, a})}"
+          )
       end
     end
 
@@ -735,7 +734,9 @@ defmodule ElixirLS.Debugger.Server do
   catch
     kind, payload ->
       # when stepping out of interpreted code a MatchError is risen inside :int module (at least in OTP 23)
-      IO.warn(":int.#{action}(#{inspect(pid)}) failed: #{Exception.format(kind, payload)}")
+      Output.debugger_important(
+        ":int.#{action}(#{inspect(pid)}) failed: #{Exception.format(kind, payload)}"
+      )
 
       unless action == :continue do
         safe_int_action(pid, :continue)
@@ -972,7 +973,7 @@ defmodule ElixirLS.Debugger.Server do
     unless is_list(task_args) and "--no-compile" in task_args do
       case Mix.Task.run("compile", ["--ignore-module-conflict"]) do
         {:error, _} ->
-          IO.puts(:standard_error, "Aborting debugger due to compile errors")
+          Output.debugger_important("Aborting debugger due to compile errors")
           :init.stop(1)
 
         _ ->
@@ -1020,7 +1021,7 @@ defmodule ElixirLS.Debugger.Server do
   defp set_stack_trace_mode(nil), do: nil
 
   defp set_stack_trace_mode(_) do
-    IO.warn(~S(stackTraceMode must be "all", "no_tail", or "false"))
+    Output.debugger_important(~S(stackTraceMode must be "all", "no_tail", or "false"))
   end
 
   defp capabilities do
@@ -1150,8 +1151,7 @@ defmodule ElixirLS.Debugger.Server do
             [regex]
 
           {:error, error} ->
-            IO.puts(
-              :standard_error,
+            Output.debugger_important(
               "Unable to compile file pattern (#{inspect(pattern)}) into a regex. Received error: #{inspect(error)}"
             )
 
@@ -1226,7 +1226,7 @@ defmodule ElixirLS.Debugger.Server do
       {:module, _} = :int.ni(mod)
     catch
       _, _ ->
-        IO.warn(
+        Output.debugger_important(
           "Module #{inspect(mod)} cannot be interpreted. Consider adding it to `excludeModules`."
         )
     end
@@ -1252,7 +1252,7 @@ defmodule ElixirLS.Debugger.Server do
         end
 
       {:error, reason} ->
-        IO.warn(
+        Output.debugger_important(
           "Unable to set condition on a breakpoint in #{module}:#{inspect(lines)}: #{inspect(reason)}"
         )
     end
@@ -1266,7 +1266,7 @@ defmodule ElixirLS.Debugger.Server do
         condition
 
       {:error, reason} ->
-        IO.warn("Cannot parse breakpoint condition: #{inspect(reason)}")
+        Output.debugger_important("Cannot parse breakpoint condition: #{inspect(reason)}")
         "true"
     end
   end
@@ -1280,12 +1280,15 @@ defmodule ElixirLS.Debugger.Server do
       if is_integer(term) do
         term
       else
-        IO.warn("Hit condition must evaluate to integer")
+        Output.debugger_important("Hit condition must evaluate to integer")
         0
       end
     catch
       kind, error ->
-        IO.warn("Error while evaluating hit condition: " <> Exception.format_banner(kind, error))
+        Output.debugger_important(
+          "Error while evaluating hit condition: " <> Exception.format_banner(kind, error)
+        )
+
         0
     end
   end

apps/elixir_ls_debugger/lib/debugger/stacktrace.ex

@@ -2,6 +2,7 @@ defmodule ElixirLS.Debugger.Stacktrace do
   @moduledoc """
   Retrieves the stack trace for a process that's paused at a breakpoint
   """
+  alias ElixirLS.Debugger.Output
 
   defmodule Frame do
     defstruct [:level, :file, :module, :function, :args, :line, :bindings, :messages]
@@ -56,7 +57,10 @@ defmodule ElixirLS.Debugger.Stacktrace do
         [first_frame | other_frames]
 
       error ->
-        IO.warn("Failed to obtain meta for pid #{inspect(pid)}: #{inspect(error)}")
+        Output.debugger_important(
+          "Failed to obtain meta for pid #{inspect(pid)}: #{inspect(error)}"
+        )
+
         []
     end
   end

apps/elixir_ls_debugger/test/debugger_test.exs

@@ -402,7 +402,7 @@ defmodule ElixirLS.Debugger.ServerTest do
                      }),
                      500
 
-      {log, stderr} =
+      {log, _stderr} =
         capture_log_and_io(:standard_error, fn ->
           assert_receive event(_, "thread", %{
                            "reason" => "exited",
@@ -412,7 +412,6 @@ defmodule ElixirLS.Debugger.ServerTest do
         end)
 
       assert log =~ "Fixture MixProject expected error"
-      assert stderr =~ "Fixture MixProject expected error"
     end)
   end
 
@@ -461,7 +460,7 @@ defmodule ElixirLS.Debugger.ServerTest do
                      }),
                      5000
 
-      {log, io} =
+      {log, _io} =
         capture_log_and_io(:stderr, fn ->
           assert_receive event(_, "thread", %{
                            "reason" => "exited",
@@ -471,7 +470,6 @@ defmodule ElixirLS.Debugger.ServerTest do
         end)
 
       assert log =~ "Fixture MixProject raise for exit_self/0"
-      assert io =~ "Fixture MixProject raise for exit_self/0"
 
       assert_receive event(_, "exited", %{
                        "exitCode" => 1
@@ -560,20 +558,20 @@ defmodule ElixirLS.Debugger.ServerTest do
                  |> Enum.filter(&(&1["name"] |> String.starts_with?("MixProject.Some")))
                  |> Enum.map(& &1["id"])
 
-        {_, stderr} =
-          capture_log_and_io(:standard_error, fn ->
-            Server.receive_packet(server, request(7, "pause", %{"threadId" => thread_id}))
-            assert_receive(response(_, 7, "pause", %{}), 500)
+        Server.receive_packet(server, request(7, "pause", %{"threadId" => thread_id}))
+        assert_receive(response(_, 7, "pause", %{}), 500)
 
-            assert_receive event(_, "stopped", %{
-                             "allThreadsStopped" => false,
-                             "reason" => "pause",
-                             "threadId" => ^thread_id
-                           }),
-                           500
-          end)
+        assert_receive event(_, "stopped", %{
+                         "allThreadsStopped" => false,
+                         "reason" => "pause",
+                         "threadId" => ^thread_id
+                       }),
+                       500
 
-        assert stderr =~ "Failed to obtain meta for pid"
+        assert_receive event(_, "output", %{
+                         "category" => "important",
+                         "output" => "Failed to obtain meta for pid" <> _
+                       })
       end)
     end