Merge pull request #1478 from TheNavigat/storage-logging

Storage logging

1 files changed, 44 insertions, 6 deletions

diff --git a/letsencrypt/storage.py b/letsencrypt/storage.py
index 52be94f68..7e2802b14 100644
--- a/letsencrypt/storage.py
+++ b/letsencrypt/storage.py
@@ -1,5 +1,6 @@
 """Renewable certificates storage."""
 import datetime
+import logging
 import os
 import re
 
@@ -13,6 +14,8 @@ from letsencrypt import errors
 from letsencrypt import error_handler
 from letsencrypt import le_util
 
+logger = logging.getLogger(__name__)
+
 ALL_FOUR = ("cert", "privkey", "chain", "fullchain")
 
 
@@ -136,14 +139,17 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
 
         """
         # Each element must be referenced with an absolute path
-        if any(not os.path.isabs(x) for x in
-               (self.cert, self.privkey, self.chain, self.fullchain)):
-            return False
+        for x in (self.cert, self.privkey, self.chain, self.fullchain):
+            if not os.path.isabs(x):
+                logger.debug("Element %s is not referenced with an "
+                             "absolute path.", x)
+                return False
 
         # Each element must exist and be a symbolic link
-        if any(not os.path.islink(x) for x in
-               (self.cert, self.privkey, self.chain, self.fullchain)):
-            return False
+        for x in (self.cert, self.privkey, self.chain, self.fullchain):
+            if not os.path.islink(x):
+                logger.debug("Element %s is not a symbolic link.", x)
+                return False
         for kind in ALL_FOUR:
             link = getattr(self, kind)
             where = os.path.dirname(link)
@@ -157,16 +163,26 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
                 self.cli_config.archive_dir, self.lineagename)
             if not os.path.samefile(os.path.dirname(target),
                                     desired_directory):
+                logger.debug("Element's link does not point within the "
+                             "cert lineage's directory within the "
+                             "official archive directory. Link: %s, "
+                             "target directory: %s, "
+                             "archive directory: %s.",
+                             link, os.path.dirname(target), desired_directory)
                 return False
 
             # The link must point to a file that exists
             if not os.path.exists(target):
+                logger.debug("Link %s points to file %s that does not exist.",
+                             link, target)
                 return False
 
             # The link must point to a file that follows the archive
             # naming convention
             pattern = re.compile(r"^{0}([0-9]+)\.pem$".format(kind))
             if not pattern.match(os.path.basename(target)):
+                logger.debug("%s does not follow the archive naming "
+                             "convention.", target)
                 return False
 
             # It is NOT required that the link's target be a regular
@@ -251,6 +267,8 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
             raise errors.CertStorageError("unknown kind of item")
         link = getattr(self, kind)
         if not os.path.exists(link):
+            logger.debug("Expected symlink %s for %s does not exist.",
+                         link, kind)
             return None
         target = os.readlink(link)
         if not os.path.isabs(target):
@@ -275,11 +293,14 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
         pattern = re.compile(r"^{0}([0-9]+)\.pem$".format(kind))
         target = self.current_target(kind)
         if target is None or not os.path.exists(target):
+            logger.debug("Current-version target for %s "
+                         "does not exist at %s.", kind, target)
             target = ""
         matches = pattern.match(os.path.basename(target))
         if matches:
             return int(matches.groups()[0])
         else:
+            logger.debug("No matches for target %s.", kind)
             return None
 
     def version(self, kind, version):
@@ -529,6 +550,7 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
 
             # Renewals on the basis of revocation
             if self.ocsp_revoked(self.latest_common_version()):
+                logger.debug("Should renew, certificate is revoked.")
                 return True
 
             # Renewals on the basis of expiry time
@@ -537,6 +559,9 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
                 "cert", self.latest_common_version()))
             now = pytz.UTC.fromutc(datetime.datetime.utcnow())
             if expiry < add_time_interval(now, interval):
+                logger.debug("Should renew, certificate "
+                             "has been expired since %s.",
+                             expiry.strftime("%Y-%m-%d %H:%M:%S %Z"))
                 return True
         return False
 
@@ -588,6 +613,7 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
                   cli_config.live_dir):
             if not os.path.exists(i):
                 os.makedirs(i, 0700)
+                logger.debug("Creating directory %s.", i)
         config_file, config_filename = le_util.unique_lineage_name(
             cli_config.renewal_configs_dir, lineagename)
         if not config_filename.endswith(".conf"):
@@ -608,6 +634,8 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
                 "live directory exists for " + lineagename)
         os.mkdir(archive)
         os.mkdir(live_dir)
+        logger.debug("Archive directory %s and live "
+                     "directory %s created.", archive, live_dir)
         relative_archive = os.path.join("..", "..", "archive", lineagename)
 
         # Put the data into the appropriate files on disk
@@ -617,15 +645,19 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
             os.symlink(os.path.join(relative_archive, kind + "1.pem"),
                        target[kind])
         with open(target["cert"], "w") as f:
+            logger.debug("Writing certificate to %s.", target["cert"])
             f.write(cert)
         with open(target["privkey"], "w") as f:
+            logger.debug("Writing private key to %s.", target["privkey"])
             f.write(privkey)
             # XXX: Let's make sure to get the file permissions right here
         with open(target["chain"], "w") as f:
+            logger.debug("Writing chain to %s.", target["chain"])
             f.write(chain)
         with open(target["fullchain"], "w") as f:
             # assumes that OpenSSL.crypto.dump_certificate includes
             # ending newline character
+            logger.debug("Writing full chain to %s.", target["fullchain"])
             f.write(cert + chain)
 
         # Document what we've done in a new renewal config file
@@ -640,6 +672,7 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
                                                     " in the renewal process"]
         # TODO: add human-readable comments explaining other available
         #       parameters
+        logger.debug("Writing new config %s.", config_filename)
         new_config.write()
         return cls(new_config.filename, cli_config)
 
@@ -690,16 +723,21 @@ class RenewableCert(object):  # pylint: disable=too-many-instance-attributes
                 old_privkey = os.readlink(old_privkey)
             else:
                 old_privkey = "privkey{0}.pem".format(prior_version)
+            logger.debug("Writing symlink to old private key, %s.", old_privkey)
             os.symlink(old_privkey, target["privkey"])
         else:
             with open(target["privkey"], "w") as f:
+                logger.debug("Writing new private key to %s.", target["privkey"])
                 f.write(new_privkey)
 
         # Save everything else
         with open(target["cert"], "w") as f:
+            logger.debug("Writing certificate to %s.", target["cert"])
             f.write(new_cert)
         with open(target["chain"], "w") as f:
+            logger.debug("Writing chain to %s.", target["chain"])
             f.write(new_chain)
         with open(target["fullchain"], "w") as f:
+            logger.debug("Writing full chain to %s.", target["fullchain"])
             f.write(new_cert + new_chain)
         return target_version