Fix deadlock in RCTLoggingTests

Summary:
Some portions of continuous test runs RNTesterIntegrationTests will hang for an hour when running in Sandcastle without outputting anything. Locally debugging, I see a deadlock waiting on a semaphore, where the test assumed an extraneous symbolication warning would be fired.

This change makes it so that we only look for the extraneous messages if we haven't already seen the target message, since they do not seem to show up in local testing. I also added assertions per semaphore that the log statement is propagated within a still very gracious 10 seconds. This means we still can see what tests are running/failing if this test has issues, instead of a deadlocked test runner with no output.

Changelog:
[Internal][Fixed] - Fix deadlock in RCTLoggingTests

Reviewed By: cipolleschi

Differential Revision: D40667275

fbshipit-source-id: ab78f3c2ef47e2fd740b1dad2a65912e9542301d

packages/rn-tester/RNTesterIntegrationTests/RCTLoggingTests.m

@@ -11,6 +11,9 @@
 #import <React/RCTBridge.h>
 #import <React/RCTLog.h>
 
+// Time to wait for an expected log statement to show before failing the test
+const int64_t LOGGER_TIMEOUT = 10 * NSEC_PER_SEC;
+
 @interface RCTLoggingTests : XCTestCase
 
 @end
@@ -71,53 +74,64 @@ - (void)tearDown
 
 - (void)testLogging
 {
+ intptr_t waitRet = 0;
+
  // 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]);
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for log marker");
+ } while (waitRet == 0 && ![_lastLogMessage isEqualToString:LogMarker]);
 
  [_bridge enqueueJSCall:@"LoggingTestModule.logToConsole" args:@[ @"Invoking console.log" ]];
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for logToConsole");
 
  XCTAssertEqual(_lastLogLevel, RCTLogLevelInfo);
  XCTAssertEqual(_lastLogSource, RCTLogSourceJavaScript);
  XCTAssertEqualObjects(_lastLogMessage, @"Invoking console.log");
 
  [_bridge enqueueJSCall:@"LoggingTestModule.warning" args:@[ @"Generating warning" ]];
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for warning");
 
  XCTAssertEqual(_lastLogLevel, RCTLogLevelWarning);
  XCTAssertEqual(_lastLogSource, RCTLogSourceJavaScript);
  XCTAssertEqualObjects(_lastLogMessage, @"Generating warning");
 
  [_bridge enqueueJSCall:@"LoggingTestModule.invariant" args:@[ @"Invariant failed" ]];
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for invariant");
 
  XCTAssertEqual(_lastLogLevel, RCTLogLevelError);
  XCTAssertEqual(_lastLogSource, RCTLogSourceJavaScript);
  XCTAssertTrue([_lastLogMessage containsString:@"Invariant Violation: Invariant failed"]);
 
  [_bridge enqueueJSCall:@"LoggingTestModule.logErrorToConsole" args:@[ @"Invoking console.error" ]];
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for logErrorToConsole");
 
- // For local bundles, we'll first get a warning about symbolication
- if ([_bridge.bundleURL isFileURL]) {
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ // For local bundles, we may first get a warning about symbolication
+ if (![_lastLogMessage isEqualToString:@"Invoking console.error"]) {
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for logErrorToConsole #2");
  }
 
  XCTAssertEqual(_lastLogLevel, RCTLogLevelError);
  XCTAssertEqual(_lastLogSource, RCTLogSourceJavaScript);
  XCTAssertEqualObjects(_lastLogMessage, @"Invoking console.error");
 
  [_bridge enqueueJSCall:@"LoggingTestModule.throwError" args:@[ @"Throwing an error" ]];
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for throwError");
 
- // For local bundles, we'll first get a warning about symbolication
- if ([_bridge.bundleURL isFileURL]) {
- dispatch_semaphore_wait(_logSem, DISPATCH_TIME_FOREVER);
+ // For local bundles, we may first get a warning about symbolication
+ if (![_lastLogMessage isEqualToString:@"Error: Throwing an error"]) {
+ waitRet = dispatch_semaphore_wait(_logSem, dispatch_time(DISPATCH_TIME_NOW, LOGGER_TIMEOUT));
+ XCTAssertEqual(waitRet, 0, @"Timed out waiting for throwError #2");
  }
 
  XCTAssertEqual(_lastLogLevel, RCTLogLevelError);