add telemetry to DAP and LSP requests

lukaszsamson · lukaszsamson · commit ed3552c48c72 · 2023-10-18T22:26:45.000+02:00
diff --git a/apps/elixir_ls_debugger/lib/debugger/output.ex b/apps/elixir_ls_debugger/lib/debugger/output.ex
@@ -60,6 +60,27 @@ defmodule ElixirLS.Debugger.Output do
     send_event(server, "output", %{"category" => "stderr", "output" => maybe_append_newline(str)})
   end
 
+  def telemetry(server \\ __MODULE__, event, properties, measurements)
+      when is_binary(event) and is_map(properties) and is_map(measurements) do
+    common_properties = %{
+      "elixir_ls.elixir_version" => System.version(),
+      "elixir_ls.otp_release" => System.otp_release(),
+      "elixir_ls.erts_version" => Application.spec(:erts, :vsn),
+      "elixir_ls.mix_env" => Mix.env(),
+      "elixir_ls.mix_target" => Mix.target()
+    }
+
+    send_event(server, "output", %{
+      "category" => "telemetry",
+      "output" => event,
+      "data" => %{
+        "name" => event,
+        "properties" => Map.merge(common_properties, properties),
+        "measurements" => measurements
+      }
+    })
+  end
+
   defp maybe_append_newline(message) do
     unless String.ends_with?(message, "\n") do
       message <> "\n"
diff --git a/apps/elixir_ls_debugger/lib/debugger/server.ex b/apps/elixir_ls_debugger/lib/debugger/server.ex
@@ -281,7 +281,11 @@ defmodule ElixirLS.Debugger.Server do
     {:noreply, %{state | dbg_session: from}}
   end
 
