add vpn auth fails notification

ccvpn/celery.py

@@ -34,6 +34,10 @@ app.conf.beat_schedule = {
         'task': 'lambdainst.tasks.notify_account_expiration',
         'schedule': timedelta(hours=6),
     },
+    'lambdainst__notify_vpn_auth_fails': {
+        'task': 'lambdainst.tasks.notify_vpn_auth_fails',
+        'schedule': timedelta(days=30),
+    },
 }
 
 # Load task modules from all registered Django app configs.

lambdainst/admin.py

@@ -35,6 +35,7 @@ class VPNUserInline(admin.StackedInline):
     fk_name = 'user'
 
     fields = ('notes', 'expiration', 'last_expiry_notice', 'notify_expiration',
+              'last_vpn_auth_fail_notice', 'notify_vpn_auth_fail',
               'trial_periods_given', 'referrer_a', 'campaign', 'last_vpn_auth', 'last_core_sync')
     readonly_fields = ('referrer_a', 'last_vpn_auth', 'last_core_sync', 'campaign')
 

lambdainst/migrations/0004_auto_20200829_2054.py

@@ -0,0 +1,23 @@
+# Generated by Django 3.1 on 2020-08-29 20:54
+
+from django.db import migrations, models
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ('lambdainst', '0003_vpnuser_last_core_sync'),
+    ]
+
+    operations = [
+        migrations.AddField(
+            model_name='vpnuser',
+            name='last_vpn_auth_fail_notice',
+            field=models.DateTimeField(blank=True, null=True),
+        ),
+        migrations.AddField(
+            model_name='vpnuser',
+            name='notify_vpn_auth_fail',
+            field=models.BooleanField(default=True),
+        ),
+    ]

lambdainst/models.py

@@ -29,7 +29,9 @@ class VPNUser(models.Model, LcoreUserProfileMethods):
 
     expiration = models.DateTimeField(blank=True, null=True)
     last_expiry_notice = models.DateTimeField(blank=True, null=True)
+    last_vpn_auth_fail_notice = models.DateTimeField(blank=True, null=True)
     notify_expiration = models.BooleanField(default=True)
+    notify_vpn_auth_fail = models.BooleanField(default=True)
 
     trial_periods_given = models.IntegerField(default=0)
 

lambdainst/tasks.py

@@ -1,14 +1,17 @@
 import logging
-from datetime import timedelta
+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
+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
@@ -19,7 +22,7 @@ SITE_NAME = settings.TICKETS_SITE_NAME
 logger = logging.getLogger(__name__)
 
 
-@task(autoretry_for=(Exception,), default_retry_delay=60*60)
+@task(autoretry_for=(Exception,), default_retry_delay=60 * 60)
 def push_all_users():
     for u in User.objects.all():
         # skip 'empty' accounts
@@ -38,6 +41,142 @@ def push_user(user_id):
     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):
+        return True
+        """ 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 """
@@ -46,7 +185,7 @@ def notify_account_expiration():
     for v in parse_integer_list(site_config.NOTIFY_DAYS_BEFORE):
         emails = []
         users = list(get_next_expirations(v))
-        logging.info("sending -%d day notification to %d users", v, len(users))
+        logger.info("sending -%d day notification to %d users", v, len(users))
 
         with transaction.atomic():
             for u in users:
@@ -56,11 +195,14 @@ def notify_account_expiration():
                 if u.get_subscription():
                     continue
 
-                ctx = dict(site_name=SITE_NAME, user=u.user,
+                ctx = dict(
-                            exp=u.expiration, url=ROOT_URL)
+                    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]))
+                text = get_template("lambdainst/mail_expire_soon.txt").render(ctx)
-                logging.debug("sending -%d days notify to %s" % (v, u.user.email))
+                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()
@@ -73,14 +215,14 @@ def get_next_expirations(days=3):
 
     limit_date = timezone.now() + timedelta(days=days)
 
-    users = VPNUser.objects.exclude(user__email__exact='')
+    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)
+    users = users.filter(
-                         | Q(expiration__gt=F('last_expiry_notice')
+        Q(last_expiry_notice__isnull=True)
-                             + timedelta(days=days)))
+        | Q(expiration__gt=F("last_expiry_notice") + timedelta(days=days))
+    )
     return users
-

templates/lambdainst/mail_expire_soon.txt

@@ -1,5 +1,5 @@
-{% load i18n %}{{ site_name }}
+{% load i18n %}CCrypto VPN
-========================================
+====================
 
 {% blocktrans with exp=exp|timeuntil %}Your account will expire in {{exp}}{% endblocktrans %}
 {% trans 'You can renew it here:' %}

templates/lambdainst/mail_vpn_auth_fails.txt

@@ -0,0 +1,11 @@
+{% load i18n %}CCrypto VPN
+====================
+
+{% blocktrans with name=user.username %}Your account {{name}} has received many VPN authentication failures recently.{% endblocktrans %}
+
+{% blocktrans trimmed %}You may have a misconfigured client currently failing to connect.
+Please make sure they use the correct password and settings and that your account is kept funded,
+or the device will not be protected by the VPN.
+{% endblocktrans %}
+
+{{ url }}