Describe the bug
A graceful server shutdown enters the Mint adapter's reconnect path twice for a single
connection drop. Two concurrent :reconnect timer chains result, and retry exhaustion is
reported twice, sending {:elixir_grpc, :connection_down, pid} to the parent process
twice for one drop.
A graceful shutdown delivers two messages to the adapter process, a GOAWAY frame and then
{:tcp_closed, port}. Both arrive after the connection is already unusable, and each one
independently re-enters attempt_reconnect/1, which unconditionally schedules a new
:reconnect timer.
To Reproduce
:sys.trace/2 is used to show internal messaging.
Mix.install([
{:grpc, github: "elixir-grpc/grpc", sparse: "grpc"},
{:mint, "~> 1.9"},
{:bandit, "~> 1.0"}
])
defmodule EchoPlug do
@behaviour Plug
@impl true
def init(opts), do: opts
@impl true
def call(conn, _opts), do: Plug.Conn.send_resp(conn, 200, "ok")
end
defmodule Repro do
@port 50_560
@retry 3
def run do
{:ok, server} = Bandit.start_link(plug: EchoPlug, scheme: :http, port: @port)
channel = %GRPC.Channel{host: "127.0.0.1", port: @port, scheme: "http"}
{:ok, %{adapter_payload: %{conn_pid: pid}}} =
GRPC.Client.Adapters.Mint.connect(channel, retry: @retry)
IO.puts("connected, conn_pid=#{inspect(pid)}, retry: #{@retry}")
:sys.trace(pid, true)
IO.puts("--- stopping server ---")
Supervisor.stop(server)
Process.sleep(8_000)
:sys.trace(pid, false)
IO.puts("--- done, conn_pid alive? #{Process.alive?(pid)} ---")
IO.puts("parent mailbox:")
Enum.each(drain(), &IO.puts(" #{inspect(&1)}"))
end
defp drain(acc \\ []) do
receive do
msg -> drain([msg | acc])
after
0 -> Enum.reverse(acc)
end
end
end
Repro.run()
10:04:50.090 [info] Running EchoPlug with Bandit 1.12.5 at 0.0.0.0:50560 (http)
connected, conn_pid=#PID<0.550.0>, retry: 3
--- stopping server ---
*DBG* <0.550.0> got {tcp,#Port<0.8>,<<0,0,0,4,0,0,0,0,0>>} <- SETTINGS frame
*DBG* <0.550.0> new state #{...}
*DBG* <0.550.0> got {tcp,#Port<0.8>,<<0,0,8,7,0,0,0,0,0,0,0,0,0,0,0,0,0>>} <- GOAWAY frame
10:04:50.113 [info] Attempting reconnection 1/3 to http://127.0.0.1:50560
*DBG* <0.550.0> new state #{...}
10:04:50.115 [warning] Reconnection attempt 1/3 failed: %Mint.TransportError{reason: :econnrefused}
*DBG* <0.550.0> got {tcp_closed,#Port<0.8>}
10:04:50.115 [info] Attempting reconnection 2/3 to http://127.0.0.1:50560
*DBG* <0.550.0> new state #{...}
10:04:50.115 [warning] Reconnection attempt 2/3 failed: %Mint.TransportError{reason: :econnrefused}
*DBG* <0.550.0> got reconnect
10:04:51.063 [info] Attempting reconnection 3/3 to http://127.0.0.1:50560
*DBG* <0.550.0> new state #{...}
10:04:51.064 [warning] Reconnection attempt 3/3 failed: %Mint.TransportError{reason: :econnrefused}
*DBG* <0.550.0> got reconnect
*DBG* <0.550.0> new state #{...}
10:04:51.460 [warning] Connection retry exhausted (3/3) for http://127.0.0.1:50560
*DBG* <0.550.0> got reconnect
*DBG* <0.550.0> new state #{...}
10:04:53.732 [warning] Connection retry exhausted (3/3) for http://127.0.0.1:50560`
--- done, conn_pid alive? true ---
parent mailbox:
{:EXIT, #PID<0.246.0>, :normal}
{:elixir_grpc, :connection_down, #PID<0.550.0>}
{:elixir_grpc, :connection_down, #PID<0.550.0>}
Reading the trace:
- GOAWAY drives reconnect attempt 1, which schedules one timer.
{:tcp_closed, port} drives attempt 2, which schedules a second timer.
The retry limit is respected, but in the end two identical {:elixir_grpc, :connection_down, pid} messages are sent to the parent.
Expected behavior
One reconnect chain per connection drop, regardless of how many socket messages the
shutdown produces.
- Exhaustion is logged once.
{:elixir_grpc, :connection_down, pid} is sent to the parent process once.
Versions:
- OS: macOS 15.7.3 (Darwin 24.6.0)
- Erlang: OTP 28, erts-16.3
- Elixir: 1.20.0
- mix.lock: grpc at master
bcef135b57a3aefeba1e1ad6591f3282308f72b2 (git, sparse: "grpc"), grpc_core 1.0.4, mint 1.9.3. Test server is bandit 1.12.5.
Describe the bug
A graceful server shutdown enters the Mint adapter's reconnect path twice for a single
connection drop. Two concurrent
:reconnecttimer chains result, and retry exhaustion isreported twice, sending
{:elixir_grpc, :connection_down, pid}to the parent processtwice for one drop.
A graceful shutdown delivers two messages to the adapter process, a GOAWAY frame and then
{:tcp_closed, port}. Both arrive after the connection is already unusable, and each oneindependently re-enters
attempt_reconnect/1, which unconditionally schedules a new:reconnecttimer.To Reproduce
:sys.trace/2is used to show internal messaging.Reading the trace:
{:tcp_closed, port}drives attempt 2, which schedules a second timer.The retry limit is respected, but in the end two identical {:elixir_grpc, :connection_down, pid} messages are sent to the
parent.Expected behavior
One reconnect chain per connection drop, regardless of how many socket messages the
shutdown produces.
{:elixir_grpc, :connection_down, pid}is sent to the parent process once.Versions:
bcef135b57a3aefeba1e1ad6591f3282308f72b2(git,sparse: "grpc"), grpc_core 1.0.4, mint 1.9.3. Test server is bandit 1.12.5.