-  def handle_call({:request_finished, packet, result}, _from, state = %__MODULE__{}) do
+  def handle_call(
+        {:request_finished, request(_, command) = packet, start_time, result},
+        _from,
+        state = %__MODULE__{}
+      ) do
     if MapSet.member?(state.progresses, packet["seq"]) do
       Output.send_event("progressEnd", %{
         "progressId" => packet["seq"]
@@ -300,7 +304,12 @@ defmodule ElixirLS.Debugger.Server do
         )
 
       {:ok, response_body} ->
+        elapsed = System.monotonic_time(:millisecond) - start_time
         Output.send_response(packet, response_body)
+
+        Output.telemetry("elixir_ls.dap_request", %{"elixir_ls.dap_command" => command}, %{
+          "elixir_ls.dap_request_time" => elapsed
+        })
     end
 
     state = %{
@@ -325,16 +334,33 @@ defmodule ElixirLS.Debugger.Server do
   @impl GenServer
   def handle_cast({:receive_packet, request(_, "disconnect") = packet}, state = %__MODULE__{}) do
     Output.send_response(packet, %{})
+
+    Output.telemetry("elixir_ls.dap_request", %{"elixir_ls.dap_command" => "disconnect"}, %{
+      "elixir_ls.dap_request_time" => 0
+    })
+
     {:noreply, state, {:continue, :disconnect}}
   end
 
-  def handle_cast({:receive_packet, request(seq, _) = packet}, state = %__MODULE__{}) do
+  def handle_cast({:receive_packet, request(seq, command) = packet}, state = %__MODULE__{}) do
+    start_time = System.monotonic_time(:millisecond)
+
     try do
       if state.client_info == nil do
         case packet do
           request(_, "initialize") ->
             {response_body, state} = handle_request(packet, state)
+            elapsed = System.monotonic_time(:millisecond) - start_time
             Output.send_response(packet, response_body)
+
+            Output.telemetry(
+              "elixir_ls.dap_request",
+              %{"elixir_ls.dap_command" => "initialize"},
+              %{
+                "elixir_ls.dap_request_time" => elapsed
+              }
+            )
+
             {:noreply, state}
 
           request(_, command) ->
@@ -349,11 +375,17 @@ defmodule ElixirLS.Debugger.Server do
         state =
           case handle_request(packet, state) do
             {response_body, state} ->
+              elapsed = System.monotonic_time(:millisecond) - start_time
               Output.send_response(packet, response_body)
+
+              Output.telemetry("elixir_ls.dap_request", %{"elixir_ls.dap_command" => command}, %{
+                "elixir_ls.dap_request_time" => elapsed
+              })
+
               state
 
             {:async, fun, state} ->
-              {pid, _ref} = handle_request_async(packet, fun)
+              {pid, _ref} = handle_request_async(packet, start_time, fun)
               %{state | requests: Map.put(state.requests, seq, {pid, packet})}
           end
 
@@ -2096,7 +2128,7 @@ defmodule ElixirLS.Debugger.Server do
     end
   end
 
-  defp handle_request_async(packet, func) do
+  defp handle_request_async(packet, start_time, func) do
     parent = self()
 
     spawn_monitor(fn ->
@@ -2116,7 +2148,7 @@ defmodule ElixirLS.Debugger.Server do
              %ServerError{message: "internalServerError", format: message, variables: %{}}}
         end
 
-      GenServer.call(parent, {:request_finished, packet, result}, :infinity)
+      GenServer.call(parent, {:request_finished, packet, start_time, result}, :infinity)
     end)
   end
 end
diff --git a/apps/language_server/lib/language_server/json_rpc.ex b/apps/language_server/lib/language_server/json_rpc.ex
@@ -90,6 +90,22 @@ defmodule ElixirLS.LanguageServer.JsonRpc do
     notify("window/logMessage", %{type: message_type_code(type), message: to_string(message)})
   end
 
+  def telemetry(name, properties, measurements) do
+    common_properties = %{
+      "elixir_ls.elixir_version" => System.version(),
+      "elixir_ls.otp_release" => System.otp_release(),
+      "elixir_ls.erts_version" => Application.spec(:erts, :vsn),
+      "elixir_ls.mix_env" => Mix.env(),
+      "elixir_ls.mix_target" => Mix.target()
+    }
+
+    notify("telemetry/event", %{
+      name: name,
+      properties: Map.merge(common_properties, properties),
+      measurements: measurements
+    })
+  end
+
   def register_capability_request(server \\ __MODULE__, server_instance_id, method, options) do
     id = server_instance_id <> method <> JasonV.encode!(options)
 
diff --git a/apps/language_server/lib/language_server/providers/execute_command.ex b/apps/language_server/lib/language_server/providers/execute_command.ex
@@ -18,7 +18,7 @@ defmodule ElixirLS.LanguageServer.Providers.ExecuteCommand do
               {:ok, any} | {:error, atom, String.t()}
 
   def execute(command_with_server_id, args, state) do
-    with [command, _server_id] <- String.split(command_with_server_id, ":"),
+    with command when not is_nil(command) <- get_command(command_with_server_id),
          handler when not is_nil(handler) <- Map.get(@handlers, command) do
       handler.execute(args, state)
     else
@@ -32,4 +32,11 @@ defmodule ElixirLS.LanguageServer.Providers.ExecuteCommand do
       "#{k}:#{server_instance_id}"
     end
   end
+
+  def get_command(command_with_server_id) do
+    case String.split(command_with_server_id, ":") do
+      [command, _server_id] -> command
+      _ -> nil
+    end
+  end
 end
diff --git a/apps/language_server/lib/language_server/server.ex b/apps/language_server/lib/language_server/server.ex
@@ -130,12 +130,32 @@ defmodule ElixirLS.LanguageServer.Server do
 
   @impl GenServer
   def handle_call({:request_finished, id, result}, _from, state = %__MODULE__{}) do
+    {{_pid, command, start_time}, requests} = Map.pop!(state.requests, id)
+
     case result do
-      {:error, type, msg} -> JsonRpc.respond_with_error(id, type, msg)
-      {:ok, result} -> JsonRpc.respond(id, result)
+      {:error, type, msg} ->
+        JsonRpc.respond_with_error(id, type, msg)
+
+        JsonRpc.telemetry(
+          "elixir_ls.lsp_request_error",
+          %{
+            "elixir_ls.lsp_command" => command,
+            "elixir_ls.lsp_error" => type,
+            "elixir_ls.lsp_error_message" => msg
+          },
+          %{}
+        )
+
+      {:ok, result} ->
+        elapsed = System.monotonic_time(:millisecond) - start_time
+        JsonRpc.respond(id, result)
+
+        JsonRpc.telemetry("elixir_ls.lsp_request", %{"elixir_ls.lsp_command" => command}, %{
+          "elixir_ls.lsp_request_time" => elapsed
+        })
     end
 
-    state = %{state | requests: Map.delete(state.requests, id)}
+    state = %{state | requests: requests}
     {:reply, :ok, state}
   end
 
@@ -259,10 +279,21 @@ defmodule ElixirLS.LanguageServer.Server do
   @impl GenServer
   def handle_info({:DOWN, _ref, :process, pid, reason}, %__MODULE__{requests: requests} = state) do
     state =
-      case Enum.find(requests, &match?({_, ^pid}, &1)) do
-        {id, _} ->
+      case Enum.find(requests, &match?({_, {^pid, _, _}}, &1)) do
+        {id, {^pid, command, _start_time}} ->
           error_msg = Exception.format_exit(reason)
           JsonRpc.respond_with_error(id, :server_error, error_msg)
+
+          JsonRpc.telemetry(
+            "elixir_ls.lsp_request_error",
+            %{
+              "elixir_ls.lsp_command" => command,
+              "elixir_ls.lsp_error" => :server_error,
+              "elixir_ls.lsp_error_message" => error_msg
+            },
+            %{}
+          )
+
           %{state | requests: Map.delete(requests, id)}
 
         nil ->
@@ -360,9 +391,10 @@ defmodule ElixirLS.LanguageServer.Server do
 
   defp handle_notification(cancel_request(id), %__MODULE__{requests: requests} = state) do
     case requests do
-      %{^id => pid} ->
+      %{^id => {pid, _command, _start_time}} ->
         Process.exit(pid, :cancelled)
         JsonRpc.respond_with_error(id, :request_cancelled, "Request cancelled")
+
         %{state | requests: Map.delete(requests, id)}
 
       _ ->
@@ -579,40 +611,132 @@ defmodule ElixirLS.LanguageServer.Server do
          state = %__MODULE__{server_instance_id: server_instance_id}
        )
        when not is_initialized(server_instance_id) do
