snap install hangs if internet is disconnected exactly right after err upload starts
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
snapd |
Triaged
|
Low
|
Unassigned |
Bug Description
I can't quite reproduce this, but what I think happened is that I happened to intentionally disconnect my internet after a snap install command failed (I know this later, but in the CLI it just hung up), and the connection snapd had made to the daisy.ubuntu.com was effectively interrupted but stuck so `snap install` just hung for multiple minutes before I killed snapd by issuing a SIGQUIT. I got the following backtrace:
Dec 04 11:10:16 snapd[3405]: SIGQUIT: quit
Dec 04 11:10:16 snapd[3405]: PC=0x462eb1 m=0 sigcode=0
Dec 04 11:10:16 snapd[3405]: goroutine 0 [idle]:
Dec 04 11:10:16 snapd[3405]: runtime.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: runtime.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: runtime.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: runtime.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: runtime.schedule()
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: runtime.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: runtime.mcall(0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: goroutine 1 [select, 203 minutes]:
Dec 04 11:10:16 snapd[3405]: main.run(
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: main.main()
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 19 [syscall, 203 minutes]:
Dec 04 11:10:16 snapd[3405]: os/signal.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: os/signal.loop()
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: created by os/signal.init.0
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: goroutine 32 [IO wait, 203 minutes]:
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*netFD)
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*UnixListe
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*UnixListe
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 64 [select]:
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 65 [select, 3 minutes]:
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 226 [IO wait]:
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*netFD)
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*UnixListe
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*UnixListe
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 227 [select]:
Dec 04 11:10:16 snapd[3405]: main.runWatchdo
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by main.runWatchdog
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 228 [syscall, 3 minutes]:
Dec 04 11:10:16 snapd[3405]: syscall.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: syscall.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: syscall.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 229 [select, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 4422 [select, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: created by github.
Dec 04 11:10:16 snapd[3405]: $GOPATH/
Dec 04 11:10:16 snapd[3405]: goroutine 5037 [IO wait, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: internal/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*netFD)
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net.(*conn)
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: crypto/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: bytes.(
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: crypto/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: crypto/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: crypto/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: crypto/
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: bufio.(
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: bufio.(
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: created by net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: goroutine 5038 [select, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: created by net/http.
Dec 04 11:10:16 snapd[3405]: /snap/go/
Dec 04 11:10:16 snapd[3405]: rax 0xca
Dec 04 11:10:16 snapd[3405]: rbx 0x14b45a0
Dec 04 11:10:16 snapd[3405]: rcx 0x462eb3
Dec 04 11:10:16 snapd[3405]: rdx 0x0
Dec 04 11:10:16 snapd[3405]: rdi 0x14b46e8
Dec 04 11:10:16 snapd[3405]: rsi 0x80
Dec 04 11:10:16 snapd[3405]: rbp 0x7ffcd68e4dc8
Dec 04 11:10:16 snapd[3405]: rsp 0x7ffcd68e4d80
Dec 04 11:10:16 snapd[3405]: r8 0x0
Dec 04 11:10:16 snapd[3405]: r9 0x0
Dec 04 11:10:16 snapd[3405]: r10 0x0
Dec 04 11:10:16 snapd[3405]: r11 0x286
Dec 04 11:10:16 snapd[3405]: r12 0xff
Dec 04 11:10:16 snapd[3405]: r13 0x0
Dec 04 11:10:16 snapd[3405]: r14 0xefccac
Dec 04 11:10:16 snapd[3405]: r15 0x0
Dec 04 11:10:16 snapd[3405]: rip 0x462eb1
Dec 04 11:10:16 snapd[3405]: rflags 0x286
Dec 04 11:10:16 snapd[3405]: cs 0x33
Dec 04 11:10:16 snapd[3405]: fs 0x0
Dec 04 11:10:16 snapd[3405]: gs 0x0
The full log is attached for context.
Changed in snapd: | |
importance: | Undecided → Low |
tags: | added: papercut |
Changed in snapd: | |
status: | New → Triaged |
I will also say anecdotally that I have seen install failures due to the install hook exiting with non-0 exit codes produces a noticable hang in `snap install` output that usually resolves itself after a few seconds to a minute depending on the machine. This could be related, not sure.