1 package com.android.compatibility.common.util;
2 
3 import static junit.framework.TestCase.fail;
4 
5 import com.google.common.base.Joiner;
6 import com.google.common.io.Closeables;
7 
8 import java.io.BufferedReader;
9 import java.io.IOException;
10 import java.io.InputStream;
11 import java.io.InputStreamReader;
12 import java.util.UUID;
13 import java.util.concurrent.TimeUnit;
14 
15 /**
16  * Inherit this class and implement {@link #executeShellCommand(String)} to be able to assert that
17  * logcat contains what you want.
18  */
19 public abstract class LogcatInspector {
20     private static final int SMALL_LOGCAT_DELAY = 1000;
21 
22     /**
23      * Should execute adb shell {@param command} and return an {@link InputStream} with the result.
24      */
executeShellCommand(String command)25     protected abstract InputStream executeShellCommand(String command) throws IOException;
26 
27     /**
28      * Logs an unique string using tag {@param tag} and wait until it appears to continue execution.
29      *
30      * @return a unique separator string.
31      * @throws IOException if error while executing command.
32      */
mark(String tag)33     public String mark(String tag) throws IOException {
34         String uniqueString = ":::" + UUID.randomUUID().toString();
35         Closeables.closeQuietly(executeShellCommand("log -t " + tag + " " + uniqueString));
36         // This is to guarantee that we only return after the string has been logged, otherwise
37         // in practice the case where calling Log.?(<message1>) right after clearAndMark() resulted
38         // in <message1> appearing before the unique identifier. It's not guaranteed per the docs
39         // that log command will have written when returning, so better be safe. 5s should be fine.
40         assertLogcatContainsInOrder(tag + ":* *:S", 5, uniqueString);
41         return uniqueString;
42     }
43 
44     /**
45      * Wait for up to {@param maxTimeoutInSeconds} for the given {@param logcatStrings} strings to
46      * appear in logcat in the given order. By passing the separator returned by {@link
47      * #mark(String)} as the first string you can ensure that only logs emitted after that
48      * call to mark() are found. Repeated strings are not supported.
49      *
50      * @throws AssertionError if the strings are not found in the given time.
51      * @throws IOException if error while reading.
52      */
assertLogcatContainsInOrder( String filterSpec, int maxTimeoutInSeconds, String... logcatStrings)53     public void assertLogcatContainsInOrder(
54             String filterSpec, int maxTimeoutInSeconds, String... logcatStrings)
55             throws AssertionError, IOException {
56         try {
57             int nextStringIndex =
58                     numberOfLogcatStringsFound(filterSpec, maxTimeoutInSeconds, logcatStrings);
59             if (nextStringIndex < logcatStrings.length) {
60                 fail(
61                         "Couldn't find "
62                                 + logcatStrings[nextStringIndex]
63                                 + (nextStringIndex > 0
64                                         ? " after " + logcatStrings[nextStringIndex - 1]
65                                         : "")
66                                 + " within "
67                                 + maxTimeoutInSeconds
68                                 + " seconds ");
69             }
70         } catch (InterruptedException e) {
71             fail("Thread interrupted unexpectedly: " + e.getMessage());
72         }
73     }
74 
75     /**
76      * Wait for up to {@param timeInSeconds}, if all the strings {@param logcatStrings} are found in
77      * order then the assertion fails, otherwise it succeeds.
78      *
79      * @throws AssertionError if all the strings are found in order in the given time.
80      * @throws IOException if error while reading.
81      */
assertLogcatDoesNotContainInOrder(int timeInSeconds, String... logcatStrings)82     public void assertLogcatDoesNotContainInOrder(int timeInSeconds, String... logcatStrings)
83             throws IOException {
84         try {
85             int stringsFound = numberOfLogcatStringsFound("", timeInSeconds, logcatStrings);
86             if (stringsFound == logcatStrings.length) {
87                 fail("Found " + Joiner.on(", ").join(logcatStrings) + " that weren't expected");
88             }
89         } catch (InterruptedException e) {
90             fail("Thread interrupted unexpectedly: " + e.getMessage());
91         }
92     }
93 
numberOfLogcatStringsFound( String filterSpec, int timeInSeconds, String... logcatStrings)94     private int numberOfLogcatStringsFound(
95             String filterSpec, int timeInSeconds, String... logcatStrings)
96             throws InterruptedException, IOException {
97         long timeout = System.currentTimeMillis() + TimeUnit.SECONDS.toMillis(timeInSeconds);
98         int stringIndex = 0;
99         long lastEpochMicroseconds = 0;
100         while (timeout >= System.currentTimeMillis()) {
101             // '-v epoch' -> Displays time as seconds since Jan 1 1970.
102             // '-v usec' -> Displays time down the microsecond precision.
103             InputStream logcatStream =
104                     executeShellCommand("logcat -v epoch -v usec -d " + filterSpec);
105             BufferedReader logcat = new BufferedReader(new InputStreamReader(logcatStream));
106             String line;
107             while ((line = logcat.readLine()) != null) {
108                 if (line.contains(logcatStrings[stringIndex])) {
109                     // Now we need to get the timestamp of this log line to ensure that
110                     // this log is after the previously matched log.
111 
112                     // Strip the leading spaces and split the line by spaces
113                     String[] splitLine = line.stripLeading().split(" ");
114 
115                     // The first one is epoch time in seconds, with microsecond precision.
116                     // It is of the format <epoch time in seconds>.xxxxxx
117                     String epochMicrosecondsStr = splitLine[0].replace(".", "");
118                     long epochMicroseconds = Long.parseLong(epochMicrosecondsStr);
119 
120                     // Check that this log time is after previously matched log
121                     if (epochMicroseconds >= lastEpochMicroseconds) {
122                         stringIndex++;
123                         if (stringIndex >= logcatStrings.length) {
124                             StreamUtil.drainAndClose(logcat);
125                             return stringIndex;
126                         }
127                     }
128                 }
129             }
130             Closeables.closeQuietly(logcat);
131             // In case the key has not been found, wait for the log to update before
132             // performing the next search.
133             Thread.sleep(SMALL_LOGCAT_DELAY);
134         }
135         return stringIndex;
136     }
137 }
138