Snap is updating off schedule

let · February 4, 2020, 4:49pm

I set the snap update schedule to every day between 9 and 10 PM using

sudo snap set system refresh.timer=21:00-22:00

I’ve checked it and found it is also updating in the morning between 8:45 AM and 9:15 AM.

$ snap refresh --time
timer: 21:00-22:00
last: today at 09:12 EST
next: today at 21:00 EST

The timer says the period I set but the history says it updated in the AM.

Why is snap updating off schedule?

$ snap --version
snap 2.42.5
snapd 2.42.5
series 16
ubuntu 18.04
kernel 4.15.0-1067-oem

Thank you

ijohnson · February 4, 2020, 5:36pm

Hi,

What’s the output of snap changes for you?

let · February 4, 2020, 6:27pm

$ snap changes
ID Status Spawn Ready Summary
42 Done 2 days ago, at 15:14 EST 2 days ago, at 15:14 EST Change configuration of “core” snap

popey · February 4, 2020, 7:50pm

What’s the output from:

$ sudo snap get system refresh.timer

let · February 4, 2020, 9:05pm

$ sudo snap get system refresh.timer
[sudo] password for luke:
21:00-22:00

mborzecki · February 5, 2020, 12:45pm

Have you observed this to happen repeatedly?

I’d would be great if you could collect some logs to help identify the source of this problem. Unfortunately the next planned refresh time is only logged when debug level logging is enabled. You can enable it executing the following commands as root:

$ mkdir /etc/systemd/system/snapd.service.d
$ cat <<'EOF' > /etc/systemd/system/snapd.service.d/override.conf
[Service]
Environment=SNAPD_DEBUG=1
EOF
$ systemctl daemon-reload
$ systemctl restart snapd.service

Messages like those below will start to be logged:

$ journalctl -u snapd.service |grep autorefresh.go
Feb 05 07:15:30 galeon snapd[56845]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-05T07:15:30+01:00.
Feb 05 07:22:37 galeon snapd[57248]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-05T12:47:03+01:00.
Feb 05 12:52:07 galeon snapd[57248]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 05 12:57:02 galeon snapd[57248]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-05T23:41:35+01:00.

let · February 5, 2020, 5:15pm

Either Saturday or Sunday I changed the update schedule and I saw it Monday and Tuesday, today’s a little different.

$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 06:16 EST
next: yesterday at 21:00 EST

I was able to create the directory but got a permission denided ion the next command

$ sudo cat <<‘EOF’ > /etc/systemd/system/snapd.service.d/override.conf

[Service]
Environment=SNAPD_DEBUG=1
EOF
bash: /etc/systemd/system/snapd.service.d/override.conf: Permission denied

ogra · February 5, 2020, 5:58pm

that should be rather:

$ cat << EOF | sudo tee /etc/systemd/system/snapd.service.d/override.conf
[Service]
Environment=SNAPD_DEBUG=1
EOF
$

let · February 5, 2020, 6:19pm

That worked

The last two lines show it is in debug mode

Feb 05 12:22:39 Books snapd[992]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 05 13:16:18 Books snapd[22552]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-05T21:00:00-05:00.

So let it run for day?

Thanks

let · February 9, 2020, 2:53pm

Thursday 3:22 PM
$ snap refresh --time
timer: 21:00-22:00
last: today at 09:49 EST
next: today at 21:00 EST

Friday 9:33 PM
$ snap refresh --time
timer: 21:00-22:00
last: today at 10:33 EST
next: today at 21:00 EST

Saturday 9:39 AM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 10:33 EST
next: yesterday at 21:00 EST

Saturday 6:10 PM
$ snap refresh --time
timer: 21:00-22:00
last: today at 11:03 EST
next: today at 21:00 EST

Sunday 7:04 AM
$ snap refresh --time
timer: 21:00-22:00
last: today at 06:25 EST
next: today at 21:00 EST

