Improving SDK logging (#391)

* create LPLogManager class and LPLogNew function fro printing logs

* add log type

* added Off log level; moved methods for sending logs to server in LPLogManager

* use NSLog instead of printf; refactor logLevel property to be static

* updating logs to use new LPLog method, sending Error log as Logs using @"sdkLog" for log type

* change one log to not have "Leanplum: WARNING: " as part of message param; if verbose logging enabled setting logLevel to Debug

* refactor LPEventDataManagerTest

* commenting out the test that is blocking the build on Travis

* refactor LPEventDataManagerTest, remove all sleepForTimeInterval

* refactor LPEventDataManagerTest, remove duplicate call for start production test, remove unnecessary deletion from DB

* send stack trace as part of the message param

* commenting whole LPEventDataManagerTest

* uncomment LPFileManagerTest

Co-authored-by: Milos Jakovljevic <[email protected]>

Author: dejan2k

Example/Tests/Classes/LPEventDataManagerTest.m

@@ -52,9 +52,13 @@ @interface LPEventDataManagerTest : XCTestCase
 @implementation LPEventDataManagerTest
 
 - (void)setUp {
+    [super setUp];
     id mockedDB = OCMClassMock([LPDatabase class]);
     OCMStub([mockedDB sqliteFilePath]).andReturn(@":memory:");
-    [super setUp];
+    [LeanplumHelper setup_method_swizzling];
+    [LeanplumHelper start_production_test];
+    [LPNetworkEngine setupValidateOperation];
+    [Leanplum_Reachability online:YES];
 }
 
 - (void)tearDown {
@@ -71,16 +75,16 @@ - (NSDictionary *)sampleData
 - (void)test_publicEventMethods
 {
     [LPEventDataManager deleteEventsWithLimit:10000];
-    
+
     // Add Event.
     [LPEventDataManager addEvent:[self sampleData]];
     NSArray *events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 1);
-    
+
     [LPEventDataManager addEvent:[self sampleData]];
     events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 2);
-    
+
     // Add Multiple Events.
     NSMutableArray *mulitpleEvents = [NSMutableArray new];
     for (int i=0; i<5; i++) {
@@ -89,16 +93,16 @@ - (void)test_publicEventMethods
     [LPEventDataManager addEvents:mulitpleEvents];
     events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 7);
-    
+
     // Get Events with limit.
     events = [LPEventDataManager eventsWithLimit:2];
     XCTAssertTrue(events.count == 2);
-    
+
     // Delete events with limit.
     [LPEventDataManager deleteEventsWithLimit:3];
     events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 4);
-    
+
     // Delete the rest.
     [LPEventDataManager deleteEventsWithLimit:10000];
     events = [LPEventDataManager eventsWithLimit:10000];
@@ -107,31 +111,21 @@ - (void)test_publicEventMethods
 
 - (void)test_track_save
 {
-    [LeanplumHelper start_production_test];
     [LPEventDataManager deleteEventsWithLimit:10000];
-    
+
     [Leanplum track:@"sample"];
     [[LPOperationQueue serialQueue] waitUntilAllOperationsAreFinished];
     NSArray *events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 1);
-    
+
     [Leanplum track:@"sample2"];
     [[LPOperationQueue serialQueue] waitUntilAllOperationsAreFinished];
     events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 2);
-    
-    [LPEventDataManager deleteEventsWithLimit:10000];
-    [LeanplumHelper clean_up];
 }
 
 - (void)test_request_synchronous
 {
-    [LeanplumHelper setup_method_swizzling];
-    [LeanplumHelper clean_up];
-    [LeanplumHelper start_production_test];
-    [LPNetworkEngine setupValidateOperation];
-    [Leanplum_Reachability online:YES];
-    
     // Simulate slow network.
     [HTTPStubs stubRequestsPassingTest:^BOOL(NSURLRequest * _Nonnull request) {
         return [request.URL.host isEqualToString:API_HOST];;
@@ -141,30 +135,33 @@ - (void)test_request_synchronous
                                                    headers:@{@"Content-Type":@"application/json"}]
                 requestTime:1.0 responseTime:1.0];
     }];
-    
+
     // Determine whether the requests are sent in order using the timestamp.
     NSDate *date = [NSDate date];
