Bug in snap refresh with private snap

spongebas · April 29, 2025, 12:46pm

I’m running into the following bug:

root@here:/home/me# snap refresh foo
error: snap "foo" not found
root@here:/home/me# snap install foo
snap "foo" is already installed, see 'snap help refresh'

I’ve tried adding --amend to the refresh command, but that doesn’t help. I don’t have a reproducer, but this issue showed up at the same time my snap login broke. This is a private snap. I logged out and logged back in again but now the refresh command is broken.

My snapd and core packages are up-to-date.

mborzecki1 · April 30, 2025, 5:18am

There’s very little information for anyone to try to figure out what the issue could be. Have you looked at snapd logs? Can you attach the output of snap list?

If you’re worried about leaking the name of the private snap, but are a customer you should file a support ticket.

spongebas · May 1, 2025, 6:20pm

Hi @mborzecki1, thanks for getting back to me.

The “foo” snap is registered as sponge-controller:

root@here:~$ snap list
Name                  Version                 Rev    Tracking       Publisher        Notes
core20                20250213                2503   latest/stable  canonical✓       base
core22                20250315                1912   latest/stable  canonical✓       base
core24                20250318                892    latest/stable  canonical✓       base
mesa-core20           21.2.6                  169    latest/stable  canonical✓       -
mesa-core22           23.2.1                  369    latest/stable  canonical✓       -
nmap                  7.95                    3887   latest/stable  maxiberta✪       -
snapd                 2.68.4                  24509  latest/stable  canonical✓       snapd
sponge-controller     0+git.d67eb1a-dirty     320    latest/beta    ******          private
ubuntu-frame          147-mir2.17.2           12367  22/stable      canonical✓       -
ubuntu-frame-osk      75-squeekboard-v1.17.1  1062   22/stable      canonical✓       -

The snapd logs don’t have a lot to say. I mainly see:

May 01 06:23:04 10002 snapd[473144]: storehelpers.go:916: cannot refresh:
May 01 06:23:04 10002 snapd[473144]: snap has no updates available: "core20", "core22", "core24", "mesa-core20", "mesa-core22", "nmap", "snapd", "ubuntu-fra>
May 01 06:23:04 10002 snapd[473144]: snap not found: "sponge-controller"
May 01 14:08:45 10002 snapd[473144]: api_snaps.go:467: Installing snap "sponge-controller" revision unset

This is from the output of journalctl -u snapd. Is there a better place to view snapd logs?

I would have assumed that the “install” and “refresh” commands use the same piece of code to verify if a snap exists, but maybe the account verification scripts differ between the two?

ogra · May 1, 2025, 6:28pm

Yes, snap changes (note though that these are not persistent and get flushed regularly, so the relevant logs might be gone already)

spongebas · May 1, 2025, 6:45pm

root@here:~$ snap changes
ID     Status  Spawn                   Ready                   Summary
27194  Done    yesterday at 14:51 EDT  yesterday at 14:53 EDT  Auto-refresh snap "snapd"

snap changes doesn’t give more info. The last snap refresh on this system for the snap in question was the 10th of February, I just noticed the other day that it was out of date.

ogra · May 1, 2025, 6:49pm

Yes, as I said, the changes get flushed regularly… (BTW with snap change <ID> you can see the actual details of such a log)

mborzecki1 · May 5, 2025, 6:27am

I think it may be really a store error that the snap wasn’t found. This is in line with what you mentioned about the snap being private.

Have you tried querying the store about the snap, by running snap info <snapname> ? Are you logged in? i.e. have you run snap login before? Does snap whoami show that you are logged in?

spongebas · May 5, 2025, 12:38pm

snap info is able to find the snap as expected:

root@here:~$ snap info sponge-controller
name:      sponge-controller
(...)
tracking:     latest/beta
refresh-date: 2025-02-10
channels:
  latest/stable:    0+git.0142686       2025-04-22 (413) 203MB -
  latest/candidate: 0+git.0142686       2025-04-22 (413) 203MB -
  latest/beta:      0+git.b0f17d6       2025-05-02 (433) 221MB -
  latest/edge:      0+git.b0f17d6       2025-05-03 (434) 301MB -
installed:          0+git.d67eb1a-dirty            (320) 199MB private

snap whoami shows that I am indeed logged in. When this issue first popped up I tried to logout and log back in again, but that didn’t help.

