snapd

blocking refresh does not block auto-refresh

Bug #2039052 reported by Pirouette Cacahuète
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mozilla Firefox
Expired
Unknown
snapd
New
Undecided
Unassigned

Bug Description

This is something we are hitting on CI, ubuntu 22.04

https://treeherder.mozilla.org/logviewer?job_id=431990807&repo=try&lineNumber=80-83

> [task 2023-10-10T15:05:03.960Z] /home/ubuntu/tasks/task_169694991363220/fetches
> [task 2023-10-10T15:05:03.960Z] + ARTIFACT_DIR=/home/ubuntu/tasks/task_169694991363220/builds/worker/artifacts/
> [task 2023-10-10T15:05:03.960Z] + mkdir -p /home/ubuntu/tasks/task_169694991363220/builds/worker/artifacts/
> [task 2023-10-10T15:05:03.965Z] + sudo snap refresh --hold=24h firefox
> [task 2023-10-10T15:05:08.788Z] General refreshes of "firefox" held until 2023-10-11T15:05:06Z
> [task 2023-10-10T15:05:08.798Z] + sudo snap install --name firefox --dangerous ./firefox.snap
> [task 2023-10-10T15:05:16.963Z] error: snap "firefox" has "auto-refresh" change in progress

snapd is:
> [task 2023-10-11T13:21:09.331Z] + snap info snapd
> [task 2023-10-11T13:21:10.223Z] name: snapd
> [task 2023-10-11T13:21:10.223Z] summary: Daemon and tooling that enable snap packages
> [task 2023-10-11T13:21:10.223Z] publisher: Canonical**
> [task 2023-10-11T13:21:10.223Z] store-url: https://snapcraft.io/snapd
> [task 2023-10-11T13:21:10.223Z] contact: https://github.com/snapcore/snapd/issues
> [task 2023-10-11T13:21:10.223Z] license: GPL-3.0
> [task 2023-10-11T13:21:10.223Z] description: |
> [task 2023-10-11T13:21:10.223Z] Install, configure, refresh and remove snap packages. Snaps are
> [task 2023-10-11T13:21:10.223Z] 'universal' packages that work across many different Linux systems,
> [task 2023-10-11T13:21:10.223Z] enabling secure distribution of the latest apps and utilities for
> [task 2023-10-11T13:21:10.223Z] cloud, servers, desktops and the internet of things.
> [task 2023-10-11T13:21:10.223Z]
> [task 2023-10-11T13:21:10.223Z] Start with 'snap list' to see installed snaps.
> [task 2023-10-11T13:21:10.223Z] type: snapd
> [task 2023-10-11T13:21:10.223Z] snap-id: PMrrV4ml8uWuEUDBT8dSGnKUYbevVhc4
> [task 2023-10-11T13:21:10.223Z] tracking: latest/stable
> [task 2023-10-11T13:21:10.223Z] refresh-date: 21 days ago, at 00:35 UTC
> [task 2023-10-11T13:21:10.223Z] channels:
> [task 2023-10-11T13:21:10.223Z] latest/stable: 2.60.4 2023-10-10 (20290) 42MB -
> [task 2023-10-11T13:21:10.223Z] latest/candidate: 2.60.4 2023-10-03 (20290) 42MB -
> [task 2023-10-11T13:21:10.223Z] latest/beta: 2.60.4 2023-09-15 (20290) 42MB -
> [task 2023-10-11T13:21:10.223Z] latest/edge: 2.60.4+git1413.g0e64f05 2023-10-10 (20479) 42MB -
> [task 2023-10-11T13:21:10.223Z] installed: 2.60.3 (20092) 42MB snapd

See original description
Pirouette Cacahuète (lissyx)
description: updated
Revision history for this message
Sebastien Bacher (seb128) wrote :

I think the title probably doesn't reflect what's going on, my guess is that the auto-refresh was already started in background by the time the hold command was issued

Unsure what would be the best outcome there. Having the install call cancel the ongoing refresh and install the specified revision after instead if returning an error? Or waiting for the ongoing transaction to be done to then install instead of returning?

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

Well, my reasonning was:
 - there's a "hold refresh" feature, so it should impact "auto-refresh"
 - "snapd refresh hold" succeeding means it has successfully blocked any refresh tentative
 - "snapd install" failing due to auto-refresh sounds unexpected

So either:
 - "refresh" and "auto-refresh" are orthogonal, and I failed to see that in the docs, and question becomes: can I and how do I block auto-refresh ?
 - they are not and as you infer maybe auto-refresh was already started, in which case either:
   - "snap refresh hold" should cancel a pending auto-refresh
   - "snap refresh hold" cannot do that and it should just fail clearly

or there's a 10ms race :p

Revision history for this message
Sergio Cazzolato (sergio-j-cazzolato) wrote :

Hi, thanks for raising this

Could you please share the output for:
# snap changes

Is it still reproducible?

