blob: 418c711652e1d97acbe2f67fa8a815cf25de6462 [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},
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800205};
206
207// Converts a string value representing the reason the system booted to an
208// integer representation. This is necessary for logging the boot_reason metric
209// via Tron, which does not accept non-integer buckets in histograms.
210int32_t BootReasonStrToEnum(const std::string& boot_reason) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800211 auto mapping = kBootReasonMap.find(boot_reason);
212 if (mapping != kBootReasonMap.end()) {
213 return mapping->second;
214 }
215
216 LOG(INFO) << "Unknown boot reason: " << boot_reason;
217 return kUnknownBootReason;
218}
219
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700220// Canonical list of supported primary reboot reasons.
221const std::vector<const std::string> knownReasons = {
222 // kernel
223 "watchdog",
224 "kernel_panic",
225 // strong
226 "recovery", // Should not happen from ro.boot.bootreason
227 "bootloader", // Should not happen from ro.boot.bootreason
228 // blunt
229 "cold",
230 "hard",
231 "warm",
232 "shutdown", // Can not happen from ro.boot.bootreason
233 "reboot", // Default catch-all for anything unknown
234};
235
236// Returns true if the supplied reason prefix is considered detailed enough.
237bool isStrongRebootReason(const std::string& r) {
238 for (auto &s : knownReasons) {
239 if (s == "cold") break;
240 // Prefix defined as terminated by a nul or comma (,).
241 if (android::base::StartsWith(r, s.c_str()) &&
242 ((r.length() == s.length()) || (r[s.length()] == ','))) {
243 return true;
244 }
245 }
246 return false;
247}
248
249// Returns true if the supplied reason prefix is associated with the kernel.
250bool isKernelRebootReason(const std::string& r) {
251 for (auto &s : knownReasons) {
252 if (s == "recovery") break;
253 // Prefix defined as terminated by a nul or comma (,).
254 if (android::base::StartsWith(r, s.c_str()) &&
255 ((r.length() == s.length()) || (r[s.length()] == ','))) {
256 return true;
257 }
258 }
259 return false;
260}
261
262// Returns true if the supplied reason prefix is considered known.
263bool isKnownRebootReason(const std::string& r) {
264 for (auto &s : knownReasons) {
265 // Prefix defined as terminated by a nul or comma (,).
266 if (android::base::StartsWith(r, s.c_str()) &&
267 ((r.length() == s.length()) || (r[s.length()] == ','))) {
268 return true;
269 }
270 }
271 return false;
272}
273
274// If the reboot reason should be improved, report true if is too blunt.
275bool isBluntRebootReason(const std::string& r) {
276 if (isStrongRebootReason(r)) return false;
277
278 if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail
279
280 size_t pos = 0;
281 while ((pos = r.find(',', pos)) != std::string::npos) {
282 ++pos;
283 std::string next(r.substr(pos));
284 if (next.length() == 0) break;
285 if (next[0] == ',') continue;
286 if (!isKnownRebootReason(next)) return false; // Unknown subreason is good.
287 if (isStrongRebootReason(next)) return false; // eg: reboot,reboot
288 }
289 return true;
290}
291
292// std::transform Helper callback functions:
293// Converts a string value representing the reason the system booted to a
294// string complying with Android system standard reason.
295char tounderline(char c) { return ::isblank(c) ? '_' : c; }
296char toprintable(char c) { return ::isprint(c) ? c : '?'; }
297
298const char system_reboot_reason_property[] = "sys.boot.reason";
299const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
300const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
301
302// Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
303std::string BootReasonStrToReason(const std::string& boot_reason) {
304 std::string ret(GetProperty(system_reboot_reason_property));
305 std::string reason(boot_reason);
306 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
307 if (reason == ret) ret = "";
308
309 // Cleanup boot_reason regarding acceptable character set
310 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
311 std::transform(reason.begin(), reason.end(), reason.begin(), tounderline);
312 std::transform(reason.begin(), reason.end(), reason.begin(), toprintable);
313
314 // Is the current system boot reason sys.boot.reason valid?
315 if (!isKnownRebootReason(ret)) ret = "";
316
317 if (ret == "") {
318 // Is the bootloader boot reason ro.boot.bootreason known?
319 std::vector<std::string> words(android::base::Split(reason, ",_-"));
320 for (auto &s : knownReasons) {
321 std::string blunt;
322 for (auto &r : words) {
323 if (r == s) {
324 if (isBluntRebootReason(s)) {
325 blunt = s;
326 } else {
327 ret = s;
328 break;
329 }
330 }
331 }
332 if (ret == "") ret = blunt;
333 if (ret != "") break;
334 }
335 }
336
337 if (ret == "") {
338 // A series of checks to take some officially unsupported reasons
339 // reported by the bootloader and find some logical and canonical
340 // sense. In an ideal world, we would require those bootloaders
341 // to behave and follow our standards.
342 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
343 {"watchdog", "wdog"},
344 {"cold,powerkey", "powerkey"},
345 {"kernel_panic", "panic"},
346 {"shutdown,thermal", "thermal"},
347 {"warm,s3_wakeup", "s3_wakeup"},
348 {"hard,hw_reset", "hw_reset"},
349 {"bootloader", ""},
350 };
351
352 // Either the primary or alias is found _somewhere_ in the reason string.
353 for (auto &s : aliasReasons) {
354 if (reason.find(s.first) != std::string::npos) {
355 ret = s.first;
356 break;
357 }
358 if (s.second.size() && (reason.find(s.second) != std::string::npos)) {
359 ret = s.first;
360 break;
361 }
362 }
363 }
364
365 // If watchdog is the reason, see if there is a security angle?
366 if (ret == "watchdog") {
367 if (reason.find("sec") != std::string::npos) {
368 ret += ",security";
369 }
370 }
371
372 // Check the other reason resources if the reason is still blunt.
373 if (isBluntRebootReason(ret)) {
374 // Check to see if last klog has some refinement hints.
375 std::string content;
376 if (!android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0",
377 &content)) {
378 android::base::ReadFileToString("/sys/fs/pstore/console-ramoops",
379 &content);
380 }
381
382 // The toybox reboot command used directly (unlikely)? But also
383 // catches init's response to the Android's more controlled reboot command.
384 if (content.rfind("reboot: Power down") != std::string::npos) {
385 ret = "shutdown"; // Still too blunt, but more accurate.
386 // ToDo: init should record the shutdown reason to kernel messages ala:
387 // init: shutdown system with command 'last_reboot_reason'
388 // so that if pstore has persistence we can get some details
389 // that could be missing in last_reboot_reason_property.
390 }
391
392 static const char cmd[] = "reboot: Restarting system with command '";
393 size_t pos = content.rfind(cmd);
394 if (pos != std::string::npos) {
395 pos += strlen(cmd);
396 std::string subReason(content.substr(pos));
397 pos = subReason.find('\'');
398 if (pos != std::string::npos) subReason.erase(pos);
399 if (subReason != "") { // Will not land "reboot" as that is too blunt.
400 if (isKernelRebootReason(subReason)) {
401 ret = "reboot," + subReason; // User space can't talk kernel reasons.
402 } else {
403 ret = subReason;
404 }
405 }
406 }
407
408 // Check for kernel panics, but allowed to override reboot command.
409 if (content.rfind("sysrq: SysRq : Trigger a crash") != std::string::npos) {
410 // Can not happen, except on userdebug, during testing/debugging.
411 ret = "kernel_panic,sysrq";
412 } else if (content.rfind(
413 "Unable to handle kernel NULL pointer dereference at virtual address")
414 != std::string::npos) {
415 ret = "kernel_panic,NULL";
416 } else if (content.rfind("Kernel BUG at ") != std::string::npos) {
417 ret = "kernel_panic,BUG";
418 } else if ((content.rfind("Power held for ") != std::string::npos) ||
419 (content.rfind("charger: [") != std::string::npos)) {
420 ret = "cold";
421 }
422
423 // The following battery test should migrate to a default system health HAL
424
425 // Let us not worry if the reboot command was issued, for the cases of
426 // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard.
427 // Same for bootloader and ro.boot.bootreasons of this set, but a dead
428 // battery could conceivably lead to these, so worthy of override.
429 if (isBluntRebootReason(ret)) {
430 // Heuristic to determine if shutdown possibly because of a dead battery?
431 // Really a hail-mary pass to find it in last klog content ...
432 static const int battery_dead_threshold = 2; // percent
433 static const char battery[] = "healthd: battery l=";
434 pos = content.rfind(battery); // last one
435 if (pos != std::string::npos) {
436 int level = atoi(content.substr(pos + strlen(battery)).c_str());
437 LOG(INFO) << "Battery level at shutdown " << level << "%";
438 if (level <= battery_dead_threshold) {
439 ret = "shutdown,battery";
440 }
441 } else { // Most likely
442 // Content buffer no longer will have console data. Beware if more
443 // checks added below, that depend on parsing console content.
444 content = "";
445
446 LOG(DEBUG) << "Can not find last low battery in last console messages";
447 android_logcat_context ctx = create_android_logcat();
448 FILE *fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d");
449 if (fp != nullptr) {
450 android::base::ReadFdToString(fileno(fp), &content);
451 }
452 android_logcat_pclose(&ctx, fp);
453 android_logcat_destroy(&ctx);
454 static const char logcat_battery[] = "W/healthd ( 0): battery l=";
455 const char* match = logcat_battery;
456
457 if (content == "") {
458 // Service logd.klog not running, go to smaller buffer in the kernel.
459 int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0);
460 if (rc > 0) {
461 ssize_t len = rc + 1024; // 1K Margin should it grow between calls.
462 std::unique_ptr<char[]> buf(new char[len]);
463 rc = klogctl(KLOG_READ_ALL, buf.get(), len);
464 if (rc < len) {
465 len = rc + 1;
466 }
467 buf[--len] = '\0';
468 content = buf.get();
469 }
470 match = battery;
471 }
472
473 pos = content.find(match); // The first one it finds.
474 if (pos != std::string::npos) {
475 pos += strlen(match);
476 int level = atoi(content.substr(pos).c_str());
477 LOG(INFO) << "Battery level at startup " << level << "%";
478 if (level <= battery_dead_threshold) {
479 ret = "shutdown,battery";
480 }
481 } else {
482 LOG(DEBUG) << "Can not find first battery level in dmesg or logcat";
483 }
484 }
485 }
486
487 // Is there a controlled shutdown hint in last_reboot_reason_property?
488 if (isBluntRebootReason(ret)) {
489 // Content buffer no longer will have console data. Beware if more
490 // checks added below, that depend on parsing console content.
491 content = GetProperty(last_reboot_reason_property);
492
493 // String is either "reboot,<reason>" or "shutdown,<reason>".
494 // We will set if default reasons, only override with detail if thermal.
495 if (!isBluntRebootReason(content)) {
496 // Ok, we want it, let's squash it if secondReason is known.
497 pos = content.find(',');
498 if (pos != std::string::npos) {
499 ++pos;
500 std::string secondReason(content.substr(pos));
501 ret = isKnownRebootReason(secondReason) ? secondReason : content;
502 } else {
503 ret = content;
504 }
505 }
506 }
507
508 // Other System Health HAL reasons?
509
510 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
511 // possibly offer hardware-specific clues from the PMIC.
512 }
513
514 // If unknown left over from above, make it "reboot,<boot_reason>"
515 if (ret == "") {
516 ret = "reboot";
517 if (android::base::StartsWith(reason, "reboot")) {
518 reason = reason.substr(strlen("reboot"));
519 while (reason[0] == ',') {
520 reason = reason.substr(1);
521 }
522 }
523 if (reason != "") {
524 ret += ",";
525 ret += reason;
526 }
527 }
528
529 LOG(INFO) << "Canonical boot reason: " << ret;
530 if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) {
531 // Rewrite as it must be old news, kernel reasons trump user space.
532 SetProperty(last_reboot_reason_property, ret);
533 }
534 return ret;
535}
536
James Hawkinsb9cf7712016-04-08 15:32:19 -0700537// Returns the appropriate metric key prefix for the boot_complete metric such
538// that boot metrics after a system update are labeled as ota_boot_complete;
539// otherwise, they are labeled as boot_complete. This method encapsulates the
540// bookkeeping required to track when a system update has occurred by storing
541// the UTC timestamp of the system build date and comparing against the current
542// system build date.
543std::string CalculateBootCompletePrefix() {
544 static const std::string kBuildDateKey = "build_date";
545 std::string boot_complete_prefix = "boot_complete";
546
547 std::string build_date_str = GetProperty("ro.build.date.utc");
James Hawkins4dded612016-07-28 11:50:23 -0700548 int32_t build_date;
Elliott Hughesda46b392016-10-11 17:09:00 -0700549 if (!android::base::ParseInt(build_date_str, &build_date)) {
James Hawkins4dded612016-07-28 11:50:23 -0700550 return std::string();
551 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700552
553 BootEventRecordStore boot_event_store;
554 BootEventRecordStore::BootEventRecord record;
James Hawkins0bc4ad42017-05-30 15:03:15 -0700555 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
556 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
557 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700558 LOG(INFO) << "Canonical boot reason: " << "reboot,factory_reset";
559 SetProperty(system_reboot_reason_property, "reboot,factory_reset");
560 if (GetProperty(bootloader_reboot_reason_property) == "") {
561 SetProperty(bootloader_reboot_reason_property, "reboot,factory_reset");
562 }
James Hawkins0bc4ad42017-05-30 15:03:15 -0700563 } else if (build_date != record.second) {
James Hawkinsb9cf7712016-04-08 15:32:19 -0700564 boot_complete_prefix = "ota_" + boot_complete_prefix;
565 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700566 LOG(INFO) << "Canonical boot reason: " << "reboot,ota";
567 SetProperty(system_reboot_reason_property, "reboot,ota");
568 if (GetProperty(bootloader_reboot_reason_property) == "") {
569 SetProperty(bootloader_reboot_reason_property, "reboot,ota");
570 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700571 }
572
573 return boot_complete_prefix;
574}
575
James Hawkinsef0a0902017-01-06 14:38:23 -0800576// Records the value of a given ro.boottime.init property in milliseconds.
577void RecordInitBootTimeProp(
578 BootEventRecordStore* boot_event_store, const char* property) {
579 std::string value = GetProperty(property);
580
James Hawkins27c05222017-01-26 11:55:44 -0800581 int32_t time_in_ms;
582 if (android::base::ParseInt(value, &time_in_ms)) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800583 boot_event_store->AddBootEventWithValue(property, time_in_ms);
584 }
585}
586
James Hawkins1bfcaec2017-05-19 14:27:27 -0700587// A map from bootloader timing stage to the time that stage took during boot.
588typedef std::map<std::string, int32_t> BootloaderTimingMap;
589
590// Returns a mapping from bootloader stage names to the time those stages
591// took to boot.
592const BootloaderTimingMap GetBootLoaderTimings() {
593 BootloaderTimingMap timings;
594
595 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
596 // where timeN is in milliseconds.
James Hawkinsbe46fd12017-02-02 16:21:25 -0800597 std::string value = GetProperty("ro.boot.boottime");
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800598 if (value.empty()) {
599 // ro.boot.boottime is not reported on all devices.
James Hawkins1bfcaec2017-05-19 14:27:27 -0700600 return BootloaderTimingMap();
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800601 }
James Hawkinsbe46fd12017-02-02 16:21:25 -0800602
603 auto stages = android::base::Split(value, ",");
James Hawkins1bfcaec2017-05-19 14:27:27 -0700604 for (const auto& stageTiming : stages) {
James Hawkinsbe46fd12017-02-02 16:21:25 -0800605 // |stageTiming| is of the form 'stage:time'.
606 auto stageTimingValues = android::base::Split(stageTiming, ":");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700607 DCHECK_EQ(2U, stageTimingValues.size());
James Hawkinsbe46fd12017-02-02 16:21:25 -0800608
609 std::string stageName = stageTimingValues[0];
610 int32_t time_ms;
611 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700612 timings[stageName] = time_ms;
James Hawkinsbe46fd12017-02-02 16:21:25 -0800613 }
614 }
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800615
James Hawkins1bfcaec2017-05-19 14:27:27 -0700616 return timings;
617}
618
619// Parses and records the set of bootloader stages and associated boot times
620// from the ro.boot.boottime system property.
621void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
622 const BootloaderTimingMap& bootloader_timings) {
623 int32_t total_time = 0;
624 for (const auto& timing : bootloader_timings) {
625 total_time += timing.second;
626 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
627 }
628
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800629 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
James Hawkinsbe46fd12017-02-02 16:21:25 -0800630}
631
James Hawkins1bfcaec2017-05-19 14:27:27 -0700632// Records the closest estimation to the absolute device boot time, i.e.,
633// from power on to boot_complete, including bootloader times.
634void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
635 const BootloaderTimingMap& bootloader_timings,
636 std::chrono::milliseconds uptime) {
637 int32_t bootloader_time_ms = 0;
638
639 for (const auto& timing : bootloader_timings) {
640 if (timing.first.compare("SW") != 0) {
641 bootloader_time_ms += timing.second;
642 }
643 }
644
645 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
646 auto absolute_total =
647 std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime);
648 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count());
649}
650
James Hawkinsc08e9962016-03-11 14:59:50 -0800651// Records several metrics related to the time it takes to boot the device,
652// including disambiguating boot time on encrypted or non-encrypted devices.
653void RecordBootComplete() {
654 BootEventRecordStore boot_event_store;
James Hawkinsb9cf7712016-04-08 15:32:19 -0700655 BootEventRecordStore::BootEventRecord record;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700656
James Hawkins1bfcaec2017-05-19 14:27:27 -0700657 auto time_since_epoch = android::base::boot_clock::now().time_since_epoch();
658 auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700659 time_t current_time_utc = time(nullptr);
660
661 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
662 time_t last_boot_time_utc = record.second;
663 time_t time_since_last_boot = difftime(current_time_utc,
664 last_boot_time_utc);
665 boot_event_store.AddBootEventWithValue("time_since_last_boot",
666 time_since_last_boot);
667 }
668
669 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
James Hawkinsc08e9962016-03-11 14:59:50 -0800670
James Hawkinsb9cf7712016-04-08 15:32:19 -0700671 // The boot_complete metric has two variants: boot_complete and
672 // ota_boot_complete. The latter signifies that the device is booting after
673 // a system update.
674 std::string boot_complete_prefix = CalculateBootCompletePrefix();
James Hawkins4dded612016-07-28 11:50:23 -0700675 if (boot_complete_prefix.empty()) {
676 // The system is hosed because the build date property could not be read.
677 return;
678 }
James Hawkinsc08e9962016-03-11 14:59:50 -0800679
680 // post_decrypt_time_elapsed is only logged on encrypted devices.
681 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
682 // Log the amount of time elapsed until the device is decrypted, which
683 // includes the variable amount of time the user takes to enter the
684 // decryption password.
James Hawkinse78ea772017-03-24 11:43:02 -0700685 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800686
687 // Subtract the decryption time to normalize the boot cycle timing.
James Hawkinse78ea772017-03-24 11:43:02 -0700688 std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second);
James Hawkinsb9cf7712016-04-08 15:32:19 -0700689 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
James Hawkinse78ea772017-03-24 11:43:02 -0700690 boot_complete.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800691 } else {
James Hawkinse78ea772017-03-24 11:43:02 -0700692 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption",
693 uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800694 }
695
696 // Record the total time from device startup to boot complete, regardless of
697 // encryption state.
James Hawkinse78ea772017-03-24 11:43:02 -0700698 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count());
James Hawkinsef0a0902017-01-06 14:38:23 -0800699
700 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
701 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
702 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
James Hawkinsbe46fd12017-02-02 16:21:25 -0800703
James Hawkins1bfcaec2017-05-19 14:27:27 -0700704 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
705 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
706
707 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch);
708 RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms);
James Hawkinsc08e9962016-03-11 14:59:50 -0800709}
710
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800711// Records the boot_reason metric by querying the ro.boot.bootreason system
712// property.
713void RecordBootReason() {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700714 const std::string reason(GetProperty(bootloader_reboot_reason_property));
715
716 // Log the raw bootloader_boot_reason property value.
717 int32_t boot_reason = BootReasonStrToEnum(reason);
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800718 BootEventRecordStore boot_event_store;
719 boot_event_store.AddBootEventWithValue("boot_reason", boot_reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700720
721 // Log the scrubbed system_boot_reason.
722 const std::string system_reason(BootReasonStrToReason(reason));
723 int32_t system_boot_reason = BootReasonStrToEnum(system_reason);
724 boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason);
725
726 // Record the scrubbed system_boot_reason to the property
727 SetProperty(system_reboot_reason_property, system_reason);
728 if (reason == "") {
729 SetProperty(bootloader_reboot_reason_property, system_reason);
730 }
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800731}
732
James Hawkins500d7152016-02-16 15:05:54 -0800733// Records two metrics related to the user resetting a device: the time at
734// which the device is reset, and the time since the user last reset the
735// device. The former is only set once per-factory reset.
736void RecordFactoryReset() {
737 BootEventRecordStore boot_event_store;
738 BootEventRecordStore::BootEventRecord record;
739
740 time_t current_time_utc = time(nullptr);
741
James Hawkins0660b302016-03-08 16:18:15 -0800742 if (current_time_utc < 0) {
743 // UMA does not display negative values in buckets, so convert to positive.
James Hawkins9aec9262017-01-31 11:42:24 -0800744 android::metricslogger::LogHistogram(
James Hawkinsfff95ba2016-03-29 16:13:49 -0700745 "factory_reset_current_time_failure", std::abs(current_time_utc));
746
James Hawkins9aec9262017-01-31 11:42:24 -0800747 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700748 // is losing records somehow.
749 boot_event_store.AddBootEventWithValue(
750 "factory_reset_current_time_failure", std::abs(current_time_utc));
James Hawkins0660b302016-03-08 16:18:15 -0800751 return;
752 } else {
James Hawkins9aec9262017-01-31 11:42:24 -0800753 android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700754
James Hawkins9aec9262017-01-31 11:42:24 -0800755 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700756 // is losing records somehow.
757 boot_event_store.AddBootEventWithValue(
758 "factory_reset_current_time", current_time_utc);
James Hawkins0660b302016-03-08 16:18:15 -0800759 }
760
James Hawkins500d7152016-02-16 15:05:54 -0800761 // The factory_reset boot event does not exist after the device is reset, so
762 // use this signal to mark the time of the factory reset.
763 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
764 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
James Hawkins3bf9b142016-03-03 14:50:24 -0800765
766 // Don't log the time_since_factory_reset until some time has elapsed.
767 // The data is not meaningful yet and skews the histogram buckets.
James Hawkins500d7152016-02-16 15:05:54 -0800768 return;
769 }
770
771 // Calculate and record the difference in time between now and the
772 // factory_reset time.
773 time_t factory_reset_utc = record.second;
James Hawkins9aec9262017-01-31 11:42:24 -0800774 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700775
James Hawkins9aec9262017-01-31 11:42:24 -0800776 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700777 // is losing records somehow.
778 boot_event_store.AddBootEventWithValue(
779 "factory_reset_record_value", factory_reset_utc);
780
James Hawkins500d7152016-02-16 15:05:54 -0800781 time_t time_since_factory_reset = difftime(current_time_utc,
782 factory_reset_utc);
783 boot_event_store.AddBootEventWithValue("time_since_factory_reset",
784 time_since_factory_reset);
785}
786
James Hawkinsabd73e62016-01-19 15:10:38 -0800787} // namespace
788
789int main(int argc, char **argv) {
790 android::base::InitLogging(argv);
791
792 const std::string cmd_line = GetCommandLine(argc, argv);
793 LOG(INFO) << "Service started: " << cmd_line;
794
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800795 int option_index = 0;
James Hawkinsc6275582016-03-22 10:47:44 -0700796 static const char value_str[] = "value";
James Hawkinsc08e9962016-03-11 14:59:50 -0800797 static const char boot_complete_str[] = "record_boot_complete";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800798 static const char boot_reason_str[] = "record_boot_reason";
James Hawkins53684ea2016-02-23 16:18:19 -0800799 static const char factory_reset_str[] = "record_time_since_factory_reset";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800800 static const struct option long_options[] = {
801 { "help", no_argument, NULL, 'h' },
802 { "log", no_argument, NULL, 'l' },
803 { "print", no_argument, NULL, 'p' },
804 { "record", required_argument, NULL, 'r' },
James Hawkinsc6275582016-03-22 10:47:44 -0700805 { value_str, required_argument, NULL, 0 },
James Hawkinsc08e9962016-03-11 14:59:50 -0800806 { boot_complete_str, no_argument, NULL, 0 },
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800807 { boot_reason_str, no_argument, NULL, 0 },
James Hawkins500d7152016-02-16 15:05:54 -0800808 { factory_reset_str, no_argument, NULL, 0 },
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800809 { NULL, 0, NULL, 0 }
810 };
811
James Hawkinsc6275582016-03-22 10:47:44 -0700812 std::string boot_event;
813 std::string value;
James Hawkinsabd73e62016-01-19 15:10:38 -0800814 int opt = 0;
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800815 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800816 switch (opt) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800817 // This case handles long options which have no single-character mapping.
818 case 0: {
819 const std::string option_name = long_options[option_index].name;
James Hawkinsc6275582016-03-22 10:47:44 -0700820 if (option_name == value_str) {
821 // |optarg| is an external variable set by getopt representing
822 // the option argument.
823 value = optarg;
824 } else if (option_name == boot_complete_str) {
James Hawkinsc08e9962016-03-11 14:59:50 -0800825 RecordBootComplete();
826 } else if (option_name == boot_reason_str) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800827 RecordBootReason();
James Hawkins500d7152016-02-16 15:05:54 -0800828 } else if (option_name == factory_reset_str) {
829 RecordFactoryReset();
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800830 } else {
831 LOG(ERROR) << "Invalid option: " << option_name;
832 }
833 break;
834 }
835
James Hawkinsabd73e62016-01-19 15:10:38 -0800836 case 'h': {
837 ShowHelp(argv[0]);
838 break;
839 }
840
841 case 'l': {
842 LogBootEvents();
843 break;
844 }
845
846 case 'p': {
847 PrintBootEvents();
848 break;
849 }
850
851 case 'r': {
852 // |optarg| is an external variable set by getopt representing
853 // the option argument.
James Hawkinsc6275582016-03-22 10:47:44 -0700854 boot_event = optarg;
James Hawkinsabd73e62016-01-19 15:10:38 -0800855 break;
856 }
857
858 default: {
859 DCHECK_EQ(opt, '?');
860
861 // |optopt| is an external variable set by getopt representing
862 // the value of the invalid option.
863 LOG(ERROR) << "Invalid option: " << optopt;
864 ShowHelp(argv[0]);
865 return EXIT_FAILURE;
866 }
867 }
868 }
869
James Hawkinsc6275582016-03-22 10:47:44 -0700870 if (!boot_event.empty()) {
871 RecordBootEventFromCommandLine(boot_event, value);
872 }
873
James Hawkinsabd73e62016-01-19 15:10:38 -0800874 return 0;
875}