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 #{reclaim_max} connections"
  39     end)
  40   end
  41
  42   def handle_event(
  43         [:pleroma, :connection_pool, :reclaim, :stop],
  44         %{reclaimed_count: 0},
  45         _,
  46         _
  47       ) do
  48     Logger.error(fn ->
  49       "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"
  50     end)
  51   end
  52
  53   def handle_event(
  54         [:pleroma, :connection_pool, :reclaim, :stop],
  55         %{reclaimed_count: reclaimed_count},
  56         _,
  57         _
  58       ) do
  59     Logger.debug(fn -> "Connection pool cleaned up #{reclaimed_count} idle connections" end)
  60   end
  61
  62   def handle_event(
  63         [:pleroma, :connection_pool, :provision_failure],
  64         %{opts: [key | _]},
  65         _,
  66         _
  67       ) do
  68     Logger.error(fn ->
  69       "Connection pool had to refuse opening a connection to #{key} due to connection limit exhaustion"
  70     end)
  71   end
  72
  73   def handle_event(
  74         [:pleroma, :connection_pool, :client, :dead],
  75         %{client_pid: client_pid, reason: reason},
  76         %{key: key},
  77         _
  78       ) do
  79     Logger.warn(fn ->
  80       "Pool worker for #{key}: Client #{inspect(client_pid)} died before releasing the connection with #{inspect(reason)}"
  81     end)
  82   end
  83
  84   def handle_event(
  85         [:pleroma, :connection_pool, :client, :add],
  86         %{clients: [_, _ | _] = clients},
  87         %{key: key, protocol: :http},
  88         _
  89       ) do
  90     Logger.info(fn ->
  91       "Pool worker for #{key}: #{length(clients)} clients are using an HTTP1 connection at the same time, head-of-line blocking might occur."
  92     end)
  93   end
  94
  95   def handle_event([:pleroma, :connection_pool, :client, :add], _, _, _), do: :ok
  96
  97   def handle_event(
  98         [:pleroma, :repo, :query] = _name,
  99         %{query_time: query_time} = measurements,
 100         %{source: source} = metadata,
 101         config
 102       ) do
 103     logging_config = Pleroma.Config.get([:telemetry, :slow_queries_logging], [])
 104
 105     if logging_config[:enabled] &&
 106          logging_config[:min_duration] &&
 107          query_time > logging_config[:min_duration] and
 108          (is_nil(logging_config[:exclude_sources]) or
 109             source not in logging_config[:exclude_sources]) do
 110       log_slow_query(measurements, metadata, config)
 111     else
 112       :ok
 113     end
 114   end
 115
 116   defp log_slow_query(
 117          %{query_time: query_time} = _measurements,
 118          %{source: _source, query: query, params: query_params, repo: repo} = _metadata,
 119          _config
 120        ) do
 121     sql_explain =
 122       with {:ok, %{rows: explain_result_rows}} <-
 123              repo.query("EXPLAIN " <> query, query_params, log: false) do
 124         Enum.map_join(explain_result_rows, "\n", & &1)
 125       end
 126
 127     {:current_stacktrace, stacktrace} = Process.info(self(), :current_stacktrace)
 128
 129     pleroma_stacktrace =
 130       Enum.filter(stacktrace, fn
 131         {__MODULE__, _, _, _} ->
 132           false
 133
 134         {mod, _, _, _} ->
 135           mod
 136           |> to_string()
 137           |> String.starts_with?("Elixir.Pleroma.")
 138       end)
 139
 140     Logger.warn(fn ->
 141       """
 142       Slow query!
 143
 144       Total time: #{round(query_time / 1_000)} ms
 145
 146       #{query}
 147
 148       #{inspect(query_params, limit: :infinity)}
 149
 150       #{sql_explain}
 151
 152       #{Exception.format_stacktrace(pleroma_stacktrace)}
 153       """
 154     end)
 155   end
 156 end