blob: 3b8b707ab2e2987492e7097c924306eb54fce18c [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>
James Hawkinsabd73e62016-01-19 15:10:38 -080022#include <unistd.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070023#include <sys/klog.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>
James Hawkinsbe46fd12017-02-02 16:21:25 -080033#include <vector>
Mark Salyzynff2dcd92016-09-28 15:54:45 -070034
James Hawkinse78ea772017-03-24 11:43:02 -070035#include <android-base/chrono_utils.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070036#include <android-base/file.h>
James Hawkinseabe08b2016-01-19 16:54:35 -080037#include <android-base/logging.h>
James Hawkins4dded612016-07-28 11:50:23 -070038#include <android-base/parseint.h>
James Hawkinsbe46fd12017-02-02 16:21:25 -080039#include <android-base/strings.h>
James Hawkinse78ea772017-03-24 11:43:02 -070040#include <android/log.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070041#include <cutils/android_reboot.h>
James Hawkinsa4a1a4a2016-02-09 15:32:38 -080042#include <cutils/properties.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070043#include <log/logcat.h>
James Hawkins9aec9262017-01-31 11:42:24 -080044#include <metricslogger/metrics_logger.h>
Mark Salyzynff2dcd92016-09-28 15:54:45 -070045
James Hawkinsabd73e62016-01-19 15:10:38 -080046#include "boot_event_record_store.h"
James Hawkinsabd73e62016-01-19 15:10:38 -080047
48namespace {
49
James Hawkinsabd73e62016-01-19 15:10:38 -080050// Scans the boot event record store for record files and logs each boot event
51// via EventLog.
52void LogBootEvents() {
53 BootEventRecordStore boot_event_store;
54
55 auto events = boot_event_store.GetAllBootEvents();
56 for (auto i = events.cbegin(); i != events.cend(); ++i) {
James Hawkins9aec9262017-01-31 11:42:24 -080057 android::metricslogger::LogHistogram(i->first, i->second);
James Hawkinsabd73e62016-01-19 15:10:38 -080058 }
59}
60
James Hawkinsc6275582016-03-22 10:47:44 -070061// Records the named boot |event| to the record store. If |value| is non-empty
62// and is a proper string representation of an integer value, the converted
63// integer value is associated with the boot event.
64void RecordBootEventFromCommandLine(
65 const std::string& event, const std::string& value_str) {
66 BootEventRecordStore boot_event_store;
67 if (!value_str.empty()) {
68 int32_t value = 0;
Elliott Hughesda46b392016-10-11 17:09:00 -070069 if (android::base::ParseInt(value_str, &value)) {
James Hawkins4dded612016-07-28 11:50:23 -070070 boot_event_store.AddBootEventWithValue(event, value);
71 }
James Hawkinsc6275582016-03-22 10:47:44 -070072 } else {
73 boot_event_store.AddBootEvent(event);
74 }
75}
76
James Hawkinsabd73e62016-01-19 15:10:38 -080077void PrintBootEvents() {
78 printf("Boot events:\n");
79 printf("------------\n");
80
81 BootEventRecordStore boot_event_store;
82 auto events = boot_event_store.GetAllBootEvents();
83 for (auto i = events.cbegin(); i != events.cend(); ++i) {
84 printf("%s\t%d\n", i->first.c_str(), i->second);
85 }
86}
87
88void ShowHelp(const char *cmd) {
89 fprintf(stderr, "Usage: %s [options]\n", cmd);
90 fprintf(stderr,
91 "options include:\n"
Yongqin Liu78b2b942017-07-07 13:26:49 +080092 " -h, --help Show this help\n"
93 " -l, --log Log all metrics to logstorage\n"
94 " -p, --print Dump the boot event records to the console\n"
95 " -r, --record Record the timestamp of a named boot event\n"
96 " --value Optional value to associate with the boot event\n"
97 " --record_boot_complete Record metrics related to the time for the device boot\n"
98 " --record_boot_reason Record the reason why the device booted\n"
James Hawkins53684ea2016-02-23 16:18:19 -080099 " --record_time_since_factory_reset Record the time since the device was reset\n");
James Hawkinsabd73e62016-01-19 15:10:38 -0800100}
101
102// Constructs a readable, printable string from the givencommand line
103// arguments.
104std::string GetCommandLine(int argc, char **argv) {
105 std::string cmd;
106 for (int i = 0; i < argc; ++i) {
107 cmd += argv[i];
108 cmd += " ";
109 }
110
111 return cmd;
112}
113
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800114// Convenience wrapper over the property API that returns an
115// std::string.
116std::string GetProperty(const char* key) {
117 std::vector<char> temp(PROPERTY_VALUE_MAX);
118 const int len = property_get(key, &temp[0], nullptr);
119 if (len < 0) {
120 return "";
121 }
122 return std::string(&temp[0], len);
123}
124
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700125void SetProperty(const char* key, const std::string& val) {
126 property_set(key, val.c_str());
127}
128
129void SetProperty(const char* key, const char* val) {
130 property_set(key, val);
131}
132
James Hawkins6f74c0b2016-02-12 15:49:16 -0800133constexpr int32_t kUnknownBootReason = 1;
134
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800135// A mapping from boot reason string, as read from the ro.boot.bootreason
136// system property, to a unique integer ID. Viewers of log data dashboards for
137// the boot_reason metric may refer to this mapping to discern the histogram
138// values.
James Hawkins6f74c0b2016-02-12 15:49:16 -0800139const std::map<std::string, int32_t> kBootReasonMap = {
140 {"unknown", kUnknownBootReason},
141 {"normal", 2},
142 {"recovery", 3},
143 {"reboot", 4},
144 {"PowerKey", 5},
145 {"hard_reset", 6},
146 {"kernel_panic", 7},
147 {"rpm_err", 8},
148 {"hw_reset", 9},
149 {"tz_err", 10},
150 {"adsp_err", 11},
151 {"modem_err", 12},
152 {"mba_err", 13},
153 {"Watchdog", 14},
154 {"Panic", 15},
155 {"power_key", 16},
156 {"power_on", 17},
157 {"Reboot", 18},
158 {"rtc", 19},
159 {"edl", 20},
James Hawkins45ead352016-03-08 16:42:07 -0800160 {"oem_pon1", 21},
161 {"oem_powerkey", 22},
162 {"oem_unknown_reset", 23},
163 {"srto: HWWDT reset SC", 24},
164 {"srto: HWWDT reset platform", 25},
165 {"srto: bootloader", 26},
166 {"srto: kernel panic", 27},
167 {"srto: kernel watchdog reset", 28},
168 {"srto: normal", 29},
169 {"srto: reboot", 30},
170 {"srto: reboot-bootloader", 31},
171 {"srto: security watchdog reset", 32},
172 {"srto: wakesrc", 33},
173 {"srto: watchdog", 34},
174 {"srto:1-1", 35},
175 {"srto:omap_hsmm", 36},
176 {"srto:phy0", 37},
177 {"srto:rtc0", 38},
178 {"srto:touchpad", 39},
179 {"watchdog", 40},
180 {"watchdogr", 41},
181 {"wdog_bark", 42},
182 {"wdog_bite", 43},
183 {"wdog_reset", 44},
James Hawkins8d7f63d2017-07-25 12:55:12 -0700184 {"shutdown,", 45}, // Trailing comma is intentional.
185 {"shutdown,userrequested", 46},
186 {"reboot,bootloader", 47},
187 {"reboot,cold", 48},
188 {"reboot,recovery", 49},
189 {"thermal_shutdown", 50},
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700190 {"s3_wakeup", 51},
191 {"kernel_panic,sysrq", 52},
192 {"kernel_panic,NULL", 53},
193 {"kernel_panic,BUG", 54},
194 {"bootloader", 55},
195 {"cold", 56},
196 {"hard", 57},
197 {"warm", 58},
198 {"recovery", 59},
199 {"thermal-shutdown", 60},
200 {"shutdown,thermal", 61},
201 {"shutdown,battery", 62},
202 {"reboot,ota", 63},
203 {"reboot,factory_reset", 64},
204 {"reboot,", 65},
Mark Salyzyn277eca12017-09-11 15:22:57 -0700205 {"reboot,shell", 66},
206 {"reboot,adb", 67},
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800207};
208
209// Converts a string value representing the reason the system booted to an
210// integer representation. This is necessary for logging the boot_reason metric
211// via Tron, which does not accept non-integer buckets in histograms.
212int32_t BootReasonStrToEnum(const std::string& boot_reason) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800213 auto mapping = kBootReasonMap.find(boot_reason);
214 if (mapping != kBootReasonMap.end()) {
215 return mapping->second;
216 }
217
218 LOG(INFO) << "Unknown boot reason: " << boot_reason;
219 return kUnknownBootReason;
220}
221
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700222// Canonical list of supported primary reboot reasons.
223const std::vector<const std::string> knownReasons = {
224 // kernel
225 "watchdog",
226 "kernel_panic",
227 // strong
228 "recovery", // Should not happen from ro.boot.bootreason
229 "bootloader", // Should not happen from ro.boot.bootreason
230 // blunt
231 "cold",
232 "hard",
233 "warm",
234 "shutdown", // Can not happen from ro.boot.bootreason
235 "reboot", // Default catch-all for anything unknown
236};
237
238// Returns true if the supplied reason prefix is considered detailed enough.
239bool isStrongRebootReason(const std::string& r) {
240 for (auto &s : knownReasons) {
241 if (s == "cold") break;
242 // Prefix defined as terminated by a nul or comma (,).
243 if (android::base::StartsWith(r, s.c_str()) &&
244 ((r.length() == s.length()) || (r[s.length()] == ','))) {
245 return true;
246 }
247 }
248 return false;
249}
250
251// Returns true if the supplied reason prefix is associated with the kernel.
252bool isKernelRebootReason(const std::string& r) {
253 for (auto &s : knownReasons) {
254 if (s == "recovery") break;
255 // Prefix defined as terminated by a nul or comma (,).
256 if (android::base::StartsWith(r, s.c_str()) &&
257 ((r.length() == s.length()) || (r[s.length()] == ','))) {
258 return true;
259 }
260 }
261 return false;
262}
263
264// Returns true if the supplied reason prefix is considered known.
265bool isKnownRebootReason(const std::string& r) {
266 for (auto &s : knownReasons) {
267 // Prefix defined as terminated by a nul or comma (,).
268 if (android::base::StartsWith(r, s.c_str()) &&
269 ((r.length() == s.length()) || (r[s.length()] == ','))) {
270 return true;
271 }
272 }
273 return false;
274}
275
276// If the reboot reason should be improved, report true if is too blunt.
277bool isBluntRebootReason(const std::string& r) {
278 if (isStrongRebootReason(r)) return false;
279
280 if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail
281
282 size_t pos = 0;
283 while ((pos = r.find(',', pos)) != std::string::npos) {
284 ++pos;
285 std::string next(r.substr(pos));
286 if (next.length() == 0) break;
287 if (next[0] == ',') continue;
288 if (!isKnownRebootReason(next)) return false; // Unknown subreason is good.
289 if (isStrongRebootReason(next)) return false; // eg: reboot,reboot
290 }
291 return true;
292}
293
294// std::transform Helper callback functions:
295// Converts a string value representing the reason the system booted to a
296// string complying with Android system standard reason.
297char tounderline(char c) { return ::isblank(c) ? '_' : c; }
298char toprintable(char c) { return ::isprint(c) ? c : '?'; }
299
300const char system_reboot_reason_property[] = "sys.boot.reason";
301const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
302const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
303
304// Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
305std::string BootReasonStrToReason(const std::string& boot_reason) {
306 std::string ret(GetProperty(system_reboot_reason_property));
307 std::string reason(boot_reason);
308 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
309 if (reason == ret) ret = "";
310
311 // Cleanup boot_reason regarding acceptable character set
312 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
313 std::transform(reason.begin(), reason.end(), reason.begin(), tounderline);
314 std::transform(reason.begin(), reason.end(), reason.begin(), toprintable);
315
316 // Is the current system boot reason sys.boot.reason valid?
317 if (!isKnownRebootReason(ret)) ret = "";
318
319 if (ret == "") {
320 // Is the bootloader boot reason ro.boot.bootreason known?
321 std::vector<std::string> words(android::base::Split(reason, ",_-"));
322 for (auto &s : knownReasons) {
323 std::string blunt;
324 for (auto &r : words) {
325 if (r == s) {
326 if (isBluntRebootReason(s)) {
327 blunt = s;
328 } else {
329 ret = s;
330 break;
331 }
332 }
333 }
334 if (ret == "") ret = blunt;
335 if (ret != "") break;
336 }
337 }
338
339 if (ret == "") {
340 // A series of checks to take some officially unsupported reasons
341 // reported by the bootloader and find some logical and canonical
342 // sense. In an ideal world, we would require those bootloaders
343 // to behave and follow our standards.
344 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
345 {"watchdog", "wdog"},
346 {"cold,powerkey", "powerkey"},
347 {"kernel_panic", "panic"},
348 {"shutdown,thermal", "thermal"},
349 {"warm,s3_wakeup", "s3_wakeup"},
350 {"hard,hw_reset", "hw_reset"},
351 {"bootloader", ""},
352 };
353
354 // Either the primary or alias is found _somewhere_ in the reason string.
355 for (auto &s : aliasReasons) {
356 if (reason.find(s.first) != std::string::npos) {
357 ret = s.first;
358 break;
359 }
360 if (s.second.size() && (reason.find(s.second) != std::string::npos)) {
361 ret = s.first;
362 break;
363 }
364 }
365 }
366
367 // If watchdog is the reason, see if there is a security angle?
368 if (ret == "watchdog") {
369 if (reason.find("sec") != std::string::npos) {
370 ret += ",security";
371 }
372 }
373
374 // Check the other reason resources if the reason is still blunt.
375 if (isBluntRebootReason(ret)) {
376 // Check to see if last klog has some refinement hints.
377 std::string content;
378 if (!android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0",
379 &content)) {
380 android::base::ReadFileToString("/sys/fs/pstore/console-ramoops",
381 &content);
382 }
383
384 // The toybox reboot command used directly (unlikely)? But also
385 // catches init's response to the Android's more controlled reboot command.
386 if (content.rfind("reboot: Power down") != std::string::npos) {
387 ret = "shutdown"; // Still too blunt, but more accurate.
388 // ToDo: init should record the shutdown reason to kernel messages ala:
389 // init: shutdown system with command 'last_reboot_reason'
390 // so that if pstore has persistence we can get some details
391 // that could be missing in last_reboot_reason_property.
392 }
393
394 static const char cmd[] = "reboot: Restarting system with command '";
395 size_t pos = content.rfind(cmd);
396 if (pos != std::string::npos) {
397 pos += strlen(cmd);
398 std::string subReason(content.substr(pos));
399 pos = subReason.find('\'');
400 if (pos != std::string::npos) subReason.erase(pos);
401 if (subReason != "") { // Will not land "reboot" as that is too blunt.
402 if (isKernelRebootReason(subReason)) {
403 ret = "reboot," + subReason; // User space can't talk kernel reasons.
404 } else {
405 ret = subReason;
406 }
407 }
408 }
409
410 // Check for kernel panics, but allowed to override reboot command.
411 if (content.rfind("sysrq: SysRq : Trigger a crash") != std::string::npos) {
412 // Can not happen, except on userdebug, during testing/debugging.
413 ret = "kernel_panic,sysrq";
414 } else if (content.rfind(
415 "Unable to handle kernel NULL pointer dereference at virtual address")
416 != std::string::npos) {
417 ret = "kernel_panic,NULL";
418 } else if (content.rfind("Kernel BUG at ") != std::string::npos) {
419 ret = "kernel_panic,BUG";
420 } else if ((content.rfind("Power held for ") != std::string::npos) ||
421 (content.rfind("charger: [") != std::string::npos)) {
422 ret = "cold";
423 }
424
425 // The following battery test should migrate to a default system health HAL
426
427 // Let us not worry if the reboot command was issued, for the cases of
428 // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard.
429 // Same for bootloader and ro.boot.bootreasons of this set, but a dead
430 // battery could conceivably lead to these, so worthy of override.
431 if (isBluntRebootReason(ret)) {
432 // Heuristic to determine if shutdown possibly because of a dead battery?
433 // Really a hail-mary pass to find it in last klog content ...
434 static const int battery_dead_threshold = 2; // percent
435 static const char battery[] = "healthd: battery l=";
436 pos = content.rfind(battery); // last one
437 if (pos != std::string::npos) {
438 int level = atoi(content.substr(pos + strlen(battery)).c_str());
439 LOG(INFO) << "Battery level at shutdown " << level << "%";
440 if (level <= battery_dead_threshold) {
441 ret = "shutdown,battery";
442 }
443 } else { // Most likely
444 // Content buffer no longer will have console data. Beware if more
445 // checks added below, that depend on parsing console content.
446 content = "";
447
448 LOG(DEBUG) << "Can not find last low battery in last console messages";
449 android_logcat_context ctx = create_android_logcat();
450 FILE *fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d");
451 if (fp != nullptr) {
452 android::base::ReadFdToString(fileno(fp), &content);
453 }
454 android_logcat_pclose(&ctx, fp);
455 android_logcat_destroy(&ctx);
456 static const char logcat_battery[] = "W/healthd ( 0): battery l=";
457 const char* match = logcat_battery;
458
459 if (content == "") {
460 // Service logd.klog not running, go to smaller buffer in the kernel.
461 int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0);
462 if (rc > 0) {
463 ssize_t len = rc + 1024; // 1K Margin should it grow between calls.
464 std::unique_ptr<char[]> buf(new char[len]);
465 rc = klogctl(KLOG_READ_ALL, buf.get(), len);
466 if (rc < len) {
467 len = rc + 1;
468 }
469 buf[--len] = '\0';
470 content = buf.get();
471 }
472 match = battery;
473 }
474
475 pos = content.find(match); // The first one it finds.
476 if (pos != std::string::npos) {
477 pos += strlen(match);
478 int level = atoi(content.substr(pos).c_str());
479 LOG(INFO) << "Battery level at startup " << level << "%";
480 if (level <= battery_dead_threshold) {
481 ret = "shutdown,battery";
482 }
483 } else {
484 LOG(DEBUG) << "Can not find first battery level in dmesg or logcat";
485 }
486 }
487 }
488
489 // Is there a controlled shutdown hint in last_reboot_reason_property?
490 if (isBluntRebootReason(ret)) {
491 // Content buffer no longer will have console data. Beware if more
492 // checks added below, that depend on parsing console content.
493 content = GetProperty(last_reboot_reason_property);
494
495 // String is either "reboot,<reason>" or "shutdown,<reason>".
496 // We will set if default reasons, only override with detail if thermal.
497 if (!isBluntRebootReason(content)) {
498 // Ok, we want it, let's squash it if secondReason is known.
499 pos = content.find(',');
500 if (pos != std::string::npos) {
501 ++pos;
502 std::string secondReason(content.substr(pos));
503 ret = isKnownRebootReason(secondReason) ? secondReason : content;
504 } else {
505 ret = content;
506 }
507 }
508 }
509
510 // Other System Health HAL reasons?
511
512 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
513 // possibly offer hardware-specific clues from the PMIC.
514 }
515
516 // If unknown left over from above, make it "reboot,<boot_reason>"
517 if (ret == "") {
518 ret = "reboot";
519 if (android::base::StartsWith(reason, "reboot")) {
520 reason = reason.substr(strlen("reboot"));
521 while (reason[0] == ',') {
522 reason = reason.substr(1);
523 }
524 }
525 if (reason != "") {
526 ret += ",";
527 ret += reason;
528 }
529 }
530
531 LOG(INFO) << "Canonical boot reason: " << ret;
532 if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) {
533 // Rewrite as it must be old news, kernel reasons trump user space.
534 SetProperty(last_reboot_reason_property, ret);
535 }
536 return ret;
537}
538
James Hawkinsb9cf7712016-04-08 15:32:19 -0700539// Returns the appropriate metric key prefix for the boot_complete metric such
540// that boot metrics after a system update are labeled as ota_boot_complete;
541// otherwise, they are labeled as boot_complete. This method encapsulates the
542// bookkeeping required to track when a system update has occurred by storing
543// the UTC timestamp of the system build date and comparing against the current
544// system build date.
545std::string CalculateBootCompletePrefix() {
546 static const std::string kBuildDateKey = "build_date";
547 std::string boot_complete_prefix = "boot_complete";
548
549 std::string build_date_str = GetProperty("ro.build.date.utc");
James Hawkins4dded612016-07-28 11:50:23 -0700550 int32_t build_date;
Elliott Hughesda46b392016-10-11 17:09:00 -0700551 if (!android::base::ParseInt(build_date_str, &build_date)) {
James Hawkins4dded612016-07-28 11:50:23 -0700552 return std::string();
553 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700554
555 BootEventRecordStore boot_event_store;
556 BootEventRecordStore::BootEventRecord record;
James Hawkins0bc4ad42017-05-30 15:03:15 -0700557 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
558 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
559 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700560 LOG(INFO) << "Canonical boot reason: " << "reboot,factory_reset";
561 SetProperty(system_reboot_reason_property, "reboot,factory_reset");
562 if (GetProperty(bootloader_reboot_reason_property) == "") {
563 SetProperty(bootloader_reboot_reason_property, "reboot,factory_reset");
564 }
James Hawkins0bc4ad42017-05-30 15:03:15 -0700565 } else if (build_date != record.second) {
James Hawkinsb9cf7712016-04-08 15:32:19 -0700566 boot_complete_prefix = "ota_" + boot_complete_prefix;
567 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700568 LOG(INFO) << "Canonical boot reason: " << "reboot,ota";
569 SetProperty(system_reboot_reason_property, "reboot,ota");
570 if (GetProperty(bootloader_reboot_reason_property) == "") {
571 SetProperty(bootloader_reboot_reason_property, "reboot,ota");
572 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700573 }
574
575 return boot_complete_prefix;
576}
577
James Hawkinsef0a0902017-01-06 14:38:23 -0800578// Records the value of a given ro.boottime.init property in milliseconds.
579void RecordInitBootTimeProp(
580 BootEventRecordStore* boot_event_store, const char* property) {
581 std::string value = GetProperty(property);
582
James Hawkins27c05222017-01-26 11:55:44 -0800583 int32_t time_in_ms;
584 if (android::base::ParseInt(value, &time_in_ms)) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800585 boot_event_store->AddBootEventWithValue(property, time_in_ms);
586 }
587}
588
James Hawkins1bfcaec2017-05-19 14:27:27 -0700589// A map from bootloader timing stage to the time that stage took during boot.
590typedef std::map<std::string, int32_t> BootloaderTimingMap;
591
592// Returns a mapping from bootloader stage names to the time those stages
593// took to boot.
594const BootloaderTimingMap GetBootLoaderTimings() {
595 BootloaderTimingMap timings;
596
597 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
598 // where timeN is in milliseconds.
James Hawkinsbe46fd12017-02-02 16:21:25 -0800599 std::string value = GetProperty("ro.boot.boottime");
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800600 if (value.empty()) {
601 // ro.boot.boottime is not reported on all devices.
James Hawkins1bfcaec2017-05-19 14:27:27 -0700602 return BootloaderTimingMap();
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800603 }
James Hawkinsbe46fd12017-02-02 16:21:25 -0800604
605 auto stages = android::base::Split(value, ",");
James Hawkins1bfcaec2017-05-19 14:27:27 -0700606 for (const auto& stageTiming : stages) {
James Hawkinsbe46fd12017-02-02 16:21:25 -0800607 // |stageTiming| is of the form 'stage:time'.
608 auto stageTimingValues = android::base::Split(stageTiming, ":");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700609 DCHECK_EQ(2U, stageTimingValues.size());
James Hawkinsbe46fd12017-02-02 16:21:25 -0800610
611 std::string stageName = stageTimingValues[0];
612 int32_t time_ms;
613 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700614 timings[stageName] = time_ms;
James Hawkinsbe46fd12017-02-02 16:21:25 -0800615 }
616 }
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800617
James Hawkins1bfcaec2017-05-19 14:27:27 -0700618 return timings;
619}
620
621// Parses and records the set of bootloader stages and associated boot times
622// from the ro.boot.boottime system property.
623void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
624 const BootloaderTimingMap& bootloader_timings) {
625 int32_t total_time = 0;
626 for (const auto& timing : bootloader_timings) {
627 total_time += timing.second;
628 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
629 }
630
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800631 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
James Hawkinsbe46fd12017-02-02 16:21:25 -0800632}
633
James Hawkins1bfcaec2017-05-19 14:27:27 -0700634// Records the closest estimation to the absolute device boot time, i.e.,
635// from power on to boot_complete, including bootloader times.
636void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
637 const BootloaderTimingMap& bootloader_timings,
638 std::chrono::milliseconds uptime) {
639 int32_t bootloader_time_ms = 0;
640
641 for (const auto& timing : bootloader_timings) {
642 if (timing.first.compare("SW") != 0) {
643 bootloader_time_ms += timing.second;
644 }
645 }
646
647 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
648 auto absolute_total =
649 std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime);
650 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count());
651}
652
James Hawkinsc08e9962016-03-11 14:59:50 -0800653// Records several metrics related to the time it takes to boot the device,
654// including disambiguating boot time on encrypted or non-encrypted devices.
655void RecordBootComplete() {
656 BootEventRecordStore boot_event_store;
James Hawkinsb9cf7712016-04-08 15:32:19 -0700657 BootEventRecordStore::BootEventRecord record;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700658
James Hawkins1bfcaec2017-05-19 14:27:27 -0700659 auto time_since_epoch = android::base::boot_clock::now().time_since_epoch();
660 auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700661 time_t current_time_utc = time(nullptr);
662
663 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
664 time_t last_boot_time_utc = record.second;
665 time_t time_since_last_boot = difftime(current_time_utc,
666 last_boot_time_utc);
667 boot_event_store.AddBootEventWithValue("time_since_last_boot",
668 time_since_last_boot);
669 }
670
671 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
James Hawkinsc08e9962016-03-11 14:59:50 -0800672
James Hawkinsb9cf7712016-04-08 15:32:19 -0700673 // The boot_complete metric has two variants: boot_complete and
674 // ota_boot_complete. The latter signifies that the device is booting after
675 // a system update.
676 std::string boot_complete_prefix = CalculateBootCompletePrefix();
James Hawkins4dded612016-07-28 11:50:23 -0700677 if (boot_complete_prefix.empty()) {
678 // The system is hosed because the build date property could not be read.
679 return;
680 }
James Hawkinsc08e9962016-03-11 14:59:50 -0800681
682 // post_decrypt_time_elapsed is only logged on encrypted devices.
683 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
684 // Log the amount of time elapsed until the device is decrypted, which
685 // includes the variable amount of time the user takes to enter the
686 // decryption password.
James Hawkinse78ea772017-03-24 11:43:02 -0700687 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800688
689 // Subtract the decryption time to normalize the boot cycle timing.
James Hawkinse78ea772017-03-24 11:43:02 -0700690 std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second);
James Hawkinsb9cf7712016-04-08 15:32:19 -0700691 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
James Hawkinse78ea772017-03-24 11:43:02 -0700692 boot_complete.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800693 } else {
James Hawkinse78ea772017-03-24 11:43:02 -0700694 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption",
695 uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800696 }
697
698 // Record the total time from device startup to boot complete, regardless of
699 // encryption state.
James Hawkinse78ea772017-03-24 11:43:02 -0700700 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count());
James Hawkinsef0a0902017-01-06 14:38:23 -0800701
702 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
703 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
704 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
James Hawkinsbe46fd12017-02-02 16:21:25 -0800705
James Hawkins1bfcaec2017-05-19 14:27:27 -0700706 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
707 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
708
709 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch);
710 RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms);
James Hawkinsc08e9962016-03-11 14:59:50 -0800711}
712
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800713// Records the boot_reason metric by querying the ro.boot.bootreason system
714// property.
715void RecordBootReason() {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700716 const std::string reason(GetProperty(bootloader_reboot_reason_property));
James Hawkins5240f202017-09-15 16:01:57 -0700717 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
718 android::metricslogger::FIELD_PLATFORM_REASON,
719 reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700720
721 // Log the raw bootloader_boot_reason property value.
722 int32_t boot_reason = BootReasonStrToEnum(reason);
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800723 BootEventRecordStore boot_event_store;
724 boot_event_store.AddBootEventWithValue("boot_reason", boot_reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700725
726 // Log the scrubbed system_boot_reason.
727 const std::string system_reason(BootReasonStrToReason(reason));
728 int32_t system_boot_reason = BootReasonStrToEnum(system_reason);
729 boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason);
730
731 // Record the scrubbed system_boot_reason to the property
732 SetProperty(system_reboot_reason_property, system_reason);
733 if (reason == "") {
734 SetProperty(bootloader_reboot_reason_property, system_reason);
735 }
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800736}
737
James Hawkins500d7152016-02-16 15:05:54 -0800738// Records two metrics related to the user resetting a device: the time at
739// which the device is reset, and the time since the user last reset the
740// device. The former is only set once per-factory reset.
741void RecordFactoryReset() {
742 BootEventRecordStore boot_event_store;
743 BootEventRecordStore::BootEventRecord record;
744
745 time_t current_time_utc = time(nullptr);
746
James Hawkins0660b302016-03-08 16:18:15 -0800747 if (current_time_utc < 0) {
748 // UMA does not display negative values in buckets, so convert to positive.
James Hawkins9aec9262017-01-31 11:42:24 -0800749 android::metricslogger::LogHistogram(
James Hawkinsfff95ba2016-03-29 16:13:49 -0700750 "factory_reset_current_time_failure", std::abs(current_time_utc));
751
James Hawkins9aec9262017-01-31 11:42:24 -0800752 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700753 // is losing records somehow.
754 boot_event_store.AddBootEventWithValue(
755 "factory_reset_current_time_failure", std::abs(current_time_utc));
James Hawkins0660b302016-03-08 16:18:15 -0800756 return;
757 } else {
James Hawkins9aec9262017-01-31 11:42:24 -0800758 android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700759
James Hawkins9aec9262017-01-31 11:42:24 -0800760 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700761 // is losing records somehow.
762 boot_event_store.AddBootEventWithValue(
763 "factory_reset_current_time", current_time_utc);
James Hawkins0660b302016-03-08 16:18:15 -0800764 }
765
James Hawkins500d7152016-02-16 15:05:54 -0800766 // The factory_reset boot event does not exist after the device is reset, so
767 // use this signal to mark the time of the factory reset.
768 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
769 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
James Hawkins3bf9b142016-03-03 14:50:24 -0800770
771 // Don't log the time_since_factory_reset until some time has elapsed.
772 // The data is not meaningful yet and skews the histogram buckets.
James Hawkins500d7152016-02-16 15:05:54 -0800773 return;
774 }
775
776 // Calculate and record the difference in time between now and the
777 // factory_reset time.
778 time_t factory_reset_utc = record.second;
James Hawkins9aec9262017-01-31 11:42:24 -0800779 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700780
James Hawkins9aec9262017-01-31 11:42:24 -0800781 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700782 // is losing records somehow.
783 boot_event_store.AddBootEventWithValue(
784 "factory_reset_record_value", factory_reset_utc);
785
James Hawkins500d7152016-02-16 15:05:54 -0800786 time_t time_since_factory_reset = difftime(current_time_utc,
787 factory_reset_utc);
788 boot_event_store.AddBootEventWithValue("time_since_factory_reset",
789 time_since_factory_reset);
790}
791
James Hawkinsabd73e62016-01-19 15:10:38 -0800792} // namespace
793
794int main(int argc, char **argv) {
795 android::base::InitLogging(argv);
796
797 const std::string cmd_line = GetCommandLine(argc, argv);
798 LOG(INFO) << "Service started: " << cmd_line;
799
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800800 int option_index = 0;
James Hawkinsc6275582016-03-22 10:47:44 -0700801 static const char value_str[] = "value";
James Hawkinsc08e9962016-03-11 14:59:50 -0800802 static const char boot_complete_str[] = "record_boot_complete";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800803 static const char boot_reason_str[] = "record_boot_reason";
James Hawkins53684ea2016-02-23 16:18:19 -0800804 static const char factory_reset_str[] = "record_time_since_factory_reset";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800805 static const struct option long_options[] = {
806 { "help", no_argument, NULL, 'h' },
807 { "log", no_argument, NULL, 'l' },
808 { "print", no_argument, NULL, 'p' },
809 { "record", required_argument, NULL, 'r' },
James Hawkinsc6275582016-03-22 10:47:44 -0700810 { value_str, required_argument, NULL, 0 },
James Hawkinsc08e9962016-03-11 14:59:50 -0800811 { boot_complete_str, no_argument, NULL, 0 },
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800812 { boot_reason_str, no_argument, NULL, 0 },
James Hawkins500d7152016-02-16 15:05:54 -0800813 { factory_reset_str, no_argument, NULL, 0 },
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800814 { NULL, 0, NULL, 0 }
815 };
816
James Hawkinsc6275582016-03-22 10:47:44 -0700817 std::string boot_event;
818 std::string value;
James Hawkinsabd73e62016-01-19 15:10:38 -0800819 int opt = 0;
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800820 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800821 switch (opt) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800822 // This case handles long options which have no single-character mapping.
823 case 0: {
824 const std::string option_name = long_options[option_index].name;
James Hawkinsc6275582016-03-22 10:47:44 -0700825 if (option_name == value_str) {
826 // |optarg| is an external variable set by getopt representing
827 // the option argument.
828 value = optarg;
829 } else if (option_name == boot_complete_str) {
James Hawkinsc08e9962016-03-11 14:59:50 -0800830 RecordBootComplete();
831 } else if (option_name == boot_reason_str) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800832 RecordBootReason();
James Hawkins500d7152016-02-16 15:05:54 -0800833 } else if (option_name == factory_reset_str) {
834 RecordFactoryReset();
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800835 } else {
836 LOG(ERROR) << "Invalid option: " << option_name;
837 }
838 break;
839 }
840
James Hawkinsabd73e62016-01-19 15:10:38 -0800841 case 'h': {
842 ShowHelp(argv[0]);
843 break;
844 }
845
846 case 'l': {
847 LogBootEvents();
848 break;
849 }
850
851 case 'p': {
852 PrintBootEvents();
853 break;
854 }
855
856 case 'r': {
857 // |optarg| is an external variable set by getopt representing
858 // the option argument.
James Hawkinsc6275582016-03-22 10:47:44 -0700859 boot_event = optarg;
James Hawkinsabd73e62016-01-19 15:10:38 -0800860 break;
861 }
862
863 default: {
864 DCHECK_EQ(opt, '?');
865
866 // |optopt| is an external variable set by getopt representing
867 // the value of the invalid option.
868 LOG(ERROR) << "Invalid option: " << optopt;
869 ShowHelp(argv[0]);
870 return EXIT_FAILURE;
871 }
872 }
873 }
874
James Hawkinsc6275582016-03-22 10:47:44 -0700875 if (!boot_event.empty()) {
876 RecordBootEventFromCommandLine(boot_event, value);
877 }
878
James Hawkinsabd73e62016-01-19 15:10:38 -0800879 return 0;
880}