Merge lp:~barry/ubuntu-system-image/lp1277589-udm into lp:~registry/ubuntu-system-image/client

[Barry Warsaw]

More fixes for concurrency protection.

=== modified file 'NEWS.rst'
--- NEWS.rst	2014-02-14 22:47:33 +0000
+++ NEWS.rst	2014-02-18 20:26:47 +0000
@@ -17,6 +17,9 @@
   * Return the empty string from `ApplyUpdate()` D-Bus method.  This restores
     the original API (patch merged from Ubuntu package, given by Didier
     Roche).  (LP: #1260768)
+  * Request ubuntu-download-manager to download all files to temporary
+    destinations, then atomically rename them into place.  This avoids
+    clobbering by multiple processes and mimic changes coming in u-d-m.
 
 2.0.5 (2014-01-30)
 ==================

=== modified file 'systemimage/api.py'
--- systemimage/api.py	2014-02-13 18:16:17 +0000
+++ systemimage/api.py	2014-02-18 20:26:47 +0000
@@ -73,6 +73,10 @@
         self._update = None
         self._callback = callback
 
+    def __repr__(self):
+        return '<Mediator at 0x{:x} | State at 0x{:x}>'.format(
+            id(self), id(self._state))
+
     def cancel(self):
         self._state.downloader.cancel()
 

=== modified file 'systemimage/dbus.py'
--- systemimage/dbus.py	2014-02-14 22:47:33 +0000
+++ systemimage/dbus.py	2014-02-18 20:26:47 +0000
@@ -23,6 +23,7 @@
 
 import os
 import sys
+import logging
 import traceback
 
 from dbus.service import Object, method, signal
@@ -35,6 +36,7 @@
 
 
 EMPTYSTRING = ''
+log = logging.getLogger('systemimage')
 
 
 class Loop:
@@ -69,6 +71,7 @@
         super().__init__(bus, object_path)
         self._loop = loop
         self._api = Mediator(self._progress_callback)
+        log.info('Mediator created {}', self._api)
         self._checking = Lock()
         self._update = None
         self._downloading = False
@@ -79,17 +82,22 @@
 
     def _check_for_update(self):
         # Asynchronous method call.
+        log.info('Checking for update')
         self._update = self._api.check_for_update()
         # Do we have an update and can we auto-download it?
         downloading = False
         if self._update.is_available:
             settings = Settings()
             auto = settings.get('auto_download')
+            log.info('Update available; auto-download: {}', auto)
             if auto in ('1', '2'):
                 # XXX When we have access to the download service, we can
                 # check if we're on the wifi (auto == '1').
-                GLib.timeout_add(50, self._download)
+                GLib.timeout_add(50, self._download, self._checking.release)
                 downloading = True
+            else:
+                log.info('release checking lock from _check_for_update()')
+                self._checking.release()
         self.UpdateAvailableStatus(
             self._update.is_available,
             downloading,
@@ -100,7 +108,6 @@
             # array of dictionaries data type.  LP: #1215586
             #self._update.descriptions,
             "")
-        self._checking.release()
         # Stop GLib from calling this method again.
         return False
 
@@ -122,12 +129,16 @@
         """
         self._loop.keepalive()
         # Check-and-acquire the lock.
+        log.info('test and acquire checking lock')
         if not self._checking.acquire(blocking=False):
             # Check is already in progress, so there's nothing more to do.
+            log.info('checking lock not acquired')
             return
+        log.info('checking lock acquired')
         # We've now acquired the lock.  Reset any failure or in-progress
         # state.  Get a new mediator to reset any of its state.
         self._api = Mediator(self._progress_callback)
+        log.info('Mediator recreated {}', self._api)
         self._failure_count = 0
         self._last_error = ''
         # Arrange for the actual check to happen in a little while, so that
@@ -142,21 +153,25 @@
         eta = 0
         self.UpdateProgress(percentage, eta)
 
-    def _download(self):
+    def _download(self, release_checking=None):
         if self._downloading and self._paused:
             self._api.resume()
             self._paused = False
+            log.info('Download previously paused')
             return
         if (self._downloading                           # Already in progress.
             or self._update is None                     # Not yet checked.
             or not self._update.is_available            # No update available.
             ):
+            log.info('Download already in progress or not available')
             return
         if self._failure_count > 0:
             self._failure_count += 1
             self.UpdateFailed(self._failure_count, self._last_error)
+            log.info('Update failure count: {}', self._failure_count)
             return
         self._downloading = True
+        log.info('Update is downloading')
         try:
             # Always start by sending a UpdateProgress(0, 0).  This is
             # enough to get the u/i's attention.
@@ -168,13 +183,20 @@
             # value, but not the traceback.
             self._last_error = EMPTYSTRING.join(
                 traceback.format_exception_only(*sys.exc_info()[:2]))
+            log.info('Update failed: {}', self._last_error)
             self.UpdateFailed(self._failure_count, self._last_error)
         else:
+            log.info('Update downloaded')
             self.UpdateDownloaded()
             self._failure_count = 0
             self._last_error = ''
             self._rebootable = True
         self._downloading = False
+        log.info('release checking lock from _download()')
+        if release_checking is not None:
+            # We were auto-downloading, so we now have to release the checking
+            # lock.  If we were manually downloading, there would be no lock.
+            release_checking()
         # Stop GLib from calling this method again.
         return False
 
@@ -297,31 +319,40 @@
                               #descriptions,
                               error_reason):
         """Signal sent in response to a CheckForUpdate()."""
+        log.info('EMIT UpdateAvailableStatus({}, {}, {}, {}, {}, {})',
+                 is_available, downloading, available_version, update_size,
+                 last_update_date, repr(error_reason))
         self._loop.keepalive()
 
     @signal('com.canonical.SystemImage', signature='id')
     def UpdateProgress(self, percentage, eta):
         """Download progress."""
+        log.info('EMIT UpdateProgress({}, {})', percentage, eta)
         self._loop.keepalive()
 
     @signal('com.canonical.SystemImage')
     def UpdateDownloaded(self):
         """The update has been successfully downloaded."""
+        log.info('EMIT UpdateDownloaded()')
         self._loop.keepalive()
 
     @signal('com.canonical.SystemImage', signature='is')
     def UpdateFailed(self, consecutive_failure_count, last_reason):
         """The update failed for some reason."""
+        log.info('EMIT UpdateFailed({}, {})',
+                 consecutive_failure_count, repr(last_reason))
         self._loop.keepalive()
 
     @signal('com.canonical.SystemImage', signature='i')
     def UpdatePaused(self, percentage):
         """The download got paused."""
+        log.info('EMIT UpdatePaused({})', percentage)
         self._loop.keepalive()
 
     @signal('com.canonical.SystemImage', signature='ss')
     def SettingChanged(self, key, new_value):
         """A setting value has change."""
+        log.info('EMIT SettingChanged({}, {})', repr(key), repr(new_value))
         self._loop.keepalive()
 
     @signal('com.canonical.SystemImage', signature='b')
@@ -329,3 +360,4 @@
         """The system is rebooting."""
         # We don't need to keep the loop alive since we're probably just going
         # to shutdown anyway.
+        log.info('EMIT Rebooting({})', status)

=== modified file 'systemimage/download.py'
--- systemimage/download.py	2014-02-13 18:16:17 +0000
+++ systemimage/download.py	2014-02-18 20:26:47 +0000
@@ -22,12 +22,16 @@
     ]
 
 
+import os
 import dbus
 import logging
+import tempfile
 
+from contextlib import ExitStack
 from io import StringIO
 from pprint import pformat
 from systemimage.config import config
+from systemimage.helpers import safe_remove
 from systemimage.reactor import Reactor
 
 
@@ -191,8 +195,25 @@
         for url, dst in downloads:
             print('\t{} -> {}'.format(url, dst), file=fp)
         log.info('{}'.format(fp.getvalue()))
+        # As a workaround for LP: #1277589, ask u-d-m to download the files to
+        # .tmp files, and if they succeed, then atomically move them into
+        # their real location.
+        renames = []
+        requests = []
+        for url, dst in downloads:
+            head, tail = os.path.split(dst)
+            fd, path = tempfile.mkstemp(suffix='.tmp', prefix='', dir=head)
+            os.close(fd)
+            renames.append((path, dst))
+            requests.append((url, path, ''))
+        # mkstemp() creates the file system path, but if the files exist when
+        # the group download is requested, ubuntu-download-manager will
+        # complain and return an error.  So, delete all temporary files now so
+        # udm has a clear path to download to.
+        for path, dst in renames:
+            os.remove(path)
         object_path = iface.createDownloadGroup(
-            [(url, dst, '') for url, dst in downloads],
+            requests,     # The temporary requests.
             '',           # No hashes yet.
             False,        # Don't allow GSM yet.
             # https://bugs.freedesktop.org/show_bug.cgi?id=55594
@@ -220,6 +241,19 @@
             raise Canceled
         if reactor.timed_out:
             raise TimeoutError
+        # Now that everything succeeded, rename the temporary files.  Just to
+        # be extra cautious, set up a context manager to safely remove all
+        # temporary files in case of an error.  If there are no errors, then
+        # there will be nothing to remove.
+        with ExitStack() as resources:
+            for tmp, dst in renames:
+                resources.callback(safe_remove, tmp)
+            for tmp, dst in renames:
+                os.rename(tmp, dst)
+            # We only get here if all the renames succeeded, so there will be
+            # no temporary files to remove, so we can throw away the new
+            # ExitStack, which holds all the removals.
+            resources.pop_all()
 
     def cancel(self):
         """Cancel any current downloads."""

=== modified file 'systemimage/service.py'
--- systemimage/service.py	2014-02-14 20:10:42 +0000
+++ systemimage/service.py	2014-02-18 20:26:47 +0000
@@ -30,7 +30,7 @@
 from dbus.mainloop.glib import DBusGMainLoop
 from pkg_resources import resource_string as resource_bytes
 from systemimage.config import config
-from systemimage.dbus import Loop, Service
+from systemimage.dbus import Loop
 from systemimage.helpers import makedirs
 from systemimage.logging import initialize
 from systemimage.main import DEFAULT_CONFIG_FILE
@@ -114,6 +114,7 @@
             config.dbus_service = get_service(
                 testing_mode, system_bus, '/Service', loop)
         else:
+            from systemimage.dbus import Service
             config.dbus_service = Service(system_bus, '/Service', loop)
         try:
             loop.run()

=== modified file 'systemimage/testing/controller.py'
--- systemimage/testing/controller.py	2014-02-13 18:16:17 +0000
+++ systemimage/testing/controller.py	2014-02-18 20:26:47 +0000
@@ -125,7 +125,7 @@
 class Controller:
     """Start and stop D-Bus service under test."""
 
-    def __init__(self):
+    def __init__(self, logfile=None):
         # Non-public.
         self._stack = ExitStack()
         self._stoppers = []
@@ -148,11 +148,15 @@
         # We need a client.ini file for the subprocess.
         ini_tmpdir = self._stack.enter_context(temporary_directory())
         ini_vardir = self._stack.enter_context(temporary_directory())
+        ini_logfile = (os.path.join(ini_tmpdir, 'client.log')
+                       if logfile is None
+                       else logfile)
         self.ini_path = os.path.join(self.tmpdir, 'client.ini')
         template = resource_bytes(
             'systemimage.tests.data', 'config_03.ini').decode('utf-8')
         with open(self.ini_path, 'w', encoding='utf-8') as fp:
-            print(template.format(tmpdir=ini_tmpdir, vardir=ini_vardir),
+            print(template.format(tmpdir=ini_tmpdir, vardir=ini_vardir,
+                                  logfile=ini_logfile),
                   file=fp)
 
     def _configure_services(self):

=== modified file 'systemimage/testing/helpers.py'
--- systemimage/testing/helpers.py	2014-02-13 21:44:16 +0000
+++ systemimage/testing/helpers.py	2014-02-18 20:26:47 +0000
@@ -347,7 +347,7 @@
         setup_keyring_txz(keyring + '.gpg', signing_kr, json_data, dst)
 
 
-def setup_index(index, todir, keyring):
+def setup_index(index, todir, keyring, write_callback=None):
     for image in get_index(index).images:
         for filerec in image.files:
             path = (filerec.path[1:]
@@ -355,10 +355,13 @@
                     else filerec.path)
             dst = os.path.join(todir, path)
             makedirs(os.path.dirname(dst))
-            contents = EMPTYSTRING.join(
-                os.path.splitext(filerec.path)[0].split('/'))
-            with open(dst, 'w', encoding='utf-8') as fp:
-                fp.write(contents)
+            if write_callback is None:
+                contents = EMPTYSTRING.join(
+                    os.path.splitext(filerec.path)[0].split('/'))
+                with open(dst, 'w', encoding='utf-8') as fp:
+                    fp.write(contents)
+            else:
+                write_callback(dst)
             # Sign with the specified signing key.
             sign(dst, keyring)
 

=== modified file 'systemimage/testing/nose.py'
--- systemimage/testing/nose.py	2014-02-14 20:12:08 +0000
+++ systemimage/testing/nose.py	2014-02-18 20:26:47 +0000
@@ -75,15 +75,24 @@
         super().__init__()
         self.patterns = []
         self.verbosity = 0
+        self.log_file = None
         self.addArgument(self.patterns, 'P', 'pattern',
                          'Add a test matching pattern')
         def bump(ignore):
             self.verbosity += 1
         self.addFlag(bump, 'V', 'Verbosity',
                      'Increase system-image verbosity')
+        def set_log_file(path):
+            self.log_file = path[0]
+        self.addOption(set_log_file, 'L', 'logfile',
+                       'Set the log file for the test run',
+                       nargs=1)
 
     @configuration
     def startTestRun(self, event):
+        from systemimage.config import config
+        if self.log_file is not None:
+            config.system.logfile = self.log_file
         DBusGMainLoop(set_as_default=True)
         initialize(verbosity=self.verbosity)
         # We need to set up the dbus service controller, since all the tests
@@ -92,7 +101,7 @@
         # individual services, and we can write new dbus configuration files
         # and HUP the dbus-launch to re-read them, but we cannot change bus
         # addresses after the initial one is set.
-        SystemImagePlugin.controller = Controller()
+        SystemImagePlugin.controller = Controller(self.log_file)
         SystemImagePlugin.controller.start()
         atexit.register(SystemImagePlugin.controller.stop)
 

=== modified file 'systemimage/tests/data/config_03.ini'
--- systemimage/tests/data/config_03.ini	2013-11-12 19:57:39 +0000
+++ systemimage/tests/data/config_03.ini	2014-02-18 20:26:47 +0000
@@ -14,7 +14,7 @@
 timeout: 1s
 build_file: {tmpdir}/ubuntu-build
 tempdir: {tmpdir}/tmp
-logfile: {tmpdir}/client.log
+logfile: {logfile}
 loglevel: info
 settings_db: {vardir}/settings.db
 

=== added file 'systemimage/tests/data/index_24.json'
--- systemimage/tests/data/index_24.json	1970-01-01 00:00:00 +0000
+++ systemimage/tests/data/index_24.json	2014-02-18 20:26:47 +0000
@@ -0,0 +1,36 @@
+{
+    "global": {
+        "generated_at": "Thu Aug 01 08:01:00 UTC 2013"
+    },
+    "images": [
+        {
+            "description": "Full",
+            "files": [
+                {
+                    "checksum": "5b05b298e974f3b9e40f0a1a8188f50984a4f18fb329e050324296632d3d9dfc",
+                    "order": 3,
+                    "path": "/3/4/5.txt",
+                    "signature": "/3/4/5.txt.asc",
+                    "size": 104857600
+                },
+                {
+                    "checksum": "5b05b298e974f3b9e40f0a1a8188f50984a4f18fb329e050324296632d3d9dfc",
+                    "order": 1,
+                    "path": "/4/5/6.txt",
+                    "signature": "/4/5/6.txt.asc",
+                    "size": 104857600
+                },
+                {
+                    "checksum": "5b05b298e974f3b9e40f0a1a8188f50984a4f18fb329e050324296632d3d9dfc",
+                    "order": 2,
+                    "path": "/5/6/7.txt",
+                    "signature": "/5/6/7.txt.asc",
+                    "size": 104857600
+                }
+            ],
+            "type": "full",
+            "version": 1600,
+            "bootme": true
+        }
+    ]
+}

=== modified file 'systemimage/tests/test_dbus.py'
--- systemimage/tests/test_dbus.py	2014-02-14 17:10:38 +0000
+++ systemimage/tests/test_dbus.py	2014-02-18 20:26:47 +0000
@@ -23,6 +23,7 @@
     'TestDBusGetSet',
     'TestDBusInfo',
     'TestDBusInfoNoDetails',
+    'TestDBusLP1277589',
     'TestDBusMockFailApply',
     'TestDBusMockFailPause',
     'TestDBusMockFailResume',
@@ -122,6 +123,23 @@
         self.quit()
 
 
+class DoubleCheckingReactor(Reactor):
+    def __init__(self, iface):
+        super().__init__(dbus.SystemBus())
+        self.iface = iface
+        self.uas_signals = []
+        self.react_to('UpdateAvailableStatus')
+        self.react_to('UpdateDownloaded')
+        self.schedule(self.iface.CheckForUpdate)
+
+    def _do_UpdateAvailableStatus(self, signal, path, *args, **kws):
+        self.uas_signals.append(args)
+        self.schedule(self.iface.CheckForUpdate)
+
+    def _do_UpdateDownloaded(self, *args, **kws):
+        self.quit()
+
+
 class _TestBase(unittest.TestCase):
     """Base class for all DBus testing."""
 
@@ -262,13 +280,14 @@
         safe_remove(self.reboot_log)
         super().tearDown()
 
-    def _prepare_index(self, index_file):
+    def _prepare_index(self, index_file, write_callback=None):
         serverdir = SystemImagePlugin.controller.serverdir
         index_path = os.path.join(serverdir, 'stable', 'nexus7', 'index.json')
         head, tail = os.path.split(index_path)
         copy(index_file, head, tail)
         sign(index_path, 'device-signing.gpg')
-        setup_index(index_file, serverdir, 'device-signing.gpg')
+        setup_index(index_file, serverdir, 'device-signing.gpg',
+                    write_callback)
 
     def _touch_build(self, version):
         # Unlike the touch_build() helper, this one uses our own config object
@@ -1542,3 +1561,45 @@
 update 5.txt 5.txt.asc
 unmount system
 """)
