Merge lp:~fcorrea/landscape-client/retry-apt-update into lp:~landscape/landscape-client/trunk

[Fernando Correa Neto]

Change the package reporter so it retries running apt-get update when an error 100 is returned, pretty much in the same way the charm code does it.

This branch changes the package reporter so it retries running apt-get update when an error 100 is returned, pretty much in the same way the charm code does it.

[Free Ekanayaka (free.ekanayaka)]

Looks basically good, just a few comments about testing and small factoring things.

review: Needs Fixing

[lp:~fcorrea/landscape-client/retry-apt-update]

808. By Fernando Correa Neto <email address hidden> on 2015-01-08

- change task handler code to accept a reactor.
- adjust tests to deal with it

809. By Fernando Correa Neto <email address hidden> on 2015-01-08

- adjust tests to advance the reactor manually

810. By Fernando Correa Neto <email address hidden> on 2015-01-08

- fix tests to comply with the new method signature
- simplify existing apt_update tests and so that it never messes with the real reactor

811. By Fernando Correa Neto <email address hidden> on 2015-01-08

- lint

812. By Fernando Correa Neto <email address hidden> on 2015-01-08

- do not gracefully bail. Log a warning instead

[Fernando Correa Neto (fcorrea)]

Thanks for the review Free.

I've addressed all points but one. See bellow.
Also, instead of faking the spawn_process call, I've decided to mock it as it ended up being cleaner.

[Free Ekanayaka (free.ekanayaka)]

Thanks Fernando, replied to the pending point and adding another one.

[lp:~fcorrea/landscape-client/retry-apt-update]

813. By Fernando Correa Neto <email address hidden> on 2015-01-09

- address review comments

[Fernando Correa Neto (fcorrea)]

Thanks, Free.

All comments has been addressed.

[Free Ekanayaka (free.ekanayaka)]

Looks great thanks, one last small thing, see the comment. +1

review: Approve

[Данило Шеган (danilo)]

Looks good, two minor comments inline.

review: Approve

[lp:~fcorrea/landscape-client/retry-apt-update]

814. By Fernando Correa Neto <email address hidden> on 2015-01-12

- address review comments

815. By Fernando Correa Neto <email address hidden> on 2015-01-12

- revert accidental syntax error

=== modified file 'landscape/package/changer.py'
--- landscape/package/changer.py	2013-07-16 13:15:03 +0000
+++ landscape/package/changer.py	2015-01-12 13:35:57 +0000
@@ -66,7 +66,8 @@
     def __init__(self, store, facade, remote, config, process_factory=reactor,
                  landscape_reactor=None,
                  reboot_required_filename=REBOOT_REQUIRED_FILENAME):
-        super(PackageChanger, self).__init__(store, facade, remote, config)
+        super(PackageChanger, self).__init__(
+            store, facade, remote, config, landscape_reactor)
         self._process_factory = process_factory
         if landscape_reactor is None:  # For testing purposes.
             from landscape.reactor import LandscapeReactor

=== modified file 'landscape/package/reporter.py'
--- landscape/package/reporter.py	2014-09-24 14:48:40 +0000
+++ landscape/package/reporter.py	2015-01-12 13:35:57 +0000
@@ -6,7 +6,8 @@
 import glob
 import apt_pkg
 
-from twisted.internet.defer import Deferred, succeed
+from twisted.internet.defer import (
+    Deferred, succeed, inlineCallbacks, returnValue)
 
 from landscape.lib.sequenceranges import sequence_to_ranges
 from landscape.lib.twisted_util import gather_results, spawn_process
@@ -21,6 +22,7 @@
 
 HASH_ID_REQUEST_TIMEOUT = 7200
 MAX_UNKNOWN_HASHES_PER_REQUEST = 500
+LOCK_RETRY_DELAYS = [0, 20, 40]
 
 
 class PackageReporterConfiguration(PackageTaskHandlerConfiguration):
@@ -192,8 +194,11 @@
         last_update = os.stat(stamp).st_mtime
         return (last_update + interval) < time.time()
 
