cannot unmarshal DNS message when login in heroku

[mbarakaja]

Hello

I am facing a problem related to a closed issue here #1899. The version of heroku-toolbelt and heroku-cli is as follow:

heroku-toolbelt/3.43.12 (x86_64-linux-gnu) ruby/2.3.1
heroku-cli/5.2.41-7b040f4 (linux-amd64) go1.6.2

When I try to log in

Enter your Heroku credentials.
Email: xxx@xxx.com
Password (typing will be hidden): 
 ▸    Post https://api.heroku.com/login: dial tcp: lookup api.heroku.com on 127.0.1.1:53: cannot unmarshal DNS message

My O.S is Ubuntu 16.04 LTS 64 Bits

[aslubsky]

+1 Ubuntu 14.04.5 LTS

[richardgroves]

Having the same problem here:

richard$ heroku version heroku-toolbelt/3.43.11 (x86_64-darwin10.8.0) ruby/1.9.3 heroku-cli/5.3.5-3e5cdd9 (darwin-amd64) go1.6.2 You have no installed plugins.

Tried to update to make sure I have the latest:

richard$ heroku update ▸ Get https://cli-assets.heroku.com/branches/stable/manifest.json: dial tcp: lookup cli-assets.heroku.com on 8.8.4.4:53: cannot unmarshal DNS message

Try the login again and now am getting a massive callback stack for the failure:

richard$ heroku login Enter your Heroku credentials. Email: richard@noodlfroot.com Password (typing will be hidden): ▸ Post https://api.heroku.com/login: dial tcp: lookup api.heroku.com on 8.8.4.4:53: cannot unmarshal DNS message

fatal error: unexpected signal during runtime execution [signal 0xb code=0x1 addr=0xb01dfacedebac1e pc=0x27e5a0]

goroutine 1 [running]: runtime.throw(0x525680, 0x2a) /usr/local/go/src/runtime/panic.go:547 +0x90 fp=0xc82018b5c0 sp=0xc82018b5a8 runtime.sigpanic() /usr/local/go/src/runtime/sigpanic_unix.go:12 +0x5a fp=0xc82018b610 sp=0xc82018b5c0 sync.(_Pool).Get(0x6bbfb0, 0x0, 0x0) /usr/local/go/src/sync/pool.go:102 +0x40 fp=0xc82018b660 sp=0xc82018b610 fmt.newPrinter(0xc82018b900) /usr/local/go/src/fmt/print.go:133 +0x27 fp=0xc82018b6a0 sp=0xc82018b660 fmt.Sprintf(0x49f630, 0xd, 0xc82018b7c0, 0x3, 0x3, 0x0, 0x0) /usr/local/go/src/fmt/print.go:202 +0x2b fp=0xc82018b6f0 sp=0xc82018b6a0 github.com/heroku/cli/vendor/github.com/go-errors/errors.(_StackFrame).String(0xc82018b8c8, 0x0, 0x0) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/go-errors/errors/stackframe.go:53 +0x20f fp=0xc82018b7f8 sp=0xc82018b6f0 github.com/heroku/cli/vendor/github.com/ansel1/merry.Stacktrace(0x7af7c0, 0xc8201d4c90, 0x0, 0x0) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/ansel1/merry/print.go:40 +0x1a8 fp=0xc82018b910 sp=0xc82018b7f8 github.com/heroku/cli/vendor/github.com/ansel1/merry.Details(0x7af7c0, 0xc8201d4c90, 0x0, 0x0) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/ansel1/merry/print.go:57 +0x274 fp=0xc82018ba08 sp=0xc82018b910 main.handlePanic() /home/ubuntu/.go_workspace/src/github.com/heroku/cli/io.go:335 +0x204 fp=0xc82018bad0 sp=0xc82018ba08 runtime.call32(0x0, 0x559d08, 0xc8200798c0, 0x0) /usr/local/go/src/runtime/asm_amd64.s:472 +0x3e fp=0xc82018baf8 sp=0xc82018bad0 panic(0x43b120, 0xc8201d4c60) /usr/local/go/src/runtime/panic.go:443 +0x4e9 fp=0xc82018bb78 sp=0xc82018baf8 main.must(0x7af710, 0xc8201d4c60) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/io.go:189 +0x4b fp=0xc82018bba0 sp=0xc82018bb78 main.v2login(0xc8201a6de0, 0x16, 0xc820077bc0, 0x8, 0x0, 0x0, 0x0, 0x0) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/auth.go:326 +0x250 fp=0xc82018bcc0 sp=0xc82018bba0 main.interactiveLogin() /home/ubuntu/.go_workspace/src/github.com/heroku/cli/auth.go:261 +0x201 fp=0xc82018bdb0 sp=0xc82018bcc0 main.login(0xc8201ac620) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/auth.go:208 +0x103 fp=0xc82018be08 sp=0xc82018bdb0 main.Start(0xc820070080, 0x2, 0x2) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/start.go:70 +0x62b fp=0xc82018bf20 sp=0xc82018be08 main.main() /home/ubuntu/.go_workspace/src/github.com/heroku/cli/main.go:22 +0x91 fp=0xc82018bf40 sp=0xc82018bf20 runtime.main() /usr/local/go/src/runtime/proc.go:188 +0x2b0 fp=0xc82018bf90 sp=0xc82018bf40 runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc82018bf98 sp=0xc82018bf90

