Merge pull request #743 from dod-ccpo/audit-event-logging

Emit plaintext logging for audit trail

atst/models/audit_event.py

@@ -25,6 +25,18 @@ class AuditEvent(Base, TimestampsMixin):
     display_name = Column(String())
     action = Column(String(), nullable=False)
 
+    @property
+    def log(self):
+        return {
+            "portfolio_id": str(self.portfolio_id),
+            "changed_state": self.changed_state,
+            "event_details": self.event_details,
+            "resource_type": self.resource_type,
+            "resource_id": str(self.resource_id),
+            "display_name": self.display_name,
+            "action": self.action,
+        }
+
     def save(self, connection):
         attrs = inspect(self).dict
 

atst/models/mixins/auditable.py

@@ -1,5 +1,5 @@
 from sqlalchemy import event, inspect
-from flask import g
+from flask import g, current_app as app
 
 from atst.models.audit_event import AuditEvent
 from atst.utils import camel_to_snake, getattr_path
@@ -31,7 +31,12 @@ class AuditableMixin(object):
             event_details=event_details,
         )
 
+        app.logger.info(
+            "Audit Event {}".format(action),
+            extra={"audit_event": audit_event.log, "tags": ["audit_event", action]},
+        )
         audit_event.save(connection)
+        return audit_event
 
     @classmethod
     def __declare_last__(cls):

atst/utils/logging.py

@@ -31,6 +31,7 @@ class JsonFormatter(logging.Formatter):
         ("severity", lambda r: r.levelname),
         ("tags", lambda r: r.__dict__.get("tags")),
         ("message", lambda r: r.msg),
+        ("audit_event", lambda r: r.__dict__.get("audit_event")),
     ]
 
     def format(self, record):

tests/conftest.py

@@ -12,6 +12,7 @@ from atst.database import db as _db
 from atst.queue import queue as atst_queue
 import tests.factories as factories
 from tests.mocks import PDF_FILENAME, PDF_FILENAME2
+from tests.utils import FakeLogger
 
 from datetime import datetime, timezone, timedelta
 from cryptography.hazmat.primitives.asymmetric import rsa
@@ -296,3 +297,13 @@ def crl_file(make_crl, ca_key, tmpdir, serialize_pki_object_to_disk):
     serialize_pki_object_to_disk(crl, crl_out, encoding=Encoding.DER)
 
     return crl_out
+
+
+@pytest.fixture
+def mock_logger(app):
+    real_logger = app.logger
+    app.logger = FakeLogger()
+
+    yield app.logger
+
+    app.logger = real_logger

tests/domain/test_authz.py

@@ -168,20 +168,10 @@ def test_user_can_access_decorator_override(set_current_user):
         assert _cloud_city()
 
 
-@pytest.fixture
-def mock_logger(app):
-    real_logger = app.logger
-    app.logger = FakeLogger()
-
-    yield app.logger
-
-    app.logger = real_logger
-
-
 def test_user_can_access_decorator_logs_access(
     set_current_user, monkeypatch, mock_logger
 ):
-    user = UserFactory.create()
+    user = UserFactory.create()  # this emits an 'Audit Event insert' event
 
     @user_can_access_decorator(Permissions.EDIT_PORTFOLIO_NAME)
     def _do_something(*args, **kwargs):
@@ -192,18 +182,20 @@ def test_user_can_access_decorator_logs_access(
     monkeypatch.setattr(
         "atst.domain.authz.decorator.check_access", lambda *a, **k: True
     )
+    num_msgs = len(mock_logger.messages)
     _do_something()
-    assert len(mock_logger.messages) == 1
+    assert len(mock_logger.messages) == num_msgs + 1
-    assert "accessed" in mock_logger.messages[0]
+    assert "accessed" in mock_logger.messages[-1]
-    assert "GET" in mock_logger.messages[0]
+    assert "GET" in mock_logger.messages[-1]
 
     def _unauthorized(*a, **k):
         raise UnauthorizedError(user, "do something")
 
     monkeypatch.setattr("atst.domain.authz.decorator.check_access", _unauthorized)
+    num_msgs = len(mock_logger.messages)
     with pytest.raises(UnauthorizedError):
         _do_something()
 
-    assert len(mock_logger.messages) == 2
+    assert len(mock_logger.messages) == num_msgs + 1
-    assert "denied access" in mock_logger.messages[1]
+    assert "denied access" in mock_logger.messages[-1]
-    assert "GET" in mock_logger.messages[1]
+    assert "GET" in mock_logger.messages[-1]

tests/models/mixins/test_auditable.py

@@ -0,0 +1,53 @@
+from atst.database import db
+from tests.factories import UserFactory
+from atst.models.mixins.auditable import AuditableMixin
+from atst.domain.users import Users
+
+
+def test_logging_audit_event_on_create(mock_logger):
+    user = UserFactory.create()
+    assert "Audit Event create" in mock_logger.messages
+    assert len(mock_logger.messages) == 1
+
+    event_log = mock_logger.extras[0]["audit_event"]
+    assert event_log["resource_type"] == "user"
+    assert event_log["resource_id"] == str(user.id)
+    assert event_log["display_name"] == user.full_name
+    assert event_log["action"] == "create"
+
+    assert "create" in mock_logger.extras[0]["tags"]
+
+
+def test_logging_audit_event_on_delete(mock_logger):
+    user = UserFactory.create()
+    assert "Audit Event create" in mock_logger.messages
+
+    db.session.delete(user)
+    db.session.commit()
+    assert "Audit Event delete" in mock_logger.messages
+    assert len(mock_logger.messages) == 2
+
+    event_log = mock_logger.extras[1]["audit_event"]
+    assert event_log["resource_type"] == "user"
+    assert event_log["resource_id"] == str(user.id)
+    assert event_log["display_name"] == user.full_name
+    assert event_log["action"] == "delete"
+
+    assert "delete" in mock_logger.extras[1]["tags"]
+
+
+def test_logging_audit_event_on_update(mock_logger):
+    user = UserFactory.create()
+    assert "Audit Event create" in mock_logger.messages
+
+    Users.update(user, {"first_name": "Greedo"})
+    assert "Audit Event update" in mock_logger.messages
+    assert len(mock_logger.messages) == 2
+
+    event_log = mock_logger.extras[1]["audit_event"]
+    assert event_log["resource_type"] == "user"
+    assert event_log["resource_id"] == str(user.id)
+    assert event_log["display_name"] == user.full_name
+    assert event_log["action"] == "update"
+
+    assert "update" in mock_logger.extras[1]["tags"]

tests/utils.py

@@ -19,15 +19,21 @@ def captured_templates(app):
 class FakeLogger:
     def __init__(self):
         self.messages = []
+        self.extras = []
 
     def log(self, _lvl, msg, *args, **kwargs):
-        self.messages.append(msg)
+        self._log(_lvl, msg, *args, **kwargs)
 
     def info(self, msg, *args, **kwargs):
-        self.messages.append(msg)
+        self._log("info", msg, *args, **kwargs)
 
     def warning(self, msg, *args, **kwargs):
-        self.messages.append(msg)
+        self._log("warning", msg, *args, **kwargs)
 
     def error(self, msg, *args, **kwargs):
+        self._log("error", msg, *args, **kwargs)
+
+    def _log(self, _lvl, msg, *args, **kwargs):
         self.messages.append(msg)
+        if "extra" in kwargs:
+            self.extras.append(kwargs["extra"])