Add lots more debug logs

bin/kano-updater-internal

@@ -69,7 +69,7 @@ from kano_updater.status import UpdaterStatus
 from kano_updater.utils import make_low_prio, is_running, \
     remove_pid_file, pause_notifications, resume_notifications, show_kano_dialog, \
     run_bg, enable_power_button, disable_power_button, verify_kit_is_plugged, \
-    clear_tracking_uuid
+    clear_tracking_uuid, thread_id
 from kano_updater.return_codes import RC, RCState
 import kano_updater.priority as Priority
 
@@ -158,18 +158,22 @@ def run_install(gui=False, confirm=True, splash_pid=None):
         try:
             launch_install_gui(confirm=confirm, splash_pid=splash_pid)
         except Relaunch as relaunch_exception:
+            logger.debug("Caught relaunch exception")
             clean_up(relaunch=True)
-            cmd_args = ['kano-updater', 'install', '--gui', '--no-confirm']
+            cmd_args = ['kano-updater-internal', 'install', '--gui', '--no-confirm']
             if relaunch_exception.pid:
+                logger.debug("Relaunch exception with pid {}".format(relaunch_exception.pid))
                 cmd_args += ['--splash-pid', str(relaunch_exception.pid)]
-            os.execvp('kano-updater', cmd_args)
+            logger.debug("Relaunch exec with args {}".format(cmd_args))
+            os.execvp('kano-updater-internal', cmd_args)
     else:
         try:
             progress = CLIProgress()
             install(progress, gui)
         except Relaunch:
             clean_up(relaunch=True)
-            os.execvp('kano-updater', ['kano-updater', 'install'])
+            logger.debug("Relaunch exec with args {}".format(cmd_args))
+            os.execvp('kano-updater-internal', ['kano-updater-internal', 'install'])
 
 
 def run_install_ind_pkg(package):
@@ -178,6 +182,7 @@ def run_install_ind_pkg(package):
 
 
 def main():
+    logger.debug("thread id {}".format(thread_id()))
 
     global _g_gui_mode
     global _g_keep_uuid
@@ -226,6 +231,8 @@ def main():
     elif args['ui']:
         if args['relaunch-splash']:
             from kano_updater.ui.main import launch_relaunch_countdown_gui
+            logger.set_app_name('kano-updater-splash') # avoid overwriting logs from other process
+            logger.debug("launch_relaunch_countdown_gui parent pid {}".format(args['<parent-pid>']))
             launch_relaunch_countdown_gui(int(args['<parent-pid>']))
 
         elif args['shutdown-window']:
@@ -274,6 +281,7 @@ def main():
             splash_pid = None
             if args['--splash-pid']:
                 splash_pid = int(args['<pid>'])
+            logger.debug("install passed splash_pid {}".format(splash_pid))
 
             run_install(gui=args['--gui'], confirm=not args['--no-confirm'],
                         splash_pid=splash_pid)

kano_updater/commands/install.py

@@ -88,6 +88,7 @@ def install(progress=None, gui=True):
     try:
         return do_install(progress, status, priority=priority)
     except Relaunch as err:
+        logger.debug("Relaunch exception in install: reraised (install)")
         raise
     except Exception as err:
         # Reset the state back to the previous one, so the updater
@@ -108,9 +109,12 @@ def do_install(progress, status, priority=Priority.NONE):
     track_data_and_sync('update-install-started', dict())
 
     if priority == Priority.URGENT:
-        install_urgent(progress, status)
+        res = install_urgent(progress, status)
     else:
-        install_standard(progress, status)
+        res = install_standard(progress, status)
+
+    if not res:
+        return False
 
     run_cmd_log('apt-get --yes autoremove')
     run_cmd_log('apt-get --yes clean')
@@ -218,6 +222,8 @@ def install_urgent(progress, status):
     except Exception:
         pass
 
