Score:0

What causes cpu overload and then server down after log of "Stopped, Starting Snap Daemon" in Ubuntu?

aq flag

I was running a spring web server in ubuntu on aws ec2. The server unexpectedly encountered a status check error during off-duty hours and forced a restart.

From the monitoring tool, it seems that the server did not work normally after a few minutes after the CPU increased rapidly.

After the forced restart, it worked normally, and when I checked the system log, it was as follows.

Oct  6 17:48:49 ip-12-0-10-30 systemd[1]: Starting Daily apt download activities...
Oct  6 17:48:54 ip-12-0-10-30 dbus-daemon[531]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.327' (uid=0 pid=98303 comm="/usr/bin/gdbus call --system --dest org.freedeskto" label="unconfined")
Oct  6 17:48:54 ip-12-0-10-30 PackageKit: daemon start
Oct  6 17:48:54 ip-12-0-10-30 systemd[1]: Starting PackageKit Daemon...
Oct  6 17:48:54 ip-12-0-10-30 dbus-daemon[531]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Oct  6 17:48:54 ip-12-0-10-30 systemd[1]: Started PackageKit Daemon.
Oct  6 17:54:00 ip-12-0-10-30 PackageKit: daemon quit
Oct  6 17:54:00 ip-12-0-10-30 systemd[1]: packagekit.service: Succeeded.
Oct  6 18:17:03 ip-12-0-10-30 CRON[98618]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct  6 18:29:05 ip-12-0-10-30 systemd[1]: snapd.service: Watchdog timeout (limit 5min)!
Oct  6 18:29:05 ip-12-0-10-30 systemd[1]: snapd.service: Killing process 62550 (snapd) with signal SIGABRT.
Oct  6 18:29:10 ip-12-0-10-30 snapd[62550]: SIGABRT: abort
Oct  6 18:29:10 ip-12-0-10-30 snapd[62550]: PC=0x55568c42a791 m=0 sigcode=0
Oct  6 18:29:10 ip-12-0-10-30 snapd[62550]: goroutine 0 [idle]:
Oct  6 18:29:11 ip-12-0-10-30 snapd[62550]: runtime.futex(0x55568def64e8, 0x80, 0x0, 0x0, 0xc000000000, 0x7ffc63c1fd50, 0x55568c3fe065, 0xc000055648, 0x7ffc63c1fd70, 0x55568c3d3b83, ...)
Oct  6 18:29:11 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/sys_linux_amd64.s:535 +0x21
Oct  6 18:29:11 ip-12-0-10-30 snapd[62550]: runtime.futexsleep(0x55568def64e8, 0x7ffc00000000, 0xffffffffffffffff)
Oct  6 18:29:11 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/os_linux.go:44 +0x46
Oct  6 18:29:11 ip-12-0-10-30 snapd[62550]: runtime.notesleep(0x55568def64e8)
Oct  6 18:29:11 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/lock_futex.go:151 +0xa3
Oct  6 18:29:12 ip-12-0-10-30 snapd[62550]: runtime.stoplockedm()
Oct  6 18:29:12 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/proc.go:2068 +0x8c
Oct  6 18:29:13 ip-12-0-10-30 snapd[62550]: runtime.schedule()
Oct  6 18:29:13 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/proc.go:2469 +0x489
Oct  6 18:29:13 ip-12-0-10-30 snapd[62550]: runtime.park_m(0xc000302d80)
Oct  6 18:29:13 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/proc.go:2610 +0xa3
Oct  6 18:29:14 ip-12-0-10-30 snapd[62550]: runtime.mcall(0x0)
Oct  6 18:29:14 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/asm_amd64.s:318 +0x53
Oct  6 18:29:15 ip-12-0-10-30 snapd[62550]: goroutine 1 [select, 13464 minutes]:
Oct  6 18:29:15 ip-12-0-10-30 snapd[62550]: main.run(0xc00033c6c0, 0x0, 0x0)
Oct  6 18:29:16 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/cmd/snapd/main.go:153 +0x4e5
Oct  6 18:29:17 ip-12-0-10-30 snapd[62550]: main.main()
Oct  6 18:29:17 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/cmd/snapd/main.go:64 +0x10e
Oct  6 18:29:18 ip-12-0-10-30 snapd[62550]: goroutine 19 [syscall, 13464 minutes]:
Oct  6 18:29:19 ip-12-0-10-30 snapd[62550]: os/signal.signal_recv(0x0)
Oct  6 18:29:19 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/sigqueue.go:147 +0x9e
Oct  6 18:29:20 ip-12-0-10-30 snapd[62550]: os/signal.loop()
Oct  6 18:29:20 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/os/signal/signal_unix.go:23 +0x24
Oct  6 18:29:20 ip-12-0-10-30 snapd[62550]: created by os/signal.init.0
Oct  6 18:29:20 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/os/signal/signal_unix.go:29 +0x43
Oct  6 18:29:21 ip-12-0-10-30 snapd[62550]: goroutine 40 [semacquire]:
Oct  6 18:29:21 ip-12-0-10-30 snapd[62550]: sync.runtime_SemacquireMutex(0xc0000ea074, 0x55568c3d1e01, 0x1)
Oct  6 18:29:22 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/sema.go:71 +0x49
Oct  6 18:29:22 ip-12-0-10-30 snapd[62550]: sync.(*Mutex).lockSlow(0xc0000ea070)
Oct  6 18:29:22 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/sync/mutex.go:138 +0xfe
Oct  6 18:29:22 ip-12-0-10-30 snapd[62550]: sync.(*Mutex).Lock(...)
Oct  6 18:29:22 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/sync/mutex.go:81
Oct  6 18:29:23 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/state.(*State).Lock(0xc0000ea070)
Oct  6 18:29:23 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/state/state.go:122 +0x4e
Oct  6 18:29:23 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/snapstate.(*SnapManager).localInstallCleanup(0xc0002ce9c0, 0x0, 0x0)
Oct  6 18:29:24 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/snapstate/snapmgr.go:1027 +0x53
Oct  6 18:29:24 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/snapstate.(*SnapManager).Ensure(0xc0002ce9c0, 0x0, 0x0)
Oct  6 18:29:24 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/snapstate/snapmgr.go:1087 +0x192
Oct  6 18:29:24 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord.(*StateEngine).Ensure(0xc000444e10, 0x0, 0x0)
Oct  6 18:29:25 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/stateengine.go:147 +0x11e
Oct  6 18:29:25 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord.(*Overlord).Loop.func1(0x55568c3cda75, 0xc00052dc80)
Oct  6 18:29:25 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/overlord.go:454 +0x64
Oct  6 18:29:25 ip-12-0-10-30 snapd[62550]: gopkg.in/tomb%2ev2.(*Tomb).run(0xc0000b6550, 0xc0006f8e80)
Oct  6 18:29:25 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Oct  6 18:29:26 ip-12-0-10-30 snapd[62550]: created by gopkg.in/tomb%2ev2.(*Tomb).Go
Oct  6 18:29:26 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc9
Oct  6 18:29:26 ip-12-0-10-30 snapd[62550]: goroutine 42 [runnable]:
Oct  6 18:29:26 ip-12-0-10-30 snapd[62550]: net.(*sysDialer).dialUnix(0xc000064dd0, 0x55568d7b3e80, 0xc0000ac058, 0x0, 0xc000568160, 0xc000568160, 0x7f58bc0031f1, 0xc000064d08)
Oct  6 18:29:27 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock_posix.go:153 +0x137
Oct  6 18:29:27 ip-12-0-10-30 snapd[62550]: net.DialUnix(0x55568ce66870, 0x8, 0x0, 0xc000568160, 0x0, 0x0, 0x0)
Oct  6 18:29:27 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock.go:210 +0x106
Oct  6 18:29:27 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/systemd.SdNotify(0x55568ce687d7, 0xa, 0x0, 0x0)
Oct  6 18:29:28 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/systemd/sdnotify.go:51 +0x136
Oct  6 18:29:28 ip-12-0-10-30 snapd[62550]: main.runWatchdog.func1(0xc0000b65f0, 0xc00001e000)
Oct  6 18:29:28 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/cmd/snapd/main.go:98 +0x4c
Oct  6 18:29:28 ip-12-0-10-30 snapd[62550]: created by main.runWatchdog
Oct  6 18:29:29 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/cmd/snapd/main.go:91 +0x1e2
Oct  6 18:29:29 ip-12-0-10-30 snapd[62550]: goroutine 43 [IO wait, 13464 minutes]:
Oct  6 18:29:29 ip-12-0-10-30 snapd[62550]: internal/poll.runtime_pollWait(0x7f58bc20ff08, 0x72, 0x0)
Oct  6 18:29:29 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/netpoll.go:184 +0x57
Oct  6 18:29:30 ip-12-0-10-30 snapd[62550]: internal/poll.(*pollDesc).wait(0xc0000f9618, 0x72, 0x0, 0x0, 0x55568ce64611)
Oct  6 18:29:30 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_poll_runtime.go:87 +0x47
Oct  6 18:29:30 ip-12-0-10-30 snapd[62550]: internal/poll.(*pollDesc).waitRead(...)
Oct  6 18:29:30 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_poll_runtime.go:92
Oct  6 18:29:31 ip-12-0-10-30 snapd[62550]: internal/poll.(*FD).Accept(0xc0000f9600, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Oct  6 18:29:31 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_unix.go:384 +0x1fa
Oct  6 18:29:32 ip-12-0-10-30 snapd[62550]: net.(*netFD).accept(0xc0000f9600, 0x203000, 0x0, 0x0)
Oct  6 18:29:32 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/fd_unix.go:238 +0x44
Oct  6 18:29:33 ip-12-0-10-30 snapd[62550]: net.(*UnixListener).accept(0xc000456120, 0xc000466090, 0x30, 0x30)
Oct  6 18:29:33 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock_posix.go:162 +0x34
Oct  6 18:29:33 ip-12-0-10-30 snapd[62550]: net.(*UnixListener).Accept(0xc000456120, 0xc000466090, 0x55568d7723f0, 0xc000307d28, 0xc000171c00)
Oct  6 18:29:33 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock.go:260 +0x49
Oct  6 18:29:33 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/daemon.(*ucrednetListener).Accept(0xc000456180, 0x55568d6d5440, 0xc000466090, 0x55568d605dc0, 0x55568de93030)
Oct  6 18:29:34 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/daemon/ucrednet.go:112 +0x4a
Oct  6 18:29:34 ip-12-0-10-30 snapd[62550]: net/http.(*Server).Serve(0xc00027c000, 0x55568d7ad480, 0xc000456180, 0x0, 0x0)
Oct  6 18:29:34 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/http/server.go:2896 +0x282
Oct  6 18:29:34 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/daemon.(*Daemon).Start.func1.1(0x0, 0x0)
Oct  6 18:29:34 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/daemon/daemon.go:370 +0x4b
Oct  6 18:29:35 ip-12-0-10-30 snapd[62550]: gopkg.in/tomb%2ev2.(*Tomb).run(0xc00001e050, 0xc000464b00)
Oct  6 18:29:35 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Oct  6 18:29:36 ip-12-0-10-30 snapd[62550]: created by gopkg.in/tomb%2ev2.(*Tomb).Go
Oct  6 18:29:36 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc9
Oct  6 18:29:36 ip-12-0-10-30 snapd[62550]: goroutine 48 [syscall, 13464 minutes]:
Oct  6 18:29:37 ip-12-0-10-30 snapd[62550]: syscall.Syscall6(0x17, 0xa, 0xc00030b628, 0x0, 0x0, 0x0, 0x0, 0xc000302300, 0x200000003, 0xc000302300)
Oct  6 18:29:37 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/syscall/asm_linux_amd64.s:44 +0x5
Oct  6 18:29:37 ip-12-0-10-30 snapd[62550]: syscall.Select(0xa, 0xc00030b628, 0x0, 0x0, 0x0, 0x55568c3f78f3, 0x55568d771910, 0xc00030b648)
Oct  6 18:29:37 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/syscall/zsyscall_linux_amd64.go:1320 +0xa2
Oct  6 18:29:38 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/osutil/udev/netlink.stopperSelectReadable(0x4, 0x9, 0x0, 0xc00030b758, 0x55568c3cdf3d)
Oct  6 18:29:38 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/osutil/udev/netlink/rawsockstop.go:57 +0x16c
Oct  6 18:29:38 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/osutil/udev/netlink.RawSockStopper.func1(0x0, 0x0, 0xc00030b790)
Oct  6 18:29:38 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/osutil/udev/netlink/rawsockstop.go:31 +0x4e
Oct  6 18:29:39 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).Monitor.func4(0xc0003cc280, 0xc000264c60, 0xc000264cc0, 0xc000264d20, 0xc0003d9300, 0x55568d7b6780, 0xc0003cc260, 0xc000264c00)
Oct  6 18:29:39 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/osutil/udev/netlink/conn.go:139 +0x46
Oct  6 18:29:39 ip-12-0-10-30 snapd[62550]: created by github.com/snapcore/snapd/osutil/udev/netlink.(*UEventConn).Monitor
Oct  6 18:29:39 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/osutil/udev/netlink/conn.go:136 +0x247
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: goroutine 41 [IO wait, 13464 minutes]:
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: internal/poll.runtime_pollWait(0x7f58bc20fe38, 0x72, 0x0)
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/netpoll.go:184 +0x57
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: internal/poll.(*pollDesc).wait(0xc0000f9518, 0x72, 0x0, 0x0, 0x55568ce64611)
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_poll_runtime.go:87 +0x47
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: internal/poll.(*pollDesc).waitRead(...)
Oct  6 18:29:40 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_poll_runtime.go:92
Oct  6 18:29:41 ip-12-0-10-30 snapd[62550]: internal/poll.(*FD).Accept(0xc0000f9500, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
Oct  6 18:29:41 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_unix.go:384 +0x1fa
Oct  6 18:29:41 ip-12-0-10-30 snapd[62550]: net.(*netFD).accept(0xc0000f9500, 0x7f58bc1cddf8, 0x0, 0x30)
Oct  6 18:29:41 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/fd_unix.go:238 +0x44
Oct  6 18:29:42 ip-12-0-10-30 snapd[62550]: net.(*UnixListener).accept(0xc0004560f0, 0xc000466000, 0x30, 0x30)
Oct  6 18:29:42 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock_posix.go:162 +0x34
Oct  6 18:29:42 ip-12-0-10-30 snapd[62550]: net.(*UnixListener).Accept(0xc0004560f0, 0xc000466000, 0x55568d7723f0, 0xc000193d28, 0xc000171c00)
Oct  6 18:29:43 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock.go:260 +0x49
Oct  6 18:29:43 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/daemon.(*ucrednetListener).Accept(0xc000456150, 0x55568d6d5440, 0xc000466000, 0x55568d605dc0, 0x55568de93030)
Oct  6 18:29:43 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/daemon/ucrednet.go:112 +0x4a
Oct  6 18:29:43 ip-12-0-10-30 snapd[62550]: net/http.(*Server).Serve(0xc00027c000, 0x55568d7ad480, 0xc000456150, 0x0, 0x0)
Oct  6 18:29:44 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/http/server.go:2896 +0x282
Oct  6 18:29:44 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/daemon.(*Daemon).Start.func1(0x55568c3cda75, 0xc00052dc80)
Oct  6 18:29:45 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/daemon/daemon.go:378 +0x56
Oct  6 18:29:45 ip-12-0-10-30 snapd[62550]: gopkg.in/tomb%2ev2.(*Tomb).run(0xc00001e050, 0xc000464af0)
Oct  6 18:29:46 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Oct  6 18:29:46 ip-12-0-10-30 snapd[62550]: created by gopkg.in/tomb%2ev2.(*Tomb).Go
Oct  6 18:29:47 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc9
Oct  6 18:29:47 ip-12-0-10-30 snapd[62550]: goroutine 39 [runnable]:
Oct  6 18:29:48 ip-12-0-10-30 snapd[62550]: encoding/json.(*scanner).pushParseState(...)
Oct  6 18:29:49 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/encoding/json/scanner.go:144
Oct  6 18:29:50 ip-12-0-10-30 snapd[62550]: encoding/json.stateBeginValue(0xc00001c028, 0x55568d6fa37b, 0x55568ce62201)
Oct  6 18:29:51 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/encoding/json/scanner.go:183 +0x4f4
Oct  6 18:29:52 ip-12-0-10-30 snapd[62550]: encoding/json.checkValid(0xc000225000, 0xac1, 0xc00, 0xc00001c028, 0xc0000864b8, 0x8)
Oct  6 18:29:52 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/encoding/json/scanner.go:29 +0xa9
Oct  6 18:29:53 ip-12-0-10-30 snapd[62550]: encoding/json.Unmarshal(0xc000225000, 0xac1, 0xc00, 0x55568d591d40, 0xc0000ae048, 0x55568c8ebd2c, 0x55568d5f3de0)
Oct  6 18:29:53 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/encoding/json/decode.go:100 +0x68
Oct  6 18:29:54 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/state.customData.get(0xc000096ed0, 0x55568ce622e6, 0x5, 0x55568d591d40, 0xc0000ae048, 0xc000190e20, 0xc000190e60)
Oct  6 18:29:54 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/state/state.go:51 +0xa0
Oct  6 18:29:54 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/state.(*State).Get(...)
Oct  6 18:29:54 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/state/state.go:271
Oct  6 18:30:35 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/snapstate.NumSnaps(0xc0000ea070, 0x0, 0xc000190ec8, 0xc000464ab0)
Oct  6 18:31:31 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/snapstate/snapstate.go:3445 +0x82
Oct  6 18:31:32 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/snapstate.(*SnapManager).CanStandby(0xc0002ce9c0, 0x55568df12201)
Oct  6 18:31:33 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/snapstate/snapmgr.go:569 +0x30
Oct  6 18:32:09 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).CanStandby(0xc0000b6460, 0x4a817c8000)
Oct  6 18:32:19 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/standby/standby.go:69 +0x254
Oct  6 18:32:20 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).Start.func1(0xc0000b6460)
Oct  6 18:32:20 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/standby/standby.go:100 +0xab
Oct  6 18:32:20 ip-12-0-10-30 snapd[62550]: created by github.com/snapcore/snapd/overlord/standby.(*StandbyOpinions).Start
Oct  6 18:32:21 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/standby/standby.go:96 +0xaa
Oct  6 18:32:21 ip-12-0-10-30 snapd[62550]: goroutine 33 [IO wait, 13464 minutes]:
Oct  6 18:32:22 ip-12-0-10-30 snapd[62550]: internal/poll.runtime_pollWait(0x7f58bc20fd68, 0x72, 0x1000)
Oct  6 18:32:23 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/runtime/netpoll.go:184 +0x57
Oct  6 18:32:24 ip-12-0-10-30 snapd[62550]: internal/poll.(*pollDesc).wait(0xc0000f8218, 0x72, 0x0, 0x10, 0xc000162c20)
Oct  6 18:32:25 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_poll_runtime.go:87 +0x47
Oct  6 18:32:25 ip-12-0-10-30 systemd[1]: snapd.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Oct  6 18:32:26 ip-12-0-10-30 snapd[62550]: internal/poll.(*pollDesc).waitRead(...)
Oct  6 18:32:27 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_poll_runtime.go:92
Oct  6 18:32:27 ip-12-0-10-30 snapd[62550]: internal/poll.(*FD).ReadMsg(0xc0000f8200, 0xc00077eb50, 0x10, 0x10, 0xc000162c20, 0x1000, 0x1000, 0x0, 0x0, 0x0, ...)
Oct  6 18:32:28 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/internal/poll/fd_unix.go:243 +0x230
Oct  6 18:32:29 ip-12-0-10-30 snapd[62550]: net.(*netFD).readMsg(0xc0000f8200, 0xc00077eb50, 0x10, 0x10, 0xc000162c20, 0x1000, 0x1000, 0xc000147d50, 0x55568deb95d6, 0x1, ...)
Oct  6 18:32:29 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/fd_unix.go:214 +0x92
Oct  6 18:32:30 ip-12-0-10-30 snapd[62550]: net.(*UnixConn).readMsg(0xc00048ca18, 0xc00077eb50, 0x10, 0x10, 0xc000162c20, 0x1000, 0x1000, 0xc00077ea20, 0xc00077ea1c, 0xc000212660, ...)
Oct  6 18:32:31 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock_posix.go:115 +0x93
Oct  6 18:32:31 ip-12-0-10-30 snapd[62550]: net.(*UnixConn).ReadMsgUnix(0xc00048ca18, 0xc00077eb50, 0x10, 0x10, 0xc000162c20, 0x1000, 0x1000, 0xc000212a60, 0x20, 0x18, ...)
Oct  6 18:32:31 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/net/unixsock.go:143 +0x9a
Oct  6 18:32:32 ip-12-0-10-30 snapd[62550]: github.com/godbus/dbus.(*oobReader).Read(0xc000162c00, 0xc00077eb50, 0x10, 0x10, 0xc000147df0, 0x55568c3d590a, 0x20)
Oct  6 18:32:32 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/github.com/godbus/dbus/transport_unix.go:21 +0x8f
Oct  6 18:32:33 ip-12-0-10-30 snapd[62550]: io.ReadAtLeast(0x55568d793220, 0xc000162c00, 0xc00077eb50, 0x10, 0x10, 0x10, 0xc000200090, 0x0, 0x0)
Oct  6 18:32:33 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/io/io.go:310 +0x89
Oct  6 18:32:42 ip-12-0-10-30 snapd[62550]: io.ReadFull(...)
Oct  6 18:32:42 ip-12-0-10-30 snapd[62550]: #011/usr/lib/go-1.13/src/io/io.go:329
Oct  6 18:32:42 ip-12-0-10-30 snapd[62550]: github.com/godbus/dbus.(*unixTransport).ReadMessage(0xc00047a800, 0xc000000002, 0x2, 0xc00014f401)
Oct  6 18:32:43 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/github.com/godbus/dbus/transport_unix.go:91 +0x11a
Oct  6 18:32:43 ip-12-0-10-30 snapd[62550]: github.com/godbus/dbus.(*Conn).inWorker(0xc0003d01b0)
Oct  6 18:32:43 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/github.com/godbus/dbus/conn.go:294 +0x42
Oct  6 18:32:44 ip-12-0-10-30 snapd[62550]: created by github.com/godbus/dbus.(*Conn).Auth
Oct  6 18:32:44 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/github.com/godbus/dbus/auth.go:118 +0x623
Oct  6 18:32:44 ip-12-0-10-30 snapd[62550]: goroutine 49 [select, 13465 minutes]:
Oct  6 18:32:45 ip-12-0-10-30 snapd[62550]: github.com/snapcore/snapd/overlord/ifacestate/udevmonitor.(*Monitor).Run.func1(0xc00004cfc8, 0x55568c85dad2)
Oct  6 18:32:45 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/overlord/ifacestate/udevmonitor/udevmon.go:147 +0x329
Oct  6 18:32:45 ip-12-0-10-30 snapd[62550]: gopkg.in/tomb%2ev2.(*Tomb).run(0xc000152c60, 0xc000076b40)
Oct  6 18:32:46 ip-12-0-10-30 systemd[1]: snapd.service: Failed with result 'watchdog'.
Oct  6 18:32:46 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2d
Oct  6 18:32:47 ip-12-0-10-30 snapd[62550]: created by gopkg.in/tomb%2ev2.(*Tomb).Go
Oct  6 18:32:47 ip-12-0-10-30 snapd[62550]: #011/build/snapd/parts/snapd-deb/build/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc9
Oct  6 18:32:48 ip-12-0-10-30 snapd[62550]: rax    0xca
Oct  6 18:32:49 ip-12-0-10-30 snapd[62550]: rbx    0x55568def63a0
Oct  6 18:32:49 ip-12-0-10-30 snapd[62550]: rcx    0x55568c42a793
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rdx    0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rdi    0x55568def64e8
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rsi    0x80
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rbp    0x7ffc63c1fd38
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rsp    0x7ffc63c1fcf0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r8     0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r9     0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r10    0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r11    0x286
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r12    0xff
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r13    0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r14    0x55568d089af2
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: r15    0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rip    0x55568c42a791
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: rflags 0x286
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: cs     0x33
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: fs     0x0
Oct  6 18:32:50 ip-12-0-10-30 snapd[62550]: gs     0x0
Oct  6 18:32:50 ip-12-0-10-30 systemd[1]: snapd.service: Scheduled restart job, restart counter is at 3.
Oct  6 18:32:51 ip-12-0-10-30 snapd[98728]: AppArmor status: apparmor is enabled and all features are available
Oct  6 18:32:51 ip-12-0-10-30 systemd[1]: Stopped Snap Daemon.
Oct  6 18:32:52 ip-12-0-10-30 systemd[1]: Starting Snap Daemon...
Oct  6 18:32:52 ip-12-0-10-30 systemd[1]: snapd.service: start operation timed out. Terminating.
Oct  6 18:32:53 ip-12-0-10-30 systemd[1]: snapd.service: Failed with result 'timeout'.