+    @inlineCallbacks
     def run_apt_update(self):
-        """Run apt-update and log a warning in case of non-zero exit code.
+        """
+        Check if an L{_apt_update} call must be performed looping over specific
+        delays so it can be retried.
 
         @return: a deferred returning (out, err, code)
         """
@@ -201,12 +206,15 @@
             or self._apt_update_timeout_expired(
                 self._config.apt_update_interval)):
 
-            result = spawn_process(self.apt_update_filename)
+            accepted_apt_errors = (
+                "Problem renaming the file /var/cache/apt/srcpkgcache.bin",
+                "Problem renaming the file /var/cache/apt/pkgcache.bin")
 
-            def callback((out, err, code)):
-                accepted_apt_errors = (
-                    "Problem renaming the file /var/cache/apt/srcpkgcache.bin",
-                    "Problem renaming the file /var/cache/apt/pkgcache.bin")
+            for retry in range(len(LOCK_RETRY_DELAYS)):
+                deferred = Deferred()
+                self._reactor.call_later(
+                    LOCK_RETRY_DELAYS[retry], self._apt_update, deferred)
+                out, err, code = yield deferred
 
                 touch_file(self._config.update_stamp_filename)
                 logging.debug(
@@ -214,11 +222,19 @@
                         self.apt_update_filename, code, out, err))
 
                 if code != 0:
+                    if code == 100:
+                        if retry < len(LOCK_RETRY_DELAYS) - 1:
+                            logging.warning(
+                                "Could not acquire the apt lock. Retrying in"
+                                " %s seconds." % LOCK_RETRY_DELAYS[retry + 1])
+                            continue
+
                     logging.warning("'%s' exited with status %d (%s)" % (
                         self.apt_update_filename, code, err))
 
-                    # Errors caused by missing cache files are acceptable, as
-                    # they are not an issue for the lists update process.
+                    # Errors caused by missing cache files are acceptable,
+                    # as they are not an issue for the lists update
+                    # process.
                     # These errors can happen if an 'apt-get clean' is run
                     # while 'apt-get update' is running.
                     for message in accepted_apt_errors:
@@ -232,17 +248,25 @@
                            (self.sources_list_filename,
                             self.sources_list_directory))
 
-                deferred = self._broker.call_if_accepted(
+                yield self._broker.call_if_accepted(
                     "package-reporter-result", self.send_result, code, err)
-                deferred.addCallback(lambda ignore: (out, err, code))
-                return deferred
-
-            return result.addCallback(callback)
-
+                yield returnValue((out, err, code))
         else:
             logging.debug("'%s' didn't run, update interval has not passed" %
                           self.apt_update_filename)
-            return succeed(("", "", 0))
+            yield returnValue(("", "", 0))
+
+    def _apt_update(self, deferred):
+        """
+        Run apt-update using the passed in deferred, which allows for callers
+        to inspect the result code.
+        """
+        result = spawn_process(self.apt_update_filename)
+
+        def callback((out, err, code), deferred):
+            return deferred.callback((out, err, code))
+
+        return result.addCallback(callback, deferred)
 
     def send_result(self, code, err):
         """

=== modified file 'landscape/package/taskhandler.py'
--- landscape/package/taskhandler.py	2013-05-21 08:37:08 +0000
+++ landscape/package/taskhandler.py	2015-01-12 13:35:57 +0000
@@ -97,13 +97,15 @@
     # update-notifier-common package is installed.
     update_notifier_stamp = "/var/lib/apt/periodic/update-success-stamp"
 
-    def __init__(self, package_store, package_facade, remote_broker, config):
+    def __init__(self, package_store, package_facade, remote_broker, config,
+                 reactor):
         self._store = package_store
         self._facade = package_facade
         self._broker = remote_broker
         self._config = config
         self._count = 0
         self._session_id = None
+        self._reactor = reactor
 
     def run(self):
         return self.handle_tasks()
@@ -295,7 +297,7 @@
 
     connector = RemoteBrokerConnector(reactor, config, retry_on_reconnect=True)
     remote = LazyRemoteBroker(connector)
