Skip to content

Commit

Permalink
Fix race condition in RCTLoggingTests integration tests (#34858)
Browse files Browse the repository at this point in the history
Summary:
Pull Request resolved: #34858

Changelog:

[iOS][Fixed] - Fix race condition in RCTLoggingTests integration tests

RCTLoggingTests work in the following way:
* Put a custom hook on logging (logging function) to intercept log messages
* Send several log messages via JS and see whether they hit the hook as expected

The problem with this approach was that there may be unexpected log messages, which squeeze inbetween the points of time when the hook was set and when the first message was sent.

There was a (now 6 years old!!!) fix to mitigate this problem, which was adding a lead pause of 2s to "make sure" that all the other possible log messages had been sent: #10568

That didn't actually guarantee fixing the problem in general, just partially mitigating it, as the race condition conceptually still remained there.

Here I take a different approach, which should guarantee that we skip all the rogue JS messages before we start sending and reading them on our own:
* Install the hook
* Log a "marker" message
* Pump the log until the marker appears - at this point we know that the hook has been definitely installed

Reviewed By: cipolleschi

Differential Revision: D40043442

fbshipit-source-id: b4aa617d27c2dcff26682dd72e47ec19cb0d11ca
  • Loading branch information
rshest authored and facebook-github-bot committed Oct 4, 2022
1 parent 06df917 commit 540ae39
Showing 1 changed file with 22 additions and 18 deletions.
40 changes: 22 additions & 18 deletions packages/rn-tester/RNTesterIntegrationTests/RCTLoggingTests.m
Original file line number Diff line number Diff line change
Expand Up @@ -44,24 +44,8 @@ - (void)setUp
XCTAssertFalse(_bridge.loading);

_logSem = dispatch_semaphore_create(0);
}

- (void)tearDown
{
[_bridge invalidate];
_bridge = nil;

RCTSetLogFunction(RCTDefaultLogFunction);
}

- (void)testLogging
{
// First console log call will fire after 2.0 sec, to allow for any initial log messages
// that might come in (seeing this in tvOS)
[_bridge enqueueJSCall:@"LoggingTestModule.logToConsoleAfterWait" args:@[ @"Invoking console.log", @2000 ]];
// Spin native layer for 1.9 sec
[[NSRunLoop currentRunLoop] runUntilDate:[NSDate dateWithTimeIntervalSinceNow:1.9]];
// Now set the log function to signal the semaphore
// Set the log function to signal the semaphore
RCTSetLogFunction(
^(RCTLogLevel level,
RCTLogSource source,
Expand All @@ -75,7 +59,27 @@ - (void)testLogging
dispatch_semaphore_signal(self->_logSem);
}
});
// Wait for console log to signal the semaphore
}

- (void)tearDown
{
[_bridge invalidate];
_bridge = nil;

RCTSetLogFunction(RCTDefaultLogFunction);
}

- (void)testLogging
{
// First queue the marker and spin until it happens to be logged.
// This is to ensure we skip all of the other messages, that were logged earlier.
NSString *const LogMarker = @"===LOG_MARKER===";
[_bridge enqueueJSCall:@"LoggingTestModule.logToConsole" args:@[ LogMarker ]];
do {
dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
} while (![_lastLogMessage isEqualToString:LogMarker]);

[_bridge enqueueJSCall:@"LoggingTestModule.logToConsole" args:@[ @"Invoking console.log" ]];
dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);

XCTAssertEqual(_lastLogLevel, RCTLogLevelInfo);
Expand Down

1 comment on commit 540ae39

@rshest
Copy link
Contributor Author

@rshest rshest commented on 540ae39 Oct 4, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Failed "TestDocker" test looks like an infra issue, not related to this change:

Unable to download: mvn:org.robolectric:utils:jar:4.4

Please sign in to comment.