+
+
+class TestDBusLP1277589(_LiveTesting):
+    def test_multiple_check_for_updates(self):
+        # Log analysis of LP: #1277589 appears to show the following scenario,
+        # reproduced in this test case:
+        #
+        # * Automatic updates are enabled.
+        # * No image signing or image master keys are present.
+        # * A full update is checked.
+        #   - A new image master key and image signing key is downloaded.
+        #   - Update is available
+        #
+        # Start by creating some big files which will take a while to
+        # download.
+        def write_callback(dst):
+            # Write a 100 MiB sized file.
+            with open(dst, 'wb') as fp:
+                for i in range(25600):
+                    fp.write(b'x' * 4096)
+        self._prepare_index('index_24.json', write_callback)
+        # Create a reactor that will exit when the UpdateDownloaded signal is
+        # received.  We're going to issue a CheckForUpdate with automatic
+        # updates enabled.  As soon as we receive the UpdateAvailableStatus
+        # signal, we'll immediately issue *another* CheckForUpdate, which
+        # should run while the auto-download is working.
+        #
+        # At the end, we should not get another UpdateAvailableStatus signal,
+        # but we should get the UpdateDownloaded signal.
+        reactor = DoubleCheckingReactor(self.iface)
+        reactor.run()
+        self.assertEqual(len(reactor.uas_signals), 1)
+        (is_available, downloading, available_version, update_size,
+         last_update_date,
+         #descriptions,
+         error_reason) = reactor.uas_signals[0]
+        self.assertTrue(is_available)
+        self.assertTrue(downloading)
+        self.assertEqual(available_version, '1600')
+        self.assertEqual(update_size, 314572800)
+        self.assertEqual(last_update_date, 'Unknown')
+        self.assertEqual(error_reason, '')