git.squeep.com Git - akkoma/blob - lib/pleroma/telemetry/logger.ex

   1 # Pleroma: A lightweight social networking server
   2 # Copyright © 2017-2021 Pleroma Authors <https://pleroma.social/>
   3 # SPDX-License-Identifier: AGPL-3.0-only
   4
   5 defmodule Pleroma.Telemetry.Logger do
   6   @moduledoc "Transforms Pleroma telemetry events to logs"
   7
   8   require Logger
   9
  10   @events [
  11     [:pleroma, :connection_pool, :reclaim, :start],
  12     [:pleroma, :connection_pool, :reclaim, :stop],
  13     [:pleroma, :connection_pool, :provision_failure],
  14     [:pleroma, :connection_pool, :client, :dead],
  15     [:pleroma, :connection_pool, :client, :add],
  16     [:pleroma, :repo, :query]
  17   ]
  18   def attach do
  19     :telemetry.attach_many(
  20       "pleroma-logger",
  21       @events,
  22       &Pleroma.Telemetry.Logger.handle_event/4,
  23       []
  24     )
  25   end
  26
  27   # Passing anonymous functions instead of strings to logger is intentional,
  28   # that way strings won't be concatenated if the message is going to be thrown
  29   # out anyway due to higher log level configured
  30
  31   def handle_event(
  32         [:pleroma, :connection_pool, :reclaim, :start],
  33         _,
  34         %{max_connections: max_connections, reclaim_max: reclaim_max},
  35         _
  36       ) do
  37     Logger.debug(fn ->
  38       "Connection pool is exhausted (reached #{max_connections} connections). Starting idle connection cleanup to reclaim as much as #{
  39         reclaim_max
  40       } connections"
  41     end)
  42   end
  43
  44   def handle_event(
  45         [:pleroma, :connection_pool, :reclaim, :stop],
  46         %{reclaimed_count: 0},
  47         _,
  48         _
  49       ) do
  50     Logger.error(fn ->
  51       "Connection pool failed to reclaim any connections due to all of them being in use. It will have to drop requests for opening connections to new hosts"
  52     end)
  53   end
  54
  55   def handle_event(
  56         [:pleroma, :connection_pool, :reclaim, :stop],
  57         %{reclaimed_count: reclaimed_count},
  58         _,
  59         _
  60       ) do
  61     Logger.debug(fn -> "Connection pool cleaned up #{reclaimed_count} idle connections" end)
  62   end
  63
  64   def handle_event(
  65         [:pleroma, :connection_pool, :provision_failure],
  66         %{opts: [key | _]},
  67         _,
  68         _
  69       ) do
  70     Logger.error(fn ->
  71       "Connection pool had to refuse opening a connection to #{key} due to connection limit exhaustion"
  72     end)
  73   end
  74
  75   def handle_event(
  76         [:pleroma, :connection_pool, :client, :dead],
  77         %{client_pid: client_pid, reason: reason},
  78         %{key: key},
  79         _
  80       ) do
  81     Logger.warn(fn ->
  82       "Pool worker for #{key}: Client #{inspect(client_pid)} died before releasing the connection with #{
  83         inspect(reason)
  84       }"
  85     end)
  86   end
  87
  88   def handle_event(
  89         [:pleroma, :connection_pool, :client, :add],
  90         %{clients: [_, _ | _] = clients},
  91         %{key: key, protocol: :http},
  92         _
  93       ) do
  94     Logger.info(fn ->
  95       "Pool worker for #{key}: #{length(clients)} clients are using an HTTP1 connection at the same time, head-of-line blocking might occur."
  96     end)
  97   end
  98
  99   def handle_event([:pleroma, :connection_pool, :client, :add], _, _, _), do: :ok
 100
 101   def handle_event(
 102         [:pleroma, :repo, :query] = _name,
 103         %{query_time: query_time} = measurements,
 104         %{source: source} = metadata,
 105         config
 106       ) do
 107     logging_config = Pleroma.Config.get([:telemetry, :slow_queries_logging], [])
 108
 109     if logging_config[:min_duration] && query_time > logging_config[:min_duration] and
 110          (is_nil(logging_config[:exclude_sources]) or
 111             source not in logging_config[:exclude_sources]) do
 112       log_slow_query(measurements, metadata, config)
 113     else
 114       :ok
 115     end
 116   end
 117
 118   defp log_slow_query(
 119          %{query_time: query_time} = _measurements,
 120          %{source: _source, query: query, params: query_params, repo: repo} = _metadata,
 121          _config
 122        ) do
 123     sql_explain =
 124       with {:ok, %{rows: explain_result_rows}} <-
 125              repo.query("EXPLAIN " <> query, query_params, log: false) do
 126         Enum.map_join(explain_result_rows, "\n", & &1)
 127       end
 128
 129     {:current_stacktrace, stacktrace} = Process.info(self(), :current_stacktrace)
 130
 131     pleroma_stacktrace =
 132       Enum.filter(stacktrace, fn
 133         {__MODULE__, _, _, _} ->
 134           false
 135
 136         {mod, _, _, _} ->
 137           mod
 138           |> to_string()
 139           |> String.starts_with?("Elixir.Pleroma.")
 140       end)
 141
 142     Logger.warn(fn ->
 143       """
 144       Slow query!
 145
 146       Total time: #{round(query_time / 1_000)} ms
 147
 148       #{query}
 149
 150       #{inspect(query_params, limit: :infinity)}
 151
 152       #{sql_explain}
 153
 154       #{Exception.format_stacktrace(pleroma_stacktrace)}
 155       """
 156     end)
 157   end
 158 end