From fdb8da099bf1f78eadc2b44a742a12b308355455 Mon Sep 17 00:00:00 2001 From: manuroe Date: Wed, 27 Mar 2019 11:44:51 +0100 Subject: [PATCH] Push: Add logs to track spontaneously disabling vector-im/riot-ios/issues/2348 --- MatrixKit/Models/Account/MXKAccount.m | 71 +++++++++++++------- MatrixKit/Models/Account/MXKAccountManager.m | 54 ++++++++++----- MatrixKit/Utils/MXKTools.h | 10 +++ MatrixKit/Utils/MXKTools.m | 9 +++ 4 files changed, 106 insertions(+), 38 deletions(-) diff --git a/MatrixKit/Models/Account/MXKAccount.m b/MatrixKit/Models/Account/MXKAccount.m index 9eae845de..4ca49c55f 100644 --- a/MatrixKit/Models/Account/MXKAccount.m +++ b/MatrixKit/Models/Account/MXKAccount.m @@ -291,6 +291,8 @@ - (void)setAntivirusServerURL:(NSString *)antivirusServerURL - (void)setPushGatewayURL:(NSString *)pushGatewayURL { _pushGatewayURL = pushGatewayURL.length ? pushGatewayURL : nil; + + NSLog(@"[MXKAccount][Push] setPushGatewayURL: %@", _pushGatewayURL); // Archive updated field [[MXKAccountManager sharedManager] saveAccounts]; @@ -373,11 +375,16 @@ - (UIColor*)userTintColor - (BOOL)pushNotificationServiceIsActive { - return ([[MXKAccountManager sharedManager] isAPNSAvailable] && _enablePushNotifications && mxSession); + BOOL pushNotificationServiceIsActive = ([[MXKAccountManager sharedManager] isAPNSAvailable] && _enablePushNotifications && mxSession); + NSLog(@"[MXKAccount][Push] pushNotificationServiceIsActive: %@", @(pushNotificationServiceIsActive)); + + return pushNotificationServiceIsActive; } - (void)setEnablePushNotifications:(BOOL)enablePushNotifications { + NSLog(@"[MXKAccount][Push] setEnablePushNotifications: %@", @(enablePushNotifications)); + if (enablePushNotifications) { _enablePushNotifications = YES; @@ -407,11 +414,16 @@ - (void)setEnablePushNotifications:(BOOL)enablePushNotifications - (BOOL)isPushKitNotificationActive { - return ([[MXKAccountManager sharedManager] isPushAvailable] && _enablePushKitNotifications && mxSession); + BOOL isPushKitNotificationActive = ([[MXKAccountManager sharedManager] isPushAvailable] && _enablePushKitNotifications && mxSession); + NSLog(@"[MXKAccount][Push] isPushKitNotificationActive: %@", @(isPushKitNotificationActive)); + + return isPushKitNotificationActive; } - (void)setEnablePushKitNotifications:(BOOL)enablePushKitNotifications { + NSLog(@"[MXKAccount][Push] setEnablePushKitNotifications: %@", @(enablePushKitNotifications)); + if (enablePushKitNotifications) { _enablePushKitNotifications = YES; @@ -423,7 +435,7 @@ - (void)setEnablePushKitNotifications:(BOOL)enablePushKitNotifications } else if (_enablePushKitNotifications) { - NSLog(@"[MXKAccount] Disable Push for %@ account", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] setEnablePushKitNotifications: Disable Push for %@ account", self.mxCredentials.userId); // Delete the pusher, report the new value only on success. [self enablePushKitPusher:NO @@ -440,6 +452,8 @@ - (void)setEnablePushKitNotifications:(BOOL)enablePushKitNotifications - (void)setEnableInAppNotifications:(BOOL)enableInAppNotifications { + NSLog(@"[MXKAccount] setEnableInAppNotifications: %@", @(enableInAppNotifications)); + _enableInAppNotifications = enableInAppNotifications; // Archive updated field @@ -1015,10 +1029,12 @@ - (void)reload:(BOOL)clearCache // Refresh the APNS pusher state for this account on this device. - (void)refreshAPNSPusher { + NSLog(@"[MXKAccount][Push] refreshAPNSPusher"); + // Check the conditions required to run the pusher if (self.pushNotificationServiceIsActive) { - NSLog(@"[MXKAccount] Refresh APNS pusher for %@ account", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] refreshAPNSPusher: Refresh APNS pusher for %@ account", self.mxCredentials.userId); // Create/restore the pusher [self enableAPNSPusher:YES @@ -1034,7 +1050,7 @@ - (void)refreshAPNSPusher else if (_enablePushNotifications && mxSession) { // Turn off pusher if user denied remote notification. - NSLog(@"[MXKAccount] Disable APNS pusher for %@ account (notifications are denied)", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] refreshAPNSPusher: Disable APNS pusher for %@ account (notifications are denied)", self.mxCredentials.userId); [self enableAPNSPusher:NO success:nil failure:nil]; } } @@ -1042,6 +1058,8 @@ - (void)refreshAPNSPusher // Enable/Disable the APNS pusher for this account on this device on the Home Server. - (void)enableAPNSPusher:(BOOL)enabled success:(void (^)(void))success failure:(void (^)(NSError *))failure { + NSLog(@"[MXKAccount][Push] enableAPNSPusher: %@", @(enabled)); + #ifdef DEBUG NSString *appId = [[NSUserDefaults standardUserDefaults] objectForKey:@"pusherAppIdDev"]; #else @@ -1052,7 +1070,7 @@ - (void)enableAPNSPusher:(BOOL)enabled success:(void (^)(void))success failure:( [self enablePusher:enabled appId:appId token:[MXKAccountManager sharedManager].apnsDeviceToken pushData:pushData success:^{ - NSLog(@"[MXKAccount] Succeeded to update APNS pusher for %@ (%d)", self.mxCredentials.userId, enabled); + NSLog(@"[MXKAccount][Push] enableAPNSPusher: Succeeded to update APNS pusher for %@ (%d)", self.mxCredentials.userId, enabled); if (success) { @@ -1070,7 +1088,7 @@ - (void)enableAPNSPusher:(BOOL)enabled success:(void (^)(void))success failure:( MXError *mxError = [[MXError alloc] initWithNSError:error]; if (mxError && [mxError.errcode isEqualToString:kMXErrCodeStringUnknown]) { - NSLog(@"[MXKAccount] APNS was already disabled for %@!", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] enableAPNSPusher: APNS was already disabled for %@!", self.mxCredentials.userId); // Ignore the error if (success) @@ -1083,11 +1101,11 @@ - (void)enableAPNSPusher:(BOOL)enabled success:(void (^)(void))success failure:( return; } - NSLog(@"[MXKAccount] Failed to disable APNS %@! (%@)", self.mxCredentials.userId, error); + NSLog(@"[MXKAccount][Push] enableAPNSPusher: Failed to disable APNS %@! (%@)", self.mxCredentials.userId, error); } else { - NSLog(@"[MXKAccount] Failed to send APNS token for %@! (%@)", self.mxCredentials.userId, error); + NSLog(@"[MXKAccount][Push] enableAPNSPusher: Failed to send APNS token for %@! (%@)", self.mxCredentials.userId, error); } if (failure) @@ -1102,10 +1120,12 @@ - (void)enableAPNSPusher:(BOOL)enabled success:(void (^)(void))success failure:( // Refresh the PushKit pusher state for this account on this device. - (void)refreshPushKitPusher { + NSLog(@"[MXKAccount][Push] refreshPushKitPusher"); + // Check the conditions required to run the pusher if (self.isPushKitNotificationActive) { - NSLog(@"[MXKAccount] Refresh PushKit pusher for %@ account", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] refreshPushKitPusher: Refresh PushKit pusher for %@ account", self.mxCredentials.userId); // Create/restore the pusher [self enablePushKitPusher:YES @@ -1121,7 +1141,7 @@ - (void)refreshPushKitPusher else if (_enablePushKitNotifications && mxSession) { // Turn off pusher if user denied remote notification. - NSLog(@"[MXKAccount] Disable PushKit pusher for %@ account (notifications are denied)", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] refreshPushKitPusher: Disable PushKit pusher for %@ account (notifications are denied)", self.mxCredentials.userId); [self enablePushKitPusher:NO success:nil failure:nil]; } } @@ -1129,6 +1149,8 @@ - (void)refreshPushKitPusher // Enable/Disable the pusher based on PushKit for this account on this device on the Home Server. - (void)enablePushKitPusher:(BOOL)enabled success:(void (^)(void))success failure:(void (^)(NSError *))failure { + NSLog(@"[MXKAccount][Push] enablePushKitPusher: %@", @(enabled)); + NSString *appId = [[NSUserDefaults standardUserDefaults] objectForKey:@"pushKitAppIdProd"]; NSMutableDictionary *pushData = [NSMutableDictionary dictionaryWithDictionary:@{@"url": self.pushGatewayURL}]; @@ -1138,10 +1160,11 @@ - (void)enablePushKitPusher:(BOOL)enabled success:(void (^)(void))success failur { [pushData addEntriesFromDictionary:options]; } - - [self enablePusher:enabled appId:appId token:[MXKAccountManager sharedManager].pushDeviceToken pushData:pushData success:^{ + + NSData *token = [MXKAccountManager sharedManager].pushDeviceToken; + [self enablePusher:enabled appId:appId token:token pushData:pushData success:^{ - NSLog(@"[MXKAccount] Succeeded to update PushKit pusher for %@ (%d)", self.mxCredentials.userId, enabled); + NSLog(@"[MXKAccount][Push] enablePushKitPusher: Succeeded to update PushKit pusher for %@. Enabled: %@. Token: %@", self.mxCredentials.userId, @(enabled), [MXKTools logForPushToken:token]); if (success) { @@ -1159,7 +1182,7 @@ - (void)enablePushKitPusher:(BOOL)enabled success:(void (^)(void))success failur MXError *mxError = [[MXError alloc] initWithNSError:error]; if (mxError && [mxError.errcode isEqualToString:kMXErrCodeStringUnknown]) { - NSLog(@"[MXKAccount] Push was already disabled for %@!", self.mxCredentials.userId); + NSLog(@"[MXKAccount][Push] enablePushKitPusher: Push was already disabled for %@!", self.mxCredentials.userId); // Ignore the error if (success) @@ -1172,11 +1195,11 @@ - (void)enablePushKitPusher:(BOOL)enabled success:(void (^)(void))success failur return; } - NSLog(@"[MXKAccount] Failed to disable Push %@! (%@)", self.mxCredentials.userId, error); + NSLog(@"[MXKAccount][Push] enablePushKitPusher: Failed to disable Push %@! (%@)", self.mxCredentials.userId, error); } else { - NSLog(@"[MXKAccount] Failed to send Push token for %@! (%@)", self.mxCredentials.userId, error); + NSLog(@"[MXKAccount][Push] enablePushKitPusher: Failed to send Push token for %@! (%@)", self.mxCredentials.userId, error); } if (failure) @@ -1190,23 +1213,25 @@ - (void)enablePushKitPusher:(BOOL)enabled success:(void (^)(void))success failur - (void)enablePusher:(BOOL)enabled appId:(NSString*)appId token:(NSData*)token pushData:(NSDictionary*)pushData success:(void (^)(void))success failure:(void (^)(NSError *))failure { + NSLog(@"[MXKAccount][Push] enablePusher: %@", @(enabled)); + // Refuse to try & turn push on if we're not logged in, it's nonsensical. if (!mxCredentials) { - NSLog(@"[MXKAccount] Not setting push token because we're not logged in"); + NSLog(@"[MXKAccount][Push] enablePusher: Not setting push token because we're not logged in"); return; } // Check whether the Push Gateway URL has been configured. if (!self.pushGatewayURL) { - NSLog(@"[MXKAccount] Not setting pusher because the Push Gateway URL is undefined"); + NSLog(@"[MXKAccount][Push] enablePusher: Not setting pusher because the Push Gateway URL is undefined"); return; } if (!appId) { - NSLog(@"[MXKAccount] Not setting pusher because pusher app id is undefined"); + NSLog(@"[MXKAccount][Push] enablePusher: Not setting pusher because pusher app id is undefined"); return; } @@ -1226,12 +1251,12 @@ - (void)enablePusher:(BOOL)enabled appId:(NSString*)appId token:(NSData*)token p unsigned char c = [alphabet characterAtIndex:arc4random() % alphabet.length]; profileTag = [profileTag stringByAppendingFormat:@"%c", c]; } - NSLog(@"[MXKAccount] Generated fresh profile tag: %@", profileTag); + NSLog(@"[MXKAccount][Push] enablePusher: Generated fresh profile tag: %@", profileTag); [[NSUserDefaults standardUserDefaults] setValue:profileTag forKey:@"pusherProfileTag"]; } else { - NSLog(@"[MXKAccount] Using existing profile tag: %@", profileTag); + NSLog(@"[MXKAccount][Push] enablePusher: Using existing profile tag: %@", profileTag); } NSObject *kind = enabled ? @"http" : [NSNull null]; @@ -1248,7 +1273,7 @@ - (void)enablePusher:(BOOL)enabled appId:(NSString*)appId token:(NSData*)token p break; } } - NSLog(@"[MXKAccount] append flag: %d", append); + NSLog(@"[MXKAccount][Push] enablePusher: append flag: %d", append); MXRestClient *restCli = self.mxRestClient; diff --git a/MatrixKit/Models/Account/MXKAccountManager.m b/MatrixKit/Models/Account/MXKAccountManager.m index 118245a44..89f5172e2 100644 --- a/MatrixKit/Models/Account/MXKAccountManager.m +++ b/MatrixKit/Models/Account/MXKAccountManager.m @@ -19,6 +19,8 @@ #import "MXKAccountManager.h" #import "MXKAppSettings.h" +#import "MXKTools.h" + static NSString *const kMXKAccountsKey = @"accounts"; NSString *const kMXKAccountManagerDidAddAccountNotification = @"kMXKAccountManagerDidAddAccountNotification"; @@ -285,15 +287,19 @@ - (NSData *)apnsDeviceToken [[NSUserDefaults standardUserDefaults] removeObjectForKey:@"apnsDeviceToken"]; token = nil; } + + NSLog(@"[MXKAccountManager][Push] apnsDeviceToken: %@", [MXKTools logForPushToken:token]); return token; } - (void)setApnsDeviceToken:(NSData *)apnsDeviceToken { + NSLog(@"[MXKAccountManager][Push] setApnsDeviceToken: %@", [MXKTools logForPushToken:apnsDeviceToken]); + NSData *oldToken = self.apnsDeviceToken; if (!apnsDeviceToken.length) { - NSLog(@"[MXKAccountManager] reset APNS device token"); + NSLog(@"[MXKAccountManager][Push] setApnsDeviceToken: reset APNS device token"); if (oldToken) { @@ -312,7 +318,7 @@ - (void)setApnsDeviceToken:(NSData *)apnsDeviceToken if (!oldToken) { - NSLog(@"[MXKAccountManager] set APNS device token"); + NSLog(@"[MXKAccountManager][Push] setApnsDeviceToken: set APNS device token"); [[NSUserDefaults standardUserDefaults] setObject:apnsDeviceToken forKey:@"apnsDeviceToken"]; @@ -324,7 +330,7 @@ - (void)setApnsDeviceToken:(NSData *)apnsDeviceToken } else if (![oldToken isEqualToData:apnsDeviceToken]) { - NSLog(@"[MXKAccountManager] update APNS device token"); + NSLog(@"[MXKAccountManager][Push] setApnsDeviceToken: update APNS device token"); // Delete the pushers related to the old token for (MXKAccount *account in activeAccounts) @@ -340,7 +346,7 @@ - (void)setApnsDeviceToken:(NSData *)apnsDeviceToken { if (account.pushNotificationServiceIsActive) { - NSLog(@"[MXKAccountManager] Resync APNS for %@ account", account.mxCredentials.userId); + NSLog(@"[MXKAccountManager][Push] setApnsDeviceToken: Resync APNS for %@ account", account.mxCredentials.userId); account.enablePushNotifications = YES; } } @@ -365,10 +371,14 @@ - (BOOL)isAPNSAvailable UIUserNotificationSettings *settings = [sharedApplication currentUserNotificationSettings]; isRemoteNotificationsAllowed = (settings.types != UIUserNotificationTypeNone); - NSLog(@"[MXKAccountManager] the user %@ remote notification", (isRemoteNotificationsAllowed ? @"allowed" : @"denied")); + NSLog(@"[MXKAccountManager][Push] isAPNSAvailable: The user %@ remote notification", (isRemoteNotificationsAllowed ? @"allowed" : @"denied")); } - - return (isRemoteNotificationsAllowed && self.apnsDeviceToken); + + BOOL isAPNSAvailable = (isRemoteNotificationsAllowed && self.apnsDeviceToken); + + NSLog(@"[MXKAccountManager][Push] isAPNSAvailable: %@", @(isAPNSAvailable)); + + return isAPNSAvailable; } - (NSData *)pushDeviceToken @@ -380,20 +390,27 @@ - (NSData *)pushDeviceToken [[NSUserDefaults standardUserDefaults] removeObjectForKey:@"pushOptions"]; token = nil; } + + NSLog(@"[MXKAccountManager][Push] pushDeviceToken: %@", [MXKTools logForPushToken:token]); return token; } - (NSDictionary *)pushOptions { - return [[NSUserDefaults standardUserDefaults] objectForKey:@"pushOptions"]; + NSDictionary *pushOptions = [[NSUserDefaults standardUserDefaults] objectForKey:@"pushOptions"]; + + NSLog(@"[MXKAccountManager][Push] pushOptions: %@", pushOptions); + return pushOptions; } - (void)setPushDeviceToken:(NSData *)pushDeviceToken withPushOptions:(NSDictionary *)pushOptions { + NSLog(@"[MXKAccountManager][Push] setPushDeviceToken: %@ withPushOptions: %@", [MXKTools logForPushToken:pushDeviceToken], pushOptions); + NSData *oldToken = self.pushDeviceToken; if (!pushDeviceToken.length) { - NSLog(@"[MXKAccountManager] reset Push device token"); + NSLog(@"[MXKAccountManager][Push] setPushDeviceToken: Reset Push device token"); if (oldToken) { @@ -413,7 +430,7 @@ - (void)setPushDeviceToken:(NSData *)pushDeviceToken withPushOptions:(NSDictiona if (!oldToken) { - NSLog(@"[MXKAccountManager] set Push device token"); + NSLog(@"[MXKAccountManager][Push] setPushDeviceToken: Set Push device token"); [[NSUserDefaults standardUserDefaults] setObject:pushDeviceToken forKey:@"pushDeviceToken"]; if (pushOptions) @@ -433,7 +450,7 @@ - (void)setPushDeviceToken:(NSData *)pushDeviceToken withPushOptions:(NSDictiona } else if (![oldToken isEqualToData:pushDeviceToken]) { - NSLog(@"[MXKAccountManager] update Push device token"); + NSLog(@"[MXKAccountManager][Push] setPushDeviceToken: Update Push device token"); // Delete the pushers related to the old token for (MXKAccount *account in activeAccounts) @@ -457,9 +474,13 @@ - (void)setPushDeviceToken:(NSData *)pushDeviceToken withPushOptions:(NSDictiona { if (account.isPushKitNotificationActive) { - NSLog(@"[MXKAccountManager] Resync Push for %@ account", account.mxCredentials.userId); + NSLog(@"[MXKAccountManager][Push] setPushDeviceToken: Resync Push for %@ account", account.mxCredentials.userId); account.enablePushKitNotifications = YES; } + else + { + NSLog(@"[MXKAccountManager][Push] setPushDeviceToken: isPushKitNotificationActive = NO for %@ account. Do not enable Push", account.mxCredentials.userId); + } } } } @@ -482,10 +503,13 @@ - (BOOL)isPushAvailable UIUserNotificationSettings *settings = [sharedApplication currentUserNotificationSettings]; isRemoteNotificationsAllowed = (settings.types != UIUserNotificationTypeNone); - NSLog(@"[MXKAccountManager] the user %@ remote notification", (isRemoteNotificationsAllowed ? @"allowed" : @"denied")); + NSLog(@"[MXKAccountManager][Push] isPushAvailable: The user %@ remote notification", (isRemoteNotificationsAllowed ? @"allowed" : @"denied")); } - - return (isRemoteNotificationsAllowed && self.pushDeviceToken); + + BOOL isPushAvailable = (isRemoteNotificationsAllowed && self.pushDeviceToken); + + NSLog(@"[MXKAccountManager][Push] isPushAvailable: %@", @(isPushAvailable)); + return isPushAvailable; } #pragma mark - diff --git a/MatrixKit/Utils/MXKTools.h b/MatrixKit/Utils/MXKTools.h index 7ad93b047..de5d4a866 100644 --- a/MatrixKit/Utils/MXKTools.h +++ b/MatrixKit/Utils/MXKTools.h @@ -388,4 +388,14 @@ manualChangeMessageForVideo:(NSString*)manualChangeMessageForVideo */ + (void)enumerateMarkedBlockquotesInAttributedString:(NSAttributedString*)attributedString usingBlock:(void (^)(NSRange range, BOOL *stop))block; +#pragma mark - Push + +/** + Trim push token in order to log it. + + @param pushToken the token to trim. + @return a trimmed description. + */ ++ (NSString*)logForPushToken:(NSData*)pushToken; + @end diff --git a/MatrixKit/Utils/MXKTools.m b/MatrixKit/Utils/MXKTools.m index 4e2bbe860..ec0371278 100644 --- a/MatrixKit/Utils/MXKTools.m +++ b/MatrixKit/Utils/MXKTools.m @@ -1222,4 +1222,13 @@ + (void)enumerateMarkedBlockquotesInAttributedString:(NSAttributedString*)attrib }]; } +#pragma mark - Push + +// Trim push token before printing it in logs ++ (NSString*)logForPushToken:(NSData*)pushToken +{ + NSUInteger len = ((pushToken.length > 8) ? 8 : pushToken.length / 2); + return [NSString stringWithFormat:@"%@...", [pushToken subdataWithRange:NSMakeRange(0, len)]]; +} + @end