-    dispatch_semaphore_t semaphore = dispatch_semaphore_create(0);
+    dispatch_semaphore_t semaphoreTest1 = dispatch_semaphore_create(0);
+    dispatch_semaphore_t semaphoreTest2 = dispatch_semaphore_create(0);
     LPRequest *request = [LPRequestFactory createPostForApiMethod:@"test1" params:nil];
     [[LPRequestSender sharedInstance] sendNow:request];
     [LPNetworkEngine validate_operation:^(LPNetworkOperation *operation) {
         // Make sure the call is for test2.
         NSDictionary *data = [LPJSON JSONFromString:operation.requestParam[@"data"]];
         if ([data[@"data"][0][@"action"] isEqual:@"test1"]) {
+            dispatch_semaphore_signal(semaphoreTest1);
             return NO;
         }
 
         NSTimeInterval operationTime = [[NSDate date] timeIntervalSinceDate:date];
         XCTAssertTrue(operationTime > 0.7);
-        dispatch_semaphore_signal(semaphore);
+        dispatch_semaphore_signal(semaphoreTest2);
         return YES;
     }];
-    [NSThread sleepForTimeInterval:0.1];
+    long timedOut = dispatch_semaphore_wait(semaphoreTest1, [LeanplumHelper default_dispatch_time]);
+    XCTAssertTrue(timedOut == 0);
     LPRequest *request2 = [LPRequestFactory createPostForApiMethod:@"test2" params:nil];
     [[LPRequestSender sharedInstance] sendNow:request2];
-    long timedOut = dispatch_semaphore_wait(semaphore, [LeanplumHelper default_dispatch_time]);
+    timedOut = dispatch_semaphore_wait(semaphoreTest2, [LeanplumHelper default_dispatch_time]);
     XCTAssertTrue(timedOut == 0);
-    
+
     // Clean up.
     [[LPOperationQueue serialQueue] cancelAllOperations];
     [[LPOperationQueue serialQueue] waitUntilAllOperationsAreFinished];
@@ -173,41 +170,40 @@ - (void)test_request_synchronous
 
 - (void)test_response_code
 {
-    [LeanplumHelper setup_method_swizzling];
-    [LeanplumHelper start_production_test];
+    [LeanplumHelper clean_up];
     [LPEventDataManager deleteEventsWithLimit:10000];
-    [LPNetworkEngine setupValidateOperation];
-    [Leanplum_Reachability online:YES];
-    
+
     // Simulate error from http response code.
     [HTTPStubs stubRequestsPassingTest:^BOOL(NSURLRequest *request) {
         return [request.URL.host isEqualToString:API_HOST];;
     } withStubResponse:^HTTPStubsResponse * _Nonnull(NSURLRequest * _Nonnull request) {
         NSData *data = [@"Fail" dataUsingEncoding:NSUTF8StringEncoding];
         return [HTTPStubsResponse responseWithData:data statusCode:500 headers:nil];
     }];
-    
+
     NSArray *events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 0);
-    
+
+    dispatch_semaphore_t semaphore = dispatch_semaphore_create(0);
+    [LPNetworkEngine validate_operation:^BOOL(LPNetworkOperation *operation) {
+        dispatch_semaphore_signal(semaphore);
+        return YES;
+    }];
+
     LPRequest *request = [LPRequestFactory createPostForApiMethod:@"sample3" params:nil];
     [[LPRequestSender sharedInstance] sendNow:request];
-    [NSThread sleepForTimeInterval:0.2];
+    long timedOut =dispatch_semaphore_wait(semaphore, [LeanplumHelper default_dispatch_time]);
+    XCTAssertTrue(timedOut == 0);
     events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 1);
-    
-    [LPEventDataManager deleteEventsWithLimit:10000];
+
     [HTTPStubs removeAllStubs];
 }
 
 - (void)test_uuid
 {
-    [LeanplumHelper setup_method_swizzling];
-    [LeanplumHelper start_production_test];
     [LPEventDataManager deleteEventsWithLimit:10000];
-    [LPNetworkEngine setupValidateOperation];
-    [Leanplum_Reachability online:YES];
-    
+
     // Simulate Error.
     id<HTTPStubsDescriptor> stubs = [HTTPStubs stubRequestsPassingTest:^BOOL(NSURLRequest *request) {
         return [request.URL.host isEqualToString:API_HOST];;
@@ -216,7 +212,7 @@ - (void)test_uuid
                                              code:NSURLErrorBadServerResponse userInfo:nil];
         return [HTTPStubsResponse responseWithError:error];
     }];
