From 208733cfce79e93e84f7bb3d75e6d663431a9e1a Mon Sep 17 00:00:00 2001 From: Felix Schwarz Date: Sun, 20 Jan 2019 16:47:30 +0100 Subject: [PATCH] - Add verbose logging to FileProviderExtension to track the commands received by iOS and the results that were returned --- .../FileProviderExtension.h | 17 +++++ .../FileProviderExtension.m | 71 +++++++++++++++++-- 2 files changed, 84 insertions(+), 4 deletions(-) diff --git a/ownCloud File Provider/FileProviderExtension.h b/ownCloud File Provider/FileProviderExtension.h index c4d0013de..f6863e9bf 100644 --- a/ownCloud File Provider/FileProviderExtension.h +++ b/ownCloud File Provider/FileProviderExtension.h @@ -30,3 +30,20 @@ @end +#define FPLogCmdBegin(command, format,...) \ + NSString *actionLogCmdUUID = nil; \ + NSArray *actionLogTags = nil; \ + if (OCLogger.logLevel <= OCLogLevelDebug) \ + { \ + actionLogCmdUUID = NSUUID.UUID.UUIDString; \ + actionLogTags = @[command, @"FPAction", OCLogTagTypedID(@"CmdUUID", actionLogCmdUUID) ]; \ + \ + [[OCLogger sharedLogger] appendLogLevel:OCLogLevelDebug functionName:@(__PRETTY_FUNCTION__) file:@(__FILE__) line:__LINE__ tags:OCLogAddTags(self,actionLogTags) message:format, ##__VA_ARGS__]; \ + } \ + +#define FPLogCmd(format,...) \ + if (OCLogger.logLevel <= OCLogLevelDebug) \ + { \ + [[OCLogger sharedLogger] appendLogLevel:OCLogLevelDebug functionName:@(__PRETTY_FUNCTION__) file:@(__FILE__) line:__LINE__ tags:OCLogAddTags(self,actionLogTags) message:format, ##__VA_ARGS__]; \ + } \ + diff --git a/ownCloud File Provider/FileProviderExtension.m b/ownCloud File Provider/FileProviderExtension.m index 8f8004691..2c8d90d9d 100644 --- a/ownCloud File Provider/FileProviderExtension.m +++ b/ownCloud File Provider/FileProviderExtension.m @@ -211,10 +211,14 @@ - (void)startProvidingItemAtURL:(NSURL *)provideAtURL completionHandler:(void (^ NSFileProviderItemIdentifier itemIdentifier = nil; NSFileProviderItem item = nil; + FPLogCmdBegin(@"StartProviding", @"Start of startProvidingItemAtURL=%@", provideAtURL); + if ((itemIdentifier = [self persistentIdentifierForItemAtURL:provideAtURL]) != nil) { if ((item = [self itemForIdentifier:itemIdentifier error:&error]) != nil) { + FPLogCmdBegin(@"StartProviding", @"Downloading %@", item); + [self.core downloadItem:(OCItem *)item options:nil resultHandler:^(NSError *error, OCCore *core, OCItem *item, OCFile *file) { OCLogDebug(@"Starting to provide file:\nPAU: %@\nFURL: %@\nID: %@\nErr: %@\nlocalRelativePath: %@", provideAtURL, file.url, item.itemIdentifier, error, item.localRelativePath); @@ -224,6 +228,8 @@ - (void)startProvidingItemAtURL:(NSURL *)provideAtURL completionHandler:(void (^ error = nil; } + FPLogCmd(@"Completed with error=%@", error); + completionHandler(error); }]; @@ -231,6 +237,8 @@ - (void)startProvidingItemAtURL:(NSURL *)provideAtURL completionHandler:(void (^ } } + FPLogCmd(@"Completed with featureUnsupportedError"); + completionHandler([NSError errorWithDomain:NSCocoaErrorDomain code:NSFeatureUnsupportedError userInfo:@{}]); // ### Apple template comments: ### @@ -300,7 +308,7 @@ - (void)stopProvidingItemAtURL:(NSURL *)url NSFileProviderItemIdentifier itemIdentifier = nil; NSFileProviderItem item = nil; - OCLogDebug(@"Stop providing file at %@", url); + FPLogCmdBegin(@"StopProviding", @"Start of stopProvidingItemAtURL=%@", url); if ((itemIdentifier = [self persistentIdentifierForItemAtURL:url]) != nil) { @@ -317,7 +325,7 @@ - (void)stopProvidingItemAtURL:(NSURL *)url } } - OCLogDebug(@"Item %@ is downloading %d: %@", item, item.isDownloading, downloadProgress); + FPLogCmd(@"Item %@ is downloading %d: %@", item, item.isDownloading, downloadProgress); } } @@ -377,13 +385,18 @@ - (void)createDirectoryWithName:(NSString *)directoryName inParentItemIdentifier NSError *error = nil; OCItem *parentItem; + FPLogCmdBegin(@"CreateDir", @"Start of createDirectoryWithName=%@, inParentItemIdentifier=%@", directoryName, parentItemIdentifier); + if ((parentItem = (OCItem *)[self itemForIdentifier:parentItemIdentifier error:&error]) != nil) { // Detect collission with existing items OCItem *existingItem; + FPLogCmd(@"Creating folder %@ inside %@", directoryName, parentItem.path); + if ((existingItem = [self findKnownExistingItemInParent:parentItem withName:directoryName]) != nil) { + FPLogCmd(@"Completed with collission with existingItem=%@ (locally detected)", existingItem); completionHandler(nil, [NSError fileProviderErrorForCollisionWithItem:existingItem]); return; } @@ -398,17 +411,23 @@ - (void)createDirectoryWithName:(NSString *)directoryName inParentItemIdentifier if ((existingItem = [self findKnownExistingItemInParent:parentItem withName:directoryName]) != nil) { + FPLogCmd(@"Completed with collission with existingItem=%@ (server response)", existingItem); completionHandler(nil, [NSError fileProviderErrorForCollisionWithItem:existingItem]); return; } } } + + FPLogCmd(@"Completed with item=%@, error=%@", item, error); + completionHandler(item, error); }]; } else { + FPLogCmd(@"Completed with parentItemNotFoundFor=%@, error=%@", parentItemIdentifier, error); + completionHandler(nil, error); } } @@ -416,17 +435,24 @@ - (void)createDirectoryWithName:(NSString *)directoryName inParentItemIdentifier - (void)reparentItemWithIdentifier:(NSFileProviderItemIdentifier)itemIdentifier toParentItemWithIdentifier:(NSFileProviderItemIdentifier)parentItemIdentifier newName:(NSString *)newName completionHandler:(void (^)(NSFileProviderItem _Nullable, NSError * _Nullable))completionHandler { NSError *error = nil; - OCItem *item, *parentItem; + OCItem *item=nil, *parentItem=nil; + + FPLogCmdBegin(@"Reparent", @"Start of reparentItemWithIdentifier=%@, toParentItemWithIdentifier=%@, newName=%@", itemIdentifier, parentItemIdentifier, newName); if (((item = (OCItem *)[self itemForIdentifier:itemIdentifier error:&error]) != nil) && ((parentItem = (OCItem *)[self itemForIdentifier:parentItemIdentifier error:&error]) != nil)) { + FPLogCmd(@"Moving %@ to %@ as %@", item, parentItem, ((newName != nil) ? newName : item.name)); + [self.core moveItem:item to:parentItem withName:((newName != nil) ? newName : item.name) options:nil resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { + FPLogCmd(@"Completed with item=%@, error=%@", item, error); + completionHandler(item, error); }]; } else { + FPLogCmd(@"Completed with item=%@ or parentItem=%@ not found, error=%@", item, parentItem, error); completionHandler(nil, error); } } @@ -436,15 +462,21 @@ - (void)renameItemWithIdentifier:(NSFileProviderItemIdentifier)itemIdentifier to NSError *error = nil; OCItem *item, *parentItem; + FPLogCmdBegin(@"Rename", @"Start of renameItemWithIdentifier=%@, toName=%@", itemIdentifier, itemName); + if (((item = (OCItem *)[self itemForIdentifier:itemIdentifier error:&error]) != nil) && ((parentItem = (OCItem *)[self itemForIdentifier:item.parentFileID error:&error]) != nil)) { + FPLogCmd(@"Renaming %@ in %@ to %@", item, parentItem, itemName); + [self.core moveItem:item to:parentItem withName:itemName options:nil resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { + FPLogCmd(@"Completed with item=%@, error=%@", item, error); completionHandler(item, error); }]; } else { + FPLogCmd(@"Completed with item=%@ or parentItem=%@ not found, error=%@", item, parentItem, error); completionHandler(nil, error); } } @@ -454,14 +486,20 @@ - (void)trashItemWithIdentifier:(NSFileProviderItemIdentifier)itemIdentifier com NSError *error = nil; OCItem *item; + FPLogCmdBegin(@"Trash", @"Start of trashItemWithIdentifier=%@", itemIdentifier); + if ((item = (OCItem *)[self itemForIdentifier:itemIdentifier error:&error]) != nil) { + FPLogCmd(@"Trashing %@", item); + [self.core deleteItem:item requireMatch:YES resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { + FPLogCmd(@"Completed with error=%@", error); completionHandler(nil, error); }]; } else { + FPLogCmd(@"Completed with item=%@ not found, error=%@", item, error); completionHandler(nil, error); } } @@ -471,14 +509,20 @@ - (void)deleteItemWithIdentifier:(NSFileProviderItemIdentifier)itemIdentifier co NSError *error = nil; OCItem *item; + FPLogCmdBegin(@"Delete", @"Start of deleteItemWithIdentifier=%@", itemIdentifier); + if ((item = (OCItem *)[self itemForIdentifier:itemIdentifier error:&error]) != nil) { + FPLogCmd(@"Deleting %@", item); + [self.core deleteItem:item requireMatch:YES resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { + FPLogCmd(@"Completed with error=%@", error); completionHandler(error); }]; } else { + FPLogCmd(@"Completed with item=%@ not found, error=%@", item, error); completionHandler(error); } } @@ -491,6 +535,8 @@ - (void)importDocumentAtURL:(NSURL *)fileURL toParentItemIdentifier:(NSFileProvi NSString *importFileName = fileURL.lastPathComponent; OCItem *parentItem; + FPLogCmdBegin(@"Import", @"Start of importDocumentAtURL=%@, toParentItemIdentifier=%@", fileURL, parentItemIdentifier); + // Detect import of documents from our own internal storage (=> used by Files.app for duplication of files) isImportingFromVault = [fileURL.path hasPrefix:self.core.vault.filesRootURL.path]; @@ -515,12 +561,16 @@ - (void)importDocumentAtURL:(NSURL *)fileURL toParentItemIdentifier:(NSFileProvi if ((existingItem = [self findKnownExistingItemInParent:parentItem withName:importFileName]) != nil) { // Return collission error + FPLogCmd(@"Completed with collission with existingItem=%@ (local)", existingItem); completionHandler(nil, [NSError fileProviderErrorForCollisionWithItem:existingItem]); return; } + FPLogCmd(@"Importing %@ at %@ fromURL %@", importFileName, parentItem, fileURL); + // Start import [self.core importFileNamed:importFileName at:parentItem fromURL:fileURL isSecurityScoped:YES options:@{ OCCoreOptionImportByCopying : @(importByCopying) } placeholderCompletionHandler:^(NSError *error, OCItem *item) { + FPLogCmd(@"Completed with placeholderItem=%@, error=%@", item, error); completionHandler(item, error); } resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { if ([error.domain isEqual:OCHTTPStatusErrorDomain] && (error.code == OCHTTPStatusCodePRECONDITION_FAILED)) @@ -540,6 +590,7 @@ - (void)importDocumentAtURL:(NSURL *)fileURL toParentItemIdentifier:(NSFileProvi if (placeholderItem.isPlaceholder) { + FPLogCmd(@"Completed with fileAlreadyExistsAs=%@", placeholderItem); [placeholderItem setUploadingError:[NSError fileProviderErrorForCollisionWithItem:placeholderItem]]; } } @@ -548,6 +599,7 @@ - (void)importDocumentAtURL:(NSURL *)fileURL toParentItemIdentifier:(NSFileProvi } else { + FPLogCmd(@"Completed with parentItem=%@ not found, error=%@", parentItem, error); completionHandler(nil, error); } } @@ -557,18 +609,24 @@ - (void)setFavoriteRank:(NSNumber *)favoriteRank forItemIdentifier:(NSFileProvid NSError *error = nil; OCItem *item; + FPLogCmdBegin(@"FavoriteRank", @"Start of setFavoriteRank=%@, forItemIdentifier=%@", favoriteRank, itemIdentifier); + if ((item = (OCItem *)[self itemForIdentifier:itemIdentifier error:&error]) != nil) { // item.isFavorite = @(favoriteRank != nil); // Stored on server [item setLocalFavoriteRank:favoriteRank]; // Stored in local attributes + FPLogCmd(@"Updating %@", item); + [self.core updateItem:item properties:@[ OCItemPropertyNameLocalAttributes ] options:nil resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { + FPLogCmd(@"Completed with item=%@, error=%@", item, error); completionHandler(item, error); }]; } else { + FPLogCmd(@"Completed with item=%@ not found, error=%@", item, error); completionHandler(nil, error); } } @@ -588,22 +646,27 @@ - (void)setTagData:(NSData *)tagData forItemIdentifier:(NSFileProviderItemIdenti // @"v" : @(1) // Version (?) // }]; + FPLogCmdBegin(@"TagData", @"Start of setTagData=%@, forItemIdentifier=%@", tagData, itemIdentifier); + if ((item = (OCItem *)[self itemForIdentifier:itemIdentifier error:&error]) != nil) { [item setLocalTagData:tagData]; // Stored in local attributes + FPLogCmd(@"Updating %@", item); + [self.core updateItem:item properties:@[ OCItemPropertyNameLocalAttributes ] options:nil resultHandler:^(NSError *error, OCCore *core, OCItem *item, id parameter) { + FPLogCmd(@"Completed with item=%@, error=%@", item, error); completionHandler(item, error); }]; } else { + FPLogCmd(@"Completed with item=%@ not found, error=%@", item, error); completionHandler(nil, error); } } #pragma mark - Enumeration - - (nullable id)enumeratorForContainerItemIdentifier:(NSFileProviderItemIdentifier)containerItemIdentifier error:(NSError **)error { if (self.domain.identifier == nil)