Super weird http issue

madasebrof

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.

9 comments

#httpoison #http-requests #mint

0 1687 9

2020-02-11 18:35:36 UTC

First 9 of 9 Posts

gmile

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.

Post #1

madasebrof

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.

Post #2

gmile

It should be possible to decrypt TLS1.2, see “TLS Decryption” in TLS - Wireshark Wiki. 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.

Post #3

voltone

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

Post #4

madasebrof

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

Post #5

gmile

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

Post #6

madasebrof

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

Post #7

madasebrof

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.

Post #8