Implement an integration/E2E test of the logging pipeline

GoogleDataLogger.podspec

@@ -3,7 +3,6 @@ Pod::Spec.new do |s|
   s.version          = '0.1.0'
   s.summary          = 'Google Data Logging iOS SDK.'
 
-
   s.description      = <<-DESC
 Shared library for iOS SDK data logging needs.
                        DESC
@@ -38,8 +37,16 @@ Shared library for iOS SDK data logging needs.
   common_test_sources = ['GoogleDataLogger/Tests/Common/**/*.{h,m}']
 
   # Unit test specs
-  s.test_spec do |test_spec|
+  s.test_spec 'Tests-Unit' do |test_spec|
     test_spec.requires_app_host = false
     test_spec.source_files = ['GoogleDataLogger/Tests/Unit/**/*.{h,m}'] + common_test_sources
   end
+
+  # Integration test specs
+  s.test_spec 'Tests-Integration' do |test_spec|
+    test_spec.requires_app_host = false
+    test_spec.source_files = ['GoogleDataLogger/Tests/Integration/**/*.{h,m}'] + common_test_sources
+    test_spec.compiler_flags = '-DGDL_LOG_TRACE_ENABLED=1'
+    test_spec.dependency 'GCDWebServer'
+  end
 end

GoogleDataLogger/GoogleDataLogger/Classes/GDLLogEvent.m

@@ -52,12 +52,12 @@ - (NSUInteger)hash {
 }
 
 - (void)setExtension:(id<GDLLogProto>)extension {
-  // If you're looking here because of a performance issue in -protoBytes slowing the assignment
+  // If you're looking here because of a performance issue in -transportBytes slowing the assignment
   // of extension, one way to address this is to add a queue to this class,
   // dispatch_(barrier_ if concurrent)async here, and implement the getter with a dispatch_sync.
   if (extension != _extension) {
     _extension = extension;
-    _extensionBytes = [extension protoBytes];
+    _extensionBytes = [extension transportBytes];
   }
 }
 

GoogleDataLogger/GoogleDataLogger/Classes/GDLLogStorage.h

@@ -38,13 +38,6 @@ NS_ASSUME_NONNULL_BEGIN
  */
 - (void)storeLog:(GDLLogEvent *)log;
 
