realm_audit_log: Fix malformed RealmAuditLog entries.

In f8bcf39014, we fixed buggy
marshalling of Streams and similar data structures where we were
including the Stream object rather than its ID in dictionaries passed
to ujson, and ujson happily wrote that large object dump into the
RealmAuditLog.extra_data field.

This commit includes a migration to fix those corrupted RealmAuditLog
entries, and because the migration loop is the same, also fixes the
format of similar RealmAuditLog entries to be in a more natural format
that doesn't weirdly nest and duplicate the "property" field.

Fixes #16066.

zerver/lib/actions.py

@@ -669,8 +669,9 @@ def do_set_realm_property(realm: Realm, name: str, value: Any,
     RealmAuditLog.objects.create(
         realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED, event_time=event_time,
         acting_user=acting_user, extra_data=ujson.dumps({
-            RealmAuditLog.OLD_VALUE: {'property': name, 'value': old_value},
+            RealmAuditLog.OLD_VALUE: old_value,
-            RealmAuditLog.NEW_VALUE: {'property': name, 'value': value}
+            RealmAuditLog.NEW_VALUE: value,
+            'property': name,
         }))
 
     if name == "email_address_visibility":
@@ -703,8 +704,9 @@ def do_set_realm_authentication_methods(realm: Realm,
     RealmAuditLog.objects.create(
         realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED, event_time=timezone_now(),
         acting_user=acting_user, extra_data=ujson.dumps({
-            RealmAuditLog.OLD_VALUE: {'property': 'authentication_methods', 'value': old_value},
+            RealmAuditLog.OLD_VALUE: old_value,
-            RealmAuditLog.NEW_VALUE: {'property': 'authentication_methods', 'value': updated_value}
+            RealmAuditLog.NEW_VALUE: updated_value,
+            'property': 'authentication_methods',
         }))
     event = dict(
         type="realm",
@@ -738,8 +740,9 @@ def do_set_realm_message_editing(realm: Realm,
         RealmAuditLog.objects.create(
             realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED, event_time=event_time,
             acting_user=acting_user, extra_data=ujson.dumps({
-                RealmAuditLog.OLD_VALUE: {'property': updated_property, 'value': old_values[updated_property]},
+                RealmAuditLog.OLD_VALUE: old_values[updated_property],
-                RealmAuditLog.NEW_VALUE: {'property': updated_property, 'value': updated_value}
+                RealmAuditLog.NEW_VALUE: updated_value,
+                'property': updated_property,
             }))
 
     realm.save(update_fields=list(updated_properties.keys()))
@@ -761,8 +764,9 @@ def do_set_realm_notifications_stream(realm: Realm, stream: Optional[Stream], st
     RealmAuditLog.objects.create(
         realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED, event_time=event_time,
         acting_user=acting_user, extra_data=ujson.dumps({
-            RealmAuditLog.OLD_VALUE: {'property': 'notifications_stream', 'value': old_value},
+            RealmAuditLog.OLD_VALUE: old_value,
-            RealmAuditLog.NEW_VALUE: {'property': 'notifications_stream', 'value': stream_id}
+            RealmAuditLog.NEW_VALUE: stream_id,
+            'property': 'notifications_stream',
         }))
 
     event = dict(
@@ -783,8 +787,9 @@ def do_set_realm_signup_notifications_stream(realm: Realm, stream: Optional[Stre
     RealmAuditLog.objects.create(
         realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED, event_time=event_time,
         acting_user=acting_user, extra_data=ujson.dumps({
-            RealmAuditLog.OLD_VALUE: {'property': 'signup_notifications_stream', 'value': old_value},
+            RealmAuditLog.OLD_VALUE: old_value,
-            RealmAuditLog.NEW_VALUE: {'property': 'signup_notifications_stream', 'value': stream_id}
+            RealmAuditLog.NEW_VALUE: stream_id,
+            'property': 'signup_notifications_stream',
         }))
     event = dict(
         type="realm",
@@ -3139,8 +3144,9 @@ def do_change_subscription_property(user_profile: UserProfile, sub: Subscription
         realm=user_profile.realm, event_type=RealmAuditLog.SUBSCRIPTION_PROPERTY_CHANGED,
         event_time=event_time, modified_user=user_profile, acting_user=acting_user,
         modified_stream=stream, extra_data=ujson.dumps({
-            RealmAuditLog.OLD_VALUE: {'property': database_property_name, 'value': old_value},
+            RealmAuditLog.OLD_VALUE: old_value,
-            RealmAuditLog.NEW_VALUE: {'property': database_property_name, 'value': database_value}
+            RealmAuditLog.NEW_VALUE: database_value,
+            'property': database_property_name,
         }))
 
     event = dict(type="subscription",
@@ -3761,8 +3767,9 @@ def do_change_notification_settings(user_profile: UserProfile, name: str,
     RealmAuditLog.objects.create(
         realm=user_profile.realm, event_type=RealmAuditLog.USER_NOTIFICATION_SETTINGS_CHANGED, event_time=event_time,
         acting_user=acting_user, modified_user=user_profile, extra_data=ujson.dumps({
-            RealmAuditLog.OLD_VALUE: {'property': name, 'value': old_value},
+            RealmAuditLog.OLD_VALUE: old_value,
-            RealmAuditLog.NEW_VALUE: {'property': name, 'value': value}
+            RealmAuditLog.NEW_VALUE: value,
+            'property': name,
         }))
 
     send_event(user_profile.realm, event, [user_profile.id])

zerver/migrations/0298_fix_realmauditlog_format.py

@@ -0,0 +1,117 @@
+# Generated by Django 2.2.14 on 2020-08-07 19:13
+
+import json
+
+from django.db import migrations
+from django.db.backends.postgresql.schema import DatabaseSchemaEditor
+from django.db.migrations.state import StateApps
+
+
+def update_realmauditlog_values(apps: StateApps, schema_editor: DatabaseSchemaEditor) -> None:
+    """
+    This migration fixes two issues with the RealmAuditLog format for certain event types:
+    * The notifications_stream and signup_notifications_stream fields had the
+      Stream objects passed into `ujson.dumps()` and thus marshalled as a giant
+      JSON object, when the intent was to store the stream ID.
+    * The default_sending_stream would also been marshalled wrong, but are part
+      of a feature that nobody should be using, so we simply assert that's the case.
+    * Changes the structure of the extra_data JSON dictionaries for those
+      RealmAuditLog entries with a sub-property field from:
+      {
+          OLD_VALUE: {"property": property, "value": old_value},
+          NEW_VALUE: {"property": property, "value": new_value},
+      }
+
+      to the more natural:
+
+      {
+          OLD_VALUE: old_value,
+          NEW_VALUE: new_value,
+          "property": property,
+      }
+    """
+    RealmAuditLog = apps.get_model('zerver', 'RealmAuditLog')
+    # Constants from models.py
+    USER_DEFAULT_SENDING_STREAM_CHANGED = 129
+    USER_DEFAULT_REGISTER_STREAM_CHANGED = 130
+    USER_DEFAULT_ALL_PUBLIC_STREAMS_CHANGED = 131
+    USER_NOTIFICATION_SETTINGS_CHANGED = 132
+    REALM_PROPERTY_CHANGED = 207
+    SUBSCRIPTION_PROPERTY_CHANGED = 304
+    OLD_VALUE = '1'
+    NEW_VALUE = '2'
+
+    unlikely_event_types = [
+        USER_DEFAULT_SENDING_STREAM_CHANGED,
+        USER_DEFAULT_REGISTER_STREAM_CHANGED,
+        USER_DEFAULT_ALL_PUBLIC_STREAMS_CHANGED,
+    ]
+    # These 3 event types are the ones that used a format with
+    # OLD_VALUE containing a dictionary with a `property` key.
+    affected_event_types = [
+        REALM_PROPERTY_CHANGED,
+        USER_NOTIFICATION_SETTINGS_CHANGED,
+        SUBSCRIPTION_PROPERTY_CHANGED,
+    ]
+    improperly_marshalled_properties = [
+        'notifications_stream',
+        'signup_notifications_stream',
+    ]
+
+    # These are also corrupted but are part of a feature nobody uses,
+    # so it's not worth writing code to fix them.
+    assert not RealmAuditLog.objects.filter(event_type__in=unlikely_event_types).exists()
+
+    for ra in RealmAuditLog.objects.filter(event_type__in=affected_event_types):
+        extra_data = json.loads(ra.extra_data)
+        old_key = extra_data[OLD_VALUE]
+        new_key = extra_data[NEW_VALUE]
+
+        # Skip any already-migrated values in case we're running this
+        # migration a second time.
+        if not isinstance(old_key, dict) and not isinstance(new_key, dict):
+            continue
+        if 'value' not in old_key or 'value' not in new_key:
+            continue
+
+        old_value = old_key["value"]
+        new_value = new_key["value"]
+        prop = old_key["property"]
+
+        # The `authentication_methods` key is the only event whose
+        # action value type is expected to be a dictionary.  That
+        # property is marshalled properly but still wants the second
+        # migration below.
+        if prop != 'authentication_methods':
+            # For the other properties, we have `stream` rather than `stream['id']`
+            # in the original extra_data object; the fix is simply to extract
+            # the intended ID field via `value = value['id']`.
+            if isinstance(old_value, dict):
+                assert prop in improperly_marshalled_properties
+                old_value = old_value['id']
+            if isinstance(new_value, dict):
+                assert prop in improperly_marshalled_properties
+                new_value = new_value['id']
+
+        # Sanity check that the original event has exactly the keys we expect.
+        assert set(extra_data.keys()) <= set([OLD_VALUE, NEW_VALUE])
+
+        ra.extra_data = json.dumps({
+            OLD_VALUE: old_value,
+            NEW_VALUE: new_value,
+            "property": prop,
+        })
+        ra.save(update_fields=["extra_data"])
+
+
+class Migration(migrations.Migration):
+
+    dependencies = [
+        ('zerver', '0297_draft'),
+    ]
+
+    operations = [
+        migrations.RunPython(update_realmauditlog_values,
+                             reverse_code=migrations.RunPython.noop,
+                             elidable=True),
+    ]

zerver/tests/test_audit_log.py

@@ -261,7 +261,7 @@ class TestRealmAuditLog(ZulipTestCase):
         now = timezone_now()
         realm = get_realm('zulip')
         user = self.example_user('hamlet')
-        expected_old_value = {'property': 'authentication_methods', 'value': realm.authentication_methods_dict()}
+        expected_old_value = realm.authentication_methods_dict()
         auth_method_dict = {'Google': False, 'Email': False, 'GitHub': False, 'Apple': False, 'Dev': True, 'SAML': True, 'GitLab': False}
 
         do_set_realm_authentication_methods(realm, auth_method_dict, acting_user=user)
@@ -269,7 +269,7 @@ class TestRealmAuditLog(ZulipTestCase):
                                                         event_time__gte=now, acting_user=user)
         self.assertEqual(realm_audit_logs.count(), 1)
         extra_data = ujson.loads(realm_audit_logs[0].extra_data)
-        expected_new_value = {'property': 'authentication_methods', 'value': auth_method_dict}
+        expected_new_value = auth_method_dict
         self.assertEqual(extra_data[RealmAuditLog.OLD_VALUE], expected_old_value)
         self.assertEqual(extra_data[RealmAuditLog.NEW_VALUE], expected_new_value)
 
@@ -288,26 +288,25 @@ class TestRealmAuditLog(ZulipTestCase):
         now = timezone_now()
         realm = get_realm('zulip')
         user = self.example_user('hamlet')
-        old_values_expected = [{'property': 'message_content_edit_limit_seconds', 'value': realm.message_content_edit_limit_seconds},
+        values_expected = [
-                               {'property': 'allow_community_topic_editing', 'value': realm.allow_community_topic_editing}]
+            {
+                'property': 'message_content_edit_limit_seconds',
+                RealmAuditLog.OLD_VALUE: realm.message_content_edit_limit_seconds,
+                RealmAuditLog.NEW_VALUE: 1000,
+            },
+            {
+                'property': 'allow_community_topic_editing',
+                RealmAuditLog.OLD_VALUE: True,
+                RealmAuditLog.NEW_VALUE: False,
+            },
+        ]
 
         do_set_realm_message_editing(realm, True, 1000, False, acting_user=user)
         realm_audit_logs = RealmAuditLog.objects.filter(realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED,
                                                         event_time__gte=now, acting_user=user).order_by("id")
         self.assertEqual(realm_audit_logs.count(), 2)
-
+        self.assertEqual([ujson.loads(entry.extra_data) for entry in realm_audit_logs],
-        # allow_message_editing was already True.
+                         values_expected)
-        new_values_expected = [{'property': 'message_content_edit_limit_seconds', 'value': 1000},
-                               {'property': 'allow_community_topic_editing', 'value': False}]
-        new_values_seen = []
-        old_values_seen = []
-        for realm_audit_log in realm_audit_logs:
-            extra_data = ujson.loads(realm_audit_log.extra_data)
-            new_values_seen.append(extra_data[RealmAuditLog.NEW_VALUE])
-            old_values_seen.append(extra_data[RealmAuditLog.OLD_VALUE])
-
-        self.assertEqual(new_values_seen, new_values_expected)
-        self.assertEqual(old_values_seen, old_values_expected)
 
     def test_set_realm_notifications_stream(self) -> None:
         now = timezone_now()
@@ -322,8 +321,9 @@ class TestRealmAuditLog(ZulipTestCase):
             realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED,
             event_time__gte=now, acting_user=user,
             extra_data=ujson.dumps({
-                RealmAuditLog.OLD_VALUE: {'property': 'notifications_stream', 'value': old_value},
+                RealmAuditLog.OLD_VALUE: old_value,
-                RealmAuditLog.NEW_VALUE: {'property': 'notifications_stream', 'value': stream.id}
+                RealmAuditLog.NEW_VALUE: stream.id,
+                'property': 'notifications_stream',
             })).count(), 1)
 
     def test_set_realm_signup_notifications_stream(self) -> None:
@@ -339,8 +339,9 @@ class TestRealmAuditLog(ZulipTestCase):
             realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED,
             event_time__gte=now, acting_user=user,
             extra_data=ujson.dumps({
-                RealmAuditLog.OLD_VALUE: {'property': 'signup_notifications_stream', 'value': old_value},
+                RealmAuditLog.OLD_VALUE: old_value,
-                RealmAuditLog.NEW_VALUE: {'property': 'signup_notifications_stream', 'value': stream.id}
+                RealmAuditLog.NEW_VALUE: stream.id,
+                'property': 'signup_notifications_stream',
             })).count(), 1)
 
     def test_change_icon_source(self) -> None:
@@ -380,8 +381,11 @@ class TestRealmAuditLog(ZulipTestCase):
             old_value = getattr(sub, property)
             self.assertNotEqual(old_value, value)
             do_change_subscription_property(user, sub, stream, property, value, acting_user=user)
-            expected_extra_data = {RealmAuditLog.OLD_VALUE: {'property': property, 'value': old_value},
+            expected_extra_data = {
-                                   RealmAuditLog.NEW_VALUE: {'property': property, 'value': value}}
+                RealmAuditLog.OLD_VALUE: old_value,
+                RealmAuditLog.NEW_VALUE: value,
+                'property': property,
+            }
             self.assertEqual(RealmAuditLog.objects.filter(
                 realm=user.realm, event_type=RealmAuditLog.SUBSCRIPTION_PROPERTY_CHANGED,
                 event_time__gte=now, acting_user=user, modified_user=user,
@@ -455,8 +459,11 @@ class TestRealmAuditLog(ZulipTestCase):
 
             old_value = getattr(user, setting)
             do_change_notification_settings(user, setting, value, acting_user=user)
-            expected_extra_data = {RealmAuditLog.OLD_VALUE: {'property': setting, 'value': old_value},
+            expected_extra_data = {
-                                   RealmAuditLog.NEW_VALUE: {'property': setting, 'value': value}}
+                RealmAuditLog.OLD_VALUE: old_value,
+                RealmAuditLog.NEW_VALUE: value,
+                'property': setting,
+            }
             self.assertEqual(RealmAuditLog.objects.filter(
                 realm=user.realm, event_type=RealmAuditLog.USER_NOTIFICATION_SETTINGS_CHANGED,
                 event_time__gte=now, acting_user=user, modified_user=user,

zerver/tests/test_events.py

@@ -2019,8 +2019,9 @@ class RealmPropertyActionTest(BaseAction):
                 realm=self.user_profile.realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED,
                 event_time__gte=now, acting_user=self.user_profile,
                 extra_data=ujson.dumps({
-                    RealmAuditLog.OLD_VALUE: {'property': name, 'value': old_value},
+                    RealmAuditLog.OLD_VALUE: old_value,
-                    RealmAuditLog.NEW_VALUE: {'property': name, 'value': val}
+                    RealmAuditLog.NEW_VALUE: val,
+                    'property': name,
                 })).count(), 1)
             check_realm_update('events[0]', events[0], name)