Merge pull request #732 from dod-ccpo/json-logging

ATST Json logging

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"]},
+        }
+    )

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:

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)

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):

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)

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

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)

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