ping-mee-self-service-platform/portal/tests/test_mailer.py

"""The outbox: queue, send, retry, rate limit and restart safety (AD-11)."""

import logging
from datetime import timedelta

import pytest
from django.core.management import call_command
from django.db import transaction
from django.utils import timezone

from portal.mailer import services
from portal.mailer.models import OutboxMail

pytestmark = pytest.mark.django_db(transaction=True)

Status = OutboxMail.Status


def queue(recipient="lena@example.test", n=1):
    return [services.enqueue("test", recipient) for _ in range(n)][-1]


# -- queueing -----------------------------------------


def test_enqueue_renders_the_mail_in_formal_german():
    mail = queue()
    assert mail.status == Status.QUEUED and mail.attempts == 0
    assert mail.subject == "Test-E-Mail vom Portal"
    assert "Wenn Sie sie lesen können" in mail.body_text


def test_the_language_of_the_request_does_not_change_the_mail():
    from django.utils import translation

    with translation.override("en"):
        assert queue().subject == "Test-E-Mail vom Portal"


@pytest.mark.parametrize(
    "address",
    ["", "nobody", "a@b", "a b@example.test", "a@example.test\r\nBcc: x@evil.test", "<a@b.test>"],
)
def test_an_unusable_address_is_refused_and_nothing_is_queued(address):
    with pytest.raises(ValueError, match="e-mail address"):
        services.enqueue("test", address)
    assert OutboxMail.objects.count() == 0


def test_a_rolled_back_change_queues_nothing():
    with pytest.raises(RuntimeError), transaction.atomic():
        queue()
        raise RuntimeError("the change failed")
    assert OutboxMail.objects.count() == 0


# -- sending -----------------------------------------


def test_flush_sends_a_queued_mail_and_removes_its_text(adapters):
    mail = queue()
    result = services.flush()
    mail.refresh_from_db()
    assert (result.sent, result.retried, result.failed) == (1, 0, 0)
    assert mail.status == Status.SENT and mail.sent_at and mail.attempts == 1
    assert mail.body_text == ""  # a one-time link must not stay in the database
    sent = adapters.mailer.sent[0]
    assert sent.recipient == "lena@example.test" and sent.sender == "Portal <portal@example.test>"
    assert "Test-E-Mail" in sent.subject and "Test-E-Mail" in sent.body_text


def test_a_mail_is_never_sent_twice(adapters):
    queue()
    services.flush()
    services.flush()
    services.flush(timezone.now() + timedelta(days=1))
    assert len(adapters.mailer.sent) == 1


def test_a_mail_that_is_not_due_yet_waits(adapters):
    mail = queue()
    later = timezone.now() + timedelta(hours=1)
    OutboxMail.objects.filter(pk=mail.pk).update(next_attempt_at=later)
    services.flush()
    assert adapters.mailer.sent == []


def test_mails_are_sent_in_the_order_they_were_queued(adapters):
    for name in ("a", "b", "c"):
        queue(f"{name}@example.test")
    services.flush()
    assert [m.recipient for m in adapters.mailer.sent] == [f"{n}@example.test" for n in "abc"]


# -- failures -----------------------------------------


def test_a_temporary_failure_is_retried_later_with_a_growing_wait(adapters):
    mail = queue()
    adapters.mailer.unavailable = True
    now = timezone.now()
    waits = []
    for attempt in range(1, 5):
        result = services.flush(now)
        mail.refresh_from_db()
        assert result.retried == 1 and mail.status == Status.QUEUED and mail.attempts == attempt
        assert mail.last_error
        waits.append(mail.next_attempt_at - now)
        now = mail.next_attempt_at
    assert waits == [timedelta(seconds=s) for s in services.BACKOFF_SECONDS]
    assert waits == sorted(waits)


def test_a_retry_before_the_wait_is_over_does_nothing(adapters):
    mail = queue()
    adapters.mailer.unavailable = True
    now = timezone.now()
    services.flush(now)
    attempts = adapters.mailer.attempts
    services.flush(now + timedelta(seconds=30))
    assert adapters.mailer.attempts == attempts
    mail.refresh_from_db()
    assert mail.attempts == 1


def test_a_mail_that_works_on_a_retry_is_sent(adapters):
    mail = queue()
    adapters.mailer.unavailable = True
    now = timezone.now()
    services.flush(now)
    adapters.mailer.unavailable = False
    mail.refresh_from_db()
    result = services.flush(mail.next_attempt_at)
    mail.refresh_from_db()
    assert result.sent == 1 and mail.status == Status.SENT and mail.attempts == 2


