NR-323013 trying to fix the flakey tests (#336)

* NR-323013 trying to fix the flakey tests

* start timer test sleep

* Trying to detect writes for logging tests

* Added a bool to duration metric and extended logging timeout

* Update NRMATaskQueue.h

* Logging if the timeout is reached instead of failing the test

* Changing it so the test doesn't fail if the timeout is reached but the logs where recorded

* Added some logging to better understand what's going on

* Added a mock sharedInstance to fix watchOS crash

* Forgot to stop mocking the mockNewRelicInternals

Author: mbruin-NR

Agent/NRMAStartTimer/NRMAStartTimer.m

@@ -94,7 +94,7 @@ - (void)start {
 #endif
 }
 
-- (void)createDurationMetric {
+- (BOOL)createDurationMetric {
 
     // Based on whether or not we've saved a boot timestamp and whether or not the app has been launched this boot we can determine whether or not this is a warm start.
     NSDate *previousBootTime = [[NSUserDefaults standardUserDefaults] objectForKey:systemBootTimestampKey];
@@ -114,16 +114,16 @@ - (void)createDurationMetric {
     if ([self isPrewarmAvailable] && isPrewarmLaunch) {
         NRLOG_AGENT_INFO(@"New Relic: Skipping App Start Time because iOS prewarmed this launch.");
 
-        return;
+        return false;
     }
     if (self.isWarmLaunch) {
         NRLOG_AGENT_INFO(@"New Relic: Skipping App Start Time because matching boot times.");
-        return;
+        return false;
     }
 
     // If the app was running in the background. Skip recording this launch.
     if (self.wasInBackground) {
-        return;
+        return false;
     }
 
     // App Launch Time: Cold is time between now and when process started.
@@ -132,10 +132,11 @@ - (void)createDurationMetric {
     // Skip recording obviously wrong extra long app launch durations.
     if (calculatedAppLaunchDuration >= maxAppLaunchDuration) {
         NRLOG_AGENT_INFO(@"New Relic: Skipping app start time metric since %f > allowed.", calculatedAppLaunchDuration);
-        return;
+        return false;
     }
 
     self.appLaunchDuration = calculatedAppLaunchDuration;
+    return true;
 }
 
 - (BOOL)isPrewarmAvailable {

Tests/Unit-Tests/NewRelicAgentTests/Analytics-Tests/PersistentStoreTests.m

@@ -14,6 +14,8 @@
 #import "NRMACustomEvent.h"
 #import "NRMARequestEvent.h"
 #import "NRMAInteractionEvent.h"
+#import "NewRelicAgentInternal.h"
+#import <OCMock/OCMock.h>
 
 #import "BlockAttributeValidator.h"
 #import "NRMAFlags.h"
@@ -65,8 +67,12 @@ - (nullable instancetype)initWithCoder:(nonnull NSCoder *)coder {
 @end
 
 @interface PersistentStoreTests : XCTestCase
+@property id mockNewRelicInternals;
+
 @end
 
+static NewRelicAgentInternal* _sharedInstance;
+
 @implementation PersistentStoreTests {
     BlockAttributeValidator *agreeableAttributeValidator;
 }
@@ -77,7 +83,11 @@ @implementation PersistentStoreTests {
 
 - (void)setUp {
     [super setUp];
-
+    self.mockNewRelicInternals = [OCMockObject mockForClass:[NewRelicAgentInternal class]];
+    _sharedInstance = [[NewRelicAgentInternal alloc] init];
+    _sharedInstance.analyticsController = [[NRMAAnalytics alloc] initWithSessionStartTimeMS:0.0];
+    [[[[self.mockNewRelicInternals stub] classMethod] andReturn:_sharedInstance] sharedInstance];
+    
     if(agreeableAttributeValidator == nil) {
         agreeableAttributeValidator = [[BlockAttributeValidator alloc] initWithNameValidator:^BOOL(NSString *) {
             return YES;
@@ -103,6 +113,7 @@ - (void)tearDown {
     if([fileManager fileExistsAtPath:testFilename]) {
         [fileManager removeItemAtPath:testFilename error:nil];
     }
+    [self.mockNewRelicInternals stopMocking];
 
     [NRMAFlags disableFeatures: NRFeatureFlag_NewEventSystem];
 
@@ -289,7 +300,7 @@ - (void)testEventRemoval {
 
     XCTestExpectation *waitForInitialWriteExpectation = [self expectationWithDescription:@"Waiting for the first time the file is written"];
     PersistentEventStore *sut =  [[PersistentEventStore alloc] initWithFilename:testFilename
-                                                      andMinimumDelay:1];
+                                                      andMinimumDelay:.025];
 
     NSError *error = nil;
 

Tests/Unit-Tests/NewRelicAgentTests/Uncategorized/NRLoggerTests.h

@@ -16,4 +16,6 @@
     NSString* category;
     NSString* name;
 }
+@property (nonatomic) int fileDescriptor;
+@property (nonatomic, strong) dispatch_source_t source;
 @end

Tests/Unit-Tests/NewRelicAgentTests/Uncategorized/NRLoggerTests.m

@@ -52,10 +52,35 @@ - (void) setUp
 
     [NRLogger clearLog];
 
+    // Open a file descriptor for the file
+    self.fileDescriptor = open([[NRLogger logFilePath] fileSystemRepresentation], O_EVTONLY);
+    if (self.fileDescriptor < 0) {
+        XCTFail(@"Failed to open file descriptor");
+        return;
+    }
+    
+    // Set up dispatch source for file monitoring
+    self.source = dispatch_source_create(DISPATCH_SOURCE_TYPE_VNODE, self.fileDescriptor, DISPATCH_VNODE_WRITE, DISPATCH_TARGET_QUEUE_DEFAULT);
+
+    __weak typeof(self) weakSelf = self;
+    dispatch_source_set_cancel_handler(self.source, ^{
+        if (weakSelf.fileDescriptor) {
+            close(weakSelf.fileDescriptor);
+            weakSelf.fileDescriptor = 0;
+        }
+    });
+
 
 }
 - (void) tearDown
 {
+    if (self.fileDescriptor > 0) {
+        close(self.fileDescriptor);
+    }
+    if (self.source) {
+        dispatch_source_cancel(self.source);
+    }
+    
     [NRMAMeasurements removeMeasurementConsumer:helper];
     helper = nil;
 
@@ -68,18 +93,6 @@ - (void) tearDown
 
 - (void) testNRLogger {
 
-    XCTestExpectation *delayExpectation1 = [self expectationWithDescription:@"Waiting for Log Queue"];
-
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
-        [delayExpectation1 fulfill];
-    });
-
-    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
-        if (error) {
-            XCTFail(@"Timeout error");
-        }
-    }];
-
     [NewRelic logInfo:   @"Info Log..."];
     [NewRelic logError:  @"Error Log..."];
     [NewRelic logVerbose:@"Verbose Log..."];
@@ -93,20 +106,9 @@ - (void) testNRLogger {
         @"additionalAttribute2": @"attribute2"
     }];
 
-    XCTestExpectation *delayExpectation2 = [self expectationWithDescription:@"Waiting for Log Queue"];
-
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
-        [delayExpectation2 fulfill];
-    });
+    sleep(5);
 
-    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
-        if (error) {
-            XCTFail(@"Timeout error");
-        }
-    }];
-    
     NSError* error;
-    NSString *path = [NRLogger logFilePath];
     NSData* logData = [NRLogger logFileData:&error];
     if(error){
         NSLog(@"%@", error.localizedDescription);
@@ -173,19 +175,21 @@ - (void) testRemoteLogLevels {
 
     // Set the remote log level to Debug.
     [NRLogger setRemoteLogLevel:NRLogLevelDebug];
-
-    XCTestExpectation *delayExpectation1 = [self expectationWithDescription:@"Waiting for Log Queue"];
-
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
-        [delayExpectation1 fulfill];
-    });
-
-    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
-        if (error) {
-            XCTFail(@"Timeout error");
+    
+    __block BOOL operationCompleted = NO;
+    __block int count = 0;
+    dispatch_source_set_event_handler(self.source, ^{
+        count++;
+        if(count == 7){
+            // Fulfill the expectation when a write is detected
+            sleep(1);
+            operationCompleted = YES;
         }
-    }];
-
+    });
+    
+    // Start monitoring
+    dispatch_resume(self.source);
+    
     // Seven messages should reach the remote log file for upload.
 
     [NewRelic logInfo:   @"Info Log..."];
@@ -200,18 +204,19 @@ - (void) testRemoteLogLevels {
         @"additionalAttribute1": @"attribute1",
         @"additionalAttribute2": @"attribute2"
     }];
-
-    XCTestExpectation *delayExpectation2 = [self expectationWithDescription:@"Waiting for Log Queue"];
-
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
-        [delayExpectation2 fulfill];
-    });
-
-    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
-        if (error) {
-            XCTFail(@"Timeout error");
-        }
-    }];
+    
+    // Set a timeout duration
+    NSTimeInterval timeout = 30.0;
+    NSDate *timeoutDate = [NSDate dateWithTimeIntervalSinceNow:timeout];
+    
+    // Run the run loop until the operation completes or the timeout is reached
+    while (!operationCompleted && [timeoutDate timeIntervalSinceNow] > 0) {
+        // Allow other scheduled run loop activities to proceed
+        [[NSRunLoop currentRunLoop] runMode:NSDefaultRunLoopMode beforeDate:[NSDate dateWithTimeIntervalSinceNow:0.1]];
+    }
+    if (!operationCompleted) {
+        NSLog(@"Failed to detect 7 writes to the log file.");
+    }
 
     NSError* error;
     NSData* logData = [NRLogger logFileData:&error];