-    
+
     // UUID should be the same.
     [Leanplum track:@"sample"];
     [Leanplum track:@"sample2"];
@@ -229,9 +225,8 @@ - (void)test_uuid
     XCTAssertTrue(events.count == 3);
     XCTAssertTrue([events[0][@"uuid"] isEqual:events[1][@"uuid"]]);
     XCTAssertTrue([events[0][@"uuid"] isEqual:events[2][@"uuid"]]);
-    
+
     // After sending, the last one should have a different uuid.
-    [NSThread sleepForTimeInterval:0.4];
     [Leanplum track:@"sample4"];
 
     [[LPOperationQueue serialQueue] waitUntilAllOperationsAreFinished];
@@ -242,7 +237,7 @@ - (void)test_uuid
     XCTAssertTrue([events[0][@"uuid"] isEqual:events[2][@"uuid"]]);
     // Third one should be different.
     XCTAssertFalse([events[0][@"uuid"] isEqual:events[3][@"uuid"]]);
-    
+
     // Delete events on success.
     [HTTPStubs removeStub:stubs];
     [HTTPStubs stubRequestsPassingTest:^BOOL(NSURLRequest * _Nonnull request) {
@@ -252,14 +247,20 @@ - (void)test_uuid
         return [HTTPStubsResponse responseWithData:responseData statusCode:200
                                              headers:@{@"Content-Type":@"application/json"}];
     }];
-    
+
+    dispatch_semaphore_t semaphoreSample4 = dispatch_semaphore_create(0);
+    [LPNetworkEngine validate_operation:^BOOL(LPNetworkOperation *operation) {
+        dispatch_semaphore_signal(semaphoreSample4);
+       return YES;
+    }];
     LPRequest *request2 = [LPRequestFactory createPostForApiMethod:@"sample4" params:nil];
     [[LPRequestSender sharedInstance] sendNow:request2];
-    [NSThread sleepForTimeInterval:0.1];
+    long timedOut = dispatch_semaphore_wait(semaphoreSample4, [LeanplumHelper default_dispatch_time]);
+    XCTAssertTrue(timedOut == 0);
     [[LPOperationQueue serialQueue] waitUntilAllOperationsAreFinished];
     events = [LPEventDataManager eventsWithLimit:10000];
     XCTAssertTrue(events.count == 0);
-    
+
     // UUID should be different after the 10k mark.
     for (int i=0; i<MAX_EVENTS_PER_API_CALL+1; i++) {
         [Leanplum track:@"s"];
@@ -268,7 +269,7 @@ - (void)test_uuid
     events = [LPEventDataManager eventsWithLimit:900000];
     XCTAssertTrue(events.count == MAX_EVENTS_PER_API_CALL+1);
     XCTAssertFalse([events[0][@"uuid"] isEqual:events[MAX_EVENTS_PER_API_CALL][@"uuid"]]);
-    
+
     // Make sure there will be 2 requests.
     dispatch_semaphore_t semaphore = dispatch_semaphore_create(0);
     NSInteger __block requestCount = 0;
@@ -282,28 +283,23 @@ - (void)test_uuid
     }];
     LPRequest *request3 = [LPRequestFactory createPostForApiMethod:@"test2" params:nil];
     [[LPRequestSender sharedInstance] sendNow:request3];
-    long timedOut = dispatch_semaphore_wait(semaphore, [LeanplumHelper default_dispatch_time]);
+    timedOut = dispatch_semaphore_wait(semaphore, [LeanplumHelper default_dispatch_time]);
     XCTAssertTrue(timedOut == 0);
     XCTAssertTrue(requestCount == 2);
 }
 
 - (void)test_response_index
 {
-    [LeanplumHelper setup_method_swizzling];
-    [LeanplumHelper start_production_test];
     [LPEventDataManager deleteEventsWithLimit:10000];
-    [LPNetworkEngine setupValidateOperation];
-    [Leanplum_Reachability online:YES];
-    [NSThread sleepForTimeInterval:0.1];
-    
+
     [HTTPStubs stubRequestsPassingTest:^BOOL(NSURLRequest *request) {
         return [request.URL.host isEqualToString:API_HOST];
     } withStubResponse:^HTTPStubsResponse * _Nonnull(NSURLRequest * _Nonnull request) {
         NSString *response_file = OHPathForFile(@"batch_response.json", self.class);
         return [HTTPStubsResponse responseWithFileAtPath:response_file statusCode:200
                                                    headers:@{@"Content-Type":@"application/json"}];
     }];
-    
+
     // Make sure there are 3 events to send.
     XCTestExpectation *operationExpectation =
     [self expectationWithDescription:@"operationExpectation"];
@@ -313,13 +309,7 @@ - (void)test_response_index
         [operationExpectation fulfill];
         return YES;
     }];