def test_after_the_last_attempt_the_mail_is_failed_and_kept_for_the_admin(adapters):
    mail = queue()
    adapters.mailer.unavailable = True
    now = timezone.now()
    for _ in range(services.MAX_ATTEMPTS):
        services.flush(now)
        mail.refresh_from_db()
        now = mail.next_attempt_at
    assert mail.status == Status.FAILED and mail.attempts == services.MAX_ATTEMPTS
    assert mail.recipient == "lena@example.test" and mail.last_error and mail.body_text == ""
    attempts = adapters.mailer.attempts
    services.flush(now + timedelta(days=1))
    assert adapters.mailer.attempts == attempts  # no further tries


def test_a_permanent_refusal_fails_at_once_without_retries(adapters):
    mail = queue("gone@example.test")
    adapters.mailer.rejected.add("gone@example.test")
    result = services.flush()
    mail.refresh_from_db()
    assert result.failed == 1 and mail.status == Status.FAILED and mail.attempts == 1
    assert "550" in mail.last_error


def test_one_refused_mail_does_not_block_the_others(adapters):
    queue("gone@example.test")
    queue("lena@example.test")
    adapters.mailer.rejected.add("gone@example.test")
    result = services.flush()
    assert (result.sent, result.failed) == (1, 1)


def test_a_dead_server_is_not_tried_for_every_mail_in_the_queue(adapters):
    for i in range(10):
        queue(f"u{i}@example.test")
    adapters.mailer.unavailable = True
    services.flush()
    assert adapters.mailer.attempts == services.STOP_AFTER_CONSECUTIVE_OUTAGES


# -- rate limit -----------------------------------------


def test_no_more_than_the_rate_limit_is_sent_per_minute(adapters):
    for i in range(services.RATE_PER_MINUTE + 5):
        queue(f"u{i}@example.test")
    now = timezone.now()
    assert services.flush(now).sent == services.RATE_PER_MINUTE
    assert services.flush(now + timedelta(seconds=30)).sent == 0
    assert services.flush(now + timedelta(seconds=61)).sent == 5
    assert len(adapters.mailer.sent) == services.RATE_PER_MINUTE + 5


# -- restarts -----------------------------------------


def test_a_mail_cut_off_while_sending_is_given_up_not_sent_again(adapters):
    mail = queue()
    now = timezone.now()
    OutboxMail.objects.filter(pk=mail.pk).update(
        status=Status.SENDING, claimed_at=now - timedelta(seconds=services.LEASE_SECONDS + 1)
    )
    result = services.flush(now)
    mail.refresh_from_db()
    assert mail.status == Status.FAILED and "unknown" in mail.last_error
    assert result.sent == 0 and adapters.mailer.sent == []


def test_a_mail_being_sent_right_now_is_left_alone(adapters):
    mail = queue()
    now = timezone.now()
    OutboxMail.objects.filter(pk=mail.pk).update(status=Status.SENDING, claimed_at=now)
    services.flush(now)
    mail.refresh_from_db()
    assert mail.status == Status.SENDING and adapters.mailer.sent == []


def test_a_row_taken_by_another_run_is_skipped(adapters, monkeypatch):
    mail = queue()
    real = OutboxMail.objects.filter

    def take_first(*args, **kwargs):
        # The moment the claim is attempted, another run has already taken the row.
        if kwargs.get("pk") == mail.pk:
            real(pk=mail.pk).update(status=Status.SENDING)
        return real(*args, **kwargs)

    monkeypatch.setattr(OutboxMail.objects, "filter", take_first)
    assert services.flush().sent == 0
    assert adapters.mailer.sent == []


# -- privacy -----------------------------------------


def test_logs_name_the_row_but_not_the_recipient_or_text(adapters, caplog):
    queue("secret.person@example.test")
    adapters.mailer.unavailable = True
    with caplog.at_level(logging.DEBUG):
        services.flush()
    assert "not sent" in caplog.text
    assert "secret.person" not in caplog.text and "Test-E-Mail" not in caplog.text


# -- the test command -----------------------------------------


def test_the_test_command_sends_a_mail_now(adapters, capsys):
    call_command("send_test_mail", "lena@example.test")
    assert "sent" in capsys.readouterr().out
    assert [m.recipient for m in adapters.mailer.sent] == ["lena@example.test"]


def test_the_test_command_reports_a_failure(adapters, capsys):
    adapters.mailer.unavailable = True
    with pytest.raises(SystemExit) as stop:
        call_command("send_test_mail", "lena@example.test")
    assert stop.value.code == 1
    assert "retried" in capsys.readouterr().out


def test_the_test_command_refuses_a_bad_address(adapters):
    from django.core.management.base import CommandError

    with pytest.raises(CommandError):
        call_command("send_test_mail", "not-an-address")