1 /*
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
21 #include <getopt.h>
22 #include <sys/klog.h>
23 #include <unistd.h>
24
25 #include <chrono>
26 #include <cmath>
27 #include <cstddef>
28 #include <cstdio>
29 #include <ctime>
30 #include <iterator>
31 #include <map>
32 #include <memory>
33 #include <regex>
34 #include <string>
35 #include <utility>
36 #include <vector>
37
38 #include <android-base/chrono_utils.h>
39 #include <android-base/file.h>
40 #include <android-base/logging.h>
41 #include <android-base/parseint.h>
42 #include <android-base/properties.h>
43 #include <android-base/strings.h>
44 #include <android/log.h>
45 #include <cutils/android_reboot.h>
46 #include <cutils/properties.h>
47 #include <metricslogger/metrics_logger.h>
48 #include <statslog.h>
49
50 #include "boot_event_record_store.h"
51
52 namespace {
53
54 // Scans the boot event record store for record files and logs each boot event
55 // via EventLog.
LogBootEvents()56 void LogBootEvents() {
57 BootEventRecordStore boot_event_store;
58
59 auto events = boot_event_store.GetAllBootEvents();
60 for (auto i = events.cbegin(); i != events.cend(); ++i) {
61 android::metricslogger::LogHistogram(i->first, i->second);
62 }
63 }
64
65 // Records the named boot |event| to the record store. If |value| is non-empty
66 // and is a proper string representation of an integer value, the converted
67 // integer value is associated with the boot event.
RecordBootEventFromCommandLine(const std::string & event,const std::string & value_str)68 void RecordBootEventFromCommandLine(const std::string& event, const std::string& value_str) {
69 BootEventRecordStore boot_event_store;
70 if (!value_str.empty()) {
71 int32_t value = 0;
72 if (android::base::ParseInt(value_str, &value)) {
73 boot_event_store.AddBootEventWithValue(event, value);
74 }
75 } else {
76 boot_event_store.AddBootEvent(event);
77 }
78 }
79
PrintBootEvents()80 void PrintBootEvents() {
81 printf("Boot events:\n");
82 printf("------------\n");
83
84 BootEventRecordStore boot_event_store;
85 auto events = boot_event_store.GetAllBootEvents();
86 for (auto i = events.cbegin(); i != events.cend(); ++i) {
87 printf("%s\t%d\n", i->first.c_str(), i->second);
88 }
89 }
90
ShowHelp(const char * cmd)91 void ShowHelp(const char* cmd) {
92 fprintf(stderr, "Usage: %s [options]...\n", cmd);
93 fprintf(stderr,
94 "options include:\n"
95 " -h, --help Show this help\n"
96 " -l, --log Log all metrics to logstorage\n"
97 " -p, --print Dump the boot event records to the console\n"
98 " -r, --record Record the timestamp of a named boot event\n"
99 " --value Optional value to associate with the boot event\n"
100 " --record_boot_complete Record metrics related to the time for the device boot\n"
101 " --record_boot_reason Record the reason why the device booted\n"
102 " --record_time_since_factory_reset Record the time since the device was reset\n"
103 " --boot_reason_enum=<reason> Report the match to the kBootReasonMap table\n");
104 }
105
106 // Constructs a readable, printable string from the givencommand line
107 // arguments.
GetCommandLine(int argc,char ** argv)108 std::string GetCommandLine(int argc, char** argv) {
109 std::string cmd;
110 for (int i = 0; i < argc; ++i) {
111 cmd += argv[i];
112 cmd += " ";
113 }
114
115 return cmd;
116 }
117
118 constexpr int32_t kEmptyBootReason = 0;
119 constexpr int32_t kUnknownBootReason = 1;
120
121 // A mapping from boot reason string, as read from the ro.boot.bootreason
122 // system property, to a unique integer ID. Viewers of log data dashboards for
123 // the boot_reason metric may refer to this mapping to discern the histogram
124 // values. Regex matching, to manage the scale, as a minimum require either
125 // [, \ or * to be present in the string to switch to checking.
126 const std::map<std::string, int32_t> kBootReasonMap = {
127 {"reboot,[empty]", kEmptyBootReason},
128 {"__BOOTSTAT_UNKNOWN__", kUnknownBootReason},
129 {"normal", 2},
130 {"recovery", 3},
131 {"reboot", 4},
132 {"PowerKey", 5},
133 {"hard_reset", 6},
134 {"kernel_panic", 7},
135 {"rpm_err", 8},
136 {"hw_reset", 9},
137 {"tz_err", 10},
138 {"adsp_err", 11},
139 {"modem_err", 12},
140 {"mba_err", 13},
141 {"Watchdog", 14},
142 {"Panic", 15},
143 {"power_key", 16},
144 {"power_on", 17},
145 {"Reboot", 18},
146 {"rtc", 19},
147 {"edl", 20},
148 {"oem_pon1", 21},
149 {"oem_powerkey", 22},
150 {"oem_unknown_reset", 23},
151 {"srto: HWWDT reset SC", 24},
152 {"srto: HWWDT reset platform", 25},
153 {"srto: bootloader", 26},
154 {"srto: kernel panic", 27},
155 {"srto: kernel watchdog reset", 28},
156 {"srto: normal", 29},
157 {"srto: reboot", 30},
158 {"srto: reboot-bootloader", 31},
159 {"srto: security watchdog reset", 32},
160 {"srto: wakesrc", 33},
161 {"srto: watchdog", 34},
162 {"srto:1-1", 35},
163 {"srto:omap_hsmm", 36},
164 {"srto:phy0", 37},
165 {"srto:rtc0", 38},
166 {"srto:touchpad", 39},
167 {"watchdog", 40},
168 {"watchdogr", 41},
169 {"wdog_bark", 42},
170 {"wdog_bite", 43},
171 {"wdog_reset", 44},
172 {"shutdown,", 45}, // Trailing comma is intentional. Do NOT use.
173 {"shutdown,userrequested", 46},
174 {"reboot,bootloader", 47},
175 {"reboot,cold", 48},
176 {"reboot,recovery", 49},
177 {"thermal_shutdown", 50},
178 {"s3_wakeup", 51},
179 {"kernel_panic,sysrq", 52},
180 {"kernel_panic,NULL", 53},
181 {"kernel_panic,null", 53},
182 {"kernel_panic,BUG", 54},
183 {"kernel_panic,bug", 54},
184 {"bootloader", 55},
185 {"cold", 56},
186 {"hard", 57},
187 {"warm", 58},
188 {"reboot,kernel_power_off_charging__reboot_system", 59}, // Can not happen
189 {"thermal-shutdown", 60},
190 {"shutdown,thermal", 61},
191 {"shutdown,battery", 62},
192 {"reboot,ota", 63},
193 {"reboot,factory_reset", 64},
194 {"reboot,", 65},
195 {"reboot,shell", 66},
196 {"reboot,adb", 67},
197 {"reboot,userrequested", 68},
198 {"shutdown,container", 69}, // Host OS asking Android Container to shutdown
199 {"cold,powerkey", 70},
200 {"warm,s3_wakeup", 71},
201 {"hard,hw_reset", 72},
202 {"shutdown,suspend", 73}, // Suspend to RAM
203 {"shutdown,hibernate", 74}, // Suspend to DISK
204 {"power_on_key", 75},
205 {"reboot_by_key", 76},
206 {"wdt_by_pass_pwk", 77},
207 {"reboot_longkey", 78},
208 {"powerkey", 79},
209 {"usb", 80},
210 {"wdt", 81},
211 {"tool_by_pass_pwk", 82},
212 {"2sec_reboot", 83},
213 {"reboot,by_key", 84},
214 {"reboot,longkey", 85},
215 {"reboot,2sec", 86}, // Deprecate in two years, replaced with cold,rtc,2sec
216 {"shutdown,thermal,battery", 87},
217 {"reboot,its_just_so_hard", 88}, // produced by boot_reason_test
218 {"reboot,Its Just So Hard", 89}, // produced by boot_reason_test
219 {"reboot,rescueparty", 90},
220 {"charge", 91},
221 {"oem_tz_crash", 92},
222 {"uvlo", 93}, // aliasReasons converts to reboot,undervoltage
223 {"oem_ps_hold", 94},
224 {"abnormal_reset", 95},
225 {"oemerr_unknown", 96},
226 {"reboot_fastboot_mode", 97},
227 {"watchdog_apps_bite", 98},
228 {"xpu_err", 99},
229 {"power_on_usb", 100},
230 {"watchdog_rpm", 101},
231 {"watchdog_nonsec", 102},
232 {"watchdog_apps_bark", 103},
233 {"reboot_dmverity_corrupted", 104},
234 {"reboot_smpl", 105}, // aliasReasons converts to reboot,powerloss
235 {"watchdog_sdi_apps_reset", 106},
236 {"smpl", 107}, // aliasReasons converts to reboot,powerloss
237 {"oem_modem_failed_to_powerup", 108},
238 {"reboot_normal", 109},
239 {"oem_lpass_cfg", 110},
240 {"oem_xpu_ns_error", 111},
241 {"power_key_press", 112},
242 {"hardware_reset", 113},
243 {"reboot_by_powerkey", 114},
244 {"reboot_verity", 115},
245 {"oem_rpm_undef_error", 116},
246 {"oem_crash_on_the_lk", 117},
247 {"oem_rpm_reset", 118},
248 {"reboot,powerloss", 119},
249 {"reboot,undervoltage", 120},
250 {"factory_cable", 121},
251 {"oem_ar6320_failed_to_powerup", 122},
252 {"watchdog_rpm_bite", 123},
253 {"power_on_cable", 124},
254 {"reboot_unknown", 125},
255 {"wireless_charger", 126},
256 {"0x776655ff", 127},
257 {"oem_thermal_bite_reset", 128},
258 {"charger", 129},
259 {"pon1", 130},
260 {"unknown", 131},
261 {"reboot_rtc", 132},
262 {"cold_boot", 133},
263 {"hard_rst", 134},
264 {"power-on", 135},
265 {"oem_adsp_resetting_the_soc", 136},
266 {"kpdpwr", 137},
267 {"oem_modem_timeout_waiting", 138},
268 {"usb_chg", 139},
269 {"warm_reset_0x02", 140},
270 {"warm_reset_0x80", 141},
271 {"pon_reason_0xb0", 142},
272 {"reboot_download", 143},
273 {"reboot_recovery_mode", 144},
274 {"oem_sdi_err_fatal", 145},
275 {"pmic_watchdog", 146},
276 {"software_master", 147},
277 {"cold,charger", 148},
278 {"cold,rtc", 149},
279 {"cold,rtc,2sec", 150},
280 {"reboot,tool", 151},
281 {"reboot,wdt", 152},
282 {"reboot,unknown", 153},
283 {"kernel_panic,audit", 154},
284 {"kernel_panic,atomic", 155},
285 {"kernel_panic,hung", 156},
286 {"kernel_panic,hung,rcu", 157},
287 {"kernel_panic,init", 158},
288 {"kernel_panic,oom", 159},
289 {"kernel_panic,stack", 160},
290 {"kernel_panic,sysrq,livelock,alarm", 161}, // llkd
291 {"kernel_panic,sysrq,livelock,driver", 162}, // llkd
292 {"kernel_panic,sysrq,livelock,zombie", 163}, // llkd
293 {"kernel_panic,modem", 164},
294 {"kernel_panic,adsp", 165},
295 {"kernel_panic,dsps", 166},
296 {"kernel_panic,wcnss", 167},
297 {"kernel_panic,_sde_encoder_phys_cmd_handle_ppdone_timeout", 168},
298 {"recovery,quiescent", 169},
299 {"reboot,quiescent", 170},
300 {"reboot,rtc", 171},
301 {"reboot,dm-verity_device_corrupted", 172},
302 {"reboot,dm-verity_enforcing", 173},
303 {"reboot,keys_clear", 174},
304 {"reboot,pmic_off_fault,.*", 175},
305 {"reboot,pmic_off_s3rst,.*", 176},
306 {"reboot,pmic_off_other,.*", 177},
307 };
308
309 // Converts a string value representing the reason the system booted to an
310 // integer representation. This is necessary for logging the boot_reason metric
311 // via Tron, which does not accept non-integer buckets in histograms.
BootReasonStrToEnum(const std::string & boot_reason)312 int32_t BootReasonStrToEnum(const std::string& boot_reason) {
313 auto mapping = kBootReasonMap.find(boot_reason);
314 if (mapping != kBootReasonMap.end()) {
315 return mapping->second;
316 }
317
318 if (boot_reason.empty()) {
319 return kEmptyBootReason;
320 }
321
322 for (const auto& [match, id] : kBootReasonMap) {
323 // Regex matches as a minimum require either [, \ or * to be present.
324 if (match.find_first_of("[\\*") == match.npos) continue;
325 // enforce match from beginning to end
326 auto exact = match;
327 if (exact[0] != '^') exact = "^" + exact;
328 if (exact[exact.size() - 1] != '$') exact = exact + "$";
329 if (std::regex_search(boot_reason, std::regex(exact))) return id;
330 }
331
332 LOG(INFO) << "Unknown boot reason: " << boot_reason;
333 return kUnknownBootReason;
334 }
335
336 // Canonical list of supported primary reboot reasons.
337 const std::vector<const std::string> knownReasons = {
338 // clang-format off
339 // kernel
340 "watchdog",
341 "kernel_panic",
342 // strong
343 "recovery", // Should not happen from ro.boot.bootreason
344 "bootloader", // Should not happen from ro.boot.bootreason
345 // blunt
346 "cold",
347 "hard",
348 "warm",
349 // super blunt
350 "shutdown", // Can not happen from ro.boot.bootreason
351 "reboot", // Default catch-all for anything unknown
352 // clang-format on
353 };
354
355 // Returns true if the supplied reason prefix is considered detailed enough.
isStrongRebootReason(const std::string & r)356 bool isStrongRebootReason(const std::string& r) {
357 for (auto& s : knownReasons) {
358 if (s == "cold") break;
359 // Prefix defined as terminated by a nul or comma (,).
360 if (android::base::StartsWith(r, s) && ((r.length() == s.length()) || (r[s.length()] == ','))) {
361 return true;
362 }
363 }
364 return false;
365 }
366
367 // Returns true if the supplied reason prefix is associated with the kernel.
isKernelRebootReason(const std::string & r)368 bool isKernelRebootReason(const std::string& r) {
369 for (auto& s : knownReasons) {
370 if (s == "recovery") break;
371 // Prefix defined as terminated by a nul or comma (,).
372 if (android::base::StartsWith(r, s) && ((r.length() == s.length()) || (r[s.length()] == ','))) {
373 return true;
374 }
375 }
376 return false;
377 }
378
379 // Returns true if the supplied reason prefix is considered known.
isKnownRebootReason(const std::string & r)380 bool isKnownRebootReason(const std::string& r) {
381 for (auto& s : knownReasons) {
382 // Prefix defined as terminated by a nul or comma (,).
383 if (android::base::StartsWith(r, s) && ((r.length() == s.length()) || (r[s.length()] == ','))) {
384 return true;
385 }
386 }
387 return false;
388 }
389
390 // If the reboot reason should be improved, report true if is too blunt.
isBluntRebootReason(const std::string & r)391 bool isBluntRebootReason(const std::string& r) {
392 if (isStrongRebootReason(r)) return false;
393
394 if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail
395
396 size_t pos = 0;
397 while ((pos = r.find(',', pos)) != std::string::npos) {
398 ++pos;
399 std::string next(r.substr(pos));
400 if (next.length() == 0) break;
401 if (next[0] == ',') continue;
402 if (!isKnownRebootReason(next)) return false; // Unknown subreason is good.
403 if (isStrongRebootReason(next)) return false; // eg: reboot,reboot
404 }
405 return true;
406 }
407
readPstoreConsole(std::string & console)408 bool readPstoreConsole(std::string& console) {
409 if (android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0", &console)) {
410 return true;
411 }
412 return android::base::ReadFileToString("/sys/fs/pstore/console-ramoops", &console);
413 }
414
415 // Implement a variant of std::string::rfind that is resilient to errors in
416 // the data stream being inspected.
417 class pstoreConsole {
418 private:
419 const size_t kBitErrorRate = 8; // number of bits per error
420 const std::string& console;
421
422 // Number of bits that differ between the two arguments l and r.
423 // Returns zero if the values for l and r are identical.
numError(uint8_t l,uint8_t r) const424 size_t numError(uint8_t l, uint8_t r) const { return std::bitset<8>(l ^ r).count(); }
425
426 // A string comparison function, reports the number of errors discovered
427 // in the match to a maximum of the bitLength / kBitErrorRate, at that
428 // point returning npos to indicate match is too poor.
429 //
430 // Since called in rfind which works backwards, expect cache locality will
431 // help if we check in reverse here as well for performance.
432 //
433 // Assumption: l (from console.c_str() + pos) is long enough to house
434 // _r.length(), checked in rfind caller below.
435 //
numError(size_t pos,const std::string & _r) const436 size_t numError(size_t pos, const std::string& _r) const {
437 const char* l = console.c_str() + pos;
438 const char* r = _r.c_str();
439 size_t n = _r.length();
440 const uint8_t* le = reinterpret_cast<const uint8_t*>(l) + n;
441 const uint8_t* re = reinterpret_cast<const uint8_t*>(r) + n;
442 size_t count = 0;
443 n = 0;
444 do {
445 // individual character bit error rate > threshold + slop
446 size_t num = numError(*--le, *--re);
447 if (num > ((8 + kBitErrorRate) / kBitErrorRate)) return std::string::npos;
448 // total bit error rate > threshold + slop
449 count += num;
450 ++n;
451 if (count > ((n * 8 + kBitErrorRate - (n > 2)) / kBitErrorRate)) {
452 return std::string::npos;
453 }
454 } while (le != reinterpret_cast<const uint8_t*>(l));
455 return count;
456 }
457
458 public:
pstoreConsole(const std::string & console)459 explicit pstoreConsole(const std::string& console) : console(console) {}
460 // scope of argument must be equal to or greater than scope of pstoreConsole
461 explicit pstoreConsole(const std::string&& console) = delete;
462 explicit pstoreConsole(std::string&& console) = delete;
463
464 // Our implementation of rfind, use exact match first, then resort to fuzzy.
rfind(const std::string & needle) const465 size_t rfind(const std::string& needle) const {
466 size_t pos = console.rfind(needle); // exact match?
467 if (pos != std::string::npos) return pos;
468
469 // Check to make sure needle fits in console string.
470 pos = console.length();
471 if (needle.length() > pos) return std::string::npos;
472 pos -= needle.length();
473 // fuzzy match to maximum kBitErrorRate
474 for (;;) {
475 if (numError(pos, needle) != std::string::npos) return pos;
476 if (pos == 0) break;
477 --pos;
478 }
479 return std::string::npos;
480 }
481
482 // Our implementation of find, use only fuzzy match.
find(const std::string & needle,size_t start=0) const483 size_t find(const std::string& needle, size_t start = 0) const {
484 // Check to make sure needle fits in console string.
485 if (needle.length() > console.length()) return std::string::npos;
486 const size_t last_pos = console.length() - needle.length();
487 // fuzzy match to maximum kBitErrorRate
488 for (size_t pos = start; pos <= last_pos; ++pos) {
489 if (numError(pos, needle) != std::string::npos) return pos;
490 }
491 return std::string::npos;
492 }
493
operator const std::string&() const494 operator const std::string&() const { return console; }
495 };
496
497 // If bit error match to needle, correct it.
498 // Return true if any corrections were discovered and applied.
correctForBitError(std::string & reason,const std::string & needle)499 bool correctForBitError(std::string& reason, const std::string& needle) {
500 bool corrected = false;
501 if (reason.length() < needle.length()) return corrected;
502 const pstoreConsole console(reason);
503 const size_t last_pos = reason.length() - needle.length();
504 for (size_t pos = 0; pos <= last_pos; pos += needle.length()) {
505 pos = console.find(needle, pos);
506 if (pos == std::string::npos) break;
507
508 // exact match has no malice
509 if (needle == reason.substr(pos, needle.length())) continue;
510
511 corrected = true;
512 reason = reason.substr(0, pos) + needle + reason.substr(pos + needle.length());
513 }
514 return corrected;
515 }
516
517 // If bit error match to needle, correct it.
518 // Return true if any corrections were discovered and applied.
519 // Try again if we can replace underline with spaces.
correctForBitErrorOrUnderline(std::string & reason,const std::string & needle)520 bool correctForBitErrorOrUnderline(std::string& reason, const std::string& needle) {
521 bool corrected = correctForBitError(reason, needle);
522 std::string _needle(needle);
523 std::transform(_needle.begin(), _needle.end(), _needle.begin(),
524 [](char c) { return (c == '_') ? ' ' : c; });
525 if (needle != _needle) {
526 corrected |= correctForBitError(reason, _needle);
527 }
528 return corrected;
529 }
530
531 // Converts a string value representing the reason the system booted to a
532 // string complying with Android system standard reason.
transformReason(std::string & reason)533 void transformReason(std::string& reason) {
534 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
535 std::transform(reason.begin(), reason.end(), reason.begin(),
536 [](char c) { return ::isblank(c) ? '_' : c; });
537 std::transform(reason.begin(), reason.end(), reason.begin(),
538 [](char c) { return ::isprint(c) ? c : '?'; });
539 }
540
541 // Check subreasons for reboot,<subreason> kernel_panic,sysrq,<subreason> or
542 // kernel_panic,<subreason>.
543 //
544 // If quoted flag is set, pull out and correct single quoted ('), newline (\n)
545 // or unprintable character terminated subreason, pos is supplied just beyond
546 // first quote. if quoted false, pull out and correct newline (\n) or
547 // unprintable character terminated subreason.
548 //
549 // Heuristics to find termination is painted into a corner:
550
551 // single bit error for quote ' that we can block. It is acceptable for
552 // the others 7, g in reason. 2/9 chance will miss the terminating quote,
553 // but there is always the terminating newline that usually immediately
554 // follows to fortify our chances.
likely_single_quote(char c)555 bool likely_single_quote(char c) {
556 switch (static_cast<uint8_t>(c)) {
557 case '\'': // '\''
558 case '\'' ^ 0x01: // '&'
559 case '\'' ^ 0x02: // '%'
560 case '\'' ^ 0x04: // '#'
561 case '\'' ^ 0x08: // '/'
562 return true;
563 case '\'' ^ 0x10: // '7'
564 break;
565 case '\'' ^ 0x20: // '\a' (unprintable)
566 return true;
567 case '\'' ^ 0x40: // 'g'
568 break;
569 case '\'' ^ 0x80: // 0xA7 (unprintable)
570 return true;
571 }
572 return false;
573 }
574
575 // ::isprint(c) and likely_space() will prevent us from being called for
576 // fundamentally printable entries, except for '\r' and '\b'.
577 //
578 // Except for * and J, single bit errors for \n, all others are non-
579 // printable so easy catch. It is _acceptable_ for *, J or j to exist in
580 // the reason string, so 2/9 chance we will miss the terminating newline.
581 //
582 // NB: J might not be acceptable, except if at the beginning or preceded
583 // with a space, '(' or any of the quotes and their BER aliases.
584 // NB: * might not be acceptable, except if at the beginning or preceded
585 // with a space, another *, or any of the quotes or their BER aliases.
586 //
587 // To reduce the chances to closer to 1/9 is too complicated for the gain.
likely_newline(char c)588 bool likely_newline(char c) {
589 switch (static_cast<uint8_t>(c)) {
590 case '\n': // '\n' (unprintable)
591 case '\n' ^ 0x01: // '\r' (unprintable)
592 case '\n' ^ 0x02: // '\b' (unprintable)
593 case '\n' ^ 0x04: // 0x0E (unprintable)
594 case '\n' ^ 0x08: // 0x02 (unprintable)
595 case '\n' ^ 0x10: // 0x1A (unprintable)
596 return true;
597 case '\n' ^ 0x20: // '*'
598 case '\n' ^ 0x40: // 'J'
599 break;
600 case '\n' ^ 0x80: // 0x8A (unprintable)
601 return true;
602 }
603 return false;
604 }
605
606 // ::isprint(c) will prevent us from being called for all the printable
607 // matches below. If we let unprintables through because of this, they
608 // get converted to underscore (_) by the validation phase.
likely_space(char c)609 bool likely_space(char c) {
610 switch (static_cast<uint8_t>(c)) {
611 case ' ': // ' '
612 case ' ' ^ 0x01: // '!'
613 case ' ' ^ 0x02: // '"'
614 case ' ' ^ 0x04: // '$'
615 case ' ' ^ 0x08: // '('
616 case ' ' ^ 0x10: // '0'
617 case ' ' ^ 0x20: // '\0' (unprintable)
618 case ' ' ^ 0x40: // 'P'
619 case ' ' ^ 0x80: // 0xA0 (unprintable)
620 case '\t': // '\t'
621 case '\t' ^ 0x01: // '\b' (unprintable) (likely_newline counters)
622 case '\t' ^ 0x02: // '\v' (unprintable)
623 case '\t' ^ 0x04: // '\r' (unprintable) (likely_newline counters)
624 case '\t' ^ 0x08: // 0x01 (unprintable)
625 case '\t' ^ 0x10: // 0x19 (unprintable)
626 case '\t' ^ 0x20: // ')'
627 case '\t' ^ 0x40: // '1'
628 case '\t' ^ 0x80: // 0x89 (unprintable)
629 return true;
630 }
631 return false;
632 }
633
getSubreason(const std::string & content,size_t pos,bool quoted)634 std::string getSubreason(const std::string& content, size_t pos, bool quoted) {
635 static constexpr size_t max_reason_length = 256;
636
637 std::string subReason(content.substr(pos, max_reason_length));
638 // Correct against any known strings that Bit Error Match
639 for (const auto& s : knownReasons) {
640 correctForBitErrorOrUnderline(subReason, s);
641 }
642 std::string terminator(quoted ? "'" : "");
643 for (const auto& m : kBootReasonMap) {
644 if (m.first.length() <= strlen("cold")) continue; // too short?
645 if (correctForBitErrorOrUnderline(subReason, m.first + terminator)) continue;
646 if (m.first.length() <= strlen("reboot,cold")) continue; // short?
647 if (android::base::StartsWith(m.first, "reboot,")) {
648 correctForBitErrorOrUnderline(subReason, m.first.substr(strlen("reboot,")) + terminator);
649 } else if (android::base::StartsWith(m.first, "kernel_panic,sysrq,")) {
650 correctForBitErrorOrUnderline(subReason,
651 m.first.substr(strlen("kernel_panic,sysrq,")) + terminator);
652 } else if (android::base::StartsWith(m.first, "kernel_panic,")) {
653 correctForBitErrorOrUnderline(subReason, m.first.substr(strlen("kernel_panic,")) + terminator);
654 }
655 }
656 for (pos = 0; pos < subReason.length(); ++pos) {
657 char c = subReason[pos];
658 if (!(::isprint(c) || likely_space(c)) || likely_newline(c) ||
659 (quoted && likely_single_quote(c))) {
660 subReason.erase(pos);
661 break;
662 }
663 }
664 transformReason(subReason);
665 return subReason;
666 }
667
addKernelPanicSubReason(const pstoreConsole & console,std::string & ret)668 bool addKernelPanicSubReason(const pstoreConsole& console, std::string& ret) {
669 // Check for kernel panic types to refine information
670 if ((console.rfind("SysRq : Trigger a crash") != std::string::npos) ||
671 (console.rfind("PC is at sysrq_handle_crash+") != std::string::npos)) {
672 ret = "kernel_panic,sysrq";
673 // Invented for Android to allow daemons that specifically trigger sysrq
674 // to communicate more accurate boot subreasons via last console messages.
675 static constexpr char sysrqSubreason[] = "SysRq : Trigger a crash : '";
676 auto pos = console.rfind(sysrqSubreason);
677 if (pos != std::string::npos) {
678 ret += "," + getSubreason(console, pos + strlen(sysrqSubreason), /* quoted */ true);
679 }
680 return true;
681 }
682 if (console.rfind("Unable to handle kernel NULL pointer dereference at virtual address") !=
683 std::string::npos) {
684 ret = "kernel_panic,null";
685 return true;
686 }
687 if (console.rfind("Kernel BUG at ") != std::string::npos) {
688 ret = "kernel_panic,bug";
689 return true;
690 }
691
692 std::string panic("Kernel panic - not syncing: ");
693 auto pos = console.rfind(panic);
694 if (pos != std::string::npos) {
695 static const std::vector<std::pair<const std::string, const std::string>> panicReasons = {
696 {"Out of memory", "oom"},
697 {"out of memory", "oom"},
698 {"Oh boy, that early out of memory", "oom"}, // omg
699 {"BUG!", "bug"},
700 {"hung_task: blocked tasks", "hung"},
701 {"audit: ", "audit"},
702 {"scheduling while atomic", "atomic"},
703 {"Attempted to kill init!", "init"},
704 {"Requested init", "init"},
705 {"No working init", "init"},
706 {"Could not decompress init", "init"},
707 {"RCU Stall", "hung,rcu"},
708 {"stack-protector", "stack"},
709 {"kernel stack overflow", "stack"},
710 {"Corrupt kernel stack", "stack"},
711 {"low stack detected", "stack"},
712 {"corrupted stack end", "stack"},
713 {"subsys-restart: Resetting the SoC - modem crashed.", "modem"},
714 {"subsys-restart: Resetting the SoC - adsp crashed.", "adsp"},
715 {"subsys-restart: Resetting the SoC - dsps crashed.", "dsps"},
716 {"subsys-restart: Resetting the SoC - wcnss crashed.", "wcnss"},
717 };
718
719 ret = "kernel_panic";
720 for (auto& s : panicReasons) {
721 if (console.find(panic + s.first, pos) != std::string::npos) {
722 ret += "," + s.second;
723 return true;
724 }
725 }
726 auto reason = getSubreason(console, pos + panic.length(), /* newline */ false);
727 if (reason.length() > 3) {
728 ret += "," + reason;
729 }
730 return true;
731 }
732 return false;
733 }
734
addKernelPanicSubReason(const std::string & content,std::string & ret)735 bool addKernelPanicSubReason(const std::string& content, std::string& ret) {
736 return addKernelPanicSubReason(pstoreConsole(content), ret);
737 }
738
739 const char system_reboot_reason_property[] = "sys.boot.reason";
740 const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
741 const char last_last_reboot_reason_property[] = "sys.boot.reason.last";
742 constexpr size_t history_reboot_reason_size = 4;
743 const char history_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY ".history";
744 const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
745
746 // Land system_boot_reason into system_reboot_reason_property.
747 // Shift system_boot_reason into history_reboot_reason_property.
BootReasonAddToHistory(const std::string & system_boot_reason)748 void BootReasonAddToHistory(const std::string& system_boot_reason) {
749 if (system_boot_reason.empty()) return;
750 LOG(INFO) << "Canonical boot reason: " << system_boot_reason;
751 auto old_system_boot_reason = android::base::GetProperty(system_reboot_reason_property, "");
752 if (!android::base::SetProperty(system_reboot_reason_property, system_boot_reason)) {
753 android::base::SetProperty(system_reboot_reason_property,
754 system_boot_reason.substr(0, PROPERTY_VALUE_MAX - 1));
755 }
756 auto reason_history =
757 android::base::Split(android::base::GetProperty(history_reboot_reason_property, ""), "\n");
758 static auto mark = time(nullptr);
759 auto mark_str = std::string(",") + std::to_string(mark);
760 auto marked_system_boot_reason = system_boot_reason + mark_str;
761 if (!reason_history.empty()) {
762 // delete any entries that we just wrote in a previous
763 // call and leveraging duplicate line handling
764 auto last = old_system_boot_reason + mark_str;
765 // trim the list to (history_reboot_reason_size - 1)
766 ssize_t max = history_reboot_reason_size;
767 for (auto it = reason_history.begin(); it != reason_history.end();) {
768 if (it->empty() || (last == *it) || (marked_system_boot_reason == *it) || (--max <= 0)) {
769 it = reason_history.erase(it);
770 } else {
771 last = *it;
772 ++it;
773 }
774 }
775 }
776 // insert at the front, concatenating mark (<epoch time>) detail to the value.
777 reason_history.insert(reason_history.begin(), marked_system_boot_reason);
778 // If the property string is too long ( > PROPERTY_VALUE_MAX)
779 // we get an error, so trim out last entry and try again.
780 while (!android::base::SetProperty(history_reboot_reason_property,
781 android::base::Join(reason_history, '\n'))) {
782 auto it = std::prev(reason_history.end());
783 if (it == reason_history.end()) break;
784 reason_history.erase(it);
785 }
786 }
787
788 // Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
BootReasonStrToReason(const std::string & boot_reason)789 std::string BootReasonStrToReason(const std::string& boot_reason) {
790 auto ret = android::base::GetProperty(system_reboot_reason_property, "");
791 std::string reason(boot_reason);
792 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
793 if (reason == ret) ret = "";
794
795 transformReason(reason);
796
797 // Is the current system boot reason sys.boot.reason valid?
798 if (!isKnownRebootReason(ret)) ret = "";
799
800 if (ret == "") {
801 // Is the bootloader boot reason ro.boot.bootreason known?
802 std::vector<std::string> words(android::base::Split(reason, ",_-"));
803 for (auto& s : knownReasons) {
804 std::string blunt;
805 for (auto& r : words) {
806 if (r == s) {
807 if (isBluntRebootReason(s)) {
808 blunt = s;
809 } else {
810 ret = s;
811 break;
812 }
813 }
814 }
815 if (ret == "") ret = blunt;
816 if (ret != "") break;
817 }
818 }
819
820 if (ret == "") {
821 // A series of checks to take some officially unsupported reasons
822 // reported by the bootloader and find some logical and canonical
823 // sense. In an ideal world, we would require those bootloaders
824 // to behave and follow our CTS standards.
825 //
826 // first member is the output
827 // second member is an unanchored regex for an alias
828 //
829 // If output has a prefix of <bang> '!', we do not use it as a
830 // match needle (and drop the <bang> prefix when landing in output),
831 // otherwise look for it as well. This helps keep the scale of the
832 // following table smaller.
833 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
834 {"watchdog", "wdog"},
835 {"cold,powerkey", "powerkey|power_key|PowerKey"},
836 {"kernel_panic", "panic"},
837 {"shutdown,thermal", "thermal"},
838 {"warm,s3_wakeup", "s3_wakeup"},
839 {"hard,hw_reset", "hw_reset"},
840 {"cold,charger", "usb"},
841 {"cold,rtc", "rtc"},
842 {"cold,rtc,2sec", "2sec_reboot"},
843 {"!warm", "wdt_by_pass_pwk"}, // change flavour of blunt
844 {"!reboot", "^wdt$"}, // change flavour of blunt
845 {"reboot,tool", "tool_by_pass_pwk"},
846 {"!reboot,longkey", "reboot_longkey"},
847 {"!reboot,longkey", "kpdpwr"},
848 {"!reboot,undervoltage", "uvlo"},
849 {"!reboot,powerloss", "smpl"},
850 {"bootloader", ""},
851 };
852
853 for (auto& s : aliasReasons) {
854 size_t firstHasNot = s.first[0] == '!';
855 if (!firstHasNot && (reason.find(s.first) != std::string::npos)) {
856 ret = s.first;
857 break;
858 }
859 if (s.second.size() && std::regex_search(reason, std::regex(s.second))) {
860 ret = s.first.substr(firstHasNot);
861 break;
862 }
863 }
864 }
865
866 // If watchdog is the reason, see if there is a security angle?
867 if (ret == "watchdog") {
868 if (reason.find("sec") != std::string::npos) {
869 ret += ",security";
870 }
871 }
872
873 if (ret == "kernel_panic") {
874 // Check to see if last klog has some refinement hints.
875 std::string content;
876 if (readPstoreConsole(content)) {
877 addKernelPanicSubReason(content, ret);
878 }
879 } else if (isBluntRebootReason(ret)) {
880 // Check the other available reason resources if the reason is still blunt.
881
882 // Check to see if last klog has some refinement hints.
883 std::string content;
884 if (readPstoreConsole(content)) {
885 const pstoreConsole console(content);
886 // The toybox reboot command used directly (unlikely)? But also
887 // catches init's response to Android's more controlled reboot command.
888 if (console.rfind("reboot: Power down") != std::string::npos) {
889 ret = "shutdown"; // Still too blunt, but more accurate.
890 // ToDo: init should record the shutdown reason to kernel messages ala:
891 // init: shutdown system with command 'last_reboot_reason'
892 // so that if pstore has persistence we can get some details
893 // that could be missing in last_reboot_reason_property.
894 }
895
896 static const char cmd[] = "reboot: Restarting system with command '";
897 size_t pos = console.rfind(cmd);
898 if (pos != std::string::npos) {
899 std::string subReason(getSubreason(content, pos + strlen(cmd), /* quoted */ true));
900 if (subReason != "") { // Will not land "reboot" as that is too blunt.
901 if (isKernelRebootReason(subReason)) {
902 ret = "reboot," + subReason; // User space can't talk kernel reasons.
903 } else if (isKnownRebootReason(subReason)) {
904 ret = subReason;
905 } else {
906 ret = "reboot," + subReason; // legitimize unknown reasons
907 }
908 }
909 // Some bootloaders shutdown results record in last kernel message.
910 if (!strcmp(ret.c_str(), "reboot,kernel_power_off_charging__reboot_system")) {
911 ret = "shutdown";
912 }
913 }
914
915 // Check for kernel panics, allowed to override reboot command.
916 if (!addKernelPanicSubReason(console, ret) &&
917 // check for long-press power down
918 ((console.rfind("Power held for ") != std::string::npos) ||
919 (console.rfind("charger: [") != std::string::npos))) {
920 ret = "cold";
921 }
922 }
923
924 // TODO: use the HAL to get battery level (http://b/77725702).
925
926 // Is there a controlled shutdown hint in last_reboot_reason_property?
927 if (isBluntRebootReason(ret)) {
928 // Content buffer no longer will have console data. Beware if more
929 // checks added below, that depend on parsing console content.
930 content = android::base::GetProperty(last_reboot_reason_property, "");
931 transformReason(content);
932
933 // Anything in last is better than 'super-blunt' reboot or shutdown.
934 if ((ret == "") || (ret == "reboot") || (ret == "shutdown") || !isBluntRebootReason(content)) {
935 ret = content;
936 }
937 }
938
939 // Other System Health HAL reasons?
940
941 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
942 // possibly offer hardware-specific clues from the PMIC.
943 }
944
945 // If unknown left over from above, make it "reboot,<boot_reason>"
946 if (ret == "") {
947 ret = "reboot";
948 if (android::base::StartsWith(reason, "reboot")) {
949 reason = reason.substr(strlen("reboot"));
950 while ((reason[0] == ',') || (reason[0] == '_')) {
951 reason = reason.substr(1);
952 }
953 }
954 if (reason != "") {
955 ret += ",";
956 ret += reason;
957 }
958 }
959
960 LOG(INFO) << "Canonical boot reason: " << ret;
961 return ret;
962 }
963
964 // Returns the appropriate metric key prefix for the boot_complete metric such
965 // that boot metrics after a system update are labeled as ota_boot_complete;
966 // otherwise, they are labeled as boot_complete. This method encapsulates the
967 // bookkeeping required to track when a system update has occurred by storing
968 // the UTC timestamp of the system build date and comparing against the current
969 // system build date.
CalculateBootCompletePrefix()970 std::string CalculateBootCompletePrefix() {
971 static const std::string kBuildDateKey = "build_date";
972 std::string boot_complete_prefix = "boot_complete";
973
974 auto build_date_str = android::base::GetProperty("ro.build.date.utc", "");
975 int32_t build_date;
976 if (!android::base::ParseInt(build_date_str, &build_date)) {
977 return std::string();
978 }
979
980 BootEventRecordStore boot_event_store;
981 BootEventRecordStore::BootEventRecord record;
982 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
983 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
984 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
985 BootReasonAddToHistory("reboot,factory_reset");
986 } else if (build_date != record.second) {
987 boot_complete_prefix = "ota_" + boot_complete_prefix;
988 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
989 BootReasonAddToHistory("reboot,ota");
990 }
991
992 return boot_complete_prefix;
993 }
994
995 // Records the value of a given ro.boottime.init property in milliseconds.
RecordInitBootTimeProp(BootEventRecordStore * boot_event_store,const char * property)996 void RecordInitBootTimeProp(BootEventRecordStore* boot_event_store, const char* property) {
997 auto value = android::base::GetProperty(property, "");
998
999 int32_t time_in_ms;
1000 if (android::base::ParseInt(value, &time_in_ms)) {
1001 boot_event_store->AddBootEventWithValue(property, time_in_ms);
1002 }
1003 }
1004
1005 // A map from bootloader timing stage to the time that stage took during boot.
1006 typedef std::map<std::string, int32_t> BootloaderTimingMap;
1007
1008 // Returns a mapping from bootloader stage names to the time those stages
1009 // took to boot.
GetBootLoaderTimings()1010 const BootloaderTimingMap GetBootLoaderTimings() {
1011 BootloaderTimingMap timings;
1012
1013 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
1014 // where timeN is in milliseconds.
1015 auto value = android::base::GetProperty("ro.boot.boottime", "");
1016 if (value.empty()) {
1017 // ro.boot.boottime is not reported on all devices.
1018 return BootloaderTimingMap();
1019 }
1020
1021 auto stages = android::base::Split(value, ",");
1022 for (const auto& stageTiming : stages) {
1023 // |stageTiming| is of the form 'stage:time'.
1024 auto stageTimingValues = android::base::Split(stageTiming, ":");
1025 DCHECK_EQ(2U, stageTimingValues.size());
1026
1027 if (stageTimingValues.size() < 2) continue;
1028 std::string stageName = stageTimingValues[0];
1029 int32_t time_ms;
1030 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
1031 timings[stageName] = time_ms;
1032 }
1033 }
1034
1035 return timings;
1036 }
1037
1038 // Returns the total bootloader boot time from the ro.boot.boottime system property.
GetBootloaderTime(const BootloaderTimingMap & bootloader_timings)1039 int32_t GetBootloaderTime(const BootloaderTimingMap& bootloader_timings) {
1040 int32_t total_time = 0;
1041 for (const auto& timing : bootloader_timings) {
1042 total_time += timing.second;
1043 }
1044
1045 return total_time;
1046 }
1047
1048 // Parses and records the set of bootloader stages and associated boot times
1049 // from the ro.boot.boottime system property.
RecordBootloaderTimings(BootEventRecordStore * boot_event_store,const BootloaderTimingMap & bootloader_timings)1050 void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
1051 const BootloaderTimingMap& bootloader_timings) {
1052 int32_t total_time = 0;
1053 for (const auto& timing : bootloader_timings) {
1054 total_time += timing.second;
1055 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
1056 }
1057
1058 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
1059 }
1060
1061 // Returns the closest estimation to the absolute device boot time, i.e.,
1062 // from power on to boot_complete, including bootloader times.
GetAbsoluteBootTime(const BootloaderTimingMap & bootloader_timings,std::chrono::milliseconds uptime)1063 std::chrono::milliseconds GetAbsoluteBootTime(const BootloaderTimingMap& bootloader_timings,
1064 std::chrono::milliseconds uptime) {
1065 int32_t bootloader_time_ms = 0;
1066
1067 for (const auto& timing : bootloader_timings) {
1068 if (timing.first.compare("SW") != 0) {
1069 bootloader_time_ms += timing.second;
1070 }
1071 }
1072
1073 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
1074 return bootloader_duration + uptime;
1075 }
1076
1077 // Records the closest estimation to the absolute device boot time in seconds.
1078 // i.e. from power on to boot_complete, including bootloader times.
RecordAbsoluteBootTime(BootEventRecordStore * boot_event_store,std::chrono::milliseconds absolute_total)1079 void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
1080 std::chrono::milliseconds absolute_total) {
1081 auto absolute_total_sec = std::chrono::duration_cast<std::chrono::seconds>(absolute_total);
1082 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total_sec.count());
1083 }
1084
1085 // Logs the total boot time and reason to statsd.
LogBootInfoToStatsd(std::chrono::milliseconds end_time,std::chrono::milliseconds total_duration,int32_t bootloader_duration_ms,double time_since_last_boot_sec)1086 void LogBootInfoToStatsd(std::chrono::milliseconds end_time,
1087 std::chrono::milliseconds total_duration, int32_t bootloader_duration_ms,
1088 double time_since_last_boot_sec) {
1089 auto reason = android::base::GetProperty(bootloader_reboot_reason_property, "<EMPTY>");
1090 auto system_reason = android::base::GetProperty(system_reboot_reason_property, "<EMPTY>");
1091 android::util::stats_write(android::util::BOOT_SEQUENCE_REPORTED, reason.c_str(),
1092 system_reason.c_str(), end_time.count(), total_duration.count(),
1093 (int64_t)bootloader_duration_ms,
1094 (int64_t)time_since_last_boot_sec * 1000);
1095 }
1096
SetSystemBootReason()1097 void SetSystemBootReason() {
1098 const auto bootloader_boot_reason =
1099 android::base::GetProperty(bootloader_reboot_reason_property, "");
1100 const std::string system_boot_reason(BootReasonStrToReason(bootloader_boot_reason));
1101 // Record the scrubbed system_boot_reason to the property
1102 BootReasonAddToHistory(system_boot_reason);
1103 // Shift last_reboot_reason_property to last_last_reboot_reason_property
1104 auto last_boot_reason = android::base::GetProperty(last_reboot_reason_property, "");
1105 if (last_boot_reason.empty() || isKernelRebootReason(system_boot_reason)) {
1106 last_boot_reason = system_boot_reason;
1107 } else {
1108 transformReason(last_boot_reason);
1109 }
1110 android::base::SetProperty(last_last_reboot_reason_property, last_boot_reason);
1111 android::base::SetProperty(last_reboot_reason_property, "");
1112 }
1113
1114 // Gets the boot time offset. This is useful when Android is running in a
1115 // container, because the boot_clock is not reset when Android reboots.
GetBootTimeOffset()1116 std::chrono::nanoseconds GetBootTimeOffset() {
1117 static const int64_t boottime_offset =
1118 android::base::GetIntProperty<int64_t>("ro.boot.boottime_offset", 0);
1119 return std::chrono::nanoseconds(boottime_offset);
1120 }
1121
1122 // Returns the current uptime, accounting for any offset in the CLOCK_BOOTTIME
1123 // clock.
GetUptime()1124 android::base::boot_clock::duration GetUptime() {
1125 return android::base::boot_clock::now().time_since_epoch() - GetBootTimeOffset();
1126 }
1127
1128 // Records several metrics related to the time it takes to boot the device,
1129 // including disambiguating boot time on encrypted or non-encrypted devices.
RecordBootComplete()1130 void RecordBootComplete() {
1131 BootEventRecordStore boot_event_store;
1132 BootEventRecordStore::BootEventRecord record;
1133
1134 auto uptime_ns = GetUptime();
1135 auto uptime_s = std::chrono::duration_cast<std::chrono::seconds>(uptime_ns);
1136 time_t current_time_utc = time(nullptr);
1137 time_t time_since_last_boot = 0;
1138
1139 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
1140 time_t last_boot_time_utc = record.second;
1141 time_since_last_boot = difftime(current_time_utc, last_boot_time_utc);
1142 boot_event_store.AddBootEventWithValue("time_since_last_boot", time_since_last_boot);
1143 }
1144
1145 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
1146
1147 // The boot_complete metric has two variants: boot_complete and
1148 // ota_boot_complete. The latter signifies that the device is booting after
1149 // a system update.
1150 std::string boot_complete_prefix = CalculateBootCompletePrefix();
1151 if (boot_complete_prefix.empty()) {
1152 // The system is hosed because the build date property could not be read.
1153 return;
1154 }
1155
1156 // post_decrypt_time_elapsed is only logged on encrypted devices.
1157 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
1158 // Log the amount of time elapsed until the device is decrypted, which
1159 // includes the variable amount of time the user takes to enter the
1160 // decryption password.
1161 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime_s.count());
1162
1163 // Subtract the decryption time to normalize the boot cycle timing.
1164 std::chrono::seconds boot_complete = std::chrono::seconds(uptime_s.count() - record.second);
1165 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
1166 boot_complete.count());
1167 } else {
1168 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption",
1169 uptime_s.count());
1170 }
1171
1172 // Record the total time from device startup to boot complete, regardless of
1173 // encryption state.
1174 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime_s.count());
1175
1176 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
1177 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
1178 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
1179
1180 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
1181 int32_t bootloader_boot_duration = GetBootloaderTime(bootloader_timings);
1182 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
1183
1184 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(uptime_ns);
1185 auto absolute_boot_time = GetAbsoluteBootTime(bootloader_timings, uptime_ms);
1186 RecordAbsoluteBootTime(&boot_event_store, absolute_boot_time);
1187
1188 auto boot_end_time_point = std::chrono::system_clock::now().time_since_epoch();
1189 auto boot_end_time = std::chrono::duration_cast<std::chrono::milliseconds>(boot_end_time_point);
1190
1191 LogBootInfoToStatsd(boot_end_time, absolute_boot_time, bootloader_boot_duration,
1192 time_since_last_boot);
1193 }
1194
1195 // Records the boot_reason metric by querying the ro.boot.bootreason system
1196 // property.
RecordBootReason()1197 void RecordBootReason() {
1198 const auto reason = android::base::GetProperty(bootloader_reboot_reason_property, "");
1199
1200 if (reason.empty()) {
1201 // Log an empty boot reason value as '<EMPTY>' to ensure the value is intentional
1202 // (and not corruption anywhere else in the reporting pipeline).
1203 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
1204 android::metricslogger::FIELD_PLATFORM_REASON, "<EMPTY>");
1205 } else {
1206 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
1207 android::metricslogger::FIELD_PLATFORM_REASON, reason);
1208 }
1209
1210 // Log the raw bootloader_boot_reason property value.
1211 int32_t boot_reason = BootReasonStrToEnum(reason);
1212 BootEventRecordStore boot_event_store;
1213 boot_event_store.AddBootEventWithValue("boot_reason", boot_reason);
1214
1215 // Log the scrubbed system_boot_reason.
1216 const auto system_reason = android::base::GetProperty(system_reboot_reason_property, "");
1217 int32_t system_boot_reason = BootReasonStrToEnum(system_reason);
1218 boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason);
1219
1220 if (reason == "") {
1221 android::base::SetProperty(bootloader_reboot_reason_property, system_reason);
1222 }
1223 }
1224
1225 // Records two metrics related to the user resetting a device: the time at
1226 // which the device is reset, and the time since the user last reset the
1227 // device. The former is only set once per-factory reset.
RecordFactoryReset()1228 void RecordFactoryReset() {
1229 BootEventRecordStore boot_event_store;
1230 BootEventRecordStore::BootEventRecord record;
1231
1232 time_t current_time_utc = time(nullptr);
1233
1234 if (current_time_utc < 0) {
1235 // UMA does not display negative values in buckets, so convert to positive.
1236 android::metricslogger::LogHistogram("factory_reset_current_time_failure",
1237 std::abs(current_time_utc));
1238
1239 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
1240 // is losing records somehow.
1241 boot_event_store.AddBootEventWithValue("factory_reset_current_time_failure",
1242 std::abs(current_time_utc));
1243 return;
1244 } else {
1245 android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc);
1246
1247 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
1248 // is losing records somehow.
1249 boot_event_store.AddBootEventWithValue("factory_reset_current_time", current_time_utc);
1250 }
1251
1252 // The factory_reset boot event does not exist after the device is reset, so
1253 // use this signal to mark the time of the factory reset.
1254 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
1255 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
1256
1257 // Don't log the time_since_factory_reset until some time has elapsed.
1258 // The data is not meaningful yet and skews the histogram buckets.
1259 return;
1260 }
1261
1262 // Calculate and record the difference in time between now and the
1263 // factory_reset time.
1264 time_t factory_reset_utc = record.second;
1265 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
1266
1267 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
1268 // is losing records somehow.
1269 boot_event_store.AddBootEventWithValue("factory_reset_record_value", factory_reset_utc);
1270
1271 time_t time_since_factory_reset = difftime(current_time_utc, factory_reset_utc);
1272 boot_event_store.AddBootEventWithValue("time_since_factory_reset", time_since_factory_reset);
1273 }
1274
1275 // List the associated boot reason(s), if arg is nullptr then all.
PrintBootReasonEnum(const char * arg)1276 void PrintBootReasonEnum(const char* arg) {
1277 int value = -1;
1278 if (arg != nullptr) {
1279 value = BootReasonStrToEnum(arg);
1280 }
1281 for (const auto& [match, id] : kBootReasonMap) {
1282 if ((value < 0) || (value == id)) {
1283 printf("%u\t%s\n", id, match.c_str());
1284 }
1285 }
1286 }
1287
1288 } // namespace
1289
main(int argc,char ** argv)1290 int main(int argc, char** argv) {
1291 android::base::InitLogging(argv);
1292
1293 const std::string cmd_line = GetCommandLine(argc, argv);
1294 LOG(INFO) << "Service started: " << cmd_line;
1295
1296 int option_index = 0;
1297 static const char value_str[] = "value";
1298 static const char system_boot_reason_str[] = "set_system_boot_reason";
1299 static const char boot_complete_str[] = "record_boot_complete";
1300 static const char boot_reason_str[] = "record_boot_reason";
1301 static const char factory_reset_str[] = "record_time_since_factory_reset";
1302 static const char boot_reason_enum_str[] = "boot_reason_enum";
1303 static const struct option long_options[] = {
1304 // clang-format off
1305 { "help", no_argument, NULL, 'h' },
1306 { "log", no_argument, NULL, 'l' },
1307 { "print", no_argument, NULL, 'p' },
1308 { "record", required_argument, NULL, 'r' },
1309 { value_str, required_argument, NULL, 0 },
1310 { system_boot_reason_str, no_argument, NULL, 0 },
1311 { boot_complete_str, no_argument, NULL, 0 },
1312 { boot_reason_str, no_argument, NULL, 0 },
1313 { factory_reset_str, no_argument, NULL, 0 },
1314 { boot_reason_enum_str, optional_argument, NULL, 0 },
1315 { NULL, 0, NULL, 0 }
1316 // clang-format on
1317 };
1318
1319 std::string boot_event;
1320 std::string value;
1321 int opt = 0;
1322 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
1323 switch (opt) {
1324 // This case handles long options which have no single-character mapping.
1325 case 0: {
1326 const std::string option_name = long_options[option_index].name;
1327 if (option_name == value_str) {
1328 // |optarg| is an external variable set by getopt representing
1329 // the option argument.
1330 value = optarg;
1331 } else if (option_name == system_boot_reason_str) {
1332 SetSystemBootReason();
1333 } else if (option_name == boot_complete_str) {
1334 RecordBootComplete();
1335 } else if (option_name == boot_reason_str) {
1336 RecordBootReason();
1337 } else if (option_name == factory_reset_str) {
1338 RecordFactoryReset();
1339 } else if (option_name == boot_reason_enum_str) {
1340 PrintBootReasonEnum(optarg);
1341 } else {
1342 LOG(ERROR) << "Invalid option: " << option_name;
1343 }
1344 break;
1345 }
1346
1347 case 'h': {
1348 ShowHelp(argv[0]);
1349 break;
1350 }
1351
1352 case 'l': {
1353 LogBootEvents();
1354 break;
1355 }
1356
1357 case 'p': {
1358 PrintBootEvents();
1359 break;
1360 }
1361
1362 case 'r': {
1363 // |optarg| is an external variable set by getopt representing
1364 // the option argument.
1365 boot_event = optarg;
1366 break;
1367 }
1368
1369 default: {
1370 DCHECK_EQ(opt, '?');
1371
1372 // |optopt| is an external variable set by getopt representing
1373 // the value of the invalid option.
1374 LOG(ERROR) << "Invalid option: " << optopt;
1375 ShowHelp(argv[0]);
1376 return EXIT_FAILURE;
1377 }
1378 }
1379 }
1380
1381 if (!boot_event.empty()) {
1382 RecordBootEventFromCommandLine(boot_event, value);
1383 }
1384
1385 return 0;
1386 }
1387