Connection mixed up when using proxy #566

thang911pk · 2019-05-16T16:25:15Z

I experienced similar issue as #545
I use the latest version of HTTPoison and Hackney. I had 2 end points. When I use Squid proxy to send HTTPS requests, all requests go to one endpoint. Hackney reused the same connection for both end points.

## Without proxy 
HTTPoison.post!(
  "https://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool]
  ]
)

HTTPoison.post!(
  "https://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool]
  ]
)


HTTPoison.post!(
  "https://2ffcbfd7.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool]
  ]
)

HTTPoison.post!(
  "https://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool]
  ]
)

#Socket connections
:sys.get_state(:hackney_pool.find_pool(:test_pool)) 

 {{[
      [
        {'b61fad2e.ngrok.io', 443, :hackney_ssl},
        {:sslsocket, {:gen_tcp, #Port<0.18470>, :tls_connection, :undefined},
         #PID<0.503.0>}
      ]
    ], [], [], [], [], [], [], [], [], [], [], [], [], [], [],
    [
      [
        {'2ffcbfd7.ngrok.io', 443, :hackney_ssl},
        {:sslsocket, {:gen_tcp, #Port<0.19373>, :tls_connection, :undefined},
         #PID<0.523.0>}
      ]
    ]}}},
 {:dict, 2, 16, 16, 8, 80, 48,
  {[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []},
  {{[], [], [], [], [], [],
    [
      [
        {:sslsocket, {:gen_tcp, #Port<0.19373>, :tls_connection, :undefined},
         #PID<0.523.0>} |
        {{'2ffcbfd7.ngrok.io', 443, :hackney_ssl},
         #Reference<0.931103709.3369074689.153627>}
      ]
    ],
    [
      [
        {:sslsocket, {:gen_tcp, #Port<0.18470>, :tls_connection, :undefined},
         #PID<0.503.0>} |
        {{'b61fad2e.ngrok.io', 443, :hackney_ssl},
         #Reference<0.931103709.3369074692.150581>}
      ]
    ], [], [], [], [], [], [], [], []}}}, 0}



## With proxy HTTPS 

HTTPoison.post!(
  "https://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)

HTTPoison.post!(
  "https://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)


HTTPoison.post!(
  "https://2ffcbfd7.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)

HTTPoison.post!(
  "https://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)

#Socket connections
:sys.get_state(:hackney_pool.find_pool(:test_pool)) 

  {{[], [], [], [], [], [], [], [], [], [], [],
    [
      [
        {'127.0.0.1', 3128, :hackney_http_connect},
        {:hackney_ssl,
         {:sslsocket, {:gen_tcp, #Port<0.9267>, :tls_connection, :undefined},
          #PID<0.383.0>}}
      ]
    ], [], [], [], []}}},
 {:dict, 1, 16, 16, 8, 80, 48,
  {[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []},
  {{[], [], [], [], [], [], [], [], [], [],
    [
      [
        {:hackney_ssl,
         {:sslsocket, {:gen_tcp, #Port<0.9267>, :tls_connection, :undefined},
          #PID<0.383.0>}} |
        {{'127.0.0.1', 3128, :hackney_http_connect},
         #Reference<0.1120821313.1221853188.123350>}
      ]
    ], [], [], [], [], []}}}, 0}


## With proxy HTTP 

HTTPoison.post!(
  "http://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)

HTTPoison.post!(
  "http://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)


HTTPoison.post!(
  "http://2ffcbfd7.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)

HTTPoison.post!(
  "http://b61fad2e.ngrok.io",
  "hello",
  [],
  [
    hackney: [pool: :test_pool],
    proxy: "http://127.0.0.1:3128"
  ]
)

Socket connections
:sys.get_state(:hackney_pool.find_pool(:test_pool)) 

  {{[], [], [], [], [], [], [], [], [], [], [], [], [], [], [],
    [[{'127.0.0.1', 3128, :hackney_tcp}, #Port<0.8843>]]}}},
 {:dict, 1, 16, 16, 8, 80, 48,
  {[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []},
  {{[], [], [], [], [], [], [], [], [], [], [], [], [],
    [
      [
        #Port<0.8843> |
        {{'127.0.0.1', 3128, :hackney_tcp},
         #Reference<0.3140736740.1760821249.15187>}
      ]
    ], [], []}}}, 0}

The text was updated successfully, but these errors were encountered:

bzmw · 2019-05-22T20:40:35Z

@benoitc have you had any time to take a look at this issue?

QuinnWilton · 2019-10-30T19:47:19Z

I'm running into this issue in production too, also using a Squid proxy. Let me know if there's any additional info I can provide that would be helpful!

benoitc · 2019-10-30T19:53:28Z

hrm i was expecting the proxy would close the connection each time (which normally it should). What let you think the same connection is reused apart the state of the pool? Do you always get the same site ?

QuinnWilton · 2019-10-30T22:34:04Z

I noticed it because a request to a Heroku app returned a Microsoft Azure 404 page, and a separate request to an Azure app returned a response from an app I have running on Gigalixir. As far as I can tell, all of the responses in question came back around the same time, and ended up associated with the wrong request.

I haven't had a chance to get a minimal reproduction to confirm that it's this exact issue, but the problem went away after removing the proxy.

bzmw · 2019-10-31T14:26:19Z

I noticed it because a request to a Heroku app returned a Microsoft Azure 404 page, and a separate request to an Azure app returned a response from an app I have running on Gigalixir. As far as I can tell, all of the responses in question came back around the same time, and ended up associated with the wrong request.

This is exactly the behaviour that we saw. We got around it by disabling connection pooling in hackney entirely.
Which sadly caused a huge jump in CPU usage, but was something we had to accommodate.

benoitc · 2019-11-01T10:05:32Z

The issue is that the connection of the proxy is not closed at the end of the session which should probably be, a trace should confirm it. Can one of you enable tracing in hackney and send me back a session. You can do it privately by mail if you need.

I may have a solution by monday.

QuinnWilton · 2019-11-01T22:53:51Z

I've been trying to get a trace for you, but I'm having trouble reproducing it reliably in an environment where I have tracing enabled. I'll let you know if I get it working though. It's something I've seen in our logs, but not something I've managed to reproduce manually.

MichaelViveros · 2019-11-02T13:30:55Z

I reproduced it locally by sending requests to 2 different ngrok endpoints (which tunneled to 2 local servers) and using a squid proxy container. The first local server returns url 1 while the second returns url 2 and the code breaks when it receives an unexpected response from a server which indicates the request was sent to the wrong endpoint (Ex. server 1 returning url 2).

proxy_request_1 = {"https://466c67ef.ngrok.io/health", "url 1", [proxy: "http://127.0.0.1:3128"]}
proxy_request_2 = {"https://4c2caca3.ngrok.io/health", "url 2", [proxy: "http://127.0.0.1:3128"]}
requests = [proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2, proxy_request_1, proxy_request_2]
for {url, expected_response, opts} = req <- requests do
  IO.puts(inspect(req))
  case HTTPoison.post!(url, "", [], opts) do
    %HTTPoison.Response{body: ^expected_response} -> IO.puts("correct endpoint")
    %HTTPoison.Response{body: body} -> 
      IO.puts("wrong endpoint - url #{url}, expected_response #{expected_response}, actual_response #{body}")
      raise "wrong endpoint"
  end
end

Sample output:

{"https://4c2caca3.ngrok.io/health", "url 2", [proxy: "http://127.0.0.1:3128"]}
correct endpoint
{"https://466c67ef.ngrok.io/health", "url 1", [proxy: "http://127.0.0.1:3128"]}
correct endpoint
{"https://4c2caca3.ngrok.io/health", "url 2", [proxy: "http://127.0.0.1:3128"]}
correct endpoint
{"https://466c67ef.ngrok.io/health", "url 1", [proxy: "http://127.0.0.1:3128"]}
wrong endpoint - url https://466c67ef.ngrok.io/health, expected_response url 1, actual_response url 2
** (RuntimeError) wrong endpoint

Note that the bug was transient - sometimes I'd have to run the script multiple times for it to occur.

I have to step out for awhile but I can look into getting more tracing later today.

MichaelViveros · 2019-11-02T14:54:26Z

You could even use a site like https://httpstat.us/ which returns different status codes depending on the route instead of using ngrok + local servers.

MichaelViveros · 2019-11-02T15:00:15Z

Actually that probably wouldn’t work since the requests would be for the same host

MichaelViveros · 2019-11-03T05:05:37Z

Here's a trace.
trace.txt

benoitc · 2019-11-03T13:26:55Z

@MichaelViveros thanks for the trace! So it's clear there what is happening. Since the response is not closing the connection (no close header), hackney will keep that connection to the proxy host open and reuse it. A quick fix is probably to probably send a Close header while sending the request. On the long term it may be better to have a separate proxy pool. I will let you know when the first one is done.

MichaelViveros · 2019-11-03T14:43:24Z

Awesome! And for my own knowledge, why does the connection with the proxy have to be closed? I thought connection pooling meant you kept the connection open and reused it. Perhaps the connection to the proxy is actually a connection to the proxy + destination server which you wouldn’t want to reuse?

…

On Sun, Nov 3, 2019 at 8:26 AM Benoit Chesneau ***@***.***> wrote: @MichaelViveros <https://github.com/MichaelViveros> thanks for the trace! So it's clear there what is happening. Since the response is not closing the connection (no close header), hackney will keep that connection to the proxy host open and reuse it. A quick fix is probably to probably send a Close header while sending the request. On the long term it may be better to have a separate proxy pool. I will let you know when the first one is done. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#566?email_source=notifications&email_token=ACDUVC2GNXL773PP5ACI6QTQR3GSFA5CNFSM4HNOGSIKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEC5SRJQ#issuecomment-549136550>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACDUVC3OZMT3OGQEE33DUHDQR3GSFANCNFSM4HNOGSIA> .

benoitc · 2019-11-05T09:10:40Z

Closing a connection ease the management of a sesion. It used (o be the default on proxes lique squid. I think a better solution is explicitley naming a connection as tunneled. Like http/proxyhost/proxyport/http/targethost/targetport if it follows the multiaddr format.

MichaelViveros · 2019-11-16T12:01:45Z

Any update @benoitc?

MichaelViveros · 2019-11-28T14:19:14Z

Any update @benoitc?

benoitc · 2019-11-28T16:46:42Z

@MichaelViveros a branch will land over the week-end...

MichaelViveros · 2019-11-28T18:13:55Z

Awesome, merci!

liamwhite · 2019-11-29T05:00:30Z

Are there any workarounds that we could use in the meantime, before a new version is cut with the fix? (Perhaps on the proxy side?)

benoitc · 2019-11-29T13:43:25Z

Are there any workarounds that we could use in the meantime, before a new version is cut with the fix? (Perhaps on the proxy side?)

you can set an Header "Connection: close" to your requests. That should fix the issue temporarely. I expect to have that new version ready this we anyway.

benoitc · 2019-12-04T22:33:58Z

@MichaelViveros so the fix will land by friday, i have been busy in refactoring some parts to allow to isolate the proxy.

liamwhite · 2019-12-07T16:34:13Z

🤞

benoitc · 2019-12-10T14:21:36Z

So I toyed with some solutions during the we, and it seems a quick fix is not possible. I will come with a plan later today with a possible fix during the week.

right now when you read the body with no redirection, the code should actually work until you make sure to always use the same proxy.

liamwhite · 2020-04-12T02:42:21Z

Any progress on this?

benoitc · 2020-04-12T20:50:14Z

@liamwhite yes. a batch of updates will be published soon.

benoitc · 2020-05-25T00:36:48Z

fixed in master finally...

thang911pk mentioned this issue May 17, 2019

Connection mixed up when using proxy #565

Closed

benoitc self-assigned this Nov 1, 2019

benoitc added bug working on it labels Nov 1, 2019

benoitc added high priority pool labels Dec 4, 2019

benoitc added this to the 1.15.3 milestone Dec 4, 2019

benoitc mentioned this issue Dec 4, 2019

connections get mixed up when using proxy and connection pooling #545

Closed

benoitc added the proxy label Dec 9, 2019

ennocramer mentioned this issue Jan 15, 2020

Use destination as pool reference for hackney_http_connect transport #606

Closed

benoitc closed this as completed May 25, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Connection mixed up when using proxy #566

Connection mixed up when using proxy #566

thang911pk commented May 16, 2019

bzmw commented May 22, 2019

QuinnWilton commented Oct 30, 2019

benoitc commented Oct 30, 2019 •

edited

QuinnWilton commented Oct 30, 2019

bzmw commented Oct 31, 2019

benoitc commented Nov 1, 2019

QuinnWilton commented Nov 1, 2019

MichaelViveros commented Nov 2, 2019 •

edited

MichaelViveros commented Nov 2, 2019

MichaelViveros commented Nov 2, 2019

MichaelViveros commented Nov 3, 2019

benoitc commented Nov 3, 2019

MichaelViveros commented Nov 3, 2019 via email

benoitc commented Nov 5, 2019

MichaelViveros commented Nov 16, 2019

MichaelViveros commented Nov 28, 2019

benoitc commented Nov 28, 2019

MichaelViveros commented Nov 28, 2019

liamwhite commented Nov 29, 2019 •

edited

benoitc commented Nov 29, 2019

benoitc commented Dec 4, 2019

liamwhite commented Dec 7, 2019

benoitc commented Dec 10, 2019 •

edited

liamwhite commented Apr 12, 2020

benoitc commented Apr 12, 2020

benoitc commented May 25, 2020

Connection mixed up when using proxy #566

Connection mixed up when using proxy #566

Comments

thang911pk commented May 16, 2019

bzmw commented May 22, 2019

QuinnWilton commented Oct 30, 2019

benoitc commented Oct 30, 2019 • edited

QuinnWilton commented Oct 30, 2019

bzmw commented Oct 31, 2019

benoitc commented Nov 1, 2019

QuinnWilton commented Nov 1, 2019

MichaelViveros commented Nov 2, 2019 • edited

MichaelViveros commented Nov 2, 2019

MichaelViveros commented Nov 2, 2019

MichaelViveros commented Nov 3, 2019

benoitc commented Nov 3, 2019

MichaelViveros commented Nov 3, 2019 via email

benoitc commented Nov 5, 2019

MichaelViveros commented Nov 16, 2019

MichaelViveros commented Nov 28, 2019

benoitc commented Nov 28, 2019

MichaelViveros commented Nov 28, 2019

liamwhite commented Nov 29, 2019 • edited

benoitc commented Nov 29, 2019

benoitc commented Dec 4, 2019

liamwhite commented Dec 7, 2019

benoitc commented Dec 10, 2019 • edited

liamwhite commented Apr 12, 2020

benoitc commented Apr 12, 2020

benoitc commented May 25, 2020

benoitc commented Oct 30, 2019 •

edited

MichaelViveros commented Nov 2, 2019 •

edited

liamwhite commented Nov 29, 2019 •

edited

benoitc commented Dec 10, 2019 •

edited