Skip to content

Commit

Permalink
realm_audit_log: Fix malformed RealmAuditLog entries.
Browse files Browse the repository at this point in the history
In f8bcf39, 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 zulip#16066.
  • Loading branch information
timabbott committed Aug 9, 2020
1 parent 83645a3 commit e12225a
Show file tree
Hide file tree
Showing 4 changed files with 173 additions and 41 deletions.
35 changes: 21 additions & 14 deletions zerver/lib/actions.py
Original file line number Diff line number Diff line change
Expand Up @@ -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.NEW_VALUE: {'property': name, 'value': value}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: value,
'property': name,
}))

if name == "email_address_visibility":
Expand Down Expand Up @@ -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.NEW_VALUE: {'property': 'authentication_methods', 'value': updated_value}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: updated_value,
'property': 'authentication_methods',
}))
event = dict(
type="realm",
Expand Down Expand Up @@ -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.NEW_VALUE: {'property': updated_property, 'value': updated_value}
RealmAuditLog.OLD_VALUE: old_values[updated_property],
RealmAuditLog.NEW_VALUE: updated_value,
'property': updated_property,
}))

realm.save(update_fields=list(updated_properties.keys()))
Expand All @@ -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.NEW_VALUE: {'property': 'notifications_stream', 'value': stream_id}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: stream_id,
'property': 'notifications_stream',
}))

event = dict(
Expand All @@ -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.NEW_VALUE: {'property': 'signup_notifications_stream', 'value': stream_id}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: stream_id,
'property': 'signup_notifications_stream',
}))
event = dict(
type="realm",
Expand Down Expand Up @@ -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.NEW_VALUE: {'property': database_property_name, 'value': database_value}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: database_value,
'property': database_property_name,
}))

event = dict(type="subscription",
Expand Down Expand Up @@ -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.NEW_VALUE: {'property': name, 'value': value}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: value,
'property': name,
}))

send_event(user_profile.realm, event, [user_profile.id])
Expand Down
117 changes: 117 additions & 0 deletions zerver/migrations/0298_fix_realmauditlog_format.py
Original file line number Diff line number Diff line change
@@ -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),
]
57 changes: 32 additions & 25 deletions zerver/tests/test_audit_log.py
Original file line number Diff line number Diff line change
Expand Up @@ -261,15 +261,15 @@ def test_set_realm_authentication_methods(self) -> None:
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)
realm_audit_logs = RealmAuditLog.objects.filter(realm=realm, event_type=RealmAuditLog.REALM_PROPERTY_CHANGED,
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)

Expand All @@ -288,26 +288,25 @@ def test_set_realm_message_editing(self) -> None:
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},
{'property': 'allow_community_topic_editing', 'value': realm.allow_community_topic_editing}]
values_expected = [
{
'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)

# allow_message_editing was already True.
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)
self.assertEqual([ujson.loads(entry.extra_data) for entry in realm_audit_logs],
values_expected)

def test_set_realm_notifications_stream(self) -> None:
now = timezone_now()
Expand All @@ -322,8 +321,9 @@ def test_set_realm_notifications_stream(self) -> None:
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.NEW_VALUE: {'property': 'notifications_stream', 'value': stream.id}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: stream.id,
'property': 'notifications_stream',
})).count(), 1)

def test_set_realm_signup_notifications_stream(self) -> None:
Expand All @@ -339,8 +339,9 @@ def test_set_realm_signup_notifications_stream(self) -> None:
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.NEW_VALUE: {'property': 'signup_notifications_stream', 'value': stream.id}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: stream.id,
'property': 'signup_notifications_stream',
})).count(), 1)

def test_change_icon_source(self) -> None:
Expand Down Expand Up @@ -380,8 +381,11 @@ def test_change_subscription_property(self) -> None:
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},
RealmAuditLog.NEW_VALUE: {'property': property, 'value': value}}
expected_extra_data = {
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,
Expand Down Expand Up @@ -455,8 +459,11 @@ def test_change_notification_settings(self) -> None:

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},
RealmAuditLog.NEW_VALUE: {'property': setting, 'value': value}}
expected_extra_data = {
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,
Expand Down
5 changes: 3 additions & 2 deletions zerver/tests/test_events.py
Original file line number Diff line number Diff line change
Expand Up @@ -2019,8 +2019,9 @@ def do_set_realm_property_test(self, name: str) -> None:
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.NEW_VALUE: {'property': name, 'value': val}
RealmAuditLog.OLD_VALUE: old_value,
RealmAuditLog.NEW_VALUE: val,
'property': name,
})).count(), 1)
check_realm_update('events[0]', events[0], name)

Expand Down

0 comments on commit e12225a

Please sign in to comment.