Test logging events for auditable mixin

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):
@@ -193,9 +183,9 @@ def test_user_can_access_decorator_logs_access(
         "atst.domain.authz.decorator.check_access", lambda *a, **k: True
     )
     _do_something()
-    assert len(mock_logger.messages) == 1
+    assert len(mock_logger.messages) == 2
-    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")
@@ -204,6 +194,6 @@ def test_user_can_access_decorator_logs_access(
     with pytest.raises(UnauthorizedError):
         _do_something()
 
-    assert len(mock_logger.messages) == 2
+    assert len(mock_logger.messages) == 3
-    assert "denied access" in mock_logger.messages[1]
+    assert "denied access" in mock_logger.messages[2]
-    assert "GET" in mock_logger.messages[1]
+    assert "GET" in mock_logger.messages[2]

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_audit_insert(mock_logger):
+    user = UserFactory.create()
+    assert "Audit Event insert" 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 "insert" in mock_logger.extras[0]["tags"]
+
+
+def test_audit_delete(mock_logger):
+    user = UserFactory.create()
+    assert "Audit Event insert" 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_audit_insert(mock_logger):
+    user = UserFactory.create()
+    assert "Audit Event insert" 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"])