skip

Oct  6 19:01:27 ip-12-0-10-30 systemd[1]: Stopped Snap Daemon.
Oct  6 19:02:54 ip-12-0-10-30 systemd[1]: Starting Snap Daemon...
Oct  6 19:05:14 ip-12-0-10-30 systemd[1]: snapd.service: start operation timed out. Terminating.
Oct  6 19:07:10 ip-12-0-10-30 systemd[1]: snapd.service: Failed with result 'timeout'.
Oct  6 19:08:57 ip-12-0-10-30 systemd[1]: Failed to start Snap Daemon.
Oct  6 19:14:41 ip-12-0-10-30 systemd[1]: snapd.service: Scheduled restart job, restart counter is at 20.
Oct  6 19:16:14 ip-12-0-10-30 systemd[1]: Stopped Snap Daemon.
Oct  6 19:18:46 ip-12-0-10-30 systemd[1]: Starting Snap Daemon...
Oct  6 19:22:44 ip-12-0-10-30 CRON[99169]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct  6 19:31:10 ip-12-0-10-30 systemd-networkd[425]: ens5: Could not set DHCPv4 address: Connection timed out
Oct  6 19:33:19 ip-12-0-10-30 systemd-networkd[425]: ens5: Failed
Oct  6 20:41:15 ip-12-0-10-30 CRON[99214]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct  6 20:50:55 ip-12-0-10-30 systemd-timesyncd[352]: Network configuration changed, trying to establish connection.