+    return True
+
 
 def install_standard(progress, status):
     progress.split(
@@ -308,7 +314,9 @@ def install_standard(progress, status):
     try:
         preup.run(progress)
     except Relaunch:
-        raise
+        logger.debug("Relaunch in install")
+        progress.relaunch()
+        return False
     except Exception as err:
         logger.error("The pre-update scenarios failed.")
         logger.error(err.encode('utf-8'))
@@ -323,8 +331,11 @@ def install_standard(progress, status):
     try:
         postup.run(progress)
     except Relaunch:
+        logger.debug("Relaunch in postupdate: (bump)")
         bump_system_version()
-        raise
+        logger.debug("Relaunch in postupdate")
+        progress.relaunch()
+        return False
     except Exception as err:
         logger.error("The post-update scenarios failed.")
         logger.error(err.encode('utf-8'))
@@ -337,6 +348,8 @@ def install_standard(progress, status):
     progress.start('aux-tasks')
     run_aux_tasks(progress)
 
+    return True
+
 
 def check_disk_space(priority):
     '''

kano_updater/scenarios.py

@@ -23,6 +23,7 @@
 from kano_updater.utils import install, remove_user_files, update_failed, \
     purge, rclocal_executable, migrate_repository, get_users, run_for_every_user
 from kano_updater.paths import PYLIBS_DIR, PYFALLBACK_DIR
+from kano_updater.progress import Relaunch
 
 
 SOURCES_DIR = '/etc/apt/sources.list.d'
@@ -1057,10 +1058,8 @@ def beta_3_15_0_to_beta_3_16_0(self, progress):
             shutil.copy(REFERENCE_STRETCH_LIST_QA_TEST, STRETCH_MIGRATION_LIST)
         else:
             shutil.copy(REFERENCE_STRETCH_LIST, STRETCH_MIGRATION_LIST)
-        apt_handle = AptWrapper.get_instance()
-        apt_handle.refresh_instance()
-        apt_handle.update(progress)
-        progress.relaunch()
+        run_cmd_log("apt-get update")
+        raise Relaunch()
 
     def beta_3_16_0_to_beta_4_0_0(self, dummy_progress):
         ''' 4.0.0 is the first Debian Stretch version. All the work for

kano_updater/ui/main.py

@@ -23,6 +23,7 @@
 def relaunch_required():
     global relaunch_required_flag
     global launched_splash_pid
+    logger.debug("Relaunch required")
 
     relaunch_required_flag = True
     launched_splash_pid = show_relaunch_splash()
@@ -34,6 +35,7 @@ def launch_install_gui(confirm=False, splash_pid=None):
     from kano_updater.ui.available_window import UpdatesDownloadedWindow
     from kano_updater.ui.install_window import InstallWindow
 
+    logger.debug("launch_install_gui")
     GObject.threads_init()
 
     win = UpdatesDownloadedWindow() if confirm else InstallWindow()
@@ -45,8 +47,9 @@ def launch_install_gui(confirm=False, splash_pid=None):
         os.kill(splash_pid, signal.SIGKILL)
 
     Gtk.main()
-
+    logger.debug("gtk main exitted {} {}".format(relaunch_required_flag, launched_splash_pid))
     if relaunch_required_flag:
+        logger.debug("raising relaunch exception passing it pid {}".format(launched_splash_pid))
         r_exc = Relaunch()
         r_exc.pid = launched_splash_pid
         raise r_exc

kano_updater/ui/progress.py

@@ -10,8 +10,8 @@
 
 from kano_updater.progress import Progress
 from kano_updater.ui.main import relaunch_required
-from kano_updater.utils import kill_flappy_judoka
-
+from kano_updater.utils import kill_flappy_judoka, thread_id
+from kano.logging import logger
 
 class GtkProgress(Progress):
 
@@ -53,5 +53,7 @@ def _relaunch(self):
         GLib.idle_add(self._do_relaunch)
 
     def _do_relaunch(self):
+        logger.debug("_do_relaunch {}".format(thread_id()))
         relaunch_required()
+        logger.debug("running main_quit()")
         Gtk.main_quit()

kano_updater/ui/views/relaunch.py

@@ -8,6 +8,7 @@
 
 import os
 import signal
+from kano.logging import logger
 
 from gi.repository import Gtk
 
@@ -33,4 +34,5 @@ def __init__(self, parent_pid):
         self.connect('map', self._on_map)
 
     def _on_map(self, widget=None):
+        logger.debug("splash signalling parent {}".format(self._parent_pid))
         os.kill(self._parent_pid, signal.SIGUSR1)

kano_updater/utils.py

@@ -237,14 +237,17 @@ def _handle_sigusr1(signum, frame):
 
 
 def show_relaunch_splash():
-    cmd = ["kano-updater", "ui", "relaunch-splash", str(os.getpid())]
-    p = subprocess.Popen(cmd, shell=False)
-
     # register a handler for SIGUSR1
+    logger.debug(" entering show_relaunch_spash")
     signal.signal(signal.SIGUSR1, _handle_sigusr1)
 
+    cmd = ["kano-updater-internal", "ui", "relaunch-splash", str(os.getpid())]
+    p = subprocess.Popen(cmd, shell=False)
+    logger.debug("Started splash process, pid {}".format(p.pid))
+
     # wait until the child process signals that it's ready
     signal.pause()
+    logger.debug("Splash process pid {} is ready, continuing".format(p.pid))
 
     return p.pid
 
@@ -625,3 +628,11 @@ def clear_tracking_uuid():
         remove_tracking_uuid(TRACKING_UUID_KEY)
     except:
         logger.error('Unexpected error:\n{}'.format(traceback.format_exc()))
+
+
+def thread_id():
+    try:
+        import thread
+        return thread.get_ident()
+    except:
+        return None

tests/commands/test_install.py

@@ -8,8 +8,10 @@
 #
 
 
+import pytest
 from tests.fixtures.progress import PyTestProgress, AbortError
 import tests.fixtures.autologin_checks
+from kano_updater.os_version import get_target_version
 
 
 def test_install(apt, state, system_version, free_space,
@@ -23,6 +25,12 @@ def test_install(apt, state, system_version, free_space,
     should_succeed = internet and server_available and \
         (space_available >= space_required)
 
+    relaunch_expected = system_version <= get_target_version()
+    rc_warning = (
+        'NOTE: Return value from install() is now coupled to whether the '
+        'updater requires a relaunch.'
+    )
+
     try:
         res = kano_updater.commands.install.install(
             progress=progress, gui=False
@@ -32,5 +40,16 @@ def test_install(apt, state, system_version, free_space,
             res == should_succeed and
             should_succeed == tests.fixtures.autologin_checks.all_checks(autologin_checks)
         )
+
+        if relaunch_expected and should_succeed:
+            pytest.fail(
+                "Updater should have relaunched but didn't\n\n" +
+                rc_warning
+            )
     except AbortError:
         assert not should_succeed
+    except AssertionError:
+        if relaunch_expected:
+            pytest.xfail(rc_warning)
+        else:
+            raise