checkout_timeout when it is set to infinity

[iguberman]

I get checkout_timeout error even though it is set to infinity:

There is a periodic POST request in my app (every 5 minutes). It's ok initially but after some while (i.e. overnight) I'm starting to see this error:
{error,checkout_timeout}

In hackney settings I have it set to infinity. NOTE: that I have commented out use_default_pool, false because I want to use the default pool. I had no checkout_timeout error while the default pool was disabled (obviously).

 {hackney, [
    %% {use_default_pool, false},
    {checkout_timeout, infinity}
  ]},

[benoitc]

@iguberman is this happening on latest version of hackney? ALso is this the only connection made?

[benoitc]

@iguberman can you paste the full trace if you have it? It would be helpful

[iguberman]

Hi Benoit, thanks so much for looking into it! I was able to reproduce it on "master" branch :( I don't get a stack trace just a response from hackney:post(Url, Headers, Data, []): {error,checkout_timeout}. I am able to run this successfully for a couple of hours with 5 minutes interval (sending stats somewhere). I'm waiting now to reproduce it for the second time. Hackney version as I see in rebar.lock {ref,"318c6adc821f6fe9dd1eac1718c0208ede40c0be"}
Usually this problem happens after a couple of hours.

[iguberman]

Yes, just confirmed again that it is indeed an issue with master branch as well. After about 2 hours or so after starting my app and hackney:post 2 requests every 5 minutes, it starts happening.

[iguberman]

sys.config:

 {hackney, [
    %%{use_default_pool, false},
    {checkout_timeout, infinity}
  ]},```

[benoitc]

do you read the return of your request? It seems like there is no connection available in the pool, which should not happen with the rate you are describing.

[iguberman]

Yes, I check the return value and if it's not 201 I display it in warning log:

case hackney:post(Url, Headers, Data, []) of
      {ok, 201, _Headers, _Ref} ->=
        lager:info("Posted data ~p to ~s", [Data, Url]);
      {ok, ErrorCode, _Headers, Ref} ->
        {ok, Message} = hackney:body(Ref),
        lager:warning("Code ~b posting data ~p to ~s: ~s", [ErrorCode, Data, Url, Message]);
      Other ->   %%% THIS IS WHERE I GET THE {error,checkout_timeout}
        lager:warning("Error posting data ~p to ~s: ~p", [Data, Url, Other])
    end.

Is there something wrong with my hackney pool config maybe? I assume using default pool is a good thing and I shouldn't run out of connections there as they should be happily reused especially at 2 connections every 5 minutes rate? These are all called from the same process. But I am running out of connections after a couple of hours which means they aren't reused somehow?

Maybe 5 minutes is too long for them to stay alive and they get closed but somehow not removed completely (accounted for) or something like that.

Something else I have to do explicitly? Should I use the default pool in this situation at all? (I can run for days without the default pool enabled, but then at some point I suddently get emfile error (setup is ample on my machine), but this might be /most likely is related to mnesia and is probably unrelated to hackney)

[benoitc]

ah but you don't read the body when you get a 201 so it won't release the socket to the pool. A socket is only returned to the pool in the following cases:

• body is read
• connection should be closed (via the Connection header
• connection is closed.

When a connection is closed, the pool is notified of it and allows to create a new socket.

Can you try to skip or read the body. You can also always retrieve the body using the with_body option.

Let me know.

[iguberman]

Wow! Had no idea. Thanks! Will try the skip_body.