Merge pull request #614 from mwhudson/reporting

structured reporting

subiquity/controllers/__init__.py

@@ -22,6 +22,7 @@ from .proxy import ProxyController
 from .mirror import MirrorController
 from .network import NetworkController
 from .refresh import RefreshController
+from .reporting import ReportingController
 from .snaplist import SnapListController
 from .ssh import SSHController
 from .welcome import WelcomeController
@@ -36,6 +37,7 @@ __all__ = [
     'MirrorController',
     'NetworkController',
     'RefreshController',
+    'ReportingController',
     'SnapListController',
     'SSHController',
     'WelcomeController',

subiquity/controllers/error.py

@@ -94,6 +94,7 @@ class ErrorReport(metaclass=urwid.MetaSignals):
     pr = attr.ib()
     state = attr.ib()
     _file = attr.ib()
+    _context = attr.ib()
 
     meta = attr.ib(default=attr.Factory(dict))
     uploader = attr.ib(default=None)
@@ -110,7 +111,8 @@ class ErrorReport(metaclass=urwid.MetaSignals):
 
         r = cls(
             controller=controller, base=base, pr=pr, file=crash_file,
-            state=ErrorReportState.INCOMPLETE)
+            state=ErrorReportState.INCOMPLETE,
+            context=controller.context.child(base))
         r.set_meta("kind", kind.name)
         return r
 
@@ -119,7 +121,8 @@ class ErrorReport(metaclass=urwid.MetaSignals):
         base = os.path.splitext(os.path.basename(fpath))[0]
         report = cls(
             controller, base, pr=apport.Report(date='???'),
-            state=ErrorReportState.LOADING, file=open(fpath, 'rb'))
+            state=ErrorReportState.LOADING, file=open(fpath, 'rb'),
+            context=controller.context.child(base))
         try:
             fp = open(report.meta_path, 'r')
         except FileNotFoundError:
@@ -130,8 +133,6 @@ class ErrorReport(metaclass=urwid.MetaSignals):
         return report
 
     def add_info(self, _bg_attach_hook, wait=False):
-        log.debug("begin adding info for report %s", self.base)
-
         def _bg_add_info():
             _bg_attach_hook()
             # Add basic info to report.
@@ -158,39 +159,38 @@ class ErrorReport(metaclass=urwid.MetaSignals):
             self.pr.write(self._file)
 
         async def add_info():
-            log.debug("adding info for report %s", self.base)
+            with self._context.child("add_info"):
-            try:
+                try:
-                await run_in_thread(_bg_add_info)
+                    await run_in_thread(_bg_add_info)
-            except Exception:
+                except Exception:
-                self.state = ErrorReportState.ERROR_GENERATING
+                    self.state = ErrorReportState.ERROR_GENERATING
-                log.exception("adding info to problem report failed")
+                    log.exception("adding info to problem report failed")
-            else:
+                else:
-                self.state = ErrorReportState.DONE
+                    self.state = ErrorReportState.DONE
-            self._file.close()
+                self._file.close()
-            self._file = None
+                self._file = None
-            urwid.emit_signal(self, "changed")
+                urwid.emit_signal(self, "changed")
         if wait:
-            _bg_add_info()
+            with self._context.child("add_info"):
+                _bg_add_info()
         else:
             schedule_task(add_info())
 
     async def load(self):
-        log.debug("loading report %s", self.base)
+        with self._context.child("load"):
-        # Load report from disk in background.
+            # Load report from disk in background.
-        try:
+            try:
-            await run_in_thread(self.pr.load, self._file)
+                await run_in_thread(self.pr.load, self._file)
-        except Exception:
+            except Exception:
-            log.exception("loading problem report failed")
+                log.exception("loading problem report failed")
-            self.state = ErrorReportState.ERROR_LOADING
+                self.state = ErrorReportState.ERROR_LOADING
-        else:
+            else:
-            log.debug("done loading report %s", self.base)
+                self.state = ErrorReportState.DONE
-            self.state = ErrorReportState.DONE
         self._file.close()
         self._file = None
         urwid.emit_signal(self, "changed")
 
     def upload(self):
-        log.debug("starting upload for %s", self.base)
         uploader = self.uploader = Upload(
             controller=self.controller, bytes_to_send=1)
 
@@ -239,16 +239,17 @@ class ErrorReport(metaclass=urwid.MetaSignals):
             return response.text.split()[0]
 
         async def upload():
-            try:
+            with self._context.child("upload") as context:
-                oops_id = await run_in_thread(_bg_upload)
+                try:
-            except requests.exceptions.RequestException:
+                    oops_id = await run_in_thread(_bg_upload)
-                log.exception("upload for %s failed", self.base)
+                except requests.exceptions.RequestException:
-            else:
+                    log.exception("upload for %s failed", self.base)
-                log.debug("finished upload for %s, %r", self.base, oops_id)
+                else:
-                self.set_meta("oops-id", oops_id)
+                    self.set_meta("oops-id", oops_id)
-            uploader.stop()
+                    context.description = oops_id
-            self.uploader = None
+                uploader.stop()
-            urwid.emit_signal(self, 'changed')
+                self.uploader = None
+                urwid.emit_signal(self, 'changed')
 
         urwid.emit_signal(self, 'changed')
         uploader.start()

subiquity/controllers/filesystem.py

@@ -86,12 +86,8 @@ class FilesystemController(BaseController):
             probe_types = None
             fname = 'probe-data.json'
             key = "ProbeData"
-        block_discover_log.exception(
-            "probing restricted=%s", restricted)
         storage = await run_in_thread(
             self.app.prober.get_storage, probe_types)
