Merge pull request #1478 from matrix-org/andy/state_logs

Add extra logs when saving and loading room state

MatrixSDK/Data/Store/MXFileStore/MXFileStore.m

@@ -568,7 +568,12 @@ - (NSArray*)stateOfRoom:(NSString *)roomId
 
     if (!stateEvents)
     {
-        stateEvents =[NSKeyedUnarchiver unarchiveObjectWithFile:[self stateFileForRoom:roomId forBackup:NO]];
+        NSString *file = [self stateFileForRoom:roomId forBackup:NO];
+        stateEvents = [self loadRootObjectWithoutSecureCodingFromFile:file];
+        if (!stateEvents || !stateEvents.count)
+        {
+            MXLogWarning(@"[MXFileStore] stateOfRoom: no state was loaded for room %@", roomId);
+        }
 
         if (NO == [NSThread isMainThread])
         {
@@ -1385,6 +1390,8 @@ - (void)saveRoomsState
             for (NSString *roomId in roomsToCommit)
             {
                 NSArray *stateEvents = roomsToCommit[roomId];
+
+                MXLogDebug(@"[MXFileStore commit] saveRoomsState: saving %lu events for room %@", stateEvents.count, roomId);
 
                 NSString *file = [self stateFileForRoom:roomId forBackup:NO];
                 NSString *backupFile = [self stateFileForRoom:roomId forBackup:YES];
@@ -1398,7 +1405,7 @@ - (void)saveRoomsState
 
                 // Store new data
                 [self checkFolderExistenceForRoom:roomId forBackup:NO];
-                [NSKeyedArchiver archiveRootObject:stateEvents toFile:file];
+                [self saveObject:stateEvents toFile:file];
             }
 #if DEBUG
             MXLogDebug(@"[MXFileStore commit] lasted %.0fms for %tu rooms state", [[NSDate date] timeIntervalSinceDate:startDate] * 1000, roomsToCommit.count);
@@ -2193,6 +2200,9 @@ - (MXFileRoomStore *)roomStoreForRoom:(NSString*)roomId
 
 #pragma mark - Tools
 
+/**
+ Save an object to file using a newer `NSKeyedArchiver` API if available, and log any potential errors
+ */
 - (void)saveObject:(id)object toFile:(NSString *)file
 {
     if (@available(iOS 11.0, *))
@@ -2201,7 +2211,7 @@ - (void)saveObject:(id)object toFile:(NSString *)file
         NSData *data = [NSKeyedArchiver archivedDataWithRootObject:object requiringSecureCoding:NO error:&error];
         if (error)
         {
-            MXLogDebug(@"[MXFileStore] Failed archiving root object with error: '%@'", error.localizedDescription);
+            MXLogFailure(@"[MXFileStore] Failed archiving root object with error: '%@'", error.debugDescription);
             return;
         }
 
@@ -2212,7 +2222,7 @@ - (void)saveObject:(id)object toFile:(NSString *)file
         }
         else
         {
-            MXLogDebug(@"[MXFileStore] Failed saving data with error: '%@'", error.localizedDescription);
+            MXLogFailure(@"[MXFileStore] Failed saving data with error: '%@'", error.debugDescription);
         }
     }
     else
@@ -2221,27 +2231,69 @@ - (void)saveObject:(id)object toFile:(NSString *)file
     }
 }
 
