Skip to content

Comments

feat: improve logging on snap error#162

Merged
james-garner-canonical merged 9 commits intocanonical:mainfrom
james-garner-canonical:2025-06/feat/improve-logging-on-snap-error
Jun 16, 2025
Merged

feat: improve logging on snap error#162
james-garner-canonical merged 9 commits intocanonical:mainfrom
james-garner-canonical:2025-06/feat/improve-logging-on-snap-error

Conversation

@james-garner-canonical
Copy link
Contributor

@james-garner-canonical james-garner-canonical commented Jun 6, 2025

When a SnapError is raised after a snap command errors (raising a CalledProcessError), the error does not currently contain the process's stderr. Additionally, the failure information may not be present in stdout or stderr, but may instead have been logged to the journal. This PR updates the 6 call sites where a CalledProcessError is converted to a SnapError as follows:

  • The subprocess call is updated to always capture stdout and stderr so that these are available in the CalledProcessError
  • The specific error message and the CalledProcessError are passed to a new constructor for SnapError
  • SnapError._from_called_process_error extends the provided message with stdout and stderr from the CalledProcessError, and attempts to extend it further with the last 20 entries from the journal from the snapd unit -- if this fails, the failure is appended to the message instead

The unit tests have been updated due to the changes to the subprocess calls. The functional change is exercised in an integration test, which has been updated to be more strict (previously it could pass even if the expected error wasn't raised), and to check that the logs have been retrieved successfully.

Fixes: #136

This is an example of the new error output (captured by forcing re-raising the exception caught in the integration test):

charms.operator_libs_linux.v2.snap.SnapError: Snap: 'lxd' -- command ['snap', 'get', 'lxd', 'keythatdoesntexist01'] failed!
Stderr:
error: snap "lxd" has no "keythatdoesntexist01" configuration option

Latest logs:
Jun 06 04:29:35 fv-az1721-795 snapd[21730]: storehelpers.go:954: cannot refresh snap "snapd": snap has no updates available
Jun 06 04:29:35 fv-az1721-795 snapd[21730]: overlord.go:518: Released state lock file
Jun 06 04:29:35 fv-az1721-795 systemd[1]: snapd.service: Deactivated successfully.
Jun 06 04:29:35 fv-az1721-795 systemd[1]: snapd.service: Scheduled restart job, restart counter is at 1.
Jun 06 04:29:35 fv-az1721-795 systemd[1]: Starting snapd.service - Snap Daemon...
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: overlord.go:284: Acquiring state lock file
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: overlord.go:289: Acquired state lock file
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: patch.go:64: Patching system state level 6 to sublevel 1...
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: patch.go:64: Patching system state level 6 to sublevel 2...
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: patch.go:64: Patching system state level 6 to sublevel 3...
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: daemon.go:250: started snapd/2.68.4 (series 16; classic) ubuntu/24.04 (amd64) linux/6.11.0-1015-azure.
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: daemon.go:353: adjusting startup timeout by 35s (pessimistic estimate of 30s plus 5s per snap)
Jun 06 04:29:36 fv-az1721-795 snapd[22044]: backends.go:91: AppArmor status: apparmor is enabled and all features are available (using snapd provided apparmor_parser)
Jun 06 04:29:37 fv-az1721-795 systemd[1]: Started snapd.service - Snap Daemon.
Jun 06 04:29:45 fv-az1721-795 snapd[22044]: api_snaps.go:467: Installing snap "charmcraft" revision unset
Jun 06 04:29:56 fv-az1721-795 snapd[22044]: api_snaps.go:467: Installing snap "hello-world" revision unset
Jun 06 04:30:01 fv-az1721-795 snapd[22044]: storehelpers.go:916: cannot refresh snap "hello-world": snap has no updates available
Jun 06 04:30:02 fv-az1721-795 snapd[22044]: api_snaps.go:467: Installing snap "lxd" revision unset
Jun 06 04:30:13 fv-az1721-795 snapd[22044]: storehelpers.go:916: cannot refresh snap "lxd": snap has no updates available
Jun 06 04:30:14 fv-az1721-795 snapd[22044]: storehelpers.go:916: cannot refresh snap "lxd": snap has no updates available

@james-garner-canonical james-garner-canonical merged commit f89e03b into canonical:main Jun 16, 2025
13 of 14 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

When a snap fails to restart for some reason, e.g. "Start request repeated too quickly", log messages do not reflect the reason

2 participants