blob: 5c32e180d12c2020959fdba69f55a25df2d9f422 [file] [log] [blame]
James Hawkinsabd73e62016-01-19 15:10:38 -08001/*
2 * Copyright (C) 2016 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// The bootstat command provides options to persist boot events with the current
18// timestamp, dump the persisted events, and log all events to EventLog to be
19// uploaded to Android log storage via Tron.
20
James Hawkinsa4a1a4a2016-02-09 15:32:38 -080021#include <getopt.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070022#include <sys/klog.h>
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -070023#include <unistd.h>
Mark Salyzynff2dcd92016-09-28 15:54:45 -070024
James Hawkinse78ea772017-03-24 11:43:02 -070025#include <chrono>
James Hawkins0660b302016-03-08 16:18:15 -080026#include <cmath>
James Hawkinsabd73e62016-01-19 15:10:38 -080027#include <cstddef>
28#include <cstdio>
James Hawkins500d7152016-02-16 15:05:54 -080029#include <ctime>
James Hawkinsa4a1a4a2016-02-09 15:32:38 -080030#include <map>
James Hawkinsabd73e62016-01-19 15:10:38 -080031#include <memory>
32#include <string>
Mark Salyzyn853bb802018-03-16 08:44:56 -070033#include <utility>
James Hawkinsbe46fd12017-02-02 16:21:25 -080034#include <vector>
Mark Salyzynff2dcd92016-09-28 15:54:45 -070035
James Hawkinse78ea772017-03-24 11:43:02 -070036#include <android-base/chrono_utils.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070037#include <android-base/file.h>
James Hawkinseabe08b2016-01-19 16:54:35 -080038#include <android-base/logging.h>
James Hawkins4dded612016-07-28 11:50:23 -070039#include <android-base/parseint.h>
James Hawkinsbe46fd12017-02-02 16:21:25 -080040#include <android-base/strings.h>
James Hawkinse78ea772017-03-24 11:43:02 -070041#include <android/log.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070042#include <cutils/android_reboot.h>
James Hawkinsa4a1a4a2016-02-09 15:32:38 -080043#include <cutils/properties.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070044#include <log/logcat.h>
James Hawkins9aec9262017-01-31 11:42:24 -080045#include <metricslogger/metrics_logger.h>
Tej Singh4eacd382018-01-25 17:59:57 -080046#include <statslog.h>
Mark Salyzynff2dcd92016-09-28 15:54:45 -070047
James Hawkinsabd73e62016-01-19 15:10:38 -080048#include "boot_event_record_store.h"
James Hawkinsabd73e62016-01-19 15:10:38 -080049
50namespace {
51
James Hawkinsabd73e62016-01-19 15:10:38 -080052// Scans the boot event record store for record files and logs each boot event
53// via EventLog.
54void LogBootEvents() {
55 BootEventRecordStore boot_event_store;
56
57 auto events = boot_event_store.GetAllBootEvents();
58 for (auto i = events.cbegin(); i != events.cend(); ++i) {
James Hawkins9aec9262017-01-31 11:42:24 -080059 android::metricslogger::LogHistogram(i->first, i->second);
James Hawkinsabd73e62016-01-19 15:10:38 -080060 }
61}
62
James Hawkinsc6275582016-03-22 10:47:44 -070063// Records the named boot |event| to the record store. If |value| is non-empty
64// and is a proper string representation of an integer value, the converted
65// integer value is associated with the boot event.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -070066void RecordBootEventFromCommandLine(const std::string& event, const std::string& value_str) {
James Hawkinsc6275582016-03-22 10:47:44 -070067 BootEventRecordStore boot_event_store;
68 if (!value_str.empty()) {
69 int32_t value = 0;
Elliott Hughesda46b392016-10-11 17:09:00 -070070 if (android::base::ParseInt(value_str, &value)) {
James Hawkins4dded612016-07-28 11:50:23 -070071 boot_event_store.AddBootEventWithValue(event, value);
72 }
James Hawkinsc6275582016-03-22 10:47:44 -070073 } else {
74 boot_event_store.AddBootEvent(event);
75 }
76}
77
James Hawkinsabd73e62016-01-19 15:10:38 -080078void PrintBootEvents() {
79 printf("Boot events:\n");
80 printf("------------\n");
81
82 BootEventRecordStore boot_event_store;
83 auto events = boot_event_store.GetAllBootEvents();
84 for (auto i = events.cbegin(); i != events.cend(); ++i) {
85 printf("%s\t%d\n", i->first.c_str(), i->second);
86 }
87}
88
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -070089void ShowHelp(const char* cmd) {
James Hawkinsabd73e62016-01-19 15:10:38 -080090 fprintf(stderr, "Usage: %s [options]\n", cmd);
91 fprintf(stderr,
92 "options include:\n"
Yongqin Liu78b2b942017-07-07 13:26:49 +080093 " -h, --help Show this help\n"
94 " -l, --log Log all metrics to logstorage\n"
95 " -p, --print Dump the boot event records to the console\n"
96 " -r, --record Record the timestamp of a named boot event\n"
97 " --value Optional value to associate with the boot event\n"
98 " --record_boot_complete Record metrics related to the time for the device boot\n"
99 " --record_boot_reason Record the reason why the device booted\n"
James Hawkins53684ea2016-02-23 16:18:19 -0800100 " --record_time_since_factory_reset Record the time since the device was reset\n");
James Hawkinsabd73e62016-01-19 15:10:38 -0800101}
102
103// Constructs a readable, printable string from the givencommand line
104// arguments.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700105std::string GetCommandLine(int argc, char** argv) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800106 std::string cmd;
107 for (int i = 0; i < argc; ++i) {
108 cmd += argv[i];
109 cmd += " ";
110 }
111
112 return cmd;
113}
114
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800115// Convenience wrapper over the property API that returns an
116// std::string.
117std::string GetProperty(const char* key) {
118 std::vector<char> temp(PROPERTY_VALUE_MAX);
119 const int len = property_get(key, &temp[0], nullptr);
120 if (len < 0) {
121 return "";
122 }
123 return std::string(&temp[0], len);
124}
125
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700126void SetProperty(const char* key, const std::string& val) {
127 property_set(key, val.c_str());
128}
129
130void SetProperty(const char* key, const char* val) {
131 property_set(key, val);
132}
133
James Hawkins25f71222017-10-10 16:37:05 -0700134constexpr int32_t kEmptyBootReason = 0;
James Hawkins6f74c0b2016-02-12 15:49:16 -0800135constexpr int32_t kUnknownBootReason = 1;
136
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800137// A mapping from boot reason string, as read from the ro.boot.bootreason
138// system property, to a unique integer ID. Viewers of log data dashboards for
139// the boot_reason metric may refer to this mapping to discern the histogram
140// values.
James Hawkins6f74c0b2016-02-12 15:49:16 -0800141const std::map<std::string, int32_t> kBootReasonMap = {
James Hawkins25f71222017-10-10 16:37:05 -0700142 {"empty", kEmptyBootReason},
Mark Salyzyn2b820532018-03-16 08:53:34 -0700143 {"__BOOTSTAT_UNKNOWN__", kUnknownBootReason},
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700144 {"normal", 2},
145 {"recovery", 3},
146 {"reboot", 4},
147 {"PowerKey", 5},
148 {"hard_reset", 6},
149 {"kernel_panic", 7},
150 {"rpm_err", 8},
151 {"hw_reset", 9},
152 {"tz_err", 10},
153 {"adsp_err", 11},
154 {"modem_err", 12},
155 {"mba_err", 13},
156 {"Watchdog", 14},
157 {"Panic", 15},
158 {"power_key", 16},
159 {"power_on", 17},
160 {"Reboot", 18},
161 {"rtc", 19},
162 {"edl", 20},
163 {"oem_pon1", 21},
164 {"oem_powerkey", 22},
165 {"oem_unknown_reset", 23},
166 {"srto: HWWDT reset SC", 24},
167 {"srto: HWWDT reset platform", 25},
168 {"srto: bootloader", 26},
169 {"srto: kernel panic", 27},
170 {"srto: kernel watchdog reset", 28},
171 {"srto: normal", 29},
172 {"srto: reboot", 30},
173 {"srto: reboot-bootloader", 31},
174 {"srto: security watchdog reset", 32},
175 {"srto: wakesrc", 33},
176 {"srto: watchdog", 34},
177 {"srto:1-1", 35},
178 {"srto:omap_hsmm", 36},
179 {"srto:phy0", 37},
180 {"srto:rtc0", 38},
181 {"srto:touchpad", 39},
182 {"watchdog", 40},
183 {"watchdogr", 41},
184 {"wdog_bark", 42},
185 {"wdog_bite", 43},
186 {"wdog_reset", 44},
187 {"shutdown,", 45}, // Trailing comma is intentional.
188 {"shutdown,userrequested", 46},
189 {"reboot,bootloader", 47},
190 {"reboot,cold", 48},
191 {"reboot,recovery", 49},
192 {"thermal_shutdown", 50},
193 {"s3_wakeup", 51},
194 {"kernel_panic,sysrq", 52},
195 {"kernel_panic,NULL", 53},
Mark Salyzyn853bb802018-03-16 08:44:56 -0700196 {"kernel_panic,null", 53},
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700197 {"kernel_panic,BUG", 54},
Mark Salyzyn853bb802018-03-16 08:44:56 -0700198 {"kernel_panic,bug", 54},
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700199 {"bootloader", 55},
200 {"cold", 56},
201 {"hard", 57},
202 {"warm", 58},
Mark Salyzyn2b820532018-03-16 08:53:34 -0700203 // {"recovery", 59}, // Duplicate of enum 3 above. Immediate reuse possible.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700204 {"thermal-shutdown", 60},
205 {"shutdown,thermal", 61},
206 {"shutdown,battery", 62},
207 {"reboot,ota", 63},
208 {"reboot,factory_reset", 64},
209 {"reboot,", 65},
210 {"reboot,shell", 66},
211 {"reboot,adb", 67},
Mark Salyzyn9033bf52017-09-21 11:30:29 -0700212 {"reboot,userrequested", 68},
Mark Salyzyn161b8622017-09-26 08:26:12 -0700213 {"shutdown,container", 69}, // Host OS asking Android Container to shutdown
Mark Salyzyn243fa292017-10-11 09:02:04 -0700214 {"cold,powerkey", 70},
215 {"warm,s3_wakeup", 71},
216 {"hard,hw_reset", 72},
217 {"shutdown,suspend", 73}, // Suspend to RAM
218 {"shutdown,hibernate", 74}, // Suspend to DISK
James Hawkins34073b52017-10-17 15:53:27 -0700219 {"power_on_key", 75},
220 {"reboot_by_key", 76},
221 {"wdt_by_pass_pwk", 77},
222 {"reboot_longkey", 78},
223 {"powerkey", 79},
224 {"usb", 80},
225 {"wdt", 81},
226 {"tool_by_pass_pwk", 82},
227 {"2sec_reboot", 83},
228 {"reboot,by_key", 84},
229 {"reboot,longkey", 85},
Mark Salyzyncabbe4f2017-10-23 13:52:39 -0700230 {"reboot,2sec", 86},
Mark Salyzync89f9da2017-10-24 15:35:34 -0700231 {"shutdown,thermal,battery", 87},
Mark Salyzyn72a8ea32017-10-25 09:23:19 -0700232 {"reboot,its_just_so_hard", 88}, // produced by boot_reason_test
233 {"reboot,Its Just So Hard", 89}, // produced by boot_reason_test
Mark Salyzyn2b820532018-03-16 08:53:34 -0700234 // {"usb", 90}, // Duplicate of enum 80 above. Immediate reuse possible.
James Hawkins74b17582017-11-20 14:13:41 -0800235 {"charge", 91},
236 {"oem_tz_crash", 92},
237 {"uvlo", 93},
238 {"oem_ps_hold", 94},
239 {"abnormal_reset", 95},
240 {"oemerr_unknown", 96},
241 {"reboot_fastboot_mode", 97},
James Hawkins5f85f832017-11-29 14:30:06 -0800242 {"watchdog_apps_bite", 98},
243 {"xpu_err", 99},
244 {"power_on_usb", 100},
James Hawkinsf4444f02017-11-30 15:01:40 -0800245 {"watchdog_rpm", 101},
246 {"watchdog_nonsec", 102},
247 {"watchdog_apps_bark", 103},
248 {"reboot_dmverity_corrupted", 104},
James Hawkins00433a22017-12-04 14:20:21 -0800249 {"reboot_smpl", 105},
250 {"watchdog_sdi_apps_reset", 106},
251 {"smpl", 107},
252 {"oem_modem_failed_to_powerup", 108},
James Hawkinse2c27242017-12-18 13:40:27 -0800253 {"reboot_normal", 109},
254 {"oem_lpass_cfg", 110},
255 {"oem_xpu_ns_error", 111},
256 {"power_key_press", 112},
257 {"hardware_reset", 113},
258 {"reboot_by_powerkey", 114},
259 {"reboot_verity", 115},
260 {"oem_rpm_undef_error", 116},
261 {"oem_crash_on_the_lk", 117},
262 {"oem_rpm_reset", 118},
263 {"oem_lpass_cfg", 119},
264 {"oem_xpu_ns_error", 120},
265 {"factory_cable", 121},
266 {"oem_ar6320_failed_to_powerup", 122},
267 {"watchdog_rpm_bite", 123},
268 {"power_on_cable", 124},
269 {"reboot_unknown", 125},
270 {"wireless_charger", 126},
271 {"0x776655ff", 127},
272 {"oem_thermal_bite_reset", 128},
273 {"charger", 129},
274 {"pon1", 130},
275 {"unknown", 131},
276 {"reboot_rtc", 132},
277 {"cold_boot", 133},
278 {"hard_rst", 134},
James Hawkinsb607dae2018-01-05 14:42:55 -0800279 {"power-on", 135},
280 {"oem_adsp_resetting_the_soc", 136},
281 {"kpdpwr", 137},
282 {"oem_modem_timeout_waiting", 138},
283 {"usb_chg", 139},
284 {"warm_reset_0x02", 140},
285 {"warm_reset_0x80", 141},
286 {"pon_reason_0xb0", 142},
287 {"reboot_download", 143},
James Hawkins79a4ee22018-01-26 14:31:04 -0800288 {"reboot_recovery_mode", 144},
289 {"oem_sdi_err_fatal", 145},
290 {"pmic_watchdog", 146},
291 {"software_master", 147},
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800292};
293
294// Converts a string value representing the reason the system booted to an
295// integer representation. This is necessary for logging the boot_reason metric
296// via Tron, which does not accept non-integer buckets in histograms.
297int32_t BootReasonStrToEnum(const std::string& boot_reason) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800298 auto mapping = kBootReasonMap.find(boot_reason);
299 if (mapping != kBootReasonMap.end()) {
300 return mapping->second;
301 }
302
James Hawkins25f71222017-10-10 16:37:05 -0700303 if (boot_reason.empty()) {
304 return kEmptyBootReason;
305 }
306
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800307 LOG(INFO) << "Unknown boot reason: " << boot_reason;
308 return kUnknownBootReason;
309}
310
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700311// Canonical list of supported primary reboot reasons.
312const std::vector<const std::string> knownReasons = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700313 // clang-format off
314 // kernel
315 "watchdog",
316 "kernel_panic",
317 // strong
318 "recovery", // Should not happen from ro.boot.bootreason
319 "bootloader", // Should not happen from ro.boot.bootreason
320 // blunt
321 "cold",
322 "hard",
323 "warm",
Mark Salyzyn62909822017-10-09 09:27:16 -0700324 // super blunt
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700325 "shutdown", // Can not happen from ro.boot.bootreason
326 "reboot", // Default catch-all for anything unknown
327 // clang-format on
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700328};
329
330// Returns true if the supplied reason prefix is considered detailed enough.
331bool isStrongRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700332 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700333 if (s == "cold") break;
334 // Prefix defined as terminated by a nul or comma (,).
Elliott Hughes579e6822017-12-20 09:41:00 -0800335 if (android::base::StartsWith(r, s) && ((r.length() == s.length()) || (r[s.length()] == ','))) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700336 return true;
337 }
338 }
339 return false;
340}
341
342// Returns true if the supplied reason prefix is associated with the kernel.
343bool isKernelRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700344 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700345 if (s == "recovery") break;
346 // Prefix defined as terminated by a nul or comma (,).
Elliott Hughes579e6822017-12-20 09:41:00 -0800347 if (android::base::StartsWith(r, s) && ((r.length() == s.length()) || (r[s.length()] == ','))) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700348 return true;
349 }
350 }
351 return false;
352}
353
354// Returns true if the supplied reason prefix is considered known.
355bool isKnownRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700356 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700357 // Prefix defined as terminated by a nul or comma (,).
Elliott Hughes579e6822017-12-20 09:41:00 -0800358 if (android::base::StartsWith(r, s) && ((r.length() == s.length()) || (r[s.length()] == ','))) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700359 return true;
360 }
361 }
362 return false;
363}
364
365// If the reboot reason should be improved, report true if is too blunt.
366bool isBluntRebootReason(const std::string& r) {
367 if (isStrongRebootReason(r)) return false;
368
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700369 if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700370
371 size_t pos = 0;
372 while ((pos = r.find(',', pos)) != std::string::npos) {
373 ++pos;
374 std::string next(r.substr(pos));
375 if (next.length() == 0) break;
376 if (next[0] == ',') continue;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700377 if (!isKnownRebootReason(next)) return false; // Unknown subreason is good.
378 if (isStrongRebootReason(next)) return false; // eg: reboot,reboot
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700379 }
380 return true;
381}
382
Mark Salyzyn64610892017-09-18 10:41:14 -0700383bool readPstoreConsole(std::string& console) {
384 if (android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0", &console)) {
385 return true;
386 }
387 return android::base::ReadFileToString("/sys/fs/pstore/console-ramoops", &console);
388}
389
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700390// Implement a variant of std::string::rfind that is resilient to errors in
391// the data stream being inspected.
392class pstoreConsole {
393 private:
394 const size_t kBitErrorRate = 8; // number of bits per error
395 const std::string& console;
396
397 // Number of bits that differ between the two arguments l and r.
398 // Returns zero if the values for l and r are identical.
399 size_t numError(uint8_t l, uint8_t r) const { return std::bitset<8>(l ^ r).count(); }
400
401 // A string comparison function, reports the number of errors discovered
402 // in the match to a maximum of the bitLength / kBitErrorRate, at that
403 // point returning npos to indicate match is too poor.
404 //
405 // Since called in rfind which works backwards, expect cache locality will
406 // help if we check in reverse here as well for performance.
407 //
408 // Assumption: l (from console.c_str() + pos) is long enough to house
409 // _r.length(), checked in rfind caller below.
410 //
411 size_t numError(size_t pos, const std::string& _r) const {
412 const char* l = console.c_str() + pos;
413 const char* r = _r.c_str();
414 size_t n = _r.length();
415 const uint8_t* le = reinterpret_cast<const uint8_t*>(l) + n;
416 const uint8_t* re = reinterpret_cast<const uint8_t*>(r) + n;
417 size_t count = 0;
418 n = 0;
419 do {
420 // individual character bit error rate > threshold + slop
421 size_t num = numError(*--le, *--re);
422 if (num > ((8 + kBitErrorRate) / kBitErrorRate)) return std::string::npos;
423 // total bit error rate > threshold + slop
424 count += num;
425 ++n;
426 if (count > ((n * 8 + kBitErrorRate - (n > 2)) / kBitErrorRate)) {
427 return std::string::npos;
428 }
429 } while (le != reinterpret_cast<const uint8_t*>(l));
430 return count;
431 }
432
433 public:
434 explicit pstoreConsole(const std::string& console) : console(console) {}
435 // scope of argument must be equal to or greater than scope of pstoreConsole
436 explicit pstoreConsole(const std::string&& console) = delete;
437 explicit pstoreConsole(std::string&& console) = delete;
438
439 // Our implementation of rfind, use exact match first, then resort to fuzzy.
440 size_t rfind(const std::string& needle) const {
441 size_t pos = console.rfind(needle); // exact match?
442 if (pos != std::string::npos) return pos;
443
444 // Check to make sure needle fits in console string.
445 pos = console.length();
446 if (needle.length() > pos) return std::string::npos;
447 pos -= needle.length();
448 // fuzzy match to maximum kBitErrorRate
Ivan Lozano44d3cac2017-11-07 13:13:55 -0800449 for (;;) {
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700450 if (numError(pos, needle) != std::string::npos) return pos;
Ivan Lozano44d3cac2017-11-07 13:13:55 -0800451 if (pos == 0) break;
452 --pos;
453 }
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700454 return std::string::npos;
455 }
456
457 // Our implementation of find, use only fuzzy match.
458 size_t find(const std::string& needle, size_t start = 0) const {
459 // Check to make sure needle fits in console string.
460 if (needle.length() > console.length()) return std::string::npos;
461 const size_t last_pos = console.length() - needle.length();
462 // fuzzy match to maximum kBitErrorRate
463 for (size_t pos = start; pos <= last_pos; ++pos) {
464 if (numError(pos, needle) != std::string::npos) return pos;
465 }
466 return std::string::npos;
467 }
468};
469
470// If bit error match to needle, correct it.
471// Return true if any corrections were discovered and applied.
472bool correctForBer(std::string& reason, const std::string& needle) {
473 bool corrected = false;
474 if (reason.length() < needle.length()) return corrected;
475 const pstoreConsole console(reason);
476 const size_t last_pos = reason.length() - needle.length();
477 for (size_t pos = 0; pos <= last_pos; pos += needle.length()) {
478 pos = console.find(needle, pos);
479 if (pos == std::string::npos) break;
480
481 // exact match has no malice
482 if (needle == reason.substr(pos, needle.length())) continue;
483
484 corrected = true;
485 reason = reason.substr(0, pos) + needle + reason.substr(pos + needle.length());
486 }
487 return corrected;
488}
489
490bool addKernelPanicSubReason(const pstoreConsole& console, std::string& ret) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700491 // Check for kernel panic types to refine information
Mark Salyzyn853bb802018-03-16 08:44:56 -0700492 if ((console.rfind("SysRq : Trigger a crash") != std::string::npos) ||
493 (console.rfind("PC is at sysrq_handle_crash+") != std::string::npos)) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700494 // Can not happen, except on userdebug, during testing/debugging.
495 ret = "kernel_panic,sysrq";
496 return true;
497 }
498 if (console.rfind("Unable to handle kernel NULL pointer dereference at virtual address") !=
499 std::string::npos) {
Mark Salyzyn853bb802018-03-16 08:44:56 -0700500 ret = "kernel_panic,null";
Mark Salyzyn64610892017-09-18 10:41:14 -0700501 return true;
502 }
503 if (console.rfind("Kernel BUG at ") != std::string::npos) {
Mark Salyzyn853bb802018-03-16 08:44:56 -0700504 ret = "kernel_panic,bug";
Mark Salyzyn64610892017-09-18 10:41:14 -0700505 return true;
506 }
507 return false;
508}
509
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700510bool addKernelPanicSubReason(const std::string& content, std::string& ret) {
511 return addKernelPanicSubReason(pstoreConsole(content), ret);
512}
513
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700514// std::transform Helper callback functions:
515// Converts a string value representing the reason the system booted to a
516// string complying with Android system standard reason.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700517char tounderline(char c) {
518 return ::isblank(c) ? '_' : c;
519}
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700520
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700521char toprintable(char c) {
522 return ::isprint(c) ? c : '?';
523}
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700524
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700525// Cleanup boot_reason regarding acceptable character set
526void transformReason(std::string& reason) {
527 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
528 std::transform(reason.begin(), reason.end(), reason.begin(), tounderline);
529 std::transform(reason.begin(), reason.end(), reason.begin(), toprintable);
530}
531
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700532const char system_reboot_reason_property[] = "sys.boot.reason";
533const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
534const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
535
536// Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
537std::string BootReasonStrToReason(const std::string& boot_reason) {
Mark Salyzyna16e4372017-09-20 08:36:12 -0700538 static const size_t max_reason_length = 256;
539
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700540 std::string ret(GetProperty(system_reboot_reason_property));
541 std::string reason(boot_reason);
542 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
543 if (reason == ret) ret = "";
544
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700545 transformReason(reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700546
547 // Is the current system boot reason sys.boot.reason valid?
548 if (!isKnownRebootReason(ret)) ret = "";
549
550 if (ret == "") {
551 // Is the bootloader boot reason ro.boot.bootreason known?
552 std::vector<std::string> words(android::base::Split(reason, ",_-"));
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700553 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700554 std::string blunt;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700555 for (auto& r : words) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700556 if (r == s) {
557 if (isBluntRebootReason(s)) {
558 blunt = s;
559 } else {
560 ret = s;
561 break;
562 }
563 }
564 }
565 if (ret == "") ret = blunt;
566 if (ret != "") break;
567 }
568 }
569
570 if (ret == "") {
571 // A series of checks to take some officially unsupported reasons
572 // reported by the bootloader and find some logical and canonical
573 // sense. In an ideal world, we would require those bootloaders
574 // to behave and follow our standards.
575 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700576 {"watchdog", "wdog"},
577 {"cold,powerkey", "powerkey"},
578 {"kernel_panic", "panic"},
579 {"shutdown,thermal", "thermal"},
580 {"warm,s3_wakeup", "s3_wakeup"},
581 {"hard,hw_reset", "hw_reset"},
Mark Salyzyncabbe4f2017-10-23 13:52:39 -0700582 {"reboot,2sec", "2sec_reboot"},
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700583 {"bootloader", ""},
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700584 };
585
586 // Either the primary or alias is found _somewhere_ in the reason string.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700587 for (auto& s : aliasReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700588 if (reason.find(s.first) != std::string::npos) {
589 ret = s.first;
590 break;
591 }
592 if (s.second.size() && (reason.find(s.second) != std::string::npos)) {
593 ret = s.first;
594 break;
595 }
596 }
597 }
598
599 // If watchdog is the reason, see if there is a security angle?
600 if (ret == "watchdog") {
601 if (reason.find("sec") != std::string::npos) {
602 ret += ",security";
603 }
604 }
605
Mark Salyzyn64610892017-09-18 10:41:14 -0700606 if (ret == "kernel_panic") {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700607 // Check to see if last klog has some refinement hints.
608 std::string content;
Mark Salyzyn64610892017-09-18 10:41:14 -0700609 if (readPstoreConsole(content)) {
610 addKernelPanicSubReason(content, ret);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700611 }
Mark Salyzyn64610892017-09-18 10:41:14 -0700612 } else if (isBluntRebootReason(ret)) {
613 // Check the other available reason resources if the reason is still blunt.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700614
Mark Salyzyn64610892017-09-18 10:41:14 -0700615 // Check to see if last klog has some refinement hints.
616 std::string content;
617 if (readPstoreConsole(content)) {
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700618 const pstoreConsole console(content);
Mark Salyzyn64610892017-09-18 10:41:14 -0700619 // The toybox reboot command used directly (unlikely)? But also
620 // catches init's response to Android's more controlled reboot command.
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700621 if (console.rfind("reboot: Power down") != std::string::npos) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700622 ret = "shutdown"; // Still too blunt, but more accurate.
623 // ToDo: init should record the shutdown reason to kernel messages ala:
624 // init: shutdown system with command 'last_reboot_reason'
625 // so that if pstore has persistence we can get some details
626 // that could be missing in last_reboot_reason_property.
627 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700628
Mark Salyzyn64610892017-09-18 10:41:14 -0700629 static const char cmd[] = "reboot: Restarting system with command '";
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700630 size_t pos = console.rfind(cmd);
Mark Salyzyn64610892017-09-18 10:41:14 -0700631 if (pos != std::string::npos) {
632 pos += strlen(cmd);
Mark Salyzyna16e4372017-09-20 08:36:12 -0700633 std::string subReason(content.substr(pos, max_reason_length));
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700634 // Correct against any known strings that Bit Error Match
635 for (const auto& s : knownReasons) {
636 correctForBer(subReason, s);
637 }
638 for (const auto& m : kBootReasonMap) {
639 if (m.first.length() <= strlen("cold")) continue; // too short?
640 if (correctForBer(subReason, m.first + "'")) continue;
641 if (m.first.length() <= strlen("reboot,cold")) continue; // short?
642 if (!android::base::StartsWith(m.first, "reboot,")) continue;
643 correctForBer(subReason, m.first.substr(strlen("reboot,")) + "'");
644 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700645 for (pos = 0; pos < subReason.length(); ++pos) {
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700646 char c = subReason[pos];
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700647 // #, &, %, / are common single bit error for ' that we can block
648 if (!::isprint(c) || (c == '\'') || (c == '#') || (c == '&') || (c == '%') || (c == '/')) {
Mark Salyzyna16e4372017-09-20 08:36:12 -0700649 subReason.erase(pos);
650 break;
651 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700652 }
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700653 transformReason(subReason);
Mark Salyzyn64610892017-09-18 10:41:14 -0700654 if (subReason != "") { // Will not land "reboot" as that is too blunt.
655 if (isKernelRebootReason(subReason)) {
656 ret = "reboot," + subReason; // User space can't talk kernel reasons.
Mark Salyzyndafced92017-09-20 08:37:46 -0700657 } else if (isKnownRebootReason(subReason)) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700658 ret = subReason;
Mark Salyzyndafced92017-09-20 08:37:46 -0700659 } else {
660 ret = "reboot," + subReason; // legitimize unknown reasons
Mark Salyzyn64610892017-09-18 10:41:14 -0700661 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700662 }
663 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700664
Mark Salyzyn64610892017-09-18 10:41:14 -0700665 // Check for kernel panics, allowed to override reboot command.
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700666 if (!addKernelPanicSubReason(console, ret) &&
Mark Salyzyn64610892017-09-18 10:41:14 -0700667 // check for long-press power down
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700668 ((console.rfind("Power held for ") != std::string::npos) ||
669 (console.rfind("charger: [") != std::string::npos))) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700670 ret = "cold";
671 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700672 }
673
674 // The following battery test should migrate to a default system health HAL
675
676 // Let us not worry if the reboot command was issued, for the cases of
677 // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard.
678 // Same for bootloader and ro.boot.bootreasons of this set, but a dead
679 // battery could conceivably lead to these, so worthy of override.
680 if (isBluntRebootReason(ret)) {
681 // Heuristic to determine if shutdown possibly because of a dead battery?
682 // Really a hail-mary pass to find it in last klog content ...
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700683 static const int battery_dead_threshold = 2; // percent
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700684 static const char battery[] = "healthd: battery l=";
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700685 const pstoreConsole console(content);
686 size_t pos = console.rfind(battery); // last one
Mark Salyzyna16e4372017-09-20 08:36:12 -0700687 std::string digits;
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700688 if (pos != std::string::npos) {
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700689 digits = content.substr(pos + strlen(battery), strlen("100 "));
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700690 // correct common errors
691 correctForBer(digits, "100 ");
692 if (digits[0] == '!') digits[0] = '1';
693 if (digits[1] == '!') digits[1] = '1';
Mark Salyzyna16e4372017-09-20 08:36:12 -0700694 }
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700695 const char* endptr = digits.c_str();
696 unsigned level = 0;
697 while (::isdigit(*endptr)) {
698 level *= 10;
699 level += *endptr++ - '0';
700 // make sure no leading zeros, except zero itself, and range check.
701 if ((level == 0) || (level > 100)) break;
702 }
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700703 // example bit error rate issues for 10%
704 // 'l=10 ' no bits in error
705 // 'l=00 ' single bit error (fails above)
706 // 'l=1 ' single bit error
707 // 'l=0 ' double bit error
708 // There are others, not typically critical because of 2%
709 // battery_dead_threshold. KISS check, make sure second
710 // character after digit sequence is not a space.
711 if ((level <= 100) && (endptr != digits.c_str()) && (endptr[0] == ' ') && (endptr[1] != ' ')) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700712 LOG(INFO) << "Battery level at shutdown " << level << "%";
713 if (level <= battery_dead_threshold) {
714 ret = "shutdown,battery";
715 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700716 } else { // Most likely
717 digits = ""; // reset digits
718
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700719 // Content buffer no longer will have console data. Beware if more
720 // checks added below, that depend on parsing console content.
721 content = "";
722
723 LOG(DEBUG) << "Can not find last low battery in last console messages";
724 android_logcat_context ctx = create_android_logcat();
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700725 FILE* fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d");
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700726 if (fp != nullptr) {
727 android::base::ReadFdToString(fileno(fp), &content);
728 }
729 android_logcat_pclose(&ctx, fp);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700730 static const char logcat_battery[] = "W/healthd ( 0): battery l=";
731 const char* match = logcat_battery;
732
733 if (content == "") {
734 // Service logd.klog not running, go to smaller buffer in the kernel.
735 int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0);
736 if (rc > 0) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700737 ssize_t len = rc + 1024; // 1K Margin should it grow between calls.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700738 std::unique_ptr<char[]> buf(new char[len]);
739 rc = klogctl(KLOG_READ_ALL, buf.get(), len);
740 if (rc < len) {
741 len = rc + 1;
742 }
743 buf[--len] = '\0';
744 content = buf.get();
745 }
746 match = battery;
747 }
748
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700749 pos = content.find(match); // The first one it finds.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700750 if (pos != std::string::npos) {
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700751 digits = content.substr(pos + strlen(match), strlen("100 "));
Mark Salyzyna16e4372017-09-20 08:36:12 -0700752 }
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700753 endptr = digits.c_str();
754 level = 0;
755 while (::isdigit(*endptr)) {
756 level *= 10;
757 level += *endptr++ - '0';
758 // make sure no leading zeros, except zero itself, and range check.
759 if ((level == 0) || (level > 100)) break;
760 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700761 if ((level <= 100) && (endptr != digits.c_str()) && (*endptr == ' ')) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700762 LOG(INFO) << "Battery level at startup " << level << "%";
763 if (level <= battery_dead_threshold) {
764 ret = "shutdown,battery";
765 }
766 } else {
767 LOG(DEBUG) << "Can not find first battery level in dmesg or logcat";
768 }
769 }
770 }
771
772 // Is there a controlled shutdown hint in last_reboot_reason_property?
773 if (isBluntRebootReason(ret)) {
774 // Content buffer no longer will have console data. Beware if more
775 // checks added below, that depend on parsing console content.
776 content = GetProperty(last_reboot_reason_property);
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700777 transformReason(content);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700778
Mark Salyzyn62909822017-10-09 09:27:16 -0700779 // Anything in last is better than 'super-blunt' reboot or shutdown.
780 if ((ret == "") || (ret == "reboot") || (ret == "shutdown") || !isBluntRebootReason(content)) {
781 ret = content;
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700782 }
783 }
784
785 // Other System Health HAL reasons?
786
787 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
788 // possibly offer hardware-specific clues from the PMIC.
789 }
790
791 // If unknown left over from above, make it "reboot,<boot_reason>"
792 if (ret == "") {
793 ret = "reboot";
794 if (android::base::StartsWith(reason, "reboot")) {
795 reason = reason.substr(strlen("reboot"));
Mark Salyzyn0af71a52017-10-05 13:58:04 -0700796 while ((reason[0] == ',') || (reason[0] == '_')) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700797 reason = reason.substr(1);
798 }
799 }
800 if (reason != "") {
801 ret += ",";
802 ret += reason;
803 }
804 }
805
806 LOG(INFO) << "Canonical boot reason: " << ret;
807 if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) {
808 // Rewrite as it must be old news, kernel reasons trump user space.
809 SetProperty(last_reboot_reason_property, ret);
810 }
811 return ret;
812}
813
James Hawkinsb9cf7712016-04-08 15:32:19 -0700814// Returns the appropriate metric key prefix for the boot_complete metric such
815// that boot metrics after a system update are labeled as ota_boot_complete;
816// otherwise, they are labeled as boot_complete. This method encapsulates the
817// bookkeeping required to track when a system update has occurred by storing
818// the UTC timestamp of the system build date and comparing against the current
819// system build date.
820std::string CalculateBootCompletePrefix() {
821 static const std::string kBuildDateKey = "build_date";
822 std::string boot_complete_prefix = "boot_complete";
823
824 std::string build_date_str = GetProperty("ro.build.date.utc");
James Hawkins4dded612016-07-28 11:50:23 -0700825 int32_t build_date;
Elliott Hughesda46b392016-10-11 17:09:00 -0700826 if (!android::base::ParseInt(build_date_str, &build_date)) {
James Hawkins4dded612016-07-28 11:50:23 -0700827 return std::string();
828 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700829
830 BootEventRecordStore boot_event_store;
831 BootEventRecordStore::BootEventRecord record;
James Hawkins0bc4ad42017-05-30 15:03:15 -0700832 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
833 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
834 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700835 LOG(INFO) << "Canonical boot reason: reboot,factory_reset";
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700836 SetProperty(system_reboot_reason_property, "reboot,factory_reset");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700837 } else if (build_date != record.second) {
James Hawkinsb9cf7712016-04-08 15:32:19 -0700838 boot_complete_prefix = "ota_" + boot_complete_prefix;
839 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700840 LOG(INFO) << "Canonical boot reason: reboot,ota";
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700841 SetProperty(system_reboot_reason_property, "reboot,ota");
James Hawkinsb9cf7712016-04-08 15:32:19 -0700842 }
843
844 return boot_complete_prefix;
845}
846
James Hawkinsef0a0902017-01-06 14:38:23 -0800847// Records the value of a given ro.boottime.init property in milliseconds.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700848void RecordInitBootTimeProp(BootEventRecordStore* boot_event_store, const char* property) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800849 std::string value = GetProperty(property);
850
James Hawkins27c05222017-01-26 11:55:44 -0800851 int32_t time_in_ms;
852 if (android::base::ParseInt(value, &time_in_ms)) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800853 boot_event_store->AddBootEventWithValue(property, time_in_ms);
854 }
855}
856
James Hawkins1bfcaec2017-05-19 14:27:27 -0700857// A map from bootloader timing stage to the time that stage took during boot.
858typedef std::map<std::string, int32_t> BootloaderTimingMap;
859
860// Returns a mapping from bootloader stage names to the time those stages
861// took to boot.
862const BootloaderTimingMap GetBootLoaderTimings() {
863 BootloaderTimingMap timings;
864
865 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
866 // where timeN is in milliseconds.
James Hawkinsbe46fd12017-02-02 16:21:25 -0800867 std::string value = GetProperty("ro.boot.boottime");
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800868 if (value.empty()) {
869 // ro.boot.boottime is not reported on all devices.
James Hawkins1bfcaec2017-05-19 14:27:27 -0700870 return BootloaderTimingMap();
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800871 }
James Hawkinsbe46fd12017-02-02 16:21:25 -0800872
873 auto stages = android::base::Split(value, ",");
James Hawkins1bfcaec2017-05-19 14:27:27 -0700874 for (const auto& stageTiming : stages) {
James Hawkinsbe46fd12017-02-02 16:21:25 -0800875 // |stageTiming| is of the form 'stage:time'.
876 auto stageTimingValues = android::base::Split(stageTiming, ":");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700877 DCHECK_EQ(2U, stageTimingValues.size());
James Hawkinsbe46fd12017-02-02 16:21:25 -0800878
879 std::string stageName = stageTimingValues[0];
880 int32_t time_ms;
881 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700882 timings[stageName] = time_ms;
James Hawkinsbe46fd12017-02-02 16:21:25 -0800883 }
884 }
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800885
James Hawkins1bfcaec2017-05-19 14:27:27 -0700886 return timings;
887}
888
Tej Singh4eacd382018-01-25 17:59:57 -0800889// Returns the total bootloader boot time from the ro.boot.boottime system property.
890int32_t GetBootloaderTime(const BootloaderTimingMap& bootloader_timings) {
891 int32_t total_time = 0;
892 for (const auto& timing : bootloader_timings) {
893 total_time += timing.second;
894 }
895
896 return total_time;
897}
898
James Hawkins1bfcaec2017-05-19 14:27:27 -0700899// Parses and records the set of bootloader stages and associated boot times
900// from the ro.boot.boottime system property.
901void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
902 const BootloaderTimingMap& bootloader_timings) {
903 int32_t total_time = 0;
904 for (const auto& timing : bootloader_timings) {
905 total_time += timing.second;
906 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
907 }
908
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800909 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
James Hawkinsbe46fd12017-02-02 16:21:25 -0800910}
911
Tej Singh4eacd382018-01-25 17:59:57 -0800912// Returns the closest estimation to the absolute device boot time, i.e.,
James Hawkins1bfcaec2017-05-19 14:27:27 -0700913// from power on to boot_complete, including bootloader times.
Tej Singh4eacd382018-01-25 17:59:57 -0800914std::chrono::milliseconds GetAbsoluteBootTime(const BootloaderTimingMap& bootloader_timings,
915 std::chrono::milliseconds uptime) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700916 int32_t bootloader_time_ms = 0;
917
918 for (const auto& timing : bootloader_timings) {
919 if (timing.first.compare("SW") != 0) {
920 bootloader_time_ms += timing.second;
921 }
922 }
923
924 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
Tej Singh4eacd382018-01-25 17:59:57 -0800925 return bootloader_duration + uptime;
926}
927
928// Records the closest estimation to the absolute device boot time in seconds.
929// i.e. from power on to boot_complete, including bootloader times.
930void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
931 std::chrono::milliseconds absolute_total) {
932 auto absolute_total_sec = std::chrono::duration_cast<std::chrono::seconds>(absolute_total);
933 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total_sec.count());
934}
935
936// Logs the total boot time and reason to statsd.
937void LogBootInfoToStatsd(std::chrono::milliseconds end_time,
938 std::chrono::milliseconds total_duration, int32_t bootloader_duration_ms,
939 double time_since_last_boot_sec) {
940 const std::string reason(GetProperty(bootloader_reboot_reason_property));
941
942 if (reason.empty()) {
943 android::util::stats_write(android::util::BOOT_SEQUENCE_REPORTED, "<EMPTY>", "<EMPTY>",
944 end_time.count(), total_duration.count(),
945 (int64_t)bootloader_duration_ms,
946 (int64_t)time_since_last_boot_sec * 1000);
947 return;
948 }
949
Tej Singhfe3e7622018-02-06 15:57:38 -0800950 const std::string system_reason(GetProperty(system_reboot_reason_property));
Tej Singh4eacd382018-01-25 17:59:57 -0800951 android::util::stats_write(android::util::BOOT_SEQUENCE_REPORTED, reason.c_str(),
952 system_reason.c_str(), end_time.count(), total_duration.count(),
953 (int64_t)bootloader_duration_ms,
954 (int64_t)time_since_last_boot_sec * 1000);
James Hawkins1bfcaec2017-05-19 14:27:27 -0700955}
956
Tej Singhfe3e7622018-02-06 15:57:38 -0800957void SetSystemBootReason() {
958 const std::string bootloader_boot_reason(GetProperty(bootloader_reboot_reason_property));
959 const std::string system_boot_reason(BootReasonStrToReason(bootloader_boot_reason));
960 // Record the scrubbed system_boot_reason to the property
961 SetProperty(system_reboot_reason_property, system_boot_reason);
962}
963
James Hawkinsc08e9962016-03-11 14:59:50 -0800964// Records several metrics related to the time it takes to boot the device,
965// including disambiguating boot time on encrypted or non-encrypted devices.
966void RecordBootComplete() {
967 BootEventRecordStore boot_event_store;
James Hawkinsb9cf7712016-04-08 15:32:19 -0700968 BootEventRecordStore::BootEventRecord record;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700969
James Hawkins1bfcaec2017-05-19 14:27:27 -0700970 auto time_since_epoch = android::base::boot_clock::now().time_since_epoch();
971 auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700972 time_t current_time_utc = time(nullptr);
Tej Singh4eacd382018-01-25 17:59:57 -0800973 time_t time_since_last_boot = 0;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700974
975 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
976 time_t last_boot_time_utc = record.second;
Tej Singh4eacd382018-01-25 17:59:57 -0800977 time_since_last_boot = difftime(current_time_utc, last_boot_time_utc);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700978 boot_event_store.AddBootEventWithValue("time_since_last_boot", time_since_last_boot);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700979 }
980
981 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
James Hawkinsc08e9962016-03-11 14:59:50 -0800982
James Hawkinsb9cf7712016-04-08 15:32:19 -0700983 // The boot_complete metric has two variants: boot_complete and
984 // ota_boot_complete. The latter signifies that the device is booting after
985 // a system update.
986 std::string boot_complete_prefix = CalculateBootCompletePrefix();
James Hawkins4dded612016-07-28 11:50:23 -0700987 if (boot_complete_prefix.empty()) {
988 // The system is hosed because the build date property could not be read.
989 return;
990 }
James Hawkinsc08e9962016-03-11 14:59:50 -0800991
992 // post_decrypt_time_elapsed is only logged on encrypted devices.
993 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
994 // Log the amount of time elapsed until the device is decrypted, which
995 // includes the variable amount of time the user takes to enter the
996 // decryption password.
James Hawkinse78ea772017-03-24 11:43:02 -0700997 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800998
999 // Subtract the decryption time to normalize the boot cycle timing.
James Hawkinse78ea772017-03-24 11:43:02 -07001000 std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second);
James Hawkinsb9cf7712016-04-08 15:32:19 -07001001 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
James Hawkinse78ea772017-03-24 11:43:02 -07001002 boot_complete.count());
James Hawkinsc08e9962016-03-11 14:59:50 -08001003 } else {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001004 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -08001005 }
1006
1007 // Record the total time from device startup to boot complete, regardless of
1008 // encryption state.
James Hawkinse78ea772017-03-24 11:43:02 -07001009 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count());
James Hawkinsef0a0902017-01-06 14:38:23 -08001010
1011 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
1012 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
1013 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
James Hawkinsbe46fd12017-02-02 16:21:25 -08001014
James Hawkins1bfcaec2017-05-19 14:27:27 -07001015 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
Tej Singh4eacd382018-01-25 17:59:57 -08001016 int32_t bootloader_boot_duration = GetBootloaderTime(bootloader_timings);
James Hawkins1bfcaec2017-05-19 14:27:27 -07001017 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
1018
1019 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch);
Tej Singh4eacd382018-01-25 17:59:57 -08001020 auto absolute_boot_time = GetAbsoluteBootTime(bootloader_timings, uptime_ms);
1021 RecordAbsoluteBootTime(&boot_event_store, absolute_boot_time);
1022
1023 auto boot_end_time_point = std::chrono::system_clock::now().time_since_epoch();
1024 auto boot_end_time = std::chrono::duration_cast<std::chrono::milliseconds>(boot_end_time_point);
1025
1026 LogBootInfoToStatsd(boot_end_time, absolute_boot_time, bootloader_boot_duration,
1027 time_since_last_boot);
James Hawkinsc08e9962016-03-11 14:59:50 -08001028}
1029
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001030// Records the boot_reason metric by querying the ro.boot.bootreason system
1031// property.
1032void RecordBootReason() {
Mark Salyzynb304f6d2017-08-04 13:35:51 -07001033 const std::string reason(GetProperty(bootloader_reboot_reason_property));
James Hawkins25f71222017-10-10 16:37:05 -07001034
1035 if (reason.empty()) {
1036 // Log an empty boot reason value as '<EMPTY>' to ensure the value is intentional
1037 // (and not corruption anywhere else in the reporting pipeline).
1038 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
1039 android::metricslogger::FIELD_PLATFORM_REASON, "<EMPTY>");
1040 } else {
1041 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
1042 android::metricslogger::FIELD_PLATFORM_REASON, reason);
1043 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -07001044
1045 // Log the raw bootloader_boot_reason property value.
1046 int32_t boot_reason = BootReasonStrToEnum(reason);
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001047 BootEventRecordStore boot_event_store;
1048 boot_event_store.AddBootEventWithValue("boot_reason", boot_reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -07001049
1050 // Log the scrubbed system_boot_reason.
Tej Singhfe3e7622018-02-06 15:57:38 -08001051 const std::string system_reason(GetProperty(system_reboot_reason_property));
Mark Salyzynb304f6d2017-08-04 13:35:51 -07001052 int32_t system_boot_reason = BootReasonStrToEnum(system_reason);
1053 boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason);
1054
Mark Salyzynb304f6d2017-08-04 13:35:51 -07001055 if (reason == "") {
1056 SetProperty(bootloader_reboot_reason_property, system_reason);
1057 }
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001058}
1059
James Hawkins500d7152016-02-16 15:05:54 -08001060// Records two metrics related to the user resetting a device: the time at
1061// which the device is reset, and the time since the user last reset the
1062// device. The former is only set once per-factory reset.
1063void RecordFactoryReset() {
1064 BootEventRecordStore boot_event_store;
1065 BootEventRecordStore::BootEventRecord record;
1066
1067 time_t current_time_utc = time(nullptr);
1068
James Hawkins0660b302016-03-08 16:18:15 -08001069 if (current_time_utc < 0) {
1070 // UMA does not display negative values in buckets, so convert to positive.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001071 android::metricslogger::LogHistogram("factory_reset_current_time_failure",
1072 std::abs(current_time_utc));
James Hawkinsfff95ba2016-03-29 16:13:49 -07001073
James Hawkins9aec9262017-01-31 11:42:24 -08001074 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -07001075 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001076 boot_event_store.AddBootEventWithValue("factory_reset_current_time_failure",
1077 std::abs(current_time_utc));
James Hawkins0660b302016-03-08 16:18:15 -08001078 return;
1079 } else {
James Hawkins9aec9262017-01-31 11:42:24 -08001080 android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -07001081
James Hawkins9aec9262017-01-31 11:42:24 -08001082 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -07001083 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001084 boot_event_store.AddBootEventWithValue("factory_reset_current_time", current_time_utc);
James Hawkins0660b302016-03-08 16:18:15 -08001085 }
1086
James Hawkins500d7152016-02-16 15:05:54 -08001087 // The factory_reset boot event does not exist after the device is reset, so
1088 // use this signal to mark the time of the factory reset.
1089 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
1090 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
James Hawkins3bf9b142016-03-03 14:50:24 -08001091
1092 // Don't log the time_since_factory_reset until some time has elapsed.
1093 // The data is not meaningful yet and skews the histogram buckets.
James Hawkins500d7152016-02-16 15:05:54 -08001094 return;
1095 }
1096
1097 // Calculate and record the difference in time between now and the
1098 // factory_reset time.
1099 time_t factory_reset_utc = record.second;
James Hawkins9aec9262017-01-31 11:42:24 -08001100 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -07001101
James Hawkins9aec9262017-01-31 11:42:24 -08001102 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -07001103 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001104 boot_event_store.AddBootEventWithValue("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -07001105
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001106 time_t time_since_factory_reset = difftime(current_time_utc, factory_reset_utc);
1107 boot_event_store.AddBootEventWithValue("time_since_factory_reset", time_since_factory_reset);
James Hawkins500d7152016-02-16 15:05:54 -08001108}
1109
James Hawkinsabd73e62016-01-19 15:10:38 -08001110} // namespace
1111
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001112int main(int argc, char** argv) {
James Hawkinsabd73e62016-01-19 15:10:38 -08001113 android::base::InitLogging(argv);
1114
1115 const std::string cmd_line = GetCommandLine(argc, argv);
1116 LOG(INFO) << "Service started: " << cmd_line;
1117
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001118 int option_index = 0;
James Hawkinsc6275582016-03-22 10:47:44 -07001119 static const char value_str[] = "value";
Tej Singhfe3e7622018-02-06 15:57:38 -08001120 static const char system_boot_reason_str[] = "set_system_boot_reason";
James Hawkinsc08e9962016-03-11 14:59:50 -08001121 static const char boot_complete_str[] = "record_boot_complete";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001122 static const char boot_reason_str[] = "record_boot_reason";
James Hawkins53684ea2016-02-23 16:18:19 -08001123 static const char factory_reset_str[] = "record_time_since_factory_reset";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001124 static const struct option long_options[] = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001125 // clang-format off
Tej Singhfe3e7622018-02-06 15:57:38 -08001126 { "help", no_argument, NULL, 'h' },
1127 { "log", no_argument, NULL, 'l' },
1128 { "print", no_argument, NULL, 'p' },
1129 { "record", required_argument, NULL, 'r' },
1130 { value_str, required_argument, NULL, 0 },
1131 { system_boot_reason_str, no_argument, NULL, 0 },
1132 { boot_complete_str, no_argument, NULL, 0 },
1133 { boot_reason_str, no_argument, NULL, 0 },
1134 { factory_reset_str, no_argument, NULL, 0 },
1135 { NULL, 0, NULL, 0 }
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001136 // clang-format on
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001137 };
1138
James Hawkinsc6275582016-03-22 10:47:44 -07001139 std::string boot_event;
1140 std::string value;
James Hawkinsabd73e62016-01-19 15:10:38 -08001141 int opt = 0;
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001142 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
James Hawkinsabd73e62016-01-19 15:10:38 -08001143 switch (opt) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001144 // This case handles long options which have no single-character mapping.
1145 case 0: {
1146 const std::string option_name = long_options[option_index].name;
James Hawkinsc6275582016-03-22 10:47:44 -07001147 if (option_name == value_str) {
1148 // |optarg| is an external variable set by getopt representing
1149 // the option argument.
1150 value = optarg;
Tej Singhfe3e7622018-02-06 15:57:38 -08001151 } else if (option_name == system_boot_reason_str) {
1152 SetSystemBootReason();
James Hawkinsc6275582016-03-22 10:47:44 -07001153 } else if (option_name == boot_complete_str) {
James Hawkinsc08e9962016-03-11 14:59:50 -08001154 RecordBootComplete();
1155 } else if (option_name == boot_reason_str) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001156 RecordBootReason();
James Hawkins500d7152016-02-16 15:05:54 -08001157 } else if (option_name == factory_reset_str) {
1158 RecordFactoryReset();
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001159 } else {
1160 LOG(ERROR) << "Invalid option: " << option_name;
1161 }
1162 break;
1163 }
1164
James Hawkinsabd73e62016-01-19 15:10:38 -08001165 case 'h': {
1166 ShowHelp(argv[0]);
1167 break;
1168 }
1169
1170 case 'l': {
1171 LogBootEvents();
1172 break;
1173 }
1174
1175 case 'p': {
1176 PrintBootEvents();
1177 break;
1178 }
1179
1180 case 'r': {
1181 // |optarg| is an external variable set by getopt representing
1182 // the option argument.
James Hawkinsc6275582016-03-22 10:47:44 -07001183 boot_event = optarg;
James Hawkinsabd73e62016-01-19 15:10:38 -08001184 break;
1185 }
1186
1187 default: {
1188 DCHECK_EQ(opt, '?');
1189
1190 // |optopt| is an external variable set by getopt representing
1191 // the value of the invalid option.
1192 LOG(ERROR) << "Invalid option: " << optopt;
1193 ShowHelp(argv[0]);
1194 return EXIT_FAILURE;
1195 }
1196 }
1197 }
1198
James Hawkinsc6275582016-03-22 10:47:44 -07001199 if (!boot_event.empty()) {
1200 RecordBootEventFromCommandLine(boot_event, value);
1201 }
1202
James Hawkinsabd73e62016-01-19 15:10:38 -08001203 return 0;
1204}