Debugging cryptic errors
26 Jan 2017At a project I am working on, our backend system makes http requests to hundreds of different servers. It is sort of like webhook, http requests are made to the customer server with the payload whenever some specific events occur in our system. We were in the midst of migrating our systems from ruby to elixir.
During the test run, we started to get a cryptic error for some small number of domains.
HTTPoison.get("https://piay.iflix.com", [], [proxy: {'10.128.10.16', 3128}])
# => timestamp=2017-01-02T04:11:00.816Z level=error message= SSL: :hello:ssl_alert.erl:88:Fatal error: handshake failure
# => {:error, %HTTPoison.Error{id: nil, reason: {:tls_alert, 'handshake failure'}}}
The error points out that the handshake phase during the ssl connection is failing. But it doesn’t say why it is failing.
To get more information, I tried to use ssl module directly.
:ssl.connect('piay.iflix.com', 443, [])
# => {:ok,{:sslsocket, {:gen_tcp, #Port<0.10658>, :tls_connection, :undefined}, #PID<0.325.0>}}
To my amazement, it worked. I was able to connect to this domain, but
https request failed. Due to compliance reasons, we have to use a
proxy server for all our outgoing http/https requests. We use
HTTPoison
library, which is a wrapper for hackney
library. We
already had some issues due to proxy. It seems like most of the users
of the hackney library don’t use the proxy option, so some of the code
paths related to proxy are not well tested. To make sure proxy is the
problem, I made the request without proxy option and it worked.
Hackney uses
connect tunneling
method, which is quite simple. The http client sends CONNECT
piay.iflix.com:443
to the proxy server, which in turn opens a tcp
connection to piay.iflix.com:443
. The proxy server will then relay
whatever data sent by http client to the destination server. In case
of https request, once the connection is established, hackney
initiates the ssl protocol using ssl:connect
method.
This looks quite simple, but still something is going wrong. The same
ssl:connect
succeeds when it is established directly, but not
through the proxy server.
The dbg app provides text based
tracing functionality. It can be used to trace function at various
granularities, from all the functions in a module to a function with
specific arguments. I started to trace all the function calls in ssl
module, but it resulted in too much data for me to analyze
properly. Then I started to read the source code of ssl
app and
started to trace a single function at a time and compared the
arguments and the results of successful and failed connection.
(<0.572.0>) returned from ssl_handshake:client_hello_extensions/6 ->
{hello_extensions,
{renegotiation_info,
{elliptic_curves,
{1,3,
132,
0,
30}]},
undefined}
(<0.572.0>) returned from ssl_handshake:client_hello_extensions/6 ->
{hello_extensions,
{renegotiation_info,
{elliptic_curves,
{1,3,
132,
0,
30}]},
{sni,
"piay.iflix.com"}}
After multiple trials and errors, I finally came across something
interesting. The sni
field was present in successful connection, but
not in failed connection. The rest of the deduction was easy. The sni
extension
allows a single server to serve different certificates for different
domains. During the initial handshake, the client has to provide the
domain name along with other details.
If a host name is passed as the first param of ssl:connect
, the sni
extension is automatically enabled. For proxy request, the connection
is established to the proxy server, which relays the data to the
destination server. As the ip address of the proxy server is passed as
the first param, sni extension was not enabled.
HTTPoison.get("https://piay.iflix.com", [], [proxy: {'10.128.10.16', 3128}, ssl: [server_name_indication: 'piay.iflix.com']])
The fix was easy. The sni extension has to be enabled explicitly. As always, more layers introduce more points of failures.