Unexpected error(s) occurred is logged in syslog

[Jaromir Obr]

I noticed an error in syslog
----------------------------------
Jan 12 07:57:18 rzbox update-notifier.desktop[380935]: Unexpected error(s) occurred.
Jan 12 07:57:18 rzbox update-notifier.desktop[380935]: For more details, see the log: /var/log/ubuntu-advantage.log
Jan 12 07:57:18 rzbox update-notifier.desktop[380935]: To file a bug run: ubuntu-bug ubuntu-advantage-tools
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: Traceback (most recent call last):
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3/dist-packages/UpdateManager/UpdateManager.py", line 241, in start_available
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: self.refresh_cache()
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3/dist-packages/UpdateManager/UpdateManager.py", line 449, in refresh_cache
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: self._get_ua_security_status()
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3/dist-packages/UpdateManager/UpdateManager.py", line 285, in _get_ua_security_status
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: s = json.load(p.stdout)
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3.10/json/__init__.py", line 293, in load
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: return loads(fp.read(),
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3.10/json/__init__.py", line 346, in loads
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: return _default_decoder.decode(s)
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3.10/json/decoder.py", line 337, in decode
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: File "/usr/lib/python3.10/json/decoder.py", line 355, in raw_decode
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: raise JSONDecodeError("Expecting value", s, err.value) from None
Jan 12 07:57:18 rzbox update-notifier.desktop[348424]: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Jan 12 07:57:18 rzbox systemd[1]: Starting Process error reports when automatic reporting is enabled...
Jan 12 07:57:18 rzbox systemd[1]: Started crash report submission.
Jan 12 07:57:18 rzbox whoopsie[381183]: [07:57:18] Using lock path: /var/lock/whoopsie/lock
Jan 12 07:57:18 rzbox systemd[1]: whoopsie.service: Deactivated successfully.
Jan 12 07:57:18 rzbox whoopsie-upload-all[381182]: INFO:root:Collecting info for /var/crash/_usr_bin_update-manager.1000.crash...
Jan 12 07:57:23 rzbox whoopsie-upload-all[381182]: WARNING: hook failed for processing /var/crash/_usr_bin_update-manager.1000.crash:
Jan 12 07:57:23 rzbox whoopsie-upload-all[381182]: INFO:root:Marking /var/crash/_usr_bin_update-manager.1000.crash for whoopsie upload
Jan 12 07:57:23 rzbox whoopsie-upload-all[381182]: INFO:root:/var/crash/_usr_share_skypeforlinux_skypeforlinux.1000.crash already marked for upload, skipping
Jan 12 07:57:23 rzbox whoopsie-upload-all[381182]: INFO:root:Waiting for whoopsie to upload reports (timeout: 20 s)
Jan 12 07:57:23 rzbox whoopsie-upload-all[381182]: INFO:root: missing (remaining: 20 s): /var/crash/_usr_bin_update-manager.1000.uploaded
Jan 12 07:57:23 rzbox systemd[1]: Started crash report submission.
Jan 12 07:57:23 rzbox whoopsie[383250]: [07:57:23] Using lock path: /var/lock/whoopsie/lock
Jan 12 07:57:23 rzbox whoopsie[383250]: [07:57:23] Parsing /var/crash/_usr_bin_update-manager.1000.crash.
Jan 12 07:57:23 rzbox whoopsie[383250]: [07:57:23] Uploading /var/crash/_usr_bin_update-manager.1000.crash.
Jan 12 07:57:24 rzbox whoopsie[383250]: [07:57:24] Sent; server replied with: No error
Jan 12 07:57:24 rzbox whoopsie[383250]: [07:57:24] Response code: 200
Jan 12 07:57:24 rzbox whoopsie[383250]: [07:57:24] Reported OOPS ID 5db82aca-9246-11ed-b711-fa163ef35206
Jan 12 07:57:24 rzbox systemd[1]: whoopsie.service: Deactivated successfully.
Jan 12 07:57:33 rzbox whoopsie-upload-all[381182]: INFO:root:All reports uploaded successfully
Jan 12 07:57:33 rzbox systemd[1]: apport-autoreport.service: Deactivated successfully.
Jan 12 07:57:33 rzbox systemd[1]: Finished Process error reports when automatic reporting is enabled.
Jan 12 07:57:33 rzbox systemd[1]: apport-autoreport.service: Consumed 3.783s CPU time.

ProblemType: Bug
DistroRelease: Ubuntu 22.10
Package: ubuntu-advantage-tools 27.12~22.10.1
Uname: Linux 6.1.4-060104-generic x86_64
ApportVersion: 2.23.1-0ubuntu3
Architecture: amd64
CasperMD5CheckResult: pass
CurrentDesktop: ubuntu:GNOME
Date: Thu Jan 12 08:08:15 2023
InstallationDate: Installed on 2022-05-23 (233 days ago)
InstallationMedia: Ubuntu 22.04 LTS "Jammy Jellyfish" - Release amd64 (20220419)
RebootRequiredPkgs: Error: path contained symlinks.
SourcePackage: ubuntu-advantage-tools
UpgradeStatus: Upgraded to kinetic on 2023-01-04 (7 days ago)
cloud-id.txt-error: Invalid command specified 'cloud-id'.
jobs-status.json: {"update_messaging": {"last_run": "2023-01-11T10:35:00.075554+00:00", "next_run": "2023-01-11T16:35:00.075554+00:00"}, "update_status": {"last_run": "2023-01-11T10:35:00.075554+00:00", "next_run": "2023-01-11T22:35:00.075554+00:00"}, "metering": {"last_run": "2023-01-11T10:35:00.075554+00:00", "next_run": "2023-01-11T14:35:00.075554+00:00"}}
livepatch-status.txt-error: Failed running command '/snap/bin/canonical-livepatch status' [exit(1)]. Message: error executing status: livepatchd error: The platform Ubuntu 22.10 is not supported. exiting.

[Grant Orndorff (orndorffgrant)]

Hello jaromir-obr,

Thank you for taking the time to report this bug! It looks like the command `ua security-status --format=json` is failing, but it isn't evident why from the logs attached.

Can you please run in your terminal `sudo ua security-status --format=json` and report what the output is? Also please upload the contents of /var/log/ubuntu-advantage.log after running the command.

Thanks again,
Grant

[Grant Orndorff (orndorffgrant)]

Thank you jaromir-obr!

Unfortunately, since the command succeeded when run manually, the logs and output don't provide much information. And I've tried to reproduce this without success. Since we don't have a reproducer or enough details about the error, I'll mark this incomplete for ubuntu-advantage-tools.

At the very least, though, I think update-manager should handle this kind of error more gracefully. I'll move this bug to update-manager to represent that.

Specifically, for update-manager, if something goes wrong early enough in the `ua security-status --format=json` command, then the output won't be json. To cover this, we'll need a try/except around the json.loads call.

Longer term, we should probably replace this `ua security-status --format=json` command with using the more recent pro client python api: https://github.com/canonical/ubuntu-advantage-client/blob/main/docs/references/api.md#upropackagesupdatesv1

[Gyurkan Mehmed (gm93)]

Hi, I am also getting error related to this when using update-manager:
ua: error: unrecognized arguments: security-status --format=json
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/UpdateManager/backend/InstallBackendAptdaemon.py", line 448, in _on_finished
    self._action_done(action,
  File "/usr/lib/python3/dist-packages/UpdateManager/backend/__init__.py", line 365, in _action_done
    self.window_main.start_available()
  File "/usr/lib/python3/dist-packages/UpdateManager/UpdateManager.py", line 241, in start_available
    self.refresh_cache()
  File "/usr/lib/python3/dist-packages/UpdateManager/UpdateManager.py", line 449, in refresh_cache
    self._get_ua_security_status()
  File "/usr/lib/python3/dist-packages/UpdateManager/UpdateManager.py", line 285, in _get_ua_security_status
    s = json.load(p.stdout)
  File "/usr/lib/python3.10/json/__init__.py", line 293, in load
    return loads(fp.read(),
  File "/usr/lib/python3.10/json/__init__.py", line 346, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.10/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.10/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

[Gyurkan Mehmed (gm93)]

Hmm I found out that when using update-manager - ua is ran as non-root user and that causes the issue as it tries to use status.json which can be used when running ua as root only. Any ideas how to resolve the issue?

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.