From 3ca825592efd55e1667ba4b2e2f19afb7f89cbbd Mon Sep 17 00:00:00 2001 From: Peter Eckersley Date: Fri, 8 Apr 2016 15:30:27 -0700 Subject: [PATCH 1/7] Reverter.py: clock change protection, and debugging for #1243 --- letsencrypt/reverter.py | 37 +++++++++++++++++++++++++++---------- 1 file changed, 27 insertions(+), 10 deletions(-) diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index ea54a91ee..c0771d577 100644 --- a/letsencrypt/reverter.py +++ b/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( - "Forgot to provide files to registration call") + raise errors.ReverterError("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( - os.path.join(cp_dir, "NEW_FILES")) + new_fd, ex_files = self._read_and_append(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 - # that will result in a name collision. - # If so, increment and try again - cur_time += .01 + logger.warning("Extreme, unexpected race condition, retrying (%s)", timestamp) # After 10 attempts... something is probably wrong here... logger.error( From 40e877750090ad3e22adb0eb15a1e0fc6bafa9fb Mon Sep 17 00:00:00 2001 From: Peter Eckersley Date: Fri, 8 Apr 2016 16:04:47 -0700 Subject: [PATCH 2/7] reverter.finalize_checkpoint() : handle empty checkpoints Should fix #1243 --- letsencrypt/reverter.py | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index ea54a91ee..0ed75df6f 100644 --- a/letsencrypt/reverter.py +++ b/letsencrypt/reverter.py @@ -481,30 +481,32 @@ class Reverter(object): checkpoint is not able to be finalized. """ - # Adds title to self.config.in_progress_dir CHANGES_SINCE - # Move self.config.in_progress_dir to Backups directory and - # rename the directory as a timestamp # Check to make sure an "in progress" directory exists if not os.path.isdir(self.config.in_progress_dir): return - changes_since_path = os.path.join( - self.config.in_progress_dir, "CHANGES_SINCE") + changes_since_path = os.path.join(self.config.in_progress_dir, "CHANGES_SINCE") + changes_since_tmp_path = os.path.join(self.config.in_progress_dir, "CHANGES_SINCE.tmp") - changes_since_tmp_path = os.path.join( - self.config.in_progress_dir, "CHANGES_SINCE.tmp") + if not os.path.exists(self.config.changes_since_path): + logger.info("Rollback checkpoint is empty (no changes made?)") + with open(self.config.changes_since_path) as f: + f.write("No changes\n") + # Add title to self.config.in_progress_dir CHANGES_SINCE try: with open(changes_since_tmp_path, "w") as changes_tmp: changes_tmp.write("-- %s --\n" % title) with open(changes_since_path, "r") as changes_orig: changes_tmp.write(changes_orig.read()) + # Move self.config.in_progress_dir to Backups directory shutil.move(changes_since_tmp_path, changes_since_path) except (IOError, OSError): logger.error("Unable to finalize checkpoint - adding title") raise errors.ReverterError("Unable to add title") + # rename the directory as a timestamp self._timestamp_progress_dir() def _timestamp_progress_dir(self): From cf4f97bbbfac73184d766a68e821f7ffa9a2ae24 Mon Sep 17 00:00:00 2001 From: Peter Eckersley Date: Fri, 8 Apr 2016 16:15:43 -0700 Subject: [PATCH 3/7] typofix --- letsencrypt/reverter.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index c0771d577..5844ae6c2 100644 --- a/letsencrypt/reverter.py +++ b/letsencrypt/reverter.py @@ -502,22 +502,22 @@ 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()) + logger.debug("Exception was:\n%s", traceback.format_exc()) raise errors.ReverterError("Unable to add title") self._timestamp_progress_dir() - def _checkpoint_timestamp(self) + 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.append(timestamp) 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) timestamp = timetravel elif len(others) > 1 and others[-2] == timestamp: # It is possible if the checkpoints are made extremely quickly From 5e971a5e5a9a7dd8baed9a61091810f3ef4bc1ac Mon Sep 17 00:00:00 2001 From: Peter Eckersley Date: Fri, 8 Apr 2016 16:38:40 -0700 Subject: [PATCH 4/7] Check the right path --- letsencrypt/reverter.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index 0ed75df6f..b7928220b 100644 --- a/letsencrypt/reverter.py +++ b/letsencrypt/reverter.py @@ -488,7 +488,7 @@ class Reverter(object): changes_since_path = os.path.join(self.config.in_progress_dir, "CHANGES_SINCE") changes_since_tmp_path = os.path.join(self.config.in_progress_dir, "CHANGES_SINCE.tmp") - if not os.path.exists(self.config.changes_since_path): + if not os.path.exists(changes_since_path): logger.info("Rollback checkpoint is empty (no changes made?)") with open(self.config.changes_since_path) as f: f.write("No changes\n") From f2e266cefd78b8c685983343fd5e54cdd1ff6e09 Mon Sep 17 00:00:00 2001 From: Peter Eckersley Date: Mon, 11 Apr 2016 13:23:05 -0700 Subject: [PATCH 5/7] Only count actual checkpoints for ordering purposes --- letsencrypt/reverter.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index 5844ae6c2..7feae966c 100644 --- a/letsencrypt/reverter.py +++ b/letsencrypt/reverter.py @@ -1,5 +1,6 @@ """Reverter class saves configuration checkpoints and allows for recovery.""" import csv +import glob import logging import os import shutil @@ -510,7 +511,7 @@ class Reverter(object): def _checkpoint_timestamp(self): "Determine the timestamp of the checkpoint, enforcing monotonicity." timestamp = str(time.time()) - others = os.listdir(self.config.backup_dir) + others = glob.glob(os.path.join(self.config.backup_dir, "[0-9]*")) others.append(timestamp) others.sort() if others[-1] != timestamp: From a6235c069ac6f4a2ebf90d3671014eeff3630e30 Mon Sep 17 00:00:00 2001 From: Peter Eckersley Date: Mon, 11 Apr 2016 13:36:01 -0700 Subject: [PATCH 6/7] glob requires basename()ing --- letsencrypt/reverter.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/letsencrypt/reverter.py b/letsencrypt/reverter.py index 7feae966c..1ee12a561 100644 --- a/letsencrypt/reverter.py +++ b/letsencrypt/reverter.py @@ -512,6 +512,7 @@ class Reverter(object): "Determine the timestamp of the checkpoint, enforcing monotonicity." timestamp = str(time.time()) others = glob.glob(os.path.join(self.config.backup_dir, "[0-9]*")) + others = [os.path.basename(d) for d in others] others.append(timestamp) others.sort() if others[-1] != timestamp: @@ -533,7 +534,7 @@ class Reverter(object): # It is possible save checkpoints faster than 1 per second resulting in # collisions in the naming convention. - for _ in xrange(10): + for _ in xrange(2): timestamp = self._checkpoint_timestamp() final_dir = os.path.join(self.config.backup_dir, timestamp) try: From 714282c82c9007c106b8f71ae43c3d377c49027d Mon Sep 17 00:00:00 2001 From: Brad Warren Date: Wed, 13 Apr 2016 10:04:22 -0700 Subject: [PATCH 7/7] Add boulder host --- .travis.yml | 1 + 1 file changed, 1 insertion(+) diff --git a/.travis.yml b/.travis.yml index 9024defcd..38c874279 100644 --- a/.travis.yml +++ b/.travis.yml @@ -89,6 +89,7 @@ addons: - le2.wtf - le3.wtf - nginx.wtf + - boulder - boulder-mysql - boulder-rabbitmq mariadb: "10.0"