Add some more debug logging for FileCache and for the pass-through path.

This makes it easier to figure out _why_ something fails to look up altogether.

Author: Flameeyes

cachecontrol/caches/file_cache.py

@@ -1,4 +1,5 @@
 import hashlib
+import logging
 import os
 from textwrap import dedent
 
@@ -12,6 +13,9 @@
     FileNotFoundError = (IOError, OSError)
 
 
+logger = logging.getLogger(__name__)
+
+
 def _secure_open_write(filename, fmode):
     # We only want to write to this file, so open it in write only mode
     flags = os.O_WRONLY
@@ -107,6 +111,7 @@ def _fn(self, name):
 
     def get(self, key):
         name = self._fn(key)
+        logger.debug("Looking up '%s' in '%s'", key, name)
         try:
             with open(name, "rb") as fh:
                 return fh.read()
@@ -116,12 +121,14 @@ def get(self, key):
 
     def set(self, key, value):
         name = self._fn(key)
+        logger.debug("Caching '%s' in '%s'", key, name)
 
         # Make sure the directory exists
+        parentdir = os.path.dirname(name)
         try:
-            os.makedirs(os.path.dirname(name), self.dirmode)
+            os.makedirs(parentdir, self.dirmode)
         except (IOError, OSError):
-            pass
+            logging.debug("Error trying to create directory '%s'", parentdir, exc_info=True)
 
         with self.lock_class(name) as lock:
             # Write our actual file

cachecontrol/controller.py

@@ -280,7 +280,7 @@ def cache_response(self, request, response, body=None, status_codes=None):
         cc = self.parse_cache_control(response_headers)
 
         cache_url = self.cache_url(request.url)
-        logger.debug('Updating cache with response from "%s"', cache_url)
+        logger.debug('Updating cache %r with response from "%s"', self.cache, cache_url)
 
         # Delete it from the cache if we happen to have it stored there
         no_store = False
@@ -321,7 +321,10 @@ def cache_response(self, request, response, body=None, status_codes=None):
         # Add to the cache if the response headers demand it. If there
         # is no date header then we can't do anything about expiring
         # the cache.
-        elif "date" in response_headers:
+        elif "date" not in response_headers:
+            logger.debug("No date header, expiration cannot be set.")
+            return
+        else:
             # cache when there is a max-age > 0
             if "max-age" in cc and cc["max-age"] > 0:
                 logger.debug("Caching b/c date exists and max-age > 0")
@@ -337,6 +340,8 @@ def cache_response(self, request, response, body=None, status_codes=None):
                     self.cache.set(
                         cache_url, self.serializer.dumps(request, response, body=body)
                     )
+            else:
+                logger.debug("No combination of headers to cache.")
 
     def update_cached_response(self, request, response):
         """On a 304 we will get a new set of headers that we want to