-        block_discover_log.info(
-            "probing successful restricted=%s", restricted)
         fpath = os.path.join(self.app.block_log_dir, fname)
         with open(fpath, 'w') as fp:
             json.dump(storage, fp, indent=4)
@@ -99,24 +95,28 @@ class FilesystemController(BaseController):
         self.model.load_probe_data(storage)
 
     async def _probe(self):
-        self._crash_reports = {}
+        with self.context.child("_probe") as context:
-        if isinstance(self.ui.body, ProbingFailed):
+            self._crash_reports = {}
-            self.ui.set_body(SlowProbing(self))
+            if isinstance(self.ui.body, ProbingFailed):
-            schedule_task(self._wait_for_probing())
+                self.ui.set_body(SlowProbing(self))
-        for (restricted, kind) in [
+                schedule_task(self._wait_for_probing())
-                (False, ErrorReportKind.BLOCK_PROBE_FAIL),
+            for (restricted, kind) in [
-                (True,  ErrorReportKind.DISK_PROBE_FAIL),
+                    (False, ErrorReportKind.BLOCK_PROBE_FAIL),
-                ]:
+                    (True,  ErrorReportKind.DISK_PROBE_FAIL),
-            try:
+                    ]:
-                await self._probe_once_task.start(restricted)
+                try:
-                await asyncio.wait_for(self._probe_once_task.task, 5.0)
+                    desc = "restricted={}".format(restricted)
-            except Exception:
+                    with context.child("probe_once", desc):
-                block_discover_log.exception(
+                        await self._probe_once_task.start(restricted)
-                    "block probing failed restricted=%s", restricted)
+                        await asyncio.wait_for(self._probe_once_task.task, 5.0)
-                self._crash_reports[restricted] = self.app.make_apport_report(
+                except Exception:
-                    kind, "block probing", interrupt=False)
+                    block_discover_log.exception(
-                continue
+                        "block probing failed restricted=%s", restricted)
-            break
+                    report = self.app.make_apport_report(
+                        kind, "block probing", interrupt=False)
+                    self._crash_reports[restricted] = report
+                    continue
+                break
 
     def start(self):
         self._start_task = schedule_task(self._start())

subiquity/controllers/installprogress.py

@@ -14,6 +14,7 @@
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
 import asyncio
+import contextlib
 import datetime
 import logging
 import os
@@ -36,6 +37,7 @@ from subiquitycore.async_helpers import (
     run_in_thread,
     schedule_task,
     )
