ccvpn/lambdainst/tasks.py

import logging
import itertools
import time
from datetime import timedelta, datetime
from celery import task
from django.db.models import Q, F
from django.db import transaction
from django.conf import settings
from django.utils import timezone
from django.template.loader import get_template
from django.core.mail import send_mass_mail, send_mail
from constance import config as site_config
import django_lcore
import lcoreapi

from ccvpn.common import parse_integer_list
from lambdainst.models import User, VPNUser

ROOT_URL = settings.ROOT_URL
SITE_NAME = settings.TICKETS_SITE_NAME

logger = logging.getLogger(__name__)


@task(autoretry_for=(Exception,), default_retry_delay=60 * 60)
def push_all_users():
    count = 0
    for u in User.objects.all():
        # skip 'empty' accounts
        if u.vpnuser.expiration is None:
            continue

        logger.debug("pushing user #%d %r", user.id, user)

        django_lcore.sync_user(u.vpnuser, fail_silently=False)
        count += 1
    logger.info("pushed %d users", count)


@task(autoretry_for=(Exception,), max_retries=10, retry_backoff=True)
def push_user(user_id):
    user = User.objects.get(id=user_id)
    logger.info("pushing user #%d %r", user.id, user)
    django_lcore.sync_user(user.vpnuser, fail_silently=False)


@task
def notify_vpn_auth_fails():
    """
    due to the high number of regular authentication fails, we'll start sending
    a periodic reminder to accounts with high rates.
    it could be a misconfigured client or a payment failure

    3 years, >0 payments:  7 marked,  883 skipped
    6 years, >0 payments: 11 marked, 1582 skipped
    3 years, incl 0 paym:  9 marked, 3590 skipped
    6 years, incl 0 paym: 14 marked, 6313 skipped [12m25s]
    """

    logger.info("searching for recent openvpn auth failures")

    api = django_lcore.api
    from_email = settings.DEFAULT_FROM_EMAIL
    FETCH_EVENTS_PER_USER = 90
    MIN_EXP = timezone.now() - timedelta(days=6 * 365)
    MIN_EVENTS = 5  # that threshold is automatically negative
    MAX_FAILS = 15  # that threshold is automatically positive
    MIN_DT_SINCE_LAST = timedelta(days=1)
    NOTIFY_EVERY = timedelta(days=180)  # users notified recently should be ignored

    def find_fails_for_user(u):
        """ returns true if there are 'many' recent fails """
        path = api.info["current_instance"] + "/users/" + u.username + "/auth-events/"
        try:
            r = api.get(path)
        except lcoreapi.APINotFoundError:
            return False
        assert r["object"] == "list", repr(r)
        items = list(itertools.islice(r.list_iter(), FETCH_EVENTS_PER_USER))

        # split the dataset, errors are ignored
        fails = [i for i in items if i["auth_status"] == "fail"]
        ok = [i for i in items if i["auth_status"] == "ok"]

        # do we have enough failures
        if len(fails) == 0:
            return False
        if len(fails) < MIN_EVENTS:
            logger.debug(
                f"#{u.id} '{u.username}': too few fails ({len(fails)} < {MIN_EVENTS})"
            )
            return False

        # are they recent
        dates = [e["event_date"] for e in fails]
        first = min(dates)
        last = max(dates)
        dt_fails = last - first
        dt_last_fail = datetime.utcnow() - last
        if dt_last_fail > MIN_DT_SINCE_LAST:
            logger.debug(
                f"#{u.id} '{u.username}': no recent enough failure ({dt_last_fail} ago > {MIN_DT_SINCE_LAST} ago)"
            )
            return False

        # ~ end of checks. now we filter positive matches ~

        # do we have only fails in the recent events?
        if len(fails) > MAX_FAILS and len(ok) == 0:
            logger.info(f"#{u.id} '{u.username}': {len(fails)} fails and 0 ok")
            return True

        # do we have many fails per hour?
        fails_per_hour = len(fails) / (dt_fails.total_seconds() / 3600.0)
        if fails_per_hour > 1:
            logger.info(
                f"#{u.id} '{u.username}': fail/hour is high ({fails_per_hour:.2f} > 1)"
            )
            return True

        # otherwise there are some of both. let's check the ratio
        fail_ratio = len(fails) / len(ok)
        if fail_ratio > 1:  # more fails than oks
            logger.info(
                f"#{u.id} '{u.username}': fail ratio is high ({fail_ratio:.2f} > 1)"
            )
            return True
        else:
            logger.debug(
                f"#{u.id} '{u.username}': fail ratio is low ({fail_ratio:.2f} < 1)"
            )
            return False

    def notify_user(user):
        if user.vpnuser.notify_vpn_auth_fail is not True:
            logger.warning("this user should not be sent a notice")
            return

        ctx = dict(user=user, url=ROOT_URL)
        text = get_template("lambdainst/mail_vpn_auth_fails.txt").render(ctx)
        send_mail("CCrypto VPN Authentication Errors", text, from_email, [user.email])
        logger.debug("sending vpn auth fails notify to %s", user.email)

        user.vpnuser.last_vpn_auth_fail_notice = timezone.now()
        user.vpnuser.save()

    def examine_users():
        skipped = 0
        marked = 0

        users = User.objects
        # skip accounts that opt out of this
        users = users.exclude(vpnuser__notify_vpn_auth_fail=False)
        # skip accounts with no email address
        users = users.exclude(email__exact="")
        # skip accounts where exp was never set
        users = users.exclude(vpnuser__expiration=None)
        # skip accounts that expired a long time ago
        users = users.exclude(vpnuser__expiration__lt=MIN_EXP)
        # skip accounts that already received a notice recently
        users = users.exclude(
            vpnuser__last_vpn_auth_fail_notice__gt=timezone.now() - NOTIFY_EVERY
        )
        # require at least one payment
        # users = users.filter(payment__status='confirmed').annotate(Count('payment')).filter(payment__count__gt=0)

        users = users.order_by("id")

        for u in users:
            if find_fails_for_user(u):
                notify_user(u)
                marked += 1
            else:
                skipped += 1
            time.sleep(0.100)

        logger.debug("auth fails: notified %d, reviewed %d", marked, skipped)

    examine_users()