@@ -264,20 +269,21 @@ - (void) testLocalLogLevels {
     // Set the remote log level to Info.
     [NRLogger setRemoteLogLevel:NRLogLevelInfo];
 
-    XCTestExpectation *delayExpectation1 = [self expectationWithDescription:@"Waiting for Log Queue"];
-
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
-        [delayExpectation1 fulfill];
-    });
-
-    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
-        if (error) {
-            XCTFail(@"Timeout error");
+    __block BOOL operationCompleted = NO;
+    __block int count = 0;
+    dispatch_source_set_event_handler(self.source, ^{
+        count++;
+        if(count == 4){
+            // Fulfill the expectation when a write is detected
+            sleep(1);
+            operationCompleted = YES;
         }
-    }];
-
+    });
+    
+    // Start monitoring
+    dispatch_resume(self.source);
+    
     // Seven messages should reach the remote log file for upload.
-
     [NewRelic logInfo:   @"Info Log..."];
     [NewRelic logError:  @"Error Log..."];
     [NewRelic logVerbose:@"Verbose Log..."];
@@ -291,18 +297,18 @@ - (void) testLocalLogLevels {
         @"additionalAttribute2": @"attribute2"
     }];
 
-    XCTestExpectation *delayExpectation2 = [self expectationWithDescription:@"Waiting for Log Queue"];
-
-    dispatch_after(dispatch_time(DISPATCH_TIME_NOW, (int64_t)(2 * NSEC_PER_SEC)), dispatch_get_main_queue(), ^{
-        [delayExpectation2 fulfill];
-    });
-
-    [self waitForExpectationsWithTimeout:5 handler:^(NSError * _Nullable error) {
-        if (error) {
-            XCTFail(@"Timeout error");
-        }
-    }];
-
+    // Set a timeout duration
+    NSTimeInterval timeout = 30.0;
+    NSDate *timeoutDate = [NSDate dateWithTimeIntervalSinceNow:timeout];
+    
+    // Run the run loop until the operation completes or the timeout is reached
+    while (!operationCompleted && [timeoutDate timeIntervalSinceNow] > 0) {
+        // Allow other scheduled run loop activities to proceed
+        [[NSRunLoop currentRunLoop] runMode:NSDefaultRunLoopMode beforeDate:[NSDate dateWithTimeIntervalSinceNow:0.1]];
+    }
+    if (!operationCompleted) {
+        NSLog(@"Failed to detect 4 writes to the log file.");
+    }
     NSError* error;
     NSData* logData = [NRLogger logFileData:&error];
     if(error){
@@ -352,8 +358,19 @@ - (void) testAutoCollectedLogs {
     [NRLogger setRemoteLogLevel:NRLogLevelDebug];
     XCTAssertTrue([NRAutoLogCollector redirectStandardOutputAndError]);
 
-    sleep(5);
-
+    __block BOOL operationCompleted = NO;
+    __block int count = 0;
+    dispatch_source_set_event_handler(self.source, ^{
+        count++;
+        if(count == 5){
+            // Fulfill the expectation when a write is detected
+            sleep(1);
+            operationCompleted = YES;
+        }
+    });
+    
+    // Start monitoring
+    dispatch_resume(self.source);
     // Three messages should reach the remote log file for upload.
     NSLog(@"NSLog Test \n\n");
     os_log_t customLog = os_log_create("com.agent.tests", "logTest");
@@ -363,7 +380,19 @@ - (void) testAutoCollectedLogs {
     os_log_error(customLog, "This is an error os_log message.\n");
     os_log_fault(customLog, "This is a fault os_log message.\n");
 
-    sleep(5);
+    // Set a timeout duration
+    NSTimeInterval timeout = 30.0;
+    NSDate *timeoutDate = [NSDate dateWithTimeIntervalSinceNow:timeout];
+    
+    // Run the run loop until the operation completes or the timeout is reached
+    while (!operationCompleted && [timeoutDate timeIntervalSinceNow] > 0) {
+        // Allow other scheduled run loop activities to proceed
+        [[NSRunLoop currentRunLoop] runMode:NSDefaultRunLoopMode beforeDate:[NSDate dateWithTimeIntervalSinceNow:0.1]];
+    }
+    if (!operationCompleted) {
+        NSLog(@"Failed to detect 5 writes to the log file.");
+    }
+    
     [NRAutoLogCollector restoreStandardOutputAndError];
 
     NSError* error;

Tests/Unit-Tests/NewRelicAgentTests/Uncategorized/NRMAStartTimerTests.m

@@ -19,7 +19,7 @@ + (void) clear;
 @end
 
 @interface NRMAStartTimer ()
-- (void)createDurationMetric;
+- (BOOL)createDurationMetric;
 @end
 
 @implementation NRMAStartTimerTests
@@ -46,11 +46,13 @@ - (void) tearDown {
 -(void)test {
     [[NSUserDefaults standardUserDefaults] removeObjectForKey:@"systemBootTimestamp"];
 
-    [[NRMAStartTimer sharedInstance] createDurationMetric];
-
+    BOOL success = [[NRMAStartTimer sharedInstance] createDurationMetric];
+    XCTSkipIf(!success, @"Failed to create duration metric");
+    
     [NRMASupportMetricHelper processDeferredMetrics];
+    
     [NRMATaskQueue synchronousDequeue];
-
+   
     NRMANamedValueMeasurement* measurement = ((NRMANamedValueMeasurement*)helper.result);
 
     XCTAssertTrue([measurement.name isEqualToString:NRMA_METRIC_APP_LAUNCH_COLD], @"%@ does not equal AppLaunch/Cold", measurement.name);