$ journalctl -u snapd.service |grep autorefresh.go | tail -n 10
Feb 05 12:22:39 Books snapd[992]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 05 13:16:18 Books snapd[22552]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-05T21:00:00-05:00.
Feb 06 09:54:28 Books snapd[22552]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-06T21:00:00-05:00.
Feb 07 10:33:01 Books snapd[22552]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 07 11:14:35 Books snapd[22552]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-07T21:00:00-05:00.
Feb 08 11:03:54 Books snapd[22552]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 08 11:08:51 Books snapd[22552]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-08T21:00:00-05:00.
Feb 08 18:30:26 Books snapd[1004]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-08T21:00:00-05:00.
Feb 09 06:25:12 Books snapd[1004]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 09 06:30:09 Books snapd[1004]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-09T21:00:00-05:00.

mborzecki · February 10, 2020, 12:16pm

Thanks for the logs. I’ll investigate this in more details now.

let · February 18, 2020, 3:02pm

Here’s the latest data starting just after the last post.
Monday 6:27 AM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 06:25 EST
next: yesterday at 21:00 EST

Monday 3:02 PM
$ snap refresh --time
timer: 21:00-22:00
last: today at 11:33 EST
next: today at 21:00 EST

Tuesday 9:29 AM
$ snap refresh --time
timer: 21:00-22:00
last: today at 08:48
next: today at 21:00 EST

Wednesday 11:01 AM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 21:22 EST
next: today at 21:00 EST

Thursday 5:33 AM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 23:54 EST
next: today at 21:00 EST

Thursday 3:37 PM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 23:54 EST
next: today at 21:00 EST

Friday 6:43 AM
$ snap refresh --time
timer: 21:00-22:00
last: 2 days ago, at 23:54 EST
next: yesterday at 21:00 EST

Friday 5:56 PM
$ snap refresh --time
timer: 21:00-22:00
last: today at 16:37 EST
next: today at 21:00 EST

Sunday 7:54 AM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 06:04 EST
next: yesterday at 21:00 EST

Monday 7:43 AM
$ snap refresh --time
timer: 21:00-22:00
last: yesterday at 11:57 EST
next: yesterday at 21:00 EST

Monday 4:28 PM
$ snap refresh --time
timer: 21:00-22:00
last: today at 16:08 EST
next: today at 21:00 EST

Tuesday 9:58 AM
$ snap refresh --time
timer: 21:00-22:00
last: today at 07:17 EST
next: today at 21:00 EST

$ journalctl -u snapd.service |grep autorefresh.go | tail -n 20
Feb 10 11:33:34 Books snapd[1004]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 10 11:38:32 Books snapd[1004]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-10T21:00:00-05:00.
Feb 11 08:53:28 Books snapd[23417]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-11T21:00:00-05:00.
Feb 11 16:51:57 Books snapd[1052]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-11T21:00:00-05:00.
Feb 11 21:22:40 Books snapd[1052]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 11 21:27:38 Books snapd[1052]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-12T21:00:00-05:00.
Feb 12 10:51:23 Books snapd[1039]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-12T21:00:00-05:00.
Feb 12 23:54:11 Books snapd[1039]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 12 23:59:08 Books snapd[1039]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-13T21:00:00-05:00.
Feb 14 16:37:08 Books snapd[1039]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 14 16:37:08 Books snapd[1039]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-14T21:00:00-05:00.
Feb 14 17:03:41 Books snapd[963]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-14T21:00:00-05:00.
Feb 15 06:04:37 Books snapd[963]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 15 06:09:34 Books snapd[963]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-15T21:00:00-05:00.
Feb 16 11:57:49 Books snapd[963]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 16 11:57:49 Books snapd[963]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-16T21:00:00-05:00.
Feb 17 16:08:17 Books snapd[963]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 17 16:13:14 Books snapd[963]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-17T21:00:00-05:00.
Feb 18 07:17:56 Books snapd[963]: autorefresh.go:397: auto-refresh: all snaps are up-to-date
Feb 18 07:22:53 Books snapd[963]: autorefresh.go:253: DEBUG: Next refresh scheduled for 2020-02-18T21:00:00-05:00.

I hope this helps