Merge lp:~barry/ubuntu-system-image/citrain302 into lp:~ubuntu-managed-branches/ubuntu-system-image/system-image

[Barry Warsaw]

Don't crash when one of the .ini files is a dangling symlink. (LP: #1495688)

3.0.2 (2015-09-22)
==================
 * Don't crash when one of the .ini files is a dangling symlink.
   (LP: #1495688)

[lp:~barry/ubuntu-system-image/citrain302]

245. By Barry Warsaw on 2015-09-28

d/rules: override_dh_auto_clean because otherwise, pybuild will
remove the .egg-info files and that causes the Jenkins job in the CI
train to fail.

=== modified file 'NEWS.rst'
--- NEWS.rst	2015-06-17 15:18:22 +0000
+++ NEWS.rst	2015-09-28 21:36:51 +0000
@@ -2,6 +2,11 @@
 NEWS for system-image updater
 =============================
 
+3.0.2 (2015-09-22)
+==================
+ * Don't crash when one of the .ini files is a dangling symlink.
+   (LP: #1495688)
+
 3.0.1 (2015-06-16)
 ==================
  * When `--progress=json` is used, print an error record to stdout if the
 
=== modified file 'PKG-INFO'
--- PKG-INFO	2015-06-17 15:18:22 +0000
+++ PKG-INFO	2015-09-28 21:36:51 +0000
@@ -1,6 +1,6 @@
 Metadata-Version: 1.0
 Name: system-image
-Version: 3.0.1
+Version: 3.0.2
 Summary: Ubuntu System Image Based Upgrades
 Home-page: UNKNOWN
 Author: Barry Warsaw
 
=== modified file 'debian/changelog'
--- debian/changelog	2015-06-18 16:23:37 +0000
+++ debian/changelog	2015-09-28 21:36:51 +0000
@@ -1,3 +1,14 @@
+system-image (3.0.2-0ubuntu1) wily; urgency=medium
+
+  * New upstream release.
+    - LP: #1495688 - Don't crash when one of the .ini files is a dangling
+      symlink.
+    - d/rules: override_dh_auto_clean because otherwise, pybuild will
+      remove the .egg-info files and that causes the Jenkins job in the CI
+      train to fail.
+
+ -- Barry Warsaw <[e-mail]>  Fri, 25 Sep 2015 15:28:37 -0400
+
 system-image (3.0.1-0ubuntu1) wily; urgency=medium
 
   * New rebuild forced.
 
=== modified file 'debian/rules'
--- debian/rules	2015-05-09 15:50:39 +0000
+++ debian/rules	2015-09-28 21:36:51 +0000
@@ -56,3 +56,6 @@
 	rst2man dbus-manpage.rst > debian/tmp/system-image-dbus.man
 	rst2man ini-manpage.rst > debian/tmp/client-ini.man
 	dh_installman
+
+# We don't want the buildds to remove the .egg-info files.
+override_dh_auto_clean:
 
=== modified file 'setup.cfg'
--- setup.cfg	2015-06-17 15:18:22 +0000
+++ setup.cfg	2015-09-28 21:36:51 +0000
@@ -4,7 +4,7 @@
 logging-filter = systemimage
 
 [egg_info]
-tag_date = 0
 tag_svn_revision = 0
 tag_build = 
+tag_date = 0
 
 
=== modified file 'system_image.egg-info/PKG-INFO'
--- system_image.egg-info/PKG-INFO	2015-06-17 15:18:22 +0000
+++ system_image.egg-info/PKG-INFO	2015-09-28 21:36:51 +0000
@@ -1,6 +1,6 @@
 Metadata-Version: 1.0
 Name: system-image
-Version: 3.0.1
+Version: 3.0.2
 Summary: Ubuntu System Image Based Upgrades
 Home-page: UNKNOWN
 Author: Barry Warsaw
 
=== modified file 'system_image.egg-info/SOURCES.txt'
--- system_image.egg-info/SOURCES.txt	2015-05-08 21:41:15 +0000
+++ system_image.egg-info/SOURCES.txt	2015-09-28 21:36:51 +0000
@@ -14,6 +14,7 @@
 system_image.egg-info/SOURCES.txt
 system_image.egg-info/dependency_links.txt
 system_image.egg-info/entry_points.txt
+system_image.egg-info/pbr.json
 system_image.egg-info/requires.txt
 system_image.egg-info/top_level.txt
 systemimage/__init__.py
 
=== added file 'system_image.egg-info/pbr.json'
--- system_image.egg-info/pbr.json	1970-01-01 00:00:00 +0000
+++ system_image.egg-info/pbr.json	2015-09-28 21:36:51 +0000
@@ -0,0 +1,1 @@
+{"is_release": true, "git_version": "4ecc87c"}
 \ No newline at end of file
 
=== modified file 'systemimage/helpers.py'
--- systemimage/helpers.py	2015-05-08 21:41:15 +0000
+++ systemimage/helpers.py	2015-09-28 21:36:51 +0000
@@ -41,7 +41,7 @@
 import logging
 import tempfile
 
-from contextlib import ExitStack, contextmanager
+from contextlib import ExitStack, contextmanager, suppress
 from datetime import datetime, timedelta
 from hashlib import sha256
 from importlib import import_module
@@ -252,13 +252,19 @@
     try:
         timestamp = datetime.fromtimestamp(os.stat(LAST_UPDATE_FILE).st_mtime)
     except (FileNotFoundError, PermissionError):
-        # We fall back to the latest mtime of the config.d/*.ini files.
-        timestamps = sorted(
-            datetime.fromtimestamp(path.stat().st_mtime)
-            for path in config.ini_files)
+        # We fall back to the latest mtime of the config.d/*.ini files.  For
+        # robustness, watch out for two possibilities: the config file could
+        # have been deleted after the system started up (thus making
+        # config.ini_files include nonexistent files), and the ini file could
+        # be a dangling symlink.  For the latter, use lstat().
+        timestamps = []
+        for path in config.ini_files:
+            with suppress(FileNotFoundError):
+                timestamps.append(
+                    datetime.fromtimestamp(path.lstat().st_mtime))
         if len(timestamps) == 0:
             return 'Unknown'
-        timestamp = timestamps[-1]
+        timestamp = sorted(timestamps)[-1]
     return str(timestamp.replace(microsecond=0))
 
 
 
=== modified file 'systemimage/logging.py'
--- systemimage/logging.py	2015-05-08 21:41:15 +0000
+++ systemimage/logging.py	2015-09-28 21:36:51 +0000
@@ -18,6 +18,7 @@
 __all__ = [
     'debug_logging',
     'initialize',
+    'make_handler',
     ]
 
 
@@ -68,13 +69,16 @@
             return super().getMessage()
 
 
-def _make_handler(path):
+def make_handler(path):
     # issue21539 - mkdir(..., exist_ok=True)
     with suppress(FileExistsError):
         path.parent.mkdir(DEFAULT_DIRMODE, parents=True)
     path.touch(LOGFILE_PERMISSIONS)
     # Our handler will output in UTF-8 using {} style logging.
-    return logging.FileHandler(bytes(path), encoding='utf-8')
+    formatter = logging.Formatter(style='{', fmt=MSG_FMT, datefmt=DATE_FMT)
+    handler = logging.FileHandler(bytes(path), encoding='utf-8')
+    handler.setFormatter(formatter)
+    return handler
 
 
 def initialize(*, verbosity=0):
@@ -95,13 +99,11 @@
         # Now configure the application level logger based on the ini file.
         log = logging.getLogger(name)
         try:
-            handler = _make_handler(Path(config.system.logfile))
+            handler = make_handler(Path(config.system.logfile))
         except PermissionError:
-            handler = _make_handler(
+            handler = make_handler(
                 Path(xdg_cache_home) / 'system-image' / 'client.log')
         handler.setLevel(level)
-        formatter = logging.Formatter(style='{', fmt=MSG_FMT, datefmt=DATE_FMT)
-        handler.setFormatter(formatter)
         log.addHandler(handler)
         log.propagate = False
         # If we want more verbosity, add a stream handler.
@@ -111,6 +113,8 @@
         else:                                       # pragma: no cover
             handler = logging.StreamHandler(stream=sys.stderr)
             handler.setLevel(level)
+            formatter = logging.Formatter(
+                style='{', fmt=MSG_FMT, datefmt=DATE_FMT)
             handler.setFormatter(formatter)
             log.addHandler(handler)
             # Set the overall level on the log object to the minimum level.
 
=== modified file 'systemimage/testing/dbus.py'
--- systemimage/testing/dbus.py	2015-05-08 21:41:15 +0000
+++ systemimage/testing/dbus.py	2015-09-28 21:36:51 +0000
@@ -22,6 +22,7 @@
 
 
 import os
+import logging
 
 try:
     import pycurl
@@ -30,10 +31,12 @@
 
 from dbus.service import method, signal
 from gi.repository import GLib
+from pathlib import Path
 from systemimage.api import Mediator
 from systemimage.config import config
 from systemimage.dbus import Service, log_and_exit
 from systemimage.helpers import MiB, makedirs, safe_remove, version_detail
+from systemimage.logging import make_handler
 from unittest.mock import patch
 
 
@@ -74,6 +77,10 @@
 class _LiveTestableService(Service):
     """For testing purposes only."""
 
+    def __init__(self, bus, object_path, loop):
+        super().__init__(bus, object_path, loop)
+        self._debug_handler = None
+
     @log_and_exit
     @method('com.canonical.SystemImage')
     def Reset(self):
@@ -103,6 +110,27 @@
     def TornDown(self):
         pass
 
+    @log_and_exit
+    @method('com.canonical.SystemImage',
+            in_signature='ss',
+            out_signature='ss')
+    def DebugDBusTo(self, filename, level_name):
+        # Get the existing logging level and logging file name.
+        dbus_log = logging.getLogger('systemimage.dbus')
+        old_level = logging.getLevelName(dbus_log.getEffectiveLevel())
+        old_filename = config.system.logfile
+        # Remove any previous D-Bus debugging handler.
+        if self._debug_handler is not None:
+            dbus_log.removeHandler(self._debug_handler)
+            self._debug_handler = None
+        new_level = getattr(logging, level_name.upper())
+        dbus_log.setLevel(new_level)
+        if filename != '':
+            self._debug_handler = make_handler(Path(filename))
+            self._debug_handler.setLevel(new_level)
+            dbus_log.addHandler(self._debug_handler)
+        return old_filename, old_level
+
 
 class _UpdateAutoSuccess(Service):
     """Normal update in auto-download mode."""
 
=== modified file 'systemimage/tests/test_dbus.py'
--- systemimage/tests/test_dbus.py	2015-05-08 21:41:15 +0000
+++ systemimage/tests/test_dbus.py	2015-09-28 21:36:51 +0000
@@ -44,10 +44,12 @@
 
 
 import os
+import sys
 import dbus
 import json
 import time
 import shutil
+import tempfile
 import unittest
 
 from contextlib import ExitStack, suppress
@@ -61,6 +63,7 @@
 from systemimage.helpers import MiB, safe_remove
 from systemimage.reactor import Reactor
 from systemimage.settings import Settings
+from systemimage.testing.controller import USING_PYCURL
 from systemimage.testing.helpers import (
     copy, data_path, find_dbus_process, make_http_server, setup_index,
     setup_keyring_txz, setup_keyrings, sign, terminate_service, touch_build,
@@ -78,6 +81,27 @@
     'last_update_date error_reason')
 
 
+def capture_dbus_calls(function):
+    def inner(self, *args, **kws):
+        with ExitStack() as resources:
+            fd, filename = tempfile.mkstemp('.log')
+            os.close(fd)
+            resources.callback(os.remove, filename)
+            old_filename, old_level = self.iface.DebugDBusTo(filename, 'debug')
+            try:
+                result = function(self, *args, **kws)
+            finally:
+                self.iface.DebugDBusTo('', old_level)
+                with open(filename, 'r', encoding='utf-8') as fp:
+                    print('\nvvvvv', function.__name__,
+                          'dbus calls vvvvv', file=sys.stderr)
+                    sys.stderr.write(fp.read())
+                    print('^^^^^', function.__name__,
+                          'dbus calls ^^^^^', file=sys.stderr)
+            return result
+    return inner
+
+
 def tweak_checksums(checksum):
     index_path = os.path.join(
         SystemImagePlugin.controller.serverdir,
@@ -1717,7 +1741,9 @@
             write_bytes(full_path, 750)
         tweak_checksums('')
 
+    @capture_dbus_calls
     def test_pause(self):
+        # Set up some extra D-Bus debugging.
         self.download_manually()
         touch_build(0, use_config=self.config)
         reactor = SignalCapturingReactor('UpdateAvailableStatus')
@@ -1966,8 +1992,6 @@
         self.assertEqual(reactor.uas_signals[0], reactor.uas_signals[1])
 
 
-from systemimage.testing.controller import USING_PYCURL
-
 @unittest.skipIf(os.getuid() == 0, 'Test cannot succeed when run as root')
 @unittest.skipUnless(USING_PYCURL, 'LP: #1411866')
 class TestDBusCheckForUpdateToUnwritablePartition(_LiveTesting):
 
=== modified file 'systemimage/tests/test_helpers.py'
--- systemimage/tests/test_helpers.py	2015-05-08 21:41:15 +0000
+++ systemimage/tests/test_helpers.py	2015-09-28 21:36:51 +0000
@@ -255,6 +255,52 @@
             # The last update date will be the date of the 99_build.ini file.
             self.assertEqual(last_update_date(), '2022-01-02 03:04:05')
 
+    @configuration
+    def test_dangling_symlink(self, config):
+        # LP: #1495688 reports a problem where /userdata/.last_update doesn't
+        # exist, and the files in the config.d directory are dangling
+        # symlinks.  In this case, there's really little that can be done to
+        # find a reliable last update date, but at least we don't crash.
+        #
+        # Start by deleting any existing .ini files in config.d.
+        for path in Path(config.config_d).iterdir():
+            if path.suffix == '.ini':
+                path.unlink()
+        with ExitStack() as stack:
+            tmpdir = stack.enter_context(temporary_directory())
+            userdata_path = Path(tmpdir) / '.last_update'
+            stack.enter_context(patch('systemimage.helpers.LAST_UPDATE_FILE',
+                                      str(userdata_path)))
+            # Do not create the .last_update file.
+            missing_ini = Path(tmpdir) / 'missing.ini'
+            config.ini_files = [missing_ini]
+            # Do not create the missing.ini file, but do create a symlink from
+            # a config.d file to this missing file.
+            default_ini = Path(config.config_d) / '00_default.ini'
+            default_ini.symlink_to(missing_ini)
+            last_update_date()
+            self.assertEqual(last_update_date(), 'Unknown')
+
+    @configuration
+    def test_post_startup_delete(self, config):
+        # Like test_dangling_symlink() except that an existing ini file gets
+        # deleted after system startup, so some of the files that
+        # last_update_date() looks at will throw an exception.
+        #
+        # Start by deleting any existing .ini files in config.d.  This time
+        # however we don't update config.ini_files.
+        for path in Path(config.config_d).iterdir():
+            if path.suffix == '.ini':
+                path.unlink()
+        with ExitStack() as stack:
+            tmpdir = stack.enter_context(temporary_directory())
+            userdata_path = Path(tmpdir) / '.last_update'
+            stack.enter_context(patch('systemimage.helpers.LAST_UPDATE_FILE',
+                                      str(userdata_path)))
+            # Do not create the .last_update file.
+            last_update_date()
+            self.assertEqual(last_update_date(), 'Unknown')
+
 
 class TestPhasedPercentage(unittest.TestCase):
     def setUp(self):
 
=== modified file 'systemimage/version.txt'
--- systemimage/version.txt	2015-06-17 15:18:22 +0000
+++ systemimage/version.txt	2015-09-28 21:36:51 +0000
@@ -1,1 +1,1 @@
-3.0.1
+3.0.2