-    handler = cls(package_store, package_facade, remote, config)
+    handler = cls(package_store, package_facade, remote, config, reactor)
     result = Deferred()
     result.addCallback(lambda x: handler.run())
     result.addCallback(lambda x: finish())

=== modified file 'landscape/package/tests/test_releaseupgrader.py'
--- landscape/package/tests/test_releaseupgrader.py	2014-12-12 12:39:21 +0000
+++ landscape/package/tests/test_releaseupgrader.py	2015-01-12 13:35:57 +0000
@@ -42,7 +42,7 @@
         os.mkdir(self.config.upgrade_tool_directory)
         self.store = PackageStore(self.makeFile())
         self.upgrader = ReleaseUpgrader(self.store, None,
-                                        self.remote, self.config)
+                                        self.remote, self.config, None)
         service = self.broker_service
         service.message_store.set_accepted_types(["operation-result"])
 

=== modified file 'landscape/package/tests/test_reporter.py'
--- landscape/package/tests/test_reporter.py	2014-09-24 14:48:40 +0000
+++ landscape/package/tests/test_reporter.py	2015-01-12 13:35:57 +0000
@@ -23,6 +23,7 @@
 from landscape.tests.helpers import (
     LandscapeTest, BrokerServiceHelper, EnvironSaverHelper)
 from landscape.tests.mocker import ANY
+from landscape.reactor import FakeReactor
 
 SAMPLE_LSB_RELEASE = "DISTRIB_CODENAME=codename\n"
 
@@ -51,8 +52,9 @@
         super(PackageReporterAptTest, self).setUp()
         self.store = PackageStore(self.makeFile())
         self.config = PackageReporterConfiguration()
+        self.reactor = FakeReactor()
         self.reporter = PackageReporter(
-            self.store, self.facade, self.remote, self.config)
+            self.store, self.facade, self.remote, self.config, self.reactor)
         self.reporter.get_session_id()
         # Assume update-notifier-common stamp file is not present by
         # default.
@@ -1119,7 +1121,6 @@
         deferred = self.reporter.run()
 
         def check_result(result):
-
             # The hashes should not go away.
             hash1 = self.store.get_hash_id(foo_hash)
             hash2 = self.store.get_hash_id(HASH2)
@@ -1140,6 +1141,7 @@
             self.assertEqual(request.hashes, [HASH3, HASH1])
 
         deferred.addCallback(check_result)
+        self.reactor.advance(0)
         return deferred
 
     def test_run_apt_update(self):
@@ -1165,6 +1167,7 @@
                 self.assertEqual("error", err)
                 self.assertEqual(0, code)
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1179,18 +1182,14 @@
         self.config.load(["--force-apt-update"])
         self._make_fake_apt_update()
 
-        deferred = Deferred()
-
-        def do_test():
-            result = self.reporter.run_apt_update()
-
-            def callback((out, err, code)):
-                self.assertEqual("output", out)
-            result.addCallback(callback)
-            result.chainDeferred(deferred)
-
-        reactor.callWhenRunning(do_test)
-        return deferred
+        result = self.reporter.run_apt_update()
+
+        def callback((out, err, code)):
+            self.assertEqual("output", out)
+
+        result.addCallback(callback)
+        self.reactor.advance(0)
+        return result
 
     def test_run_apt_update_with_force_apt_update_if_sources_changed(self):
         """
@@ -1203,18 +1202,14 @@
         self.reporter.sources_list_filename = self.makeFile("deb ftp://url ./")
         self._make_fake_apt_update()
 
-        deferred = Deferred()
-
-        def do_test():
-            result = self.reporter.run_apt_update()
-
-            def callback((out, err, code)):
-                self.assertEqual("output", out)
-            result.addCallback(callback)
-            result.chainDeferred(deferred)
-
-        reactor.callWhenRunning(do_test)
-        return deferred
+        result = self.reporter.run_apt_update()
+
+        def callback((out, err, code)):
+            self.assertEqual("output", out)
+
+        result.addCallback(callback)
+        self.reactor.advance(0)
+        return result
 
     def test_run_apt_update_warns_about_failures(self):
         """
