From 62f2ad09ccd38d6aee41e692d93a03681427b04c Mon Sep 17 00:00:00 2001 From: Thomas Thorogood Date: Fri, 24 Jun 2022 10:31:24 -0700 Subject: [PATCH] Remove the singular JsonLogger in favor of the uw-it-flask-gunicorn-json-logger package (#136) * Remove the singular JsonLogger component and use the new, shared one instead. :) Please note that the `@logged_timer` function in the new package does not yet have features that are implemented in the current `@timed` decorator in this package, so I haven't stripped that out yet. (i.e., we're still using the existing timers.) * [Bot] Update version to 2.1.10 Co-authored-by: github-actions <41898282+github-actions[bot]@users.noreply.github.com> --- husky_directory/app.py | 21 +-- husky_directory/blueprints/app.py | 10 +- husky_directory/blueprints/saml.py | 9 +- husky_directory/blueprints/search.py | 17 +-- husky_directory/logging.py | 120 ------------------ husky_directory/services/pws.py | 7 +- husky_directory/services/reducer.py | 11 +- husky_directory/services/search.py | 7 +- husky_directory/settings/logging.yml | 39 ------ .../static/assets/uw-sprite-mini.svg | 5 +- husky_directory/util.py | 24 +++- poetry.lock | 18 ++- pyproject.toml | 3 +- tests/test_logging.py | 38 ------ 14 files changed, 63 insertions(+), 266 deletions(-) delete mode 100644 husky_directory/logging.py delete mode 100644 husky_directory/settings/logging.yml delete mode 100644 tests/test_logging.py diff --git a/husky_directory/app.py b/husky_directory/app.py index beca0492..61e2d031 100755 --- a/husky_directory/app.py +++ b/husky_directory/app.py @@ -1,7 +1,5 @@ -import logging import os from datetime import datetime -from logging.config import dictConfig from typing import List, NoReturn, Optional, Type, cast import inflection @@ -13,6 +11,7 @@ from injector import Injector, Module, provider, singleton from jinja2.tests import test_undefined from redis import Redis +from uw_it.flask_util.logger import FlaskJSONLogger from uw_saml2 import mock, python3_saml from werkzeug.exceptions import HTTPException, InternalServerError from werkzeug.local import LocalProxy @@ -29,7 +28,6 @@ from .app_config import ( ApplicationConfig, ApplicationConfigInjectorModule, - YAMLSettingsLoader, ) @@ -64,18 +62,6 @@ def provide_request_session(self) -> LocalProxy: LocalProxy, flask_session ) # Cast this so that IDEs knows what's up; does not affect runtime - @provider - @singleton - def provide_logger( - self, yaml_loader: YAMLSettingsLoader, injector: Injector - ) -> logging.Logger: - logger_settings = yaml_loader.load_settings("logging") - dictConfig(logger_settings) - app_logger = logging.getLogger("gunicorn.error").getChild("app") - formatter = app_logger.handlers[0].formatter - formatter.injector = injector - return app_logger - def register_jinja_extensions(self, app: Flask): """You can define jinja filters here in order to make them available in our jinja templates.""" @@ -141,7 +127,6 @@ def provide_app( self, injector: Injector, app_settings: ApplicationConfig, - logger: logging.Logger, # Any blueprints that are depended on here must # get registered below, under "App blueprints get registered here." search_blueprint: SearchBlueprint, @@ -171,12 +156,10 @@ def provide_app( app.register_blueprint(search_blueprint) app.register_blueprint(saml_blueprint) - # Ensure the application is using the same logger as everything else. - app.logger = logger - # Bind an injector to the app itself to manage the scopes of # our dependencies appropriate for each request. FlaskInjector(app=app, injector=injector) + FlaskJSONLogger(app) self._configure_app_session(app, app_settings) self._configure_prometheus(app, app_settings, injector) attach_app_error_handlers(app) diff --git a/husky_directory/blueprints/app.py b/husky_directory/blueprints/app.py index 3a1436ec..82c52df2 100644 --- a/husky_directory/blueprints/app.py +++ b/husky_directory/blueprints/app.py @@ -1,4 +1,3 @@ -from logging import Logger from typing import Optional from flask import Blueprint, Request, jsonify @@ -8,7 +7,7 @@ from husky_directory.app_config import ApplicationConfig from husky_directory.services.pws import PersonWebServiceClient -from husky_directory.util import camelize +from husky_directory.util import AppLoggerMixIn, camelize class HealthReport(BaseModel): @@ -24,20 +23,17 @@ class Config: deployment_id: Optional[str] -class AppBlueprint(Blueprint): +class AppBlueprint(Blueprint, AppLoggerMixIn): """Blueprint for root urls within the application.""" @inject - def __init__( - self, app_config: ApplicationConfig, logger: Logger, injector: Injector - ): + def __init__(self, app_config: ApplicationConfig, injector: Injector): super().__init__("uw-directory", __name__) self.add_url_rule("/status", view_func=self.health) self.config = app_config self.start_time = app_config.start_time self._app_config = app_config self._injector = injector - self.logger = logger self.__pws_result = None @property diff --git a/husky_directory/blueprints/saml.py b/husky_directory/blueprints/saml.py index 58470d59..821a80f3 100644 --- a/husky_directory/blueprints/saml.py +++ b/husky_directory/blueprints/saml.py @@ -1,6 +1,5 @@ import getpass import urllib.parse -from logging import Logger from typing import Dict import uw_saml2 @@ -11,19 +10,21 @@ from werkzeug.local import LocalProxy from husky_directory.app_config import ApplicationConfig +from husky_directory.util import AppLoggerMixIn -class SAMLBlueprint(Blueprint): +class SAMLBlueprint(Blueprint, AppLoggerMixIn): @inject def __init__( - self, idp_config: IdpConfig, settings: ApplicationConfig, logger: Logger + self, + idp_config: IdpConfig, + settings: ApplicationConfig, ): super().__init__("saml", __name__, url_prefix="/saml") self.idp_config = idp_config self.add_url_rule("/login", view_func=self.login, methods=["GET", "POST"]) self.add_url_rule("/logout", view_func=self.log_out) self.auth_settings = settings.auth_settings - self.logger = logger def process_saml_request(self, request: Request, session: LocalProxy, **kwargs): dest_url = request.form.get("RelayState") or request.host_url diff --git a/husky_directory/blueprints/search.py b/husky_directory/blueprints/search.py index 0017e755..b9b2c997 100644 --- a/husky_directory/blueprints/search.py +++ b/husky_directory/blueprints/search.py @@ -1,5 +1,4 @@ from base64 import b64decode -from logging import Logger from typing import Optional, Union from flask import ( @@ -27,6 +26,7 @@ ) from husky_directory.services.search import DirectorySearchService from husky_directory.services.vcard import VCardService +from husky_directory.util import AppLoggerMixIn class ErrorModel(DirectoryBaseModel): @@ -46,12 +46,11 @@ class Config(DirectoryBaseModel.Config): @singleton -class SearchBlueprint(Blueprint): +class SearchBlueprint(Blueprint, AppLoggerMixIn): @inject - def __init__(self, logger: Logger, injector: Injector): + def __init__(self, injector: Injector): super().__init__("search", __name__) self.injector = injector - self.logger = logger self.add_url_rule("/", view_func=self.index, methods=("GET",)) self.add_url_rule("/", view_func=self.search_listing, methods=("POST",)) self.add_url_rule( @@ -84,10 +83,9 @@ def index(request: Request, session: LocalProxy, settings: ApplicationConfig): 200, ) - @staticmethod def get_person_listing( + self, request: Request, - logger: Logger, session: LocalProxy, service: DirectorySearchService, ): @@ -103,7 +101,7 @@ def get_person_listing( ) except Exception as e: template = "views/index.html" - logger.exception(str(e)) + self.logger.exception(str(e)) SearchBlueprint.handle_search_exception(e, context) finally: return ( @@ -141,11 +139,10 @@ def handle_search_exception(e: Exception, context: RenderingContext): "email help@uw.edu describing your problem." ) - @staticmethod def search_listing( + self, request: Request, service: DirectorySearchService, - logger: Logger, session: LocalProxy, settings: ApplicationConfig, ): @@ -160,7 +157,7 @@ def search_listing( request_input = SearchDirectoryInput.from_form_input(form_input) context.search_result = service.search_directory(request_input) except Exception as e: - logger.exception(str(e)) + self.logger.exception(str(e)) SearchBlueprint.handle_search_exception(e, context) finally: response: Response = make_response( diff --git a/husky_directory/logging.py b/husky_directory/logging.py deleted file mode 100644 index f9cd6a54..00000000 --- a/husky_directory/logging.py +++ /dev/null @@ -1,120 +0,0 @@ -import json -import logging -import os -import threading -import traceback -from typing import Any, Dict, Optional, Type, TypeVar - -import injector -from flask import Request -from injector import Injector -from werkzeug.local import LocalProxy - -T = TypeVar("T") - -ROOT_LOGGER = "gunicorn.error" -PRETTY_JSON = os.environ.get("FLASK_ENV", "production") == "development" - - -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 - # All of our logs must be children of the gunicorn.error log as long - # as we continue to use gunicorn. - root_logger: str = ROOT_LOGGER - - def _get_optional_injected(self, cls: Type[T]) -> Optional[T]: - if not self.injector: - return None - try: - return self.injector.get(cls) - except ( - # If injector tries to create an instance of an unbound object - # but the object cannot be created - injector.CallError, - # If the injector tries to fetch an instance outside its - # specified scope - RuntimeError, - # If the injector tries to fetch something it has no knowledge - # of whatsoever. - KeyError, - ): - 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 sanitize_logger_name(self, name: str): - """ - Removes the scary looking 'gunicorn.error' string from the logs - so as not to confuse anyone and also have nicer looking logs. - """ - if name.startswith(self.root_logger): - name = name.replace(self.root_logger, "") - if not name: - # All gunicorn logs go to the gunicorn.error log, - # we rename it in our json payload to make it - # more approachable - name = "gunicorn_worker" - if name.startswith("."): - name = name[1:] - return name - - def _append_request_log(self, data: Dict[str, Any]): - request = self.get_request() - if request: - request_log = { - "method": request.method, - "url": request.url, - "remoteIp": request.headers.get("X-Forwarded-For", request.remote_addr), - "id": id(request), - } - session = self.get_session() - if session and session.get("uwnetid"): - request_log["uwnetid"] = session["uwnetid"] - data["request"] = request_log - - @staticmethod - def _append_custom_attrs(record: logging.LogRecord, data: Dict[str, Any]): - if hasattr(record, "extra_keys"): - extras = {key: getattr(record, key, None) for key in record.extra_keys} - data.update(extras) - - @staticmethod - def _append_exception_info(record: logging.LogRecord, data: Dict[str, Any]): - if record.exc_info: - exc_type, exc_message, tb = record.exc_info - data["exception"] = { - "message": f"{exc_type.__name__}: {exc_message}", - "traceback": traceback.format_tb(tb, limit=20), - } - - def format(self, record): - data = { - "severity": record.levelname, - "message": record.getMessage(), - "line": f"{record.filename}#{record.funcName}:{record.lineno}", - "logger": self.sanitize_logger_name(record.name), - "thread": threading.currentThread().ident, - } - self._append_request_log(data) - self._append_custom_attrs(record, data) - self._append_exception_info(record, data) - - kwargs = {} - if PRETTY_JSON: - kwargs["indent"] = 4 - return json.dumps(data, default=str, **kwargs) - - -def build_extras(attrs: Dict) -> Dict: - attrs = attrs.copy() - attrs["extra_keys"] = list(attrs.keys()) - return attrs diff --git a/husky_directory/services/pws.py b/husky_directory/services/pws.py index 8c8e015e..3a9c2332 100644 --- a/husky_directory/services/pws.py +++ b/husky_directory/services/pws.py @@ -1,7 +1,6 @@ import os from collections import namedtuple from functools import partial -from logging import Logger from typing import Any, Dict, List, Optional, Type, TypeVar, Union import requests @@ -19,7 +18,7 @@ PersonOutput, ) from husky_directory.services.auth import AuthService -from husky_directory.util import timed +from husky_directory.util import AppLoggerMixIn, timed RequestsCertificate = namedtuple("RequestsCertificate", ["cert_path", "key_path"]) @@ -48,7 +47,7 @@ def clear_namespace(namespace, record: Any) -> bool: @request -class PersonWebServiceClient: +class PersonWebServiceClient(AppLoggerMixIn): _GLOBAL_CONSTRAINTS = [ RecordConstraint( # If the identity has no netid, we are not interested @@ -103,7 +102,6 @@ class PersonWebServiceClient: def __init__( self, application_config: ApplicationConfig, - logger: Logger, auth: AuthService, ): uwca_cert_path = application_config.auth_settings.uwca_cert_path @@ -114,7 +112,6 @@ def __init__( ) self.host = application_config.pws_settings.pws_host self.default_path = application_config.pws_settings.pws_default_path - self.logger = logger self.auth = auth @property diff --git a/husky_directory/services/reducer.py b/husky_directory/services/reducer.py index b19c839c..dcb220e6 100644 --- a/husky_directory/services/reducer.py +++ b/husky_directory/services/reducer.py @@ -1,14 +1,11 @@ from collections import OrderedDict from functools import cached_property -from logging import Logger from typing import Dict, Optional, Tuple -from injector import inject - from husky_directory.models.pws import ListPersonsOutput, NamedIdentity from husky_directory.models.transforms import ResultBucket from husky_directory.services.name_analyzer import NameAnalyzer -from husky_directory.util import is_similar, readable_list +from husky_directory.util import AppLoggerMixIn, is_similar, readable_list class NameQueryResultAnalyzer: @@ -84,12 +81,10 @@ def relevant_bucket(self) -> Optional[Tuple[str, int]]: return f"Name contains {readable}", 7 -class NameSearchResultReducer: - @inject - def __init__(self, logger: Logger): +class NameSearchResultReducer(AppLoggerMixIn): + def __init__(self): self.duplicate_netids = set() self.duplicate_hit_count = 0 - self.logger = logger def reduce_output( self, diff --git a/husky_directory/services/search.py b/husky_directory/services/search.py index d509a021..ace28a34 100644 --- a/husky_directory/services/search.py +++ b/husky_directory/services/search.py @@ -1,6 +1,5 @@ from __future__ import annotations -from logging import Logger from typing import Dict, List from flask_injector import request @@ -26,23 +25,21 @@ from husky_directory.services.translator import ( ListPersonsOutputTranslator, ) -from husky_directory.util import Timer +from husky_directory.util import AppLoggerMixIn, Timer @request -class DirectorySearchService: +class DirectorySearchService(AppLoggerMixIn): @inject def __init__( self, pws: PersonWebServiceClient, - logger: Logger, query_generator: SearchQueryGenerator, pws_translator: ListPersonsOutputTranslator, auth_service: AuthService, reducer: NameSearchResultReducer, ): self._pws = pws - self.logger = logger self.query_generator = query_generator self.pws_translator = pws_translator self.auth_service = auth_service diff --git a/husky_directory/settings/logging.yml b/husky_directory/settings/logging.yml deleted file mode 100644 index 9c2ed392..00000000 --- a/husky_directory/settings/logging.yml +++ /dev/null @@ -1,39 +0,0 @@ -base: &base - version: 1 - formatters: - default: - format: "[%(levelname)s][%(asctime)s][%(module)s]: %(message)s" - json: - '()': husky_directory.logging.JsonFormatter - handlers: - wsgi: - level: INFO - class: logging.StreamHandler - formatter: json - gunicorn: - level: ERROR - class: logging.StreamHandler - formatter: default - loggers: - glogging: - # Turn off all but critical `glogging` messages, because it's - # a very noisy module that is out of our control. - level: CRITICAL - propagate: false - gunicorn.error.app: - level: DEBUG - propagate: false - handlers: - - wsgi - gunicorn.error: - handlers: - - gunicorn - gunicorn.error.app.unscoped: - handlers: - - gunicorn - -development: *base - -test: *base - -production: *base diff --git a/husky_directory/static/assets/uw-sprite-mini.svg b/husky_directory/static/assets/uw-sprite-mini.svg index 3b588fcd..94acd45c 100644 --- a/husky_directory/static/assets/uw-sprite-mini.svg +++ b/husky_directory/static/assets/uw-sprite-mini.svg @@ -1,8 +1,9 @@ - + bool: return not value or target in value -class Timer: +class AppLoggerMixIn: + @property + def logger(self) -> Logger: + """ + Lazily gets the logger from the current app, so that the app has been + created by the time the logger is accessed (rather than doing this when the + object is created). + """ + return current_app.logger + + +class Timer(AppLoggerMixIn): """ This timer integrates with logging and also offers a timed context to make it easy to time functions or even just blocks of code with @@ -131,7 +141,6 @@ def __init__( self, name: str, emit_log: bool = True, context: Optional[Dict[str, Any]] = None ): self.name = name - self.logger = logging.getLogger(ROOT_LOGGER).getChild(self.logger_name) self.start_time = None self.end_time = None self.result = None @@ -172,8 +181,9 @@ def _emit_log(self): "endTime": self.end_time, } self.context["timer"] = summary - extras = build_extras(self.context) - self.logger.info(f"{self.name} [{self.result}] {self.context}", extra=extras) + self.logger.info( + f"{self.name} [{self.result}] {self.context}", extra=self.context + ) def timed(function: Callable): diff --git a/poetry.lock b/poetry.lock index 0c83d435..c0b12006 100644 --- a/poetry.lock +++ b/poetry.lock @@ -964,6 +964,18 @@ brotli = ["brotlicffi (>=0.8.0)", "brotli (>=1.0.9)", "brotlipy (>=0.6.0)"] secure = ["pyOpenSSL (>=0.14)", "cryptography (>=1.3.4)", "idna (>=2.0.0)", "certifi", "ipaddress"] socks = ["PySocks (>=1.5.6,!=1.5.7,<2.0)"] +[[package]] +name = "uw-it-flask-gunicorn-json-logger" +version = "0.1.6" +description = "" +category = "main" +optional = false +python-versions = ">=3.7,<4" + +[package.dependencies] +Flask = ">=2,<3" +PyYAML = ">=6.0,<7.0" + [[package]] name = "uw-saml" version = "1.1.1" @@ -1082,7 +1094,7 @@ testing = ["coverage (>=5.0.3)", "zope.event", "zope.testing"] [metadata] lock-version = "1.1" python-versions = ">=3.8,<3.9" -content-hash = "71966ccbef1af8c4259ae1a05a454434de7bba5af76348c28fb9b6cf41f5bb92" +content-hash = "b286b275d5bc82656f25f9fdf0f6737164b1322b0547a02ee74997242f028221" [metadata.files] asttokens = [ @@ -1718,6 +1730,10 @@ urllib3 = [ {file = "urllib3-1.26.9-py2.py3-none-any.whl", hash = "sha256:44ece4d53fb1706f667c9bd1c648f5469a2ec925fcf3a776667042d645472c14"}, {file = "urllib3-1.26.9.tar.gz", hash = "sha256:aabaf16477806a5e1dd19aa41f8c2b7950dd3c746362d7e3223dbe6de6ac448e"}, ] +uw-it-flask-gunicorn-json-logger = [ + {file = "uw-it-flask-gunicorn-json-logger-0.1.6.tar.gz", hash = "sha256:1a72156cf53aa2613ab785993d2e434533329c3ae700a08f0102b535d6707904"}, + {file = "uw_it_flask_gunicorn_json_logger-0.1.6-py3-none-any.whl", hash = "sha256:284ff62ff9f697d7788fdf6b2a6c963e5f38edfddade8c3e9aae0926f4ad2936"}, +] uw-saml = [ {file = "uw-saml-1.1.1.tar.gz", hash = "sha256:842fac070728635620018c41a9510ca199a3c4c905a17c7082043da17944dc33"}, {file = "uw_saml-1.1.1-py3-none-any.whl", hash = "sha256:5fb229a1c266cbc81a0f6deef3fb748b1efbe2905f3b8707b717188a79bcf02b"}, diff --git a/pyproject.toml b/pyproject.toml index 2483c7fd..6442663a 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [tool.poetry] name = "uw-husky-directory" -version = "2.1.9" +version = "2.1.10" description = "An updated version of the UW Directory" authors = ["Thomas Thorogood "] license = "MIT" @@ -24,6 +24,7 @@ pytz = "^2022.1" prometheus-flask-exporter = "^0.19" Flask-HTTPAuth = "^4.4.0" python-Levenshtein = "^0.12.2" +uw-it-flask-gunicorn-json-logger = "^0.1.6" [tool.poetry.dev-dependencies] black = "^22.0" diff --git a/tests/test_logging.py b/tests/test_logging.py deleted file mode 100644 index 669ddc91..00000000 --- a/tests/test_logging.py +++ /dev/null @@ -1,38 +0,0 @@ -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"