Log IP address for each Version creation (#16695)

* Log IP address for each Version creation

* Prevent using FileUpload with no user/ip_address/source (might break more tests)

* Test nit: use variable

src/olympia/activity/migrations/0008_iplog.py

@@ -0,0 +1,31 @@
+# Generated by Django 2.2.18 on 2021-03-08 13:55
+
+from django.db import migrations, models
+import django.db.models.deletion
+import django.utils.timezone
+import olympia.amo.models
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ('activity', '0007_auto_20210114_1347'),
+    ]
+
+    operations = [
+        migrations.CreateModel(
+            name='IPLog',
+            fields=[
+                ('id', models.AutoField(auto_created=True, primary_key=True, serialize=False, verbose_name='ID')),
+                ('created', models.DateTimeField(blank=True, default=django.utils.timezone.now, editable=False)),
+                ('modified', models.DateTimeField(auto_now=True)),
+                ('ip_address', models.CharField(max_length=45)),
+                ('activity_log', models.ForeignKey(on_delete=django.db.models.deletion.CASCADE, to='activity.ActivityLog')),
+            ],
+            options={
+                'db_table': 'log_activity_ip',
+                'ordering': ('-created',),
+            },
+            bases=(olympia.amo.models.SearchMixin, olympia.amo.models.SaveUpdateMixin, models.Model),
+        ),
+    ]

src/olympia/activity/models.py

@@ -193,6 +193,20 @@ class BlockLog(ModelBase):
         ordering = ('-created',)
 
 
