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

wayback/_client.py

@@ -400,17 +400,21 @@ def send(self, *args, **kwargs):
         retries = 0
         while True:
             try:
+                logger.debug("sending %s", kwargs)
                 result = super().send(*args, **kwargs)
                 if retries >= maximum or not self.should_retry(result):
                     if result.status_code == 429:
+                        logger.warning("caught rate limit error: %s", result.content)
                         raise RateLimitError(result)
                     return result
             except WaybackSession.handleable_errors as error:
+                logging.warn("caught exception during request: %s", error)
                 response = getattr(error, 'response', None)
                 if response:
                     read_and_close(response)
 
                 if retries >= maximum:
+                    logger.error("Too many retries %s >= %s", retries, maximum)
                     raise WaybackRetryError(retries, total_time, error) from error
                 elif not self.should_retry_error(error):
                     raise
@@ -419,6 +423,7 @@ def send(self, *args, **kwargs):
             if retries > 0:
                 seconds = self.backoff * 2 ** (retries - 1)
                 total_time += seconds
+                logger.debug("retrying after sleep of %s seconds", seconds)
                 time.sleep(seconds)
 
             retries += 1
@@ -712,6 +717,7 @@ def search(self, url, *, match_type=None, limit=1000, offset=None,
             sent_query, next_query = next_query, None
             with _utils.rate_limited(self.session.search_calls_per_second,
                                      group='search'):
+                logger.debug("querying %s %s", CDX_SEARCH_URL, sent_query)
                 response = self.session.request('GET', CDX_SEARCH_URL,
                                                 params=sent_query)
                 try:

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.5, 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))
+                secs = minimum_wait - (current_time - last_call)
+                logging.debug("sleeping %s", secs)
+                time.sleep(secs)
             _last_call_by_group[group] = time.time()
         yield