snapd

snap install hangs if internet is disconnected exactly right after err upload starts

Bug #1855155 reported by Ian Johnson on 2019-12-04

This bug affects 1 person

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.futex(0x14b46e8, 0x80, 0x0, 0x0, 0xc000000000, 0x7ffc00000000, 0x436c63, 0xc00009e848, 0x7ffcd68e4e00, 0x40cb0f, ...)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/sys_linux_amd64.s:535 +0x21
Dec 04 11:10:16 snapd[3405]: runtime.futexsleep(0x14b46e8, 0x7ffc00000000, 0xffffffffffffffff)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/os_linux.go:44 +0x46
Dec 04 11:10:16 snapd[3405]: runtime.notesleep(0x14b46e8)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/lock_futex.go:151 +0x9f
Dec 04 11:10:16 snapd[3405]: runtime.stoplockedm()
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/proc.go:2068 +0x88
Dec 04 11:10:16 snapd[3405]: runtime.schedule()
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/proc.go:2469 +0x485
Dec 04 11:10:16 snapd[3405]: runtime.park_m(0xc0002b6180)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/proc.go:2610 +0x9d
Dec 04 11:10:16 snapd[3405]: runtime.mcall(0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/asm_amd64.s:318 +0x5b
Dec 04 11:10:16 snapd[3405]: goroutine 1 [select, 203 minutes]:
Dec 04 11:10:16 snapd[3405]: main.run(0xc0003b8000, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/cmd/snapd/main.go:153 +0x4d7
Dec 04 11:10:16 snapd[3405]: main.main()
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/cmd/snapd/main.go:64 +0x107
Dec 04 11:10:16 snapd[3405]: goroutine 19 [syscall, 203 minutes]:
Dec 04 11:10:16 snapd[3405]: os/signal.signal_recv(0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/sigqueue.go:147 +0x9c
Dec 04 11:10:16 snapd[3405]: os/signal.loop()
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/os/signal/signal_unix.go:23 +0x22
Dec 04 11:10:16 snapd[3405]: created by os/signal.init.0
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/os/signal/signal_unix.go:29 +0x41
Dec 04 11:10:16 snapd[3405]: goroutine 32 [IO wait, 203 minutes]:
Dec 04 11:10:16 snapd[3405]: internal/poll.runtime_pollWait(0x7f592c50df08, 0x72, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/netpoll.go:184 +0x55
Dec 04 11:10:16 snapd[3405]: internal/poll.(*pollDesc).wait(0xc000144398, 0x72, 0x0, 0x0, 0xd6c895)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_poll_runtime.go:87 +0x45
Dec 04 11:10:16 snapd[3405]: internal/poll.(*pollDesc).waitRead(...)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_poll_runtime.go:92
Dec 04 11:10:16 snapd[3405]: internal/poll.(*FD).Accept(0xc000144380, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_unix.go:384 +0x1f8
Dec 04 11:10:16 snapd[3405]: net.(*netFD).accept(0xc000144380, 0x0, 0x203000, 0x1600000000)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/fd_unix.go:238 +0x42
Dec 04 11:10:16 snapd[3405]: net.(*UnixListener).accept(0xc00033c6f0, 0x203000, 0xaa, 0x14ba098)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/unixsock_posix.go:162 +0x32
Dec 04 11:10:16 snapd[3405]: net.(*UnixListener).Accept(0xc00033c6f0, 0x30, 0x30, 0xcf6820, 0xc000673560)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/unixsock.go:260 +0x47
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/daemon.(*ucrednetListener).Accept(0xc00033c750, 0x0, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/daemon/ucrednet.go:108 +0x5b
Dec 04 11:10:16 snapd[3405]: net/http.(*Server).Serve(0xc00047a0e0, 0xf2a460, 0xc00033c750, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/server.go:2896 +0x286
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/daemon.(*Daemon).Start.func1.1(0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/daemon/daemon.go:462 +0x49
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc000034870, 0xc00033e000)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc7
Dec 04 11:10:16 snapd[3405]: goroutine 64 [select]:
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).Start.func1(0xc0003706e0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/overlord/standby/standby.go:91 +0x124
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).Start
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/overlord/standby/standby.go:84 +0x3f
Dec 04 11:10:16 snapd[3405]: goroutine 65 [select, 3 minutes]:
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/overlord.(*Overlord).Loop.func1(0x5300000000, 0x1f7)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/overlord/overlord.go:399 +0x11d
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc000370140, 0xc00032a050)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc7
Dec 04 11:10:16 snapd[3405]: goroutine 226 [IO wait]:
Dec 04 11:10:16 snapd[3405]: internal/poll.runtime_pollWait(0x7f592c50de38, 0x72, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/netpoll.go:184 +0x55
Dec 04 11:10:16 snapd[3405]: internal/poll.(*pollDesc).wait(0xc000144298, 0x72, 0x0, 0x0, 0xd6c895)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_poll_runtime.go:87 +0x45
Dec 04 11:10:16 snapd[3405]: internal/poll.(*pollDesc).waitRead(...)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_poll_runtime.go:92
Dec 04 11:10:16 snapd[3405]: internal/poll.(*FD).Accept(0xc000144280, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_unix.go:384 +0x1f8
Dec 04 11:10:16 snapd[3405]: net.(*netFD).accept(0xc000144280, 0xc0001a9cb8, 0x4102ae, 0xcc11a0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/fd_unix.go:238 +0x42
Dec 04 11:10:16 snapd[3405]: net.(*UnixListener).accept(0xc00033c6c0, 0x203000, 0xc0001a9cb8, 0x4305c1)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/unixsock_posix.go:162 +0x32
Dec 04 11:10:16 snapd[3405]: net.(*UnixListener).Accept(0xc00033c6c0, 0xc0001a9cf0, 0xc0001a9cc8, 0xc0001a9d30, 0xb90247)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/unixsock.go:260 +0x47
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/daemon.(*ucrednetListener).Accept(0xc00033c720, 0x0, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/daemon/ucrednet.go:108 +0x5b
Dec 04 11:10:16 snapd[3405]: net/http.(*Server).Serve(0xc00047a0e0, 0xf2a460, 0xc00033c720, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/server.go:2896 +0x286
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/daemon.(*Daemon).Start.func1(0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/daemon/daemon.go:470 +0x54
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc000034870, 0xc00032a060)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc7
Dec 04 11:10:16 snapd[3405]: goroutine 227 [select]:
Dec 04 11:10:16 snapd[3405]: main.runWatchdog.func1(0xc000370d70, 0xc000034820)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/cmd/snapd/main.go:93 +0xe3
Dec 04 11:10:16 snapd[3405]: created by main.runWatchdog
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/cmd/snapd/main.go:91 +0x1e0
Dec 04 11:10:16 snapd[3405]: goroutine 228 [syscall, 3 minutes]:
Dec 04 11:10:16 snapd[3405]: syscall.Syscall6(0x2d, 0x3, 0xc000b05000, 0x1000, 0x2, 0xc0001a8de0, 0xc0001a8dd4, 0xc0004dac30, 0xc000c70480, 0xc000c70480)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/syscall/asm_linux_amd64.s:44 +0x5
Dec 04 11:10:16 snapd[3405]: syscall.recvfrom(0x3, 0xc000b05000, 0x1000, 0x1000, 0x2, 0xc0001a8de0, 0xc0001a8dd4, 0x100000000000000, 0x0, 0x1000)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/syscall/zsyscall_linux_amd64.go:1618 +0xa3
Dec 04 11:10:16 snapd[3405]: syscall.Recvfrom(0x3, 0xc000b05000, 0x1000, 0x1000, 0x2, 0x51, 0xc0004dac30, 0xc0009aaf00, 0x2, 0xc000371110)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/syscall/syscall_unix.go:273 +0xaf
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).ReadMsg(0xc000297bc0, 0x407f1a, 0xc000038840, 0x0, 0xc0004dac00, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/osutil/udev/netlink/conn.go:65 +0xc2
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).ReadUEvent(0xc000297bc0, 0xc000038840, 0x0, 0xc000cc5ec0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/osutil/udev/netlink/conn.go:92 +0x2f
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).Monitor.func1(0xc000038840, 0xc000297bc0, 0xc000038720, 0xf30460, 0xc0000f50e0, 0xc0000386c0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/osutil/udev/netlink/conn.go:120 +0x6d
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).Monitor
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/osutil/udev/netlink/conn.go:114 +0xa7
Dec 04 11:10:16 snapd[3405]: goroutine 229 [select, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/overlord/ifacestate/udevmonitor.(*Monitor).Run.func1(0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/overlord/ifacestate/udevmonitor/udevmon.go:144 +0x327
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc0003cf170, 0xc0001c7700)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc7
Dec 04 11:10:16 snapd[3405]: goroutine 4422 [select, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: net/http.(*persistConn).roundTrip(0xc00093aa20, 0xc0007f5800, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:2425 +0x770
Dec 04 11:10:16 snapd[3405]: net/http.(*Transport).roundTrip(0x14a5920, 0xc0008bf700, 0xc000c21300, 0xc0002252f8, 0x20000000040e868)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:535 +0x9af
Dec 04 11:10:16 snapd[3405]: net/http.(*Transport).RoundTrip(0x14a5920, 0xc0008bf700, 0x14a5920, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/roundtrip.go:17 +0x35
Dec 04 11:10:16 snapd[3405]: net/http.send(0xc0008bf700, 0xf19400, 0x14a5920, 0x0, 0x0, 0x0, 0xc000611400, 0x203000, 0x1, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/client.go:250 +0x443
Dec 04 11:10:16 snapd[3405]: net/http.(*Client).send(0xc0007f56e0, 0xc0008bf700, 0x0, 0x0, 0x0, 0xc000611400, 0x0, 0x1, 0xc9ab60)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/client.go:174 +0xfa
Dec 04 11:10:16 snapd[3405]: net/http.(*Client).do(0xc0007f56e0, 0xc0008bf700, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/client.go:641 +0x3ce
Dec 04 11:10:16 snapd[3405]: net/http.(*Client).Do(...)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/client.go:509
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/errtracker.report(0xc00079a500, 0x243c, 0xc00079ca00, 0x23d9, 0xc000cf1410, 0x0, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/errtracker/errtracker.go:502 +0x1238
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/errtracker.Report(0xc0007b2183, 0x5, 0xc00079a500, 0x243c, 0xc00079ca00, 0x23d9, 0xc000cf1410, 0x0, 0x0, 0x0, ...)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/errtracker/errtracker.go:250 +0x286
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/overlord/snapstate.(*SnapManager).undoPrepareSnap(0xc0003ad4f0, 0xc0001338c0, 0xc0007dc550, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/overlord/snapstate/handlers.go:493 +0x124b
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/overlord/state.(*TaskRunner).run.func1(0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/overlord/state/taskrunner.go:195 +0xc8
Dec 04 11:10:16 snapd[3405]: github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc0007dc550, 0xc000837890)
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
Dec 04 11:10:16 snapd[3405]: created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
Dec 04 11:10:16 snapd[3405]: $GOPATH/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc7
Dec 04 11:10:16 snapd[3405]: goroutine 5037 [IO wait, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: internal/poll.runtime_pollWait(0x7f592c50d7b8, 0x72, 0xffffffffffffffff)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/runtime/netpoll.go:184 +0x55
Dec 04 11:10:16 snapd[3405]: internal/poll.(*pollDesc).wait(0xc000368d18, 0x72, 0xe00, 0xe7a, 0xffffffffffffffff)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_poll_runtime.go:87 +0x45
Dec 04 11:10:16 snapd[3405]: internal/poll.(*pollDesc).waitRead(...)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_poll_runtime.go:92
Dec 04 11:10:16 snapd[3405]: internal/poll.(*FD).Read(0xc000368d00, 0xc000a66000, 0xe7a, 0xe7a, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/internal/poll/fd_unix.go:169 +0x1cf
Dec 04 11:10:16 snapd[3405]: net.(*netFD).Read(0xc000368d00, 0xc000a66000, 0xe7a, 0xe7a, 0x203000, 0xc0000fb109, 0x76)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/fd_unix.go:202 +0x4f
Dec 04 11:10:16 snapd[3405]: net.(*conn).Read(0xc000972040, 0xc000a66000, 0xe7a, 0xe7a, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/net.go:184 +0x68
Dec 04 11:10:16 snapd[3405]: crypto/tls.(*atLeastReader).Read(0xc000b18560, 0xc000a66000, 0xe7a, 0xe7a, 0x2, 0x2, 0xc0000ae8a0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/crypto/tls/conn.go:780 +0x60
Dec 04 11:10:16 snapd[3405]: bytes.(*Buffer).ReadFrom(0xc0009d0cd8, 0xf17fc0, 0xc000b18560, 0x40bfd5, 0xc7e9e0, 0xd3d6a0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/bytes/buffer.go:204 +0xb4
Dec 04 11:10:16 snapd[3405]: crypto/tls.(*Conn).readFromUntil(0xc0009d0a80, 0xf19360, 0xc000972040, 0x5, 0xc000972040, 0x40e868)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/crypto/tls/conn.go:802 +0xec
Dec 04 11:10:16 snapd[3405]: crypto/tls.(*Conn).readRecordOrCCS(0xc0009d0a80, 0x0, 0x0, 0xc032ccfc0e)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/crypto/tls/conn.go:609 +0x124
Dec 04 11:10:16 snapd[3405]: crypto/tls.(*Conn).readRecord(...)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/crypto/tls/conn.go:577
Dec 04 11:10:16 snapd[3405]: crypto/tls.(*Conn).Read(0xc0009d0a80, 0xc000a67000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/crypto/tls/conn.go:1255 +0x161
Dec 04 11:10:16 snapd[3405]: net/http.(*persistConn).Read(0xc00093aa20, 0xc000a67000, 0x1000, 0x1000, 0x4069dd, 0x60, 0x0)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:1752 +0x75
Dec 04 11:10:16 snapd[3405]: bufio.(*Reader).fill(0xc000887a40)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/bufio/bufio.go:100 +0x103
Dec 04 11:10:16 snapd[3405]: bufio.(*Reader).Peek(0xc000887a40, 0x1, 0xc0003bd140, 0xc0004f7d20, 0xc000585c70, 0x419085, 0x14bab58)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/bufio/bufio.go:138 +0x4f
Dec 04 11:10:16 snapd[3405]: net/http.(*persistConn).readLoop(0xc00093aa20)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:1905 +0x1d6
Dec 04 11:10:16 snapd[3405]: created by net/http.(*Transport).dialConn
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:1574 +0xafe
Dec 04 11:10:16 snapd[3405]: goroutine 5038 [select, 4 minutes]:
Dec 04 11:10:16 snapd[3405]: net/http.(*persistConn).writeLoop(0xc00093aa20)
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:2204 +0x123
Dec 04 11:10:16 snapd[3405]: created by net/http.(*Transport).dialConn
Dec 04 11:10:16 snapd[3405]: /snap/go/4762/src/net/http/transport.go:1575 +0xb23
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.

Tags:

Revision history for this message

Ian Johnson (anonymouse67) wrote on 2019-12-04:

full-snapd.log Edit (36.8 KiB, text/plain)

Revision history for this message

Ian Johnson (anonymouse67) wrote on 2019-12-04:

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.

Revision history for this message

John Lenton (chipaca) wrote on 2019-12-05:

From a quick look at the logs I'd suspect

sha1sum: /var/lib/snapd/lib/gl/libGL.so.1: Permission denied

as the bit responsible for the hang & etc, especially if you've seen similar hangs from failing hooks.

I can't say I have seen that though.

Does changing your internet settings change GL settings? (wat)

Revision history for this message

Ian Johnson (anonymouse67) wrote on 2019-12-05:

It was expected that the install hook would fail, that's on purpose (from my testing of another bug).

Additionally, this command when it works does not hang:

```
$ time sha1sum /var/lib/snapd/lib/gl/libGL.so.1
f474a86f17c2c9b31ffd974e92dbcbeb4968863f /var/lib/snapd/lib/gl/libGL.so.1

real 0m0.003s
user 0m0.000s
sys 0m0.003s
```

and even if that is denied it still doesn't take long:

```
$ time sha1sum /var/lib/snapd/lib/gl/libGL.so.1
sha1sum: /var/lib/snapd/lib/gl/libGL.so.1: Permission denied

real 0m0.001s
user 0m0.001s
sys 0m0.000s
```

Ian Johnson (anonymouse67) on 2019-12-13

Changed in snapd:
importance:	Undecided → Low
tags:	added: papercut

Paweł Stołowski (stolowski) on 2019-12-17

Changed in snapd:
status:	New → Triaged

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

full-snapd.log Edit

Add attachment

Remote bug watches

Bug watches keep track of this bug in other bug trackers.