test: BatcherImplTest.testThrottlingBlocking to check actual wait time (#2285)

* test: additional logs in BatcherImplTest

* Replaced the assertion with actual wait time count

Author: suztomo

gax-java/gax/pom.xml

@@ -93,6 +93,14 @@
           </excludes>
         </configuration>
       </plugin>
+      <plugin>
+        <!-- Troubleshooting a flaky test in https://github.com/googleapis/sdk-platform-java/issues/1931 -->
+        <groupId>org.apache.maven.plugins</groupId>
+        <artifactId>maven-surefire-plugin</artifactId>
+        <configuration>
+          <argLine>-Djava.util.logging.SimpleFormatter.format="%1$tY %1$tl:%1$tM:%1$tS.%1$tL %2$s %4$s: %5$s%6$s%n"</argLine>
+        </configuration>
+      </plugin>
     </plugins>
   </build>
 </project>

gax-java/gax/src/test/java/com/google/api/gax/batching/BatcherImplTest.java

@@ -85,6 +85,8 @@
 @RunWith(JUnit4.class)
 public class BatcherImplTest {
 
+  private static final Logger logger = Logger.getLogger(BatcherImplTest.class.getName());
+
   private static final ScheduledExecutorService EXECUTOR =
       Executors.newSingleThreadScheduledExecutor();
 
@@ -871,6 +873,7 @@ public void testThrottlingBlocking() throws Exception {
                 public void run() {
                   batcherAddThreadHolder.add(Thread.currentThread());
                   batcher.add(1);
+                  logger.info("Called batcher.add(1)");
                 }
               });
 
@@ -885,20 +888,38 @@ public void run() {
       } while (batcherAddThreadHolder.isEmpty()
           || batcherAddThreadHolder.get(0).getState() != Thread.State.WAITING);
 
+      long beforeGetCall = System.currentTimeMillis();
       executor.submit(
           () -> {
             try {
               Thread.sleep(throttledTime);
+              logger.info("Calling flowController.release");
               flowController.release(1, 1);
+              logger.info("Called flowController.release");
             } catch (InterruptedException e) {
             }
           });
 
       try {
+        logger.info("Calling future.get(10 ms)");
         future.get(10, TimeUnit.MILLISECONDS);
-        assertWithMessage("adding elements to batcher should be blocked by FlowControlled").fail();
+        long afterGetCall = System.currentTimeMillis();
+        long actualWaitTimeMs = afterGetCall - beforeGetCall;
+
+        logger.info("future.get(10 ms) unexpectedly returned. Wait time: " + actualWaitTimeMs);
+        // In a flaky test troubleshooting
+        // (https://github.com/googleapis/sdk-platform-java/issues/1931), we observed that
+        // "future.get" method did not throw TimeoutException in this multithreaded test.
+        // It's because the thread calling "future.get" was not being run (i.e. in the wait queue of
+        // CPUs) in a timely manner.
+        // To avoid the flakiness, as long as the "future.get" does not return before the specified
+        // timeout, this assertion is considered as good.
+        assertWithMessage("adding elements to batcher should be blocked by FlowControlled")
+            .that(actualWaitTimeMs)
+            .isAtLeast(10);
       } catch (TimeoutException e) {
         // expected
+        logger.info("future.get(10 ms) timed out expectedly.");
       }
 
       try {