+from subiquitycore.context import Status
 from subiquitycore.controller import BaseController
 from subiquitycore.utils import (
     arun_command,
@@ -76,14 +78,15 @@ class TracebackExtractor:
             self.traceback.append(line)
 
 
-def install_step(label):
+def install_step(label, level=None, childlevel=None):
     def decorate(meth):
-        async def decorated(self):
+        name = meth.__name__
-            self._install_event_start(label)
+
-            try:
+        async def decorated(self, context):
-                await meth(self)
+            manager = self.install_context(
-            finally:
+                context, name, label, level, childlevel)
-                self._install_event_finish()
+            with manager as subcontext:
+                await meth(self, subcontext)
         return decorated
     return decorate
 
@@ -107,9 +110,10 @@ class InstallProgressController(BaseController):
         self._event_syslog_identifier = 'curtin_event.%s' % (os.getpid(),)
         self._log_syslog_identifier = 'curtin_log.%s' % (os.getpid(),)
         self.tb_extractor = TracebackExtractor()
+        self.curtin_context = None
 
     def start(self):
-        self.install_task = schedule_task(self.install())
+        self.install_task = schedule_task(self.install(self.context))
 
     def tpath(self, *path):
         return os.path.join(self.model.target, *path)
@@ -117,14 +121,15 @@ class InstallProgressController(BaseController):
     def curtin_error(self):
         self.install_state = InstallState.ERROR
         kw = {}
+        if sys.exc_info()[0] is not None:
+            log.exception("curtin_error")
+            self.progress_view.add_log_line(traceback.format_exc())
         if self.tb_extractor.traceback:
             kw["Traceback"] = "\n".join(self.tb_extractor.traceback)
         crash_report = self.app.make_apport_report(
             ErrorReportKind.INSTALL_FAIL, "install failed", interrupt=False,
             **kw)
         self.progress_view.spinner.stop()
-        if sys.exc_info()[0] is not None:
-            self.progress_view.add_log_line(traceback.format_exc())
         self.progress_view.set_status(('info_error',
                                        _("An error has occurred")))
         self.start_ui()
@@ -140,30 +145,46 @@ class InstallProgressController(BaseController):
         elif event['SYSLOG_IDENTIFIER'] == self._log_syslog_identifier:
             self.curtin_log(event)
 
+    @contextlib.contextmanager
+    def install_context(self, context, name, description, level, childlevel):
+        self._install_event_start(description)
+        try:
+            subcontext = context.child(name, description, level, childlevel)
+            with subcontext:
+                yield subcontext
+        finally:
+            self._install_event_finish()
+
     def _install_event_start(self, message):
-        log.debug("_install_event_start %s", message)
         self.progress_view.add_event(self._event_indent + message)
         self._event_indent += "  "
         self.progress_view.spinner.start()
 
     def _install_event_finish(self):
         self._event_indent = self._event_indent[:-2]
-        log.debug("_install_event_finish %r", self._event_indent)
         self.progress_view.spinner.stop()
 
     def curtin_event(self, event):
-        e = {}
+        e = {
+            "EVENT_TYPE": "???",
+            "MESSAGE": "???",
+            "NAME": "???",
+            "RESULT": "???",
+            }
+        prefix = "CURTIN_"
         for k, v in event.items():
-            if k.startswith("CURTIN_"):
+            if k.startswith(prefix):
-                e[k] = v
+                e[k[len(prefix):]] = v
-        log.debug("curtin_event received %r", e)
+        event_type = e["EVENT_TYPE"]
-        event_type = event.get("CURTIN_EVENT_TYPE")
-        if event_type not in ['start', 'finish']:
-            return
         if event_type == 'start':
-            self._install_event_start(event.get("CURTIN_MESSAGE", "??"))
+            self._install_event_start(e["MESSAGE"])
+            if self.curtin_context is not None:
+                self.curtin_context.child(e["NAME"], e["MESSAGE"]).enter()
         if event_type == 'finish':
             self._install_event_finish()
+            status = getattr(Status, e["RESULT"], Status.WARN)
+            if self.curtin_context is not None:
+                self.curtin_context.child(e["NAME"], e["MESSAGE"]).exit(status)
 
     def curtin_log(self, event):
         log_line = event['MESSAGE']
@@ -222,9 +243,11 @@ class InstallProgressController(BaseController):
 
         return curtin_cmd
 
-    async def curtin_install(self):
+    @install_step("installing system", level="INFO", childlevel="DEBUG")
+    async def curtin_install(self, context):
         log.debug('curtin_install')
         self.install_state = InstallState.RUNNING
+        self.curtin_context = context
 
         self.journal_listener_handle = self.start_journald_listener(
             [self._event_syslog_identifier, self._log_syslog_identifier],
@@ -245,19 +268,19 @@ class InstallProgressController(BaseController):
     def cancel(self):
         pass
 
-    async def install(self):
+    async def install(self, context):
         try:
             await asyncio.wait(
                 {e.wait() for e in self.model.install_events})
 
-            await self.curtin_install()
+            await self.curtin_install(context)
 
             await asyncio.wait(
                 {e.wait() for e in self.model.postinstall_events})
 
-            await self.drain_curtin_events()
+            await self.drain_curtin_events(context)
 
-            await self.postinstall()
+            await self.postinstall(context)
 
             self.ui.set_header(_("Installation complete!"))
             self.progress_view.set_status(_("Finished install!"))
@@ -265,10 +288,10 @@ class InstallProgressController(BaseController):
 
             if self.model.network.has_network:
                 self.progress_view.update_running()
-                await self.run_unattended_upgrades()
+                await self.run_unattended_upgrades(context)
                 self.progress_view.update_done()
 
-            await self.copy_logs_to_target()
+            await self.copy_logs_to_target(context)
         except Exception:
             self.curtin_error()
 
@@ -276,26 +299,28 @@ class InstallProgressController(BaseController):
 
         self.reboot()
 
-    async def drain_curtin_events(self):
+    async def drain_curtin_events(self, context):
         waited = 0.0
         while self._event_indent and waited < 5.0:
             await asyncio.sleep(0.1)
             waited += 0.1
         log.debug("waited %s seconds for events to drain", waited)
+        self.curtin_context = None
 
-    @install_step("final system configuration")
+    @install_step(
-    async def postinstall(self):
+        "final system configuration", level="INFO", childlevel="DEBUG")
-        await self.configure_cloud_init()
+    async def postinstall(self, context):
+        await self.configure_cloud_init(context)
         if self.model.ssh.install_server:
-            await self.install_openssh()
+            await self.install_openssh(context)
-        await self.restore_apt_config()
+        await self.restore_apt_config(context)
 
     @install_step("configuring cloud-init")
-    async def configure_cloud_init(self):
+    async def configure_cloud_init(self, context):
         await run_in_thread(self.model.configure_cloud_init)
 
     @install_step("installing openssh")
-    async def install_openssh(self):
+    async def install_openssh(self, context):
         if self.opts.dry_run:
             cmd = ["sleep", str(2/self.app.scale_factor)]
         else:
@@ -307,7 +332,7 @@ class InstallProgressController(BaseController):
         await arun_command(self.logged_command(cmd), check=True)
 
     @install_step("restoring apt configuration")
-    async def restore_apt_config(self):
+    async def restore_apt_config(self, context):
         if self.opts.dry_run:
             cmds = [["sleep", str(1/self.app.scale_factor)]]
         else:
@@ -325,7 +350,7 @@ class InstallProgressController(BaseController):
             await arun_command(self.logged_command(cmd), check=True)
 
     @install_step("downloading and installing security updates")
-    async def run_unattended_upgrades(self):
+    async def run_unattended_upgrades(self, context):
         target_tmp = os.path.join(self.model.target, "tmp")
         os.makedirs(target_tmp, exist_ok=True)
         apt_conf = tempfile.NamedTemporaryFile(
@@ -362,7 +387,7 @@ class InstallProgressController(BaseController):
                 ], check=True))
 
     @install_step("copying logs to installed system")
-    async def copy_logs_to_target(self):
+    async def copy_logs_to_target(self, context):
         if self.opts.dry_run:
             if 'copy-logs-fail' in self.app.debug_flags:
                 raise PermissionError()

subiquity/controllers/mirror.py

@@ -56,32 +56,33 @@ class MirrorController(BaseController):
             schedule_task(self.lookup())
 
     async def lookup(self):
