feat: alias audit log (#2261)

* feat: alias audit log

* feat: crontab to delete old alias_audit_log entries

* Unified messages

---------

Co-authored-by: Adrià Casajús <adria.casajus@proton.ch>

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,
+    )

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()

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

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))

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

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")
 

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()
 

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:

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"),
+    )

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()

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

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,

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 ###

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("")

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")

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)

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