feat: opentelemetry + logging (#311)

This patch adds support for opentelemetry tracing as well as better logging.

The included docker-compose includes grafana tempo to view the opentelemetry traces

.gitignore

@@ -31,3 +31,5 @@ result
 /priv/plts/*.plt
 /priv/plts/*.plt.hash
 node_modules
+
+tempo-data

bin/start

@@ -2,4 +2,4 @@
 
 cd "$(dirname "$0")"/.. || exit 1
 
-elixir -S mix run --no-halt -e "Application.ensure_all_started(:next_ls)" -- "$@"
+mix run --no-halt -e "Application.ensure_all_started(:next_ls)" -- "$@"

config/config.exs

@@ -2,6 +2,16 @@ import Config
 
 config :next_ls, :indexing_timeout, 100
 
-config :logger, :default_handler, config: [type: :standard_error]
+config :logger, :default_handler,
+  config: [
+    file: ~c".elixir-tools/next-ls.log",
+    filesync_repeat_interval: 5000,
+    file_check: 5000,
+    max_no_bytes: 10_000_000,
+    max_no_files: 5,
+    compress_on_rotate: true
+  ]
+
+config :logger, :default_formatter, format: "\n$time $metadata[$level] $message\n", metadata: [:id]
 
 import_config "#{config_env()}.exs"

config/runtime.exs

@@ -0,0 +1,12 @@
+import Config
+
+if System.get_env("NEXTLS_OTEL") == "1" do
+  config :next_ls,
+    otel: true
+
+  config :opentelemetry_exporter,
+    otlp_protocol: :grpc,
+    otlp_endpoint: "http://localhost:4317"
+else
+  config :opentelemetry, traces_exporter: :none
+end

config/test.exs

@@ -1,3 +1,5 @@
 import Config
 
+config :logger, :default_handler, config: [type: :standard_error]
+
 config :gen_lsp, :exit_on_end, false

docker-compose.yml

@@ -0,0 +1,47 @@
+version: "3"
+services:
+  tempo:
+    image: grafana/tempo:latest
+    command: [ "-config.file=/etc/tempo.yaml" ]
+    volumes:
+      - ./tempo.yaml:/etc/tempo.yaml
+      - ./tempo-data:/tmp/tempo
+    ports:
+      - "14268:14268"  # jaeger ingest
+      - "3200:3200"   # tempo
+      # - "4317:4317"  # otlp grpc
+      # - "4318:4318"  # otlp http
+      - "9411:9411"   # zipkin
+
+  otel-collector:
+    image: otel/opentelemetry-collector:0.61.0
+    command: [ "--config=/etc/otel-collector.yaml" ]
+    volumes:
+      - ./otel-collector.yaml:/etc/otel-collector.yaml
+    ports:
+      - "4317:4317"  # otlp grpc
+      - "4318:4318"  # otlp http
+
+  prometheus:
+    image: prom/prometheus:latest
+    command:
+      - --config.file=/etc/prometheus.yaml
+      - --web.enable-remote-write-receiver
+      - --enable-feature=exemplar-storage
+    volumes:
+      - ./prometheus.yaml:/etc/prometheus.yaml
+    ports:
+      - "9090:9090"
+
+  grafana:
+    image: grafana/grafana:9.4.3
+    volumes:
+      - ./grafana-datasources.yaml:/etc/grafana/provisioning/datasources/datasources.yaml
+    environment:
+      - GF_AUTH_ANONYMOUS_ENABLED=true
+      - GF_AUTH_ANONYMOUS_ORG_ROLE=Admin
+      - GF_AUTH_DISABLE_LOGIN_FORM=true
+      - GF_FEATURE_TOGGLES_ENABLE=traceqlEditor
+    ports:
+      - "3000:3000"
+

flake.nix

@@ -61,7 +61,7 @@
             src = self.outPath;
             inherit version elixir;
             pname = "next-ls-deps";
-            hash = "sha256-LV1DYmWi0Mcz1S5k77/jexXYqay7OpysCwOtUcafqGE=";
+            hash = "sha256-M8BtmnSWpABqu8ZelZkzG1BOhD8sm3MoqXFIEgCy708=";
           };
 
           BURRITO_ERTS_PATH = "${beamPackages.erlang}/lib/erlang";

grafana-datasources.yaml

@@ -0,0 +1,30 @@
+apiVersion: 1
+
+datasources:
+- name: Prometheus
+  type: prometheus
+  uid: prometheus
+  access: proxy
+  orgId: 1
+  url: http://prometheus:9090
+  basicAuth: false
+  isDefault: false
+  version: 1
+  editable: false
+  jsonData:
+    httpMethod: GET
+- name: Tempo
+  type: tempo
+  access: proxy
+  orgId: 1
+  url: http://tempo:3200
+  basicAuth: false
+  isDefault: true
+  version: 1
+  editable: false
+  apiVersion: 1
+  uid: tempo
+  jsonData:
+    httpMethod: GET
+    serviceMap:
+      datasourceUid: prometheus

lib/next_ls/application.ex

@@ -7,6 +7,11 @@ defmodule NextLS.Application do
 
   @impl true
   def start(_type, _args) do
+    if Application.get_env(:next_ls, :otel, false) do
+      NextLS.OpentelemetrySchematic.setup()
+      NextLS.OpentelemetryGenLSP.setup()
+    end
+
     case System.cmd("epmd", ["-daemon"], stderr_to_stdout: true) do
       {_, 0} ->
         :ok

lib/next_ls/db.ex

@@ -4,14 +4,21 @@ defmodule NextLS.DB do
 
   import __MODULE__.Query
 
+  alias OpenTelemetry.Tracer
+
+  require OpenTelemetry.Tracer
+
   @type query :: String.t()
 
   def start_link(args) do
     GenServer.start_link(__MODULE__, args, Keyword.take(args, [:name]))
   end
 
   @spec query(pid(), query(), list()) :: list()
-  def query(server, query, opts \\ []), do: GenServer.call(server, {:query, query, opts}, :infinity)
+  def query(server, query, opts \\ []) do
+    ctx = OpenTelemetry.Ctx.get_current()
+    GenServer.call(server, {:query, query, opts, ctx}, :infinity)
+  end
 
   @spec insert_symbol(pid(), map()) :: :ok
   def insert_symbol(server, payload), do: GenServer.cast(server, {:insert_symbol, payload})
@@ -43,28 +50,36 @@ defmodule NextLS.DB do
      }}
   end
 
-  def handle_call({:query, query, args_or_opts}, _from, %{conn: conn} = s) do
-    {:message_queue_len, count} = Process.info(self(), :message_queue_len)
-    NextLS.DB.Activity.update(s.activity, count)
-    opts = if Keyword.keyword?(args_or_opts), do: args_or_opts, else: [args: args_or_opts]
-
-    query =
-      if opts[:select] do
-        String.replace(query, ":select", Enum.map_join(opts[:select], ", ", &to_string/1))
-      else
-        query
+  def handle_call({:query, query, args_or_opts, ctx}, _from, %{conn: conn} = s) do
+    token = OpenTelemetry.Ctx.attach(ctx)
+
+    try do
+      Tracer.with_span :"db.query receive", %{attributes: %{query: query}} do
+        {:message_queue_len, count} = Process.info(self(), :message_queue_len)
+        NextLS.DB.Activity.update(s.activity, count)
+        opts = if Keyword.keyword?(args_or_opts), do: args_or_opts, else: [args: args_or_opts]
+
+        query =
+          if opts[:select] do
+            String.replace(query, ":select", Enum.map_join(opts[:select], ", ", &to_string/1))
+          else
+            query
+          end
+
+        rows =
+          for row <- __query__({conn, s.logger}, query, opts[:args] || []) do
+            if opts[:select] do
+              opts[:select] |> Enum.zip(row) |> Map.new()
+            else
+              row
+            end
+          end
+
+        {:reply, rows, s}
       end
-
-    rows =
-      for row <- __query__({conn, s.logger}, query, opts[:args] || []) do
-        if opts[:select] do
-          opts[:select] |> Enum.zip(row) |> Map.new()
-        else
-          row
-        end
-      end
-
-    {:reply, rows, s}
+    after
+      OpenTelemetry.Ctx.detach(token)
+    end
   end
 
   def handle_cast({:insert_symbol, symbol}, %{conn: conn} = s) do
@@ -190,22 +205,24 @@ defmodule NextLS.DB do
   end
 
   def __query__({conn, logger}, query, args) do
-    args = Enum.map(args, &cast/1)
+    Tracer.with_span :"db.query process", %{attributes: %{query: query}} do
+      args = Enum.map(args, &cast/1)
 
-    case Exqlite.Basic.exec(conn, query, args) do
-      {:error, %{message: message, statement: statement}, _} ->
-        NextLS.Logger.warning(logger, """
-        sqlite3 error: #{message}
+      case Exqlite.Basic.exec(conn, query, args) do
+        {:error, %{message: message, statement: statement}, _} ->
+          NextLS.Logger.warning(logger, """
+          sqlite3 error: #{message}
 
-        statement: #{statement}
-        arguments: #{inspect(args)}
-        """)
+          statement: #{statement}
+          arguments: #{inspect(args)}
+          """)
 
-        {:error, message}
+          {:error, message}
 
-      result ->
-        {:ok, rows, _} = Exqlite.Basic.rows(result)
-        rows
+        result ->
+          {:ok, rows, _} = Exqlite.Basic.rows(result)
+          rows
+      end
     end
   end
 

lib/next_ls/db/schema.ex

@@ -29,7 +29,7 @@ defmodule NextLS.DB.Schema do
     # FIXME: this is odd tech debt. not a big deal but is confusing
     {_, logger} = conn
 
-    NextLS.Logger.log(logger, "Beginning DB migration...")
+    NextLS.Logger.info(logger, "Beginning DB migration...")
 
     DB.__query__(
       conn,
@@ -113,7 +113,7 @@ defmodule NextLS.DB.Schema do
           {:ok, :reindex}
       end
 
-    NextLS.Logger.log(logger, "Finished DB migration...")
+    NextLS.Logger.info(logger, "Finished DB migration...")
     result
   end
 end

lib/next_ls/extensions/credo_extension.ex

@@ -30,7 +30,7 @@ defmodule NextLS.CredoExtension do
     if settings.enable do
       Registry.register(registry, :extensions, :credo)
 
-      NextLS.Logger.log(logger, "[extension] Credo initializing with options #{inspect(settings)}")
+      NextLS.Logger.info(logger, "[extension] Credo initializing with options #{inspect(settings)}")
 
       {:ok,
        %{
@@ -44,7 +44,7 @@ defmodule NextLS.CredoExtension do
          refresh_refs: Map.new()
        }}
     else
-      NextLS.Logger.log(logger, "[extension] Credo disabled")
+      NextLS.Logger.info(logger, "[extension] Credo disabled")
       :ignore
     end
   end

lib/next_ls/logger.ex

@@ -2,6 +2,8 @@ defmodule NextLS.Logger do
   @moduledoc false
   use GenServer
 
+  require Logger
+
   def start_link(arg) do
     GenServer.start_link(__MODULE__, arg, Keyword.take(arg, [:name]))
   end
@@ -22,6 +24,14 @@ defmodule NextLS.Logger do
 
   def handle_cast({:log, type, msg}, state) do
     apply(GenLSP, type, [state.lsp, String.trim("[NextLS] #{msg}")])
+
+    case type do
+      :log -> Logger.debug(msg)
+      :warning -> Logger.warning(msg)
+      :error -> Logger.error(msg)
+      :info -> Logger.info(msg)
+    end
+
     {:noreply, state}
   end
 

lib/next_ls/opentelemetry/gen_lsp.ex

@@ -0,0 +1,68 @@
+defmodule NextLS.OpentelemetryGenLSP do
+  @moduledoc false
+  require Logger
+
+  @tracer_id __MODULE__
+
+  def setup do
+    :ok =
+      :telemetry.attach_many(
+        "gen_lsp-handler",
+        [
+          [:gen_lsp, :notify, :server, :start],
+          [:gen_lsp, :notify, :server, :stop],
+          [:gen_lsp, :request, :server, :start],
+          [:gen_lsp, :request, :server, :stop],
+          [:gen_lsp, :request, :client, :start],
+          [:gen_lsp, :request, :client, :stop],
+          [:gen_lsp, :notification, :client, :start],
+          [:gen_lsp, :notification, :client, :stop],
+          [:gen_lsp, :handle_request, :start],
+          [:gen_lsp, :handle_request, :stop],
+          [:gen_lsp, :handle_notification, :start],
+          [:gen_lsp, :handle_notification, :stop],
+          [:gen_lsp, :handle_info, :start],
+          [:gen_lsp, :handle_info, :stop]
+          # [:gen_lsp, :buffer, :outgoing, :start],
+          # [:gen_lsp, :buffer, :outgoing, :stop],
+          # [:gen_lsp, :buffer, :incoming, :start],
+          # [:gen_lsp, :buffer, :incoming, :stop]
+        ],
+        &__MODULE__.process/4,
+        nil
+      )
+  end
+
+  def process([:gen_lsp, type1, type2, :start], _measurements, metadata, _config) do
+    OpentelemetryTelemetry.start_telemetry_span(
+      @tracer_id,
+      :"gen_lsp.#{type1}.#{type2}",
+      metadata,
+      %{kind: :server, attributes: metadata}
+    )
+  end
+
+  def process([:gen_lsp, handle, :start], _measurements, metadata, _config) do
+    if handle in [:handle_request, :handle_notification] do
+      # set attribute for parent span
+      OpenTelemetry.Tracer.set_attribute(:method, metadata[:method])
+    end
+
+    OpentelemetryTelemetry.start_telemetry_span(
+      @tracer_id,
+      :"next_ls.#{handle}",
+      metadata,
+      %{kind: :server, attributes: metadata}
+    )
+  end
+
+  def process([:gen_lsp, _, _, :stop], _measurements, metadata, _config) do
+    OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, metadata)
+    OpentelemetryTelemetry.end_telemetry_span(@tracer_id, metadata)
+  end
+
+  def process([:gen_lsp, _, :stop], _measurements, metadata, _config) do
+    OpentelemetryTelemetry.set_current_telemetry_span(@tracer_id, metadata)
+    OpentelemetryTelemetry.end_telemetry_span(@tracer_id, metadata)
+  end
+end