context_processor: trace if template refresh fails for 1 hour and 3 times (#86346)

Aslo capture network errors in the same error handling code.

hobo/context_processors.py

@@ -58,7 +58,7 @@ class RemoteTemplate:
         if self.source != '404' and item:
             # page_cache is a dict redirect_url -> page content, get the best
             # match.
-            page_cache, expiry_time = item
+            page_cache = item['page_cache']
             selected_cache_page = None
             for page_redirect_url in sorted(page_cache.keys(), key=len):
                 if selected_cache_page is None:
@@ -68,19 +68,21 @@ class RemoteTemplate:
                     continue
                 if len(page_redirect_url) > len(selected_cache_page):
                     selected_cache_page = page_redirect_url
-            item = (page_cache[selected_cache_page], expiry_time)
+            return {**item, 'template_body': page_cache[selected_cache_page], 'page_cache': None, 'count': 0}
         else:
-            item = cache.get(self.cache_key)
-        return item
+            return cache.get(self.cache_key)
 
     def get_page_cache_key(self):
-        return self.PAGE_CACHE_KEY + '-' + self.language_code
+        # added v2 for change of cache item structure
+        return self.PAGE_CACHE_KEY + '-' + self.language_code + 'v2'
 
     @property
     def cache_key(self):
+        # added v2 for change of cache item structure
         return hashlib.md5(
             urllib.parse.urlunparse(urllib.parse.urlparse(self.source)[:3] + ('', '', '')).encode('ascii')
             + self.language_code.encode('ascii')
+            + b'v2'
         ).hexdigest()
 
     def get_template(self):
@@ -100,38 +102,50 @@ class RemoteTemplate:
         else:
             self.theme_skeleton_url = settings.THEME_SKELETON_URL
         if item is None:
-            template_body = self.update_content(in_thread=False)
-            if template_body is None:
-                raise Exception('Failed to retrieve theme')
+            template_body = self.update_content()
         else:
-            template_body, expiry_time = item
-            if expiry_time < datetime.datetime.now():
+            if item['expiry_time'] < datetime.datetime.now():
                 # stale value, put it back into the cache for other consumers and
                 # update the content in a different thread
-                self.cache(template_body)
-                threading.Thread(target=self.update_content).start()
+                self.cache(item['template_body'], old_cache=item)
+                threading.Thread(target=lambda: self.update_content(old_cache=item)).start()
+            template_body = item['template_body']
         return Template(template_body)
 
-    def update_content(self, in_thread=True):
-        r = requests.get(
-            self.theme_skeleton_url,
-            params={'source': self.source},
-            headers={'Accept-Language': self.language_code},
-            timeout=10,
-        )
-        if r.status_code != 200:
-            logger.error('failed to retrieve theme (status code: %s)', r.status_code)
+    def update_content(self, old_cache=None):
+        last_update = old_cache and old_cache['last_update']
+        count = old_cache['count'] if old_cache else 0
+        try:
+            r = requests.get(
+                self.theme_skeleton_url,
+                params={'source': self.source},
+                headers={'Accept-Language': self.language_code},
+                timeout=10,
+            )
+            r.raise_for_status()
+        except requests.RequestException as e:
+            if old_cache is None:
+                raise Exception(f'Failed to retrieve theme: {e}')
+            if datetime.datetime.now() - last_update < datetime.timedelta(hours=1) or count < 3:
+                log_function = logger.warning
+            else:
+                log_function = logger.error
+            log_function('failed to retrieve theme since %s: %s', last_update, e)
             return None
-        self.cache(r.text)
-        if r.headers.get('X-Combo-Skeleton-Pages'):
+
+        template_body = r.text
+
+        self.cache(template_body)
+        if x_combo_skeleton_pages := r.headers.get('X-Combo-Skeleton-Pages'):
             # X-Combo-Skeleton-Pages header is a dict (page_id -> redirect_url),
             # it is use to create page cache.
-            self.combo_skeleton_pages = json.loads(r.headers.get('X-Combo-Skeleton-Pages'))
-            if in_thread:
+            self.combo_skeleton_pages = json.loads(x_combo_skeleton_pages)
+            if last_update is not None:
+                # cache is filled, so we are in a thread
                 self.update_all_pages_cache()
             else:
                 threading.Thread(target=self.update_all_pages_cache).start()
-        return r.text
+        return template_body
 
     def update_all_pages_cache(self):
         for lang_code, _ in settings.LANGUAGES:
@@ -158,12 +172,29 @@ class RemoteTemplate:
 
             expiry_time = datetime.datetime.now() + datetime.timedelta(seconds=CACHE_REFRESH_TIMEOUT)
             cache.set(
-                self.get_page_cache_key(), (page_cache, expiry_time), 2592000
+                self.get_page_cache_key(),
+                {
+                    'page_cache': page_cache,
+                    'expiry_time': expiry_time,
+                    'last_update': datetime.datetime.now(),
+                },
+                2592000,
             )  # bypass cache level expiration time
 
-    def cache(self, template_body):
+    def cache(self, template_body, old_cache=None):
+        last_update = old_cache['last_update'] if old_cache else datetime.datetime.now()
         expiry_time = datetime.datetime.now() + datetime.timedelta(seconds=CACHE_REFRESH_TIMEOUT)
-        cache.set(self.cache_key, (template_body, expiry_time), 2592000)  # bypass cache level expiration time
+        count = old_cache['count'] + 1 if old_cache else 0
+        cache.set(
+            self.cache_key,
+            {
+                'template_body': template_body,
+                'expiry_time': expiry_time,
+                'last_update': last_update,
+                'count': count,
+            },
+            2592000,
+        )  # bypass cache level expiration time
 
 
 def theme_base(request):

tests/test_context_processors.py

@@ -1,9 +1,11 @@
 import json
+import re
 import threading
 import time
 from unittest import mock
 
 import pytest
+import requests
 import responses
 from django.core.cache import cache
 from django.test import override_settings
@@ -79,6 +81,87 @@ def test_theme_base(portal_mock, theme_base_source):
     assert not calls
 
 
+@pytest.fixture
+def portal_mock_error():
+    def callback(request):
+        headers = {
+            'X-Combo-Skeleton-Pages': json.dumps(
+                {'1': 'http://testserver/foo', '2': 'http://testserver/page1/page2/'}
+            )
+        }
+        if 'page2' in request.url:
+            raise requests.RequestException('page2 boom!')
+        return 200, headers, TEMPLATE
+
+    with responses.RequestsMock() as rsps, override_settings(
+        INSTALLED_APPS=[], THEME_SKELETON_URL='http://combo.example.com/_skeleton_/'
+    ):
+        rsps.add_callback(responses.GET, 'http://combo.example.com/_skeleton_/', callback=callback)
+        yield rsps
+
+
+def test_theme_base_error(portal_mock_error, theme_base_source, caplog, freezer):
+    calls = portal_mock_error.calls
+    cache.clear()
+    caplog.set_level('WARNING')
+
+    assert not caplog.messages
+    assert theme_base_source('/') == TEMPLATE
+    wait_other_threads()
+    assert len(calls) == 3
+
+    calls.reset()
+    portal_mock_error.replace(
+        responses.GET, 'http://combo.example.com/_skeleton_/', body=requests.RequestException('boom!')
+    )
+
+    assert theme_base_source('/') == TEMPLATE
+    assert not calls
+    assert not caplog.messages
+
+    # move 5 minutes later...
+    freezer.tick(301)
+    assert theme_base_source('/') == TEMPLATE
+    wait_other_threads()
+
+    assert calls
+    assert re.match('WARNING.*failed to retrieve theme.*boom!', caplog.text)
+    caplog.clear()
+    calls.reset()
+
+    # move 1 hours later...
+    freezer.tick(3300)
+    assert theme_base_source('/') == TEMPLATE
+    wait_other_threads()
+    assert len(calls) == 1
+    assert re.match('WARNING.*failed to retrieve theme.*boom!', caplog.text)
+    caplog.clear()
+    calls.reset()
+
+    freezer.tick(301)
+
+    assert theme_base_source('/') == TEMPLATE
+    wait_other_threads()
+    assert len(calls) == 1
+    assert re.match('WARNING.*failed to retrieve theme.*boom!', caplog.text)
+    caplog.clear()
+    calls.reset()
+
+    freezer.tick(301)
+
+    assert theme_base_source('/') == TEMPLATE
+    wait_other_threads()
+    assert len(calls) == 1
+    assert re.match('ERROR.*failed to retrieve theme.*boom!', caplog.text)
+    caplog.clear()
+    calls.reset()
+
+    # after some times cache is evicted and...
+    cache.clear()
+    with pytest.raises(Exception, match=r'Failed to retrieve theme:.*boom'):
+        theme_base_source('/')
+
+
 @pytest.fixture
 def portal_mock_language():
     def callback(request):