After a refresh doesn't use the right version of the snap

[Jean-Baptiste Lallement]

snapd:
  Installed: 2.0.9+16.10

A snap refresh this morning updated krita to version 3 but snap list and the launcher still use 2 as current version.

⟫ snap list krita
Name Version Rev Developer Notes
krita 3.0-snap11 2 krita -

⟫ grep exec /snap/bin/krita
exec /usr/bin/ubuntu-core-launcher snap.krita.krita snap.krita.krita /snap/krita/2/command-krita.wrapper "$@"

⟫ ls -l /snap/krita/
total 0
drwxrwxr-x 8 root root 123 juin 1 20:24 1
drwxrwxr-x 8 root root 123 juin 2 16:36 2
drwxrwxr-x 8 root root 123 juin 4 10:46 3
lrwxrwxrwx 1 root root 1 juin 20 10:29 current -> 2

Re-running snap refresh fails with
⟫ snap refresh

error: cannot perform the following tasks:
- Download snap "krita" from channel "stable" (revision 3 of snap "krita" already installed)

[Mark Shuttleworth (sabdfl)]

I see this too, thanks for the report.

 status: confirmed

[John Lenton (chipaca)]

Do you still have the change for the original refresh? If so, could you paste the output of "snap change <the change number>"?

[Jean-Baptiste Lallement (jibel)]

⟫ snap change 30
Status Spawn Ready Summary
Done 2016-06-20T08:28:09Z 2016-06-20T08:29:12Z Download snap "krita" from channel "stable"
Done 2016-06-20T08:28:09Z 2016-06-20T08:29:12Z Mount snap "krita"
Done 2016-06-20T08:28:09Z 2016-06-20T08:29:12Z Make current revision for snap "krita" unavailable
Done 2016-06-20T08:28:09Z 2016-06-20T08:29:13Z Copy snap "krita" data
Done 2016-06-20T08:28:09Z 2016-06-20T08:29:13Z Setup snap "krita" security profiles
Done 2016-06-20T08:28:09Z 2016-06-20T08:29:13Z Make snap "krita" available to the system

[Michael Vogt (mvo)]

@jibel Could you please attach the output of `$ grep snapd /var/log/syslog` so that we can try to understand how the system came into this state.

[Jean-Baptiste Lallement (jibel)]

grep snapd /var/log/syslog

[Jean-Baptiste Lallement (jibel)]

journalctl -u snapd

[Gustavo Niemeyer (niemeyer)]

It looks like the store replied with revision 3 and then 2 for two refresh requests, one right after the other. If the store is alternating between 3 and 2, that'd explain the behavior observed.

Jun 20 13:17:58 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=1000;@ GET /v2/find?q=&select=refresh 319.1011ms 200
Jun 20 13:17:58 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=1000;@ POST /v2/snaps/krita 20.822311ms 202
Jun 20 13:17:58 sark /usr/lib/snapd/snapd[1351]: taskrunner.go:238: DEBUG: Running task 168 on Do: Download snap "krita" from channel "stable"
Jun 20 13:17:58 sark /usr/lib/snapd/snapd[1351]: task.go:250: DEBUG: 2016-06-20T13:17:58+02:00 ERROR revision 3 of snap "krita" already installed
Jun 20 13:18:31 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=1000;@ GET /v2/snaps 4.388231ms 200
Jun 20 13:19:50 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=1000;@ GET /v2/find?q=&select=refresh 376.562661ms 200
Jun 20 13:19:50 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=1000;@ GET /v2/snaps 5.899994ms 200
Jun 20 13:20:05 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=0;@ POST /v2/snaps/krita 13.480955ms 202
Jun 20 13:20:05 sark /usr/lib/snapd/snapd[1351]: taskrunner.go:238: DEBUG: Running task 174 on Do: Download snap "krita" from channel "stable"
Jun 20 13:20:05 sark /usr/lib/snapd/snapd[1351]: task.go:250: DEBUG: 2016-06-20T13:20:05+02:00 ERROR revision 2 of snap "krita" already installed
Jun 20 13:20:08 sark /usr/lib/snapd/snapd[1351]: daemon.go:181: DEBUG: uid=1000;@ POST /v2/snaps/krita 13.795327ms 202

[Michael Vogt (mvo)]

Here is my theory what happend:
"""
- user has rev 3 installed
- store is modified (e.g. by the krita owner) to make rev 3 unavailable in the stable channel
- on the next refresh snapd gets "2" as the latest snap in stable
- snapd install "2" (because that is what the store told it)
- store is modified again to make rev 3 available in stable again
- on the next refresh snapd gets "3" again and tries to refresh to that
- it fails because 3 is already installed, however it should not fail but instead just link rev 3 instead of rev 2.
"""
once we implement the last step we also solve the issue when alternating between channels.

[John Lenton (chipaca)]

Note that this was reported at the same time we had operational issues in
the store that resulted in inconsistent results (e.g. the revision could've
flapped)

On 27 Jun 2016 07:15, "Michael Vogt" <email address hidden> wrote:

> Here is my theory what happend:
> """
> - user has rev 3 installed
> - store is modified (e.g. by the krita owner) to make rev 3 unavailable in
> the stable channel
> - on the next refresh snapd gets "2" as the latest snap in stable
> - snapd install "2" (because that is what the store told it)
> - store is modified again to make rev 3 available in stable again
> - on the next refresh snapd gets "3" again and tries to refresh to that
> - it fails because 3 is already installed, however it should not fail but
> instead just link rev 3 instead of rev 2.
> """
> once we implement the last step we also solve the issue when alternating
> between channels.
>
> --
> You received this bug notification because you are a member of Snappy
> Developers, which is subscribed to Snappy.
> https://bugs.launchpad.net/bugs/1594330
>
> Title:
> After a refresh doesn't use the right version of the snap
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/snappy/+bug/1594330/+subscriptions
>