+/**
+ Load an object from file using a newer `NSKeyedUnarchiver` API if available, and log any potential errors
+ 
+ @discussion
+ Newer `NSKeyedUnarchiver` API sets `requiresSecureCoding` to `YES` by default, meaning that the caller
+ needs to provide a set of classes expected to be decoded. All of these classes must implement `NSSecureCoding`.
+ */
 - (id)loadObjectOfClasses:(NSSet<Class> *)classes fromFile:(NSString *)file
 {
     if (@available(iOS 11.0, *))
     {
-        NSData *data = [NSData dataWithContentsOfFile:file];
-        if (!data)
+        NSError *error;
+        NSData *data = [self loadDataFromFile:file];
+        id object = [NSKeyedUnarchiver unarchivedObjectOfClasses:classes fromData:data error:&error];
+        if (object)
+        {
+            MXLogDebug(@"[MXFileStore] Loaded object from class");
+            return object;
+        }
+        else
         {
-            MXLogDebug(@"[MXFileStore] No data to load at file %@", file);
+            MXLogFailure(@"[MXFileStore] Failed loading object from class with error: '%@'", error.debugDescription);
             return nil;
         }
-
+    }
+    else
+    {
+        return [NSKeyedUnarchiver unarchiveObjectWithFile:file];
+    }
+}
+
+/**
+ Load an object from file using a newer `NSKeyedUnarchiver` API if available, and log any potential errors
+ 
+ @discussion
+ An equivalent of `loadObjectOfClasses` but setting `requiresSecureCoding` to NO. Because of this the caller
+ does not have to specify classes to be decoded, and can archive / unarchive classes that do not implement
+ `NSSecureCoding` protocol.
+ */
+- (id)loadRootObjectWithoutSecureCodingFromFile:(NSString *)file
+{
+    if (@available(iOS 11.0, *))
+    {
         NSError *error;
-        id object = [NSKeyedUnarchiver unarchivedObjectOfClasses:classes fromData:data error:&error];
+        NSData *data = [self loadDataFromFile:file];
+        NSKeyedUnarchiver *unarchiver = [[NSKeyedUnarchiver alloc] initForReadingFromData:data error:&error];
+        if (error && !unarchiver)
+        {
+            MXLogFailure(@"[MXFileStore] Cannot create unarchiver with error: '%@'", error.debugDescription);
+            return nil;
+        }
+        unarchiver.requiresSecureCoding = NO;
+
+        // Seems to be an implementation detaul
+        id object = [unarchiver decodeTopLevelObjectForKey:NSKeyedArchiveRootObjectKey error:&error];
         if (object)
         {
             MXLogDebug(@"[MXFileStore] Loaded object from class");
             return object;
         }
         else
         {
-            MXLogDebug(@"[MXFileStore] Failed loading object from class with error: '%@'", error.localizedDescription);
+            MXLogFailure(@"[MXFileStore] Failed loading object from class with error: '%@'", error.debugDescription);
             return nil;
         }
     }
@@ -2251,6 +2303,17 @@ - (id)loadObjectOfClasses:(NSSet<Class> *)classes fromFile:(NSString *)file
     }
 }
 
+- (NSData *)loadDataFromFile:(NSString *)file
+{
+    NSData *data = [NSData dataWithContentsOfFile:file];
+    if (!data)
+    {
+        MXLogDebug(@"[MXFileStore] No data to load at file %@", file);
+        return nil;
+    }
+    return data;
+}
+
 /**
  List recursevely files in a folder
  

MatrixSDKTests/MXStoreFileStoreTests.m

@@ -299,6 +299,53 @@ - (void)testMXFileStoreFilterId
     }];
 }
 
+- (void)testRoomStateIsStoredAndRestored
+{
+    [self doTestWithMXFileStoreAndMessagesLimit:10 readyToTest:^(MXRoom *room) {
+        MXFileStore *fileStore = mxSession.store;
+
+        // Load pre-existing room state
+        [fileStore stateOfRoom:room.roomId success:^(NSArray<MXEvent *> * _Nonnull originalEvents) {
+
+            MXEvent *name = [MXEvent modelFromJSON:@{
+                @"type": kMXEventTypeStringRoomName,
+                @"content": @{
+                    @"name": @"Room 1"
+                }
+            }];
+            NSArray *extendedEvents = [originalEvents arrayByAddingObject:name];
+
+            // Save all existing events plus one additional
+            [fileStore storeStateForRoom:room.roomId stateEvents:extendedEvents];
+            [fileStore commitWithCompletion:^{
+
+                // Need to fetch state of room twice due to a caching issue
+                [fileStore stateOfRoom:room.roomId success:^(NSArray<MXEvent *> * _Nonnull _stateEvents) {
+                    [fileStore stateOfRoom:room.roomId success:^(NSArray<MXEvent *> * _Nonnull stateEvents) {
+
+                        // Loaded state should include an extra event that was archived and unarchived
+                        XCTAssertTrue(stateEvents.count);
+                        XCTAssertEqual(stateEvents.count, extendedEvents.count);
+                        XCTAssertNotEqual(stateEvents.count, originalEvents.count);
+                        [expectation fulfill];
+
+                    } failure:^(NSError * _Nonnull error) {
+                        XCTFail(@"Cannot load state - error: %@", error);
+                        [expectation fulfill];
+                    }];
+                } failure:^(NSError * _Nonnull error) {
+                    XCTFail(@"Cannot load state - error: %@", error);
+                    [expectation fulfill];
+                }];
+            }];
+
+        } failure:^(NSError * _Nonnull error) {
+            XCTFail(@"Cannot load state - error: %@", error);
+            [expectation fulfill];
+        }];
+    }];
+}
+
 @end
 
 #pragma clang diagnostic pop

changelog.d/pr-1478.misc

@@ -0,0 +1 @@
+MXFileStore: Add extra logs when saving and loading room state