+class IPLog(ModelBase):
+    """
+    This table is for indexing the activity log by IP (only for specific
+    actions).
+    """
+
+    activity_log = models.ForeignKey('ActivityLog', on_delete=models.CASCADE)
+    ip_address = models.CharField(max_length=45)
+
+    class Meta:
+        db_table = 'log_activity_ip'
+        ordering = ('-created',)
+
+
 class DraftComment(ModelBase):
     """A model that allows us to draft comments for reviews before we have
     an ActivityLog instance ready.
@@ -698,6 +712,16 @@ class ActivityLog(ModelBase):
                     created=kw.get('created', timezone.now()),
                 )
 
+        if getattr(action, 'store_ip', False):
+            # Index specific actions by their IP address. Note that the caller
+            # must take care of overriding remote addr if the action is created
+            # from a task.
+            IPLog.objects.create(
+                ip_address=core.get_remote_addr(),
+                activity_log=al,
+                created=kw.get('created', timezone.now()),
+            )
+
         # Index by every user
         UserLog.objects.create(
             activity_log=al, user=user, created=kw.get('created', timezone.now())

src/olympia/activity/tests/test_models.py

@@ -11,6 +11,7 @@ from olympia.activity.models import (
     ActivityLogToken,
     AddonLog,
     DraftComment,
+    IPLog,
 )
 from olympia.addons.models import Addon, AddonUser
 from olympia.amo.tests import (
@@ -230,6 +231,37 @@ class TestActivityLog(TestCase):
         entries = ActivityLog.objects.for_user(user)
         assert len(entries) == 1
 
+    def test_ip_log(self):
+        addon = Addon.objects.get()
+        assert IPLog.objects.count() == 0
+        # Creating an activity log for an action without store_ip=True doesn't
+        # create an IPLog.
+        action = amo.LOG.REJECT_VERSION
+        assert not getattr(action, 'store_ip', False)
+        with core.override_remote_addr('127.0.4.8'):
+            activity = ActivityLog.create(
+                action,
+                addon,
+                addon.current_version,
+                user=self.request.user,
+            )
+        assert IPLog.objects.count() == 0
+        # Creating an activity log for an action *with* store_ip=True *does*
+        # create an IPLog.
+        action = amo.LOG.ADD_VERSION
+        assert getattr(action, 'store_ip', False)
+        with core.override_remote_addr('15.16.23.42'):
+            activity = ActivityLog.create(
+                action,
+                addon,
+                addon.current_version,
+                user=self.request.user,
+            )
+        assert IPLog.objects.count() == 1
+        ip_log = IPLog.objects.get()
+        assert ip_log.activity_log == activity
+        assert ip_log.ip_address == '15.16.23.42'
+
     def test_version_log(self):
         version = Version.objects.all()[0]
         ActivityLog.create(

src/olympia/constants/activity.py

@@ -91,6 +91,7 @@ class ADD_VERSION(_LOG):
     action_class = 'add'
     format = _('{version} added to {addon}.')
     keep = True
+    store_ip = True
 
 
 class EDIT_VERSION(_LOG):

src/olympia/devhub/tests/test_feeds.py

@@ -37,7 +37,8 @@ class TestActivity(HubTest):
         version = Version.objects.create(version=version_string, addon=self.addon)
 
         for i in range(num):
-            ActivityLog.create(amo.LOG.ADD_VERSION, self.addon, version)
+            with core.override_remote_addr('127.0.0.1'):
+                ActivityLog.create(amo.LOG.ADD_VERSION, self.addon, version)
 
     def log_status(self, num):
         for i in range(num):

src/olympia/devhub/tests/test_views_submit.py

@@ -2231,8 +2231,13 @@ class TestVersionSubmitUploadListed(VersionSubmitUploadMixin, UploadTest):
         assert version.channel == amo.RELEASE_CHANNEL_LISTED
         assert version.all_files[0].status == amo.STATUS_AWAITING_REVIEW
         self.assert3xx(response, self.get_next_url(version))
-        log_items = ActivityLog.objects.for_addons(self.addon)
-        assert log_items.filter(action=amo.LOG.ADD_VERSION.id)
+        logs_qs = ActivityLog.objects.for_addons(self.addon).filter(
+            action=amo.LOG.ADD_VERSION.id
+        )
+        assert logs_qs.count() == 1
+        log = logs_qs.get()
+        assert log.iplog_set.count() == 1
+        assert log.iplog_set.get().ip_address == self.upload.ip_address
 
     def test_experiment_inside_webext_upload_without_permission(self):
         self.upload = self.get_upload(

src/olympia/files/tests/test_models.py

@@ -58,12 +58,16 @@ class UploadTest(TestCase, amo.tests.AMOPaths):
         version=None,
         with_validation=True,
     ):
+        if user is None:
+            user = user_factory()
         with open(abspath if abspath else self.file_path(filename), 'rb') as f:
             xpi = f.read()
         upload = FileUpload.from_post([xpi], filename=abspath or filename, size=1234)
         upload.addon = addon
         upload.user = user
         upload.version = version
+        upload.ip_address = '127.0.0.42'
+        upload.source = amo.UPLOAD_SOURCE_DEVHUB
         if with_validation:
             # Simulate what fetch_manifest() does after uploading an app.
             upload.validation = validation or json.dumps(

src/olympia/users/management/commands/clear_old_user_data.py

@@ -2,9 +2,11 @@ from datetime import datetime, timedelta
 
 from django.core.management.base import BaseCommand
 from django.db.models import Q
+from django.db.transaction import atomic
 
 import olympia.core.logger
 from olympia import amo
+from olympia.activity.models import IPLog
 from olympia.addons.models import Addon, AddonUser
 from olympia.addons.tasks import delete_addons
 from olympia.users.models import UserProfile, UserRestrictionHistory
@@ -42,11 +44,18 @@ class Command(BaseCommand):
         )
         addon_ids = list(addons_qs.values_list('id', flat=True))
 
-        log.info('Clearing %s for %d users', profile_clear.keys(), len(users))
-        for user in users:
-            user.update(**profile_clear, _signal=False)
+        with atomic():
+            log.info('Clearing %s for %d users', profile_clear.keys(), len(users))
+            for user in users:
+                user.update(**profile_clear, _signal=False)
 
-        user_restrictions.update(ip_address='', last_login_ip='')
+            user_restrictions.update(ip_address='', last_login_ip='')
+
+            # IPLog is only useful to link between an ip and an activity log, so we
+            # can delete any IPLog pointing to an activity belonging to one of the
+            # users we want to clear the data for.
+            ip_logs = IPLog.objects.filter(activity_log__user__in=users)
+            ip_logs.delete()
 
         if addon_ids:
             delete_addons.delay(addon_ids, with_deleted=True)

src/olympia/users/tests/test_commands.py

@@ -7,6 +7,7 @@ from django.core.management import call_command
 from unittest.mock import ANY, patch
 
 from olympia import amo
+from olympia.activity.models import ActivityLog, IPLog
 from olympia.addons.models import Addon
 from olympia.amo.tests import addon_factory, TestCase, user_factory
 from olympia.users.management.commands.createsuperuser import Command as CreateSuperUser
@@ -75,6 +76,15 @@ class TestCreateSuperUser(TestCase):
 
 
 class TestClearOldUserData(TestCase):
+    def create_ip_log(self, user):
+        # Note: this is a dummy log that doesn't have store_ip=True on
+        # purpose, to ensure we directly use IPLog when it comes to
+        # deletion - so even if we change our minds about storing ips for
+        # a given action after a while, we'll still correctly clear the old
+        # data when it's time to do so.
+        activity = ActivityLog.create(amo.LOG.CUSTOM_TEXT, 'hi', user=user)
+        IPLog.objects.create(activity_log=activity, ip_address='127.0.0.56')
+
     def test_no_addons(self):
         recent_date = self.days_ago(2)
         old_date = self.days_ago((365 * 7) + 1)
@@ -82,32 +92,38 @@ class TestClearOldUserData(TestCase):
         # old enough but not deleted
         recent_not_deleted = user_factory(last_login_ip='127.0.0.1', fxa_id='12345')
         recent_not_deleted.update(modified=recent_date)
+        self.create_ip_log(recent_not_deleted)
 
         # Deleted but new
         new_user = user_factory(last_login_ip='127.0.0.1', deleted=True, fxa_id='67890')
+        self.create_ip_log(new_user)
 
         # Deleted and recent: last_login_ip, email, fxa_id must be cleared.
         recent_deleted_user = user_factory(
             last_login_ip='127.0.0.1', deleted=True, fxa_id='abcde'
         )
         recent_deleted_user.update(modified=recent_date)
+        self.create_ip_log(recent_deleted_user)
 
         # Deleted and recent but with some cleared data already null.
         recent_deleted_user_part = user_factory(
             last_login_ip='127.0.0.1', deleted=True, fxa_id=None
         )
         recent_deleted_user_part.update(modified=recent_date)
+        self.create_ip_log(recent_deleted_user_part)
 
         # recent and banned
         recent_banned_user = user_factory(
             last_login_ip='127.0.0.1', deleted=True, fxa_id='abcde', banned=recent_date
         )
         recent_banned_user.update(modified=recent_date)
+        self.create_ip_log(recent_banned_user)
 
         old_banned_user = user_factory(
             last_login_ip='127.0.0.1', deleted=True, fxa_id='abcde', banned=recent_date
         )
         old_banned_user.update(modified=old_date)
+        self.create_ip_log(old_banned_user)
 
         call_command('clear_old_user_data')
 
@@ -117,12 +133,22 @@ class TestClearOldUserData(TestCase):
         assert recent_not_deleted.email
         assert recent_not_deleted.fxa_id
         assert recent_not_deleted.modified == recent_date
+        assert recent_not_deleted.activitylog_set.count() == 1
+        assert (
+            IPLog.objects.filter(activity_log__user=recent_not_deleted).get().ip_address
+            == '127.0.0.56'
+        )
 
         new_user.reload()
         assert new_user.last_login_ip == '127.0.0.1'
         assert new_user.deleted is True
         assert new_user.email
         assert new_user.fxa_id
+        assert new_user.activitylog_set.count() == 1
+        assert (
+            IPLog.objects.filter(activity_log__user=new_user).get().ip_address
+            == '127.0.0.56'
+        )
 
         recent_deleted_user.reload()
         assert recent_deleted_user.last_login_ip == ''
@@ -130,6 +156,8 @@ class TestClearOldUserData(TestCase):
         assert not recent_deleted_user.email
         assert not recent_deleted_user.fxa_id
         assert recent_deleted_user.modified == recent_date
+        assert recent_deleted_user.activitylog_set.count() == 1
+        assert not IPLog.objects.filter(activity_log__user=recent_deleted_user).exists()
 
         recent_deleted_user_part.reload()
         assert recent_deleted_user_part.last_login_ip == ''
@@ -137,6 +165,10 @@ class TestClearOldUserData(TestCase):
         assert not recent_deleted_user_part.email
         assert not recent_deleted_user_part.fxa_id
         assert recent_deleted_user_part.modified == recent_date
+        assert recent_deleted_user_part.activitylog_set.count() == 1
+        assert not IPLog.objects.filter(
+            activity_log__user=recent_deleted_user_part
+        ).exists()
 
         recent_banned_user.reload()
         assert recent_banned_user.last_login_ip == '127.0.0.1'
@@ -144,6 +176,11 @@ class TestClearOldUserData(TestCase):
         assert recent_banned_user.email
         assert recent_banned_user.fxa_id
         assert recent_banned_user.banned
+        assert recent_banned_user.activitylog_set.count() == 1
+        assert (
+            IPLog.objects.filter(activity_log__user=recent_banned_user).get().ip_address
+            == '127.0.0.56'
+        )
 
         old_banned_user.reload()
         assert old_banned_user.last_login_ip == ''
@@ -152,6 +189,8 @@ class TestClearOldUserData(TestCase):
         assert not old_banned_user.fxa_id
         assert old_banned_user.modified == old_date
         assert old_banned_user.banned
+        assert old_banned_user.activitylog_set.count() == 1
+        assert not IPLog.objects.filter(activity_log__user=old_banned_user).exists()
 
     def test_user_restriction_history_cleared_too(self):
         recent_date = self.days_ago(2)
@@ -232,6 +271,7 @@ class TestClearOldUserData(TestCase):
         # Old but not deleted
         old_not_deleted = user_factory(last_login_ip='127.0.0.1', fxa_id='12345')
         old_not_deleted.update(modified=old_date)
+        self.create_ip_log(old_not_deleted)
         old_not_deleted_addon = addon_factory(
             users=[old_not_deleted], status=amo.STATUS_DELETED
         )
@@ -241,12 +281,14 @@ class TestClearOldUserData(TestCase):
             last_login_ip='127.0.0.1', deleted=True, fxa_id='67890'
         )
         recent_user.update(modified=self.days_ago(365))
+        self.create_ip_log(recent_user)
         recent_user_addon = addon_factory(
             users=[recent_user], status=amo.STATUS_DELETED
         )
 
         old_user = user_factory(deleted=True, fxa_id='dfdf')
         old_user.update(modified=old_date)
+        self.create_ip_log(old_user)
         old_user_addon = addon_factory(users=[old_user], status=amo.STATUS_DELETED)
         # Include an add-on that old_user _was_ an owner of, but now isn't.
         # Even if the addon is now deleted it shouldn't be hard-deleted with
@@ -272,6 +314,7 @@ class TestClearOldUserData(TestCase):
             last_login_ip='127.0.0.1', deleted=True, fxa_id='abcde', banned=old_date
         )
         old_banned_user.update(modified=old_date)
+        self.create_ip_log(old_banned_user)
         old_banned_user_addon = addon_factory(
             users=[old_banned_user], status=amo.STATUS_DISABLED
         )
@@ -285,6 +328,10 @@ class TestClearOldUserData(TestCase):
         assert old_not_deleted.fxa_id
         assert old_not_deleted.modified == old_date
         assert old_not_deleted_addon.reload()
+        assert (
+            IPLog.objects.filter(activity_log__user=old_not_deleted).get().ip_address
+            == '127.0.0.56'
+        )
 
         recent_user.reload()
         assert recent_user.last_login_ip == '127.0.0.1'
@@ -292,6 +339,10 @@ class TestClearOldUserData(TestCase):
         assert recent_user.email
         assert recent_user.fxa_id
         assert recent_user_addon.reload()
+        assert (
+            IPLog.objects.filter(activity_log__user=recent_user).get().ip_address
+            == '127.0.0.56'
+        )
 
         old_user.reload()
         assert old_user.last_login_ip == ''
@@ -301,6 +352,7 @@ class TestClearOldUserData(TestCase):
         assert old_user.modified == old_date
         assert not Addon.unfiltered.filter(id=old_user_addon.id).exists()
         assert no_longer_owner_addon.reload()
+        assert not IPLog.objects.filter(activity_log__user=old_user).exists()
 
         assert not Addon.unfiltered.filter(id=old_data_cleared_addon.id).exists()
 
@@ -312,6 +364,7 @@ class TestClearOldUserData(TestCase):
         assert old_banned_user.modified == old_date
         assert old_banned_user.banned
         assert not Addon.unfiltered.filter(id=old_banned_user_addon.id).exists()
+        assert not IPLog.objects.filter(activity_log__user=old_banned_user).exists()
 
         # But check that no_longer_owner_addon is deleted eventually
         old_not_deleted.update(deleted=True)

src/olympia/versions/models.py

@@ -243,6 +243,9 @@ class Version(OnChangeMixin, ModelBase):
         if upload.addon and upload.addon != addon:
             raise VersionCreateError('FileUpload was made for a different Addon')
 
+        if not upload.user or not upload.ip_address or not upload.source:
+            raise VersionCreateError('FileUpload does not have some required fields')
+
         license_id = None
         if channel == amo.RELEASE_CHANNEL_LISTED:
             previous_version = addon.find_latest_version(channel=channel, exclude=())

src/olympia/versions/tests/test_models.py

@@ -37,7 +37,6 @@ from olympia.files.utils import parse_addon
 from olympia.promoted.models import PromotedApproval
 from olympia.reviewers.models import AutoApprovalSummary
 from olympia.users.models import UserProfile
-from olympia.users.utils import get_task_user
 from olympia.versions.compare import version_int, VersionString
 from olympia.versions.models import (
     ApplicationsVersions,
@@ -1214,35 +1213,38 @@ class TestExtensionVersionFromUpload(TestVersionFromUpload):
         self.upload.reload()
         assert self.upload.addon == self.addon
 
-    @mock.patch('olympia.versions.models.log')
-    def test_logging_nulls(self, log_mock):
-        assert self.upload.user is None
-        assert self.upload.ip_address is None
-        assert self.upload.source is None
-        version = Version.from_upload(
-            self.upload,
-            self.addon,
-            [self.selected_app],
-            amo.RELEASE_CHANNEL_LISTED,
-            parsed_data=self.dummy_parsed_data,
-        )
-        assert log_mock.info.call_count == 2
-        assert log_mock.info.call_args_list[0][0] == (
-            ('New version: %r (%s) from %r' % (version, version.pk, self.upload)),
-        )
-        assert log_mock.info.call_args_list[0][1] == {
-            'extra': {
-                'email': '',
-                'guid': self.addon.guid,
-                'upload': self.upload.uuid.hex,
-                'user_id': None,
-                'from_api': False,
-            }
-        }
-        assert ActivityLog.objects.count() == 1
-        activity = ActivityLog.objects.latest('pk')
-        assert activity.arguments == [version, self.addon]
-        assert activity.user == get_task_user()
+    def test_from_upload_no_user(self):
+        self.upload.update(user=None)
+        with self.assertRaises(VersionCreateError):
+            Version.from_upload(
+                self.upload,
+                self.addon,
+                [self.selected_app],
+                amo.RELEASE_CHANNEL_LISTED,
+                parsed_data=self.dummy_parsed_data,
+            )
+
+    def test_from_upload_no_ip_address(self):
+        self.upload.update(ip_address=None)
+        with self.assertRaises(VersionCreateError):
+            Version.from_upload(
+                self.upload,
+                self.addon,
+                [self.selected_app],
+                amo.RELEASE_CHANNEL_LISTED,
+                parsed_data=self.dummy_parsed_data,
+            )
+
+    def test_from_upload_no_source(self):
+        self.upload.update(source=None)
+        with self.assertRaises(VersionCreateError):
+            Version.from_upload(
+                self.upload,
+                self.addon,
+                [self.selected_app],
+                amo.RELEASE_CHANNEL_LISTED,
+                parsed_data=self.dummy_parsed_data,
+            )
 
     @mock.patch('olympia.versions.models.log')
     def test_logging(self, log_mock):
@@ -1691,6 +1693,8 @@ class TestExtensionVersionFromUploadTransactional(
         upload.addon = addon
         upload.user = user
         upload.version = version
+        upload.ip_address = '127.0.0.42'
+        upload.source = amo.UPLOAD_SOURCE_DEVHUB
         if with_validation:
             # Simulate what fetch_manifest() does after uploading an app.
             upload.validation = validation or json.dumps(