Revision history for this message
In , Intermittent-bug-filer (intermittent-bug-filer) wrote :

**Filed by:** ncsoregi [at] mozilla.com
**Parsed log:** https://treeherder.mozilla.org/logviewer?job_id=434368570&repo=mozilla-central
**Full log:** https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NP0F1ywGRJqN7gbIVTKj0w/runs/0/artifacts/public/logs/live_backing.log

---
```
[task 2023-10-31T01:18:15.368Z] + export TASKCLUSTER_ROOT_DIR=/home/ubuntu/tasks/task_169871481951330
[task 2023-10-31T01:18:15.368Z] + TASKCLUSTER_ROOT_DIR=/home/ubuntu/tasks/task_169871481951330
[task 2023-10-31T01:18:15.368Z] + cd /home/ubuntu/tasks/task_169871481951330/fetches/
[task 2023-10-31T01:18:15.368Z] + ./tests.sh
[task 2023-10-31T01:18:15.373Z] + pwd
[task 2023-10-31T01:18:15.373Z] /home/ubuntu/tasks/task_169871481951330/fetches
[task 2023-10-31T01:18:15.373Z] + ARTIFACT_DIR=/home/ubuntu/tasks/task_169871481951330/builds/worker/artifacts/
[task 2023-10-31T01:18:15.373Z] + mkdir -p /home/ubuntu/tasks/task_169871481951330/builds/worker/artifacts/
[task 2023-10-31T01:18:15.378Z] + sudo snap refresh
[task 2023-10-31T01:18:16.675Z] All snaps up to date.
[task 2023-10-31T01:18:16.680Z] + sudo snap refresh --hold=24h firefox
[task 2023-10-31T01:18:16.781Z] General refreshes of "firefox" held until 2023-11-01T01:18:16Z
[task 2023-10-31T01:18:16.786Z] + sudo snap install --name firefox --dangerous ./firefox.snap
[task 2023-10-31T01:18:41.968Z] error: snap "firefox" has "auto-refresh" change in progress
[taskcluster 2023-10-31T01:18:41.987Z] Exit Code: 10
[taskcluster 2023-10-31T01:18:41.987Z] User Time: 15.579606s
[taskcluster 2023-10-31T01:18:41.987Z] Kernel Time: 16.232894s
[taskcluster 2023-10-31T01:18:41.987Z] Wall Time: 57.767360121s
[taskcluster 2023-10-31T01:18:41.987Z] Result: FAILED
[taskcluster 2023-10-31T01:18:41.987Z] === Task Finished ===
[taskcluster 2023-10-31T01:18:41.987Z] Task Duration: 57.779593383s
[taskcluster 2023-10-31T01:18:42.053Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-01-29T00:03:51.005Z
[taskcluster:error] exit status 10
```

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

It happened yes even though we added a "snap refresh" before:

> [task 2023-10-31T01:18:15.378Z] + sudo snap refresh
> [task 2023-10-31T01:18:16.675Z] All snaps up to date.
> [task 2023-10-31T01:18:16.680Z] + sudo snap refresh --hold=24h firefox
> [task 2023-10-31T01:18:16.781Z] General refreshes of "firefox" held until 2023-11-01T01:18:16Z
> [task 2023-10-31T01:18:16.786Z] + sudo snap install --name firefox --dangerous ./firefox.snap
> [task 2023-10-31T01:18:41.968Z] error: snap "firefox" has "auto-refresh" change in progress

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

@sergio-j-cazzolato, do you need "snap changes" before, or after the failure ?

Revision history for this message
In , Lissyx+mozillians (lissyx+mozillians) wrote :

Thanks, it's clearly an upstream issue, I hoped forcing a refresh would be enough but it is not. Retry should be enough and intermittence should be low, but we still want to get rid of this.

Bug Watch Updater (bug-watch-updater)
Changed in firefox:
status: Unknown → Confirmed
Revision history for this message
In , Orangefactor (orangefactor) wrote :

1 failures in 3356 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 1

Platform and build breakdown:
* linux64-snap-nightly: 1
  * debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1862106&startday=2023-10-30&endday=2023-11-05&tree=all