enter image description here

The graph above shows a sharp increase in cpu.

At 17:40, the cpu usage increased, and from 17:44, it increased sharply. It peaked at 93% usage at 17:55 and the CPU usage dropped at 18:55.

The status check failed from 20:25, and the server went down around 20:30.

My guess is snapd.service: Watchdog timeout (limit 5min)! It seems that snapd started and stopped after that.

What is the cause of this and what can be done to prevent it?

in flag
Which EC2 instance is being used and in what region is it running? Reason I ask is because there are some instance types in some regions that have awful I/O performance, which can result in failures such as this. Those charts and graphs in the dashboard consistently show no I/O problem ... because there is no I/O for the instance to use. I've encountered this a number of times in `us-east` and `eu-central` on t1.micro, t1.small, t2.micro, t2.small, t2.medium, and t3.small servers. The solution was to move the server to a different location or upgrade to a more expensive instance type.
Drew avatar
cn flag
I'm running into this issue. Did you find a solution?
Joker avatar
aq flag
@ matigo/ I also saw the solution mentioned by matigo for this problem. It is not in the us-east and eu-central region, but the instance is using a lower specification. However, in the case of some instances, it is continuously being used well, but only certain instances are experiencing errors. I'm not sure if this is a real solution.
Filo avatar
ao flag
I encountered the same problem. My instance is also low-spec (t2.micro with 1GB of memory), so I believe Rohjay's solution is effective. However, in the end, I decided to completely stop Ubuntu's daily tasks to avoid this problem altogether. Please refer to the link below for instructions on how to disable these tasks: https://superuser.com/questions/1327884/how-to-disable-daily-upgrade-and-clean-on-ubuntu-16-04
Score:1
sx flag

I was running into this issue as well. I did a few things, but I think the biggest effect was changing the threshold of "swappiness", since I have a pretty small VM that I'm running on.

Link to thread I used

Effectively, edit the /etc/sysctl.conf file and update/add the line vm.swappiness=10 to whatever threshold you want. I changed mine from like 60 to 10 (in other words: only leverage swap at when available mem is less than or equal to 10%). That pepped a bunch of stuff up.

Reboot and the effects should take place.

Joker avatar
aq flag
Now, since the error hasn't occurred since rebooting, I can't confirm if this is the solution. But thanks for the nice answer.
Rohjay avatar
sx flag
No problem, man! Keep us posted if that seemed to do the trick for you. Cheers!
mangohost

Post an answer

Most people don’t grasp that asking a lot of questions unlocks learning and improves interpersonal bonding. In Alison’s studies, for example, though people could accurately recall how many questions had been asked in their conversations, they didn’t intuit the link between questions and liking. Across four studies, in which participants were engaged in conversations themselves or read transcripts of others’ conversations, people tended not to realize that question asking would influence—or had influenced—the level of amity between the conversationalists.