feat!: be resilient to LSP protocol errors (#56)

Previously, if a user passed non compliant reply to a request, the
framework would raise and your server would crash.

Previously, if a client sent an invalid request or notification, the
framework would raise, not providing a good error for the user or the
LSP author.

Now, in those three cases, if the framework sees a non-compliant
response, it will respond to the client with a relevant error code and
message.

Note: in the case of notifications, we just log, as there is nothing to
respond to.

Author: mhanberg

lib/gen_lsp.ex

@@ -4,6 +4,54 @@ defmodule GenLSP do
              |> String.split("<!-- MDOC !-->")
              |> Enum.fetch!(1)
 
+  defmodule InvalidRequest do
+    defexception message: nil
+
+    @impl true
+    def exception({request, errors}) do
+      msg = """
+      Invalid request from the client
+
+      Received: #{inspect(request)}
+      Errors: #{inspect(errors)}
+      """
+
+      %__MODULE__{message: msg}
+    end
+  end
+
+  defmodule InvalidResponse do
+    defexception message: nil
+
+    @impl true
+    def exception({method, response, errors}) do
+      msg = """
+      Invalid response for request #{method}.
+
+      Response: #{inspect(response)}
+      Errors: #{inspect(errors)}
+      """
+
+      %__MODULE__{message: msg}
+    end
+  end
+
+  defmodule InvalidNotification do
+    defexception message: nil
+
+    @impl true
+    def exception({notification, errors}) do
+      msg = """
+      Invalid notification from the client
+
+      Given: #{inspect(notification)}
+      Errors: #{inspect(errors)}
+      """
+
+      %__MODULE__{message: msg}
+    end
+  end
+
   alias GenLSP.LSP
 
   defmacro __using__(_) do
@@ -251,7 +299,7 @@ defmodule GenLSP do
   end
 
   defp write_debug(device, event, name) do
-    IO.write(device, "#{inspect(name)} event = #{inspect(event)}")
+    IO.write(device, "#{inspect(name)} event = #{inspect(event)}\n")
   end
 
   defp loop(%LSP{} = lsp, parent, deb) do
@@ -270,55 +318,108 @@ defmodule GenLSP do
           "Last message received: handle_request #{inspect(request)}",
           [:gen_lsp, :request, :client],
           fn ->
-            {:ok, %{id: id} = req} = GenLSP.Requests.new(request)
-
-            result =
-              :telemetry.span([:gen_lsp, :handle_request], %{method: req.method}, fn ->
-                {lsp.mod.handle_request(req, lsp), %{}}
-              end)
-
-            case result do
-              {:reply, reply, %LSP{} = lsp} ->
-                response_key =
-                  case reply do
-                    %GenLSP.ErrorResponse{} -> "error"
-                    _ -> "result"
-                  end
+            case GenLSP.Requests.new(request) do
+              {:ok, %{id: id} = req} ->
+                result =
+                  :telemetry.span([:gen_lsp, :handle_request], %{method: req.method}, fn ->
+                    {lsp.mod.handle_request(req, lsp), %{}}
+                  end)
+
+                case result do
+                  {:reply, reply, %LSP{} = lsp} ->
+                    response_key =
+                      case reply do
+                        %GenLSP.ErrorResponse{} -> "error"
+                        _ -> "result"
+                      end
+
+                    # if result is valid, continue, if not, we return an internal error
+                    {response_key, response} =
+                      case Schematic.dump(req.__struct__.result(), reply) do
+                        {:ok, output} ->
+                          {response_key, output}
+
+                        {:error, errors} ->
+                          exception = InvalidResponse.exception({req.method, reply, errors})
+
+                          Logger.error(Exception.format(:error, exception))
+
+                          {:ok, output} =
+                            Schematic.dump(
+                              GenLSP.ErrorResponse.schematic(),
+                              %GenLSP.ErrorResponse{
+                                code: GenLSP.Enumerations.ErrorCodes.internal_error(),
+                                message: exception.message
+                              }
+                            )
+
+                          {"error", output}
+                      end
+
+                    packet = %{
+                      "jsonrpc" => "2.0",
+                      "id" => id,
+                      response_key => response
+                    }
+
+                    deb =
+                      :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:out, :request, from})
+
+                    GenLSP.Buffer.outgoing(lsp.buffer, packet)
+
+                    duration = System.system_time(:microsecond) - start
+
+                    Logger.debug(
+                      "handled request client -> server #{req.method} in #{format_time(duration)}",
+                      id: req.id,
+                      method: req.method
+                    )
+
+                    :telemetry.execute([:gen_lsp, :request, :client, :stop], %{duration: duration})
+
+                    loop(lsp, parent, deb)
+
+                  {:noreply, lsp} ->
+                    duration = System.system_time(:microsecond) - start
+
+                    Logger.debug(
+                      "handled request client -> server #{req.method} in #{format_time(duration)}",
+                      id: req.id,
+                      method: req.method
+                    )
+
+                    :telemetry.execute([:gen_lsp, :request, :client, :stop], %{duration: duration})
+
+                    loop(lsp, parent, deb)
+                end
+
+              {:error, errors} ->
+                # the payload is not parseable at all, other than being valid JSON and having
+                # an `id` property to signal its a request
+                exception = InvalidRequest.exception({request, errors})
+
+                Logger.error(Exception.format(:error, exception))
+
+                {:ok, output} =
+                  Schematic.dump(
+                    GenLSP.ErrorResponse.schematic(),
+                    %GenLSP.ErrorResponse{
+                      code: GenLSP.Enumerations.ErrorCodes.invalid_request(),
+                      message: exception.message
+                    }
+                  )
 
                 packet = %{
                   "jsonrpc" => "2.0",
-                  "id" => id,
-                  response_key => dump!(req.__struct__.result(), reply)
+                  "id" => request["id"],
+                  "error" => output
                 }
 
                 deb =
                   :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:out, :request, from})
 
                 GenLSP.Buffer.outgoing(lsp.buffer, packet)
 