I tried some other snap commands too: snap install, snap switch, snap info, snap enable all recognize that the snap is installed. snap refresh seems to think that the snap is not installed.

Ordinarily I would try to uninstall and reinstall the snap, but this machine is a remote iot machine for which the remote access is handled by the snap in question. I can’t risk uninstalling the existing version and loosing access.

spongebas · May 5, 2025, 12:56pm

I suppose I could install a different means of remote access and reinstall the snap after, but if this is indeed a bug in snapd then fixing it there would be a better solution.

mborzecki1 · May 5, 2025, 6:49pm

It could be that the snap store is returning not found error which snapd relays back to the user. Can you add the following:

SNAPD_DEBUG_HTTP=7
SNAPD_DEBUG=1

to the snapd service environment, restart snapd, run snap refresh and collect the logs?

Make sure to edit the logs and erase authentication Macaroon before pasting them to the forum.

Other snap versions seem to be listed properly, is it possible that the private revision was removed? Can you paste the output of snap list sponge-controller?

If the snap is unasserted you may need to run snap refresh --amend sponge-controller for snapd to start tacking the version available from the store again.

spongebas · May 6, 2025, 12:44pm

The snap store is indeed returning a not found error, but the error is different from a snap that actually does not exist.

These are the snapd logs with the debug flags enabled for snap refresh sponge-controller:

May 06 08:28:45 here snapd[2358262]: store_action.go:607: DEBUG: Deltas enabled. Adding header Snap-Accept-Delta-Format: xdelta3
May 06 08:28:45 here snapd[2358262]: retry.go:51: DEBUG: Retrying https://api.snapcraft.io/v2/snaps/refresh, attempt 1, elapsed time=11.314µs
May 06 08:28:45 here snapd[2358262]: logger.go:67: DEBUG: > "POST /v2/snaps/refresh HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.68.4 (series 16; classic) ubuntu/22.04 (arm64>
May 06 08:28:47 here snapd[2358262]: logger.go:74: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 957\r\nContent-Type: application/json\r\nDate: Tue, 06 May 2025 12:28:47 GMT\r\nServer: gun>
May 06 08:28:47 here snapd[2358262]: retry.go:63: DEBUG: The retry loop for https://api.snapcraft.io/v2/snaps/refresh finished after 1 retries, elapsed time=1.985163529s, status: 200
May 06 08:28:47 here snapd[2358262]: store_action.go:607: DEBUG: Deltas enabled. Adding header Snap-Accept-Delta-Format: xdelta3
May 06 08:28:47 here snapd[2358262]: retry.go:51: DEBUG: Retrying https://api.snapcraft.io/v2/snaps/refresh, attempt 1, elapsed time=9.908µs
May 06 08:28:47 here snapd[2358262]: logger.go:67: DEBUG: > "POST /v2/snaps/refresh HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.68.4 (series 16; classic) ubuntu/22.04 (arm64>
May 06 08:28:48 here snapd[2358262]: logger.go:74: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 275\r\nContent-Type: application/json\r\nDate: Tue, 06 May 2025 12:28:48 GMT\r\nServer: gun>
May 06 08:28:48 here snapd[2358262]: retry.go:63: DEBUG: The retry loop for https://api.snapcraft.io/v2/snaps/refresh finished after 1 retries, elapsed time=813.929704ms, status: 200
May 06 08:28:48 here snapd[2358262]: daemon.go:220: DEBUG: pid=2358813;uid=1000;socket=/run/snapd.socket; POST /v2/snaps/sponge-controller 2.854062054s 404

And when I call snap refresh non-existing-snap:

May 06 08:31:34 here snapd[2358262]: store_action.go:607: DEBUG: Deltas enabled. Adding header Snap-Accept-Delta-Format: xdelta3
May 06 08:31:34 here snapd[2358262]: retry.go:51: DEBUG: Retrying https://api.snapcraft.io/v2/snaps/refresh, attempt 1, elapsed time=15.5µs
May 06 08:31:34 here snapd[2358262]: logger.go:67: DEBUG: > "POST /v2/snaps/refresh HTTP/1.1\r\nHost: api.snapcraft.io\r\nUser-Agent: snapd/2.68.4 (series 16; classic) ubuntu/22.04 (arm64) linux/>
May 06 08:31:35 here snapd[2358262]: logger.go:74: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 957\r\nContent-Type: application/json\r\nDate: Tue, 06 May 2025 12:31:35 GMT\r\nServer: gunicorn\r\>
May 06 08:31:35 here snapd[2358262]: retry.go:63: DEBUG: The retry loop for https://api.snapcraft.io/v2/snaps/refresh finished after 1 retries, elapsed time=1.75552389s, status: 200
May 06 08:31:35 here snapd[2358262]: daemon.go:220: DEBUG: pid=2359353;uid=1000;socket=/run/snapd.socket; POST /v2/snaps/non-existing-snap 1.832124613s 400

