cannot unmarshal DNS message when login in heroku

Question

cannot unmarshal DNS message when login in heroku

mbarakaja opened this issue 8 years ago · 19 comments

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

Answer 1 · 2016-09-24T07:47:24.000Z

+1
Ubuntu 14.04.5 LTS

Answer 2 · 2016-09-27T10:14:44.000Z

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`

Answer 3 · 2016-09-27T13:14:47.000Z

@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.

Answer 4 · 2016-09-27T13:20:30.000Z

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

Answer 5 · 2016-09-27T13:30:28.000Z

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.

Answer 6 · 2016-09-27T13:54:33.000Z

@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.

Answer 7 · 2016-09-27T14:08:06.000Z

Ok. Thanks

Answer 8 · 2016-09-27T14:31:14.000Z

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

Answer 9 · 2016-09-27T18:55:02.000Z

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

Answer 10 · 2016-09-28T13:51:19.000Z

@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.

Answer 11 · 2016-09-28T13:56:17.000Z

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

Answer 12 · 2016-09-28T14:03:33.000Z

@aslubsky great to hear!

Answer 13 · 2016-09-28T14:14:56.000Z

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.

Answer 14 · 2016-09-28T16:23:56.000Z

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.

Answer 15 · 2016-09-29T08:59:31.000Z

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

Answer 16 · 2016-09-29T15:06:19.000Z

@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

Answer 17 · 2016-09-29T15:36:20.000Z

@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.

Answer 18 · 2016-10-24T20:48:37.000Z

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

Answer 19 · 2016-10-24T20:58:02.000Z

@mbarakaja good to hear!