add some logging around moving between screens

my best guess at why CI is currently hanging sometimes is that the
'next-screen' signal is being sent too often / too early.  add some
logging around this so that we will be able to confirm / deny this by
reading the logs.

subiquity/controllers/filesystem.py

@@ -171,6 +171,7 @@ class FilesystemController(BaseController):
         self.signal.emit_signal('prev-screen')
 
     def finish(self):
+        log.debug("FilesystemController.finish next-screen")
         # start curtin install in background
         self.signal.emit_signal('installprogress:filesystem-config-done')
         # switch to next screen

subiquity/controllers/identity.py

@@ -47,7 +47,9 @@ class IdentityController(BaseController):
     def done(self, user_spec):
         safe_spec = user_spec.copy()
         safe_spec['password'] = '<REDACTED>'
-        log.debug("User input: {}".format(safe_spec))
+        log.debug(
+            "IdentityController.done next-screen user_spec=%s",
+            safe_spec)
         self.model.add_user(user_spec)
         self.signal.emit_signal('installprogress:identity-config-done')
         self.signal.emit_signal('next-screen')

subiquity/controllers/installpath.py

@@ -39,6 +39,9 @@ class InstallpathController(BaseController):
                 self.install_ubuntu()
             else:
                 self.model.update(self.answers)
+                log.debug(
+                    "InstallpathController.default next-screen answers=%s",
+                    self.answers)
                 self.signal.emit_signal('next-screen')
 
     def cancel(self):
@@ -56,7 +59,7 @@ class InstallpathController(BaseController):
         getattr(self, 'install_' + path)()
 
     def install_ubuntu(self):
-        log.debug("Installing Ubuntu path chosen.")
+        log.debug("InstallpathController.install_ubuntu next-screen")
         self.signal.emit_signal('next-screen')
 
     def install_cmdline(self):
@@ -89,5 +92,6 @@ class InstallpathController(BaseController):
         self.ui.set_body(MAASView(self.model, self, title, excerpt))
 
     def setup_maas(self, result):
+        log.debug("InstallpathController.setup_mass next-screen")
         self.model.update(result)
         self.signal.emit_signal('next-screen')

subiquity/controllers/keyboard.py

@@ -59,6 +59,7 @@ class KeyboardController(BaseController):
             self._done)
 
     def _done(self, fut):
+        log.debug("KeyboardController._done next-screen")
         self.signal.emit_signal('next-screen')
 
     def cancel(self):

subiquity/controllers/mirror.py

@@ -102,6 +102,7 @@ class MirrorController(BaseController):
         self.model.mirror = data
 
     def done(self, mirror):
+        log.debug("MirrorController.done next-screen mirror=%s", mirror)
         if mirror != self.model.mirror:
             self.model.mirror = mirror
         self.signal.emit_signal('next-screen')

subiquity/controllers/proxy.py

@@ -45,6 +45,7 @@ class ProxyController(BaseController):
         self.model.proxy = data
 
     def done(self, proxy):
+        log.debug("ProxyController.done next-screen proxy=%s", proxy)
         if proxy != self.model.proxy:
             self.model.proxy = proxy
             os.environ['http_proxy'] = os.environ['https_proxy'] = proxy

subiquity/controllers/refresh.py

@@ -277,6 +277,7 @@ class RefreshController(BaseController):
             raise Skip()
 
     def done(self, sender=None):
+        log.debug("RefreshController.done next-screen")
         self.signal.emit_signal('next-screen')
 
     def cancel(self, sender=None):

subiquity/controllers/snaplist.py

@@ -176,6 +176,9 @@ class SnapListController(BaseController):
         self.loader.get_snap_info(snap, callback)
 
     def done(self, snaps_to_install):
+        log.debug(
+            "SnapListController.done next-screen snaps_to_install=%s",
+            snaps_to_install)
         self.model.set_installed_list(snaps_to_install)
         self.signal.emit_signal("installprogress:snap-config-done")
         self.signal.emit_signal("next-screen")

subiquity/controllers/ssh.py

@@ -92,6 +92,9 @@ class SSHController(BaseController):
         if not isinstance(self.ui.frame.body, SSHView):
             # This can happen if curtin failed while the keys where being
             # fetched and we jump to the log view.
+            log.debug(
+                "view is now an instance of %s, not SSHView",
+                type(self.ui.frame.body))
             return
         try:
             result = fut.result()
@@ -123,7 +126,7 @@ class SSHController(BaseController):
             self._fetched_ssh_keys)
 
     def done(self, result):
-        log.debug("SSHController result %s", result)
+        log.debug("SSHController.done next-screen result=%s", result)
         self.model.install_server = result['install_server']
         self.model.authorized_keys = result.get('authorized_keys', [])
         self.model.pwauth = result.get('pwauth', True)

subiquity/controllers/welcome.py

@@ -36,6 +36,7 @@ class WelcomeController(BaseController):
             self.done()
 
     def done(self):
+        log.debug("WelcomeController.done next-screen")
         self.signal.emit_signal('next-screen')
 
     def cancel(self):

subiquitycore/controllers/network.py

@@ -238,6 +238,7 @@ class NetworkController(BaseController):
         self.observer.trigger_scan(dev.ifindex)
 
     def done(self):
+        log.debug("NetworkController.done next-screen")
         self.view = None
         self.model.has_network = bool(
             self.network_event_receiver.default_routes)

subiquitycore/core.py

@@ -364,6 +364,8 @@ class Application:
             try:
                 self.select_screen(self.controller_index + 1)
             except Skip:
+                controller_name = self.controllers[self.controller_index]
+                log.debug("skipping screen %s", controller_name)
                 continue
             else:
                 return