1 /*
2  * Copyright (C) 2023 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 package android.boottime;
18 
19 import com.android.ddmlib.testrunner.IRemoteAndroidTestRunner;
20 import com.android.ddmlib.testrunner.RemoteAndroidTestRunner;
21 import com.android.tradefed.config.Option;
22 import com.android.tradefed.config.OptionClass;
23 import com.android.tradefed.device.DeviceNotAvailableException;
24 import com.android.tradefed.device.ITestDevice;
25 import com.android.tradefed.device.LogcatReceiver;
26 import com.android.tradefed.invoker.TestInformation;
27 import com.android.tradefed.log.LogUtil.CLog;
28 import com.android.tradefed.result.CollectingTestListener;
29 import com.android.tradefed.result.FileInputStreamSource;
30 import com.android.tradefed.result.InputStreamSource;
31 import com.android.tradefed.result.LogDataType;
32 import com.android.tradefed.testtype.DeviceJUnit4ClassRunner;
33 import com.android.tradefed.testtype.DeviceJUnit4ClassRunner.TestLogData;
34 import com.android.tradefed.testtype.DeviceJUnit4ClassRunner.TestMetrics;
35 import com.android.tradefed.testtype.junit4.BaseHostJUnit4Test;
36 import com.android.tradefed.testtype.junit4.BeforeClassWithInfo;
37 import com.android.tradefed.util.CommandResult;
38 import com.android.tradefed.util.CommandStatus;
39 import com.android.tradefed.util.RunUtil;
40 
41 import org.junit.Before;
42 import org.junit.Rule;
43 import org.junit.Test;
44 import org.junit.runner.RunWith;
45 
46 import java.io.File;
47 import java.util.ArrayList;
48 import java.util.List;
49 
50 /** Performs successive reboots */
51 @RunWith(DeviceJUnit4ClassRunner.class)
52 @OptionClass(alias = "boot-time-test")
53 public class BootTimeTest extends BaseHostJUnit4Test {
54     private static final String LOGCAT_CMD_ALL = "logcat -b all *:V";
55     private static final String LOGCAT_CMD_CLEAR = "logcat -c";
56     private static final long LOGCAT_SIZE = 80 * 1024 * 1024;
57     private static final String DMESG_FILE = "/data/local/tmp/dmesglogs.txt";
58     private static final String DUMP_DMESG = String.format("dmesg > %s", DMESG_FILE);
59     private static final String LOGCAT_FILENAME = "Successive_reboots_logcat";
60     private static final String DMESG_FILENAME = "Successive_reboots_dmesg";
61     private static final String IMMEDIATE_DMESG_FILENAME = "Successive_reboots_immediate_dmesg";
62     private static final String F2FS_SHUTDOWN_COMMAND = "f2fs_io shutdown 4 /data";
63     private static final String F2FS_SHUTDOWN_SUCCESS_OUTPUT = "Shutdown /data with level=4";
64     private static final String BOOT_TIME_PROP = "ro.boot.boottime";
65     private static final String BOOT_TIME_PROP_KEY = "boot_time_prop";
66     private static final String METRIC_KEY_SEPARATOR = "_";
67     private static final String PERFETTO_TRACE_FILE_CHECK_CMD = "ls -l /data/misc/perfetto-traces";
68     private static final String PERFETTO_TRACE_MV_CMD =
69             "mv /data/misc/perfetto-traces/boottrace.perfetto-trace %s";
70     private static final String PERFETTO_FILE_PATH = "perfetto_file_path";
71     private static final int BOOT_COMPLETE_POLL_INTERVAL = 1000;
72     private static final int BOOT_COMPLETE_POLL_RETRY_COUNT = 45;
73     private static final String PACKAGE_NAME = "com.android.boothelper";
74     private static final String CLASS_NAME = "com.android.boothelper.BootHelperTest";
75     private static final String RUNNER = "androidx.test.runner.AndroidJUnitRunner";
76     private static final String UNLOCK_PIN_TEST = "unlockScreenWithPin";
77     private static final String SETUP_PIN_TEST = "setupLockScreenPin";
78 
getBootTimePropKey()79     public static String getBootTimePropKey() {
80         return BOOT_TIME_PROP_KEY;
81     }
82 
83     @Option(
84             name = "boot-count",
85             description =
86                     "Number of times to boot the devices to calculate the successive boot delay."
87                             + " Second boot after the first boot will be skipped for correctness.")
88     private int mBootCount = 5;
89 
90     @Option(
91             name = "boot-delay",
92             isTimeVal = true,
93             description = "Time to wait between the successive boots.")
94     private long mBootDelayTime = 2000;
95 
96     @Option(
97             name = "after-boot-delay",
98             isTimeVal = true,
99             description = "Time to wait immediately after the successive boots.")
100     private long mAfterBootDelayTime = 0;
101 
102     @Option(name = "device-boot-time", description = "Max time in ms to wait for device to boot.")
103     protected long mDeviceBootTime = 5 * 60 * 1000;
104 
105     @Option(
106             name = "successive-boot-prepare-cmd",
107             description =
108                     "A list of adb commands to run after first boot to prepare for successive"
109                             + " boot tests")
110     private List<String> mDeviceSetupCommands = new ArrayList<>();
111 
112     /**
113      * Use this flag not to dump the dmesg logs immediately after the device is online. Use it only
114      * if some of the boot dmesg logs are cleared when waiting until boot completed. By default this
115      * is set to true which might result in duplicate logging.
116      */
117     @Option(
118             name = "dump-dmesg-immediate",
119             description =
120                     "Whether to dump the dmesg logs" + "immediately after the device is online")
121     private boolean mDumpDmesgImmediate = true;
122 
123     @Option(
124             name = "force-f2fs-shutdown",
125             description = "Force f2fs shutdown to trigger fsck check during the reboot.")
126     private boolean mForceF2FsShutdown = false;
127 
128     @Option(
129             name = "skip-pin-setup",
130             description =
131                     "Skip the pin setup if already set once"
132                             + "and not needed for the second run especially in local testing.")
133     private boolean mSkipPinSetup = false;
134 
135     private LogcatReceiver mRebootLogcatReceiver = null;
136     private IRemoteAndroidTestRunner mPostBootTestRunner = null;
137 
138     @Rule public TestLogData testLog = new TestLogData();
139     @Rule public TestMetrics testMetrics = new TestMetrics();
140 
141     /**
142      * Prepares the device for successive boots
143      *
144      * @param testInfo Test Information
145      * @throws DeviceNotAvailableException if connection with device is lost and cannot be
146      *     recovered.
147      */
148     @BeforeClassWithInfo
beforeClassWithDevice(TestInformation testInfo)149     public static void beforeClassWithDevice(TestInformation testInfo)
150             throws DeviceNotAvailableException {
151         ITestDevice testDevice = testInfo.getDevice();
152 
153         testDevice.enableAdbRoot();
154         testDevice.setDate(null);
155         testDevice.nonBlockingReboot();
156         testDevice.waitForDeviceOnline();
157         testDevice.waitForDeviceAvailable(0);
158     }
159 
160     @Before
setUp()161     public void setUp() throws Exception {
162         mPostBootTestRunner = null;
163         setUpDeviceForSuccessiveBoots();
164         CLog.v("Waiting for %d msecs before successive boots.", mBootDelayTime);
165         sleep(mBootDelayTime);
166     }
167 
168     @Test
testSuccessiveBoots()169     public void testSuccessiveBoots() throws Exception {
170         for (int count = 0; count < mBootCount; count++) {
171             testSuccessiveBoot(count);
172         }
173     }
174 
175     @Test
testSuccessiveBootsDismissPin()176     public void testSuccessiveBootsDismissPin() throws Exception {
177         // If pin is already set skip the setup method otherwise setup the pin.
178         if (!mSkipPinSetup) {
179             getDevice()
180                     .runInstrumentationTests(
181                             createRemoteAndroidTestRunner(SETUP_PIN_TEST),
182                             new CollectingTestListener());
183         }
184         mPostBootTestRunner = createRemoteAndroidTestRunner(UNLOCK_PIN_TEST);
185         for (int count = 0; count < mBootCount; count++) {
186             testSuccessiveBoot(count);
187         }
188     }
189 
testSuccessiveBoot(int iteration)190     public void testSuccessiveBoot(int iteration) throws Exception {
191         CLog.v("Successive boot iteration %d", iteration);
192         getDevice().enableAdbRoot();
193         // Property used for collecting the perfetto trace file on boot.
194         getDevice().executeShellCommand("setprop persist.debug.perfetto.boottrace 1");
195         if (mForceF2FsShutdown) {
196             forseF2FsShutdown();
197         }
198         clearAndStartLogcat();
199         sleep(5000);
200         getDevice().nonBlockingReboot();
201         getDevice().waitForDeviceOnline(mDeviceBootTime);
202         getDevice().enableAdbRoot();
203         if (mDumpDmesgImmediate) {
204             saveDmesgInfo(
205                     String.format(
206                             "%s%s%d", IMMEDIATE_DMESG_FILENAME, METRIC_KEY_SEPARATOR, iteration));
207         }
208         CLog.v("Waiting for %d msecs immediately after successive boot.", mAfterBootDelayTime);
209         sleep(mAfterBootDelayTime);
210         waitForBootComplete();
211         if (mPostBootTestRunner != null) {
212             sleep(2000);
213             getDevice().runInstrumentationTests(mPostBootTestRunner, new CollectingTestListener());
214         }
215         saveDmesgInfo(String.format("%s%s%d", DMESG_FILENAME, METRIC_KEY_SEPARATOR, iteration));
216         saveLogcatInfo(iteration);
217         // TODO(b/288323866): figure out why is the prop value null
218         String bootLoaderVal = getDevice().getProperty(BOOT_TIME_PROP);
219         // Sample Output : 1BLL:89,1BLE:590,2BLL:0,2BLE:1344,SW:6734,KL:1193
220         CLog.d("%s value is %s", BOOT_TIME_PROP, bootLoaderVal);
221         testMetrics.addTestMetric(
222                 String.format("%s%s%d", BOOT_TIME_PROP_KEY, METRIC_KEY_SEPARATOR, iteration),
223                 bootLoaderVal == null ? "" : bootLoaderVal);
224         String perfettoTraceFilePath =
225                 processPerfettoFile(
226                         String.format(
227                                 "%s%s%d",
228                                 BootTimeTest.class.getSimpleName(),
229                                 METRIC_KEY_SEPARATOR,
230                                 iteration));
231         if (perfettoTraceFilePath != null) {
232             testMetrics.addTestMetric(
233                     String.format("%s%s%d", PERFETTO_FILE_PATH, METRIC_KEY_SEPARATOR, iteration),
234                     perfettoTraceFilePath);
235         }
236     }
237 
setUpDeviceForSuccessiveBoots()238     private void setUpDeviceForSuccessiveBoots() throws DeviceNotAvailableException {
239         for (String cmd : mDeviceSetupCommands) {
240             CommandResult result;
241             result = getDevice().executeShellV2Command(cmd);
242             if (!CommandStatus.SUCCESS.equals(result.getStatus())) {
243                 CLog.w(
244                         "Post boot setup cmd: '%s' failed, returned:\nstdout:%s\nstderr:%s",
245                         cmd, result.getStdout(), result.getStderr());
246             }
247         }
248     }
249 
forseF2FsShutdown()250     private void forseF2FsShutdown() throws DeviceNotAvailableException {
251         String output = getDevice().executeShellCommand(F2FS_SHUTDOWN_COMMAND).trim();
252         if (!F2FS_SHUTDOWN_SUCCESS_OUTPUT.equalsIgnoreCase(output)) {
253             CLog.e("Unable to shutdown the F2FS.");
254         } else {
255             CLog.i("F2FS shutdown successful.");
256         }
257     }
258 
saveLogcatInfo(int iteration)259     private void saveLogcatInfo(int iteration) {
260         try (InputStreamSource logcat = mRebootLogcatReceiver.getLogcatData()) {
261             String testLogKey =
262                     String.format("%s%s%d", LOGCAT_FILENAME, METRIC_KEY_SEPARATOR, iteration);
263             testLog.addTestLog(testLogKey, LogDataType.LOGCAT, logcat);
264         }
265     }
266 
saveDmesgInfo(String filename)267     private void saveDmesgInfo(String filename) throws DeviceNotAvailableException {
268         getDevice().executeShellCommand(DUMP_DMESG);
269         File dmesgFile = getDevice().pullFile(DMESG_FILE);
270         testLog.addTestLog(
271                 filename, LogDataType.HOST_LOG, new FileInputStreamSource(dmesgFile, false));
272     }
273 
clearAndStartLogcat()274     private void clearAndStartLogcat() throws DeviceNotAvailableException {
275         getDevice().executeShellCommand(LOGCAT_CMD_CLEAR);
276         if (mRebootLogcatReceiver != null) {
277             mRebootLogcatReceiver.clear();
278             mRebootLogcatReceiver.stop();
279             mRebootLogcatReceiver = null;
280         }
281         mRebootLogcatReceiver = new LogcatReceiver(getDevice(), LOGCAT_CMD_ALL, LOGCAT_SIZE, 0);
282         mRebootLogcatReceiver.start();
283     }
284 
sleep(long duration)285     private void sleep(long duration) {
286         RunUtil.getDefault().sleep(duration);
287     }
288 
289     /**
290      * Look for the perfetto trace file collected during reboot under /data/misc/perfetto-traces and
291      * copy the file under /data/local/tmp using the test iteration name and return the path to the
292      * newly copied trace file.
293      */
processPerfettoFile(String testId)294     private String processPerfettoFile(String testId) throws DeviceNotAvailableException {
295         CommandResult result = getDevice().executeShellV2Command(PERFETTO_TRACE_FILE_CHECK_CMD);
296         if (result != null) {
297             CLog.i(
298                     "Command Output: Cmd - %s, Output - %s, Error - %s, Status - %s",
299                     PERFETTO_TRACE_FILE_CHECK_CMD,
300                     result.getStdout(),
301                     result.getStderr(),
302                     result.getStatus());
303             if (CommandStatus.SUCCESS.equals(result.getStatus())
304                     && result.getStdout().contains("boottrace.perfetto-trace")) {
305                 // Move the perfetto trace file to the new location and rename it using the test
306                 // name.
307                 String finalTraceFileLocation =
308                         String.format("/data/local/tmp/%s.perfetto-trace", testId);
309                 CommandResult moveResult =
310                         getDevice()
311                                 .executeShellV2Command(
312                                         String.format(
313                                                 PERFETTO_TRACE_MV_CMD, finalTraceFileLocation));
314                 if (moveResult != null) {
315                     CLog.i(
316                             "Command Output: Cmd - %s, Output - %s, Error - %s, Status - %s",
317                             PERFETTO_TRACE_MV_CMD,
318                             moveResult.getStdout(),
319                             moveResult.getStderr(),
320                             moveResult.getStatus());
321                     if (CommandStatus.SUCCESS.equals(result.getStatus())) {
322                         return finalTraceFileLocation;
323                     }
324                 }
325             }
326         }
327         return null;
328     }
329 
waitForBootComplete()330     private void waitForBootComplete() throws DeviceNotAvailableException {
331         for (int i = 0; i < BOOT_COMPLETE_POLL_RETRY_COUNT; i++) {
332             if (isBootCompleted()) {
333                 return;
334             }
335             CLog.v(String.format("waitForBootComplete %d", i));
336             sleep(BOOT_COMPLETE_POLL_INTERVAL);
337         }
338         throw new DeviceNotAvailableException(
339                 "Can't confirm boot complete. Exhausted retries. sys.boot_completed property does"
340                         + " not equal 1.",
341                 getDevice().getSerialNumber());
342     }
343 
isBootCompleted()344     private boolean isBootCompleted() throws DeviceNotAvailableException {
345         return "1".equals(getDevice().getProperty("sys.boot_completed"));
346     }
347 
348     /**
349      * Method to create the runner with given testName
350      *
351      * @return the {@link IRemoteAndroidTestRunner} to use.
352      */
createRemoteAndroidTestRunner(String testName)353     IRemoteAndroidTestRunner createRemoteAndroidTestRunner(String testName)
354             throws DeviceNotAvailableException {
355         RemoteAndroidTestRunner runner =
356                 new RemoteAndroidTestRunner(PACKAGE_NAME, RUNNER, getDevice().getIDevice());
357         runner.setMethodName(CLASS_NAME, testName);
358         return runner;
359     }
360 }
361