-        try:
+        with self.context.child("lookup"):
-            response = await run_in_thread(
+            try:
-                requests.get, "https://geoip.ubuntu.com/lookup")
+                response = await run_in_thread(
-            response.raise_for_status()
+                    requests.get, "https://geoip.ubuntu.com/lookup")
-        except requests.exceptions.RequestException:
+                response.raise_for_status()
-            log.exception("geoip lookup failed")
+            except requests.exceptions.RequestException:
-            self.check_state = CheckState.FAILED
+                log.exception("geoip lookup failed")
-            return
+                self.check_state = CheckState.FAILED
-        try:
+                return
-            e = ElementTree.fromstring(response.text)
+            try:
-        except ElementTree.ParseError:
+                e = ElementTree.fromstring(response.text)
-            log.exception("parsing %r failed", response.text)
+            except ElementTree.ParseError:
-            self.check_state = CheckState.FAILED
+                log.exception("parsing %r failed", response.text)
-            return
+                self.check_state = CheckState.FAILED
-        cc = e.find("CountryCode")
+                return
-        if cc is None:
+            cc = e.find("CountryCode")
-            log.debug("no CountryCode found in %r", response.text)
+            if cc is None:
-            self.check_state = CheckState.FAILED
+                log.debug("no CountryCode found in %r", response.text)
-            return
+                self.check_state = CheckState.FAILED
-        cc = cc.text.lower()
+                return
-        if len(cc) != 2:
+            cc = cc.text.lower()
-            log.debug("bogus CountryCode found in %r", response.text)
+            if len(cc) != 2:
-            self.check_state = CheckState.FAILED
+                log.debug("bogus CountryCode found in %r", response.text)
-            return
+                self.check_state = CheckState.FAILED
-        self.check_state = CheckState.DONE
+                return
-        self.model.set_country(cc)
+            self.check_state = CheckState.DONE
+            self.model.set_country(cc)
 
     def start_ui(self):
         self.check_state = CheckState.DONE

subiquity/controllers/refresh.py

@@ -72,30 +72,32 @@ class RefreshController(BaseController):
         return task.result()
 
     async def configure_snapd(self):
-        log.debug("configure_snapd")
+        with self.context.child("configure_snapd") as context:
-        try:
+            with context.child("get_details") as subcontext:
-            r = await self.app.snapd.get(
+                try:
-                'v2/snaps/{snap_name}'.format(snap_name=self.snap_name))
+                    r = await self.app.snapd.get(
-        except requests.exceptions.RequestException:
+                        'v2/snaps/{snap_name}'.format(
-            log.exception("getting snap details")
+                            snap_name=self.snap_name))
-            return
+                except requests.exceptions.RequestException:
-        self.current_snap_version = r['result']['version']
+                    log.exception("getting snap details")
-        for k in 'channel', 'revision', 'version':
+                    return
-            self.app.note_data_for_apport(
+                self.current_snap_version = r['result']['version']
-                "Snap" + k.title(), r['result'][k])
+                for k in 'channel', 'revision', 'version':
-        log.debug(
+                    self.app.note_data_for_apport(
-            "current version of snap is: %r",
+                        "Snap" + k.title(), r['result'][k])
-            self.current_snap_version)
+                subcontext.description = "current version of snap is: %r" % (
-        channel = self.get_refresh_channel()
+                    self.current_snap_version)
-        log.debug("switching %s to %s", self.snap_name, channel)
+            channel = self.get_refresh_channel()
-        try:
+            desc = "switching {} to {}".format(self.snap_name, channel)
-            await self.app.snapd.post_and_wait(
+            with context.child("switching", desc) as subcontext:
-                'v2/snaps/{}'.format(self.snap_name),
+                try:
-                {'action': 'switch', 'channel': channel})
+                    await self.app.snapd.post_and_wait(
-        except requests.exceptions.RequestException:
+                        'v2/snaps/{}'.format(self.snap_name),
-            log.exception("switching channels")
+                        {'action': 'switch', 'channel': channel})
-            return
+                except requests.exceptions.RequestException:
-        log.debug("snap switching completed")
+                    log.exception("switching channels")
+                    return
+                subcontext.description = "switched to " + channel
 
     def get_refresh_channel(self):
         """Return the channel we should refresh subiquity to."""
@@ -134,28 +136,34 @@ class RefreshController(BaseController):
 
     async def check_for_update(self):
         await asyncio.shield(self.configure_task)
-        # If we restarted into this version, don't check for a new version.
+        with self.context.child("check_for_update") as context:
-        if self.app.updated:
+            if self.app.updated:
+                context.description = (
+                    "not offered update when already updated")
+                return CheckState.UNAVAILABLE
+            result = await self.app.snapd.get('v2/find', select='refresh')
+            log.debug("check_for_update received %s", result)
+            for snap in result["result"]:
+                if snap["name"] == self.snap_name:
+                    self.new_snap_version = snap["version"]
+                    context.description = (
+                        "new version of snap available: %r"
+                        % self.new_snap_version)
+                    return CheckState.AVAILABLE
+            else:
+                context.description = (
+                    "no new version of snap available")
             return CheckState.UNAVAILABLE
-        result = await self.app.snapd.get('v2/find', select='refresh')
-        log.debug("check_for_update received %s", result)
-        for snap in result["result"]:
-            if snap["name"] == self.snap_name:
-                self.new_snap_version = snap["version"]
-                log.debug(
-                    "new version of snap available: %r",
-                    self.new_snap_version)
-                return CheckState.AVAILABLE
-        return CheckState.UNAVAILABLE
 
     async def start_update(self):
         update_marker = os.path.join(self.app.state_dir, 'updating')
         open(update_marker, 'w').close()
-        change = await self.app.snapd.post(
+        with self.context.child("starting_update") as context:
-            'v2/snaps/{}'.format(self.snap_name),
+            change = await self.app.snapd.post(
-            {'action': 'refresh'})
+                'v2/snaps/{}'.format(self.snap_name),
-        log.debug("refresh requested: %s", change)
+                {'action': 'refresh'})
-        return change
+            context.description = "change id: {}".format(change)
+            return change
 
     async def get_progress(self, change):
         result = await self.app.snapd.get('v2/changes/{}'.format(change))

