Improve Logging For Disappearing Messages (#2332)

*   [x] Log updates to last message (message preview) in conversation list.
        Should help debug cases such as:
        https://github.com/signalapp/Signal-Desktop/issues/2323
*   [x] Use structured logs:
    *   [x] Use static prefix (easier to search)
    *   [x] Capitalize log message and use present tense
            (consistent with Git logging conventions).
    *   [x] Attach metadata as JSON serializable object. This has the benefit
            that all fields are named and can be searched for.
*   [x] Remove newlines from group IDs during redaction so they don’t break up
        log lines.

js/expiring_messages.js

@@ -6,7 +6,9 @@
     // Load messages that have expired and destroy them
     var expired = new Whisper.MessageCollection();
     expired.on('add', function(message) {
-      console.log('message', message.get('sent_at'), 'expired');
+      console.log('Message expired', {
+        sentAt: message.get('sent_at'),
+      });
       var conversation = message.getConversation();
       if (conversation) {
         conversation.trigger('expired', message);

js/models/conversations.js

@@ -813,17 +813,24 @@
       await collection.fetchConversation(this.id, 1);
       const lastMessage = collection.at(0);
 
+      const lastMessageJSON = lastMessage ? lastMessage.toJSON() : null;
       const lastMessageUpdate = window.Signal.Types.Conversation.createLastMessageUpdate(
         {
           currentLastMessageText: this.get('lastMessage') || null,
           currentTimestamp: this.get('timestamp') || null,
-          lastMessage: lastMessage ? lastMessage.toJSON() : null,
+          lastMessage: lastMessageJSON,
           lastMessageNotificationText: lastMessage
             ? lastMessage.getNotificationText()
             : null,
         }
       );
 
+      console.log('Conversation: Update last message:', {
+        id: this.idForLogging() || null,
+        messageTimestamp: lastMessageUpdate.timestamp || null,
+        messageType: lastMessageJSON ? lastMessageJSON.type : null,
+        messageSentAt: lastMessageJSON ? lastMessageJSON.sent_at : null,
+      });
       this.set(lastMessageUpdate);
 
       if (this.hasChanged('lastMessage') || this.hasChanged('timestamp')) {
@@ -853,14 +860,12 @@
         return Promise.resolve();
       }
 
-      console.log(
+      console.log("Update conversation 'expireTimer'", {
-        'Updating expireTimer for conversation',
+        id: this.idForLogging(),
-        this.idForLogging(),
-        'to',
         expireTimer,
-        'via',
+        source,
-        source
+      });
-      );
+
       source = source || textsecure.storage.user.getNumber();
       const timestamp = receivedAt || Date.now();
 

js/models/messages.js

@@ -632,13 +632,11 @@
             const shouldLogExpireTimerChange =
               message.isExpirationTimerUpdate() || expireTimer;
             if (shouldLogExpireTimerChange) {
-              console.log(
+              console.log("Update conversation 'expireTimer'", {
-                'Updating expireTimer for conversation',
+                id: conversation.idForLogging(),
-                conversation.idForLogging(),
-                'to',
                 expireTimer,
-                'via `handleDataMessage`'
+                source: 'handleDataMessage',
-              );
+              });
             }
 
             if (!message.isEndSession() && !message.isGroupUpdate()) {
@@ -847,7 +845,10 @@
         }
 
         Whisper.ExpiringMessagesListener.update();
-        console.log('message', this.get('sent_at'), 'expires at', expiresAt);
+        console.log('Set message expiration', {
+          expiresAt,
+          sentAt: this.get('sent_at'),
+        });
       }
     },
   });
@@ -961,7 +962,7 @@
     },
 
     fetchExpired() {
-      console.log('loading expired messages');
+      console.log('Load expired messages');
       this.fetch({
         conditions: { expires_at: { $lte: Date.now() } },
         addIndividually: true,

js/modules/privacy.js

@@ -73,7 +73,7 @@ exports.redactGroupIds = text => {
   return text.replace(
     GROUP_ID_PATTERN,
     (match, before, id, after) =>
-      `${before}${REDACTION_PLACEHOLDER}${id.slice(-3)}${after}`
+      `${before}${REDACTION_PLACEHOLDER}${removeNewlines(id).slice(-3)}${after}`
   );
 };
 
@@ -86,3 +86,5 @@ exports.redactAll = compose(
   exports.redactGroupIds,
   exports.redactPhoneNumbers
 );
+
+const removeNewlines = text => text.replace(/\r?\n|\r/g, '');

js/views/conversation_view.js

@@ -815,11 +815,9 @@
     },
     async onExpiredCollection(message) {
       const removeMessage = () => {
-        console.log(
+        console.log('Remove expired message from message collection', {
-          'removing message',
+          sentAt: message.get('sent_at'),
-          message.get('sent_at'),
+        });
-          'from collection'
-        );
         this.model.messageCollection.remove(message.id);
       };
 

test/modules/privacy_test.js

@@ -33,6 +33,18 @@ describe('Privacy', () => {
         'and group([REDACTED]hij)';
       assert.equal(actual, expected);
     });
+
+    it('should remove newlines from redacted group IDs', () => {
+      const text =
+        'This is a log line with two group IDs: group(12345678\n9)\n' +
+        'and group(abc\ndefghij)';
+
+      const actual = Privacy.redactGroupIds(text);
+      const expected =
+        'This is a log line with two group IDs: group([REDACTED]789)\n' +
+        'and group([REDACTED]hij)';
+      assert.equal(actual, expected);
+    });
   });
 
   describe('redactAll', () => {