Log checks messages in heartbeat view (#86)

* Log checks messages in heartbeat view

This implements ``monitoring-heartbeat-error`` of our https://mozilla.github.io/syseng-pod/quality-standards/

* @grahamalama review

Author: leplatrem

src/dockerflow/django/views.py

@@ -1,6 +1,8 @@
 # This Source Code Form is subject to the terms of the Mozilla Public
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, you can obtain one at http://mozilla.org/MPL/2.0/.
+import logging
+
 from django.conf import settings
 from django.core import checks
 from django.http import HttpResponse, HttpResponseNotFound, JsonResponse
@@ -14,6 +16,9 @@
 )
 
 
+logger = logging.getLogger("dockerflow.django")
+
+
 def version(request):
     """
     Returns the contents of version.json or a 404.
@@ -51,11 +56,18 @@ def heartbeat(request):
     level = 0
 
     for check in all_checks:
-        detail = heartbeat_check_detail(check)
-        statuses[check.__name__] = detail["status"]
-        level = max(level, detail["level"])
-        if detail["level"] > 0:
-            details[check.__name__] = detail
+        check_level, check_errors = heartbeat_check_detail(check)
+        level_text = level_to_text(check_level)
+        statuses[check.__name__] = level_text
+        level = max(level, check_level)
+        if level > 0:
+            for error in check_errors:
+                logger.log(error.level, "%s: %s", error.id, error.msg)
+            details[check.__name__] = {
+                "status": level_text,
+                "level": level,
+                "messages": {e.id: e.msg for e in check_errors},
+            }
 
     if level < checks.messages.ERROR:
         status_code = 200
@@ -75,9 +87,4 @@ def heartbeat_check_detail(check):
     errors = check(app_configs=None)
     errors = list(filter(lambda e: e.id not in settings.SILENCED_SYSTEM_CHECKS, errors))
     level = max([0] + [e.level for e in errors])
-
-    return {
-        "status": level_to_text(level),
-        "level": level,
-        "messages": {e.id: e.msg for e in errors},
-    }
+    return level, errors

src/dockerflow/flask/app.py

@@ -306,12 +306,7 @@ def _lbheartbeat_view(self):
     def _heartbeat_check_detail(self, check):
         errors = list(filter(lambda e: e.id not in self.silenced_checks, check()))
         level = max([0] + [e.level for e in errors])
-
-        return {
-            "status": checks.level_to_text(level),
-            "level": level,
-            "messages": {e.id: e.msg for e in errors},
-        }
+        return level, errors
 
     def _heartbeat_view(self):
         """
@@ -326,11 +321,18 @@ def _heartbeat_view(self):
         level = 0
 
         for name, check in self.checks.items():