subiquity/controllers/reporting.py

@@ -0,0 +1,58 @@
+# Copyright 2019 Canonical, Ltd.
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as
+# published by the Free Software Foundation, either version 3 of the
+# License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+import logging
+
+from curtin.reporter import (
+    available_handlers,
+    update_configuration,
+    )
+from curtin.reporter.events import (
+    report_finish_event,
+    report_start_event,
+    status,
+    )
+from curtin.reporter.handlers import (
+    LogHandler,
+    )
+
+from subiquitycore.controller import NoUIController
+
+
+class LogHandler(LogHandler):
+    def publish_event(self, event):
+        level = getattr(logging, event.level)
+        logger = logging.getLogger('')
+        logger.log(level, event.as_string())
+
+
+available_handlers.unregister_item('log')
+available_handlers.register_item('log', LogHandler)
+
+
+class ReportingController(NoUIController):
+
+    def __init__(self, app):
+        super().__init__(app)
+
+    def start(self):
+        update_configuration({'logging': {'type': 'log', 'level': 'INFO'}})
+
+    def report_start_event(self, name, description, level):
+        report_start_event(name, description, level=level)
+
+    def report_finish_event(self, name, description, result, level):
+        result = getattr(status, result.name, status.WARN)
+        report_finish_event(name, description, result, level=level)

subiquity/controllers/snaplist.py

@@ -33,9 +33,10 @@ log = logging.getLogger('subiquity.controllers.snaplist')
 
 class SnapdSnapInfoLoader:
 
-    def __init__(self, model, snapd, store_section):
+    def __init__(self, model, snapd, store_section, context):
         self.model = model
         self.store_section = store_section
+        self.context = context
 
         self.main_task = None
         self.snap_list_fetched = False
@@ -50,41 +51,42 @@ class SnapdSnapInfoLoader:
         self.main_task = schedule_task(self._start())
 
     async def _start(self):
-        task = self.tasks[None] = schedule_task(self._load_list())
+        with self.context:
-        await task
+            task = self.tasks[None] = schedule_task(self._load_list())
-        self.pending_snaps = self.model.get_snap_list()
-        log.debug("fetched list of %s snaps", len(self.pending_snaps))
-        while self.pending_snaps:
-            snap = self.pending_snaps.pop(0)
-            task = self.tasks[snap] = schedule_task(
-                self._fetch_info_for_snap(snap))
             await task
+            self.pending_snaps = self.model.get_snap_list()
+            log.debug("fetched list of %s snaps", len(self.pending_snaps))
+            while self.pending_snaps:
+                snap = self.pending_snaps.pop(0)
+                task = self.tasks[snap] = schedule_task(
+                    self._fetch_info_for_snap(snap))
+                await task
 
     async def _load_list(self):
-        try:
+        with self.context.child("list"):
-            result = await self.snapd.get(
+            try:
-                'v2/find', section=self.store_section)
+                result = await self.snapd.get(
-        except requests.exceptions.RequestException:
+                    'v2/find', section=self.store_section)
-            log.exception("loading list of snaps failed")
+            except requests.exceptions.RequestException:
-            self.failed = True
+                log.exception("loading list of snaps failed")
-            return
+                self.failed = True
-        self.model.load_find_data(result)
+                return
-        self.snap_list_fetched = True
+            self.model.load_find_data(result)
+            self.snap_list_fetched = True
 
     def stop(self):
         if self.main_task is not None:
             self.main_task.cancel()
 
     async def _fetch_info_for_snap(self, snap):
-        log.debug('starting fetch for %s', snap.name)
+        with self.context.child("fetch").child(snap.name):
-        try:
+            try:
-            data = await self.snapd.get('v2/find', name=snap.name)
+                data = await self.snapd.get('v2/find', name=snap.name)
-        except requests.exceptions.RequestException:
+            except requests.exceptions.RequestException:
-            log.exception("loading snap info failed")
+                log.exception("loading snap info failed")
-            # XXX something better here?
+                # XXX something better here?
-            return
+                return
-        log.debug('got data for %s', snap.name)
+            self.model.load_info_data(data)
-        self.model.load_info_data(data)
 
     def get_snap_list_task(self):
         return self.tasks[None]
@@ -106,8 +108,8 @@ class SnapListController(BaseController):
 
     def _make_loader(self):
         return SnapdSnapInfoLoader(
-            self.model, self.app.snapd,
+            self.model, self.app.snapd, self.opts.snap_section,
-            self.opts.snap_section)
+            self.context.child("loader"))
 
     def __init__(self, app):
         super().__init__(app)

subiquity/controllers/ssh.py

@@ -76,37 +76,35 @@ class SSHController(BaseController):
 
     async def _fetch_ssh_keys(self, user_spec):
         ssh_import_id = "{ssh_import_id}:{import_username}".format(**user_spec)
-        log.debug(
+        with self.context.child("ssh_import_id", ssh_import_id):
-            "User input: %s, fetching ssh keys for %s",
+            try:
-            user_spec, ssh_import_id)
+                cp = await self.run_cmd_checked(
-        try:
+                    ['ssh-import-id', '-o-', ssh_import_id],
-            cp = await self.run_cmd_checked(
+                    failmsg=_("Importing keys failed:"))
-                ['ssh-import-id', '-o-', ssh_import_id],
+            except subprocess.CalledProcessError:
-                failmsg=_("Importing keys failed:"))
+                return
-        except subprocess.CalledProcessError:
+            key_material = cp.stdout.replace('\r', '').strip()
-            return
-        key_material = cp.stdout.replace('\r', '').strip()
 
