From 747a59825a5e698e431c61f155413eb2cc08fef9 Mon Sep 17 00:00:00 2001 From: Montana Date: Wed, 3 Apr 2019 15:39:18 -0400 Subject: [PATCH 1/5] Use JSONLogger to log audit event information --- atst/models/audit_event.py | 13 +++++++++++++ atst/models/mixins/auditable.py | 21 +++++++++++++++++---- atst/utils/logging.py | 1 + 3 files changed, 31 insertions(+), 4 deletions(-) diff --git a/atst/models/audit_event.py b/atst/models/audit_event.py index 0e46b086..3a442f5b 100644 --- a/atst/models/audit_event.py +++ b/atst/models/audit_event.py @@ -25,6 +25,19 @@ class AuditEvent(Base, TimestampsMixin): display_name = Column(String()) action = Column(String(), nullable=False) + @property + def log(self): + return { + "user_id": str(self.id), + "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..140e4743 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 @@ -32,6 +32,7 @@ class AuditableMixin(object): ) audit_event.save(connection) + return audit_event @classmethod def __declare_last__(cls): @@ -42,17 +43,29 @@ class AuditableMixin(object): @staticmethod def audit_insert(mapper, connection, target): """Listen for the `after_insert` event and create an AuditLog entry""" - target.create_audit_event(connection, target, ACTION_CREATE) + event = target.create_audit_event(connection, target, ACTION_CREATE) + app.logger.info( + "Audit Event insert", + extra={"audit_event": event.log, "tags": ["audit_event", "insert"]}, + ) @staticmethod def audit_delete(mapper, connection, target): """Listen for the `after_delete` event and create an AuditLog entry""" - target.create_audit_event(connection, target, ACTION_DELETE) + event = target.create_audit_event(connection, target, ACTION_DELETE) + app.logger.info( + "Audit Event delete", + extra={"audit_event": event.log, "tags": ["audit_event", "delete"]}, + ) @staticmethod def audit_update(mapper, connection, target): if AuditableMixin.get_changes(target): - target.create_audit_event(connection, target, ACTION_UPDATE) + event = target.create_audit_event(connection, target, ACTION_UPDATE) + app.logger.info( + "Audit Event update", + extra={"audit_event": event.log, "tags": ["audit_event", "update"]}, + ) def get_changes(self): """ 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): From 86f106f6d1259fdd35291e30349e631dc93cdf1a Mon Sep 17 00:00:00 2001 From: Montana Date: Wed, 3 Apr 2019 17:07:33 -0400 Subject: [PATCH 2/5] Test logging events for auditable mixin --- tests/conftest.py | 11 ++++++ tests/domain/test_authz.py | 24 ++++-------- tests/models/mixins/test_auditable.py | 53 +++++++++++++++++++++++++++ tests/utils.py | 12 ++++-- 4 files changed, 80 insertions(+), 20 deletions(-) create mode 100644 tests/models/mixins/test_auditable.py 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..b1345059 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): @@ -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 "accessed" in mock_logger.messages[0] - assert "GET" in mock_logger.messages[0] + assert len(mock_logger.messages) == 2 + assert "accessed" in mock_logger.messages[1] + 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 "denied access" in mock_logger.messages[1] - assert "GET" in mock_logger.messages[1] + assert len(mock_logger.messages) == 3 + assert "denied access" in mock_logger.messages[2] + assert "GET" in mock_logger.messages[2] diff --git a/tests/models/mixins/test_auditable.py b/tests/models/mixins/test_auditable.py new file mode 100644 index 00000000..aadab029 --- /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_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"] 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"]) From a5848877aeb6c2d07556e81f29f7fb5263721840 Mon Sep 17 00:00:00 2001 From: Montana Date: Thu, 4 Apr 2019 08:33:07 -0400 Subject: [PATCH 3/5] No need to include user_id in audit event log --- atst/models/audit_event.py | 1 - 1 file changed, 1 deletion(-) diff --git a/atst/models/audit_event.py b/atst/models/audit_event.py index 3a442f5b..2d8d4ea1 100644 --- a/atst/models/audit_event.py +++ b/atst/models/audit_event.py @@ -28,7 +28,6 @@ class AuditEvent(Base, TimestampsMixin): @property def log(self): return { - "user_id": str(self.id), "portfolio_id": str(self.portfolio_id), "changed_state": self.changed_state, "event_details": self.event_details, From ea2338bc301786e118f9c3a99b87d6df37757c13 Mon Sep 17 00:00:00 2001 From: Montana Date: Thu, 4 Apr 2019 08:38:52 -0400 Subject: [PATCH 4/5] Make test more robust --- tests/domain/test_authz.py | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/tests/domain/test_authz.py b/tests/domain/test_authz.py index b1345059..2f450a82 100644 --- a/tests/domain/test_authz.py +++ b/tests/domain/test_authz.py @@ -182,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) == 2 - assert "accessed" in mock_logger.messages[1] - assert "GET" in mock_logger.messages[1] + 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) == 3 - assert "denied access" in mock_logger.messages[2] - assert "GET" in mock_logger.messages[2] + assert len(mock_logger.messages) == num_msgs + 1 + assert "denied access" in mock_logger.messages[-1] + assert "GET" in mock_logger.messages[-1] From 8057c7b2fc1f7abbbf7bbb053bd383005c238565 Mon Sep 17 00:00:00 2001 From: Montana Date: Thu, 4 Apr 2019 08:58:27 -0400 Subject: [PATCH 5/5] Log audit events before we save them to the DB --- atst/models/mixins/auditable.py | 22 +++++++--------------- tests/models/mixins/test_auditable.py | 14 +++++++------- 2 files changed, 14 insertions(+), 22 deletions(-) diff --git a/atst/models/mixins/auditable.py b/atst/models/mixins/auditable.py index 140e4743..d8133afe 100644 --- a/atst/models/mixins/auditable.py +++ b/atst/models/mixins/auditable.py @@ -31,6 +31,10 @@ 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 @@ -43,29 +47,17 @@ class AuditableMixin(object): @staticmethod def audit_insert(mapper, connection, target): """Listen for the `after_insert` event and create an AuditLog entry""" - event = target.create_audit_event(connection, target, ACTION_CREATE) - app.logger.info( - "Audit Event insert", - extra={"audit_event": event.log, "tags": ["audit_event", "insert"]}, - ) + target.create_audit_event(connection, target, ACTION_CREATE) @staticmethod def audit_delete(mapper, connection, target): """Listen for the `after_delete` event and create an AuditLog entry""" - event = target.create_audit_event(connection, target, ACTION_DELETE) - app.logger.info( - "Audit Event delete", - extra={"audit_event": event.log, "tags": ["audit_event", "delete"]}, - ) + target.create_audit_event(connection, target, ACTION_DELETE) @staticmethod def audit_update(mapper, connection, target): if AuditableMixin.get_changes(target): - event = target.create_audit_event(connection, target, ACTION_UPDATE) - app.logger.info( - "Audit Event update", - extra={"audit_event": event.log, "tags": ["audit_event", "update"]}, - ) + target.create_audit_event(connection, target, ACTION_UPDATE) def get_changes(self): """ diff --git a/tests/models/mixins/test_auditable.py b/tests/models/mixins/test_auditable.py index aadab029..a3e357a4 100644 --- a/tests/models/mixins/test_auditable.py +++ b/tests/models/mixins/test_auditable.py @@ -4,9 +4,9 @@ from atst.models.mixins.auditable import AuditableMixin from atst.domain.users import Users -def test_audit_insert(mock_logger): +def test_logging_audit_event_on_create(mock_logger): user = UserFactory.create() - assert "Audit Event insert" in mock_logger.messages + assert "Audit Event create" in mock_logger.messages assert len(mock_logger.messages) == 1 event_log = mock_logger.extras[0]["audit_event"] @@ -15,12 +15,12 @@ def test_audit_insert(mock_logger): assert event_log["display_name"] == user.full_name assert event_log["action"] == "create" - assert "insert" in mock_logger.extras[0]["tags"] + assert "create" in mock_logger.extras[0]["tags"] -def test_audit_delete(mock_logger): +def test_logging_audit_event_on_delete(mock_logger): user = UserFactory.create() - assert "Audit Event insert" in mock_logger.messages + assert "Audit Event create" in mock_logger.messages db.session.delete(user) db.session.commit() @@ -36,9 +36,9 @@ def test_audit_delete(mock_logger): assert "delete" in mock_logger.extras[1]["tags"] -def test_audit_insert(mock_logger): +def test_logging_audit_event_on_update(mock_logger): user = UserFactory.create() - assert "Audit Event insert" in mock_logger.messages + assert "Audit Event create" in mock_logger.messages Users.update(user, {"first_name": "Greedo"}) assert "Audit Event update" in mock_logger.messages