nb_requests issue

[silviucpp]

Hello,

When I'm stopping my app I would like to wait for all in progress hackney requests. For this I was thinking to wait for nb_requests to hit 0 so I implemented the following:

wait_all_pending_requests() ->
    Nr = folsom_metrics:get_metric_value([hackney, nb_requests]),
    if
        Nr > 0 ->
            ?PRINT(<<"Wait for requests in progress: ~p ~n">>, [Nr]),
            timer:sleep(1000),
            wait_all_pending_requests();
        true ->
            ok
    end.

I observed that for some reason this metric returns wrong results. Even if I don't have any request in progress I get a big number which never decrease. I have no idea what queries breaks the stats and why.

Any other way to implement this or any suggestion ?

Silviu

[benoitc]

do you actually close the requests? Or read the body?

[silviucpp]

Yes . All the time

On Friday, 8 January 2016, Benoit Chesneau notifications@github.com wrote:

do you actually close the requests? Or read the body?

— Reply to this email directly or view it on GitHub https://github.com/benoitc/hackney/issues/265#issuecomment-169963201.

[jschniper]

I'm going to piggyback on this issue since I'm seeing a similar problem. I've started collecting stats on the hackney_pool and I've been seeing the in_use count grow as though some of the sockets are never getting released. Eventually, if left unchecked, this causes any requests to stay in the queue forever. Originally I had a number of requests all using the same default pool, but I broke them apart and used a separate pool for each and now I'm really only seeing the issue on a single request.

For some extra background, we're using the Phoenix framework and HTTPoison in order to make the requests. The code we're using is as follows:

def profile(token) do
  pid = :poolboy.checkout(:redis_pool)

  case :eredis.q(pid, ["GET", "profile:#{token}"], 5000) do
    {:ok, :undefined} ->
      resp = Service.get!("/profile/#{token}", ["Content-Type": "text/plain"], hackney: [pool: :profile])

      :eredis.q(pid, ["SET", "profile:#{token}", Poison.encode!(resp.body), "EX", 900], 5000)

      profile = resp.body
    {:ok, profile} ->
      profile = Poison.decode!(profile)
  end

  :poolboy.checkin(:redis_pool, pid)

  profile
end

defmodule Service do
  use HTTPoison.Base

  def process_url(url) do
    "http://example.com" <> url
  end

  def process_request_headers(headers) do
    ["Content-Type": "application/json", "Accept": "application/json"] ++ headers
  end

  def process_response_body(body) do
    case Poison.decode(body) do
      {:ok, json} -> json
      _ -> body
    end
  end
end

@edgurgel was asking about the redis pooling but I actually deployed a version with that code removed and saw the same results. There might be some more information in HTTPoison issue https://github.com/edgurgel/httpoison/issues/98.

As of right now, I have a scheduled job that stops the pool which seems to set the in_use count back to zero, but the hackney.nb_requests count is still growing.

Please let me know if you need any more information. I'm going to try to dig into it myself but hopefully some of this information is useful.

[jschniper]

I wanted to go ahead and include the charts as well. The first one shows the pool metrics on one of the servers. The scheduled job stops the pool that is getting filled up every six hours. All of the other pools have been left running for the duration shown on the graph.

The second chart is for the same time frame and shows that even though the pool gets flushed it looks as though there are still "active" sockets out there.

[jschniper]

I went back and replaced the call to HTTPoison with a call directly to hackney and it looks as though it might have resolved the issue. I'm going to keep monitoring it for a day or two but I wanted to let you know to keep you from chasing phantom bugs.