hackney icon indicating copy to clipboard operation
hackney copied to clipboard

File download hangs infinitely

Open jeromedoyle opened this issue 8 years ago • 10 comments

I have been using HTTPoison (which uses hackney under the hood) to download hundreds of files per day asynchronously using the stream_to: self() option. I've recently encountered a file that stops receiving after the headers are received. I tried it directly in hackney and get the same result. The url is http://engine.edocbuilder.com/include/fileDownload.aspx?p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9

Example (In Elixir)

{:ok, 200, headers, ref} = :hackney.get("http://engine.edocbuilder.com/include/fileDownload.aspx?p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9")

{:ok, 200,
 [{"Cache-Control", "private"}, {"Transfer-Encoding", "chunked"},
  {"Content-Type", "application/pdf"},
  {"Expires", "Mon, 24 Apr 2017 19:27:25 GMT"}, {"Server", "Microsoft-IIS/8.5"},
  {"Set-Cookie",
   "ASP.NET_SessionId=vwk2cd4lv5itarskrcynezym; path=/; HttpOnly"},
  {"Content-Disposition", "attachment; filename=production.pdf"},
  {"X-Original-Filename-Urlencode", "production.pdf"},
  {"X-AspNet-Version", "4.0.30319"}, {"X-Powered-By", "ASP.NET"},
  {"X-Webfarm-Member", "eDocProdChi3"}, {"Access-Control-Allow-Origin", "*"},
  {"Access-Control-Allow-Headers",
   "Content-Type,cache-control,accept,x-requested-with"},
  {"Access-Control-Methods", "*"}, {"Date", "Mon, 24 Apr 2017 19:25:25 GMT"}],
 #Reference<0.0.3.1945>}

{:ok, body} = :hackney.body(ref)

After the call to :hackney.body(ref) it hangs indefinitely. I have tested and neither httpc or ibrowse have an issue with the url.

jeromedoyle avatar Apr 24 '17 19:04 jeromedoyle

what do you mean by "hang"?

benoitc avatar May 09 '17 12:05 benoitc

The call to {:ok, body} = :hackney.body(ref) doesn't return and cpu spikes.

jeromedoyle avatar May 09 '17 13:05 jeromedoyle

@jeromedoyle I reproduce the issue.

I thought first that it was an issue with the pathe encoding as curl is sending me a 500 error but it's not the case. I still reproduce it. Tracing the request return the following below. I will have a closer look on it today.

1> hackney_trace:enable(max, io).
ok
2> F = fun(P) -> P end.
#Fun<erl_eval.6.118419387>
3> hackney:get("http://engine.edocbuilder.com/include/fileDownload.aspx?p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9", [], [], [{path_encode, F}, with_body]).
[hackney trace 80 <0.377.0> 2017:05:09 13:54:09 4940] request
   Content: [{module,hackney},
             {line,308},
             {method,get},
             {url,{hackney_url,hackney_tcp,http,<<"engine.edocbuilder.com">>,
                               <<"/include/fileDownload.aspx?p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9">>,
                               <<"/include/fileDownload.aspx">>,
                               <<"p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9">>,
                               <<>>,"engine.edocbuilder.com",80,<<>>,<<>>}},
             {headers,[]},
             {body,[]},
             {options,[{path_encode,#Fun<erl_eval.6.118419387>},with_body]}]
[hackney trace 60 <0.377.0> 2017:05:09 13:54:09 4942] request without proxy
   Content: [{module,hackney},{line,680}]
[hackney trace 60 <0.377.0> 2017:05:09 13:54:09 4944] connect
   Content: [{module,hackney_connect},
             {line,33},
             {transport,hackney_tcp},
             {host,"engine.edocbuilder.com"},
             {port,80},
             {dynamic,true}]
[hackney trace 80 <0.377.0> 2017:05:09 13:54:09 4951] no socket in the pool
   Content: [{module,hackney_connect},{line,200},{pool,default}]
15:54:09.950 [warning] lager_error_logger_h dropped 83 messages in the last second that exceeded the limit of 50 messages/sec
[hackney trace 80 <0.377.0> 2017:05:09 13:54:10 4153] new connection
   Content: [{module,hackney_connect},{line,248}]
[hackney trace 40 <0.377.0> 2017:05:09 13:54:10 4157] perform request
   Content: [{module,hackney_request},
             {line,100},
             {header_data,[<<"GET /include/fileDownload.aspx?p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9 HTTP/1.1\r\n">>,
                           [[<<"Host">>,": ",<<"engine.edocbuilder.com">>,
                             "\r\n"],
                            [<<"User-Agent">>,": ",<<"hackney/1.7.1">>,"\r\n"],
                            "\r\n"]]},
             {perform_all,true},
             {expect,false}]
[hackney trace 80 <0.377.0> 2017:05:09 13:54:10 4293] got response
   Content: [{module,hackney},
             {line,376},
             {response,
                 {ok,200,
                     [{<<"Cache-Control">>,<<"private">>},
                      {<<"Transfer-Encoding">>,<<"chunked">>},
                      {<<"Content-Type">>,<<"application/pdf">>},
                      {<<"Expires">>,<<"Tue, 09 May 2017 13:56:10 GMT">>},
                      {<<"Server">>,<<"Microsoft-IIS/8.5">>},
                      {<<"Set-Cookie">>,
                       <<"ASP.NET_SessionId=wvqgdyxvqkhe304ahuh21i3g; path=/; HttpOnly">>},
                      {<<"Content-Disposition">>,
                       <<"attachment; filename=production.pdf">>},
                      {<<"X-Original-Filename-Urlencode">>,
                       <<"production.pdf">>},
                      {<<"X-AspNet-Version">>,<<"4.0.30319">>},
                      {<<"X-Powered-By">>,<<"ASP.NET">>},
                      {<<"X-Webfarm-Member">>,<<"eDocProdChi2">>},
                      {<<"Access-Control-Allow-Origin">>,<<"*">>},
                      {<<"Access-Control-Allow-Headers">>,
                       <<"Content-Type,cache-control,accept,x-requested-with">>},
                      {<<"Access-Control-Methods">>,<<"*">>},
                      {<<"Date">>,<<"Tue, 09 May 2017 13:54:10 GMT">>}],
                     {client,
                         {1494,338049,943762},
                         {metrics_ng,metrics_dummy},
                         hackney_tcp,"engine.edocbuilder.com",80,
                         <<"engine.edocbuilder.com">>,
                         [{path_encode,#Fun<erl_eval.6.118419387>},with_body],
                         #Port<0.84624>,
                         {default,#Ref<0.0.1.7126>,
                             {"engine.edocbuilder.com",80,hackney_tcp},
                             <0.587.0>,hackney_tcp},
                         #Ref<0.0.1.7126>,true,hackney_pool,5000,false,5,
                         false,5,nil,nil,
                         {hparser,response,4096,10,0,on_body,
                             <<52,100,51,97,48,102,53,13,10,37,80,68,70,45,49,
                               46,55,13,10,37,249,250,154,231,13,10,49,32,48,
                               32,111,98,106,13,10,60,60,10,47,65,110,110,111,
                               116,115,32,55,50,32,48,32,82,10,47,65,114,116,
                               66,111,120,32,91,50,49,32,50,49,32,49,52,54,49,
                               32,50,49,48,57,93,10,47,66,108,101,101,100,66,
                               111,120,32,91,49,50,32,49,50,32,49,52,55,48,32,
                               50,49,49,56,93,10,47,67,111,110,116,101,110,116,
                               115,32,91,50,32,48,32,82,32,50,52,32,48,32,82,
                               93,10,47,67,114,111,112,66,111,120,32,91,48,32,
                               48,32,49,52,56,50,32,50,49,51,48,93,10,47,77,
                               101,100,105,97,66,111,120,32,91,48,32,48,32,49,
                               52,56,50,32,50,49,51,48,93,10,47,80,97,114,101,
                               110,116,32,52,55,54,32,48,32,82,10,47,82,101,
                               115,111,117,114,99,101,115,32,60,60,10,47,67,
                               111,108,111,114,83,112,97,99,101,32,60,60,10,47,
                               67,83,48,32,52,57,49,32,48,32,82,10,62,62,10,47,
                               69,120,116,71,83,116,97,116,101,32,60,60,10,47,
                               71,83,48,32,52,57,50,32,48,32,82,10,47,71,83,49,
                               32,57,57,32,48,32,82,10,62,62,10,47,70,111,110,
                               116,32,60,60,10,47,70,97,98,99,49,50,32,49,50,
                               32,48,32,82,10,47,84,84,48,32,52,57,52,32,48,32,
                               82,10,62,62,10,47,80,114,111,99,83,101,116,32,
                               91,47,80,68,70,10,47,84,101,120,116,10,47,73,
                               109,97,103,101,66,10,47,73,109,97,103,101,67,10,
                               47,73,109,97,103,101,73,93,10,62,62,10,47,82,
                               111,116,97,116,101,32,48,10,47,83,116,114,117,
                               99,116,80,97,114,101,110,116,115,32,49,10,47,84,
                               114,105,109,66,111,120,32,91,50,49,32,50,49,32,
                               49,52,54,49,32,50,49,48,57,93,10,47,84,121,112,
                               101,32,47,80,97,103,101,10,62,62,13,10,101,110,
                               100,111,98,106,13,10,13,10,50,32,48,32,111,98,
                               106,13,10,60,60,10,47,76,101,110,103,116,104,32,
                               55,54,52,10,62,62,13,10,115,116,114,101,97,109,
                               13,10,113,13,10,48,32,48,32,48,32,49,32,107,10,
                               47,80,101,114,99,101,112,116,117,97,108,32,114,
                               105,10,47,71,83,48,32,103,115,10,49,50,32,49,50,
                               32,49,52,53,56,32,50,49,48,54,32,114,101,10,102,
                               10,47,83,112,97,110,32,60,60,47,76,97,110,103,
                               32,40,101,110,45,85,83,41,47,77,67,73,68,32,49,
                               32,62,62,66,68,67,32,10,66,84,10,48,32,48,32,48,
                               32,48,32,107,10,47,84,84,48,32,49,32,84,102,10,
                               55,50,32,48,32,48,32,55,50,32,54,51,52,46,52,56,
                               48,49,32,49,48,52,50,46,54,56,50,49,32,84,109,
                               10,40,49,48,48,37,32,75,41,84,106,10,69,84,10,
                               69,77,67,32,10,57,50,49,32,49,48,53,48,46,52,32,
                               49,49,56,46,56,32,51,49,46,56,32,114,101,10,102,
                               10,47,83,112,97,110,32,60,60,47,76,97,110,103,
                               32,40,101,110,45,85,83,41,47,77,67,73,68,32,50,
                               32,62,62,66,68,67,32,10,66,84,10,48,32,48,32,48,
                               32,49,32,107,10,47,71,83,49,32,103,115,10,51,54,
                               32,48,32,48,32,51,54,32,57,52,51,46,56,56>>,
                             {1,1},
                             undefined,[],undefined,<<"chunked">>,undefined,
                             <<"application/pdf">>,undefined,waiting},
                         {15,
                          {dict,15,16,16,8,80,48,
                              {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                               []},
                              {{[],[],
                                [[<<"x-webfarm-member">>,
                                  {10,<<"X-Webfarm-Member">>,
                                   <<"eDocProdChi2">>}],
                                 [<<"date">>,
                                  {14,<<"Date">>,
                                   <<"Tue, 09 May 2017 13:54:10 GMT">>}]],
                                [[<<"expires">>,
                                  {3,<<"Expires">>,
                                   <<"Tue, 09 May 2017 13:56:10 GMT">>}],
                                 [<<"access-control-methods">>,
                                  {13,<<"Access-Control-Methods">>,<<"*">>}]],
                                [],
                                [[<<"server">>,
                                  {4,<<"Server">>,<<"Microsoft-IIS/8.5">>}]],
                                [[<<"content-disposition">>,
                                  {6,<<"Content-Disposition">>,
                                   <<"attachment; filename=production.pdf">>}],
                                 [<<"access-control-allow-origin">>,
                                  {11,<<"Access-Control-Allow-Origin">>,
                                   <<"*">>}]],
                                [[<<"cache-control">>,
                                  {0,<<"Cache-Control">>,<<"private">>}]],
                                [],
                                [[<<"x-powered-by">>,
                                  {9,<<"X-Powered-By">>,<<"ASP.NET">>}],
                                 [<<"access-control-allow-headers">>,
                                  {12,<<"Access-Control-Allow-Headers">>,
                                   <<"Content-Type,cache-control,accept,x-requested-with">>}]],
                                [[<<"transfer-encoding">>,
                                  {1,<<"Transfer-Encoding">>,<<"chunked">>}],
                                 [<<"content-type">>,
                                  {2,<<"Content-Type">>,
                                   <<"application/pdf">>}]],
                                [[<<"x-original-filename-urlencode">>,
                                  {7,<<"X-Original-Filename-Urlencode">>,
                                   <<"production.pdf">>}],
                                 [<<"x-aspnet-version">>,
                                  {8,<<"X-AspNet-Version">>,<<"4.0.30319">>}]],
                                [],
                                [[<<"set-cookie">>,
                                  {5,<<"Set-Cookie">>,
                                   <<"ASP.NET_SessionId=wvqgdyxvqkhe304ahuh21i3g; path=/; HttpOnly">>}]],
                                [],[]}}}},
                         connected,waiting,nil,normal,false,false,true,
                         undefined,false,#Fun<hackney_request.send.2>,waiting,
                         nil,4096,<<>>,[],
                         {1,1},
                         nil,<<"chunked">>,nil,<<"GET">>,
                         <<"/include/fileDownload.aspx?p=TlP1kM4If79%2fS5yf5VAZfuSSS2SI862sDOM%2fAMvrDvQxjLow6uGW3OoW7aQ1uLPaxlH8MW480DxvjmWU10ihIYZO%2fLkHRzm%2fBbPSXm2FRxPiwxODgyFPPU5Dfdf%2f%2banX&s=26eb1c62-54eb-4800-aae5-eb48b5c8a3c9">>,
                         nil}}},
             {client,
                 {client,
                     {1494,338049,943762},
                     {metrics_ng,metrics_dummy},
                     hackney_tcp,"engine.edocbuilder.com",80,
                     <<"engine.edocbuilder.com">>,
                     [{path_encode,#Fun<erl_eval.6.118419387>},with_body],
                     #Port<0.84624>,
                     {default,#Ref<0.0.1.7126>,
                         {"engine.edocbuilder.com",80,hackney_tcp},
                         <0.587.0>,hackney_tcp},
                     #Ref<0.0.1.7126>,true,hackney_pool,5000,false,5,false,5,
                     nil,nil,nil,
                     {0,
                      {dict,0,16,16,8,80,48,
                          {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                          {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                            []}}}},
                     connected,start,nil,normal,false,false,true,undefined,
                     false,nil,waiting,nil,4096,<<>>,[],undefined,nil,nil,nil,
                     nil,undefined,nil}}]

benoitc avatar May 09 '17 13:05 benoitc

Awesome, thank you!

jeromedoyle avatar May 09 '17 14:05 jeromedoyle

so the error apparently is that it got the full body but wait for the next bit until it timeout (and return the body). Not sure why yet. I will take care over the we.

benoitc avatar May 19 '17 16:05 benoitc

Awesome, glad you found the issue. Is there anything you need from me?

jeromedoyle avatar May 19 '17 16:05 jeromedoyle

Any chance this is related to #420?

jeromedoyle avatar Aug 14 '17 16:08 jeromedoyle

Any news on this? We are having the same issue :(

odarriba avatar Sep 26 '17 15:09 odarriba

I think that I'm facing the same issue. In my case, however, it doesn't hang forever, but takes way to much time to return.

Running the following script takes 384 seconds on my machine, compared to 43 seconds that it takes for wget to download the same 54MB page.

{:ok, 200, _headers, client} = :hackney.request(:get, 'https://github.com/everypolitician/everypolitician-data', [], '', [recv_timeout: 10_000])
start = System.monotonic_time(:second)
{:ok, _body} = :hackney.body(client)
finish = System.monotonic_time(:second)
IO.puts("#{finish - start} seconds")

Elixir: 1.5.1 Erlang: 20 Hackney: 1.9.0

If it's unrelated to the issue please ignore and accept my apologize for interfering.

Nagasaki45 avatar Sep 29 '17 17:09 Nagasaki45

@Nagasaki45 Not it seems related, thanks for that new link. This chunked encoding definitely needs some love.

I've looked at the trace using hackney_trace and it seems to hang for a while on the first chunk (7665\r\n\n\n\n\n\n\n ...). Not sure why, maybe the size given is not ok, or maybe the time to receive it was too long. Checking.

benoitc avatar Oct 08 '17 14:10 benoitc