commit 4209a52a73435f34715359d211b2c2fdd22f321e
author Steven Moreland <smoreland@google.com> Wed Jan 11 02:10:04 2023 +0000
committer Steven Moreland <smoreland@google.com> Wed Jan 11 02:17:29 2023 +0000
tree ec93df21e67dbe0c6d7c9cbff2de717475ec97fa
parent a715e0cfdbd38fdc6319c0ebe82ff619843080c5

binderUtilsHostTest: more debuggable

Changes to make a flake that happens here more visible.

- if final sleep is not logged, wait much longer
- log times of various commands

Bug: 264505396
Test: binderUtilsHostTest
Change-Id: I0cb676556ce18fbbbb6d7955cfa43fef77fecc3d

libs/binder/tests/binderUtilsHostTest.cpp

diff --git a/libs/binder/tests/binderUtilsHostTest.cpp b/libs/binder/tests/binderUtilsHostTest.cpp
index 4330e3e..25e286c 100644
--- a/libs/binder/tests/binderUtilsHostTest.cpp
+++ b/libs/binder/tests/binderUtilsHostTest.cpp
@@ -37,17 +37,24 @@
     EXPECT_EQ(result->stdoutStr, "foo\n");
 }
 
+template <typename T>
+auto millisSince(std::chrono::time_point<T> now) {
+    auto elapsed = std::chrono::system_clock::now() - now;
+    return std::chrono::duration_cast<std::chrono::milliseconds>(elapsed).count();
+}
+
 TEST(UtilsHost, ExecuteLongRunning) {
-    auto now = std::chrono::system_clock::now();
+    auto start = std::chrono::system_clock::now();
 
     {
-        std::vector<std::string> args{"sh", "-c",
-                                      "sleep 0.5 && echo -n f && sleep 0.5 && echo oo && sleep 1"};
-        auto result = execute(std::move(args), [](const CommandResult& commandResult) {
+        std::vector<std::string>
+                args{"sh", "-c", "sleep 0.5 && echo -n f && sleep 0.5 && echo oo && sleep 100"};
+        auto result = execute(std::move(args), [&](const CommandResult& commandResult) {
+            std::cout << millisSince(start)
+                      << "ms: GOT PARTIAL COMMAND RESULT:" << commandResult.stdoutStr << std::endl;
             return android::base::EndsWith(commandResult.stdoutStr, "\n");
         });
-        auto elapsed = std::chrono::system_clock::now() - now;
-        auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(elapsed).count();
+        auto elapsedMs = millisSince(start);
         EXPECT_GE(elapsedMs, 1000);
         EXPECT_LT(elapsedMs, 2000);
 
@@ -58,22 +65,21 @@
 
     // ~CommandResult() called, child process is killed.
     // Assert that the second sleep does not finish.
-    auto elapsed = std::chrono::system_clock::now() - now;
-    auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(elapsed).count();
-    EXPECT_LT(elapsedMs, 2000);
+    EXPECT_LT(millisSince(start), 2000);
 }
 
 TEST(UtilsHost, ExecuteLongRunning2) {
-    auto now = std::chrono::system_clock::now();
+    auto start = std::chrono::system_clock::now();
 
     {
         std::vector<std::string> args{"sh", "-c",
-                                      "sleep 2 && echo -n f && sleep 2 && echo oo && sleep 2"};
-        auto result = execute(std::move(args), [](const CommandResult& commandResult) {
+                                      "sleep 2 && echo -n f && sleep 2 && echo oo && sleep 100"};
+        auto result = execute(std::move(args), [&](const CommandResult& commandResult) {
+            std::cout << millisSince(start)
+                      << "ms: GOT PARTIAL COMMAND RESULT:" << commandResult.stdoutStr << std::endl;
             return android::base::EndsWith(commandResult.stdoutStr, "\n");
         });
-        auto elapsed = std::chrono::system_clock::now() - now;
-        auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(elapsed).count();
+        auto elapsedMs = millisSince(start);
         EXPECT_GE(elapsedMs, 4000);
         EXPECT_LT(elapsedMs, 6000);
 
@@ -84,9 +90,7 @@
 
     // ~CommandResult() called, child process is killed.
     // Assert that the second sleep does not finish.
-    auto elapsed = std::chrono::system_clock::now() - now;
-    auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(elapsed).count();
-    EXPECT_LT(elapsedMs, 6000);
+    EXPECT_LT(millisSince(start), 6000);
 }
 
 TEST(UtilsHost, KillWithSigKill) {