From 3d5f7e6bf3640c7fdf520d957b13d29e5fbc8986 Mon Sep 17 00:00:00 2001 From: Michael Kirk Date: Tue, 13 Feb 2018 18:16:05 -0800 Subject: [PATCH] Clean up logging - tag all log lines for easier filtering - use up-to-date database path // FREEBIE --- Signal/src/AppDelegate.m | 2 +- .../OWS106EnsureProfileComplete.swift | 2 +- .../src/Storage/OWSOrphanedDataCleaner.m | 46 +++++++++---------- SignalServiceKit/src/Storage/OWSStorage.m | 2 +- .../src/Storage/TSStorageManager.m | 8 ++-- SignalServiceKit/src/Util/Cryptography.m | 14 +++--- .../ShareViewController.swift | 2 +- 7 files changed, 39 insertions(+), 37 deletions(-) diff --git a/Signal/src/AppDelegate.m b/Signal/src/AppDelegate.m index 9f5ffd440..f6ef22a7b 100644 --- a/Signal/src/AppDelegate.m +++ b/Signal/src/AppDelegate.m @@ -1091,7 +1091,7 @@ static NSString *const kURLHostVerifyPrefix = @"verify"; } self.hasInitialRootViewController = YES; - DDLogInfo(@"Presenting initial root view controller"); + DDLogInfo(@"%@ Presenting initial root view controller", self.logTag); if ([TSAccountManager isRegistered]) { HomeViewController *homeView = [HomeViewController new]; diff --git a/SignalMessaging/environment/migrations/OWS106EnsureProfileComplete.swift b/SignalMessaging/environment/migrations/OWS106EnsureProfileComplete.swift index 384c4791b..dbeac5ae7 100644 --- a/SignalMessaging/environment/migrations/OWS106EnsureProfileComplete.swift +++ b/SignalMessaging/environment/migrations/OWS106EnsureProfileComplete.swift @@ -68,7 +68,7 @@ public class OWS106EnsureProfileComplete: OWSDatabaseMigration { var isCompleted = false strongSelf.ensureProfileComplete().then { _ -> Void in guard isCompleted == false else { - Logger.info("Already saved. Skipping redundant call.") + Logger.info("\(strongSelf.TAG) Already saved. Skipping redundant call.") return } Logger.info("\(strongSelf.TAG) complete. Canceling timer and saving.") diff --git a/SignalServiceKit/src/Storage/OWSOrphanedDataCleaner.m b/SignalServiceKit/src/Storage/OWSOrphanedDataCleaner.m index 5fc6ce190..44edb3a82 100644 --- a/SignalServiceKit/src/Storage/OWSOrphanedDataCleaner.m +++ b/SignalServiceKit/src/Storage/OWSOrphanedDataCleaner.m @@ -76,18 +76,18 @@ NS_ASSUME_NONNULL_BEGIN }]; }]; - CleanupLogDebug(@"fileCount: %zd", fileCount); - CleanupLogDebug(@"totalFileSize: %lld", totalFileSize); - CleanupLogDebug(@"attachmentStreams: %d", attachmentStreamCount); - CleanupLogDebug(@"attachmentStreams with file paths: %zd", attachmentFilePaths.count); + CleanupLogDebug(@"%@ fileCount: %zd", self.logTag, fileCount); + CleanupLogDebug(@"%@ totalFileSize: %lld", self.logTag, totalFileSize); + CleanupLogDebug(@"%@ attachmentStreams: %d", self.logTag, attachmentStreamCount); + CleanupLogDebug(@"%@ attachmentStreams with file paths: %zd", self.logTag, attachmentFilePaths.count); NSMutableSet *orphanDiskFilePaths = [diskFilePaths mutableCopy]; [orphanDiskFilePaths minusSet:attachmentFilePaths]; NSMutableSet *missingAttachmentFilePaths = [attachmentFilePaths mutableCopy]; [missingAttachmentFilePaths minusSet:diskFilePaths]; - CleanupLogDebug(@"orphan disk file paths: %zd", orphanDiskFilePaths.count); - CleanupLogDebug(@"missing attachment file paths: %zd", missingAttachmentFilePaths.count); + CleanupLogDebug(@"%@ orphan disk file paths: %zd", self.logTag, orphanDiskFilePaths.count); + CleanupLogDebug(@"%@ missing attachment file paths: %zd", self.logTag, missingAttachmentFilePaths.count); [self printPaths:orphanDiskFilePaths.allObjects label:@"orphan disk file paths"]; [self printPaths:missingAttachmentFilePaths.allObjects label:@"missing attachment file paths"]; @@ -116,17 +116,17 @@ NS_ASSUME_NONNULL_BEGIN }]; }]; - CleanupLogDebug(@"attachmentIds: %zd", attachmentIds.count); - CleanupLogDebug(@"messageAttachmentIds: %zd", messageAttachmentIds.count); + CleanupLogDebug(@"%@ attachmentIds: %zd", self.logTag, attachmentIds.count); + CleanupLogDebug(@"%@ messageAttachmentIds: %zd", self.logTag, messageAttachmentIds.count); NSMutableSet *orphanAttachmentIds = [attachmentIds mutableCopy]; [orphanAttachmentIds minusSet:messageAttachmentIds]; NSMutableSet *missingAttachmentIds = [messageAttachmentIds mutableCopy]; [missingAttachmentIds minusSet:attachmentIds]; - CleanupLogDebug(@"orphan attachmentIds: %zd", orphanAttachmentIds.count); - CleanupLogDebug(@"missing attachmentIds: %zd", missingAttachmentIds.count); - CleanupLogDebug(@"orphan interactions: %zd", orphanInteractionIds.count); + CleanupLogDebug(@"%@ orphan attachmentIds: %zd", self.logTag, orphanAttachmentIds.count); + CleanupLogDebug(@"%@ missing attachmentIds: %zd", self.logTag, missingAttachmentIds.count); + CleanupLogDebug(@"%@ orphan interactions: %zd", self.logTag, orphanInteractionIds.count); // We need to avoid cleaning up new attachments and files that are still in the process of // being created/written, so we don't clean up anything recent. @@ -145,10 +145,10 @@ NS_ASSUME_NONNULL_BEGIN TSInteraction *interaction = [TSInteraction fetchObjectWithUniqueID:interactionId transaction:transaction]; if (!interaction) { // This could just be a race condition, but it should be very unlikely. - OWSFail(@"Could not load interaction: %@", interactionId); + OWSFail(@"%@ Could not load interaction: %@", self.logTag, interactionId); continue; } - CleanupLogInfo(@"Removing orphan message: %@", interaction.uniqueId); + CleanupLogInfo(@"%@ Removing orphan message: %@", self.logTag, interaction.uniqueId); [interaction removeWithTransaction:transaction]; } for (NSString *attachmentId in orphanAttachmentIds) { @@ -165,11 +165,11 @@ NS_ASSUME_NONNULL_BEGIN TSAttachmentStream *attachmentStream = (TSAttachmentStream *)attachment; // Don't delete attachments which were created in the last N minutes. if (fabs([attachmentStream.creationTimestamp timeIntervalSinceNow]) < kMinimumOrphanAge) { - CleanupLogInfo(@"Skipping orphan attachment due to age: %f", + CleanupLogInfo(@"%@ Skipping orphan attachment due to age: %f", self.logTag, fabs([attachmentStream.creationTimestamp timeIntervalSinceNow])); continue; } - CleanupLogInfo(@"Removing orphan attachment: %@", attachmentStream.uniqueId); + CleanupLogInfo(@"%@ Removing orphan attachmentStream from DB: %@", self.logTag, attachmentStream.uniqueId); [attachmentStream removeWithTransaction:transaction]; } }]; @@ -178,20 +178,20 @@ NS_ASSUME_NONNULL_BEGIN NSError *error; NSDictionary *attributes = [[NSFileManager defaultManager] attributesOfItemAtPath:filePath error:&error]; if (!attributes || error) { - OWSFail(@"Could not get attributes of file at: %@", filePath); + OWSFail(@"%@ Could not get attributes of file at: %@", self.logTag, filePath); continue; } // Don't delete files which were created in the last N minutes. if (fabs([attributes.fileModificationDate timeIntervalSinceNow]) < kMinimumOrphanAge) { - CleanupLogInfo(@"Skipping orphan attachment file due to age: %f", + CleanupLogInfo(@"%@ Skipping orphan attachment file due to age: %f", self.logTag, fabs([attributes.fileModificationDate timeIntervalSinceNow])); continue; } - CleanupLogInfo(@"Removing orphan attachment file: %@", filePath); + CleanupLogInfo(@"%@ Deleting orphan attachment file: %@", self.logTag, filePath); [[NSFileManager defaultManager] removeItemAtPath:filePath error:&error]; if (error) { - OWSFail(@"Could not remove orphan file at: %@", filePath); + OWSFail(@"%@ Could not remove orphan file at: %@", self.logTag, filePath); } } @@ -205,14 +205,14 @@ NS_ASSUME_NONNULL_BEGIN + (void)printPaths:(NSArray *)paths label:(NSString *)label { for (NSString *path in [paths sortedArrayUsingSelector:@selector(compare:)]) { - CleanupLogDebug(@"%@: %@", label, path); + CleanupLogDebug(@"%@ %@: %@", self.logTag, label, path); } } + (NSSet *)filePathsInAttachmentsFolder { NSString *attachmentsFolder = [TSAttachmentStream attachmentsFolder]; - CleanupLogDebug(@"attachmentsFolder: %@", attachmentsFolder); + CleanupLogDebug(@"%@ attachmentsFolder: %@", self.logTag, attachmentsFolder); return [self filePathsInDirectory:attachmentsFolder]; } @@ -223,7 +223,7 @@ NS_ASSUME_NONNULL_BEGIN NSError *error; NSArray *fileNames = [[NSFileManager defaultManager] contentsOfDirectoryAtPath:dirPath error:&error]; if (error) { - OWSFail(@"contentsOfDirectoryAtPath error: %@", error); + OWSFail(@"%@ contentsOfDirectoryAtPath error: %@", self.logTag, error); return [NSSet new]; } for (NSString *fileName in fileNames) { @@ -244,7 +244,7 @@ NS_ASSUME_NONNULL_BEGIN NSError *error; NSNumber *fileSize = [[NSFileManager defaultManager] attributesOfItemAtPath:filePath error:&error][NSFileSize]; if (error) { - OWSFail(@"attributesOfItemAtPath: %@ error: %@", filePath, error); + OWSFail(@"%@ attributesOfItemAtPath: %@ error: %@", self.logTag, filePath, error); return 0; } return fileSize.longLongValue; diff --git a/SignalServiceKit/src/Storage/OWSStorage.m b/SignalServiceKit/src/Storage/OWSStorage.m index 967588424..c886aaa74 100644 --- a/SignalServiceKit/src/Storage/OWSStorage.m +++ b/SignalServiceKit/src/Storage/OWSStorage.m @@ -693,7 +693,7 @@ typedef NSData *_Nullable (^CreateDatabaseMetadataBlock)(void); OWSRaiseException( OWSStorageExceptionName_DatabasePasswordUnwritable, @"Setting keychain value failed with error: %@", error); } else { - DDLogWarn(@"Successfully set new keychain value."); + DDLogWarn(@"%@ Successfully set new keychain value.", self.logTag); } } diff --git a/SignalServiceKit/src/Storage/TSStorageManager.m b/SignalServiceKit/src/Storage/TSStorageManager.m index c3f642b3f..47d2775ed 100644 --- a/SignalServiceKit/src/Storage/TSStorageManager.m +++ b/SignalServiceKit/src/Storage/TSStorageManager.m @@ -151,9 +151,9 @@ void runAsyncRegistrationsForStorage(OWSStorage *storage) + (void)protectFiles { - DDLogInfo(@"%@ Database file size: %@", self.logTag, [OWSFileSystem fileSizeOfPath:self.legacyDatabaseFilePath]); - DDLogInfo(@"%@ \t SHM file size: %@", self.logTag, [OWSFileSystem fileSizeOfPath:self.legacyDatabaseFilePath_SHM]); - DDLogInfo(@"%@ \t WAL file size: %@", self.logTag, [OWSFileSystem fileSizeOfPath:self.legacyDatabaseFilePath_WAL]); + DDLogInfo(@"%@ Database file size: %@", self.logTag, [OWSFileSystem fileSizeOfPath:self.sharedDataDatabaseFilePath]); + DDLogInfo(@"%@ \t SHM file size: %@", self.logTag, [OWSFileSystem fileSizeOfPath:self.sharedDataDatabaseFilePath_SHM]); + DDLogInfo(@"%@ \t WAL file size: %@", self.logTag, [OWSFileSystem fileSizeOfPath:self.sharedDataDatabaseFilePath_WAL]); // The old database location was in the Document directory, // so protect the database files individually. @@ -241,7 +241,7 @@ void runAsyncRegistrationsForStorage(OWSStorage *storage) + (NSString *)databaseFilePath { - DDLogVerbose(@"databasePath: %@", TSStorageManager.sharedDataDatabaseFilePath); + DDLogVerbose(@"%@ databasePath: %@", self.logTag, TSStorageManager.sharedDataDatabaseFilePath); return self.sharedDataDatabaseFilePath; } diff --git a/SignalServiceKit/src/Util/Cryptography.m b/SignalServiceKit/src/Util/Cryptography.m index e4cea1a2d..761f24090 100755 --- a/SignalServiceKit/src/Util/Cryptography.m +++ b/SignalServiceKit/src/Util/Cryptography.m @@ -1,5 +1,5 @@ // -// Copyright (c) 2017 Open Whisper Systems. All rights reserved. +// Copyright (c) 2018 Open Whisper Systems. All rights reserved. // #import "Cryptography.h" @@ -213,7 +213,9 @@ const NSUInteger kAES256_KeyByteLength = 32; } if (hmac == nil || ![ourHmacData ows_constantTimeIsEqualToData:hmac]) { - DDLogError(@"%@ %s Bad HMAC on decrypting payload. Their MAC: %@, our MAC: %@", + DDLogError(@"%@ Bad HMAC on decrypting payload.", self.logTag); + // Don't log HMAC in prod + DDLogDebug(@"%@ %s Bad HMAC on decrypting payload. Their MAC: %@, our MAC: %@", self.logTag, __PRETTY_FUNCTION__, hmac, @@ -223,11 +225,13 @@ const NSUInteger kAES256_KeyByteLength = 32; // Optionally verify digest of: version? || iv || encrypted data || hmac if (digest) { - DDLogDebug(@"%@ %s verifying their digest: %@", self.logTag, __PRETTY_FUNCTION__, digest); + DDLogDebug(@"%@ verifying their digest", self.logTag); [dataToAuth appendData:ourHmacData]; NSData *ourDigest = [Cryptography computeSHA256Digest:dataToAuth]; if (!ourDigest || ![ourDigest ows_constantTimeIsEqualToData:digest]) { - DDLogWarn(@"%@ Bad digest on decrypting payload. Their digest: %@, our digest: %@", + DDLogWarn(@"%@ Bad digest on decrypting payload", self.logTag); + // Don't log digest in prod + DDLogDebug(@"%@ Bad digest on decrypting payload. Their digest: %@, our digest: %@", self.logTag, digest, ourDigest); @@ -433,13 +437,11 @@ const NSUInteger kAES256_KeyByteLength = 32; // compute hmac of: iv || encrypted data NSData *hmac = [Cryptography truncatedSHA256HMAC:encryptedPaddedData withHMACKey:hmacKey truncation:HMAC256_OUTPUT_LENGTH]; - DDLogVerbose(@"%@ computed hmac: %@", self.logTag, hmac); [encryptedPaddedData appendData:hmac]; // compute digest of: iv || encrypted data || hmac *outDigest = [self computeSHA256Digest:encryptedPaddedData]; - DDLogVerbose(@"%@ computed digest: %@", self.logTag, *outDigest); return [encryptedPaddedData copy]; } diff --git a/SignalShareExtension/ShareViewController.swift b/SignalShareExtension/ShareViewController.swift index 595c6434d..406fb9d15 100644 --- a/SignalShareExtension/ShareViewController.swift +++ b/SignalShareExtension/ShareViewController.swift @@ -283,7 +283,7 @@ public class ShareViewController: UIViewController, ShareViewDelegate, SAEFailed } hasInitialRootViewController = true - Logger.info("Presenting initial root view controller") + Logger.info("\(logTag) Presenting initial root view controller") if !TSAccountManager.isRegistered() { showNotRegisteredView()