Reverter.py: clock change protection, and debugging for #1243

letsencrypt/reverter.py

@@ -4,6 +4,7 @@ import logging
 import os
 import shutil
 import time
+import traceback
 
 import zope.component
 
@@ -333,16 +334,14 @@ class Reverter(object):
         # Make sure some files are provided... as this is an error
         # Made this mistake in my initial implementation of apache.dvsni.py
         if not files:
-            raise errors.ReverterError(
+            raise errors.ReverterError("Forgot to provide files to registration call")
-                "Forgot to provide files to registration call")
 
         cp_dir = self._get_cp_dir(temporary)
 
         # Append all new files (that aren't already registered)
         new_fd = None
         try:
-            new_fd, ex_files = self._read_and_append(
+            new_fd, ex_files = self._read_and_append(os.path.join(cp_dir, "NEW_FILES"))
-                os.path.join(cp_dir, "NEW_FILES"))
 
             for path in files:
                 if path not in ex_files:
@@ -503,26 +502,44 @@ class Reverter(object):
             shutil.move(changes_since_tmp_path, changes_since_path)
         except (IOError, OSError):
             logger.error("Unable to finalize checkpoint - adding title")
+            logger.debug("Exception was:\%s", traceback.format_exc())
             raise errors.ReverterError("Unable to add title")
 
         self._timestamp_progress_dir()
 
+    def _checkpoint_timestamp(self)
+        "Determine the timestamp of the checkpoint, enforcing monotonicity."
+        timestamp = str(time.time())
+        others = os.listdir(self.config.backup_dir)
+        others.append(new_dir)
+        others.sort()
+        if others[-1] != timestamp:
+            timetravel = str(float(others[-1]) + 1)
+            logger.warn("Current timestamp %s does not correspond to newest reverter "
+                "checkpoint; your clock probably jumped. Time travelling to %s",
+                new_dir, timetravel)
+            timestamp = timetravel
+        elif len(others) > 1 and others[-2] == timestamp:
+            # It is possible if the checkpoints are made extremely quickly
+            # that will result in a name collision.
+            logger.debug("Race condition with timestamp %s, incrementing by 0.01", timestamp)
+            timetravel = str(float(others[-1]) + 0.01)
+            timestamp = timetravel
+        return timestamp
+
     def _timestamp_progress_dir(self):
         """Timestamp the checkpoint."""
         # It is possible save checkpoints faster than 1 per second resulting in
         # collisions in the naming convention.
-        cur_time = time.time()
 
         for _ in xrange(10):
-            final_dir = os.path.join(self.config.backup_dir, str(cur_time))
+            timestamp = self._checkpoint_timestamp()
+            final_dir = os.path.join(self.config.backup_dir, timestamp)
             try:
                 os.rename(self.config.in_progress_dir, final_dir)
                 return
             except OSError:
-                # It is possible if the checkpoints are made extremely quickly
+                logger.warning("Extreme, unexpected race condition, retrying (%s)", timestamp)
-                # that will result in a name collision.
-                # If so, increment and try again
-                cur_time += .01
 
         # After 10 attempts... something is probably wrong here...
         logger.error(