From 15e585853fdc97db32f46da0f0886b19f8f022d5 Mon Sep 17 00:00:00 2001
From: Mark Salyzyn <salyzyn@google.com>
Date: Mon, 23 Jan 2017 08:01:51 -0800
Subject: [PATCH] logcat: test: inject messages if necessary for tail test
 requirements

For the gTests logcat.tz, logcat.tail_3, logcat.tail_10,
logcat.tail_100, logcat.tail_1000 and logcat.tail_time tests inject
messages if we come up short should the background logging not be
sufficient to feed the test requirements.  Test frames run the
tests right after reboot requiring injection.  Will have radio
silence, so we also add kernel logs if available to help add to the
background logging activity level.

We also will inject a radio message for logcat.buckets so that test
can survive no radio content.

Test: set device to airplane mode (to stress this problem) then:
      adb logcat -b all -c && adb shell su root \
          /data/nativetest/logcat-unit-tests/logcat-unit-tests \
          --gtest_filter=logcat.tail_1000 (or others in this set)
Bug: 34454772
Change-Id: I5ec246552f3ab1fc9c5864ed69d63b851fdf538d
---
 logcat/tests/logcat_test.cpp | 79 +++++++++++++++++++++++++++---------
 1 file changed, 59 insertions(+), 20 deletions(-)

diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp
index 8a390f66f..337861e6e 100644
--- a/logcat/tests/logcat_test.cpp
+++ b/logcat/tests/logcat_test.cpp
@@ -23,6 +23,7 @@
 #include <sys/stat.h>
 #include <sys/types.h>
 #include <sys/wait.h>
+#include <unistd.h>
 
 #include <memory>
 #include <string>
@@ -54,6 +55,11 @@ static const char begin[] = "--------- beginning of ";
 TEST(logcat, buckets) {
     FILE *fp;
 
+#undef LOG_TAG
+#define LOG_TAG "inject"
+    RLOGE("logcat.buckets");
+    sleep(1);
+
     ASSERT_TRUE(NULL != (fp = popen(
       "logcat -b radio -b events -b system -b main -d 2>/dev/null",
       "r")));
@@ -165,13 +171,39 @@ char *fgetLongTime(char *buffer, size_t buflen, FILE *fp) {
         if (!ep) {
             continue;
         }
-        ep -= 7;
+        static const size_t tag_field_width = 7;
+        ep -= tag_field_width;
         *ep = '\0';
         return cp;
     }
     return NULL;
 }
 
+// If there is not enough background noise in the logs, then spam the logs to
+// permit tail checking so that the tests can progress.
+static size_t inject(ssize_t count) {
+    if (count <= 0) return 0;
+
+    static const size_t retry = 3;
+    size_t errors = retry;
+    size_t num = 0;
+    for(;;) {
+        log_time ts(CLOCK_MONOTONIC);
+        if (__android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)) >= 0) {
+            if (++num >= (size_t)count) {
+                sleep(1); // let data settle end-to-end
+                return num;
+            }
+            errors = retry;
+            usleep(50);
+        } else if (--errors <= 0) {
+            return num;
+        }
+    }
+    // NOTREACH
+    return num;
+}
+
 TEST(logcat, tz) {
 
     if (android_log_clockid() == CLOCK_MONOTONIC) {
@@ -201,7 +233,7 @@ TEST(logcat, tz) {
 
         pclose(fp);
 
-    } while ((count < 3) && --tries && (sleep(1), true));
+    } while ((count < 3) && --tries && inject(3 - count));
 
     ASSERT_EQ(3, count);
 }
@@ -236,8 +268,7 @@ void do_tail(int num) {
         char buffer[BIG_BUFFER];
 
         snprintf(buffer, sizeof(buffer),
-          "logcat -v long -b radio -b events -b system -b main -t %d 2>/dev/null",
-          num);
+                 "logcat -v long -b all -t %d 2>/dev/null", num);
 
         FILE *fp;
         ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
@@ -250,7 +281,7 @@ void do_tail(int num) {
 
         pclose(fp);
 
-    } while ((count < num) && --tries && (sleep(1), true));
+    } while ((count < num) && --tries && inject(num - count));
 
     ASSERT_EQ(num, count);
 }
@@ -273,26 +304,34 @@ TEST(logcat, tail_1000) {
 
 TEST(logcat, tail_time) {
     FILE *fp;
-
-    ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r")));
-
+    int count;
     char buffer[BIG_BUFFER];
     char *last_timestamp = NULL;
     char *first_timestamp = NULL;
-    int count = 0;
-
     char *cp;
-    while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
-        ++count;
-        if (!first_timestamp) {
-            first_timestamp = strdup(cp);
-        }
-        free(last_timestamp);
-        last_timestamp = strdup(cp);
-    }
-    pclose(fp);
 
-    EXPECT_EQ(10, count);
+    int tries = 3; // in case run too soon after system start or buffer clear
+
+    // Do not be tempted to use -v usec because that increases the
+    // chances of an occasional test failure by 1000 (see below).
+    do {
+        ASSERT_TRUE(NULL != (fp = popen("logcat -v long -b all -t 10 2>&1", "r")));
+
+        count = 0;
+
+        while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
+            ++count;
+            if (!first_timestamp) {
+                first_timestamp = strdup(cp);
+            }
+            free(last_timestamp);
+            last_timestamp = strdup(cp);
+        }
+        pclose(fp);
+
+    } while ((count < 10) && --tries && inject(10 - count));
+
+    EXPECT_EQ(10, count); // We want _some_ history, too small, falses below
     EXPECT_TRUE(last_timestamp != NULL);
     EXPECT_TRUE(first_timestamp != NULL);