From bdb0c8bd08980e939da3736642066f4e91de57dc Mon Sep 17 00:00:00 2001 From: Carlos Quintana <74399022+cquintana92@users.noreply.github.com> Date: Mon, 14 Oct 2024 12:45:00 +0200 Subject: [PATCH] feat: alias audit log (#2261) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * feat: alias audit log * feat: crontab to delete old alias_audit_log entries * Unified messages --------- Co-authored-by: Adrià Casajús --- app/alias_audit_log_utils.py | 32 +++++++ app/alias_utils.py | 30 +++++- app/api/views/alias.py | 24 ++++- app/config.py | 2 + app/dashboard/views/alias_transfer.py | 7 ++ app/dashboard/views/index.py | 4 +- app/dashboard/views/unsubscribe.py | 4 +- app/handler/unsubscribe_handler.py | 4 +- app/models.py | 22 +++++ cron.py | 9 ++ crontab.yml | 7 ++ email_handler.py | 4 +- ...024_101113_91ed7f46dc81_alias_audit_log.py | 45 +++++++++ .../alias_partner_set_flag_and_clear_note.py | 10 +- tasks/clean_alias_audit_log.py | 12 +++ tests/events/test_sent_events.py | 2 +- tests/test_alias_audit_log_utils.py | 95 +++++++++++++++++++ 17 files changed, 300 insertions(+), 13 deletions(-) create mode 100644 app/alias_audit_log_utils.py create mode 100644 migrations/versions/2024_101113_91ed7f46dc81_alias_audit_log.py create mode 100644 tasks/clean_alias_audit_log.py create mode 100644 tests/test_alias_audit_log_utils.py diff --git a/app/alias_audit_log_utils.py b/app/alias_audit_log_utils.py new file mode 100644 index 00000000..e5897213 --- /dev/null +++ b/app/alias_audit_log_utils.py @@ -0,0 +1,32 @@ +from enum import Enum +from typing import Optional + +from app.models import Alias, AliasAuditLog + + +class AliasAuditLogAction(Enum): + CreateAlias = "create" + ChangeAliasStatus = "change_status" + DeleteAlias = "delete" + UpdateAlias = "update" + InitiateTransferAlias = "initiate_transfer_alias" + AcceptTransferAlias = "accept_transfer_alias" + TransferredAlias = "transferred_alias" + ChangedMailboxes = "changed_mailboxes" + + +def emit_alias_audit_log( + alias: Alias, + action: AliasAuditLogAction, + message: str, + user_id: Optional[int] = None, + commit: bool = False, +): + AliasAuditLog.create( + user_id=user_id or alias.user_id, + alias_id=alias.id, + alias_email=alias.email, + action=action.value, + message=message, + commit=commit, + ) diff --git a/app/alias_utils.py b/app/alias_utils.py index 47851f8b..8bd273d7 100644 --- a/app/alias_utils.py +++ b/app/alias_utils.py @@ -8,6 +8,7 @@ from email_validator import validate_email, EmailNotValidError from sqlalchemy.exc import IntegrityError, DataError from flask import make_response +from app.alias_audit_log_utils import AliasAuditLogAction, emit_alias_audit_log from app.config import ( BOUNCE_PREFIX_FOR_REPLY_PHASE, BOUNCE_PREFIX, @@ -368,6 +369,10 @@ def delete_alias( alias_id = alias.id alias_email = alias.email + + emit_alias_audit_log( + alias, AliasAuditLogAction.DeleteAlias, "Alias deleted by user action" + ) Alias.filter(Alias.id == alias.id).delete() Session.commit() @@ -450,7 +455,7 @@ def alias_export_csv(user, csv_direct_export=False): return output -def transfer_alias(alias, new_user, new_mailboxes: [Mailbox]): +def transfer_alias(alias: Alias, new_user: User, new_mailboxes: [Mailbox]): # cannot transfer alias which is used for receiving newsletter if User.get_by(newsletter_alias_id=alias.id): raise Exception("Cannot transfer alias that's used to receive newsletter") @@ -504,6 +509,12 @@ def transfer_alias(alias, new_user, new_mailboxes: [Mailbox]): alias.disable_pgp = False alias.pinned = False + emit_alias_audit_log( + alias=alias, + action=AliasAuditLogAction.TransferredAlias, + message=f"Lost ownership of alias due to alias transfer confirmed. New owner is {new_user.id}", + user_id=old_user.id, + ) EventDispatcher.send_event( old_user, EventContent( @@ -513,6 +524,13 @@ def transfer_alias(alias, new_user, new_mailboxes: [Mailbox]): ) ), ) + + emit_alias_audit_log( + alias=alias, + action=AliasAuditLogAction.AcceptTransferAlias, + message=f"Accepted alias transfer from user {old_user.id}", + user_id=new_user.id, + ) EventDispatcher.send_event( new_user, EventContent( @@ -529,7 +547,9 @@ def transfer_alias(alias, new_user, new_mailboxes: [Mailbox]): Session.commit() -def change_alias_status(alias: Alias, enabled: bool, commit: bool = False): +def change_alias_status( + alias: Alias, enabled: bool, message: Optional[str] = None, commit: bool = False +): LOG.i(f"Changing alias {alias} enabled to {enabled}") alias.enabled = enabled @@ -540,6 +560,12 @@ def change_alias_status(alias: Alias, enabled: bool, commit: bool = False): created_at=int(alias.created_at.timestamp), ) EventDispatcher.send_event(alias.user, EventContent(alias_status_change=event)) + audit_log_message = f"Set alias status to {enabled}" + if message is not None: + audit_log_message += f". {message}" + emit_alias_audit_log( + alias, AliasAuditLogAction.ChangeAliasStatus, audit_log_message + ) if commit: Session.commit() diff --git a/app/api/views/alias.py b/app/api/views/alias.py index fffe3434..572ef21b 100644 --- a/app/api/views/alias.py +++ b/app/api/views/alias.py @@ -4,6 +4,7 @@ from flask import jsonify from flask import request from app import alias_utils +from app.alias_audit_log_utils import emit_alias_audit_log, AliasAuditLogAction from app.api.base import api_bp, require_api_auth from app.api.serializer import ( AliasInfo, @@ -185,7 +186,11 @@ def toggle_alias(alias_id): if not alias or alias.user_id != user.id: return jsonify(error="Forbidden"), 403 - alias_utils.change_alias_status(alias, enabled=not alias.enabled) + alias_utils.change_alias_status( + alias, + enabled=not alias.enabled, + message=f"Set enabled={not alias.enabled} via API", + ) LOG.i(f"User {user} changed alias {alias} enabled status to {alias.enabled}") Session.commit() @@ -272,10 +277,12 @@ def update_alias(alias_id): if not alias or alias.user_id != user.id: return jsonify(error="Forbidden"), 403 + changed_fields = [] changed = False if "note" in data: new_note = data.get("note") alias.note = new_note + changed_fields.append("note") changed = True if "mailbox_id" in data: @@ -285,6 +292,7 @@ def update_alias(alias_id): return jsonify(error="Forbidden"), 400 alias.mailbox_id = mailbox_id + changed_fields.append(f"mailbox_id ({mailbox_id})") changed = True if "mailbox_ids" in data: @@ -314,6 +322,11 @@ def update_alias(alias_id): AliasMailbox.create(alias_id=alias.id, mailbox_id=mailbox.id) # <<< END update alias mailboxes >>> + mailbox_ids_string = ",".join(map(str, mailbox_ids)) + changed_fields.append(f"mailbox_ids ({mailbox_ids_string})") + emit_alias_audit_log( + alias, AliasAuditLogAction.ChangedMailboxes, message=mailbox_ids_string + ) changed = True if "name" in data: @@ -325,17 +338,26 @@ def update_alias(alias_id): if new_name: new_name = new_name.replace("\n", "") alias.name = new_name + changed_fields.append("name") changed = True if "disable_pgp" in data: alias.disable_pgp = data.get("disable_pgp") + changed_fields.append("disable_pgp") changed = True if "pinned" in data: alias.pinned = data.get("pinned") + changed_fields.append("pinned") changed = True if changed: + changed_fields_string = ",".join(changed_fields) + emit_alias_audit_log( + alias, + AliasAuditLogAction.UpdateAlias, + f"Alias fields updated ({changed_fields_string})", + ) Session.commit() return jsonify(ok=True), 200 diff --git a/app/config.py b/app/config.py index 0ad1d37e..2a021cf6 100644 --- a/app/config.py +++ b/app/config.py @@ -663,3 +663,5 @@ PARTNER_CUSTOM_DOMAIN_VALIDATION_PREFIXES: dict[int, str] = read_partner_dict( MAILBOX_VERIFICATION_OVERRIDE_CODE: Optional[str] = os.environ.get( "MAILBOX_VERIFICATION_OVERRIDE_CODE", None ) + +AUDIT_LOG_MAX_DAYS = int(os.environ.get("AUDIT_LOG_MAX_DAYS", 30)) diff --git a/app/dashboard/views/alias_transfer.py b/app/dashboard/views/alias_transfer.py index 8b2e7676..99670c35 100644 --- a/app/dashboard/views/alias_transfer.py +++ b/app/dashboard/views/alias_transfer.py @@ -7,6 +7,7 @@ from flask import render_template, redirect, url_for, flash, request from flask_login import login_required, current_user from app import config +from app.alias_audit_log_utils import emit_alias_audit_log, AliasAuditLogAction from app.alias_utils import transfer_alias from app.dashboard.base import dashboard_bp from app.dashboard.views.enter_sudo import sudo_required @@ -57,6 +58,12 @@ def alias_transfer_send_route(alias_id): transfer_token = f"{alias.id}.{secrets.token_urlsafe(32)}" alias.transfer_token = hmac_alias_transfer_token(transfer_token) alias.transfer_token_expiration = arrow.utcnow().shift(hours=24) + + emit_alias_audit_log( + alias, + AliasAuditLogAction.InitiateTransferAlias, + "Initiated alias transfer", + ) Session.commit() alias_transfer_url = ( config.URL diff --git a/app/dashboard/views/index.py b/app/dashboard/views/index.py index d48d7f38..26f2ab48 100644 --- a/app/dashboard/views/index.py +++ b/app/dashboard/views/index.py @@ -149,7 +149,9 @@ def index(): ) flash(f"Alias {email} has been deleted", "success") elif request.form.get("form-name") == "disable-alias": - alias_utils.change_alias_status(alias, enabled=False) + alias_utils.change_alias_status( + alias, enabled=False, message="Set enabled=False from dashboard" + ) Session.commit() flash(f"Alias {alias.email} has been disabled", "success") diff --git a/app/dashboard/views/unsubscribe.py b/app/dashboard/views/unsubscribe.py index 47286f1d..855c9607 100644 --- a/app/dashboard/views/unsubscribe.py +++ b/app/dashboard/views/unsubscribe.py @@ -32,7 +32,9 @@ def unsubscribe(alias_id): # automatic unsubscribe, according to https://tools.ietf.org/html/rfc8058 if request.method == "POST": - alias_utils.change_alias_status(alias, False) + alias_utils.change_alias_status( + alias, enabled=False, message="Set enabled=False from unsubscribe request" + ) flash(f"Alias {alias.email} has been blocked", "success") Session.commit() diff --git a/app/handler/unsubscribe_handler.py b/app/handler/unsubscribe_handler.py index 21faeb58..f41d9afb 100644 --- a/app/handler/unsubscribe_handler.py +++ b/app/handler/unsubscribe_handler.py @@ -103,7 +103,9 @@ class UnsubscribeHandler: ): return status.E509 LOG.i(f"User disabled alias {alias} via unsubscribe header") - alias_utils.change_alias_status(alias, enabled=False) + alias_utils.change_alias_status( + alias, enabled=False, message="Set enabled=False via unsubscribe header" + ) Session.commit() enable_alias_url = config.URL + f"/dashboard/?highlight_alias_id={alias.id}" for mailbox in alias.mailboxes: diff --git a/app/models.py b/app/models.py index 092c1060..6bd6be66 100644 --- a/app/models.py +++ b/app/models.py @@ -1673,6 +1673,7 @@ class Alias(Base, ModelMixin): Session.flush() # Internal import to avoid global import cycles + from app.alias_audit_log_utils import AliasAuditLogAction, emit_alias_audit_log from app.events.event_dispatcher import EventDispatcher from app.events.generated.event_pb2 import AliasCreated, EventContent @@ -1684,6 +1685,9 @@ class Alias(Base, ModelMixin): created_at=int(new_alias.created_at.timestamp), ) EventDispatcher.send_event(user, EventContent(alias_created=event)) + emit_alias_audit_log( + new_alias, AliasAuditLogAction.CreateAlias, "New alias created" + ) return new_alias @@ -3801,3 +3805,21 @@ class SyncEvent(Base, ModelMixin): .limit(100) .all() ) + + +class AliasAuditLog(Base, ModelMixin): + """This model holds an audit log for all the actions performed to an alias""" + + __tablename__ = "alias_audit_log" + + user_id = sa.Column(sa.Integer, nullable=False) + alias_id = sa.Column(sa.Integer, nullable=False) + alias_email = sa.Column(sa.String(255), nullable=False) + action = sa.Column(sa.String(255), nullable=False) + message = sa.Column(sa.Text, default=None, nullable=True) + + __table_args__ = ( + sa.Index("ix_alias_audit_log_user_id", "user_id"), + sa.Index("ix_alias_audit_log_alias_id", "alias_id"), + sa.Index("ix_alias_audit_log_alias_email", "alias_email"), + ) diff --git a/cron.py b/cron.py index f8bb09f4..5cd0cbbe 100644 --- a/cron.py +++ b/cron.py @@ -62,6 +62,7 @@ from app.pgp_utils import load_public_key_and_check, PGPException from app.proton.utils import get_proton_partner from app.utils import sanitize_email from server import create_light_app +from tasks.clean_alias_audit_log import cleanup_alias_audit_log from tasks.cleanup_old_imports import cleanup_old_imports from tasks.cleanup_old_jobs import cleanup_old_jobs from tasks.cleanup_old_notifications import cleanup_old_notifications @@ -1241,6 +1242,11 @@ def delete_old_data(): cleanup_old_notifications(oldest_valid) +def clear_alias_audit_log(): + oldest_valid = arrow.now().shift(days=-config.AUDIT_LOG_MAX_DAYS) + cleanup_alias_audit_log(oldest_valid) + + if __name__ == "__main__": LOG.d("Start running cronjob") parser = argparse.ArgumentParser() @@ -1314,3 +1320,6 @@ if __name__ == "__main__": elif args.job == "delete_scheduled_users": LOG.d("Deleting users scheduled to be deleted") clear_users_scheduled_to_be_deleted(dry_run=True) + elif args.job == "clear_alias_audit_log": + LOG.d("Clearing alias audit log") + clear_alias_audit_log() diff --git a/crontab.yml b/crontab.yml index e780ac80..08e773a8 100644 --- a/crontab.yml +++ b/crontab.yml @@ -80,3 +80,10 @@ jobs: schedule: "*/5 * * * *" captureStderr: true concurrencyPolicy: Forbid + + - name: SimpleLogin clear alias_audit_log old entries + command: python /code/cron.py -j clear_alias_audit_log + shell: /bin/bash + schedule: "0 * * * *" # Once every hour + captureStderr: true + concurrencyPolicy: Forbid diff --git a/email_handler.py b/email_handler.py index d44555b3..38fa8ab4 100644 --- a/email_handler.py +++ b/email_handler.py @@ -1502,7 +1502,9 @@ def handle_bounce_forward_phase(msg: Message, email_log: EmailLog): LOG.w( f"Disable alias {alias} because {reason}. {alias.mailboxes} {alias.user}. Last contact {contact}" ) - change_alias_status(alias, enabled=False) + change_alias_status( + alias, enabled=False, message=f"Set enabled=False due to {reason}" + ) Notification.create( user_id=user.id, diff --git a/migrations/versions/2024_101113_91ed7f46dc81_alias_audit_log.py b/migrations/versions/2024_101113_91ed7f46dc81_alias_audit_log.py new file mode 100644 index 00000000..11b448f0 --- /dev/null +++ b/migrations/versions/2024_101113_91ed7f46dc81_alias_audit_log.py @@ -0,0 +1,45 @@ +"""alias_audit_log + +Revision ID: 91ed7f46dc81 +Revises: 62afa3a10010 +Create Date: 2024-10-11 13:22:11.594054 + +""" +import sqlalchemy_utils +from alembic import op +import sqlalchemy as sa + + +# revision identifiers, used by Alembic. +revision = '91ed7f46dc81' +down_revision = '62afa3a10010' +branch_labels = None +depends_on = None + + +def upgrade(): + # ### commands auto generated by Alembic - please adjust! ### + op.create_table('alias_audit_log', + sa.Column('id', sa.Integer(), autoincrement=True, nullable=False), + sa.Column('created_at', sqlalchemy_utils.types.arrow.ArrowType(), nullable=False), + sa.Column('updated_at', sqlalchemy_utils.types.arrow.ArrowType(), nullable=True), + sa.Column('user_id', sa.Integer(), nullable=False), + sa.Column('alias_id', sa.Integer(), nullable=False), + sa.Column('alias_email', sa.String(length=255), nullable=False), + sa.Column('action', sa.String(length=255), nullable=False), + sa.Column('message', sa.Text(), nullable=True), + sa.PrimaryKeyConstraint('id') + ) + op.create_index('ix_alias_audit_log_alias_email', 'alias_audit_log', ['alias_email'], unique=False) + op.create_index('ix_alias_audit_log_alias_id', 'alias_audit_log', ['alias_id'], unique=False) + op.create_index('ix_alias_audit_log_user_id', 'alias_audit_log', ['user_id'], unique=False) + # ### end Alembic commands ### + + +def downgrade(): + # ### commands auto generated by Alembic - please adjust! ### + op.drop_index('ix_alias_audit_log_user_id', table_name='alias_audit_log') + op.drop_index('ix_alias_audit_log_alias_id', table_name='alias_audit_log') + op.drop_index('ix_alias_audit_log_alias_email', table_name='alias_audit_log') + op.drop_table('alias_audit_log') + # ### end Alembic commands ### diff --git a/oneshot/alias_partner_set_flag_and_clear_note.py b/oneshot/alias_partner_set_flag_and_clear_note.py index b2d60dbc..dc8c73d9 100644 --- a/oneshot/alias_partner_set_flag_and_clear_note.py +++ b/oneshot/alias_partner_set_flag_and_clear_note.py @@ -21,7 +21,7 @@ if max_alias_id == 0: max_alias_id = Session.query(func.max(Alias.id)).scalar() print(f"Checking alias {alias_id_start} to {max_alias_id}") -step = 1000 +step = 10000 noteSql = "(note = 'Created through Proton' or note = 'Created through partner Proton')" alias_query = f"UPDATE alias set note = NULL, flags = flags | :flag where id>=:start AND id<:end and {noteSql}" updated = 0 @@ -38,12 +38,12 @@ for batch_start in range(alias_id_start, max_alias_id, step): updated += rows_done.rowcount Session.commit() elapsed = time.time() - start_time - time_per_alias = elapsed / (updated + 1) last_batch_id = batch_start + step + time_per_alias = elapsed / (last_batch_id) remaining = max_alias_id - last_batch_id - time_remaining = (max_alias_id - last_batch_id) * time_per_alias - hours_remaining = time_remaining / 3600.0 + time_remaining = remaining / time_per_alias + hours_remaining = time_remaining / 60.0 print( - f"\rAlias {batch_start}/{max_alias_id} {updated} {hours_remaining:.2f}hrs remaining" + f"\rAlias {batch_start}/{max_alias_id} {updated} {hours_remaining:.2f} mins remaining" ) print("") diff --git a/tasks/clean_alias_audit_log.py b/tasks/clean_alias_audit_log.py new file mode 100644 index 00000000..c94f2f50 --- /dev/null +++ b/tasks/clean_alias_audit_log.py @@ -0,0 +1,12 @@ +import arrow + +from app.db import Session +from app.log import LOG +from app.models import AliasAuditLog + + +def cleanup_alias_audit_log(oldest_allowed: arrow.Arrow): + LOG.i(f"Deleting alias_audit_log older than {oldest_allowed}") + count = AliasAuditLog.filter(AliasAuditLog.created_at < oldest_allowed).delete() + Session.commit() + LOG.i(f"Deleted {count} alias_audit_log entries") diff --git a/tests/events/test_sent_events.py b/tests/events/test_sent_events.py index 910e3db1..805abdf9 100644 --- a/tests/events/test_sent_events.py +++ b/tests/events/test_sent_events.py @@ -79,7 +79,7 @@ def test_fire_event_on_alias_status_change(): alias = Alias.create_new_random(user) Session.flush() on_memory_dispatcher.clear() - alias_utils.change_alias_status(alias, True) + alias_utils.change_alias_status(alias, enabled=True) assert len(on_memory_dispatcher.memory) == 1 event_data = on_memory_dispatcher.memory[0] event_content = _get_event_from_string(event_data, user, pu) diff --git a/tests/test_alias_audit_log_utils.py b/tests/test_alias_audit_log_utils.py new file mode 100644 index 00000000..8bf708a7 --- /dev/null +++ b/tests/test_alias_audit_log_utils.py @@ -0,0 +1,95 @@ +import random + +from app.alias_audit_log_utils import emit_alias_audit_log, AliasAuditLogAction +from app.alias_utils import delete_alias, transfer_alias +from app.models import Alias, AliasAuditLog, AliasDeleteReason +from app.utils import random_string +from tests.utils import create_new_user, random_email + + +def test_emit_alias_audit_log_for_random_data(): + user = create_new_user() + alias = Alias.create( + user_id=user.id, + email=random_email(), + mailbox_id=user.default_mailbox_id, + ) + + random_user_id = random.randint(1000, 2000) + message = random_string() + action = AliasAuditLogAction.ChangeAliasStatus + emit_alias_audit_log( + alias=alias, + user_id=random_user_id, + action=action, + message=message, + commit=True, + ) + + logs_for_alias = AliasAuditLog.filter_by(alias_id=alias.id).all() + assert len(logs_for_alias) == 2 + + last_log = logs_for_alias[-1] + assert last_log.alias_id == alias.id + assert last_log.alias_email == alias.email + assert last_log.user_id == random_user_id + assert last_log.action == action.value + assert last_log.message == message + + +def test_emit_alias_audit_log_on_alias_creation(): + user = create_new_user() + alias = Alias.create( + user_id=user.id, + email=random_email(), + mailbox_id=user.default_mailbox_id, + ) + + log_for_alias = AliasAuditLog.filter_by(alias_id=alias.id).all() + assert len(log_for_alias) == 1 + assert log_for_alias[0].alias_id == alias.id + assert log_for_alias[0].alias_email == alias.email + assert log_for_alias[0].user_id == user.id + assert log_for_alias[0].action == AliasAuditLogAction.CreateAlias.value + + +def test_alias_audit_log_exists_after_alias_deletion(): + user = create_new_user() + alias = Alias.create( + user_id=user.id, + email=random_email(), + mailbox_id=user.default_mailbox_id, + ) + alias_id = alias.id + emit_alias_audit_log(alias, AliasAuditLogAction.UpdateAlias, "") + emit_alias_audit_log(alias, AliasAuditLogAction.UpdateAlias, "") + delete_alias(alias, user, AliasDeleteReason.ManualAction, commit=True) + + db_alias = Alias.get_by(id=alias_id) + assert db_alias is None + + logs_for_alias = AliasAuditLog.filter_by(alias_id=alias.id).all() + assert len(logs_for_alias) == 4 + assert logs_for_alias[0].action == AliasAuditLogAction.CreateAlias.value + assert logs_for_alias[1].action == AliasAuditLogAction.UpdateAlias.value + assert logs_for_alias[2].action == AliasAuditLogAction.UpdateAlias.value + assert logs_for_alias[3].action == AliasAuditLogAction.DeleteAlias.value + + +def test_alias_audit_log_for_transfer(): + original_user = create_new_user() + new_user = create_new_user() + alias = Alias.create( + user_id=original_user.id, + email=random_email(), + mailbox_id=original_user.default_mailbox_id, + ) + transfer_alias(alias, new_user, [new_user.default_mailbox]) + + logs_for_alias = AliasAuditLog.filter_by(alias_id=alias.id).all() + assert len(logs_for_alias) == 3 + assert logs_for_alias[0].action == AliasAuditLogAction.CreateAlias.value + assert logs_for_alias[1].action == AliasAuditLogAction.TransferredAlias.value + assert logs_for_alias[1].user_id == original_user.id + assert logs_for_alias[2].action == AliasAuditLogAction.AcceptTransferAlias.value + assert logs_for_alias[2].user_id == new_user.id