Comment 7 for bug 1897952

Revision history for this message
Paweł Stołowski (stolowski) wrote :

It seems we lost the opportunity to connect to these systems, anyway I think the attached logs are good enough:

Sep 30 17:57:04 ip-10-0-1-79 snapd[920]: daemon.go:343: started snapd/2.46.1+18.04 (series 16; classic) ubuntu/18.04 (amd64) linux/5.4.0-1025-aws.
Sep 30 17:57:04 ip-10-0-1-79 snapd[920]: daemon.go:436: adjusting startup timeout by 30s (pessimistic estimate of 30s plus 5s per snap)
Sep 30 17:57:06 ip-10-0-1-79 snapd[920]: helpers.go:105: error trying to compare the snap system key: system-key missing on disk
Sep 30 17:57:06 ip-10-0-1-79 systemd[1]: Started Snap Daemon.
Sep 30 17:57:06 ip-10-0-1-79 systemd[1]: Starting Wait until snapd is fully seeded...
Sep 30 17:57:13 ip-10-0-1-79 systemd-timesyncd[522]: Synchronized to time server 91.189.94.4:123 (ntp.ubuntu.com).
Sep 30 17:57:56 ip-10-0-1-79 snap[1214]: error: cannot communicate with server: timeout exceeded while waiting for response
Sep 30 17:57:56 ip-10-0-1-79 systemd[1]: snapd.seeded.service: Main process exited, code=exited, status=1/FAILURE

what I gather from this is snapd started on boot at 17:57:04 (started seeding), at 17:57:06 the snap.service.seeded job was started but failed after less than 1 minute at 17:57:56, despite using timeout of 2 minutes as Maciej said.

Now, I wonder if problem isn't related to time synchronization taking place in the middle of all this:
Sep 30 17:57:13 ip-10-0-1-79 systemd-timesyncd[522]: Synchronized to time server 91.189.94.4:123 (ntp.ubuntu.com).

This is during snap wait execution. In snap wait client code we set deadline time to "time.Now().Add(timeout))", so perhaps time gets skewed and we don't wait long enough.