Merge pull request #1975 from ogayot/v2-systems-log-error

storage: log snapd response text when v2/systems/{system} or v2/snaps/{snap} fails

apt-deps.txt

@@ -43,6 +43,7 @@ python3-pytest
 python3-pytest-xdist
 python3-pyudev
 python3-requests
+python3-requests-mock
 python3-requests-unixsocket
 python3-setuptools
 python3-systemd

subiquity/server/controllers/filesystem.py

@@ -26,6 +26,7 @@ from typing import Any, Callable, Dict, List, Optional, Union
 
 import attr
 import pyudev
+import requests
 from curtin import swap
 from curtin.commands.extract import AbstractSourceHandler
 from curtin.storage_config import ptable_part_type_to_flag
@@ -342,6 +343,9 @@ class FilesystemController(SubiquityController, FilesystemManipulator):
             return None
         try:
             system = await self.app.snapdapi.v2.systems[label].GET()
+        except requests.exceptions.HTTPError as http_err:
+            log.warning("v2/systems/%s returned %s", label, http_err.response.text)
+            raise
         finally:
             await self._unmount_systems_dir()
         log.debug("got system %s", system)

subiquity/server/controllers/refresh.py

@@ -214,9 +214,15 @@ class RefreshController(SubiquityController):
 
     @with_context()
     async def start_update(self, context):
-        change_id = await self.app.snapdapi.v2.snaps[self.snap_name].POST(
-            SnapActionRequest(action=SnapAction.REFRESH, ignore_running=True)
-        )
+        try:
+            change_id = await self.app.snapdapi.v2.snaps[self.snap_name].POST(
+                SnapActionRequest(action=SnapAction.REFRESH, ignore_running=True)
+            )
+        except requests.exceptions.HTTPError as http_err:
+            log.warning(
+                "v2/snaps/%s returned %s", self.snap_name, http_err.response.text
+            )
+            raise
         context.description = "change id: {}".format(change_id)
         return change_id
 

subiquity/server/controllers/tests/test_filesystem.py

@@ -19,6 +19,8 @@ import uuid
 from unittest import IsolatedAsyncioTestCase, mock
 
 import jsonschema
+import requests
+import requests_mock
 from curtin.commands.extract import TrivialSourceHandler
 from jsonschema.validators import validator_for
 
@@ -61,7 +63,7 @@ from subiquity.server.controllers.filesystem import (
     VariationInfo,
 )
 from subiquity.server.dryrun import DRConfig
-from subiquitycore.snapd import AsyncSnapd, get_fake_connection
+from subiquitycore.snapd import AsyncSnapd, SnapdConnection, get_fake_connection
 from subiquitycore.tests.mocks import make_app
 from subiquitycore.tests.parameterized import parameterized
 from subiquitycore.tests.util import random_string
@@ -414,6 +416,39 @@ class TestSubiquityControllerFilesystem(IsolatedAsyncioTestCase):
 
         JsonValidator.check_schema(FilesystemController.autoinstall_schema)
 
+    async def test__get_system_api_error_logged(self):
+        mount_mock = mock.patch.object(self.fsc, "_mount_systems_dir")
+        unmount_mock = mock.patch.object(self.fsc, "_unmount_systems_dir")
+
+        self.app.snapdapi = snapdapi.make_api_client(
+            AsyncSnapd(SnapdConnection(root="/inexistent", sock="snapd"))
+        )
+        json_body = {
+            "type": "error",
+            "status-code": 500,
+            "status": "Internal Server Error",
+            "result": {
+                "message": "cannot load assertions for label ...",
+            },
+        }
+        requests_mocker = requests_mock.Mocker()
+        requests_mocker.get(
+            "http+unix://snapd/v2/systems/enhanced-secureboot-desktop",
+            json=json_body,
+            status_code=500,
+        )
+
+        with mount_mock, unmount_mock, requests_mocker:
+            with self.assertRaises(requests.exceptions.HTTPError):
+                with self.assertLogs(
+                    "subiquity.server.controllers.filesystem", level="WARNING"
+                ) as logs:
+                    await self.fsc._get_system(
+                        variation_name="minimal", label="enhanced-secureboot-desktop"
+                    )
+
+            self.assertIn("cannot load assertions for label", logs.output[0])
+
 
 class TestGuided(IsolatedAsyncioTestCase):
     boot_expectations = [

subiquity/server/controllers/tests/test_refresh.py

@@ -16,12 +16,14 @@
 from unittest import mock
 
 import jsonschema
+import requests
+import requests_mock
 from jsonschema.validators import validator_for
 
 from subiquity.server import snapdapi
 from subiquity.server.controllers import refresh as refresh_mod
 from subiquity.server.controllers.refresh import RefreshController, SnapChannelSource
-from subiquitycore.snapd import AsyncSnapd, get_fake_connection
+from subiquitycore.snapd import AsyncSnapd, SnapdConnection, get_fake_connection
 from subiquitycore.tests import SubiTestCase
 from subiquitycore.tests.mocks import make_app
 
@@ -111,3 +113,31 @@ class TestRefreshController(SubiTestCase):
         )
 
         JsonValidator.check_schema(RefreshController.autoinstall_schema)
+
+    async def test_start_update_api_error_logged(self):
+        self.app.snapdapi = snapdapi.make_api_client(
+            AsyncSnapd(SnapdConnection(root="/inexistent", sock="snapd"))
+        )
+        json_body = {
+            "type": "error",
+            "status-code": 409,
+            "status": "Conflict",
+            "result": {
+                "message": 'snap "subiquity" has "update" change in progress',
+            },
+        }
+        requests_mocker = requests_mock.Mocker()
+        requests_mocker.post(
+            "http+unix://snapd/v2/snaps/subiquity",
+            json=json_body,
+            status_code=409,
+        )
+
+        with requests_mocker:
+            with self.assertRaises(requests.exceptions.HTTPError):
+                with self.assertLogs(
+                    "subiquity.server.controllers.refresh", level="WARNING"
+                ) as logs:
+                    await self.rc.start_update()
+
+            self.assertIn('snap \\"subiquity\\" has \\"update\\"', logs.output[0])