Make sure the device reboots after snap refresh/revert tests (BugFix) (…

…#1124)

* Provide more information in Snapd._poll_change()

In order to get more data in the job logs, Snapd._poll_change() is
amended to do the following:

- Outuput info about the task when it's in the "Wait" status (and
return, as it likely means the snap is waiting for a reboot)
- Outuput info about the task when it's in the "Error" status
- If an ongoing task (status = "Doing") has a progress label assigned,
print the current progress in % (similar to what's done in the snap
command itself). This is useful to investigate if tasks like snap
downloads have frozen at some point.

Unit tests for the _poll_change() method are also added.

* Return the response when calling Snapd.install() and remove()

In order to be more consistent with other methods, these methods now
return the response.

Unit tests are added for these methods as well.

* Add timeout argument to snap_update_test.py and output more info

Script can now be called with the --timeout argument (defaulting to 300
seconds).

This is passed to the Snapd() instance, along with the verbosity flag
that enables Snapd._info() to output useful information for the job
logs.

* Replace logging with print statements in snap_update_test.py

Print statements make more sense because any information captured during
the snap commands should be made available to the Checkbox results later
on.

* Modify snap-refresh-revert jobs

- Reboot commands are moved inside the snapd/snap-[refresh|revert]-*
jobs. This is to make sure the device is rebooted right after the
command is issued (with previous version, some other jobs might be run
between the refresh/revert command and the reboot command, making the
test results unreliable)
- As a result, the snapd/snap-[refresh|revert]-* are flagged as noreturn
- Because Checkbox does not capture the outputs of noreturn jobs, their
outputs are stored in the $PLAINBOX_SESSION_SHARE directory using `tee`
- Reboot jobs are replaced with attachment jobs to upload the outputs
along with the submissions

* Replace reboot jobs with log attachment jobs in snap-refresh-revert test plan

Fix CHECKBOX-1264

* Fix snapd unit tests

* Add unit test to improve coverage

* Fix unit test

* Add template-id to log-attach jobs

Following the work done in commit
b8befd8, add template-id to the new
templates that don't have them set yet.

checkbox-support/checkbox_support/snap_utils/snapd.py

@@ -89,8 +89,27 @@ def _poll_change(self, change_id):
                 abort_result = self._abort_change(change_id)
                 raise AsyncException(status, abort_result)
             for task in self.tasks(change_id):
-                if task['status'] == 'Doing':
-                    self._info(task['summary'])
+                if task["status"] == "Doing":
+                    if task["progress"]["label"]:
+                        done = task["progress"]["done"]
+                        total = task["progress"]["total"]
+                        total_progress = done / total * 100
+                        message = "({}) {} ({:.1f}%)".format(
+                            task["status"], task["summary"], total_progress
+                        )
+                    else:
+                        message = "({}) {}".format(
+                            task["status"], task["summary"]
+                        )
+                    self._info(message)
+                elif task["status"] == "Wait":
+                    message = "({}) {}".format(task["status"], task["summary"])
+                    self._info(message)
+                    return
+                elif task["status"] == "Error":
+                    message = "({}) {}".format(task["status"], task["summary"])
+                    self._info(message)
+                    raise AsyncException(task.get("log"))
             time.sleep(self._poll_interval)
 
     def _abort_change(self, change_id):
@@ -110,23 +129,25 @@ def list(self, snap=None):
                 return None
             raise
 
-    def install(self, snap, channel='stable', revision=None):
-        path = self._snaps + '/' + snap
-        data = {'action': 'install', 'channel': channel}
+    def install(self, snap, channel="stable", revision=None):
+        path = self._snaps + "/" + snap
+        data = {"action": "install", "channel": channel}
         if revision is not None:
-            data['revision'] = revision
+            data["revision"] = revision
         r = self._post(path, json.dumps(data))
-        if r['type'] == 'async' and r['status'] == 'Accepted':
-            self._poll_change(r['change'])
+        if r["type"] == "async" and r["status"] == "Accepted":
+            self._poll_change(r["change"])
+        return r
 
     def remove(self, snap, revision=None):
-        path = self._snaps + '/' + snap
-        data = {'action': 'remove'}
+        path = self._snaps + "/" + snap
+        data = {"action": "remove"}
         if revision is not None:
-            data['revision'] = revision
+            data["revision"] = revision
         r = self._post(path, json.dumps(data))
-        if r['type'] == 'async' and r['status'] == 'Accepted':
-            self._poll_change(r['change'])
+        if r["type"] == "async" and r["status"] == "Accepted":
+            self._poll_change(r["change"])
+        return r
 
     def find(self, search, exact=False):
         if exact:

checkbox-support/checkbox_support/snap_utils/tests/test_snapd.py

