Add logging to main cache operations

2 files changed, 33 insertions, 16 deletions

diff --git a/requests_cache/backends/base.py b/requests_cache/backends/base.py
index 26b5775..923e6f2 100644
--- a/requests_cache/backends/base.py
+++ b/requests_cache/backends/base.py
@@ -1,12 +1,12 @@
 import hashlib
 import json
 import pickle
+import warnings
 from abc import ABC
 from collections.abc import MutableMapping
 from logging import getLogger
 from typing import Iterable, List, Union
 from urllib.parse import parse_qsl, urlencode, urlparse, urlunparse
-from warnings import warn
 
 import requests
 
@@ -85,7 +85,7 @@ class BaseCache:
                 del self.redirects[key]
             for r in response.history:
                 del self.redirects[self.create_key(r.request)]
-        except KeyError:
+        except (AttributeError, KeyError):
             pass
 
     def delete_url(self, url: str):
@@ -96,6 +96,7 @@ class BaseCache:
 
     def clear(self):
         """Delete all items from the cache"""
+        logger.info('Clearing all items from the cache')
         self.responses.clear()
         self.redirects.clear()
 
@@ -105,7 +106,19 @@ class BaseCache:
         Args:
             expire_after: A new expiration time used to revalidate the cache
         """
-        for key, response in list(self.responses.items()):
+        logger.info(
+            'Removing expired responses.'
+            + (f'Revalidating with: {expire_after}' if expire_after else '')
+        )
+        for key in list(self.responses.keys()):
+            # If a response is invalid, delete it
+            try:
+                response = self.responses[key]
+            except Exception as e:
+                logger.info(f'Unable to deserialize response with key {key}: {str(e)}')
+                self.delete(key)
+                continue
+
             # If we're revalidating and it's not yet expired, update the cached item's expiration
             if expire_after is not None and not response.revalidate(expire_after):
                 self.responses[key] = response
@@ -194,11 +207,13 @@ class BaseStorage(MutableMapping, ABC):
         **kwargs,
     ):
         self._serializer = serializer or self._get_serializer(secret_key, salt)
-        if not secret_key and not suppress_warnings:
-            warn(
-                'Using a secret_key to sign cached items is recommended for this backend.\n'
-                'Use suppress_warnings=True to ignore this message.'
-            )
+        logger.info(f'Initializing {type(self).__name__} with serializer: {type(self._serializer)}')
+
+        if kwargs:
+            logger.warning(f'Unrecognized keyword arguments: {kwargs}')
+        if not secret_key:
+            warn_func = logger.info if suppress_warnings else warnings.warn
+            warn_func('Using a secret key to sign cached items is recommended for this backend')
 
     def serialize(self, item: Union[CachedResponse, str]) -> bytes:
         """Serialize a URL or response into bytes"""
diff --git a/requests_cache/backends/sqlite.py b/requests_cache/backends/sqlite.py
index 7915a11..d8d9bd6 100644
--- a/requests_cache/backends/sqlite.py
+++ b/requests_cache/backends/sqlite.py
@@ -1,10 +1,13 @@
 import sqlite3
 import threading
 from contextlib import contextmanager
+from logging import getLogger
 from os.path import expanduser
 
 from .base import BaseCache, BaseStorage
 
+logger = getLogger(__name__)
+
 
 class DbCache(BaseCache):
     """SQLite cache backend.
@@ -49,15 +52,13 @@ class DbDict(BaseStorage):
 
     def __init__(self, filename, table_name='http_cache', fast_save=False, timeout=5.0, **kwargs):
         super().__init__(**kwargs)
+        self.fast_save = fast_save
         self.filename = filename
         self.table_name = table_name
-        self.fast_save = fast_save
         self.timeout = timeout
 
-        #: Transactions can be committed if this property is set to `True`
-        self.can_commit = True
-
         self._bulk_commit = False
+        self._can_commit = True
         self._pending_connection = None
         self._lock = threading.RLock()
         with self.connection() as con:
@@ -65,6 +66,7 @@ class DbDict(BaseStorage):
 
     @contextmanager
     def connection(self, commit_on_success=False):
+        logger.debug(f'Opening connection to {self.filename}:{self.table_name}')
         with self._lock:
             if self._bulk_commit:
                 if self._pending_connection is None:
@@ -76,7 +78,7 @@ class DbDict(BaseStorage):
                 if self.fast_save:
                     con.execute("PRAGMA synchronous = 0;")
                 yield con
-                if commit_on_success and self.can_commit:
+                if commit_on_success and self._can_commit:
                     con.commit()
             finally:
                 if not self._bulk_commit:
@@ -88,7 +90,7 @@ class DbDict(BaseStorage):
 
         :param force: force commit, ignore :attr:`can_commit`
         """
-        if force or self.can_commit:
+        if force or self._can_commit:
             if self._pending_connection is not None:
                 self._pending_connection.commit()
 
@@ -105,13 +107,13 @@ class DbDict(BaseStorage):
 
         """
         self._bulk_commit = True
-        self.can_commit = False
+        self._can_commit = False
         try:
             yield
             self.commit(True)
         finally:
             self._bulk_commit = False
-            self.can_commit = True
+            self._can_commit = True
             if self._pending_connection is not None:
                 self._pending_connection.close()
                 self._pending_connection = None