diff --git a/atst/models/audit_event.py b/atst/models/audit_event.py index 0e46b086..2d8d4ea1 100644 --- a/atst/models/audit_event.py +++ b/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 diff --git a/atst/models/mixins/auditable.py b/atst/models/mixins/auditable.py index 86ada487..d8133afe 100644 --- a/atst/models/mixins/auditable.py +++ b/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): diff --git a/atst/utils/logging.py b/atst/utils/logging.py index 1ef84d0a..5cc8e90d 100644 --- a/atst/utils/logging.py +++ b/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): diff --git a/tests/conftest.py b/tests/conftest.py index 01683898..6faaf715 100644 --- a/tests/conftest.py +++ b/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 diff --git a/tests/domain/test_authz.py b/tests/domain/test_authz.py index bfebe562..2f450a82 100644 --- a/tests/domain/test_authz.py +++ b/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 "accessed" in mock_logger.messages[0] - assert "GET" in mock_logger.messages[0] + assert len(mock_logger.messages) == num_msgs + 1 + assert "accessed" in mock_logger.messages[-1] + 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 "denied access" in mock_logger.messages[1] - assert "GET" in mock_logger.messages[1] + assert len(mock_logger.messages) == num_msgs + 1 + assert "denied access" in mock_logger.messages[-1] + assert "GET" in mock_logger.messages[-1] diff --git a/tests/models/mixins/test_auditable.py b/tests/models/mixins/test_auditable.py new file mode 100644 index 00000000..a3e357a4 --- /dev/null +++ b/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"] diff --git a/tests/utils.py b/tests/utils.py index 636f08b9..a8d7522a 100644 --- a/tests/utils.py +++ b/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"])