Elixir: Trouble installing hex (first time fails, second time mostly works) - CI & deploys

[PragTob]

Environment

• Elixir & Erlang versions (elixir --version): Elixir 1.4, Erlang 18.3
• Operating system: Ubuntu 14.04

Current behavior

We've been experiencing failures during the installation of hex for a good 2 weeks now. The error always looks something like this:

# install dependency managers
mix local.hex --force
** (Mix) httpc request failed with: {:failed_connect, [{:to_address, {'repo.hex.pm', 443}}, {:inet, [:inet], :nxdomain}]}

Could not install Hex because Mix could not download metadata at https://repo.hex.pm/installs/hex-1.x.csv.

This is what happens on our CI. Mostly, when this happens (which is ~50% of all initial builds I'd say) then the next time the build runs/is restarted it works (but it might fail again later on).

This also happens for deploys (using edeliver and exrm in up to date versions), e.g:

-----> Cleaning generated files from last build
-----> Fetching / Updating dependencies
using mix to fetch and update deps
rebar and rebar3 for mix was built already
** (Mix) httpc request failed with: {:failed_connect, [{:to_address, {'repo.hex.pm', 443}}, {:inet, [:inet], :nxdomain}]}

Could not install Hex because Mix could not download metadata at https://repo.hex.pm/installs/hex-1.x.csv.

A remote command failed on:

Again, I'm not sure if this is the correct repo to file this issue (could also be hex/hex_web) but I found a bunch of hex installation issues here ( #3075 #3956 ) those seem/seemed to be Proxy related and/or consistently not working. For us it breaks at some point and the next try usually works. Also, the request doesn't go through a proxy for all that I know.

I'm not 100% sure but I believe it also happened 1 or 2 times for me during development, and I sit far away from the servers these issues happened at.

Expected behavior

Hex should install correctly :slightly_smiling_face:

I realize this is probably hard to debug unless someone knows that there were some flakyness problems (semi cautiously pinging @ericmj ). As a workaround/patching it together sort of thing I'd propose an option to retry installing hex

Thanks for all of your work :tada: :green_heart:
Tobi

[josevalim]

@ericmj I believe those are related to the DNS issues we have been talking about?

[ericmj]

@josevalim Yes, I believe it's a DNS issue but I am still not sure.

[PragTob]

Certainly seems possible from the behavior we are seeing. Anything we can do to help you debug this? :)

[ericmj]

If anyone knows a way to debug why it's slow that would be appreciated. For some people, me included, it's also slow in the browser the first time you visit hex.pm/hexdocs.pm in the browser in a while. Which is what is leading me to believe it's only fast when DNS is cached.

But I don't know how to confirm it's actually DNS that is slow. When I run dig -t ANY hex.pm in the shell it's always quick.

[slofurno]

was getting the same behavior in docker, but it seems like running dig before trying to install hex fixes the issue

[nonotest]

I am getting the same behaviour in docker, dig does not help.
** (Mix) httpc request failed with: {:failed_connect, [{:to_address, {'repo.hex.pm', 443}}, {:inet, [:inet], :nxdomain}]}

[josevalim]

@nonotest where are you located and what is your DNS server? I am in Kraków/Poland and I'm having the same issues but it changes if I pick another DNS (such as Google's 8.8.8.8 and 8.8.8.4).

[capitalist]

curl --compress -w "\nLookup time:\t%{time_namelookup}\nConnect time:\t%{time_connect}\nPreXfer time:\t%{time_pretransfer}\nStartXfer time:\t%{time_starttransfer}\n\nTotal time:\t%{time_total}\n" -svo /dev/null https://repo.hex.pm/installs/hex-1.x.csv?v=1&origin=https%3A%2F%2Frepo.hex.pm

from my location, yields:

