Add extensive debug logging (#4704)

* Add extensive debug logging

This is to help adopters understand what the state of the library is

* Fix variable type

Author: mikehaney24

GoogleDataTransport/GDTCORLibrary/GDTCORConsoleLogger.m

@@ -25,12 +25,12 @@
 
 void GDTCORLog(GDTCORMessageCode code, NSString *format, ...) {
 // Don't log anything in not debug builds.
-#ifndef NDEBUG
+#if !NDEBUG
   NSString *logFormat = [NSString stringWithFormat:@"%@[%@] %@", kGDTCORConsoleLogger,
                                                    GDTCORMessageCodeEnumToString(code), format];
   va_list args;
   va_start(args, format);
   NSLogv(logFormat, args);
   va_end(args);
-#endif  // NDEBUG
+#endif  // !NDEBUG
 }

GoogleDataTransport/GDTCORLibrary/GDTCOREvent.m

@@ -17,6 +17,7 @@
 #import <GoogleDataTransport/GDTCOREvent.h>
 
 #import <GoogleDataTransport/GDTCORAssert.h>
+#import <GoogleDataTransport/GDTCORConsoleLogger.h>
 #import <GoogleDataTransport/GDTCORStoredEvent.h>
 
 #import "GDTCORLibrary/Private/GDTCOREvent_Private.h"
@@ -35,6 +36,8 @@ - (nullable instancetype)initWithMappingID:(NSString *)mappingID target:(NSInteg
     _target = target;
     _qosTier = GDTCOREventQosDefault;
   }
+  GDTCORLogDebug("Event %@ created. mappingID: %@ target:%ld qos:%ld", self, _mappingID,
+                 (long)_target, (long)_qosTier);
   return self;
 }
 
@@ -45,6 +48,7 @@ - (instancetype)copy {
   copy.qosTier = _qosTier;
   copy.clockSnapshot = _clockSnapshot;
   copy.customPrioritizationParams = _customPrioritizationParams;
+  GDTCORLogDebug("Copying event %@ to event %@", self, copy);
   return copy;
 }
 

GoogleDataTransport/GDTCORLibrary/GDTCORLifecycle.m

@@ -16,6 +16,7 @@
 
 #import "GDTCORLibrary/Public/GDTCORLifecycle.h"
 
+#import <GoogleDataTransport/GDTCORConsoleLogger.h>
 #import <GoogleDataTransport/GDTCOREvent.h>
 
 #import "GDTCORLibrary/Private/GDTCORRegistrar_Private.h"
