4.x regression, a slow connect crashes the caller

[jegaxd26]

Hi we're in the middle of upgrading to hackney 4.x and stumbled upon this regression (presumably) when a client taking more then 8 seconds to accept the connection will crash the caller. I double checked that this is not the case with 1.x

Environment

• hackney 4.7.2
• Erlang/OTP 27 (erts-15.2.6)
• Elixir 1.18.3
• OS X

a script to reproduce:

Mix.install([{:hackney, "~> 4.0"}])

Application.ensure_all_started(:hackney)

defmodule StalledHackneyTransport do

  def connect(_host, _port, _options, _timeout) do
    # hackney_conn:connect/1 has a fixed 8-second call timeout. Ignoring the
    # transport timeout reproduces a stalled connect that outlives that call.
    Process.sleep(8_500)
    {:error, :timeout}
  end
end

defmodule Test do
  @pool_name :hackney_connect_timeout_regression
  
  def run do
    :ok = :hackney_pool.start_pool(@pool_name, [])

    pool_pid = :hackney_pool.find_pool(@pool_name)

    monitor_ref = Process.monitor(pool_pid)

    {:error, _reason} =
      :hackney_pool.checkout(
        ~c"stalled.example",
        443,
        StalledHackneyTransport,
        pool: @pool_name,
        connect_timeout: 100,
        checkout_timeout: 100
      )

    receive do
      {:DOWN, ^monitor_ref, :process, ^pool_pid, _reason} ->
        IO.puts "Bug"
    after 9000 ->
        IO.puts "No bug"
    end
  end
end

Test.run

when run, with 4.0 it prints "Bug" and throws this exception:

[error] GenServer #PID<0.208.0> terminating
** (stop) exited in: :gen_statem.call(#PID<0.209.0>, :connect, 8000)
    ** (EXIT) time out
    (stdlib 6.2.2) gen.erl:277: :gen.do_call/4
    (stdlib 6.2.2) gen_statem.erl:3250: :gen_statem.call/3
    (hackney 4.7.2) /Users/Library/Caches/mix/installs/elixir-1.18.3-erts-15.2.6/d8d5a2166b8316f756e16fc57188eab6/deps/hackney/src/hackney_pool.erl:1017: :hackney_pool.start_connection/6
    (hackney 4.7.2) /Users/Library/Caches/mix/installs/elixir-1.18.3-erts-15.2.6/d8d5a2166b8316f756e16fc57188eab6/deps/hackney/src/hackney_pool.erl:573: :hackney_pool.handle_call/3
    (stdlib 6.2.2) gen_server.erl:2381: :gen_server.try_handle_call/4
    (stdlib 6.2.2) gen_server.erl:2410: :gen_server.handle_msg/6
    (stdlib 6.2.2) proc_lib.erl:329: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.94.0>): {:checkout, {~c"stalled.example", 443, StalledHackneyTransport, :default}, #PID<0.94.0>, [pool: :hackney_connect_timeout_regression, connect_timeout: 100, checkout_timeout: 100]}
State: {:state, :hackney_connect_timeout_regression, 50, 2000, 4, %{}, %{}, %{}, {:set, 0, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []}, {{[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []}}}, %{}, %{}, %{}}
Client #PID<0.94.0> is alive

if run with hackney 1.0 we get the desired output which is No bug printed and no exceptions raised

[nulian]

You do show pool but we had the timeout when we actually disabled the pool. Because in the past hackney 1.x sometimes had issues with the pool we disabled it.

config :hackney, use_default_pool: false

With hackney 4 this actually causes process leaks and in the end 8 seconds timeouts.
But my solution for this was enabling pool that stopped process leaking and this issue.