Better logging for expiration timer updates

ts/background.ts

@@ -2729,15 +2729,13 @@ export async function startApp(): Promise<void> {
       const { expireTimer } = details;
       const isValidExpireTimer = typeof expireTimer === 'number';
       if (isValidExpireTimer) {
-        await conversation.updateExpirationTimer(
+        await conversation.updateExpirationTimer(expireTimer, {
-          expireTimer,
+          source: window.ConversationController.getOurConversationId(),
-          window.ConversationController.getOurConversationId(),
+          receivedAt: ev.receivedAtCounter,
-          undefined,
+          fromSync: true,
-          {
+          isInitialSync,
-            fromSync: true,
+          reason: 'contact sync',
-            isInitialSync,
+        });
-          }
-        );
       }
     } catch (error) {
       log.error('onContactReceived error:', Errors.toLogFormat(error));
@@ -2813,14 +2811,12 @@ export async function startApp(): Promise<void> {
       return;
     }
 
-    await conversation.updateExpirationTimer(
+    await conversation.updateExpirationTimer(expireTimer, {
-      expireTimer,
+      fromSync: true,
-      window.ConversationController.getOurConversationId(),
+      receivedAt: ev.receivedAtCounter,
-      undefined,
+      source: window.ConversationController.getOurConversationId(),
-      {
+      reason: 'group sync',
-        fromSync: true,
+    });
-      }
-    );
   }
 
   // Received:

ts/groups.ts

@@ -1870,7 +1870,9 @@ export async function createGroupV2({
   conversation.trigger('newmessage', model);
 
   if (expireTimer) {
-    await conversation.updateExpirationTimer(expireTimer);
+    await conversation.updateExpirationTimer(expireTimer, {
+      reason: 'createGroupV2',
+    });
   }
 
   return conversation;

ts/models/conversations.ts

@@ -3288,7 +3288,9 @@ export class ConversationModel extends window.Backbone
         `maybeApplyUniversalTimer(${this.idForLogging()}): applying timer`
       );
 
-      await this.updateExpirationTimer(expireTimer);
+      await this.updateExpirationTimer(expireTimer, {
+        reason: 'maybeApplyUniversalTimer',
+      });
     }
   }
 
