Raise 412 response on expirer

Currently, the expirer daemon treats 412 (precondition failed)
as successful DELETEs.

On the other hand, it treats 404 as failed while reclaim_age
(usually a week) has not passed.
This patch unifies both cases to the same handling: waiting for
reclaim_age to pass, then deleting the entry.

The reason the expirer should not delete a 412 entry right away,
is that it might be the case that 412 is returned because of
a split brain, where the updated object servers are currently down.
Same reason holds for a 404 response.

Change-Id: Icabbdd72746a211b68f266a49231881f0f4ace94

swift/obj/expirer.py

@@ -260,7 +260,8 @@ class ObjectExpirer(Daemon):
             try:
                 self.delete_actual_object(actual_obj, timestamp)
             except UnexpectedResponse as err:
-                if err.resp.status_int != HTTP_NOT_FOUND:
+                if err.resp.status_int not in {HTTP_NOT_FOUND,
+                                               HTTP_PRECONDITION_FAILED}:
                     raise
                 if float(timestamp) > time() - self.reclaim_age:
                     # we'll have to retry the DELETE later
@@ -301,4 +302,4 @@ class ObjectExpirer(Daemon):
         self.swift.make_request('DELETE', path,
                                 {'X-If-Delete-At': str(timestamp),
                                  'X-Timestamp': str(timestamp)},
-                                (2, HTTP_PRECONDITION_FAILED))
+                                (2,))

test/probe/test_object_expirer.py

@@ -50,6 +50,15 @@ class TestObjectExpirer(ReplProbeTest):
         self.brain = BrainSplitter(self.url, self.token, self.container_name,
                                    self.object_name)
 
+    def _check_obj_in_container_listing(self):
+        for obj in self.client.iter_objects(self.account,
+                                            self.container_name):
+
+            if self.object_name == obj['name']:
+                return True
+
+        return False
+
     def test_expirer_object_split_brain(self):
         if len(ENABLED_POLICIES) < 2:
             raise SkipTest('Need more than one policy')
@@ -93,12 +102,8 @@ class TestObjectExpirer(ReplProbeTest):
                          create_timestamp)
 
         # but it is still in the listing
-        for obj in self.client.iter_objects(self.account,
+        self.assertTrue(self._check_obj_in_container_listing(),
-                                            self.container_name):
+                        msg='Did not find listing for %s' % self.object_name)
-            if self.object_name == obj['name']:
-                break
-        else:
-            self.fail('Did not find listing for %s' % self.object_name)
 
         # clear proxy cache
         client.post_container(self.url, self.token, self.container_name, {})
@@ -106,10 +111,8 @@ class TestObjectExpirer(ReplProbeTest):
         self.expirer.once()
 
         # object is not in the listing
-        for obj in self.client.iter_objects(self.account,
+        self.assertFalse(self._check_obj_in_container_listing(),
-                                            self.container_name):
+                         msg='Found listing for %s' % self.object_name)
-            if self.object_name == obj['name']:
-                self.fail('Found listing for %s' % self.object_name)
 
         # and validate object is tombstoned
         found_in_policy = None
@@ -226,6 +229,73 @@ class TestObjectExpirer(ReplProbeTest):
 
         self.assertIn('x-object-meta-expired', metadata)
 
+    def _test_expirer_delete_outdated_object_version(self, object_exists):
+        # This test simulates a case where the expirer tries to delete
+        # an outdated version of an object.
+        # One case is where the expirer gets a 404, whereas the newest version
+        # of the object is offline.
+        # Another case is where the expirer gets a 412, since the old version
+        # of the object mismatches the expiration time sent by the expirer.
+        # In any of these cases, the expirer should retry deleting the object
+        # later, for as long as a reclaim age has not passed.
+        obj_brain = BrainSplitter(self.url, self.token, self.container_name,
+                                  self.object_name, 'object', self.policy)
+
+        obj_brain.put_container()
+
+        if object_exists:
+            obj_brain.put_object()
+
+        # currently, the object either doesn't exist, or does not have
+        # an expiration
+
+        # stop primary servers and put a newer version of the object, this
+        # time with an expiration. only the handoff servers will have
+        # the new version
+        obj_brain.stop_primary_half()
+        now = time.time()
+        delete_at = int(now + 2.0)
+        obj_brain.put_object({'X-Delete-At': delete_at})
+
+        # make sure auto-created containers get in the account listing
+        Manager(['container-updater']).once()
+
+        # update object record in the container listing
+        Manager(['container-replicator']).once()
+
+        # take handoff servers down, and bring up the outdated primary servers
+        obj_brain.start_primary_half()
+        obj_brain.stop_handoff_half()
+
+        # wait until object expiration time
+        while time.time() <= delete_at:
+            time.sleep(0.1)
+
+        # run expirer against the outdated servers. it should fail since
+        # the outdated version does not match the expiration time
+        self.expirer.once()
+
+        # bring all servers up, and run replicator to update servers
+        obj_brain.start_handoff_half()
+        Manager(['object-replicator']).once()
+
+        # verify the deletion has failed by checking the container listing
+        self.assertTrue(self._check_obj_in_container_listing(),
+                        msg='Did not find listing for %s' % self.object_name)
+
+        # run expirer again, delete should now succeed
+        self.expirer.once()
+
+        # verify the deletion by checking the container listing
+        self.assertFalse(self._check_obj_in_container_listing(),
+                         msg='Found listing for %s' % self.object_name)
+
+    def test_expirer_delete_returns_outdated_404(self):
+        self._test_expirer_delete_outdated_object_version(object_exists=False)
+
+    def test_expirer_delete_returns_outdated_412(self):
+        self._test_expirer_delete_outdated_object_version(object_exists=True)
+
 
 if __name__ == "__main__":
     unittest.main()

