Productionize log configuration (#86)

* Add a JsonFormatter (similar to identity-uw formatter) so that stackdriver logs are useful.

* [Bot] Update version to 1.1.0

Co-authored-by: github-actions <41898282+github-actions[bot]@users.noreply.github.com>

husky_directory/app.py

@@ -69,10 +69,17 @@ def provide_request_session(self) -> LocalProxy:
 
     @provider
     @singleton
-    def provide_logger(self, yaml_loader: YAMLSettingsLoader) -> logging.Logger:
+    def provide_logger(
+        self, yaml_loader: YAMLSettingsLoader, injector: Injector
+    ) -> logging.Logger:
         logger_settings = yaml_loader.load_settings("logging")
         dictConfig(logger_settings)
         gunicorn_error_logger = logging.getLogger("gunicorn.error")
+        formatter = gunicorn_error_logger.handlers[0].formatter
+        formatter.injector = injector
+        gunicorn_error_logger.info(
+            f"Log formatter: {gunicorn_error_logger.handlers[0].formatter}"
+        )
         return gunicorn_error_logger
 
     def register_jinja_extensions(self, app: Flask):

husky_directory/blueprints/saml.py

@@ -42,7 +42,7 @@ def login(self, request: Request, session: LocalProxy):
 
         if request.method == "GET":
             args["return_to"] = request.host_url
-            self.logger.info(f"Redirecting {request.remote_addr} to SAML sign in.")
+            self.logger.debug(f"Redirecting {request.remote_addr} to SAML sign in.")
             return redirect(uw_saml2.login_redirect(**args))
 
         return self.process_saml_request(request, session, **args)

husky_directory/logging.py

@@ -0,0 +1,53 @@
+import json
+import logging
+from typing import Optional, Type, TypeVar
+
+from flask import Request
+from injector import Injector
+from werkzeug.local import LocalProxy
+
+T = TypeVar("T")
+
+
+class JsonFormatter(logging.Formatter):
+    """
+    A formatter adhering to the structure advised in
+    https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry.
+    """
+
+    injector: Injector = None
+
+    def _get_optional_injected(self, cls: Type[T]) -> Optional[T]:
+        if not self.injector:
+            return None
+        try:
+            return self.injector.get(cls)
+        except RuntimeError:
+            return None
+
+    def get_request(self) -> Optional[Request]:
+        return self._get_optional_injected(Request)
+
+    def get_session(self) -> Optional[LocalProxy]:
+        return self._get_optional_injected(LocalProxy)
+
+    def format(self, record):
+        data = {
+            "severity": record.levelname,
+            "message": record.getMessage(),
+            "module": record.module,
+            "line": f"{record.filename}#{record.funcName}:{record.lineno}",
+        }
+        request = self.get_request()
+        if request:
+            request_log = {
+                "method": request.method,
+                "url": request.url,
+                "remoteIp": request.remote_addr,
+            }
+            session = self.get_session()
+            if session and session.get("uwnetid"):
+                request_log["uwnetid"] = session["uwnetid"]
+            data["request"] = request_log
+
+        return json.dumps(data, default=str)

husky_directory/settings/logging.yml

@@ -3,16 +3,23 @@ base: &base
   formatters:
     default:
       format: "[%(levelname)s][%(asctime)s][%(module)s]: %(message)s"
+    json:
+      '()': husky_directory.logging.JsonFormatter
   handlers:
     wsgi:
-      level: DEBUG
+      level: INFO
       class: logging.StreamHandler
-      formatter: default
+      formatter: json
   loggers:
     glogging:
-      level: WARNING  # This is very noisy and duplicates a lot of error messages.
-    gunicorn.error:
+      # Turn off all but critical `glogging` messages, because it's
+      # a very noisy module that is out of our control.
+      level: CRITICAL
+      propagate: true
+    app:
       level: DEBUG
+      propagate: true
+    gunicorn.error:
       handlers:
         - wsgi
 

pyproject.toml

@@ -1,6 +1,6 @@
 [tool.poetry]
 name = "uw-husky-directory"
-version = "1.0.2"
+version = "1.1.0"
 description = "An updated version of the UW Directory"
 authors = ["Thomas Thorogood <[email protected]>"]
 license = "MIT"

tests/test_logging.py

@@ -0,0 +1,38 @@
+from unittest import mock
+from unittest.mock import MagicMock
+
+from flask import Request
+from injector import Injector
+from werkzeug.local import LocalProxy
+
+from husky_directory.logging import JsonFormatter
+
+
+def test_get_attrs_no_injector():
+    formatter = JsonFormatter()
+    assert formatter.get_session() is None
+    assert formatter.get_request() is None
+
+
+def test_get_attrs_injector_error(injector: Injector):
+    formatter = JsonFormatter()
+    formatter.injector = injector
+    with mock.patch.object(injector, "get") as mock_get:
+        mock_get.side_effect = RuntimeError
+        assert formatter.get_session() is None
+        assert formatter.get_request() is None
+
+
+def test_formatter_late_injection(injector: Injector, client, mock_injected):
+    formatter = JsonFormatter()
+    formatter.injector = injector
+    with mock_injected(LocalProxy, {}) as session:
+        request = MagicMock(Request)
+        request.method = "GET"
+        request.url = "https://www.uw.edu"
+        request.remote_addr = "127.0.0.1"
+        session["uwnetid"] = "dawg"
+        with mock_injected(Request, request):
+            client.get("/")
+            assert formatter.get_request().url == "https://www.uw.edu"
+            assert formatter.get_session().get("uwnetid") == "dawg"