goroutine 19 [syscall]: os/signal.signal_recv(0x0) /usr/local/go/src/runtime/sigqueue.go:116 +0x132 os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:22 +0x18 created by os/signal.init.1 /usr/local/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 20 [chan receive]: github.com/heroku/cli/vendor/github.com/stvp/rollbar.init.1.func1() /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/stvp/rollbar/rollbar.go:103 +0x5c created by github.com/heroku/cli/vendor/github.com/stvp/rollbar.init.1 /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/stvp/rollbar/rollbar.go:114 +0x91

goroutine 3 [select, locked to thread]: runtime.gopark(0x55a558, 0xc82002af28, 0x49e660, 0x6, 0x18, 0x2) /usr/local/go/src/runtime/proc.go:262 +0x163 runtime.selectgoImpl(0xc82002af28, 0x0, 0x18) /usr/local/go/src/runtime/select.go:392 +0xa67 runtime.selectgo(0xc82002af28) /usr/local/go/src/runtime/select.go:215 +0x12 runtime.ensureSigM.func1() /usr/local/go/src/runtime/signal1_unix.go:279 +0x32c runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1

goroutine 4 [chan receive]: main.handleSignal.func1(0xc8200180c0, 0x559d68) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/io.go:316 +0x36 created by main.handleSignal /home/ubuntu/.go_workspace/src/github.com/heroku/cli/io.go:318 +0xd9

goroutine 5 [chan receive]: github.com/heroku/cli/vendor/github.com/dickeyxxx/speakeasy.getPassword.func1(0xc8200750e0, 0xc8201a6e00, 0x3, 0x3) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/dickeyxxx/speakeasy/speakeasy_unix.go:48 +0x36 created by github.com/heroku/cli/vendor/github.com/dickeyxxx/speakeasy.getPassword /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/dickeyxxx/speakeasy/speakeasy_unix.go:51 +0x4dd