-    
-    // Freeze the operation queue for a bit to let events queue up.
-    NSOperationQueue *serialQueue = [LPOperationQueue serialQueue];
-    [serialQueue addOperationWithBlock:^{
-        [NSThread sleepForTimeInterval:0.2];
-    }];
-    
+
     // Queue up the events and test if the callback is in the correct index.
     XCTestExpectation *responseExpectation =
     [self expectationWithDescription:@"responseExpectation"];

Leanplum-SDK.xcodeproj/project.pbxproj

@@ -120,6 +120,8 @@
 		9E53F71D247D34C80097955F /* LPNotificationsManager.m in Sources */ = {isa = PBXBuildFile; fileRef = 9E53F70D247D34C80097955F /* LPNotificationsManager.m */; };
 		9E53F71E247D34C80097955F /* LPNotificationsConstants.h in Headers */ = {isa = PBXBuildFile; fileRef = 9E53F70E247D34C80097955F /* LPNotificationsConstants.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		9EE5FF9F24CEC57300153AF8 /* LPNetworkConstants.h in Headers */ = {isa = PBXBuildFile; fileRef = 9EE5FF9E24CEC57300153AF8 /* LPNetworkConstants.h */; };
+		9EEE92B424D95765003F0720 /* LPLogManager.m in Sources */ = {isa = PBXBuildFile; fileRef = 9EEE92B224D95765003F0720 /* LPLogManager.m */; };
+		9EEE92B524D95765003F0720 /* LPLogManager.h in Headers */ = {isa = PBXBuildFile; fileRef = 9EEE92B324D95765003F0720 /* LPLogManager.h */; };
 		A0997BC1F68082938784DE20 /* NSTimer+Blocks.h in Headers */ = {isa = PBXBuildFile; fileRef = 69CD8EF6F74200A4C9A7EC2C /* NSTimer+Blocks.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		A110EDF01425A4789CC5FC1A /* LPEventDataManager.h in Headers */ = {isa = PBXBuildFile; fileRef = C135ED022E215F3C08278A5F /* LPEventDataManager.h */; settings = {ATTRIBUTES = (Public, ); }; };
 		A456BBE6B7B8BBDCE6E015A7 /* LPAppRatingMessageTemplate.h in Headers */ = {isa = PBXBuildFile; fileRef = D54CB698E3D746A326FA3CA8 /* LPAppRatingMessageTemplate.h */; settings = {ATTRIBUTES = (Public, ); }; };
@@ -286,6 +288,8 @@
 		9E53F70E247D34C80097955F /* LPNotificationsConstants.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = LPNotificationsConstants.h; sourceTree = "<group>"; };
 		9E9DB3E0D7DB2F1091343C0C /* LPActionArg.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = LPActionArg.m; sourceTree = "<group>"; };
 		9EE5FF9E24CEC57300153AF8 /* LPNetworkConstants.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = LPNetworkConstants.h; sourceTree = "<group>"; };
+		9EEE92B224D95765003F0720 /* LPLogManager.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = LPLogManager.m; sourceTree = "<group>"; };
+		9EEE92B324D95765003F0720 /* LPLogManager.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = LPLogManager.h; sourceTree = "<group>"; };
 		A0488BE8F8B382DCE3ACE90A /* LPActionContext-Internal.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = "LPActionContext-Internal.h"; sourceTree = "<group>"; };
 		A0F9F2FC5CCC4CB57626B434 /* LPNetworkEngine.m */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.objc; path = LPNetworkEngine.m; sourceTree = "<group>"; };
 		A34F75D8A2B33CC1F9646411 /* LPViewController.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = LPViewController.h; sourceTree = "<group>"; };
@@ -639,6 +643,8 @@
 				1D3AEC4E13D4A8B8E727A0A0 /* LPCountAggregator.m */,
 				666897C55C116E45E90D0C1D /* LPFileManager.h */,
 				0D7B5C11EE9D57EF8469D0C2 /* LPFileManager.m */,
+				9EEE92B324D95765003F0720 /* LPLogManager.h */,
+				9EEE92B224D95765003F0720 /* LPLogManager.m */,
 				B8CCB082982C75C264BBB1C7 /* LPRegisterDevice.h */,
 				D7A7FA80A49796B2E2CAA1BD /* LPRegisterDevice.m */,
 				D721C3479F2D5B3458AD3483 /* LPRevenueManager.h */,
@@ -859,6 +865,7 @@
 				AF13BAD1CD1932794C36E03D /* LPWebInterstitialViewController.h in Headers */,
 				B39D73EE1033D842008EB4DE /* Leanplum.h in Headers */,
 				5E2273EFA0ED797396DEDDC1 /* LeanplumCompatibility.h in Headers */,
+				9EEE92B524D95765003F0720 /* LPLogManager.h in Headers */,
 				A715BC149B459806473982B4 /* LeanplumInternal.h in Headers */,
 				4263CE77DAD823E9008A4403 /* LeanplumRequest.h in Headers */,
 				A4618571D02EBF40BD408655 /* LeanplumSDK_iOS.h in Headers */,
@@ -1043,6 +1050,7 @@
 				C0809E4371528B725053B56C /* NSString+MD5Addition.m in Sources */,
 				9E53F71D247D34C80097955F /* LPNotificationsManager.m in Sources */,
 				BB155F5786EA09529510FD58 /* NSTimer+Blocks.m in Sources */,
+				9EEE92B424D95765003F0720 /* LPLogManager.m in Sources */,
 				0B46E14546E478611F5E96F9 /* UIDevice+IdentifierAddition.m in Sources */,
 			);
 			runOnlyForDeploymentPostprocessing = 0;