-        try:
+            try:
-            cp = await self.run_cmd_checked(
+                cp = await self.run_cmd_checked(
-                ['ssh-keygen', '-lf-'],
+                    ['ssh-keygen', '-lf-'],
-                failmsg=_(
+                    failmsg=_(
-                    "ssh-keygen failed to show fingerprint of downloaded "
+                        "ssh-keygen failed to show fingerprint of downloaded "
-                    "keys:"),
+                        "keys:"),
-                input=key_material)
+                    input=key_material)
-        except subprocess.CalledProcessError:
+            except subprocess.CalledProcessError:
-            return
+                return
 
-        fingerprints = cp.stdout.replace(
+            fingerprints = cp.stdout.replace(
-            "# ssh-import-id {}".format(ssh_import_id),
+                "# ssh-import-id {}".format(ssh_import_id),
-            "").strip().splitlines()
+                "").strip().splitlines()
 
-        if 'ssh-import-id' in self.app.answers.get("Identity", {}):
+            if 'ssh-import-id' in self.app.answers.get("Identity", {}):
-            user_spec['authorized_keys'] = key_material.splitlines()
+                user_spec['authorized_keys'] = key_material.splitlines()
-            self.done(user_spec)
+                self.done(user_spec)
-        else:
+            else:
-            self.ui.body.confirm_ssh_keys(
+                self.ui.body.confirm_ssh_keys(
-                user_spec, ssh_import_id, key_material, fingerprints)
+                    user_spec, ssh_import_id, key_material, fingerprints)
 
     def fetch_ssh_keys(self, user_spec):
         self._fetch_task = schedule_task(self._fetch_ssh_keys(user_spec))

subiquity/controllers/tests/test_filesystem.py

@@ -15,6 +15,7 @@
 
 import unittest
 
+from subiquitycore.context import Context
 from subiquity.controllers.filesystem import (
     FilesystemController,
     )
@@ -35,15 +36,19 @@ class Thing:
 
 class MiniApplication:
     ui = signal = loop = None
+    project = "mini"
     answers = {}
     opts = Thing()
     opts.dry_run = True
     opts.bootloader = None
+    def report_start_event(*args): pass
+    def report_finish_event(*args): pass
 
 
 def make_controller(bootloader=None):
     app = MiniApplication()
     app.base_model = bm = Thing()
+    app.context = Context.new(app)
     bm.filesystem = make_model(bootloader)
     controller = FilesystemController(app)
     return controller

subiquity/core.py

@@ -87,6 +87,7 @@ class Subiquity(Application):
             "SnapList",
             "InstallProgress",
             "Error",  # does not have a UI
+            "Reporting",  # does not have a UI
     ]
 
     def __init__(self, opts, block_log_dir):
@@ -123,6 +124,14 @@ class Subiquity(Application):
             print("report saved to {}".format(report.path))
             raise
 
+    def report_start_event(self, name, description, level="INFO"):
+        self.controllers.Reporting.report_start_event(
+            name, description, level)
+
+    def report_finish_event(self, name, description, status, level="INFO"):
+        self.controllers.Reporting.report_finish_event(
+            name, description, status, level)
+
     def select_initial_screen(self, index):
         super().select_initial_screen(index)
         for report in self.controllers.Error.reports:

subiquitycore/context.py

@@ -0,0 +1,100 @@
+# Copyright 2019 Canonical, Ltd.
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU Affero General Public License as
+# published by the Free Software Foundation, either version 3 of the
+# License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+
+import asyncio
+import enum
+
+
+class Status(enum.Enum):
+    SUCCESS = enum.auto()
+    FAIL = enum.auto()
+    WARN = enum.auto()
+
+
+class Context:
+    """Class to report when things start and finish.
+
+    The expected way to use this is something like:
+
+    with somecontext.child("operation"):
+        await long_running_operation()
+
+    but you can also call .enter() and .exit() if use as a context
+    manager isn't possible.
+
+    start and finish events are reported via the report_start_event and
+    report_finish_event methods on app.
+
+    You can override the message shown on exit by passing it to the .exit
+    method or by assigning to description:
+
+    with somecontext.child("operation") as context:
+        result = await long_running_operation()
+        context.description = "result was {}".format(result)
+    """
+
+    def __init__(self, app, name, description, parent, level, childlevel=None):
+        self.app = app
+        self.name = name
+        self.description = description
+        self.parent = parent
+        self.level = level
+        if childlevel is None:
+            childlevel = level
+        self.childlevel = childlevel
+
+    @classmethod
+    def new(self, app):
+        return Context(app, app.project, "", None, "INFO")
+
+    def child(self, name, description="", level=None, childlevel=None):
+        if level is None:
+            level = self.childlevel
+        return Context(self.app, name, description, self, level, childlevel)
+
+    def _name(self):
+        c = self
+        names = []
+        while c is not None:
+            names.append(c.name)
+            c = c.parent
+        return '/'.join(reversed(names))
+
+    def enter(self, description=None):
+        if description is None:
+            description = self.description
+        self.app.report_start_event(self._name(), description, self.level)
+
+    def exit(self, description=None, result=Status.SUCCESS):
+        if description is None:
+            description = self.description
+        self.app.report_finish_event(
+            self._name(), description, result, self.level)
+
+    def __enter__(self):
+        self.enter()
+        return self
+
+    def __exit__(self, exc, value, tb):
+        if exc is not None:
+            result = Status.FAIL
+            if isinstance(value, asyncio.CancelledError):
+                description = "cancelled"
+            else:
+                description = str(value)
+        else:
+            result = Status.SUCCESS
+            description = None
+        self.exit(description, result)

subiquitycore/controller.py