-/** Removes the corresponding log file from disk.
- *
- * @param logHash The hash value of the original log.
- * @param logTarget The logTarget of the original log.
- */
-- (void)removeLog:(NSNumber *)logHash logTarget:(NSNumber *)logTarget;
-
 /** Removes a set of log fields specified by their filenames.
  *
  * @param logHashes The set of log files to remove.

GoogleDataLogger/GoogleDataLogger/Classes/GDLLogStorage.m

@@ -105,30 +105,6 @@ - (void)storeLog:(GDLLogEvent *)log {
   });
 }
 
-- (void)removeLog:(NSNumber *)logHash logTarget:(NSNumber *)logTarget {
-  dispatch_async(_storageQueue, ^{
-    NSURL *logFile = self.logHashToLogFile[logHash];
-
-    // Remove from disk, first and foremost.
-    NSError *error;
-    [[NSFileManager defaultManager] removeItemAtURL:logFile error:&error];
-    GDLAssert(error == nil, @"There was an error removing a logFile: %@", error);
-
-    // Remove from the tracking collections.
-    [self.logHashToLogFile removeObjectForKey:logHash];
-    NSMutableSet<NSNumber *> *logHashes = self.logTargetToLogHashSet[logTarget];
-    GDLAssert(logHashes, @"There wasn't a logSet for this logTarget.");
-    [logHashes removeObject:logHash];
-    // It's fine to not remove the set if it's empty.
-
-    // Check that a log prioritizer is available for this logTarget.
-    id<GDLLogPrioritizer> logPrioritizer =
-        [GDLRegistrar sharedInstance].logTargetToPrioritizer[logTarget];
-    GDLAssert(logPrioritizer, @"There's no prioritizer registered for the given logTarget.");
-    [logPrioritizer unprioritizeLog:logHash];
-  });
-}
-
 - (void)removeLogs:(NSSet<NSNumber *> *)logHashes logTarget:(NSNumber *)logTarget {
   dispatch_sync(_storageQueue, ^{
     for (NSNumber *logHash in logHashes) {
@@ -151,6 +127,33 @@ - (void)removeLogs:(NSSet<NSNumber *> *)logHashes logTarget:(NSNumber *)logTarge
 
 #pragma mark - Private helper methods
 
+/** Removes the corresponding log file from disk.
+ *
+ * @param logHash The hash value of the original log.
+ * @param logTarget The logTarget of the original log.
+ */
+- (void)removeLog:(NSNumber *)logHash logTarget:(NSNumber *)logTarget {
+  NSURL *logFile = self.logHashToLogFile[logHash];
+
+  // Remove from disk, first and foremost.
+  NSError *error;
+  [[NSFileManager defaultManager] removeItemAtURL:logFile error:&error];
+  GDLAssert(error == nil, @"There was an error removing a logFile: %@", error);
+
+  // Remove from the tracking collections.
+  [self.logHashToLogFile removeObjectForKey:logHash];
+  NSMutableSet<NSNumber *> *logHashes = self.logTargetToLogHashSet[logTarget];
+  GDLAssert(logHashes, @"There wasn't a logSet for this logTarget.");
+  [logHashes removeObject:logHash];
+  // It's fine to not remove the set if it's empty.
+
+  // Check that a log prioritizer is available for this logTarget.
+  id<GDLLogPrioritizer> logPrioritizer =
+      [GDLRegistrar sharedInstance].logTargetToPrioritizer[logTarget];
+  GDLAssert(logPrioritizer, @"There's no prioritizer registered for the given logTarget.");
+  [logPrioritizer unprioritizeLog:logHash];
+}
+
 /** Creates the log directory if it does not exist. */
 - (void)createLogDirectoryIfNotExists {
   NSError *error;
@@ -168,16 +171,16 @@ - (void)createLogDirectoryIfNotExists {
  * @note This method should only be called from a method within a block on _storageQueue to maintain
  * thread safety.
  *
- * @param logProtoBytes The extensionBytes of the log, presumably proto bytes.
+ * @param logTransportBytes The extensionBytes of the log, presumably proto bytes.
  * @param logHash The hash value of the log.
  * @return The filename
  */
-- (NSURL *)saveLogProtoToDisk:(NSData *)logProtoBytes logHash:(NSUInteger)logHash {
+- (NSURL *)saveLogProtoToDisk:(NSData *)logTransportBytes logHash:(NSUInteger)logHash {
   NSString *storagePath = GDLStoragePath();
   NSString *logFile = [NSString stringWithFormat:@"log-%lu", (unsigned long)logHash];
   NSURL *logFilePath = [NSURL fileURLWithPath:[storagePath stringByAppendingPathComponent:logFile]];
 
-  BOOL writingSuccess = [logProtoBytes writeToURL:logFilePath atomically:YES];
+  BOOL writingSuccess = [logTransportBytes writeToURL:logFilePath atomically:YES];
   if (!writingSuccess) {
     GDLLogError(GDLMCEFileWriteError, @"A log file could not be written: %@", logFilePath);
   }

GoogleDataLogger/GoogleDataLogger/Classes/GDLUploadCoordinator.m

@@ -102,6 +102,7 @@ - (GDLUploaderCompletionBlock)onCompleteBlock {
           strongSelf->_logTargetToNextUploadTimes[logTarget] = nextUploadAttemptUTC;
           NSSet<NSNumber *> *logHashSet =
               [strongSelf->_logTargetToInFlightLogSet objectForKey:logTarget];
+          GDLAssert(logHashSet, @"There should be an in-flight log set to remove.");
           [strongSelf.logStorage removeLogs:logHashSet logTarget:logTarget];
           [strongSelf->_logTargetToInFlightLogSet removeObjectForKey:logTarget];
           if (strongSelf->_forcedUploadQueue.count) {
@@ -158,15 +159,16 @@ - (void)checkPrioritizersAndUploadLogs {
         GDLAssert(prioritizer && uploader, @"log target '%@' is missing an implementation",
                   logTarget);
         GDLUploadConditions conds = [self uploadConditions];
-        NSSet<NSNumber *> *logHashesToUpload = [prioritizer logsToUploadGivenConditions:conds];
+        NSSet<NSNumber *> *logHashesToUpload =
+            [[prioritizer logsToUploadGivenConditions:conds] copy];
         if (logHashesToUpload && logHashesToUpload.count > 0) {
           NSAssert(logHashesToUpload.count > 0, @"");
           NSSet<NSURL *> *logFilesToUpload =
               [strongSelf.logStorage logHashesToFiles:logHashesToUpload];
           NSAssert(logFilesToUpload.count == logHashesToUpload.count,
                    @"There should be the same number of files to logs");
-          [uploader uploadLogs:logFilesToUpload onComplete:self.onCompleteBlock];
           strongSelf->_logTargetToInFlightLogSet[logTarget] = logHashesToUpload;
+          [uploader uploadLogs:logFilesToUpload onComplete:self.onCompleteBlock];
         }
       }
     }

GoogleDataLogger/GoogleDataLogger/Classes/Public/GDLLogProto.h

@@ -27,7 +27,7 @@ NS_ASSUME_NONNULL_BEGIN
  *
  * @return the serialized proto bytes of the implementing log proto.
  */
-- (NSData *)protoBytes;
+- (NSData *)transportBytes;
 
 @end
 

GoogleDataLogger/GoogleDataLogger/DependencyWrappers/GDLConsoleLogger.h

@@ -30,7 +30,7 @@ static GULLoggerService kGDLConsoleLogger = @"[GoogleDataLogger]";
  */
 typedef NS_ENUM(NSInteger, GDLMessageCode) {
 
-  /** For warning messages concerning protoBytes: not being implemented by a log extension. */
+  /** For warning messages concerning transportBytes: not being implemented by a log extension. */
   GDLMCWExtensionMissingBytesImpl = 1,
 
   /** For warning message concerning a failed log upload. */

GoogleDataLogger/Tests/Integration/GDLIntegrationTest.m

@@ -0,0 +1,173 @@
+/*
+ * Copyright 2019 Google
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#import <XCTest/XCTest.h>
+
+#import <GoogleDataLogger/GoogleDataLogger.h>
+
+#import "GDLIntegrationTestPrioritizer.h"
+#import "GDLIntegrationTestUploader.h"
+#import "GDLTestServer.h"
+
+#import "GDLLogStorage_Private.h"
+#import "GDLUploadCoordinator+Testing.h"
+
+/** A test-only log object used in this integration test. */
+@interface GDLIntegrationTestLog : NSObject <GDLLogProto>
+
+@end
+
+@implementation GDLIntegrationTestLog
+
+- (NSData *)transportBytes {
+  // In real usage, protobuf's -data method or a custom implementation using nanopb are used.
+  return [[NSString stringWithFormat:@"%@", [NSDate date]] dataUsingEncoding:NSUTF8StringEncoding];
+}
+
+@end
+
+/** A test-only log transformer. */
+@interface GDLIntegrationTestTransformer : NSObject <GDLLogTransformer>
+
+@end
+
+@implementation GDLIntegrationTestTransformer
+
+- (GDLLogEvent *)transform:(GDLLogEvent *)logEvent {
+  // drop half the logs during transforming.
+  if (arc4random_uniform(2) == 1) {
+    logEvent = nil;
+  }
+  return logEvent;
+}
+
+@end
+
+@interface GDLIntegrationTest : XCTestCase
+
+/** A test prioritizer. */
+@property(nonatomic) GDLIntegrationTestPrioritizer *prioritizer;
+
+/** A test uploader. */
+@property(nonatomic) GDLIntegrationTestUploader *uploader;
+
+/** The first test logger. */
+@property(nonatomic) GDLLogger *logger1;
+
+/** The second test logger. */
+@property(nonatomic) GDLLogger *logger2;
+
+@end
+
+@implementation GDLIntegrationTest
+
+- (void)tearDown {
+  dispatch_sync([GDLLogStorage sharedInstance].storageQueue, ^{
+    XCTAssertEqual([GDLLogStorage sharedInstance].logHashToLogFile.count, 0);
+  });
+}
+
+- (void)testEndToEndLog {
+  XCTestExpectation *expectation = [self expectationWithDescription:@"server got the request"];
+  expectation.assertForOverFulfill = NO;
+
+  // Create the server.
+  GDLTestServer *testServer = [[GDLTestServer alloc] init];
+  [testServer setResponseCompletedBlock:^(GCDWebServerRequest *_Nonnull request,
+                                          GCDWebServerResponse *_Nonnull response) {
+    [expectation fulfill];
+  }];
+  [testServer registerTestPaths];
+  [testServer start];
+
+  // Create loggers.
+  self.logger1 = [[GDLLogger alloc] initWithLogMapID:@"logMap1"
+                                     logTransformers:nil
+                                           logTarget:kGDLIntegrationTestTarget];
+
+  self.logger2 = [[GDLLogger alloc] initWithLogMapID:@"logMap2"
+                                     logTransformers:nil
+                                           logTarget:kGDLIntegrationTestTarget];
+
+  // Create a prioritizer and uploader.
+  self.prioritizer = [[GDLIntegrationTestPrioritizer alloc] init];
+  self.uploader = [[GDLIntegrationTestUploader alloc] initWithServerURL:testServer.serverURL];
+
+  // Set the interval to be much shorter than the standard timer.
+  [GDLUploadCoordinator sharedInstance].timerInterval = NSEC_PER_SEC * 0.1;
+  [GDLUploadCoordinator sharedInstance].timerLeeway = NSEC_PER_SEC * 0.01;
+
+  // Confirm no logs are in disk.
+  XCTAssertEqual([GDLLogStorage sharedInstance].logHashToLogFile.count, 0);
+  XCTAssertEqual([GDLLogStorage sharedInstance].logTargetToLogHashSet.count, 0);
+
+  // Generate some logs data.
+  [self generateLogs];
+
+  // Confirm logs are on disk.
+  dispatch_sync([GDLLogStorage sharedInstance].storageQueue, ^{
+    XCTAssertGreaterThan([GDLLogStorage sharedInstance].logHashToLogFile.count, 0);
+    XCTAssertGreaterThan([GDLLogStorage sharedInstance].logTargetToLogHashSet.count, 0);
+  });
+
+  // Confirm logs were sent and received.
+  [self waitForExpectations:@[ expectation ] timeout:10.0];
+
+  // Generate logs for a bit.
+  NSUInteger lengthOfTestToRunInSeconds = 30;
+  [GDLUploadCoordinator sharedInstance].timerInterval = NSEC_PER_SEC * 5;
+  [GDLUploadCoordinator sharedInstance].timerLeeway = NSEC_PER_SEC * 1;
+  dispatch_queue_t queue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0);
+  dispatch_source_t timer = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, queue);
+  dispatch_source_set_timer(timer, DISPATCH_TIME_NOW, 1 * NSEC_PER_SEC, 0.1 * NSEC_PER_SEC);
+  dispatch_source_set_event_handler(timer, ^{
+    static int numberOfTimesCalled = 0;
+    numberOfTimesCalled++;
+    if (numberOfTimesCalled < lengthOfTestToRunInSeconds) {
+      [self generateLogs];
+    } else {
+      dispatch_source_cancel(timer);
+    }
+  });
+  dispatch_resume(timer);
+
+  // Run for a bit, a couple seconds longer than the previous bit.
+  [[NSRunLoop currentRunLoop]
+      runUntilDate:[NSDate dateWithTimeIntervalSinceNow:lengthOfTestToRunInSeconds + 2]];
+
+  [testServer stop];
+}
+
+/** Generates and logs a bunch of random logs. */
+- (void)generateLogs {
+  for (int i = 0; i < 50; i++) {
+    // Choose a random logger, and randomly choose if it's a telemetry log.
+    GDLLogger *logger = arc4random_uniform(2) ? self.logger1 : self.logger2;
+    BOOL isTelemetryLog = arc4random_uniform(2);
+
+    // Create a log
+    GDLLogEvent *logEvent = [logger newEvent];
+    logEvent.extension = [[GDLIntegrationTestLog alloc] init];
+
+    if (isTelemetryLog) {
+      [logger logTelemetryEvent:logEvent];
+    } else {
+      [logger logDataEvent:logEvent];
+    }
+  }
+}
+
+@end

GoogleDataLogger/Tests/Integration/Helpers/GDLIntegrationTestPrioritizer.h

@@ -0,0 +1,27 @@
+/*
+ * Copyright 2019 Google
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#import <Foundation/Foundation.h>
+
+#import <GoogleDataLogger/GoogleDataLogger.h>
+
+/** The integration test log target. Normally, you should use a value in GDLLogTargets.h. */
+static GDLLogTarget kGDLIntegrationTestTarget = 100;
+
+/** An integration test prioritization class. */
+@interface GDLIntegrationTestPrioritizer : NSObject <GDLLogPrioritizer>
+
+@end