test/unit/obj/test_expirer.py

@@ -24,7 +24,7 @@ import mock
 import six
 from six.moves import urllib
 
-from swift.common import internal_client, utils
+from swift.common import internal_client, utils, swob
 from swift.obj import expirer
 
 
@@ -55,7 +55,7 @@ class TestObjectExpirer(TestCase):
 
         self.rcache = mkdtemp()
         self.conf = {'recon_cache_path': self.rcache}
-        self.logger = debug_logger('test-recon')
+        self.logger = debug_logger('test-expirer')
 
     def tearDown(self):
         rmtree(self.rcache)
@@ -185,52 +185,55 @@ class TestObjectExpirer(TestCase):
         self.assertEqual(len(set(x.obj_containers_in_order[:4])), 4)
 
     def test_delete_object(self):
-        class InternalClient(object):
+        x = expirer.ObjectExpirer({}, logger=self.logger)
-
+        actual_obj = 'actual_obj'
-            container_ring = None
+        timestamp = int(time())
-
+        reclaim_ts = timestamp - x.reclaim_age
-            def __init__(self, test, account, container, obj):
-                self.test = test
-                self.account = account
-                self.container = container
-                self.obj = obj
-                self.delete_object_called = False
-
-        class DeleteActualObject(object):
-            def __init__(self, test, actual_obj, timestamp):
-                self.test = test
-                self.actual_obj = actual_obj
-                self.timestamp = timestamp
-                self.called = False
-
-            def __call__(self, actual_obj, timestamp):
-                self.test.assertEqual(self.actual_obj, actual_obj)
-                self.test.assertEqual(self.timestamp, timestamp)
-                self.called = True
-
         container = 'container'
         obj = 'obj'
-        actual_obj = 'actual_obj'
-        timestamp = 'timestamp'
 
-        x = expirer.ObjectExpirer({}, logger=self.logger)
+        http_exc = {
-        x.swift = \
+            resp_code:
-            InternalClient(self, x.expiring_objects_account, container, obj)
+                internal_client.UnexpectedResponse(
-        x.delete_actual_object = \
+                    str(resp_code), swob.HTTPException(status=resp_code))
-            DeleteActualObject(self, actual_obj, timestamp)
+            for resp_code in {404, 412, 500}
+        }
+        exc_other = Exception()
 
-        delete_object_called = []
+        def check_call_to_delete_object(exc, ts, should_pop):
+            x.logger.clear()
+            start_reports = x.report_objects
+            with mock.patch.object(x, 'delete_actual_object',
+                                   side_effect=exc) as delete_actual:
+                with mock.patch.object(x, 'pop_queue') as pop_queue:
+                    x.delete_object(actual_obj, ts, container, obj)
 
-        def pop_queue(c, o):
+            delete_actual.assert_called_once_with(actual_obj, ts)
-            self.assertEqual(container, c)
+            log_lines = x.logger.get_lines_for_level('error')
-            self.assertEqual(obj, o)
+            if should_pop:
-            delete_object_called[:] = [True]
+                pop_queue.assert_called_once_with(container, obj)
+                self.assertEqual(start_reports + 1, x.report_objects)
+                self.assertFalse(log_lines)
+            else:
+                self.assertFalse(pop_queue.called)
+                self.assertEqual(start_reports, x.report_objects)
+                self.assertEqual(1, len(log_lines))
+                self.assertIn('Exception while deleting object container obj',
+                              log_lines[0])
 
-        x.pop_queue = pop_queue
+        # verify pop_queue logic on exceptions
+        for exc, ts, should_pop in [(None, timestamp, True),
+                                    (http_exc[404], timestamp, False),
+                                    (http_exc[412], timestamp, False),
+                                    (http_exc[500], reclaim_ts, False),
+                                    (exc_other, reclaim_ts, False),
+                                    (http_exc[404], reclaim_ts, True),
+                                    (http_exc[412], reclaim_ts, True)]:
 
-        x.delete_object(actual_obj, timestamp, container, obj)
+            try:
-        self.assertTrue(delete_object_called)
+                check_call_to_delete_object(exc, ts, should_pop)
-        self.assertTrue(x.delete_actual_object.called)
+            except AssertionError as err:
+                self.fail("Failed on %r at %f: %s" % (exc, ts, err))
 
     def test_report(self):
         x = expirer.ObjectExpirer({}, logger=self.logger)
@@ -710,7 +713,7 @@ class TestObjectExpirer(TestCase):
         self.assertRaises(internal_client.UnexpectedResponse,
                           x.delete_actual_object, '/path/to/object', '1234')
 
-    def test_delete_actual_object_handles_412(self):
+    def test_delete_actual_object_raises_412(self):
 
         def fake_app(env, start_response):
             start_response('412 Precondition Failed',
@@ -720,7 +723,8 @@ class TestObjectExpirer(TestCase):
         internal_client.loadapp = lambda *a, **kw: fake_app
 
         x = expirer.ObjectExpirer({})
-        x.delete_actual_object('/path/to/object', '1234')
+        self.assertRaises(internal_client.UnexpectedResponse,
+                          x.delete_actual_object, '/path/to/object', '1234')
 
     def test_delete_actual_object_does_not_handle_odd_stuff(self):