@@ -36,6 +36,7 @@ class BaseController(ABC):
         self.opts = app.opts
         self.loop = app.loop
         self.app = app
+        self.context = self.app.context.child(self.name, childlevel="DEBUG")
         self.answers = app.answers.get(self.name, {})
         if self.model_name is not None:
             self.model = getattr(self.app.base_model, self.model_name)
@@ -143,6 +144,7 @@ class RepeatedController(BaseController):
         self.name = "{}-{}".format(orig.name, index)
         self.orig = orig
         self.index = index
+        self.context = orig.context
 
     def register_signals(self):
         pass

subiquitycore/controllers/network.py

@@ -25,7 +25,11 @@ from probert.network import IFF_UP, NetworkEventReceiver
 from subiquitycore.async_helpers import SingleInstanceTask
 from subiquitycore.controller import BaseController
 from subiquitycore.file_util import write_file
-from subiquitycore.models.network import BondParameters, sanitize_config
+from subiquitycore.models.network import (
+    BondParameters,
+    NetDevAction,
+    sanitize_config,
+    )
 from subiquitycore import netplan
 from subiquitycore.ui.views.network import (
     NetworkView,
@@ -231,7 +235,8 @@ class NetworkController(BaseController):
             meth = getattr(
                 self.ui.body,
                 "_action_{}".format(action['action']))
-            meth(obj)
+            action_obj = getattr(NetDevAction, action['action'])
+            self.ui.body._action(None, (action_obj, meth), obj)
             yield
             body = self.ui.body._w
             if not isinstance(body, StretchyOverlay):
@@ -343,92 +348,94 @@ class NetworkController(BaseController):
         self.model.parse_netplan_configs(self.root)
 
     async def _apply_config(self, silent):
-        log.debug("apply_config silent=%s", silent)
+        with self.context.child(
+                "apply_config", "silent={}".format(silent), level="INFO"):
+            devs_to_delete = []
+            devs_to_down = []
+            dhcp_device_versions = []
+            dhcp_events = set()
+            for dev in self.model.get_all_netdevs(include_deleted=True):
+                dev.dhcp_events = {}
+                for v in 4, 6:
+                    if dev.dhcp_enabled(v):
+                        if not silent:
+                            dev.set_dhcp_state(v, "PENDING")
+                            self.network_event_receiver.update_link(
+                                dev.ifindex)
+                        else:
+                            dev.set_dhcp_state(v, "RECONFIGURE")
+                        dev.dhcp_events[v] = e = asyncio.Event()
+                        dhcp_events.add(e)
+                if dev.info is None:
+                    continue
+                if dev.is_virtual:
+                    devs_to_delete.append(dev)
+                    continue
+                if dev.config != self.model.config.config_for_device(dev.info):
+                    devs_to_down.append(dev)
 
-        devs_to_delete = []
+            self._write_config()
-        devs_to_down = []
-        dhcp_device_versions = []
-        dhcp_events = set()
-        for dev in self.model.get_all_netdevs(include_deleted=True):
-            dev.dhcp_events = {}
-            for v in 4, 6:
-                if dev.dhcp_enabled(v):
-                    if not silent:
-                        dev.set_dhcp_state(v, "PENDING")
-                        self.network_event_receiver.update_link(dev.ifindex)
-                    else:
-                        dev.set_dhcp_state(v, "RECONFIGURE")
-                    dev.dhcp_events[v] = e = asyncio.Event()
-                    dhcp_events.add(e)
-            if dev.info is None:
-                continue
-            if dev.is_virtual:
-                devs_to_delete.append(dev)
-                continue
-            if dev.config != self.model.config.config_for_device(dev.info):
-                devs_to_down.append(dev)
 
-        self._write_config()
-
-        if not silent and self.view:
-            self.view.show_apply_spinner()
-
-        def error(stage):
             if not silent and self.view:
-                self.view.show_network_error(stage)
+                self.view.show_apply_spinner()
 
-        if self.opts.dry_run:
+            def error(stage):
-            delay = 1/self.app.scale_factor
+                if not silent and self.view:
-            await arun_command(['sleep', str(delay)])
+                    self.view.show_network_error(stage)
-            if os.path.exists('/lib/netplan/generate'):
+
-                # If netplan appears to be installed, run generate to at
+            if self.opts.dry_run:
-                # least test that what we wrote is acceptable to netplan.
+                delay = 1/self.app.scale_factor
-                await arun_command(
+                await arun_command(['sleep', str(delay)])
-                    ['netplan', 'generate', '--root', self.root], check=True)
+                if os.path.exists('/lib/netplan/generate'):
-        else:
+                    # If netplan appears to be installed, run generate to at
-            if devs_to_down or devs_to_delete:
+                    # least test that what we wrote is acceptable to netplan.
-                try:
                     await arun_command(
-                        ['systemctl', 'stop', 'systemd-networkd.service'],
+                        ['netplan', 'generate', '--root', self.root],
                         check=True)
+            else:
+                if devs_to_down or devs_to_delete:
+                    try:
+                        await arun_command(
+                            ['systemctl', 'stop', 'systemd-networkd.service'],
+                            check=True)
+                    except subprocess.CalledProcessError:
+                        error("stop-networkd")
+                        raise
+                if devs_to_down:
+                    await self._down_devs(devs_to_down)
+                if devs_to_delete:
+                    await self._delete_devs(devs_to_delete)
+                try:
+                    await arun_command(['netplan', 'apply'], check=True)
                 except subprocess.CalledProcessError:
-                    error("stop-networkd")
+                    error("apply")
                     raise
-            if devs_to_down:
+
-                await self._down_devs(devs_to_down)
+            if not silent and self.view:
-            if devs_to_delete:
+                self.view.hide_apply_spinner()
-                await self._delete_devs(devs_to_delete)
+
+            if self.answers.get('accept-default', False):
+                self.done()
+            elif self.answers.get('actions', False):
+                actions = self.answers['actions']
+                self.answers.clear()
+                self._run_iterator(self._run_actions(actions))
+
+            if not dhcp_events:
+                return
+
             try:
-                await arun_command(['netplan', 'apply'], check=True)
+                await asyncio.wait_for(
-            except subprocess.CalledProcessError:
+                    asyncio.wait({e.wait() for e in dhcp_events}),
-                error("apply")
+                    10)
-                raise
+            except asyncio.TimeoutError:
+                pass
 
-        if not silent and self.view:
+            for dev, v in dhcp_device_versions:
-            self.view.hide_apply_spinner()
+                dev.dhcp_events = {}
-
+                if not dev.dhcp_addresses()[v]:
-        if self.answers.get('accept-default', False):
+                    dev.set_dhcp_state(v, "TIMEDOUT")
-            self.done()
+                    self.network_event_receiver.update_link(dev.ifindex)
-        elif self.answers.get('actions', False):
-            actions = self.answers['actions']
-            self.answers.clear()
-            self._run_iterator(self._run_actions(actions))
-
-        if not dhcp_events:
-            return
-
-        try:
-            await asyncio.wait_for(
-                asyncio.wait({e.wait() for e in dhcp_events}),
-                10)
-        except asyncio.TimeoutError:
-            pass
-
-        for dev, v in dhcp_device_versions:
-            dev.dhcp_events = {}
-            if not dev.dhcp_addresses()[v]:
-                dev.set_dhcp_state(v, "TIMEDOUT")
-                self.network_event_receiver.update_link(dev.ifindex)
 
     def add_vlan(self, device, vlan):
         return self.model.new_vlan(device, vlan)

subiquitycore/core.py

@@ -25,6 +25,9 @@ import urwid
 import yaml
 
 from subiquitycore.async_helpers import schedule_task
+from subiquitycore.context import (
+    Context,
+    )
 from subiquitycore.controller import (
     RepeatedController,
     Skip,
@@ -385,6 +388,7 @@ class Application:
         self.prober = prober
         self.loop = None
         self.controllers = ControllerSet(self, self.controllers)
+        self.context = Context.new(self)
 
     def run_command_in_foreground(self, cmd, before_hook=None, after_hook=None,
                                   **kw):
@@ -440,10 +444,14 @@ class Application:
             json.dump(cur.serialize(), fp)
 
     def select_screen(self, new):
-        log.info("moving to screen %s", new.name)
+        new.context.enter("starting UI")
         if self.opts.screens and new.name not in self.opts.screens:
             raise Skip
-        new.start_ui()
+        try:
+            new.start_ui()
+        except Skip:
+            new.context.exit("(skipped)")
+            raise
         state_path = os.path.join(self.state_dir, 'last-screen')
         with open(state_path, 'w') as fp:
             fp.write(new.name)
@@ -452,6 +460,7 @@ class Application:
         self.save_state()
         old = self.controllers.cur
         if old is not None:
+            old.context.exit("completed")
             old.end_ui()
         while True:
             self.controllers.index += increment
@@ -476,6 +485,17 @@ class Application:
         self.controllers.index = controller_index - 1
         self.next_screen()
 
+    def report_start_event(self, name, description, level):
+        # See context.py for what calls these.
+        log = logging.getLogger(name)
+        level = getattr(logging, level)
+        log.log(level, "start: %s", description)
+
+    def report_finish_event(self, name, description, status, level):
+        log = logging.getLogger(name)
+        level = getattr(logging, level)
+        log.log(level, "finish: %s %s", description, status.name)
+
 # EventLoop -------------------------------------------------------------------
 
     def exit(self):

subiquitycore/ui/stretchy.py

@@ -78,6 +78,10 @@ class Stretchy(metaclass=urwid.MetaSignals):
     def stretchy_w(self):
         return self.widgets[self.stretchy_index]
 
+    def attach_context(self, context):
+        urwid.connect_signal(self, 'opened', lambda: context.enter("opened"))
+        urwid.connect_signal(self, 'closed', lambda: context.exit("closed"))
+
 
 class StretchyOverlay(urwid.Widget):
     _selectable = True

subiquitycore/ui/views/network.py

@@ -64,8 +64,10 @@ log = logging.getLogger('subiquitycore.views.network')
 
 
 def _stretchy_shower(cls, *args):
-    def impl(self, device):
+    def impl(self, name, device):
-        self.show_stretchy_overlay(cls(self, device, *args))
+        stretchy = cls(self, device, *args)
+        stretchy.attach_context(self.controller.context.child(name))
+        self.show_stretchy_overlay(stretchy)
     impl.opens_dialog = True
     return impl
 
@@ -140,8 +142,7 @@ class NetworkView(BaseView):
 
     def _action(self, sender, action, device):
         action, meth = action
-        log.debug("_action %s %s", action.name, device.name)
+        meth("{}/{}".format(device.name, action.name), device)
-        meth(device)
 
     def _route_watcher(self, routes):
         log.debug('view route_watcher %s', routes)
@@ -377,8 +378,9 @@ class NetworkView(BaseView):
         return rows
 
     def _create_bond(self, sender=None):
-        log.debug("_create_bond")
+        stretchy = BondStretchy(self)
-        self.show_stretchy_overlay(BondStretchy(self))
+        stretchy.attach_context(self.controller.context.child("add_bond"))
+        self.show_stretchy_overlay(stretchy)
 
     def show_network_error(self, action, info=None):
         self.error_showing = True