@task
def notify_account_expiration():
    """ Notify users near the end of their subscription """
    from_email = settings.DEFAULT_FROM_EMAIL

    for v in parse_integer_list(site_config.NOTIFY_DAYS_BEFORE):
        emails = []
        users = list(get_next_expirations(v))
        logger.info("sending -%d day notification to %d users", v, len(users))

        with transaction.atomic():
            for u in users:
                # Ignore users with active subscriptions
                # They will get notified only if it gets cancelled (payments
                # processors will cancel after a few failed payments)
                if u.get_subscription():
                    continue

                ctx = dict(
                    site_name=SITE_NAME, user=u.user, exp=u.expiration, url=ROOT_URL
                )
                text = get_template("lambdainst/mail_expire_soon.txt").render(ctx)
                emails.append(
                    ("CCrypto VPN Expiration", text, from_email, [u.user.email])
                )
                logger.debug("sending -%d days notify to %s" % (v, u.user.email))

                u.last_expiry_notice = timezone.now()
                u.save()

            send_mass_mail(emails)


def get_next_expirations(days=3):
    """ Gets users whose subscription will expire in some days """

    limit_date = timezone.now() + timedelta(days=days)

    users = VPNUser.objects.exclude(user__email__exact="")

    users = users.filter(expiration__gt=timezone.now())  # Not expired
    users = users.filter(expiration__lt=limit_date)  # Expire in a few days

    # Make sure we dont send the notice twice
    users = users.filter(
        Q(last_expiry_notice__isnull=True)
        | Q(expiration__gt=F("last_expiry_notice") + timedelta(days=days))
    )
    return users