Revision history for this message
In , Release-mgmt-account-bot (release-mgmt-account-bot) wrote :

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit [BugBot documentation](https://wiki.mozilla.org/BugBot#close_intermittents.py).

Bug Watch Updater (bug-watch-updater)
Changed in firefox:
status: Confirmed → Expired
Revision history for this message
In , Ncsoregi (ncsoregi) wrote :

Recent failed job: [job](https://treeherder.mozilla.org/jobs?repo=mozilla-central&searchStr=linux64-snap-esr%2Copt%2Csnap-upstream-test-amd64-esr%2Fopt%2Csel&revision=27636a965cb6b6fb3f56596852a05e406edcc8eb)

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=447021158&repo=mozilla-central&lineNumber=106

```
[task 2024-02-13T01:45:11.598Z] All snaps up to date.
[task 2024-02-13T01:45:11.605Z] + sudo snap refresh --hold=24h firefox
[task 2024-02-13T01:45:11.732Z] General refreshes of "firefox" held until 2024-02-14T01:45:11Z
[task 2024-02-13T01:45:11.738Z] + sudo snap install --name firefox --dangerous ./firefox.snap
[task 2024-02-13T01:45:29.898Z] error: snap "firefox" has "auto-refresh" change in progress
[taskcluster 2024-02-13T01:45:29.929Z] Exit Code: 10
[taskcluster 2024-02-13T01:45:29.929Z] User Time: 4.012128s
[taskcluster 2024-02-13T01:45:29.929Z] Kernel Time: 7.864103s
[taskcluster 2024-02-13T01:45:29.929Z] Wall Time: 41.294695116s
[taskcluster 2024-02-13T01:45:29.929Z] Result: FAILED
[taskcluster 2024-02-13T01:45:29.929Z] === Task Finished ===
[taskcluster 2024-02-13T01:45:29.929Z] Task Duration: 41.301847439s
[taskcluster 2024-02-13T01:45:30.016Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2024-05-13T00:04:17.166Z
[taskcluster:error] exit status 10
```

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

This is still happening with 2.61.1, is there any workaround?

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

> [task 2023-10-31T01:18:15.378Z] + sudo snap refresh
> [task 2023-10-31T01:18:16.675Z] All snaps up to date.
> [task 2023-10-31T01:18:16.680Z] + sudo snap refresh --hold=24h firefox
> [task 2023-10-31T01:18:16.781Z] General refreshes of "firefox" held until 2023-11-01T01:18:16Z
> [task 2023-10-31T01:18:16.786Z] + sudo snap install --name firefox --dangerous ./firefox.snap
> [task 2023-10-31T01:18:41.968Z] error: snap "firefox" has "auto-refresh" change in progress

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

Also wondering if this is expected:

> [task 2024-02-13T08:55:58.170Z] + sudo snap refresh
> [task 2024-02-13T08:55:59.288Z] All snaps up to date.
> [task 2024-02-13T08:55:59.293Z] + sudo snap refresh --hold=24h firefox
> [task 2024-02-13T08:55:59.542Z] General refreshes of "firefox" held until 2024-02-14T08:55:59Z
> [task 2024-02-13T08:55:59.548Z] + sudo snap install --name firefox --dangerous ./firefox.snap
> [task 2024-02-13T08:56:06.776Z] error: cannot install snap file: cannot update disabled snap "firefox"

Revision history for this message
Maciej Borzecki (maciek-borzecki) wrote :

Is the firefox snap preinstalled in the images you use during the CI runs? I suspect you're basically racing with snapd which finds there's an update for firefox and starts it. Then subsequent commands have no effect on a refresh which is already in progress.

Would it be possible to grab the output of `snap changes` and add it to the bug report?

For the time being, I would suggest to use this order:
1. set snap refresh --hold=forever
2. run `snap changes` and sleep whenever you observe `(Doing/Undoing/Do\s)`, eg:

  while true; do
    if snap changes 2>&1 | grep -E '(Doing|Undoing|Do\s|restarting)'; then
      echo wait; sleep 0.5
    else
      break
    fi
  done

Bug Watch Updater (bug-watch-updater)
Changed in firefox:
status: Expired → Confirmed
Revision history for this message
In , Orangefactor (orangefactor) wrote :

1 failures in 3125 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 1

Platform and build breakdown:
* linux64-snap-esr: 1
  * opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1862106&startday=2024-02-12&endday=2024-02-18&tree=all

Revision history for this message
In , Orangefactor (orangefactor) wrote :

2 failures in 3382 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 2

Platform and build breakdown:
* linux64-snap-beta: 1
  * opt: 1
* linux64-snap-stable: 1
  * opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1862106&startday=2024-02-19&endday=2024-02-25&tree=all

Revision history for this message
In , Orangefactor (orangefactor) wrote :

1 failures in 3849 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 1

Platform and build breakdown:
* linux64-snap-nightly: 1
  * opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1862106&startday=2024-03-11&endday=2024-03-17&tree=all

Revision history for this message
In , Orangefactor (orangefactor) wrote :

1 failures in 3590 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 1

Platform and build breakdown:
* linux64-snap-beta: 1
  * opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1862106&startday=2024-03-25&endday=2024-03-31&tree=all

Revision history for this message
In , Release-mgmt-account-bot (release-mgmt-account-bot) wrote :

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit [BugBot documentation](https://wiki.mozilla.org/BugBot#close_intermittents.py).

Revision history for this message
Pirouette Cacahuète (lissyx) wrote :

This is also blocking me from making mozregression actually working ...

Bug Watch Updater (bug-watch-updater)
Changed in firefox:
status: Confirmed → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.