-            detail = self._heartbeat_check_detail(check)
-            statuses[name] = detail["status"]
-            level = max(level, detail["level"])
-            if detail["level"] > 0:
-                details[name] = detail
+            check_level, check_errors = self._heartbeat_check_detail(check)
+            level_text = checks.level_to_text(check_level)
+            statuses[name] = level_text
+            level = max(level, check_level)
+            if check_level > 0:
+                for error in check_errors:
+                    self.logger.log(error.level, "%s: %s", error.id, error.msg)
+                details[name] = {
+                    "status": level_text,
+                    "level": level,
+                    "messages": {e.id: e.msg for e in check_errors},
+                }
 
         payload = {
             "status": checks.level_to_text(level),

src/dockerflow/sanic/app.py

@@ -214,12 +214,7 @@ async def _heartbeat_check_detail(self, check):
             result = await result
         errors = [e for e in result if e.id not in self.silenced_checks]
         level = max([0] + [e.level for e in errors])
-
-        return {
-            "status": checks.level_to_text(level),
-            "level": level,
-            "messages": {e.id: e.msg for e in errors},
-        }
+        return level, errors
 
     async def _heartbeat_view(self, request):
         """
@@ -234,11 +229,18 @@ async def _heartbeat_view(self, request):
         level = 0
 
         for name, check in self.checks.items():
-            detail = await self._heartbeat_check_detail(check)
-            statuses[name] = detail["status"]
-            level = max(level, detail["level"])
-            if detail["level"] > 0:
-                details[name] = detail
+            check_level, check_errors = await self._heartbeat_check_detail(check)
+            level_text = checks.level_to_text(check_level)
+            statuses[name] = level_text
+            level = max(level, check_level)
+            if check_level > 0:
+                for error in check_errors:
+                    self.logger.log(error.level, "%s: %s", error.id, error.msg)
+                details[name] = {
+                    "status": level_text,
+                    "level": check_level,
+                    "messages": {e.id: e.msg for e in check_errors},
+                }
 
         payload = {
             "status": checks.level_to_text(level),

tests/django/test_django.py

@@ -68,6 +68,22 @@ def test_heartbeat(dockerflow_middleware, reset_checks, rf, settings):
     assert response.status_code == 500
 
 
+@pytest.mark.django_db
+def test_heartbeat_logging(dockerflow_middleware, reset_checks, rf, settings, caplog):
+    request = rf.get("/__heartbeat__")
+    settings.DOCKERFLOW_CHECKS = [
+        "tests.django.django_checks.warning",
+        "tests.django.django_checks.error",
+    ]
+    checks.register()
+
+    with caplog.at_level(logging.INFO, logger="dockerflow.django"):
+        dockerflow_middleware.process_request(request)
+    logged = [(record.levelname, record.message) for record in caplog.records]
+    assert ("ERROR", "tests.checks.E001: some error") in logged
+    assert ("WARNING", "tests.checks.W001: some warning") in logged
+
+
 @pytest.mark.django_db
 def test_lbheartbeat_makes_no_db_queries(dockerflow_middleware, rf):
     queries = CaptureQueriesContext(connection)

tests/flask/test_flask.py

@@ -139,6 +139,25 @@ def warning_check2():
     assert "warning-check-two" in defaults
 
 
+def test_heartbeat_logging(app, dockerflow, caplog):
+    dockerflow.checks.clear()
+
+    @dockerflow.check
+    def error_check():
+        return [checks.Error("some error", id="tests.checks.E001")]
+
+    @dockerflow.check()
+    def warning_check():
+        return [checks.Warning("some warning", id="tests.checks.W001")]
+
+    with caplog.at_level(logging.INFO, logger="dockerflow.django"):
+        app.test_client().get("/__heartbeat__")
+
+    logged = [(record.levelname, record.message) for record in caplog.records]
+    assert ("ERROR", "tests.checks.E001: some error") in logged
+    assert ("WARNING", "tests.checks.W001: some warning") in logged
+
+
 def test_lbheartbeat_makes_no_db_queries(dockerflow, app):
     with app.app_context():
         assert len(get_debug_queries()) == 0

tests/sanic/test_sanic.py

@@ -162,6 +162,25 @@ async def warning_check2():
     assert "warning-check-two" in details
 
 
+def test_heartbeat_logging(dockerflow, test_client, caplog):
+    dockerflow.checks.clear()
+
+    @dockerflow.check
+    def error_check():
+        return [checks.Error("some error", id="tests.checks.E001")]
+
+    @dockerflow.check()
+    def warning_check():
+        return [checks.Warning("some warning", id="tests.checks.W001")]
+
+    with caplog.at_level(logging.INFO, logger="dockerflow.sanic"):
+        _, response = test_client.get("/__heartbeat__")
+
+    logged = [(record.levelname, record.message) for record in caplog.records]
+    assert ("ERROR", "tests.checks.E001: some error") in logged
+    assert ("WARNING", "tests.checks.W001: some warning") in logged
+
+
 def test_redis_check(dockerflow_redis, mocker, test_client):
     assert "check_redis_connected" in dockerflow_redis.checks
     mocker.patch.object(sanic_redis.core, "from_url", fake_redis)