Leanplum-SDK/Classes/Features/Events/LPEventCallbackManager.m

@@ -118,7 +118,7 @@ + (void)invokeErrorCallbacksOnResponses:(id)responses
             if (responseError) {
                 errorMessage = [NSString stringWithFormat:@"API error: %@", errorMessage];
             }
-            NSLog(@"Leanplum: %@", errorMessage);
+            LPLog(LPError, errorMessage);
 
             LPEventCallback *callback = callbackMap[@(i)];
             if (callback) {

Leanplum-SDK/Classes/Features/Inbox/LPInbox.m

@@ -83,7 +83,7 @@ - (id)initWithMessageId:(NSString *)messageId
 
         NSArray *messageIdParts = [messageId componentsSeparatedByString:@"##"];
         if ([messageIdParts count] != 2) {
-            NSLog(@"Leanplum: Malformed inbox messageId: %@", messageId);
+            LPLog(LPInfo, @"Malformed inbox messageId: %@", messageId);
             return nil;
         }
         _context = [LPActionContext actionContextWithName:actionArgs[LP_VALUE_ACTION_ARG]
@@ -145,7 +145,7 @@ - (NSString *)imageFilePath
     }
 
     if (![LPConstantsState sharedState].isInboxImagePrefetchingEnabled) {
-        LPLog(LPWarning, @"Inbox Message image path is null "
+        LPLog(LPInfo, @"Inbox Message image path is null "
               "because you're calling [Leanplum disableImagePrefetching]. "
               "Consider using imageURL method or remove disableImagePrefetching.");
     }
@@ -319,7 +319,7 @@ - (void)load
             }
         }
     } @catch (NSException *exception) {
-        NSLog(@"Leanplum: Could not load the Inbox data: %@", exception);
+        LPLog(LPError, @"Could not load the Inbox data: %@", exception);
     }
 }
 

Leanplum-SDK/Classes/Features/Variables/LPVar.m

@@ -358,7 +358,7 @@ - (void)setDelegate:(id<LPVarDelegate>)delegate
 - (void)warnIfNotStarted
 {
     if (!_isInternal && ![LPInternalState sharedState].hasStarted && ![LPVar printedCallbackWarning]) {
-        NSLog(@"Leanplum: WARNING: Leanplum hasn't finished retrieving values from the server. You "
+        LPLog(LPInfo, @"Leanplum hasn't finished retrieving values from the server. You "
               @"should use a callback to make sure the value for '%@' is ready. Otherwise, your "
               @"app may not use the most up-to-date value.", self.name);
         [LPVar setPrintedCallbackWarning:YES];