Merge "binderUtilsHostTest: more debuggable" am: 98c7655dfa am: cacb9d84b4

Original change: https://android-review.googlesource.com/c/platform/frameworks/native/+/2381579

Change-Id: Id643d2172b5a8571b0fab10e3ca078063f1464f0
Signed-off-by: Automerger Merge Worker <android-build-automerger-merge-worker@system.gserviceaccount.com>

1 files changed, 21 insertions, 17 deletions

diff --git a/libs/binder/tests/binderUtilsHostTest.cpp b/libs/binder/tests/binderUtilsHostTest.cpp
index 4330e3e615..25e286ce0c 100644
--- a/libs/binder/tests/binderUtilsHostTest.cpp
+++ b/libs/binder/tests/binderUtilsHostTest.cpp
@@ -37,17 +37,24 @@ TEST(UtilsHost, ExecuteImmediately) {
     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 @@ TEST(UtilsHost, ExecuteLongRunning) {
 
     // ~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 @@ TEST(UtilsHost, ExecuteLongRunning2) {
 
     // ~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) {