From d2fbc4cd591a5656b8715fa39cc548366738d940 Mon Sep 17 00:00:00 2001
From: Ruslan Shestopalyuk <rshest@meta.com>
Date: Tue, 4 Oct 2022 04:38:07 -0700
Subject: [PATCH] Fix race condition in RCTLoggingTests integration tests
 (#34858)

Summary:
Pull Request resolved: https://github.com/facebook/react-native/pull/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: https://github.com/facebook/react-native/pull/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
---
 .../RCTLoggingTests.m                         | 40 ++++++++++---------
 1 file changed, 22 insertions(+), 18 deletions(-)

diff --git a/packages/rn-tester/RNTesterIntegrationTests/RCTLoggingTests.m b/packages/rn-tester/RNTesterIntegrationTests/RCTLoggingTests.m
index 03a1d4defda35f..cb151181c92fff 100644
--- a/packages/rn-tester/RNTesterIntegrationTests/RCTLoggingTests.m
+++ b/packages/rn-tester/RNTesterIntegrationTests/RCTLoggingTests.m
@@ -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,
@@ -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);