From 7a1aceb273c25b47908a6f81cdd894da72798b45 Mon Sep 17 00:00:00 2001
From: PLPeeters <PLPeeters@users.noreply.github.com>
Date: Mon, 16 Dec 2019 13:52:11 +0100
Subject: [PATCH] Tweak logging of exceptions to exclude traceback if we have a
 default factory

---
 reppy/cache/__init__.py        |  9 ++++-
 tests/test_cache/test_cache.py | 62 +++++++++++++++++++++++++++++++---
 2 files changed, 66 insertions(+), 5 deletions(-)

diff --git a/reppy/cache/__init__.py b/reppy/cache/__init__.py
index 0dfd8bc..dce207b 100644
--- a/reppy/cache/__init__.py
+++ b/reppy/cache/__init__.py
@@ -7,6 +7,7 @@
 from cachetools import LRUCache
 
 from .policy import DefaultObjectPolicy, ReraiseExceptionPolicy
+from ..exceptions import ReppyException
 from ..robots import Robots, AllowNone, Agent
 from .. import logger
 
@@ -65,7 +66,13 @@ def factory(self, url):
         try:
             return self.fetch(url)
         except BaseException as exc:
-            logger.exception('Reppy cache fetch error on %s' % url)
+            # Log the whole stack trace only if the exception is not a ReppyException
+            # or if we do not have a default factory
+            if isinstance(exc, ReppyException) and isinstance(self.cache_policy, DefaultObjectPolicy):
+                logger.info('Reppy cache fetch error on %s; using factory.' % url)
+            else:
+                logger.exception('Reppy cache fetch error on %s' % url)
+
             return self.cache_policy.exception(url, exc)
 
     def fetch(self, url):
diff --git a/tests/test_cache/test_cache.py b/tests/test_cache/test_cache.py
index e2afa93..f76206c 100644
--- a/tests/test_cache/test_cache.py
+++ b/tests/test_cache/test_cache.py
@@ -1,5 +1,7 @@
 from __future__ import print_function
 
+from reppy.cache import DefaultObjectPolicy, ReraiseExceptionPolicy
+
 '''Tests about our caching utilities.'''
 
 import unittest
@@ -9,6 +11,7 @@
 
 from reppy import cache
 from reppy import logger
+from reppy.robots import AllowNone
 import reppy.exceptions
 
 from ..util import requests_fixtures
@@ -96,6 +99,36 @@ def test_caches_robots(self):
         self.assertTrue(
             self.cache.allowed('http://example.com/allowed', 'agent'))
 
+    def test_logs_on_timeout_without_default_object_policy(self):
+        '''On fetch timeout without a default object policy, it logs the exception.'''
+        robots_cache = cache.RobotsCache(10, timeout=1, cache_policy=ReraiseExceptionPolicy(ttl=600))
+        logs = []
+
+        def mock_logger(msg):
+            exc_type = sys.exc_info()[0]
+            logs.append((exc_type, msg))
+
+        with mock.patch.object(logger, 'exception', mock_logger):
+            robots_cache.factory('https://httpstat.us/200?sleep=10000')
+
+            expected_err = reppy.exceptions.ReadTimeout
+            expected_msg = 'Reppy cache fetch error on https://httpstat.us/200?sleep=10000'
+            self.assertIn((expected_err, expected_msg), logs)
+
+    def test_logs_on_timeout_with_default_object_policy(self):
+        '''On fetch timeout with a default object policy, it logs an informative message.'''
+        robots_cache = cache.RobotsCache(10, timeout=1, cache_policy=DefaultObjectPolicy(ttl=600, factory=AllowNone))
+        logs = []
+
+        def mock_logger(msg):
+            logs.append(msg)
+
+        with mock.patch.object(logger, 'info', mock_logger):
+            robots_cache.factory('https://httpstat.us/200?sleep=10000')
+
+            expected_msg = 'Reppy cache fetch error on https://httpstat.us/200?sleep=10000; using factory.'
+            self.assertIn(expected_msg, logs)
+
 
 class TestAgentCache(unittest.TestCase):
     '''Tests about AgentCache.'''
@@ -122,19 +155,40 @@ def test_uses_default_expiration_on_failure(self):
                 self.assertEqual(
                     self.cache.cache['http://does-not-resolve/robots.txt'].expires, 17)
 
-    def test_logs_on_failure(self):
-        '''On fetch failure, it logs the exception.'''
+    def test_logs_on_failure_without_default_object_policy(self):
+        '''On fetch failure without a default object policy, it logs the exception.'''
+        agents_cache = cache.AgentCache('agent', 10, cache_policy=ReraiseExceptionPolicy(ttl=600))
         logs = []
+
         def mock_logger(msg):
             exc_type = sys.exc_info()[0]
-            logs.append( (exc_type, msg) )
+            logs.append((exc_type, msg))
+
         with mock.patch.object(logger, 'exception', mock_logger):
-            self.cache.get('http://does-not-resolve/')
+            try:
+                agents_cache.get('http://does-not-resolve/')
+            except reppy.exceptions.ConnectionException:
+                # This is expected since the cache policy is a ReraiseExceptionPolicy
+                pass
 
             expected_err = reppy.exceptions.ConnectionException
             expected_msg = 'Reppy cache fetch error on http://does-not-resolve/robots.txt'
             self.assertIn((expected_err, expected_msg), logs)
 
+    def test_logs_on_failure_with_default_object_policy(self):
+        '''On fetch failure with a default object policy, it logs an informative message.'''
+        agents_cache = cache.AgentCache('agent', 10, cache_policy=DefaultObjectPolicy(ttl=600, factory=AllowNone))
+        logs = []
+
+        def mock_logger(msg):
+            logs.append(msg)
+
+        with mock.patch.object(logger, 'info', mock_logger):
+            agents_cache.get('http://does-not-resolve/')
+
+            expected_msg = 'Reppy cache fetch error on http://does-not-resolve/robots.txt; using factory.'
+            self.assertIn(expected_msg, logs)
+
     def test_agent_allowed(self):
         '''Can check for allowed.'''
         with requests_fixtures('test_agent_allowed'):