@@ -71,47 +72,59 @@ - (void)dealloc {
 - (void)applicationDidEnterBackground:(NSNotification *)notification {
   GDTCORApplication *application = [GDTCORApplication sharedApplication];
   if ([[GDTCORTransformer sharedInstance] respondsToSelector:@selector(appWillBackground:)]) {
+    GDTCORLogDebug("%@", @"Signaling GDTCORTransformer that the app is backgrounding.");
     [[GDTCORTransformer sharedInstance] appWillBackground:application];
   }
   if ([[GDTCORStorage sharedInstance] respondsToSelector:@selector(appWillBackground:)]) {
+    GDTCORLogDebug("%@", @"Signaling GDTCORStorage that the app is backgrounding.");
     [[GDTCORStorage sharedInstance] appWillBackground:application];
   }
   if ([[GDTCORUploadCoordinator sharedInstance] respondsToSelector:@selector(appWillBackground:)]) {
+    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.");
     [[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.");
     [[GDTCORTransformer sharedInstance] appWillForeground:application];
   }
   if ([[GDTCORStorage sharedInstance] respondsToSelector:@selector(appWillForeground:)]) {
+    GDTCORLogDebug("%@", @"Signaling GDTCORStorage that the app is foregrounding.");
     [[GDTCORStorage sharedInstance] appWillForeground:application];
   }
   if ([[GDTCORUploadCoordinator sharedInstance] respondsToSelector:@selector(appWillForeground:)]) {
+    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.");
     [[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.");
     [[GDTCORTransformer sharedInstance] appWillTerminate:application];
   }
   if ([[GDTCORStorage sharedInstance] respondsToSelector:@selector(appWillTerminate:)]) {
+    GDTCORLogDebug("%@", @"Signaling GDTCORStorage that the app is terminating.");
     [[GDTCORStorage sharedInstance] appWillTerminate:application];
   }
   if ([[GDTCORUploadCoordinator sharedInstance] respondsToSelector:@selector(appWillTerminate:)]) {
+    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.");
     [[GDTCORRegistrar sharedInstance] appWillTerminate:application];
   }
 }

GoogleDataTransport/GDTCORLibrary/GDTCORPlatform.m

@@ -17,6 +17,7 @@
 #import <GoogleDataTransport/GDTCORPlatform.h>
 
 #import <GoogleDataTransport/GDTCORAssert.h>
+#import <GoogleDataTransport/GDTCORConsoleLogger.h>
 
 #import "GDTCORLibrary/Private/GDTCORRegistrar_Private.h"
 
@@ -60,6 +61,10 @@ @interface GDTCORApplication ()
 @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.");
 #if TARGET_OS_IOS || TARGET_OS_TV
   // If this asserts, please file a bug at https://github.com/firebase/firebase-ios-sdk/issues.
   GDTCORFatalAssert(
@@ -127,13 +132,22 @@ - (instancetype)init {
 
 - (GDTCORBackgroundIdentifier)beginBackgroundTaskWithName:(NSString *)name
                                         expirationHandler:(void (^)(void))handler {
-  return [[self sharedApplicationForBackgroundTask] beginBackgroundTaskWithName:name
-                                                              expirationHandler:handler];
+  GDTCORBackgroundIdentifier bgID =
+      [[self sharedApplicationForBackgroundTask] beginBackgroundTaskWithName:name
+                                                           expirationHandler:handler];
+#if !NDEBUG
+  if (bgID != GDTCORBackgroundIdentifierInvalid) {
+    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);
     [[self sharedApplicationForBackgroundTask] endBackgroundTask:bgID];
+    return;
   }
 }
 
@@ -176,18 +190,21 @@ - (void)iOSApplicationDidEnterBackground:(NSNotification *)notif {
   _isRunningInBackground = YES;
 
   NSNotificationCenter *notifCenter = [NSNotificationCenter defaultCenter];
+  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.");
   [notifCenter postNotificationName:kGDTCORApplicationWillEnterForegroundNotification object:nil];
 }
 
 - (void)iOSApplicationWillTerminate:(NSNotification *)notif {
   NSNotificationCenter *notifCenter = [NSNotificationCenter defaultCenter];
+  GDTCORLogDebug("%@", @"GDTCORPlatform is sending a notif that the app is terminating.");
   [notifCenter postNotificationName:kGDTCORApplicationWillTerminateNotification object:nil];
 }
 #endif  // TARGET_OS_IOS || TARGET_OS_TV
@@ -197,6 +214,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.");
   [notifCenter postNotificationName:kGDTCORApplicationWillTerminateNotification object:nil];
 }
 #endif  // TARGET_OS_OSX

GoogleDataTransport/GDTCORLibrary/GDTCORReachability.m

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

GoogleDataTransport/GDTCORLibrary/GDTCORRegistrar.m

@@ -15,9 +15,10 @@
  */
 
 #import "GDTCORLibrary/Public/GDTCORRegistrar.h"
-
 #import "GDTCORLibrary/Private/GDTCORRegistrar_Private.h"
 
+#import <GoogleDataTransport/GDTCORConsoleLogger.h>
+
 @implementation GDTCORRegistrar {
   /** Backing ivar for targetToUploader property. */
   NSMutableDictionary<NSNumber *, id<GDTCORUploader>> *_targetToUploader;
@@ -50,6 +51,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);
       strongSelf->_targetToUploader[@(target)] = backend;
     }
   });
@@ -60,6 +62,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);
       strongSelf->_targetToPrioritizer[@(target)] = prioritizer;
     }
   });

GoogleDataTransport/GDTCORLibrary/GDTCORStorage.m

@@ -38,6 +38,7 @@
     NSString *cachePath =
         NSSearchPathForDirectoriesInDomains(NSCachesDirectory, NSUserDomainMask, YES)[0];
     storagePath = [NSString stringWithFormat:@"%@/google-sdks-events", cachePath];
+    GDTCORLogDebug("Events will be saved to %@", storagePath);
   });
   return storagePath;
 }