+    start_time = System.monotonic_time(:millisecond)
+
     case packet do
       initialize_req(_id, _root_uri, _client_capabilities) ->
         {:ok, result, state} = handle_request(packet, state)
+        elapsed = System.monotonic_time(:millisecond) - start_time
         JsonRpc.respond(id, result)
+
+        JsonRpc.telemetry("elixir_ls.lsp_request", %{"elixir_ls.lsp_command" => "initialize"}, %{
+          "elixir_ls.lsp_request_time" => elapsed
+        })
+
         state
 
       _ ->
         JsonRpc.respond_with_error(id, :server_not_initialized)
+
+        JsonRpc.telemetry(
+          "elixir_ls.lsp_request_error",
+          %{
+            "elixir_ls.lsp_command" => "initialize",
+            "elixir_ls.lsp_error" => :server_not_initialized,
+            "elixir_ls.lsp_error_message" => "Server not initialized"
+          },
+          %{}
+        )
+
         state
     end
   end
 
-  defp handle_request_packet(id, packet, state = %__MODULE__{received_shutdown?: false}) do
-    case handle_request(packet, state) do
-      {:ok, result, state} ->
-        JsonRpc.respond(id, result)
-        state
+  defp handle_request_packet(
+         id,
+         packet = %{"method" => command},
+         state = %__MODULE__{received_shutdown?: false}
+       ) do
+    command =
+      case packet do
+        execute_command_req(_id, custom_command_with_server_id, _args) ->
+          command <> ":" <> (ExecuteCommand.get_command(custom_command_with_server_id) || "")
+
+        _ ->
+          command
+      end
+
+    start_time = System.monotonic_time(:millisecond)
+
+    try do
+      case handle_request(packet, state) do
+        {:ok, result, state} ->
+          elapsed = System.monotonic_time(:millisecond) - start_time
+          JsonRpc.respond(id, result)
+
+          JsonRpc.telemetry("elixir_ls.lsp_request", %{"elixir_ls.lsp_command" => command}, %{
+            "elixir_ls.lsp_request_time" => elapsed
+          })
+
+          state
+
+        {:error, type, msg, state} ->
+          JsonRpc.respond_with_error(id, type, msg)
+
+          JsonRpc.telemetry(
+            "elixir_ls.lsp_request_error",
+            %{
+              "elixir_ls.lsp_command" => command,
+              "elixir_ls.lsp_error" => type,
+              "elixir_ls.lsp_error_message" => msg
+            },
+            %{}
+          )
+
+          state
+
+        {:async, fun, state} ->
+          {pid, _ref} = handle_request_async(id, fun)
+          %{state | requests: Map.put(state.requests, id, {pid, command, start_time})}
+      end
+    rescue
+      e in InvalidParamError ->
+        JsonRpc.respond_with_error(id, :invalid_params, e.message)
+
+        JsonRpc.telemetry(
+          "elixir_ls.lsp_request_error",
+          %{
+            "elixir_ls.lsp_command" => command,
+            "elixir_ls.lsp_error" => :invalid_params,
+            "elixir_ls.lsp_error_message" => e.message
+          },
+          %{}
+        )
 
-      {:error, type, msg, state} ->
-        JsonRpc.respond_with_error(id, type, msg)
         state
+    catch
+      kind, payload ->
+        {payload, stacktrace} = Exception.blame(kind, payload, __STACKTRACE__)
+        error_msg = Exception.format(kind, payload, stacktrace)
+        JsonRpc.respond_with_error(id, :server_error, error_msg)
+
+        JsonRpc.telemetry(
+          "elixir_ls.lsp_request_error",
+          %{
+            "elixir_ls.lsp_command" => command,
+            "elixir_ls.lsp_error" => :server_error,
+            "elixir_ls.lsp_error_message" => error_msg
+          },
+          %{}
+        )
 
-      {:async, fun, state} ->
-        {pid, _ref} = handle_request_async(id, fun)
-        %{state | requests: Map.put(state.requests, id, pid)}
+        state
     end
-  rescue
-    e in InvalidParamError ->
-      JsonRpc.respond_with_error(id, :invalid_params, e.message)
-      state
   end
 
-  defp handle_request_packet(id, _packet, state = %__MODULE__{}) do
+  defp handle_request_packet(id, _packet = %{"method" => command}, state = %__MODULE__{}) do
     JsonRpc.respond_with_error(id, :invalid_request)
+
+    JsonRpc.telemetry(
+      "elixir_ls.lsp_request_error",
+      %{
+        "elixir_ls.lsp_command" => command,
+        "elixir_ls.lsp_error" => :invalid_request,
+        "elixir_ls.lsp_error_message" => "Invalid Request"
+      },
+      %{}
+    )
+
     state
   end
 
