Pool connection not freed when response code is 307 (with example! 🎉 )

[marcinkoziej]

Hi!

I managed to track down a situation where hackney_pool fills up if the response to POST is 307. I started seeing this in some APIs (SalesForce).

Try this example:

Save file below as server.exs and run elixir server.exs. It will make a POST 51 times until the last ones timeouts when waiting for the pool.

Mix.install [
  :cowboy, :plug, :plug_cowboy, :hackney
]

import Logger

defmodule Serv do 
  import Plug.Conn 

  def init(o) do
    o
  end

  def call(conn, _o) do 
    conn
    |> put_resp_content_type("text/plain")
    |> put_resp_header("Location", "/some")
    |> send_resp(307, "OK")

  end
end

{:ok, pid} = Plug.Cowboy.http Serv, [], port: 5000

info("Started server #{inspect pid}")

Enum.each 1..51, fn _ -> 
  {:ok, 307, _, _} = :hackney.request(:post, "http://localhost:5000", [], "", [pool: Pool])
  info inspect :hackney_pool.get_stats Pool 
end

What I am seeing is:

$ elixir -v
Erlang/OTP 25 [erts-13.1.4] [source] [64-bit] [smp:16:16] [ds:16:16:10] [async-threads:1] [jit:ns]
Elixir 1.14.3 (compiled with Erlang/OTP 23)

$ elixir server.exs
14:01:12.211 [info] Started server #PID<0.293.0>
14:01:12.242 [info] [name: Pool, max: 50, in_use_count: 1, free_count: 0, queue_count: 0]
14:01:12.242 [info] [name: Pool, max: 50, in_use_count: 2, free_count: 0, queue_count: 0]
(.......)
14:01:12.265 [info] [name: Pool, max: 50, in_use_count: 49, free_count: 0, queue_count: 0]
14:01:12.266 [info] [name: Pool, max: 50, in_use_count: 50, free_count: 0, queue_count: 0]


** (MatchError) no match of right hand side value: {:error, :checkout_timeout}
    server.exs:28: anonymous fn/1 in :elixir_compiler_0.__FILE__/1
    (elixir 1.14.3) lib/enum.ex:980: anonymous fn/3 in Enum.each/2
    (elixir 1.14.3) lib/enum.ex:4299: Enum.reduce_range/5
    (elixir 1.14.3) lib/enum.ex:2472: Enum.each/2

Hope this helps tracking down these pesky connection pool bugs!

[felipe-lopez-solaris]

+1

[kevin-sdev]

Not sure it's an issue with 307 redirects. The same thing happens when you replace the 307 response with a 200 response in your example.

[svdmitrij]

To close connections there is need to add hackney:body/1 call after receive an answer, or hackney:skip_body/1 if not interesting in body content.

Enum.each 1..51, fn _ -> 
  {:ok, 307, _, Ref} = :hackney.request(:post, "http://localhost:5000", [], "", [pool: Pool])
  _Result = :hackney.skip_body(Ref)
  info inspect :hackney_pool.get_stats Pool 
end

https://github.com/benoitc/hackney/blob/master/src/hackney.erl#L508-L531