goroutine 7 [runnable]: net/http.setRequestCancel.func4(0x0, 0xc8201b20c0, 0xc820073f80, 0xc8200751a0) /usr/local/go/src/net/http/client.go:333 +0x12e created by net/http.setRequestCancel /usr/local/go/src/net/http/client.go:341 +0x2f7`

[ransombriggs]

@mbarakaja @aslubsky are you using google DNS? I can see from the debug output that richardgroves is but am wondering if you are as well. So far we have only seen this issue with google public DNS, but have not been able to recreate it ourselves. Could you please reply with which google DNS server you are using and I will start a ticket with them to try and resolve. The underlying problem is that google DNS responds with DNS messages that are too large and the go DNS libraries refuse to parse them. I have tried to recreate it myself using google DNS but have had no luck so I may need more information in the future.

[aslubsky]

No, I use my ISP DNS. For fix this bug I set 23.21.149.112 api.heroku.com in my /etc/hosts

[richardgroves]

I've also tried several other DNS servers and have the same problem on them all.

eg. 37.235.1.174 162.211.64.20 84.200.69.80

Googling for 'cannot unmarshal DNS message' shows some problems in Docker CLI as well and they seem to trace it to a problem in the GO language DNS parser not expecting a >512 byte DNS response (dig is showing me that api.heroku.com lookup is a 612 byte msg). It all gets a bit above my head at that point with comments about 'EDNS' and RCP compliance of returning messages >512 bytes. I'm trying to work out what version of GO the heroku toolbelt is using, but without any joy.

[ransombriggs]

@richardgroves @aslubsky thanks for the quick response. I went through the same issue as @richardgroves and ended up learning a fair amount about DNS in the process. Apparently it asks for a response < 512, but a response is returned that is > 512 which is not to the DNS spec. We are in the process of bumping golang from 1.6 to 1.7 to fix a Mac OS Sierra bug. There is nothing in the official release notes regarding a fix for this, but it may help. I will update this issue once we have shipped it, we are just waiting on a review at this point.

[aslubsky]

Ok. Thanks

[richardgroves]

Thanks - I've used the /etc/hosts hack as suggested by @aslubsky for now.

[mbarakaja]

@ransombriggs I'm not using Google DNS servers and error.log file doesn't appear in .heroku folder.

[ransombriggs]

@mbarakaja @aslubsky @richardgroves could you heroku update and try again, we just upgraded to go 1.7 and I want to see if it made a difference, but I have never been able to replicate this myself. I tried the servers @richardgroves mentioned earlier but receive normal sized responses when I request using dig.

For what it is worth, here are links to serverfault and stackoverflow questions from last time I tried to reproduce this error. The relevant quote as to why I do not see this but you do.

You are hitting different server farms. Both of you are sending requests to the same IP, but your requests are arriving at different destinations due to Anycast. As to why the servers are responding differently, only Google can answer that.

[aslubsky]

Works fine

root@xxx:~# heroku update ▸ Update in progress ! To update this version of the Heroku client please use ! apt-get install heroku-toolbelt root@xxx:~# heroku --version heroku-toolbelt/3.43.12 (x86_64-linux) ruby/1.9.3 heroku-cli/5.4.1-ae9db27 (linux-amd64) go1.7.1 You have no installed plugins. root@xxx:~# heroku login Enter your Heroku credentials. Email: xxx@gmail.com Password (typing will be hidden): Logged in as xxx@gmail.com

[ransombriggs]

@aslubsky great to hear!

[richardgroves]

I can't test today as the location I'm at is getting a 193 byte size response for api.heroku.com, but will be back in the problem location tomorrow and will re-test then.

[mbarakaja]

After the update, I am getting another error:

Post https://api.heroku.com/login: dial tcp: lookup api.heroku.com on 127.0.1.1:53: read udp 127.0.0.1:59962->127.0.1.1:53: i/o timeout

I will try to login in another computer. Maybe something is wrong with my O.S.

[richardgroves]

I'm back in the problem location, but can't actually update to the latest version:

richard$ heroku update ▸ Get https://cli-assets.heroku.com/branches/stable/manifest.json: dial tcp: lookup cli-assets.heroku.com on 8.8.4.4:53: cannot unmarshal DNS message ! Usebrew upgrade herokuto update

Using the suggested brew upgrade gives: richard$ brew upgrade heroku Error: heroku 3.43.12 already installed

Using dig to lookup cli-assets.heroku.com and adding 54.230.0.226 cli-assets.heroku.com to my /etc/host and repeating the 'heroku update' gives a massive error dump - pasted below

So unlesss there is another way to update I'm stuck - will try the update when back in my working location and then try the login here again, but it will be early next week now before I can complete that test.

---

richard$ heroku update fatal error: unexpected signal during runtime executionB [signal 0xb code=0x1 addr=0x126e2d8 pc=0x258ff5]

goroutine 16 [running]: runtime.throw(0x525680, 0x2a) /usr/local/go/src/runtime/panic.go:547 +0x90 fp=0xc820026e00 sp=0xc820026de8 runtime.sigpanic() /usr/local/go/src/runtime/sigpanic_unix.go:12 +0x5a fp=0xc820026e50 sp=0xc820026e00 runtime/internal/atomic.Load64(0x126e2d8, 0x126e2db4265) /usr/local/go/src/runtime/internal/atomic/atomic_amd64x.go:26 +0x5 fp=0xc820026e58 sp=0xc820026e50 runtime.lfstackpop(0x6c4c08, 0x53103) /usr/local/go/src/runtime/lfstack.go:38 +0x6d fp=0xc820026e90 sp=0xc820026e58 runtime.getempty(0x67, 0x0) /usr/local/go/src/runtime/mgcwork.go:341 +0x3b fp=0xc820026ec0 sp=0xc820026e90 runtime.(_gcWork).init(0xc82001b220) /usr/local/go/src/runtime/mgcwork.go:100 +0x53 fp=0xc820026ed8 sp=0xc820026ec0 runtime.(_gcWork).tryGet(0xc82001b220, 0x1) /usr/local/go/src/runtime/mgcwork.go:141 +0x38 fp=0xc820026f08 sp=0xc820026ed8 runtime.gcDrain(0xc82001b220, 0x5) /usr/local/go/src/runtime/mgcmark.go:833 +0x22a fp=0xc820026f40 sp=0xc820026f08 runtime.gcBgMarkWorker(0xc82001a000) /usr/local/go/src/runtime/mgc.go:1435 +0x583 fp=0xc820026fb8 sp=0xc820026f40 runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1 fp=0xc820026fc0 sp=0xc820026fb8 created by runtime.gcBgMarkStartWorkers /usr/local/go/src/runtime/mgc.go:1330 +0x92

goroutine 1 [GC assist wait]: io.copyBuffer(0x7b2330, 0xc82002e8c8, 0x7c9998, 0xc820262480, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) /usr/local/go/src/io/io.go:377 +0x1df io.Copy(0x7b2330, 0xc82002e8c8, 0x7c9998, 0xc820262480, 0xc82002e8c8, 0x0, 0x0) /usr/local/go/src/io/io.go:350 +0x64 main.extractFile(0x7c9998, 0xc820262480, 0xc8201621a0, 0xc82013d200, 0x86, 0x0, 0x0) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/tar.go:45 +0x1f9 main.extractTar(0x7c93c0, 0xc8201a9540, 0xc82044c510, 0x30, 0x0, 0x0) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/tar.go:29 +0x44e main.DownloadCLI(0x5597d8, 0x6, 0xc82047c000, 0x26, 0xc8201abc80) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/update.go:96 +0x607 main.updateCLI(0x5597d8, 0x6) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/update.go:67 +0x22c main.Update(0x5597d8, 0x6) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/update.go:50 +0x30 main.init.8.func1(0xc8201a4620) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/update.go:33 +0xa5 main.Start(0xc82000a240, 0x2, 0x2) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/start.go:70 +0x62b main.main() /home/ubuntu/.go_workspace/src/github.com/heroku/cli/main.go:22 +0x91

goroutine 5 [syscall]: os/signal.signal_recv(0x0) /usr/local/go/src/runtime/sigqueue.go:116 +0x132 os/signal.loop() /usr/local/go/src/os/signal/signal_unix.go:22 +0x18 created by os/signal.init.1 /usr/local/go/src/os/signal/signal_unix.go:28 +0x37

goroutine 6 [chan receive]: github.com/heroku/cli/vendor/github.com/stvp/rollbar.init.1.func1() /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/stvp/rollbar/rollbar.go:103 +0x5c created by github.com/heroku/cli/vendor/github.com/stvp/rollbar.init.1 /home/ubuntu/.go_workspace/src/github.com/heroku/cli/vendor/github.com/stvp/rollbar/rollbar.go:114 +0x91

goroutine 7 [select, locked to thread]: runtime.gopark(0x55a558, 0xc82002cf28, 0x49e660, 0x6, 0x18, 0x2) /usr/local/go/src/runtime/proc.go:262 +0x163 runtime.selectgoImpl(0xc82002cf28, 0x0, 0x18) /usr/local/go/src/runtime/select.go:392 +0xa67 runtime.selectgo(0xc82002cf28) /usr/local/go/src/runtime/select.go:215 +0x12 runtime.ensureSigM.func1() /usr/local/go/src/runtime/signal1_unix.go:279 +0x32c runtime.goexit() /usr/local/go/src/runtime/asm_amd64.s:1998 +0x1

goroutine 8 [chan receive]: main.handleSignal.func1(0xc820018420, 0x559d68) /home/ubuntu/.go_workspace/src/github.com/heroku/cli/io.go:316 +0x36 created by main.handleSignal /home/ubuntu/.go_workspace/src/github.com/heroku/cli/io.go:318 +0xd9

goroutine 19 [select]: net/http.setRequestCancel.func4(0x0, 0xc82044c240, 0xc82044e100, 0xc82031e0c0) /usr/local/go/src/net/http/client.go:333 +0x12e created by net/http.setRequestCancel /usr/local/go/src/net/http/client.go:341 +0x2f7

goroutine 17 [select]: net/http.(_persistConn).readLoop(0xc8201a6a90) /usr/local/go/src/net/http/transport.go:1182 +0xd52 created by net/http.(_Transport).dialConn /usr/local/go/src/net/http/transport.go:857 +0x10a6

goroutine 18 [select]: net/http.(_persistConn).writeLoop(0xc8201a6a90) /usr/local/go/src/net/http/transport.go:1277 +0x472 created by net/http.(_Transport).dialConn /usr/local/go/src/net/http/transport.go:858 +0x10cb ! Use brew upgrade heroku to update

[ransombriggs]

@richardgroves I am assuming that you are running Mac OS Sierra. There was an issue with our CLI with Sierra that we have shipped a fix for, but it appears that the issue may be interfering with the update process. If you run the following commands, it should clear things out and download the fix. I am sorry that this has not been a good experience for you.

rm ~/.local/share/heroku/cli/bin/heroku 
heroku update

[richardgroves]

@ransombriggs Correct - am on Sierra, and it hasn't been great. But the support response here has been good.

Anyway - ran your incantations and got myself updated:

heroku --version heroku-toolbelt/3.43.12 (x86_64-darwin15) ruby/2.3.0 heroku-cli/5.4.1-ae9db27 (darwin-amd64) go1.7.1 You have no installed plugins.

Removed the /etc/hosts hacks and ran heroku login:

heroku login Enter your Heroku credentials. Email: richard@<my email hidden> Password (typing will be hidden): ▸ Post https://api.heroku.com/login: dial tcp: lookup api.heroku.com on 8.8.4.4:53: read udp 10.0.124.128:62428->8.8.4.4:53: i/o timeout

which looks to be exactly what @mbarakaja was getting earlier - but I do seem to be logged in, and running a plain heroku at the command line gives me output about my account and dynos.

[mbarakaja]

Since the last update I'm not having more problems with the tool. So, this issue can be closed if you wish.

[ransombriggs]

@mbarakaja good to hear!