@@ -74,7 +75,9 @@ - (instancetype)init {
 }
 
 - (void)storeEvent:(GDTCOREvent *)event {
+  GDTCORLogDebug("Saving event: %@", event);
   if (event == nil) {
+    GDTCORLogDebug("%@", @"The event was nil, so it was not saved.");
     return;
   }
 
@@ -96,12 +99,14 @@ - (void)storeEvent:(GDTCOREvent *)event {
     // Check that a prioritizer is available for this target.
     id<GDTCORPrioritizer> prioritizer =
         [GDTCORRegistrar sharedInstance].targetToPrioritizer[@(target)];
-    GDTCORAssert(prioritizer, @"There's no prioritizer registered for the given target.");
+    GDTCORAssert(prioritizer, @"There's no prioritizer registered for the given target. Are you "
+                              @"sure you've added the support library for the backend you need?");
 
     // Write the transport bytes to disk, get a filename.
     GDTCORAssert(event.dataObjectTransportBytes, @"The event should have been serialized to bytes");
     NSURL *eventFile = [self saveEventBytesToDisk:event.dataObjectTransportBytes
                                         eventHash:event.hash];
+    GDTCORLogDebug("Event saved to disk: %@", eventFile);
     GDTCORDataFuture *dataFuture = [[GDTCORDataFuture alloc] initWithFileURL:eventFile];
     GDTCORStoredEvent *storedEvent = [event storedEventWithDataFuture:dataFuture];
 
@@ -118,6 +123,7 @@ - (void)storeEvent:(GDTCOREvent *)event {
 
     // Write state to disk if we're in the background.
     if ([[GDTCORApplication sharedApplication] isRunningInBackground]) {
+      GDTCORLogDebug("%@", @"Saving storage state because the app is running in the background");
       if (@available(macOS 10.13, iOS 11.0, tvOS 11.0, *)) {
         NSError *error;
         NSData *data = [NSKeyedArchiver archivedDataWithRootObject:self
@@ -134,6 +140,8 @@ - (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,
+                   (unsigned long)self->_storedEvents.count);
   });
 }
 
@@ -147,6 +155,7 @@ - (void)removeEvents:(NSSet<GDTCORStoredEvent *> *)events {
         NSURL *fileURL = event.dataFuture.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);
       }
 
       // Remove from the tracking collections.

GoogleDataTransport/GDTCORLibrary/GDTCORTransformer.m

@@ -19,6 +19,7 @@
 
 #import <GoogleDataTransport/GDTCORAssert.h>
 #import <GoogleDataTransport/GDTCORConsoleLogger.h>
+#import <GoogleDataTransport/GDTCOREvent.h>
 #import <GoogleDataTransport/GDTCOREventTransformer.h>
 #import <GoogleDataTransport/GDTCORLifecycle.h>
 
@@ -60,6 +61,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);
         transformedEvent = [transformer transform:transformedEvent];
         if (!transformedEvent) {
           return;

GoogleDataTransport/GDTCORLibrary/GDTCORTransport.m

@@ -41,6 +41,8 @@ - (nullable instancetype)initWithMappingID:(NSString *)mappingID
     _target = target;
     _transformerInstance = [GDTCORTransformer sharedInstance];
   }
+  GDTCORLogDebug("Transport object created. mappingID:%@ transformers:%@ target:%ld", _mappingID,
+                 _transformers, (long)_target);
   return self;
 }
 
@@ -51,6 +53,7 @@ - (void)sendTelemetryEvent:(GDTCOREvent *)event {
   copiedEvent.qosTier = GDTCOREventQoSTelemetry;
   copiedEvent.clockSnapshot = [GDTCORClock snapshot];
   [self.transformerInstance transformEvent:copiedEvent withTransformers:_transformers];
+  GDTCORLogDebug("Telemetry event sent: %@", event);
 }
 
 - (void)sendDataEvent:(GDTCOREvent *)event {
@@ -60,6 +63,7 @@ - (void)sendDataEvent:(GDTCOREvent *)event {
   GDTCOREvent *copiedEvent = [event copy];
   copiedEvent.clockSnapshot = [GDTCORClock snapshot];
   [self.transformerInstance transformEvent:copiedEvent withTransformers:_transformers];
+  GDTCORLogDebug("Data event sent: %@", event);
 }
 
 - (GDTCOREvent *)eventForTransport {

GoogleDataTransport/GDTCORLibrary/GDTCORUploadCoordinator.m

@@ -51,6 +51,7 @@ - (instancetype)init {
 
 - (void)forceUploadForTarget:(GDTCORTarget)target {
   dispatch_async(_coordinationQueue, ^{
+    GDTCORLogDebug("Forcing an upload of target %ld", (long)target);
     GDTCORUploadConditions conditions = [self uploadConditions];
     conditions |= GDTCORUploadConditionHighPriority;
     [self uploadTargets:@[ @(target) ] conditions:conditions];
@@ -82,9 +83,11 @@ - (void)startTimer {
     dispatch_source_set_event_handler(self->_timer, ^{
       if (![[GDTCORApplication sharedApplication] isRunningInBackground]) {
         GDTCORUploadConditions conditions = [self uploadConditions];
+        GDTCORLogDebug("%@", @"Upload timer fired");
         [self uploadTargets:[self.registrar.targetToUploader allKeys] conditions:conditions];
       }
     });
+    GDTCORLogDebug("%@", @"Upload timer started");
     dispatch_resume(self->_timer);
   });
 }
@@ -109,6 +112,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);
         continue;
       }
       // Ask the uploader if they can upload and do so, if it can.
@@ -118,11 +122,14 @@ - (void)uploadTargets:(NSArray<NSNumber *> *)targets conditions:(GDTCORUploadCon
         GDTCORUploadPackage *package = [prioritizer uploadPackageWithConditions:conditions];
         if (package.events.count) {
           self->_targetToInFlightPackages[target] = package;
+          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);
     }
   });
 }