-                duration = System.system_time(:microsecond) - start
-
-                Logger.debug(
-                  "handled request client -> server #{req.method} in #{format_time(duration)}",
-                  id: req.id,
-                  method: req.method
-                )
-
-                :telemetry.execute([:gen_lsp, :request, :client, :stop], %{duration: duration})
-
-                loop(lsp, parent, deb)
-
-              {:noreply, lsp} ->
-                duration = System.system_time(:microsecond) - start
-
-                Logger.debug(
-                  "handled request client -> server #{req.method} in #{format_time(duration)}",
-                  id: req.id,
-                  method: req.method
-                )
-
-                :telemetry.execute([:gen_lsp, :request, :client, :stop], %{duration: duration})
-
                 loop(lsp, parent, deb)
             end
           end
@@ -334,32 +435,45 @@ defmodule GenLSP do
           "Last message received: handle_notification #{inspect(notification)}",
           [:gen_lsp, :notification, :client],
           fn ->
-            {:ok, note} = GenLSP.Notifications.new(notification)
+            case GenLSP.Notifications.new(notification) do
+              {:ok, note} ->
+                result =
+                  :telemetry.span([:gen_lsp, :handle_notification], %{method: note.method}, fn ->
+                    {lsp.mod.handle_notification(note, lsp), %{}}
+                  end)
 
-            result =
-              :telemetry.span([:gen_lsp, :handle_notification], %{method: note.method}, fn ->
-                {lsp.mod.handle_notification(note, lsp), %{}}
-              end)
+                case result do
+                  {:noreply, %LSP{} = lsp} ->
+                    duration = System.system_time(:microsecond) - start
 
-            case result do
-              {:noreply, %LSP{} = lsp} ->
-                duration = System.system_time(:microsecond) - start
+                    Logger.debug(
+                      "handled notification client -> server #{note.method} in #{format_time(duration)}",
+                      method: note.method
+                    )
 
-                Logger.debug(
-                  "handled notification client -> server #{note.method} in #{format_time(duration)}",
-                  method: note.method
-                )
+                    :telemetry.execute([:gen_lsp, :notification, :client, :stop], %{
+                      duration: duration
+                    })
 