The difference seems to be a 404 when looking for sponge-controller and 400 for non-existing-snap.

Snapd logs for snap info sponge-controller:

May 06 08:36:41 here snapd[2358262]: retry.go:51: DEBUG: Retrying https://api.snapcraft.io/v2/snaps/info/sponge-controller?architecture=arm64&fields=architectures%2Cbase%2Cconfinement%2Clinks%2Cc>
May 06 08:36:41 here snapd[2358262]: logger.go:67: DEBUG: > "GET /v2/snaps/info/sponge-controller?architecture=arm64&fields=architectures%2Cbase%2Cconfinement%2Clinks%2Ccontact%2Ccreated-at%2Cdes>
May 06 08:36:43 here snapd[2358262]: logger.go:74: DEBUG: < "HTTP/1.1 200 OK\r\nContent-Length: 3056\r\nContent-Type: application/json\r\nDate: Tue, 06 May 2025 12:36:43 GMT\r\nServer: gunicorn\r>
May 06 08:36:43 here snapd[2358262]: retry.go:63: DEBUG: The retry loop for https://api.snapcraft.io/v2/snaps/info/sponge-controller?architecture=arm64&fields=architectures%2Cbase%2Cconfinement%2>
May 06 08:36:43 here snapd[2358262]: daemon.go:220: DEBUG: pid=2360575;uid=1000;socket=/run/snapd.socket; GET /v2/find?name=sponge-controller 2.103744734s 200
May 06 08:36:44 here snapd[2358262]: daemon.go:220: DEBUG: pid=2360575;uid=1000;socket=/run/snapd.socket; GET /v2/snaps/sponge-controller 715.617405ms 200

Snapd logs for snap info non-existing-snap:

May 06 08:34:54 here snapd[2358262]: retry.go:51: DEBUG: Retrying https://api.snapcraft.io/v2/snaps/info/non-existing-snap?architecture=arm64&fields=architectures%2Cbase%2Cconfinement%2Clinks%2Cc>
May 06 08:34:54 here snapd[2358262]: logger.go:67: DEBUG: > "GET /v2/snaps/info/non-existing-snap?architecture=arm64&fields=architectures%2Cbase%2Cconfinement%2Clinks%2Ccontact%2Ccreated-at%2Cdes>
May 06 08:34:56 here snapd[2358262]: logger.go:74: DEBUG: < "HTTP/1.1 404 NOT FOUND\r\nContent-Length: 115\r\nContent-Type: application/json\r\nDate: Tue, 06 May 2025 12:34:55 GMT\r\nServer: guni>
May 06 08:34:56 here snapd[2358262]: retry.go:63: DEBUG: The retry loop for https://api.snapcraft.io/v2/snaps/info/non-existing-snap?architecture=arm64&fields=architectures%2Cbase%2Cconfinement%2>
May 06 08:34:56 here snapd[2358262]: daemon.go:220: DEBUG: pid=2360217;uid=1000;socket=/run/snapd.socket; GET /v2/find?name=non-existing-snap 1.91079169s 404
May 06 08:34:56 here snapd[2358262]: daemon.go:220: DEBUG: pid=2360217;uid=1000;socket=/run/snapd.socket; GET /v2/snaps/non-existing-snap 855.927µs 404

The messages from the snap refresh command are also different between the two:

root@here:~$ snap refresh sponge-controller
error: snap "sponge-controller" not found
root@here:~$ snap refresh non-existing-snap
error: cannot refresh "non-existing-snap": snap "non-existing-snap" is not installed

The other two commands you requested:

root@here:~$ snap list sponge-controller
Name               Version              Rev  Tracking     Publisher        Notes
sponge-controller  0+git.d67eb1a-dirty  320  latest/beta  ******           private
root@here:~$ snap refresh --amend sponge-controller
error: snap "sponge-controller" not found

mborzecki1 · May 6, 2025, 1:34pm

The logs appear to be truncated. Try using journalctl --no-pager -u snapd