Super weird http issue

madasebrof · February 11, 2020, 2:01pm

Wow, this is an odd one.

I’m making an http request (post) to a server.

Work fine from curl
Works fine from iex
Bombs out when I run from within app!

I have literally never had this happen before, when the EXACT same function behaves differently live vs. iex.

Just wondering if anyone has insight into some magic that might be going on behind the scenes that could be causing this! (This is a phoenix app, but doesn’t seem phoenix-related…)

I even added a checksum function to make sure the data being sent was identical & there wasn’t some odd file-write delay causing the issue.

Example - Success from iex (note–iex is actually connected to the running app!):

iex(91be5e1d30ff@172.21.0.3)5> Polo.Ib.Connect.post(body, "/create") 
13:24:11.570 [info]  Ib.Connect.post endpoint: [ https://qa.xyz.com/ws/eca/create ]
13:24:11.573 [warn]  
Mojito.request(
  method: :post,
  url: https://qa.xyz.com/ws/eca/create,
  headers: [{"Content-Type", "application/json"}, {"User-Agent", "Elixir"}, {"Accept", "*/*"}],
  body: data -> checksum = 904033a8a73bdea778edf96317957f40704686cd,
  opts: [timeout: 180_000, transport_opts: [verify: :verify_none]]
)

{:ok,
 %{
   "batchId" => 305738,
   "fileData" => %{
     "data" => "hQ ... eFBJXdc/cKHQ==",
     "name" => "sgimFA_20200211-082414031_965716.xml"
   },
   "isProcessed" => true,
   "timestamp" => "2020-02-11 08:24:15"
 }}

works great!

From with the app, when running programmatically, I get

[info] Ib.Connect.post endpoint: [ https://qa.xyz.com/ws/eca/create ]
[warn] 

Mojito.request(
  method: :post,
  url: https://qa.xyz.com/ws/eca/create,
  headers: [{"Content-Type", "application/json"}, {"User-Agent", "Elixir"}, {"Accept", "*/*"}],
  body: data -> checksum = 904033a8a73bdea778edf96317957f40704686cd,
  opts: [timeout: 180_000, transport_opts: [verify: :verify_none]]
)

[error] %Mojito.Response{body: "<!DOCTYPE html>\n<html>
\n<head>\n<title>Account Management Unavailable | ... \" content=\"500 Error\">\n<<> ..., 
complete: true, 
headers: [{"date", "Tue, 11 Feb 2020 13:21:47 GMT"}, 
{"server", "Apache"}, 
{"vary", "\\\"Origin\\\""}, 
{"content-security-policy", "frame-ancestors 'self'  ... .com;"}, 
{"content-length", "5879"}, 
{"connection", "close"}, 
{"content-type", "text/html; charset=UTF-8"}], 
status_code: 500}

Note that the checksum of the data is identical! The headers are identical! It’s literally the exact same function with identical arguments.

I am just totally at a loss as to what could be different.

Any thoughts are appreciated!

ps Was using HTTPPoision, then switched to Mojito/Mint to see if that would fix, but same issue.

gmile · February 11, 2020, 2:21pm

When you make it from the application & from iex, I’d suggest using wireshark to look into the headers/body of outgoing request & look again byte-by-byte how are they different.

madasebrof · February 11, 2020, 2:38pm

Cool, thanks for the suggestion. Installed wireshark, but unfortunately all TLS1.2, so all encrypted packets! Unable to read headers, etc. I guess I’d need to be able to run Mint in debug-mode to have it print out header, etc, like when you run curl -v.

gmile · February 11, 2020, 2:51pm

It should be possible to decrypt TLS1.2, see “TLS Decryption” in https://wiki.wireshark.org/TLS. It will require some manual setup steps though.

Alternatively, if you control the other end, e.g. https://qa.xyz.com/ws/eca/create, then turning off HTTPS for the purpose of debugging may save you some time.

voltone · February 11, 2020, 3:06pm

Decrypting TLS would be possible in two scenarios:

You have access to the server’s private key and you constrain the negotiated cipher suites to ensure the key exchange does not use (EC)DHE, or
You write the master secret for the session you want to decode to a file

This last option can work both on the server side (if you control the server) or on the client side (using Erlang’s :ssl.connection_information(socket, [:client_random, :master_secret]).

But there is an easier way: use Erlang’s tracing functionality, e.g. using :dbg or some higher level abstraction such as recon:

iex(1)> :dbg.tracer()                                                            
{:ok, #PID<0.258.0>}
iex(2)> :dbg.p(:all, :call)                                                      
{:ok, [{:matched, :nonode@nohost, 119}]}
iex(3)> :dbg.tp({Mint.Core.Transport.SSL, :send, :_}, :cx)                       
{:ok, [{:matched, :nonode@nohost, 1}, {:saved, :cx}]}
iex(4)> {:ok, response} = Mojito.request(method: :get, url: "https://github.com")
(<0.269.0>) call 'Elixir.Mint.Core.Transport.SSL':send({sslsocket,{gen_tcp,#Port<0.6>,tls_connection,undefined},
           [<0.303.0>,<0.302.0>]},[[<<"GET">>,32,<<"/">>,<<" HTTP/1.1\r\n">>],
 [[[<<>>,<<"content-length">>,<<": ">>,<<"0">>,<<"\r\n">>],
   <<"host">>,<<": ">>,<<"github.com">>,<<"\r\n">>],
  <<"user-agent">>,<<": ">>,<<"mint/1.0.0">>,<<"\r\n">>],
 <<"\r\n">>,<<>>]) ({'Elixir.Mint.HTTP1',request,5})
(<0.269.0>) returned from 'Elixir.Mint.Core.Transport.SSL':send/2 -> ok
{:ok,
 %Mojito.Response{...}

It takes a second to spot the actual request data in the output and perhaps reformat it, but it is much easier than setting up TLS decoding

madasebrof · February 11, 2020, 3:30pm

Awesome! So cool to know about this!

Yet the insanity continues:

When run from the app: error (returns status: 500)

(<0.935.0>) call 'Elixir.Mint.Core.Transport.SSL':send({sslsocket,{gen_tcp,#Port<0.55584>,tls_connection,undefined},<0.941.0>},
[[<<"POST">>,32,<<"/ws/eca/create">>,<<" HTTP/1.1\r\n">>],
 [[[[[<<>>,<<"content-length">>,<<": ">>,<<"1449713">>,<<"\r\n">>],
     <<"host">>,<<": ">>,<<"qa.xyz.com">>,<<"\r\n">>],
    <<"content-type">>,<<": ">>,<<"application/json">>,<<"\r\n">>],
   <<"user-agent">>,<<": ">>,<<"Elixir">>,<<"\r\n">>],
  <<"accept">>,<<": ">>,<<"*/*">>,<<"\r\n">>],
 <<"\r\n">>,
 <<"{\"CSID\":\"1245012...64696CCA\",\"payload\":\"hQIMAxEI/r3iJfdFAQ//aB/GhVKG4boVF22IlHJBWyro...
 5})
(<0.935.0>) returned from 'Elixir.Mint.Core.Transport.SSL':send/2 -> ok

run from iex! Works like a charm! (returns status: 200)

(<0.873.0>) call 'Elixir.Mint.Core.Transport.SSL':send({sslsocket,{gen_tcp,#Port<0.55628>,tls_connection,undefined},<0.947.0>},
[[<<"POST">>,32,<<"/ws/eca/create">>,<<" HTTP/1.1\r\n">>],
 [[[[[<<>>,<<"content-length">>,<<": ">>,<<"1449713">>,<<"\r\n">>],
     <<"host">>,<<": ">>,<<"qa.xyz.com">>,<<"\r\n">>],
    <<"content-type">>,<<": ">>,<<"application/json">>,<<"\r\n">>],
   <<"user-agent">>,<<": ">>,<<"Elixir">>,<<"\r\n">>],
  <<"accept">>,<<": ">>,<<"*/*">>,<<"\r\n">>],
 <<"\r\n">>,
 <<"{\"CSID\":\"1245012...64696CCA\",\"payload\":\"hQIMAxEI/r3iJfdFAQ//aB/GhVKG4boVF22IlHJBWyro...
 5})
(<0.873.0>) returned from 'Elixir.Mint.Core.Transport.SSL':send/2 -> ok

Those look identical to me!

wat

gmile · February 11, 2020, 3:44pm

Are you running the requests from the same IP? I am just thinking what else can be different…

madasebrof · February 11, 2020, 3:47pm

Crazy right?!?!

Yes, I’m actually connecting to the live app and running it from there!

E.g.

iex \
  --name $name \
  --cookie $cookie \
  --remsh $remote

madasebrof · February 11, 2020, 4:26pm

Something very odd is going on.

I ran curl as a System.cmd and am having the same issue!

E.g. function calling curl run as a System.cmd works fine from iex, but not when run programmatically from app! Seems like maybe some weird permission thing, as it is being called from a phoenix channel, then spawned as a task of another Supervisor.

Anyway, will continue to troubleshoot. So strange!

Thanks for all the responses!!!

ps We are making http requests to tons of other http endpoints from other vendors that work just fine! This is a new vendor.

madasebrof · February 11, 2020, 6:35pm

At the end of the day, I think it’s just a super flaky endpoint, and it was more coincidence that some requests were working and other were not!

I just tried 4 request in a row–first 3 bombed, last one went through.

Again, thanks for all ideas!

Rock on,