diff --git a/atst/app.py b/atst/app.py index adf018ed..13c801f8 100644 --- a/atst/app.py +++ b/atst/app.py @@ -29,11 +29,16 @@ from atst.utils.form_cache import FormCache from atst.utils.json import CustomJSONEncoder from atst.queue import queue +from logging.config import dictConfig +from atst.utils.logging import JsonFormatter, RequestContextFilter + ENV = os.getenv("FLASK_ENV", "dev") def make_app(config): + if ENV == "prod" or config.get("LOG_JSON"): + apply_json_logger() parent_dir = Path().parent @@ -143,6 +148,7 @@ def map_config(config): "RQ_QUEUES": [config["default"]["RQ_QUEUES"]], "DISABLE_CRL_CHECK": config.getboolean("default", "DISABLE_CRL_CHECK"), "CRL_FAIL_OPEN": config.getboolean("default", "CRL_FAIL_OPEN"), + "LOG_JSON": config.getboolean("default", "LOG_JSON"), } @@ -228,3 +234,22 @@ def make_mailer(app): ) sender = app.config.get("MAIL_SENDER") app.mailer = mailer.Mailer(mailer_connection, sender) + + +def apply_json_logger(): + dictConfig( + { + "version": 1, + "formatters": {"default": {"()": lambda *a, **k: JsonFormatter()}}, + "filters": {"requests": {"()": lambda *a, **k: RequestContextFilter()}}, + "handlers": { + "wsgi": { + "class": "logging.StreamHandler", + "stream": "ext://flask.logging.wsgi_errors_stream", + "formatter": "default", + "filters": ["requests"], + } + }, + "root": {"level": "INFO", "handlers": ["wsgi"]}, + } + ) diff --git a/atst/domain/authnid/crl/__init__.py b/atst/domain/authnid/crl/__init__.py index 3451e30e..6a5addd2 100644 --- a/atst/domain/authnid/crl/__init__.py +++ b/atst/domain/authnid/crl/__init__.py @@ -2,6 +2,7 @@ import sys import os import re import hashlib +import logging from flask import current_app as app from datetime import datetime from OpenSSL import crypto, SSL @@ -30,9 +31,9 @@ class CRLInterface: def __init__(self, *args, logger=None, **kwargs): self.logger = logger - def _log_info(self, message): + def _log(self, message, level=logging.INFO): if self.logger: - self.logger.info(message) + self.logger.log(level, message, extras={"tags": ["authorization", "crl"]}) def crl_check(self, cert): raise NotImplementedError() @@ -50,7 +51,7 @@ class NoOpCRLCache(CRLInterface): def crl_check(self, cert): cn = self._get_cn(cert) - self._log_info( + self._log( "Did not perform CRL validation for certificate with Common Name '{}'".format( cn ) @@ -111,11 +112,14 @@ class CRLCache(CRLInterface): try: return crypto.load_crl(crypto.FILETYPE_ASN1, crl_file.read()) except crypto.Error: - self._log_info("Could not load CRL at location {}".format(crl_location)) + self._log( + "Could not load CRL at location {}".format(crl_location), + level=logging.WARNING, + ) def _build_store(self, issuer): store = self.store_class() - self._log_info("STORE ID: {}. Building store.".format(id(store))) + self._log("STORE ID: {}. Building store.".format(id(store))) store.set_flags(crypto.X509StoreFlags.CRL_CHECK) crl_info = self.crl_cache.get(issuer.der(), {}) issuer_name = get_common_name(issuer) @@ -132,7 +136,7 @@ class CRLCache(CRLInterface): crl = self._load_crl(crl_info["location"]) store.add_crl(crl) - self._log_info( + self._log( "STORE ID: {}. Adding CRL with issuer Common Name {}".format( id(store), issuer_name ) @@ -158,7 +162,7 @@ class CRLCache(CRLInterface): def _add_certificate_chain_to_store(self, store, issuer): ca = self.certificate_authorities.get(issuer.der()) store.add_cert(ca) - self._log_info( + self._log( "STORE ID: {}. Adding CA with subject {}".format( id(store), ca.get_subject() ) @@ -182,10 +186,11 @@ class CRLCache(CRLInterface): except crypto.X509StoreContextError as err: if err.args[0][0] == CRL_EXPIRED_ERROR_CODE: if app.config.get("CRL_FAIL_OPEN"): - self._log_info( + self._log( "Encountered expired CRL for certificate with CN {} and issuer CN {}, failing open.".format( parsed.get_subject().CN, parsed.get_issuer().CN - ) + ), + level=logging.WARNING, ) return True else: diff --git a/atst/domain/authz/decorator.py b/atst/domain/authz/decorator.py index e9efac3a..980ee04c 100644 --- a/atst/domain/authz/decorator.py +++ b/atst/domain/authz/decorator.py @@ -45,17 +45,19 @@ def user_can_access_decorator(permission, message=None, override=None): try: check_access(permission, message, override, *args, **kwargs) app.logger.info( - "[access] User {} accessed {} {}".format( + "User {} accessed {} {}".format( g.current_user.id, request.method, request.path - ) + ), + extra={"tags": ["access", "success"]}, ) return f(*args, **kwargs) except UnauthorizedError as err: app.logger.warning( - "[access] User {} denied access {} {}".format( + "User {} denied access {} {}".format( g.current_user.id, request.method, request.path - ) + ), + extra={"tags": ["access", "failure"]}, ) raise (err) diff --git a/atst/routes/errors.py b/atst/routes/errors.py index d00c7f0a..c129e08d 100644 --- a/atst/routes/errors.py +++ b/atst/routes/errors.py @@ -15,7 +15,7 @@ from atst.utils.flash import formatted_flash as flash def log_error(e): error_message = e.message if hasattr(e, "message") else str(e) - current_app.logger.error(error_message) + current_app.logger.exception(error_message) def handle_error(e, message="Not Found", code=404): diff --git a/atst/utils/logging.py b/atst/utils/logging.py new file mode 100644 index 00000000..1ef84d0a --- /dev/null +++ b/atst/utils/logging.py @@ -0,0 +1,47 @@ +import datetime +import json +import logging + +from flask import g, request, has_request_context + + +class RequestContextFilter(logging.Filter): + def filter(self, record): + if has_request_context(): + if getattr(g, "current_user", None): + record.user_id = str(g.current_user.id) + + if request.environ.get("HTTP_X_REQUEST_ID"): + record.request_id = request.environ.get("HTTP_X_REQUEST_ID") + + return True + + +def epoch_to_iso8601(ts): + dt = datetime.datetime.utcfromtimestamp(ts) + return dt.replace(tzinfo=datetime.timezone.utc).isoformat() + + +class JsonFormatter(logging.Formatter): + _DEFAULT_RECORD_FIELDS = [ + ("timestamp", lambda r: epoch_to_iso8601(r.created)), + ("version", lambda r: 1), + ("request_id", lambda r: r.__dict__.get("request_id")), + ("user_id", lambda r: r.__dict__.get("user_id")), + ("severity", lambda r: r.levelname), + ("tags", lambda r: r.__dict__.get("tags")), + ("message", lambda r: r.msg), + ] + + def format(self, record): + message_dict = {} + for field, func in self._DEFAULT_RECORD_FIELDS: + message_dict[field] = func(record) + + if record.__dict__.get("exc_info") is not None: + message_dict["details"] = { + "backtrace": self.formatException(record.exc_info), + "exception": str(record.exc_info[1]), + } + + return json.dumps(message_dict) diff --git a/config/base.ini b/config/base.ini index 37f5df0a..7e41e672 100644 --- a/config/base.ini +++ b/config/base.ini @@ -10,6 +10,7 @@ DISABLE_CRL_CHECK = false CRL_FAIL_OPEN = false DEBUG = true ENVIRONMENT = dev +LOG_JSON = false PERMANENT_SESSION_LIFETIME = 600 PE_NUMBER_CSV_URL = http://c95e1ebb198426ee57b8-174bb05a294821bedbf46b6384fe9b1f.r31.cf5.rackcdn.com/penumbers.csv PGAPPNAME = atst diff --git a/tests/utils.py b/tests/utils.py index 0615aec7..636f08b9 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -20,11 +20,14 @@ class FakeLogger: def __init__(self): self.messages = [] - def info(self, msg): + def log(self, _lvl, msg, *args, **kwargs): self.messages.append(msg) - def warning(self, msg): + def info(self, msg, *args, **kwargs): self.messages.append(msg) - def error(self, msg): + def warning(self, msg, *args, **kwargs): + self.messages.append(msg) + + def error(self, msg, *args, **kwargs): self.messages.append(msg) diff --git a/tests/utils/test_logging.py b/tests/utils/test_logging.py new file mode 100644 index 00000000..cb8198d3 --- /dev/null +++ b/tests/utils/test_logging.py @@ -0,0 +1,74 @@ +from io import StringIO +import json +import logging +from uuid import uuid4 + +import pytest + +from atst.utils.logging import JsonFormatter, RequestContextFilter + +from tests.factories import UserFactory + + +@pytest.fixture +def log_stream(): + return StringIO() + + +@pytest.fixture +def log_stream_content(log_stream): + def _log_stream_content(): + log_stream.seek(0) + return log_stream.read() + + return _log_stream_content + + +@pytest.fixture +def logger(log_stream): + logger = logging.getLogger() + for handler in logger.handlers: + logger.removeHandler(handler) + + logHandler = logging.StreamHandler(log_stream) + formatter = JsonFormatter() + logHandler.setFormatter(formatter) + logger.setLevel(logging.INFO) + logger.addFilter(RequestContextFilter()) + logger.addHandler(logHandler) + + return logger + + +def test_json_formatter(logger, log_stream_content): + logger.warning("do or do not", extra={"tags": ["wisdom", "jedi"]}) + + log = json.loads(log_stream_content()) + + assert log["tags"] == ["wisdom", "jedi"] + assert log["message"] == "do or do not" + assert log["severity"] == "WARNING" + assert log.get("details") is None + + +def test_json_formatter_for_exceptions(logger, log_stream_content): + try: + raise Exception() + except Exception: + logger.exception("you found the ventilation shaft!") + + log = json.loads(log_stream_content()) + assert log["severity"] == "ERROR" + assert log.get("details") + + +def test_request_context_filter(logger, log_stream_content, request_ctx): + user = UserFactory.create() + uuid = str(uuid4()) + + request_ctx.g.current_user = user + request_ctx.request.environ["HTTP_X_REQUEST_ID"] = uuid + logger.info("this user is doing something") + log = json.loads(log_stream_content()) + assert log["user_id"] == str(user.id) + assert log["request_id"] == uuid