@@ -1225,21 +1220,87 @@
         logging_mock = self.mocker.replace("logging.warning")
         logging_mock("'%s' exited with status 2"
                      " (error)" % self.reporter.apt_update_filename)
-        self.mocker.replay()
-        deferred = Deferred()
-
-        def do_test():
-            result = self.reporter.run_apt_update()
-
-            def callback((out, err, code)):
-                self.assertEqual("output", out)
-                self.assertEqual("error", err)
-                self.assertEqual(2, code)
-            result.addCallback(callback)
-            result.chainDeferred(deferred)
-
-        reactor.callWhenRunning(do_test)
-        return deferred
+
+        self.mocker.replay()
+
+        result = self.reporter.run_apt_update()
+
+        def callback((out, err, code)):
+            self.assertEqual("output", out)
+            self.assertEqual("error", err)
+            self.assertEqual(2, code)
+
+        result.addCallback(callback)
+        self.reactor.advance(0)
+        return result
+
+    def test_run_apt_update_warns_about_lock_failure(self):
+        """
+        The L{PackageReporter.run_apt_update} method logs a warnings when
+        apt-update fails acquiring the lock.
+        """
+        self._make_fake_apt_update(code=100)
+        logging_mock = self.mocker.replace("logging.warning")
+        logging_mock("Could not acquire the apt lock. Retrying in 20 seconds.")
+        logging_mock("Could not acquire the apt lock. Retrying in 40 seconds.")
+        logging_mock("'%s' exited with status 100 ()" %
+                     self.reporter.apt_update_filename)
+
+        spawn_mock = self.mocker.replace(
+            "landscape.lib.twisted_util.spawn_process")
+        spawn_mock(ANY)
+        # Simulate the first failure.
+        self.mocker.result(succeed(('', '', 100)))
+        spawn_mock(ANY)
+        # Simulate the second failure.
+        self.mocker.result(succeed(('', '', 100)))
+        spawn_mock(ANY)
+        # Simulate the second failure.
+        self.mocker.result(succeed(('', '', 100)))
+
+        self.mocker.replay()
+
+        result = self.reporter.run_apt_update()
+
+        def callback((out, err, code)):
+            self.assertEqual("", out)
+            self.assertEqual("", err)
+            self.assertEqual(100, code)
+
+        result.addCallback(callback)
+        self.reactor.advance(60)
+        return result
+
+    def test_run_apt_update_stops_retrying_after_lock_acquired(self):
+        """
+        When L{PackageReporter.run_apt_update} method successfully acquires the
+        lock, it will stop retrying.
+        """
+        self._make_fake_apt_update(code=100)
+        logging_mock = self.mocker.replace("logging.warning")
+        logging_mock("Could not acquire the apt lock. Retrying in 20 seconds.")
+
+        spawn_mock = self.mocker.replace(
+            "landscape.lib.twisted_util.spawn_process")
+        spawn_mock(ANY)
+        # Simulate the first failure.
+        self.mocker.result(succeed(('', '', 100)))
+        spawn_mock(ANY)
+        # Simulate a successful apt lock grab.
+        self.mocker.result(succeed(('output', 'error', 0)))
+
+        self.mocker.replay()
+
+        result = self.reporter.run_apt_update()
+
+        def callback((out, err, code)):
+            self.assertEqual("output", out)
+            self.assertEqual("error", err)
+            self.assertEqual(0, code)
+
+        result.addCallback(callback)
+        self.reactor.advance(20)
+        return result
 
     def test_run_apt_update_report_apt_failure(self):
         """
@@ -1260,6 +1321,7 @@
                     [{"type": "package-reporter-result",
                       "code": 2, "err": u"error"}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1290,6 +1352,7 @@
                     [{"type": "package-reporter-result",
                       "code": 1, "err": error}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1315,6 +1378,7 @@
                     [{"type": "package-reporter-result",
                       "code": 2, "err": u"error"}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1339,6 +1403,7 @@
                     [{"type": "package-reporter-result",
                       "code": 0, "err": u"message"}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1366,6 +1431,7 @@
                 self.assertEqual("", err)
                 self.assertEqual(0, code)
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1402,6 +1468,7 @@
                 self.assertEqual("", err)
                 self.assertEqual(0, code)
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1438,6 +1505,7 @@
                     [{"type": "package-reporter-result",
                       "code": 0, "err": u"message"}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1459,6 +1527,7 @@
                 self.assertTrue(
                     os.path.exists(self.config.update_stamp_filename))
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1492,6 +1561,7 @@
                     [{"type": "package-reporter-result",
                       "code": 0, "err": u""}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1528,6 +1598,7 @@
                     [{"type": "package-reporter-result",
                       "code": 0, "err": u""}])
             result.addCallback(callback)
+            self.reactor.advance(0)
             result.chainDeferred(deferred)
 
         reactor.callWhenRunning(do_test)
@@ -1632,8 +1703,9 @@
         super(GlobalPackageReporterAptTest, self).setUp()
         self.store = FakePackageStore(self.makeFile())
         self.config = PackageReporterConfiguration()
+        self.reactor = FakeReactor()
         self.reporter = FakeGlobalReporter(
-            self.store, self.facade, self.remote, self.config)
+            self.store, self.facade, self.remote, self.config, self.reactor)
         # Assume update-notifier-common stamp file is not present by
         # default.
         self.reporter.update_notifier_stamp = "/Not/Existing"
@@ -1654,6 +1726,7 @@
         def do_test():
             self.reporter.get_session_id()
             result = self.reporter.run_apt_update()
+            self.reactor.advance(0)
 
             def callback(ignore):
                 message = {"type": "package-reporter-result",
@@ -1683,8 +1756,9 @@
         self.global_store = FakePackageStore(global_file)
         os.environ["FAKE_PACKAGE_STORE"] = global_file
         self.config = PackageReporterConfiguration()
+        self.reactor = FakeReactor()
         self.reporter = FakeReporter(
-            self.store, None, self.remote, self.config)
+            self.store, None, self.remote, self.config, self.reactor)
         self.config.data_path = self.makeDir()
         os.mkdir(self.config.package_directory)
 

=== modified file 'landscape/package/tests/test_taskhandler.py'
--- landscape/package/tests/test_taskhandler.py	2013-05-21 08:37:08 +0000
+++ landscape/package/tests/test_taskhandler.py	2015-01-12 13:35:57 +0000
@@ -44,8 +44,9 @@
         super(PackageTaskHandlerTest, self).setUp()
         self.config = PackageTaskHandlerConfiguration()
         self.store = PackageStore(self.makeFile())
+        self.reactor = FakeReactor()
         self.handler = PackageTaskHandler(
-            self.store, self.facade, self.remote, self.config)
+            self.store, self.facade, self.remote, self.config, self.reactor)
 
     def test_use_hash_id_db(self):
 
@@ -363,7 +364,7 @@
         umask(022)
 
         handler_args = []
-        HandlerMock(ANY, ANY, ANY, ANY)
+        HandlerMock(ANY, ANY, ANY, ANY, ANY)
         self.mocker.passthrough()  # Let the real constructor run for testing.
         self.mocker.call(lambda *args: handler_args.extend(args))
 
@@ -390,7 +391,7 @@
 
         def assert_task_handler(ignored):
 
-            store, facade, broker, config = handler_args
+            store, facade, broker, config, reactor = handler_args
 
             try:
                 # Verify the arguments passed to the reporter constructor.
@@ -399,6 +400,7 @@
                 self.assertEqual(type(broker), LazyRemoteBroker)
                 self.assertEqual(type(config),
                                  PackageTaskHandlerConfiguration)
+                self.assertEqual(type(reactor), LandscapeReactor)
 
                 # Let's see if the store path is where it should be.
                 filename = os.path.join(self.data_path, "package", "database")