@@ -0,0 +1,150 @@
+import json
+
+from unittest import TestCase
+from unittest.mock import patch, MagicMock, ANY
+
+from checkbox_support.snap_utils.snapd import AsyncException, Snapd
+
+
+class TestSnapd(TestCase):
+    @patch("checkbox_support.snap_utils.snapd.time.sleep")
+    @patch("checkbox_support.snap_utils.snapd.time.time")
+    def test_poll_change_done(self, mock_time, mock_sleep):
+        mock_self = MagicMock()
+        mock_self.change.return_value = "Done"
+        self.assertTrue(Snapd._poll_change(mock_self, 0))
+
+    @patch("checkbox_support.snap_utils.snapd.time.sleep")
+    @patch("checkbox_support.snap_utils.snapd.time.time")
+    def test_poll_change_timeout(self, mock_time, mock_sleep):
+        mock_time.side_effect = [0, 1]
+        mock_self = MagicMock()
+        mock_self._task_timeout = 0
+        with self.assertRaises(AsyncException):
+            Snapd._poll_change(mock_self, 0)
+
+    @patch("checkbox_support.snap_utils.snapd.time.sleep")
+    @patch("checkbox_support.snap_utils.snapd.time.time")
+    def test_poll_change_doing(self, mock_time, mock_sleep):
+        mock_time.return_value = 0
+        mock_self = MagicMock()
+        mock_self.change.side_effect = ["Doing", "Done"]
+        mock_self._task_timeout = 0
+        mock_self.tasks.return_value = [
+            {
+                "summary": "Test",
+                "status": "Doing",
+                "progress": {"label": "", "done": 1, "total": 1},
+            },
+        ]
+        Snapd._poll_change(mock_self, 0)
+        message = "(Doing) Test"
+        mock_self._info.assert_called_with(message)
+        mock_self.change.side_effect = ["Doing", "Done"]
+        mock_self.tasks.return_value = [
+            {
+                "summary": "Test",
+                "status": "Doing",
+                "progress": {"label": "Downloading", "done": 1, "total": 2},
+            },
+        ]
+        Snapd._poll_change(mock_self, 0)
+        message = "(Doing) Test (50.0%)"
+        mock_self._info.assert_called_with(message)
+
+    @patch("checkbox_support.snap_utils.snapd.time.sleep")
+    @patch("checkbox_support.snap_utils.snapd.time.time")
+    def test_poll_change_wait(self, mock_time, mock_sleep):
+        mock_time.return_value = 0
+        mock_self = MagicMock()
+        mock_self.change.return_value = "Wait"
+        mock_self._task_timeout = 0
+        mock_self.tasks.return_value = [
+            {
+                "summary": "Test",
+                "status": "Wait",
+                "progress": {"label": "", "done": 1, "total": 1},
+            },
+        ]
+        Snapd._poll_change(mock_self, 0)
+        message = "(Wait) Test"
+        mock_self._info.assert_called_with(message)
+
+    @patch("checkbox_support.snap_utils.snapd.time.sleep")
+    @patch("checkbox_support.snap_utils.snapd.time.time")
+    def test_poll_change_error(self, mock_time, mock_sleep):
+        mock_time.return_value = 0
+        mock_self = MagicMock()
+        mock_self.change.return_value = "Error"
+        mock_self._task_timeout = 0
+        mock_self.tasks.return_value = [
+            {
+                "summary": "Test",
+                "status": "Error",
+                "progress": {"label": "", "done": 1, "total": 1},
+            },
+        ]
+        message = "(Error) Test"
+        with self.assertRaises(AsyncException):
+            Snapd._poll_change(mock_self, 0)
+        mock_self._info.assert_called_with(message)
+
+    def test_install_accepted(self):
+        mock_self = MagicMock()
+        mock_self._poll_change = MagicMock()
+        mock_self._post.return_value = {
+            "type": "async",
+            "status": "Accepted",
+            "change": "1",
+        }
+        response = Snapd.install(mock_self, "test")
+        self.assertEqual(response, mock_self._post.return_value)
+        mock_self._poll_change.assert_called_with("1")
+
+    def test_install_other(self):
+        mock_self = MagicMock()
+        mock_self._poll_change = MagicMock()
+        mock_self._post.return_value = {
+            "type": "async",
+            "status": "Other",
+            "change": "1",
+        }
+        response = Snapd.install(mock_self, "test")
+        self.assertEqual(response, mock_self._post.return_value)
+        mock_self._poll_change.assert_not_called()
+
+    def test_install_revision(self):
+        mock_self = MagicMock()
+        Snapd.install(mock_self, "test", revision="1")
+        test_data = {"action": "install", "channel": "stable", "revision": "1"}
+        mock_self._post.assert_called_with(ANY, json.dumps(test_data))
+
+    def test_remove_accepted(self):
+        mock_self = MagicMock()
+        mock_self._poll_change = MagicMock()
+        mock_self._post.return_value = {
+            "type": "async",
+            "status": "Accepted",
+            "change": "1",
+        }
+        response = Snapd.remove(mock_self, "test")
+        self.assertEqual(response, mock_self._post.return_value)
+        mock_self._poll_change.assert_called_with("1")
+
+    def test_remove_other(self):
+        mock_self = MagicMock()
+        mock_self._poll_change = MagicMock()
+        mock_self._post.return_value = {
+            "type": "async",
+            "status": "Other",
+            "change": "1",
+        }
+        response = Snapd.remove(mock_self, "test")
+        self.assertEqual(response, mock_self._post.return_value)
+        mock_self._poll_change.assert_not_called()
+
+    def test_remove_revision(self):
+        mock_self = MagicMock()
+        Snapd.remove(mock_self, "test", revision="1")
+        test_data = {"action": "remove", "revision": "1"}
+        mock_self._post.assert_called_with(ANY, json.dumps(test_data))