Repository: edgi-govdata-archiving/wayback (python)

Issue:
More logging
I think it would be useful to see more debug logging when requests are being made and when sleeping happens as the result of errors. When I was trying to diagnose #137 I had to sprinkle some `logger.warn` statements in.

Pull request description:
More debug logging
To help diagnose when things are going wrong this commit adds some additional debug logging when requests are happening, what parameters are being used, sleep behavior and error responses from web.archive.org.

Closes #138


Patch:
diff --git a/requirements-dev.txt b/requirements-dev.txt
index 7d0559d..a7aaa14 100644
--- a/requirements-dev.txt
+++ b/requirements-dev.txt
@@ -2,7 +2,7 @@
 # etc.) but not necessarily required for _using_ it. Some dev tooling requires
 # newer Python versions than the package itself (>=3.8)
 wheel
-check-wheel-contents ~=0.5.0
+check-wheel-contents ~=0.6.0
 flake8 ~=6.1.0
 twine
 -r requirements-test.txt
diff --git a/wayback/_client.py b/wayback/_client.py
index 3383f53..d2e4a97 100644
--- a/wayback/_client.py
+++ b/wayback/_client.py
@@ -347,7 +347,7 @@ class WaybackSession(_utils.DisableAfterCloseSession, requests.Session):
     user_agent : str, optional
         A custom user-agent string to use in all requests. Defaults to:
         `wayback/{version} (+https://github.com/edgi-govdata-archiving/wayback)`
-    search_calls_per_second : int or float, default: 1.5
+    search_calls_per_second : int or float, default: 1
         The maximum number of calls made to the search API per second.
         To disable the rate limit, set this to 0.
     memento_calls_per_second : int or float, default: 30
@@ -366,7 +366,7 @@ class WaybackSession(_utils.DisableAfterCloseSession, requests.Session):
     handleable_errors = (ConnectionError,) + retryable_errors
 
     def __init__(self, retries=6, backoff=2, timeout=60, user_agent=None,
-                 search_calls_per_second=1.5, memento_calls_per_second=30):
+                 search_calls_per_second=1, memento_calls_per_second=30):
         super().__init__()
         self.retries = retries
         self.backoff = backoff
@@ -400,11 +400,16 @@ def send(self, *args, **kwargs):
         retries = 0
         while True:
             try:
+                logger.debug('sending HTTP request %s "%s", %s', args[0].method, args[0].url, kwargs)
                 result = super().send(*args, **kwargs)
                 if retries >= maximum or not self.should_retry(result):
                     if result.status_code == 429:
                         raise RateLimitError(result)
                     return result
+                else:
+                    # TODO: parse and use Retry-After header if present.
+                    # TODO: add additional delay for 429 responses.
+                    logger.debug('Received error response (status: %s), will retry', result.status_code)
             except WaybackSession.handleable_errors as error:
                 response = getattr(error, 'response', None)
                 if response:
@@ -412,13 +417,16 @@ def send(self, *args, **kwargs):
 
                 if retries >= maximum:
                     raise WaybackRetryError(retries, total_time, error) from error
-                elif not self.should_retry_error(error):
+                elif self.should_retry_error(error):
+                    logger.warn('Caught exception during request, will retry: %s', error)
+                else:
                     raise
 
             # The first retry has no delay.
             if retries > 0:
                 seconds = self.backoff * 2 ** (retries - 1)
                 total_time += seconds
+                logger.debug('Will retry after sleeping for %s seconds...', seconds)
                 time.sleep(seconds)
 
             retries += 1
diff --git a/wayback/_utils.py b/wayback/_utils.py
index 00b1a4f..1df4be2 100644
--- a/wayback/_utils.py
+++ b/wayback/_utils.py
@@ -204,7 +204,7 @@ def set_memento_url_mode(url, mode):
 
 
 @contextmanager
-def rate_limited(calls_per_second=2, group='default'):
+def rate_limited(calls_per_second=1, group='default'):
     """
     A context manager that restricts entries to its body to occur only N times
     per second (N can be a float). The current thread will be put to sleep in
@@ -226,7 +226,9 @@ def rate_limited(calls_per_second=2, group='default'):
             minimum_wait = 1.0 / calls_per_second
             current_time = time.time()
             if current_time - last_call < minimum_wait:
-                time.sleep(minimum_wait - (current_time - last_call))
+                seconds = minimum_wait - (current_time - last_call)
+                logger.debug('Hit %s rate limit, sleeping for %s seconds', group, seconds)
+                time.sleep(seconds)
             _last_call_by_group[group] = time.time()
         yield
 


Test patch:
diff --git a/wayback/tests/test_client.py b/wayback/tests/test_client.py
index cc5548b..cd8e676 100644
--- a/wayback/tests/test_client.py
+++ b/wayback/tests/test_client.py
@@ -792,7 +792,7 @@ def test_search_rate_limits(self):
                 next(client.search('zew.de'))
         duration_with_limits_custom = time.time() - start_time
 
-        assert 1.3 <= duration_with_limits <= 1.4
+        assert 1.9 <= duration_with_limits <= 2.1
         assert 0.0 <= duration_without_limits <= 0.05
         assert 0.0 <= duration_with_limits_custom <= 1.05