*   Trying 151.101.65.5...
* TCP_NODELAY set
* Connected to repo.hex.pm (151.101.65.5) port 443 (#0)
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate: n.ssl.fastly.net
* Server certificate: GlobalSign CloudSSL CA - SHA256 - G3
* Server certificate: GlobalSign Root CA
> GET /installs/hex-1.x.csv?v=1&origin=https%3A%2F%2Frepo.hex.pm HTTP/1.1
> Host: repo.hex.pm
> User-Agent: curl/7.51.0
> Accept: */*
> Accept-Encoding: deflate, gzip
>
< HTTP/1.1 200 OK
< x-amz-id-2: /7KqaoweXooEcxuCnGIjNyuy8GbS6YvSiEFtopunDjGvrsjpw8GODrEDqEd2/5Zhom+V5xaoesE=
< x-amz-request-id: D005D4391DC79B12
< x-amz-replication-status: FAILED
< Last-Modified: Fri, 23 Dec 2016 23:29:36 GMT
< ETag: "dc70a815bfd75c5a770c7203744c8d0f"
< Cache-Control: public, max-age=604800
< x-amz-meta-surrogate-key: installs
< x-amz-version-id: x7oQTJrGagpIQPxvru9UsZApW1Y5EPjE
< Content-Type: text/csv
< Server: AmazonS3
< Via: 1.1 varnish
< Fastly-Debug-Digest: 57fe195e57bbad43f9d72564115ab7e327eb2deac34363ca051d1dfef6139f50
< Content-Length: 1704
< Accept-Ranges: bytes
< Date: Thu, 16 Feb 2017 12:38:32 GMT
< Via: 1.1 varnish
< Age: 77
< Connection: keep-alive
< X-Served-By: cache-iad2132-IAD, cache-atl6224-ATL
< X-Cache: HIT, HIT
< X-Cache-Hits: 1, 1
< X-Timer: S1487248712.494913,VS0,VE0
<
{ [1704 bytes data]
* Curl_http_done: called premature == 0
* Connection #0 to host repo.hex.pm left intact

Lookup time: 0.004
Connect time: 0.021
PreXfer time: 0.074
StartXfer time: 0.094

Total time: 0.094

[tsubery]

FWIW, It works fine from my home office in Austin, TX.
Trying to lookup dns from a linode vm in Dallas, TX datacenter I got:

time nslookup repo.hex.pm                                                                                                         
Server:         96.126.122.5
Address:        96.126.122.5#53

Non-authoritative answer:
repo.hex.pm     canonical name = n.global-ssl.fastly.net.
Name:   n.global-ssl.fastly.net
Address: 151.101.49.5

real    0m9.759s
user    0m0.023s
sys     0m0.013s

[nonotest]

Hello,
It mostly happens when I run it using my phone's hotspot over 4g.
I am based in Perth, Australia.

I have

Server:     172.20.10.1
Address:    172.20.10.1#53

Non-authoritative answer:
repo.hex.pm canonical name = n.global-ssl.fastly.net.
Name:   n.global-ssl.fastly.net
Address: 151.101.105.5

from my mac will try google later.

[ericmj]

We are currently investigating this issue and have confirmed that it's a DNS issue.

We use Cloudflare for DNS for hex.pm and hexdocs.pm and I have been talking with their support who have been really helpful. The slowness seems to be isolated to some ISPs, Google's DNS servers (8.8.8.8, 8.8.4.4) are consistently fast, so you can use them as a workaround.

If it's slow for you, please do a time nslookup repo.hex.pm like @tsubery and, if you don't mind, include your IP and/or where you are located and post it here to help us debug this.

It's slow with my ISP also (Com Hem Sweden) and I am talking with their support to see if it's an issue on the ISPs end of things.

[PragTob]

Thanks a lot @ericmj ! Will see that we get you that data :)

[cdegroot]

I'm seeing it too. I'm running a home network with a DNS resolver on OpenWRT which most likely caches. My ISP is Teksavvy, and I'm using a fixed IPv4 and IPv6 setup.

IPv4: 69.165.222.176
IPv6: 2607:f2c0:f00e:4800::/64

hex.pm resolves for me to

hex.pm.         60  IN  A   23.23.113.85
hex.pm.         60  IN  A   54.225.148.21
hex.pm.         60  IN  A   23.23.151.110

I'm not getting any AAAA records (today. I think I saw them before; not having IPv6 records may slow down things for me because most of my network stacks are set to prefer v6 over v4). Currently not seeing delays, I'll try to remember and dig around tomorrow to see what an empty cache does.

[PragTob]

so, today we got a failure with the error again after we added the nslookup inbetween:

# Workaround for mix dns issue
# https://github.com/elixir-lang/elixir/issues/5731
time nslookup repo.hex.pm
Server:     8.8.8.8
Address:    8.8.8.8#53

Non-authoritative answer:
repo.hex.pm canonical name = n.global-ssl.fastly.net.
Name:   n.global-ssl.fastly.net
Address: 151.101.193.5
Name:   n.global-ssl.fastly.net
Address: 151.101.1.5
Name:   n.global-ssl.fastly.net
Address: 151.101.129.5
Name:   n.global-ssl.fastly.net
Address: 151.101.65.5


real    0m2.062s
user    0m0.004s
sys 0m0.005s

cp config/dev.secret.exs.example config/dev.secret.exs

# install dependency managers
mix local.hex --force
** (Mix) httpc request failed with: {:failed_connect, [{:to_address, {'repo.hex.pm', 443}}, {:inet, [:inet], :nxdomain}]}

Could not install Hex because Mix could not download metadata at https://repo.hex.pm/installs/hex-1.x.csv.

[OvermindDL1]

so, today we got a failure with the error again after we added the nslookup inbetween:

Oh I've had that exact same issue with other systems!

After working with Fastly we determined it to be an issue with Level 3 backbone's network on certain paths. Do you touch Level 3 at any point on your path? Do note it was happening 50% of the time with me on my server (north-east USA, south-east Canada) because half the time a good path was taken (not Level 3) and the other half the bad path was taken. Can you ran a series of tests to see if you see the same?

EDIT1: This was a couple of years ago, it never got resolved, I ended up manually setting up a bouncer in California to work around it (SSH tunnel).

EDIT2: Also where is your server located that you are trying to download that to, is it in the North-East USA / South-East Canada as well? That was the only place I encountered that issue...

EDIT3: To be more clear, it was a specific routing path between Level 3 and Fastly, the only way to resolve it that we saw was to somehow contact Level 3 (neither I nor Fastly had success) or for the place you are downloading from to just not use Fastly (hex in this case).

[josevalim]

I believe this can be closed. Right @ericmj?

[josevalim]

Yup, the hex issues are gone. Thanks everyone, please let us know if they still persist in your case and we will gladly reopen.

[almassapargali]

Hello, I'm having this problem, during update with edeliver:

** (Mix) httpc request failed with: {:failed_connect, [{:to_address, {'repo.hex.pm', 443}}, {:inet, [:inet], :nxdomain}]}

Could not install Hex because Mix could not download metadata at https://repo.hex.pm/installs/hex-1.x.csv.

Though it works ok with curl.

[ericmj]

@almassapargali Do you get the error consistently or only from time to time?

[almassapargali]

Used to be ok, but getting consistently today.

[almassapargali]

Oh, let me try this, might be related: https://www.digitalocean.com/community/questions/how-to-fix-the-march-2017-ubuntu-dns-resolution-issues

[almassapargali]

Sorry to bother you, it turns out to be DO/Google issue, please check this if you're having any issues on DO SFO/NYC servers: https://www.digitalocean.com/community/questions/how-to-fix-the-march-2017-ubuntu-dns-resolution-issues?comment=57938

[joshuataylor]

I'm also randomly seeing this, if I run it it'll work, otherwise it'll fail:

rm -rf ~/.mix/ ; mix local.hex --force ; mix local.rebar --force

12:21:24.852 [error] Failed updating session: 
   ProfileName: :httpc_mix
   SessionId:   {{'repo.hex.pm', 443}, #PID<0.137.0>}
   Pos:         7
   Value:       0
when
   Session (db) info: :undefined
   Session (db):      {:session, {{'repo.hex.pm', 443}, #PID<0.137.0>}, false, :https,
 {:sslsocket, {:gen_tcp, #Port<0.4193>, :tls_connection, :undefined},
  #PID<0.138.0>}, {:essl, []}, 1, :keep_alive, true}
   Session (record):  {:EXIT,
 {:badarg,
  [{:ets, :lookup,
    [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.137.0>}], []},
   {:httpc_manager, :lookup_session, 2, [file: 'httpc_manager.erl', line: 189]},
   {:httpc_handler, :update_session, 4,
    [file: 'httpc_handler.erl', line: 1909]},
   {:httpc_handler, :handle_empty_queue, 4,
    [file: 'httpc_handler.erl', line: 1368]},
   {:httpc_handler, :handle_info, 2, [file: 'httpc_handler.erl', line: 471]},
   {:gen_server, :try_dispatch, 4, [file: 'gen_server.erl', line: 601]},
   {:gen_server, :handle_msg, 5, [file: 'gen_server.erl', line: 667]},
   {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]}}
   T: :error
   E: :badarg

12:21:24.853 [error] Failed updating session: 
   ProfileName: :httpc_mix
   SessionId:   {{'repo.hex.pm', 443}, #PID<0.137.0>}
   Pos:         9
   Value:       true
when
   Session (db) info: :undefined
   Session (db):      {:session, {{'repo.hex.pm', 443}, #PID<0.137.0>}, false, :https,
 {:sslsocket, {:gen_tcp, #Port<0.4193>, :tls_connection, :undefined},
  #PID<0.138.0>}, {:essl, []}, 1, :keep_alive, false}
   Session (record):  {:EXIT,
 {:badarg,
  [{:ets, :lookup,
    [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.137.0>}], []},
   {:httpc_manager, :lookup_session, 2, [file: 'httpc_manager.erl', line: 189]},
   {:httpc_handler, :update_session, 4,
    [file: 'httpc_handler.erl', line: 1909]},
   {:httpc_handler, :maybe_make_session_available, 2,
    [file: 'httpc_handler.erl', line: 1516]},
   {:httpc_handler, :answer_request, 3,
    [file: 'httpc_handler.erl', line: 1507]},
   {:httpc_handler, :terminate, 2, [file: 'httpc_handler.erl', line: 759]},
   {:gen_server, :try_terminate, 3, [file: 'gen_server.erl', line: 629]},
   {:gen_server, :terminate, 7, [file: 'gen_server.erl', line: 795]}]}}
   T: :error
   E: :badarg

12:21:24.858 [error] GenServer #PID<0.137.0> terminating
** (stop) {:failed_updating_session, [profile: :httpc_mix, session_id: {{'repo.hex.pm', 443}, #PID<0.137.0>}, pos: 9, value: true, etype: :error, error: :badarg, stacktrace: [{:ets, :update_element, [:httpc_mix__session_db, {{'repo.hex.pm', 443}, #PID<0.137.0>}, {9, true}], []}, {:httpc_manager, :update_session, 4, [file: 'httpc_manager.erl', line: 210]}, {:httpc_handler, :update_session, 4, [file: 'httpc_handler.erl', line: 1887]}, {:httpc_handler, :maybe_make_session_available, 2, [file: 'httpc_handler.erl', line: 1516]}, {:httpc_handler, :answer_request, 3, [file: 'httpc_handler.erl', line: 1507]}, {:httpc_handler, :terminate, 2, [file: 'httpc_handler.erl', line: 759]}, {:gen_server, :try_terminate, 3, [file: 'gen_server.erl', line: 629]}, {:gen_server, :terminate, 7, [file: 'gen_server.erl', line: 795]}]]}
    (inets) httpc_handler.erl:1911: :httpc_handler.update_session/4
    (inets) httpc_handler.erl:1516: :httpc_handler.maybe_make_session_available/2
    (inets) httpc_handler.erl:1507: :httpc_handler.answer_request/3
    (inets) httpc_handler.erl:759: :httpc_handler.terminate/2
    (stdlib) gen_server.erl:629: :gen_server.try_terminate/3
    (stdlib) gen_server.erl:795: :gen_server.terminate/7
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message: {:ssl, {:sslsocket, {:gen_tcp, #Port<0.4193>, :tls_connection, :undefined}, #PID<0.138.0>}, "MdsarNTW5+Qulv581S7Qp21tx8kaVpgDQMZXIIU7betyBRPfqWAUMQW5K+JmXVhS\nuvr3JxndE4zu5U+eFuXjAUfI4vkLTZ4aFwF94wqG4R+yzaB55ubIH8JWhMMilLBy\n3Ql/45410MV3lueQKgQ68X0cSwBPE7X2bjHKd/3geZX6C9vrbBp5YmUzQYH1S16V\nS6snDvPQkVVJCZZnM9PNTUf3okqxe0ugZieLkbJymgqb8epcck7dpDzMsSjBEEZN\nVaprWu64HvIn2MX4jkYiuJLYv4lJbqUJ/sVClSbWLDaMCFx5MAePGBxU/+34ja3v\nMscx1neQM1av3KNLHkfreA==\n"}
State: {:state, {:request, #Reference<0.0.1.541>, #PID<0.70.0>, 0, :https, {'repo.hex.pm', 443}, '/installs/rebar3-1.x.csv.signed', [], :get, {:http_request_h, :undefined, 'keep-alive', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, 'repo.hex.pm', :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, :undefined, [], 'Mix/1.4.2', :undefined, :undefined, :undefined, '0', :undefined, :undefined, :undefined, :undefined, :undefined, ...}, {[], []}, {:http_options, 'HTTP/1.1', :infinity, true, {:essl, []}, :undefined, true, :infinity, false}, 'https://repo.hex.pm/installs/rebar3-1.x.csv.signed', [], :none, [], 1491913284793, :undefined, :undefined, false}, {:session, {{'repo.hex.pm', 443}, #PID<0.137.0>}, false, :https, {:sslsocket, {:gen_tcp, #Port<0.4193>, :tls_connection, :undefined}, #PID<0.138.0>}, {:essl, []}, 1, :keep_alive, false}, {'HTTP/1.1', 200, 'OK'}, {:http_response_h, 'public, max-age=604800', 'keep-alive', 'Tue, 11 Apr 2017 12:21:24 GMT', :undefined, :undefined, :undefined, :undefined, '1.1 varnish', :undefined, 'bytes', '98962', '"97e852cec4c2ca70b56f49a2cd41a93c"', :undefined, :undefined, :undefined, 'AmazonS3', :undefined, :undefined, :undefined, :undefined, :undefined, '350', :undefined, :undefined, :undefined, 'binary/octet-stream', :undefined, 'Fri, 20 Jan 2017 09:53:39 GMT', [{'x-amz-id-2', 'W33/2vHDUdqyO8dphQOtqJjC6Pug8k96WfFs4nmkjIhd7D1HkGLTG4aQx3Vyk5IOKWAf3yTEfqA='}, {'x-amz-request-id', '2F36FAB4E9AF0E3F'}, {'x-amz-replication-status', 'FAILED'}, {'x-amz-meta-surrogate-key', 'installs'}, {'x-amz-version-id', 'qMfBkYLIJh1jk7Wmw6hAYVe1MJ2ttAk8'}, {'fastly-debug-digest', '864530c58fa2f5e6f7b455ba1b8a8fd668c94f688c98b6cdc85319515ff6f6b1'}, {'x-served-by', 'cache-iad2143-IAD, cache-per7622-PER'}, {'x-cache', 'HIT, HIT'}, {'x-cache-hits', '2, 22'}, {'x-timer', 'S1491913285.851139,VS0,VE0'}]}, :undefined, {:httpc_response, :whole_body, ["", 350]}, {[], []}, {[], []}, :new, [], :nolimit, :nolimit, {:options, {:undefined, []}, {:undefined, []}, 0, 2, 5, 120000, 2, :disabled, false, :inet, :default, :default, []}, {:timers, [], :undefined}, :httpc_mix, :inactive}

[ericmj]

@joshuataylor Even if you get this error message the command completed successfully. The issue is being tracked on OTP.

[joshuataylor]

Thanks for the quick response @ericmj , will just ignore for now.