Handle events that fail to write or are missing and add logging levels (#5357)

* Change removeItemAtURL to removeItemAtPath

It seems to work better, for reasons that aren't clear. It may have something to do with forming URLs being more strict.

* Add logging levels, fix failed write events

* Update comment

Author: mikehaney24

GoogleDataTransport/GDTCORLibrary/GDTCORConsoleLogger.m

@@ -16,30 +16,34 @@
 
 #import "GDTCORLibrary/Public/GDTCORConsoleLogger.h"
 
+volatile NSInteger GDTCORConsoleLoggerLoggingLevel = GDTCORLoggingLevelErrors;
+
 /** The console logger prefix. */
 static NSString *kGDTCORConsoleLogger = @"[GoogleDataTransport]";
 
 NSString *GDTCORMessageCodeEnumToString(GDTCORMessageCode code) {
   return [[NSString alloc] initWithFormat:@"I-GDTCOR%06ld", (long)code];
 }
 
-void GDTCORLog(GDTCORMessageCode code, NSString *format, ...) {
+void GDTCORLog(GDTCORMessageCode code, GDTCORLoggingLevel logLevel, NSString *format, ...) {
 // Don't log anything in not debug builds.
 #if !NDEBUG
-  NSString *logFormat = [NSString stringWithFormat:@"%@[%@] %@", kGDTCORConsoleLogger,
-                                                   GDTCORMessageCodeEnumToString(code), format];
-  va_list args;
-  va_start(args, format);
-  NSLogv(logFormat, args);
-  va_end(args);
+  if (logLevel >= GDTCORConsoleLoggerLoggingLevel) {
+    NSString *logFormat = [NSString stringWithFormat:@"%@[%@] %@", kGDTCORConsoleLogger,
+                                                     GDTCORMessageCodeEnumToString(code), format];
+    va_list args;
+    va_start(args, format);
+    NSLogv(logFormat, args);
+    va_end(args);
+  }
 #endif  // !NDEBUG
 }
 
 void GDTCORLogAssert(
     BOOL wasFatal, NSString *_Nonnull file, NSInteger line, NSString *_Nullable format, ...) {
-  GDTCORMessageCode code = wasFatal ? GDTCORMCEFatalAssertion : GDTCORMCEGeneralError;
 // Don't log anything in not debug builds.
 #if !NDEBUG
+  GDTCORMessageCode code = wasFatal ? GDTCORMCEFatalAssertion : GDTCORMCEGeneralError;
   NSString *logFormat =
       [NSString stringWithFormat:@"%@[%@] (%@:%ld) : %@", kGDTCORConsoleLogger,
                                  GDTCORMessageCodeEnumToString(code), file, (long)line, format];

GoogleDataTransport/GDTCORLibrary/GDTCOREvent.m

@@ -74,7 +74,7 @@ - (nullable instancetype)initWithMappingID:(NSString *)mappingID target:(NSInteg
     _target = target;
     _qosTier = GDTCOREventQosDefault;
   }
-  GDTCORLogDebug("Event %@ created. mappingID: %@ target:%ld", self, mappingID, (long)target);
+  GDTCORLogDebug(@"Event %@ created. mappingID: %@ target:%ld", self, mappingID, (long)target);
   return self;
 }
 
@@ -86,7 +86,7 @@ - (instancetype)copy {
   copy.clockSnapshot = _clockSnapshot;
   copy.customBytes = _customBytes;
   copy->_GDTFilePath = _GDTFilePath;
-  GDTCORLogDebug("Copying event %@ to event %@", self, copy);
+  GDTCORLogDebug(@"Copying event %@ to event %@", self, copy);
   return copy;
 }
 

GoogleDataTransport/GDTCORLibrary/GDTCORFlatFileStorage.m

@@ -74,9 +74,9 @@ - (instancetype)init {
 
 - (void)storeEvent:(GDTCOREvent *)event
         onComplete:(void (^_Nullable)(BOOL wasWritten, NSError *_Nullable error))completion {
-  GDTCORLogDebug("Saving event: %@", event);
+  GDTCORLogDebug(@"Saving event: %@", event);
   if (event == nil) {
-    GDTCORLogDebug("%@", @"The event was nil, so it was not saved.");
+    GDTCORLogDebug(@"%@", @"The event was nil, so it was not saved.");
     return;
   }
   BOOL hadOriginalCompletion = completion != nil;
@@ -113,10 +113,12 @@ - (void)storeEvent:(GDTCOREvent *)event
     NSURL *eventFile = [self saveEventBytesToDisk:event eventHash:event.hash error:&error];
     if (!eventFile || error) {
       GDTCORLogError(GDTCORMCEFileWriteError, @"Event failed to save to disk: %@", error);
+      completion(NO, error);
+      return;
     } else {
-      GDTCORLogDebug("Event saved to disk: %@", eventFile);
+      GDTCORLogDebug(@"Event saved to disk: %@", eventFile);
+      completion(YES, error);
     }
-    completion(eventFile != nil, error);
 
     // Add event to tracking collections.
     [self addEventToTrackingCollections:event];
@@ -137,11 +139,11 @@ - (void)storeEvent:(GDTCOREvent *)event
     // Write state to disk if there was an onComplete block or if we're in the background.
     if (hadOriginalCompletion || [[GDTCORApplication sharedApplication] isRunningInBackground]) {
       if (hadOriginalCompletion) {
-        GDTCORLogDebug("%@",
+        GDTCORLogDebug(@"%@",
                        @"Saving flat file storage state because a completion block was passed.");
       } else {
         GDTCORLogDebug(
-            "%@", @"Saving flat file storage state because the app is running in the background");
+            @"%@", @"Saving flat file storage state because the app is running in the background");
       }
       NSError *error;
       GDTCOREncodeArchive(self, [GDTCORFlatFileStorage archivePath], &error);
@@ -153,7 +155,7 @@ - (void)storeEvent:(GDTCOREvent *)event
     // Cancel or end the associated background task if it's still valid.
     [[GDTCORApplication sharedApplication] endBackgroundTask:bgID];
     bgID = GDTCORBackgroundIdentifierInvalid;
-    GDTCORLogDebug("Event %@ is stored. There are %ld events stored on disk", event,
+    GDTCORLogDebug(@"Event %@ is stored. There are %ld events stored on disk", event,
                    (unsigned long)self->_storedEvents.count);
   });
 }
@@ -168,9 +170,13 @@ - (void)removeEvents:(NSSet<NSNumber *> *)eventIDs {
         NSError *error;
         if (event.fileURL) {
           NSURL *fileURL = event.fileURL;
-          [[NSFileManager defaultManager] removeItemAtURL:fileURL error:&error];
-          GDTCORAssert(error == nil, @"There was an error removing an event file: %@", error);
-          GDTCORLogDebug("Removed event from disk: %@", fileURL);
+          BOOL result = [[NSFileManager defaultManager] removeItemAtPath:fileURL.path error:&error];
+          if (!result || error) {
+            GDTCORLogWarning(GDTCORMCWFileReadError,
+                             @"There was an error removing an event file: %@", error);
+          } else {
+            GDTCORLogDebug(@"Removed event from disk: %@", fileURL);
+          }
         }
 
         // Remove from the tracking collections.

GoogleDataTransport/GDTCORLibrary/GDTCORLifecycle.m

@@ -71,47 +71,47 @@ - (void)dealloc {
 - (void)applicationDidEnterBackground:(NSNotification *)notification {
   GDTCORApplication *application = [GDTCORApplication sharedApplication];
   if ([[GDTCORTransformer sharedInstance] respondsToSelector:@selector(appWillBackground:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORTransformer that the app is backgrounding.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORTransformer that the app is backgrounding.");
     [[GDTCORTransformer sharedInstance] appWillBackground:application];
   }
   if ([[GDTCORUploadCoordinator sharedInstance] respondsToSelector:@selector(appWillBackground:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORUploadCoordinator that the app is backgrounding.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORUploadCoordinator that the app is backgrounding.");
     [[GDTCORUploadCoordinator sharedInstance] appWillBackground:application];
   }
   if ([[GDTCORRegistrar sharedInstance] respondsToSelector:@selector(appWillBackground:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORRegistrar that the app is backgrounding.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORRegistrar that the app is backgrounding.");
     [[GDTCORRegistrar sharedInstance] appWillBackground:application];
   }
 }
 
 - (void)applicationWillEnterForeground:(NSNotification *)notification {
   GDTCORApplication *application = [GDTCORApplication sharedApplication];
   if ([[GDTCORTransformer sharedInstance] respondsToSelector:@selector(appWillForeground:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORTransformer that the app is foregrounding.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORTransformer that the app is foregrounding.");
     [[GDTCORTransformer sharedInstance] appWillForeground:application];
   }
   if ([[GDTCORUploadCoordinator sharedInstance] respondsToSelector:@selector(appWillForeground:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORUploadCoordinator that the app is foregrounding.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORUploadCoordinator that the app is foregrounding.");
     [[GDTCORUploadCoordinator sharedInstance] appWillForeground:application];
   }
   if ([[GDTCORRegistrar sharedInstance] respondsToSelector:@selector(appWillForeground:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORRegistrar that the app is foregrounding.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORRegistrar that the app is foregrounding.");
     [[GDTCORRegistrar sharedInstance] appWillForeground:application];
   }
 }
 
 - (void)applicationWillTerminate:(NSNotification *)notification {
   GDTCORApplication *application = [GDTCORApplication sharedApplication];
   if ([[GDTCORTransformer sharedInstance] respondsToSelector:@selector(appWillTerminate:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORTransformer that the app is terminating.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORTransformer that the app is terminating.");
     [[GDTCORTransformer sharedInstance] appWillTerminate:application];
   }
   if ([[GDTCORUploadCoordinator sharedInstance] respondsToSelector:@selector(appWillTerminate:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORUploadCoordinator that the app is terminating.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORUploadCoordinator that the app is terminating.");
     [[GDTCORUploadCoordinator sharedInstance] appWillTerminate:application];
   }
   if ([[GDTCORRegistrar sharedInstance] respondsToSelector:@selector(appWillTerminate:)]) {
-    GDTCORLogDebug("%@", @"Signaling GDTCORRegistrar that the app is terminating.");
+    GDTCORLogDebug(@"%@", @"Signaling GDTCORRegistrar that the app is terminating.");
     [[GDTCORRegistrar sharedInstance] appWillTerminate:application];
   }
 }

GoogleDataTransport/GDTCORLibrary/GDTCORPlatform.m

@@ -49,7 +49,7 @@
         NSSearchPathForDirectoriesInDomains(NSCachesDirectory, NSUserDomainMask, YES)[0];
     GDTPath =
         [NSURL fileURLWithPath:[NSString stringWithFormat:@"%@/google-sdks-events", cachePath]];
-    GDTCORLogDebug("GDT's state will be saved to: %@", GDTPath);
+    GDTCORLogDebug(@"GDT's state will be saved to: %@", GDTPath);
     if (![[NSFileManager defaultManager] fileExistsAtPath:GDTPath.path]) {
       NSError *error;
       [[NSFileManager defaultManager] createDirectoryAtPath:GDTPath.path
@@ -247,9 +247,9 @@ @implementation GDTCORApplication
 
 + (void)load {
   GDTCORLogDebug(
-      "%@", @"GDT is initializing. Please note that if you quit the app via the "
-             "debugger and not through a lifecycle event, event data will remain on disk but "
-             "storage won't have a reference to them since the singleton wasn't saved to disk.");
+      @"%@", @"GDT is initializing. Please note that if you quit the app via the "
+              "debugger and not through a lifecycle event, event data will remain on disk but "
+              "storage won't have a reference to them since the singleton wasn't saved to disk.");
 #if TARGET_OS_IOS || TARGET_OS_TV
   // If this asserts, please file a bug at https://github.com/firebase/firebase-ios-sdk/issues.
   GDTCORFatalAssert(
@@ -322,15 +322,15 @@ - (GDTCORBackgroundIdentifier)beginBackgroundTaskWithName:(NSString *)name
                                                            expirationHandler:handler];
 #if !NDEBUG
   if (bgID != GDTCORBackgroundIdentifierInvalid) {
-    GDTCORLogDebug("Creating background task with name:%@ bgID:%ld", name, (long)bgID);
+    GDTCORLogDebug(@"Creating background task with name:%@ bgID:%ld", name, (long)bgID);
   }
 #endif  // !NDEBUG
   return bgID;
 }
 
 - (void)endBackgroundTask:(GDTCORBackgroundIdentifier)bgID {
   if (bgID != GDTCORBackgroundIdentifierInvalid) {
-    GDTCORLogDebug("Ending background task with ID:%ld was successful", (long)bgID);
+    GDTCORLogDebug(@"Ending background task with ID:%ld was successful", (long)bgID);
     [[self sharedApplicationForBackgroundTask] endBackgroundTask:bgID];
     return;
   }
@@ -375,21 +375,21 @@ - (void)iOSApplicationDidEnterBackground:(NSNotification *)notif {
   _isRunningInBackground = YES;
 
   NSNotificationCenter *notifCenter = [NSNotificationCenter defaultCenter];
-  GDTCORLogDebug("%@", @"GDTCORPlatform is sending a notif that the app is backgrounding.");
+  GDTCORLogDebug(@"%@", @"GDTCORPlatform is sending a notif that the app is backgrounding.");
   [notifCenter postNotificationName:kGDTCORApplicationDidEnterBackgroundNotification object:nil];
 }
 
 - (void)iOSApplicationWillEnterForeground:(NSNotification *)notif {
   _isRunningInBackground = NO;
 
   NSNotificationCenter *notifCenter = [NSNotificationCenter defaultCenter];
-  GDTCORLogDebug("%@", @"GDTCORPlatform is sending a notif that the app is foregrounding.");
+  GDTCORLogDebug(@"%@", @"GDTCORPlatform is sending a notif that the app is foregrounding.");
   [notifCenter postNotificationName:kGDTCORApplicationWillEnterForegroundNotification object:nil];
 }
 
 - (void)iOSApplicationWillTerminate:(NSNotification *)notif {
   NSNotificationCenter *notifCenter = [NSNotificationCenter defaultCenter];
-  GDTCORLogDebug("%@", @"GDTCORPlatform is sending a notif that the app is terminating.");
+  GDTCORLogDebug(@"%@", @"GDTCORPlatform is sending a notif that the app is terminating.");
   [notifCenter postNotificationName:kGDTCORApplicationWillTerminateNotification object:nil];
 }
 #endif  // TARGET_OS_IOS || TARGET_OS_TV
@@ -399,7 +399,7 @@ - (void)iOSApplicationWillTerminate:(NSNotification *)notif {
 #if TARGET_OS_OSX
 - (void)macOSApplicationWillTerminate:(NSNotification *)notif {
   NSNotificationCenter *notifCenter = [NSNotificationCenter defaultCenter];
-  GDTCORLogDebug("%@", @"GDTCORPlatform is sending a notif that the app is terminating.");
+  GDTCORLogDebug(@"%@", @"GDTCORPlatform is sending a notif that the app is terminating.");
   [notifCenter postNotificationName:kGDTCORApplicationWillTerminateNotification object:nil];
 }
 #endif  // TARGET_OS_OSX

GoogleDataTransport/GDTCORLibrary/GDTCORReachability.m

@@ -62,7 +62,7 @@ + (SCNetworkReachabilityFlags)currentFlags {
     GDTCORReachability *reachability = [GDTCORReachability sharedInstance];
     currentFlags =
         reachability->_callbackFlags ? reachability->_callbackFlags : reachability->_flags;
-    GDTCORLogDebug("Initial reachability flags determined: %d", currentFlags);
+    GDTCORLogDebug(@"Initial reachability flags determined: %d", currentFlags);
   });
   return currentFlags;
 }
@@ -93,7 +93,7 @@ - (instancetype)init {
     dispatch_async(_reachabilityQueue, ^{
       Boolean valid = SCNetworkReachabilityGetFlags(self->_reachabilityRef, &self->_flags);
       if (!valid) {
-        GDTCORLogDebug("%@", @"Determining reachability failed.");
+        GDTCORLogDebug(@"%@", @"Determining reachability failed.");
         self->_flags = 0;
       }
     });
@@ -112,7 +112,7 @@ - (void)setCallbackFlags:(SCNetworkReachabilityFlags)flags {
 static void GDTCORReachabilityCallback(SCNetworkReachabilityRef reachability,
                                        SCNetworkReachabilityFlags flags,
                                        void *info) {
-  GDTCORLogDebug("Reachability changed, new flags: %d", flags);
+  GDTCORLogDebug(@"Reachability changed, new flags: %d", flags);
   [[GDTCORReachability sharedInstance] setCallbackFlags:flags];
 }
 

GoogleDataTransport/GDTCORLibrary/GDTCORRegistrar.m

@@ -55,7 +55,7 @@ - (void)registerUploader:(id<GDTCORUploader>)backend target:(GDTCORTarget)target
   dispatch_async(_registrarQueue, ^{
     GDTCORRegistrar *strongSelf = weakSelf;
     if (strongSelf) {
-      GDTCORLogDebug("Registered an uploader: %@ for target:%ld", backend, (long)target);
+      GDTCORLogDebug(@"Registered an uploader: %@ for target:%ld", backend, (long)target);
       strongSelf->_targetToUploader[@(target)] = backend;
     }
   });
@@ -66,7 +66,7 @@ - (void)registerStorage:(id<GDTCORStorageProtocol>)storage target:(GDTCORTarget)
   dispatch_async(_registrarQueue, ^{
     GDTCORRegistrar *strongSelf = weakSelf;
     if (strongSelf) {
-      GDTCORLogDebug("Registered storage: %@ for target:%ld", storage, (long)target);
+      GDTCORLogDebug(@"Registered storage: %@ for target:%ld", storage, (long)target);
       strongSelf->_targetToStorage[@(target)] = storage;
     }
   });
@@ -77,7 +77,7 @@ - (void)registerPrioritizer:(id<GDTCORPrioritizer>)prioritizer target:(GDTCORTar
   dispatch_async(_registrarQueue, ^{
     GDTCORRegistrar *strongSelf = weakSelf;
     if (strongSelf) {
-      GDTCORLogDebug("Registered a prioritizer: %@ for target:%ld", prioritizer, (long)target);
+      GDTCORLogDebug(@"Registered a prioritizer: %@ for target:%ld", prioritizer, (long)target);
       strongSelf->_targetToPrioritizer[@(target)] = prioritizer;
     }
   });

GoogleDataTransport/GDTCORLibrary/GDTCORTransformer.m

@@ -68,7 +68,7 @@ - (void)transformEvent:(GDTCOREvent *)event
     GDTCOREvent *transformedEvent = event;
     for (id<GDTCOREventTransformer> transformer in transformers) {
       if ([transformer respondsToSelector:@selector(transform:)]) {
-        GDTCORLogDebug("Applying a transformer to event %@", event);
+        GDTCORLogDebug(@"Applying a transformer to event %@", event);
         transformedEvent = [transformer transform:transformedEvent];
         if (!transformedEvent) {
           completion(NO, nil);

GoogleDataTransport/GDTCORLibrary/GDTCORTransport.m

@@ -41,7 +41,7 @@ - (nullable instancetype)initWithMappingID:(NSString *)mappingID
     _target = target;
     _transformerInstance = [GDTCORTransformer sharedInstance];
   }
-  GDTCORLogDebug("Transport object created. mappingID:%@ transformers:%@ target:%ld", mappingID,
+  GDTCORLogDebug(@"Transport object created. mappingID:%@ transformers:%@ target:%ld", mappingID,
                  transformers, (long)target);
   return self;
 }

GoogleDataTransport/GDTCORLibrary/GDTCORUploadCoordinator.m

@@ -50,7 +50,7 @@ - (instancetype)init {
 
 - (void)forceUploadForTarget:(GDTCORTarget)target {
   dispatch_async(_coordinationQueue, ^{
-    GDTCORLogDebug("Forcing an upload of target %ld", (long)target);
+    GDTCORLogDebug(@"Forcing an upload of target %ld", (long)target);
     GDTCORUploadConditions conditions = [self uploadConditions];
     conditions |= GDTCORUploadConditionHighPriority;
     [self uploadTargets:@[ @(target) ] conditions:conditions];
@@ -71,11 +71,11 @@ - (void)startTimer {
     dispatch_source_set_event_handler(self->_timer, ^{
       if (![[GDTCORApplication sharedApplication] isRunningInBackground]) {
         GDTCORUploadConditions conditions = [self uploadConditions];
-        GDTCORLogDebug("%@", @"Upload timer fired");
+        GDTCORLogDebug(@"%@", @"Upload timer fired");
         [self uploadTargets:[self.registrar.targetToUploader allKeys] conditions:conditions];
       }
     });
-    GDTCORLogDebug("%@", @"Upload timer started");
+    GDTCORLogDebug(@"%@", @"Upload timer started");
     dispatch_resume(self->_timer);
   });
 }
@@ -100,7 +100,7 @@ - (void)uploadTargets:(NSArray<NSNumber *> *)targets conditions:(GDTCORUploadCon
     for (NSNumber *target in targets) {
       // Don't trigger uploads for targets that have an in-flight package already.
       if (self->_targetToInFlightPackages[target]) {
-        GDTCORLogDebug("Target %@ will not upload, there's an upload in flight", target);
+        GDTCORLogDebug(@"Target %@ will not upload, there's an upload in flight", target);
         continue;
       }
       // Ask the uploader if they can upload and do so, if it can.
@@ -111,14 +111,14 @@ - (void)uploadTargets:(NSArray<NSNumber *> *)targets conditions:(GDTCORUploadCon
                                                                  conditions:conditions];
         if (package.events.count) {
           self->_targetToInFlightPackages[target] = package;
-          GDTCORLogDebug("Package of %ld events is being handed over to an uploader",
+          GDTCORLogDebug(@"Package of %ld events is being handed over to an uploader",
                          (long)package.events.count);
           [uploader uploadPackage:package];
         } else {
           [package completeDelivery];
         }
       }
-      GDTCORLogDebug("Target %@ is not ready to upload", target);
+      GDTCORLogDebug(@"Target %@ is not ready to upload", target);
     }
   });
 }