From eb97e9fae0cd27cc0ca9056e3b8dbf667653a735 Mon Sep 17 00:00:00 2001 From: Tim Abbott Date: Sun, 5 May 2019 18:23:34 -0700 Subject: [PATCH] soft_deactivation: Fix buggy handling of race condition. If a soft deactivated user had a subscription double-toggled without any new messages being sent in between, add_missing_messages might incorrectly process those two subscription changes in the wrong order. Fortunately, the failure mode was usually to throw this exception: django.db.utils.IntegrityError: duplicate key value violates unique constraint "zerver_usermessage_user_profile_id_message_id_4936d0df_uniq" DETAIL: Key (user_profile_id, message_id)=(4, 57) already exists. Our unit tests actually had this precise setup some fraction of the time, because a bit of the test setup code subscribed+unsubscribed the target user without sending any messages in between, resulting in a test failure something like 50% of the time. The original exception was hard to reproduce reliably originally (resulting in an extremely annoying nondetermnistic test failure), but is easily reproducible by changing the "id" to "-id" in this change to always mis-order the processing of those RealmAuditLog events. --- zerver/lib/soft_deactivation.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/zerver/lib/soft_deactivation.py b/zerver/lib/soft_deactivation.py index ef17d936ae..9b9deb89ec 100644 --- a/zerver/lib/soft_deactivation.py +++ b/zerver/lib/soft_deactivation.py @@ -124,11 +124,18 @@ def add_missing_messages(user_profile: UserProfile) -> None: stream_ids = [sub['recipient__type_id'] for sub in all_stream_subs] events = [RealmAuditLog.SUBSCRIPTION_CREATED, RealmAuditLog.SUBSCRIPTION_DEACTIVATED, RealmAuditLog.SUBSCRIPTION_ACTIVATED] + + # Important: We order first by event_last_message_id, which is the + # official ordering, and then tiebreak by RealmAuditLog event ID. + # That second tiebreak is important in case a user is subscribed + # and then unsubscribed without any messages being sent in the + # meantime. Without that tiebreak, we could end up incorrectly + # processing the ordering of those two subscription changes. subscription_logs = list(RealmAuditLog.objects.select_related( 'modified_stream').filter( modified_user=user_profile, modified_stream__id__in=stream_ids, - event_type__in=events).order_by('event_last_message_id')) + event_type__in=events).order_by('event_last_message_id', 'id')) all_stream_subscription_logs = defaultdict(list) # type: DefaultDict[int, List[RealmAuditLog]] for log in subscription_logs: