From 2ff7c80539e3ec5d421eb2c6086151aa93d27986 Mon Sep 17 00:00:00 2001 From: Thomas Thorogood Date: Tue, 24 Aug 2021 10:58:19 -0700 Subject: [PATCH] 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 | 9 ++++- husky_directory/blueprints/saml.py | 2 +- husky_directory/logging.py | 53 ++++++++++++++++++++++++++++ husky_directory/settings/logging.yml | 15 +++++--- pyproject.toml | 2 +- tests/test_logging.py | 38 ++++++++++++++++++++ 6 files changed, 112 insertions(+), 7 deletions(-) create mode 100644 husky_directory/logging.py create mode 100644 tests/test_logging.py diff --git a/husky_directory/app.py b/husky_directory/app.py index de59e29f..212e7ca6 100755 --- a/husky_directory/app.py +++ b/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): diff --git a/husky_directory/blueprints/saml.py b/husky_directory/blueprints/saml.py index ab8bc58e..76febf7e 100644 --- a/husky_directory/blueprints/saml.py +++ b/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) diff --git a/husky_directory/logging.py b/husky_directory/logging.py new file mode 100644 index 00000000..7a5d3d2e --- /dev/null +++ b/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) diff --git a/husky_directory/settings/logging.yml b/husky_directory/settings/logging.yml index 450b93df..dfb3802f 100644 --- a/husky_directory/settings/logging.yml +++ b/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 diff --git a/pyproject.toml b/pyproject.toml index bce8fb0b..c0c8f2f2 100644 --- a/pyproject.toml +++ b/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 "] license = "MIT" diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 00000000..669ddc91 --- /dev/null +++ b/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"