@@ -4446,19 +4448,27 @@ export class ConversationModel extends window.Backbone
 
   async updateExpirationTimer(
     providedExpireTimer: number | undefined,
-    providedSource?: unknown,
-    initiatingMessage?: MessageModel,
     {
+      reason,
+      receivedAt,
+      receivedAtMS = Date.now(),
+      sentAt: providedSentAt,
+      source: providedSource,
       fromSync = false,
       isInitialSync = false,
       fromGroupUpdate = false,
     }: {
+      reason: string;
+      receivedAt?: number;
+      receivedAtMS?: number;
+      sentAt?: number;
+      source?: string;
       fromSync?: boolean;
       isInitialSync?: boolean;
       fromGroupUpdate?: boolean;
-    } = {}
+    }
   ): Promise<boolean | null | MessageModel | void> {
-    const isSetByOther = providedSource || initiatingMessage;
+    const isSetByOther = providedSource || providedSentAt !== undefined;
 
     if (isGroupV2(this.attributes)) {
       if (isSetByOther) {
@@ -4496,11 +4506,12 @@ export class ConversationModel extends window.Backbone
       return null;
     }
 
-    log.info("Update conversation 'expireTimer'", {
+    const logId =
-      id: this.idForLogging(),
+      `updateExpirationTimer(${this.idForLogging()}, ` +
-      expireTimer,
+      `${expireTimer || 'disabled'}) ` +
-      source,
+      `source=${source ?? '?'} reason=${reason}`;
-    });
+
+    log.info(`${logId}: updating`);
 
     // if change wasn't made remotely, send it to the number/group
     if (!isSetByOther) {
@@ -4512,7 +4523,7 @@ export class ConversationModel extends window.Backbone
         });
       } catch (error) {
         log.error(
-          'updateExpirationTimer: Failed to queue expiration timer update',
+          `${logId}: Failed to queue expiration timer update`,
           Errors.toLogFormat(error)
         );
         throw error;
@@ -4521,14 +4532,6 @@ export class ConversationModel extends window.Backbone
 
     source = source || window.ConversationController.getOurConversationId();
 
-    // When we add a disappearing messages notification to the conversation, we want it
-    //   to be above the message that initiated that change, hence the subtraction.
-    const receivedAt =
-      initiatingMessage?.get('received_at') ||
-      window.Signal.Util.incrementMessageCounter();
-    const receivedAtMS = initiatingMessage?.get('received_at_ms') || Date.now();
-    const sentAt = (initiatingMessage?.get('sent_at') || receivedAtMS) - 1;
-
     this.set({ expireTimer });
 
     // This call actually removes universal timer notification and clears
@@ -4537,6 +4540,10 @@ export class ConversationModel extends window.Backbone
 
     window.Signal.Data.updateConversation(this.attributes);
 
+    // When we add a disappearing messages notification to the conversation, we want it
+    //   to be above the message that initiated that change, hence the subtraction.
+    const sentAt = (providedSentAt || receivedAtMS) - 1;
+
     const model = new window.Whisper.Message({
       conversationId: this.id,
       expirationTimerUpdate: {
@@ -4548,7 +4555,7 @@ export class ConversationModel extends window.Backbone
       flags: Proto.DataMessage.Flags.EXPIRATION_TIMER_UPDATE,
       readStatus: isInitialSync ? ReadStatus.Read : ReadStatus.Unread,
       received_at_ms: receivedAtMS,
-      received_at: receivedAt,
+      received_at: receivedAt ?? window.Signal.Util.incrementMessageCounter(),
       seenStatus: isInitialSync ? SeenStatus.Seen : SeenStatus.Unseen,
       sent_at: sentAt,
       type: 'timer-notification',
@@ -4566,6 +4573,10 @@ export class ConversationModel extends window.Backbone
     this.addSingleMessage(message);
     this.updateUnread();
 
+    log.info(
+      `${logId}: added a notification received_at=${model.get('received_at')}`
+    );
+
     return message;
   }
 

ts/models/messages.ts

@@ -2611,21 +2611,27 @@ export class MessageModel extends window.Backbone.Model<MessageAttributesType> {
                 if (
                   dataMessage.expireTimer !== conversation.get('expireTimer')
                 ) {
-                  conversation.updateExpirationTimer(
+                  conversation.updateExpirationTimer(dataMessage.expireTimer, {
-                    dataMessage.expireTimer,
                     source,
-                    message,
+                    receivedAt: message.get('received_at'),
-                    {
+                    receivedAtMS: message.get('received_at_ms'),
-                      fromGroupUpdate: isGroupUpdate(message.attributes),
+                    sentAt: message.get('sent_at'),
-                    }
+                    fromGroupUpdate: isGroupUpdate(message.attributes),
-                  );
+                    reason: `handleDataMessage(${this.idForLogging()})`,
+                  });
                 }
               } else if (
                 conversation.get('expireTimer') &&
                 // We only turn off timers if it's not a group update
                 !isGroupUpdate(message.attributes)
               ) {
-                conversation.updateExpirationTimer(undefined, source, message);
+                conversation.updateExpirationTimer(undefined, {
+                  source,
+                  receivedAt: message.get('received_at'),
+                  receivedAtMS: message.get('received_at_ms'),
+                  sentAt: message.get('sent_at'),
+                  reason: `handleDataMessage(${this.idForLogging()})`,
+                });
               }
             }
           }

ts/textsecure/MessageReceiver.ts

@@ -2723,7 +2723,10 @@ export default class MessageReceiver
     const contactBuffer = new ContactBuffer(attachmentPointer.data);
     let contactDetails = contactBuffer.next();
     while (contactDetails !== undefined) {
-      const contactEvent = new ContactEvent(contactDetails);
+      const contactEvent = new ContactEvent(
+        contactDetails,
+        envelope.receivedAtCounter
+      );
       results.push(this.dispatchAndWait(contactEvent));
 
       contactDetails = contactBuffer.next();
@@ -2767,10 +2770,13 @@ export default class MessageReceiver
         continue;
       }
 
-      const ev = new GroupEvent({
+      const ev = new GroupEvent(
-        ...groupDetails,
+        {
-        id: Bytes.toBinary(id),
+          ...groupDetails,
-      });
+          id: Bytes.toBinary(id),
+        },
+        envelope.receivedAtCounter
+      );
       const promise = this.dispatchAndWait(ev).catch(e => {
         log.error('error processing group', e);
       });

ts/textsecure/messageReceiverEvents.ts

@@ -73,7 +73,10 @@ export class ErrorEvent extends Event {
 }
 
 export class ContactEvent extends Event {
-  constructor(public readonly contactDetails: ModifiedContactDetails) {
+  constructor(
+    public readonly contactDetails: ModifiedContactDetails,
+    public readonly receivedAtCounter: number
+  ) {
     super('contact');
   }
 }
@@ -90,7 +93,10 @@ export type GroupEventData = Omit<ModifiedGroupDetails, 'id'> &
   }>;
 
 export class GroupEvent extends Event {
-  constructor(public readonly groupDetails: GroupEventData) {
+  constructor(
+    public readonly groupDetails: GroupEventData,
+    public readonly receivedAtCounter: number
+  ) {
     super('group');
   }
 }

ts/views/conversation_view.tsx

@@ -2552,7 +2552,10 @@ export class ConversationView extends window.Backbone.View<ConversationModel> {
 
     await this.longRunningTaskWrapper({
       name: 'updateExpirationTimer',
-      task: async () => model.updateExpirationTimer(valueToSet),
+      task: async () =>
+        model.updateExpirationTimer(valueToSet, {
+          reason: 'setDisappearingMessages',
+        }),
     });
   }