From 89a7efab69d905cc3521388b1e1cf43851848627 Mon Sep 17 00:00:00 2001
From: rinpatch <rinpatch@sdf.org>
Date: Fri, 11 Sep 2020 14:22:54 +0300
Subject: [PATCH] ConnectionPool: Log possible HTTP1 blocks

---
 lib/pleroma/gun/conn.ex                   | 12 ++++++------
 lib/pleroma/gun/connection_pool/worker.ex | 22 ++++++++++++++++------
 lib/pleroma/telemetry/logger.ex           | 18 ++++++++++++++++--
 3 files changed, 38 insertions(+), 14 deletions(-)

diff --git a/lib/pleroma/gun/conn.ex b/lib/pleroma/gun/conn.ex
index 75b1ffc0a..477e19c6e 100644
--- a/lib/pleroma/gun/conn.ex
+++ b/lib/pleroma/gun/conn.ex
@@ -50,10 +50,10 @@ defp do_open(uri, %{proxy: {proxy_host, proxy_port}} = opts) do
 
     with open_opts <- Map.delete(opts, :tls_opts),
          {:ok, conn} <- Gun.open(proxy_host, proxy_port, open_opts),
-         {:ok, _} <- Gun.await_up(conn, opts[:connect_timeout]),
+         {:ok, protocol} <- Gun.await_up(conn, opts[:connect_timeout]),
          stream <- Gun.connect(conn, connect_opts),
          {:response, :fin, 200, _} <- Gun.await(conn, stream) do
-      {:ok, conn}
+      {:ok, conn, protocol}
     else
       error ->
         Logger.warn(
@@ -88,8 +88,8 @@ defp do_open(uri, %{proxy: {proxy_type, proxy_host, proxy_port}} = opts) do
       |> Map.put(:socks_opts, socks_opts)
 
     with {:ok, conn} <- Gun.open(proxy_host, proxy_port, opts),
-         {:ok, _} <- Gun.await_up(conn, opts[:connect_timeout]) do
-      {:ok, conn}
+         {:ok, protocol} <- Gun.await_up(conn, opts[:connect_timeout]) do
+      {:ok, conn, protocol}
     else
       error ->
         Logger.warn(
@@ -106,8 +106,8 @@ defp do_open(%URI{host: host, port: port} = uri, opts) do
     host = Pleroma.HTTP.AdapterHelper.parse_host(host)
 
     with {:ok, conn} <- Gun.open(host, port, opts),
-         {:ok, _} <- Gun.await_up(conn, opts[:connect_timeout]) do
-      {:ok, conn}
+         {:ok, protocol} <- Gun.await_up(conn, opts[:connect_timeout]) do
+      {:ok, conn, protocol}
     else
       error ->
         Logger.warn(
diff --git a/lib/pleroma/gun/connection_pool/worker.ex b/lib/pleroma/gun/connection_pool/worker.ex
index c36332817..49d41e4c7 100644
--- a/lib/pleroma/gun/connection_pool/worker.ex
+++ b/lib/pleroma/gun/connection_pool/worker.ex
@@ -15,7 +15,7 @@ def init([_key, _uri, _opts, _client_pid] = opts) do
 
   @impl true
   def handle_continue({:connect, [key, uri, opts, client_pid]}, _) do
-    with {:ok, conn_pid} <- Gun.Conn.open(uri, opts),
+    with {:ok, conn_pid, protocol} <- Gun.Conn.open(uri, opts),
          Process.link(conn_pid) do
       time = :erlang.monotonic_time(:millisecond)
 
@@ -27,8 +27,12 @@ def handle_continue({:connect, [key, uri, opts, client_pid]}, _) do
       send(client_pid, {:conn_pid, conn_pid})
 
       {:noreply,
-       %{key: key, timer: nil, client_monitors: %{client_pid => Process.monitor(client_pid)}},
-       :hibernate}
+       %{
+         key: key,
+         timer: nil,
+         client_monitors: %{client_pid => Process.monitor(client_pid)},
+         protocol: protocol
+       }, :hibernate}
     else
       err ->
         {:stop, {:shutdown, err}, nil}
@@ -53,14 +57,20 @@ def handle_cast({:remove_client, client_pid}, state) do
   end
 
   @impl true
-  def handle_call(:add_client, {client_pid, _}, %{key: key} = state) do
+  def handle_call(:add_client, {client_pid, _}, %{key: key, protocol: protocol} = state) do
     time = :erlang.monotonic_time(:millisecond)
 
-    {{conn_pid, _, _, _}, _} =
+    {{conn_pid, used_by, _, _}, _} =
       Registry.update_value(@registry, key, fn {conn_pid, used_by, crf, last_reference} ->
         {conn_pid, [client_pid | used_by], crf(time - last_reference, crf), time}
       end)
 
+    :telemetry.execute(
+      [:pleroma, :connection_pool, :client, :add],
+      %{client_pid: client_pid, clients: used_by},
+      %{key: state.key, protocol: protocol}
+    )
+
     state =
       if state.timer != nil do
         Process.cancel_timer(state[:timer])
@@ -131,7 +141,7 @@ def handle_info({:gun_down, _pid, _protocol, _reason, _killed_streams}, state) d
   @impl true
   def handle_info({:DOWN, _ref, :process, pid, reason}, state) do
     :telemetry.execute(
-      [:pleroma, :connection_pool, :client_death],
+      [:pleroma, :connection_pool, :client, :dead],
       %{client_pid: pid, reason: reason},
       %{key: state.key}
     )
diff --git a/lib/pleroma/telemetry/logger.ex b/lib/pleroma/telemetry/logger.ex
index 4cacae02f..197b1d091 100644
--- a/lib/pleroma/telemetry/logger.ex
+++ b/lib/pleroma/telemetry/logger.ex
@@ -7,7 +7,8 @@ defmodule Pleroma.Telemetry.Logger do
     [:pleroma, :connection_pool, :reclaim, :start],
     [:pleroma, :connection_pool, :reclaim, :stop],
     [:pleroma, :connection_pool, :provision_failure],
-    [:pleroma, :connection_pool, :client_death]
+    [:pleroma, :connection_pool, :client, :dead],
+    [:pleroma, :connection_pool, :client, :add]
   ]
   def attach do
     :telemetry.attach_many("pleroma-logger", @events, &handle_event/4, [])
@@ -62,7 +63,7 @@ def handle_event(
   end
 
   def handle_event(
-        [:pleroma, :connection_pool, :client_death],
+        [:pleroma, :connection_pool, :client, :dead],
         %{client_pid: client_pid, reason: reason},
         %{key: key},
         _
@@ -73,4 +74,17 @@ def handle_event(
       }"
     end)
   end
+
+  def handle_event(
+        [:pleroma, :connection_pool, :client, :add],
+        %{clients: [_, _ | _] = clients},
+        %{key: key, protocol: :http},
+        _
+      ) do
+    Logger.info(fn ->
+      "Pool worker for #{key}: #{length(clients)} clients are using an HTTP1 connection at the same time, head-of-line blocking might occur."
+    end)
+  end
+
+  def handle_event([:pleroma, :connection_pool, :client, :add], _, _, _), do: :ok
 end