-                :telemetry.execute([:gen_lsp, :notification, :client, :stop], %{
-                  duration: duration
-                })
+                    loop(lsp, parent, deb)
+                end
+
+              {:error, errors} ->
+                # the payload is not parseable at all, other than being valid JSON
+                exception = InvalidNotification.exception({notification, errors})
+
+                Logger.warning(Exception.format(:error, exception))
+
+                deb =
+                  :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:out, :request, from})
 
                 loop(lsp, parent, deb)
             end
           end
         )
 
       message ->
+        deb = :sys.handle_debug(deb, &write_debug/3, __MODULE__, {:in, :info, message})
         start = System.system_time(:microsecond)
         :telemetry.execute([:gen_lsp, :info, :start], %{})
 

test/gen_lsp_test.exs

@@ -4,6 +4,7 @@ defmodule GenLSPTest do
   alias GenLSP.Structures
 
   import GenLSP.Test
+  import ExUnit.CaptureLog
 
   setup do
     server = server(GenLSPTest.ExampleServer, test_pid: self())
@@ -190,13 +191,12 @@ defmodule GenLSPTest do
 
     assert :ok ==
              request(client, %{
-               method: "textDocument/documentSymbol",
+               method: "textDocument/definition",
                id: id,
                jsonrpc: "2.0",
                params: %{
-                 textDocument: %{
-                   uri: "file://file/doesnt/matter.ex"
-                 }
+                 position: %{line: 0, character: 0},
+                 textDocument: %{uri: "foo"}
                }
              })
 
@@ -214,4 +214,67 @@ defmodule GenLSPTest do
 
     refute alive?(server)
   end
+
+  test "returns an internal error and logs when the reply to a request is invalid", %{
+    client: client
+  } do
+    id = System.unique_integer([:positive])
+
+    expected_msg =
+      ~S'''
+      Invalid response for request textDocument/documentSymbol.
+
+      Response: [nil, []]
+      Errors: "expected either either a list of a %GenLSP.Structures.SymbolInformation{}, a list of a %GenLSP.Structures.DocumentSymbol{}, or null or a %GenLSP.ErrorResponse{}"
+      '''
+
+    assert :ok ==
+             request(client, %{
+               "jsonrpc" => "2.0",
+               "method" => "initialize",
+               "params" => %{"capabilities" => %{}},
+               "id" => id
+             })
+
+    log =
+      capture_log(fn ->
+        assert :ok ==
+                 request(client, %{
+                   "jsonrpc" => "2.0",
+                   "method" => "textDocument/documentSymbol",
+                   "params" => %{"textDocument" => %{"uri" => "foo"}},
+                   "id" => 2
+                 })
+
+        assert_error 2,
+                     %{
+                       "message" => msg,
+                       "code" => -32603
+                     },
+                     500
+
+        assert msg =~ expected_msg
+      end)
+
+    assert log =~ expected_msg
+  end
+
+  test "returns an invalid request when the paylaod is not parseable, but is still deemed a request",
+       %{client: client} do
+    assert :ok == request(client, %{"id" => "bingo", "random" => "stuff"})
+
+    assert_error "bingo",
+                 %{
+                   "message" => "Invalid request from the client" <> _,
+                   "code" => -32600
+                 },
+                 500
+  end
+
+  test "logs when an invalid payload is received", %{client: client} do
+    assert capture_log(fn ->
+             assert :ok == notify(client, %{"random" => "stuff"})
+             Process.sleep(100)
+           end) =~ "Invalid notification from the client"
+  end
 end

test/support/example_server.ex

@@ -27,6 +27,10 @@ defmodule GenLSPTest.ExampleServer do
      }, lsp}
   end
 
+  def handle_request(%Requests.TextDocumentDocumentSymbol{}, lsp) do
+    {:reply, [nil, []], lsp}
+  end
+
   def handle_request(_, lsp) do
     {:reply,
      %GenLSP.ErrorResponse{