blob: d4c45a2480beb5ef3f5425708c6f59f72c3b5c82 [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
Mark Salyzyn64610892017-09-18 10:41:14 -0700294bool readPstoreConsole(std::string& console) {
295 if (android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0", &console)) {
296 return true;
297 }
298 return android::base::ReadFileToString("/sys/fs/pstore/console-ramoops", &console);
299}
300
301bool addKernelPanicSubReason(const std::string& console, std::string& ret) {
302 // Check for kernel panic types to refine information
303 if (console.rfind("SysRq : Trigger a crash") != std::string::npos) {
304 // Can not happen, except on userdebug, during testing/debugging.
305 ret = "kernel_panic,sysrq";
306 return true;
307 }
308 if (console.rfind("Unable to handle kernel NULL pointer dereference at virtual address") !=
309 std::string::npos) {
310 ret = "kernel_panic,NULL";
311 return true;
312 }
313 if (console.rfind("Kernel BUG at ") != std::string::npos) {
314 ret = "kernel_panic,BUG";
315 return true;
316 }
317 return false;
318}
319
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700320// std::transform Helper callback functions:
321// Converts a string value representing the reason the system booted to a
322// string complying with Android system standard reason.
323char tounderline(char c) { return ::isblank(c) ? '_' : c; }
324char toprintable(char c) { return ::isprint(c) ? c : '?'; }
325
326const char system_reboot_reason_property[] = "sys.boot.reason";
327const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
328const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
329
330// Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
331std::string BootReasonStrToReason(const std::string& boot_reason) {
332 std::string ret(GetProperty(system_reboot_reason_property));
333 std::string reason(boot_reason);
334 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
335 if (reason == ret) ret = "";
336
337 // Cleanup boot_reason regarding acceptable character set
338 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
339 std::transform(reason.begin(), reason.end(), reason.begin(), tounderline);
340 std::transform(reason.begin(), reason.end(), reason.begin(), toprintable);
341
342 // Is the current system boot reason sys.boot.reason valid?
343 if (!isKnownRebootReason(ret)) ret = "";
344
345 if (ret == "") {
346 // Is the bootloader boot reason ro.boot.bootreason known?
347 std::vector<std::string> words(android::base::Split(reason, ",_-"));
348 for (auto &s : knownReasons) {
349 std::string blunt;
350 for (auto &r : words) {
351 if (r == s) {
352 if (isBluntRebootReason(s)) {
353 blunt = s;
354 } else {
355 ret = s;
356 break;
357 }
358 }
359 }
360 if (ret == "") ret = blunt;
361 if (ret != "") break;
362 }
363 }
364
365 if (ret == "") {
366 // A series of checks to take some officially unsupported reasons
367 // reported by the bootloader and find some logical and canonical
368 // sense. In an ideal world, we would require those bootloaders
369 // to behave and follow our standards.
370 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
371 {"watchdog", "wdog"},
372 {"cold,powerkey", "powerkey"},
373 {"kernel_panic", "panic"},
374 {"shutdown,thermal", "thermal"},
375 {"warm,s3_wakeup", "s3_wakeup"},
376 {"hard,hw_reset", "hw_reset"},
377 {"bootloader", ""},
378 };
379
380 // Either the primary or alias is found _somewhere_ in the reason string.
381 for (auto &s : aliasReasons) {
382 if (reason.find(s.first) != std::string::npos) {
383 ret = s.first;
384 break;
385 }
386 if (s.second.size() && (reason.find(s.second) != std::string::npos)) {
387 ret = s.first;
388 break;
389 }
390 }
391 }
392
393 // If watchdog is the reason, see if there is a security angle?
394 if (ret == "watchdog") {
395 if (reason.find("sec") != std::string::npos) {
396 ret += ",security";
397 }
398 }
399
Mark Salyzyn64610892017-09-18 10:41:14 -0700400 if (ret == "kernel_panic") {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700401 // Check to see if last klog has some refinement hints.
402 std::string content;
Mark Salyzyn64610892017-09-18 10:41:14 -0700403 if (readPstoreConsole(content)) {
404 addKernelPanicSubReason(content, ret);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700405 }
Mark Salyzyn64610892017-09-18 10:41:14 -0700406 } else if (isBluntRebootReason(ret)) {
407 // Check the other available reason resources if the reason is still blunt.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700408
Mark Salyzyn64610892017-09-18 10:41:14 -0700409 // Check to see if last klog has some refinement hints.
410 std::string content;
411 if (readPstoreConsole(content)) {
412 // The toybox reboot command used directly (unlikely)? But also
413 // catches init's response to Android's more controlled reboot command.
414 if (content.rfind("reboot: Power down") != std::string::npos) {
415 ret = "shutdown"; // Still too blunt, but more accurate.
416 // ToDo: init should record the shutdown reason to kernel messages ala:
417 // init: shutdown system with command 'last_reboot_reason'
418 // so that if pstore has persistence we can get some details
419 // that could be missing in last_reboot_reason_property.
420 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700421
Mark Salyzyn64610892017-09-18 10:41:14 -0700422 static const char cmd[] = "reboot: Restarting system with command '";
423 size_t pos = content.rfind(cmd);
424 if (pos != std::string::npos) {
425 pos += strlen(cmd);
426 std::string subReason(content.substr(pos));
427 pos = subReason.find('\'');
428 if (pos != std::string::npos) subReason.erase(pos);
429 if (subReason != "") { // Will not land "reboot" as that is too blunt.
430 if (isKernelRebootReason(subReason)) {
431 ret = "reboot," + subReason; // User space can't talk kernel reasons.
432 } else {
433 ret = subReason;
434 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700435 }
436 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700437
Mark Salyzyn64610892017-09-18 10:41:14 -0700438 // Check for kernel panics, allowed to override reboot command.
439 if (!addKernelPanicSubReason(content, ret) &&
440 // check for long-press power down
441 ((content.rfind("Power held for ") != std::string::npos) ||
442 (content.rfind("charger: [") != std::string::npos))) {
443 ret = "cold";
444 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700445 }
446
447 // The following battery test should migrate to a default system health HAL
448
449 // Let us not worry if the reboot command was issued, for the cases of
450 // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard.
451 // Same for bootloader and ro.boot.bootreasons of this set, but a dead
452 // battery could conceivably lead to these, so worthy of override.
453 if (isBluntRebootReason(ret)) {
454 // Heuristic to determine if shutdown possibly because of a dead battery?
455 // Really a hail-mary pass to find it in last klog content ...
456 static const int battery_dead_threshold = 2; // percent
457 static const char battery[] = "healthd: battery l=";
Mark Salyzyn64610892017-09-18 10:41:14 -0700458 size_t pos = content.rfind(battery); // last one
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700459 if (pos != std::string::npos) {
460 int level = atoi(content.substr(pos + strlen(battery)).c_str());
461 LOG(INFO) << "Battery level at shutdown " << level << "%";
462 if (level <= battery_dead_threshold) {
463 ret = "shutdown,battery";
464 }
465 } else { // Most likely
466 // Content buffer no longer will have console data. Beware if more
467 // checks added below, that depend on parsing console content.
468 content = "";
469
470 LOG(DEBUG) << "Can not find last low battery in last console messages";
471 android_logcat_context ctx = create_android_logcat();
472 FILE *fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d");
473 if (fp != nullptr) {
474 android::base::ReadFdToString(fileno(fp), &content);
475 }
476 android_logcat_pclose(&ctx, fp);
477 android_logcat_destroy(&ctx);
478 static const char logcat_battery[] = "W/healthd ( 0): battery l=";
479 const char* match = logcat_battery;
480
481 if (content == "") {
482 // Service logd.klog not running, go to smaller buffer in the kernel.
483 int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0);
484 if (rc > 0) {
485 ssize_t len = rc + 1024; // 1K Margin should it grow between calls.
486 std::unique_ptr<char[]> buf(new char[len]);
487 rc = klogctl(KLOG_READ_ALL, buf.get(), len);
488 if (rc < len) {
489 len = rc + 1;
490 }
491 buf[--len] = '\0';
492 content = buf.get();
493 }
494 match = battery;
495 }
496
497 pos = content.find(match); // The first one it finds.
498 if (pos != std::string::npos) {
499 pos += strlen(match);
500 int level = atoi(content.substr(pos).c_str());
501 LOG(INFO) << "Battery level at startup " << level << "%";
502 if (level <= battery_dead_threshold) {
503 ret = "shutdown,battery";
504 }
505 } else {
506 LOG(DEBUG) << "Can not find first battery level in dmesg or logcat";
507 }
508 }
509 }
510
511 // Is there a controlled shutdown hint in last_reboot_reason_property?
512 if (isBluntRebootReason(ret)) {
513 // Content buffer no longer will have console data. Beware if more
514 // checks added below, that depend on parsing console content.
515 content = GetProperty(last_reboot_reason_property);
516
517 // String is either "reboot,<reason>" or "shutdown,<reason>".
518 // We will set if default reasons, only override with detail if thermal.
Mark Salyzyn08b02562017-09-18 10:07:07 -0700519 if ((android::base::StartsWith(content, ret.c_str()) && (content[ret.length()] == ',')) ||
520 !isBluntRebootReason(content)) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700521 // Ok, we want it, let's squash it if secondReason is known.
Mark Salyzyn64610892017-09-18 10:41:14 -0700522 size_t pos = content.find(',');
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700523 if (pos != std::string::npos) {
524 ++pos;
525 std::string secondReason(content.substr(pos));
526 ret = isKnownRebootReason(secondReason) ? secondReason : content;
527 } else {
528 ret = content;
529 }
530 }
531 }
532
533 // Other System Health HAL reasons?
534
535 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
536 // possibly offer hardware-specific clues from the PMIC.
537 }
538
539 // If unknown left over from above, make it "reboot,<boot_reason>"
540 if (ret == "") {
541 ret = "reboot";
542 if (android::base::StartsWith(reason, "reboot")) {
543 reason = reason.substr(strlen("reboot"));
544 while (reason[0] == ',') {
545 reason = reason.substr(1);
546 }
547 }
548 if (reason != "") {
549 ret += ",";
550 ret += reason;
551 }
552 }
553
554 LOG(INFO) << "Canonical boot reason: " << ret;
555 if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) {
556 // Rewrite as it must be old news, kernel reasons trump user space.
557 SetProperty(last_reboot_reason_property, ret);
558 }
559 return ret;
560}
561
James Hawkinsb9cf7712016-04-08 15:32:19 -0700562// Returns the appropriate metric key prefix for the boot_complete metric such
563// that boot metrics after a system update are labeled as ota_boot_complete;
564// otherwise, they are labeled as boot_complete. This method encapsulates the
565// bookkeeping required to track when a system update has occurred by storing
566// the UTC timestamp of the system build date and comparing against the current
567// system build date.
568std::string CalculateBootCompletePrefix() {
569 static const std::string kBuildDateKey = "build_date";
570 std::string boot_complete_prefix = "boot_complete";
571
572 std::string build_date_str = GetProperty("ro.build.date.utc");
James Hawkins4dded612016-07-28 11:50:23 -0700573 int32_t build_date;
Elliott Hughesda46b392016-10-11 17:09:00 -0700574 if (!android::base::ParseInt(build_date_str, &build_date)) {
James Hawkins4dded612016-07-28 11:50:23 -0700575 return std::string();
576 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700577
578 BootEventRecordStore boot_event_store;
579 BootEventRecordStore::BootEventRecord record;
James Hawkins0bc4ad42017-05-30 15:03:15 -0700580 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
581 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
582 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700583 LOG(INFO) << "Canonical boot reason: " << "reboot,factory_reset";
584 SetProperty(system_reboot_reason_property, "reboot,factory_reset");
585 if (GetProperty(bootloader_reboot_reason_property) == "") {
586 SetProperty(bootloader_reboot_reason_property, "reboot,factory_reset");
587 }
James Hawkins0bc4ad42017-05-30 15:03:15 -0700588 } else if (build_date != record.second) {
James Hawkinsb9cf7712016-04-08 15:32:19 -0700589 boot_complete_prefix = "ota_" + boot_complete_prefix;
590 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700591 LOG(INFO) << "Canonical boot reason: " << "reboot,ota";
592 SetProperty(system_reboot_reason_property, "reboot,ota");
593 if (GetProperty(bootloader_reboot_reason_property) == "") {
594 SetProperty(bootloader_reboot_reason_property, "reboot,ota");
595 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700596 }
597
598 return boot_complete_prefix;
599}
600
James Hawkinsef0a0902017-01-06 14:38:23 -0800601// Records the value of a given ro.boottime.init property in milliseconds.
602void RecordInitBootTimeProp(
603 BootEventRecordStore* boot_event_store, const char* property) {
604 std::string value = GetProperty(property);
605
James Hawkins27c05222017-01-26 11:55:44 -0800606 int32_t time_in_ms;
607 if (android::base::ParseInt(value, &time_in_ms)) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800608 boot_event_store->AddBootEventWithValue(property, time_in_ms);
609 }
610}
611
James Hawkins1bfcaec2017-05-19 14:27:27 -0700612// A map from bootloader timing stage to the time that stage took during boot.
613typedef std::map<std::string, int32_t> BootloaderTimingMap;
614
615// Returns a mapping from bootloader stage names to the time those stages
616// took to boot.
617const BootloaderTimingMap GetBootLoaderTimings() {
618 BootloaderTimingMap timings;
619
620 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
621 // where timeN is in milliseconds.
James Hawkinsbe46fd12017-02-02 16:21:25 -0800622 std::string value = GetProperty("ro.boot.boottime");
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800623 if (value.empty()) {
624 // ro.boot.boottime is not reported on all devices.
James Hawkins1bfcaec2017-05-19 14:27:27 -0700625 return BootloaderTimingMap();
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800626 }
James Hawkinsbe46fd12017-02-02 16:21:25 -0800627
628 auto stages = android::base::Split(value, ",");
James Hawkins1bfcaec2017-05-19 14:27:27 -0700629 for (const auto& stageTiming : stages) {
James Hawkinsbe46fd12017-02-02 16:21:25 -0800630 // |stageTiming| is of the form 'stage:time'.
631 auto stageTimingValues = android::base::Split(stageTiming, ":");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700632 DCHECK_EQ(2U, stageTimingValues.size());
James Hawkinsbe46fd12017-02-02 16:21:25 -0800633
634 std::string stageName = stageTimingValues[0];
635 int32_t time_ms;
636 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700637 timings[stageName] = time_ms;
James Hawkinsbe46fd12017-02-02 16:21:25 -0800638 }
639 }
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800640
James Hawkins1bfcaec2017-05-19 14:27:27 -0700641 return timings;
642}
643
644// Parses and records the set of bootloader stages and associated boot times
645// from the ro.boot.boottime system property.
646void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
647 const BootloaderTimingMap& bootloader_timings) {
648 int32_t total_time = 0;
649 for (const auto& timing : bootloader_timings) {
650 total_time += timing.second;
651 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
652 }
653
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800654 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
James Hawkinsbe46fd12017-02-02 16:21:25 -0800655}
656
James Hawkins1bfcaec2017-05-19 14:27:27 -0700657// Records the closest estimation to the absolute device boot time, i.e.,
658// from power on to boot_complete, including bootloader times.
659void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
660 const BootloaderTimingMap& bootloader_timings,
661 std::chrono::milliseconds uptime) {
662 int32_t bootloader_time_ms = 0;
663
664 for (const auto& timing : bootloader_timings) {
665 if (timing.first.compare("SW") != 0) {
666 bootloader_time_ms += timing.second;
667 }
668 }
669
670 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
671 auto absolute_total =
672 std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime);
673 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count());
674}
675
James Hawkinsc08e9962016-03-11 14:59:50 -0800676// Records several metrics related to the time it takes to boot the device,
677// including disambiguating boot time on encrypted or non-encrypted devices.
678void RecordBootComplete() {
679 BootEventRecordStore boot_event_store;
James Hawkinsb9cf7712016-04-08 15:32:19 -0700680 BootEventRecordStore::BootEventRecord record;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700681
James Hawkins1bfcaec2017-05-19 14:27:27 -0700682 auto time_since_epoch = android::base::boot_clock::now().time_since_epoch();
683 auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700684 time_t current_time_utc = time(nullptr);
685
686 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
687 time_t last_boot_time_utc = record.second;
688 time_t time_since_last_boot = difftime(current_time_utc,
689 last_boot_time_utc);
690 boot_event_store.AddBootEventWithValue("time_since_last_boot",
691 time_since_last_boot);
692 }
693
694 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
James Hawkinsc08e9962016-03-11 14:59:50 -0800695
James Hawkinsb9cf7712016-04-08 15:32:19 -0700696 // The boot_complete metric has two variants: boot_complete and
697 // ota_boot_complete. The latter signifies that the device is booting after
698 // a system update.
699 std::string boot_complete_prefix = CalculateBootCompletePrefix();
James Hawkins4dded612016-07-28 11:50:23 -0700700 if (boot_complete_prefix.empty()) {
701 // The system is hosed because the build date property could not be read.
702 return;
703 }
James Hawkinsc08e9962016-03-11 14:59:50 -0800704
705 // post_decrypt_time_elapsed is only logged on encrypted devices.
706 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
707 // Log the amount of time elapsed until the device is decrypted, which
708 // includes the variable amount of time the user takes to enter the
709 // decryption password.
James Hawkinse78ea772017-03-24 11:43:02 -0700710 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800711
712 // Subtract the decryption time to normalize the boot cycle timing.
James Hawkinse78ea772017-03-24 11:43:02 -0700713 std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second);
James Hawkinsb9cf7712016-04-08 15:32:19 -0700714 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
James Hawkinse78ea772017-03-24 11:43:02 -0700715 boot_complete.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800716 } else {
James Hawkinse78ea772017-03-24 11:43:02 -0700717 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption",
718 uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800719 }
720
721 // Record the total time from device startup to boot complete, regardless of
722 // encryption state.
James Hawkinse78ea772017-03-24 11:43:02 -0700723 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count());
James Hawkinsef0a0902017-01-06 14:38:23 -0800724
725 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
726 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
727 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
James Hawkinsbe46fd12017-02-02 16:21:25 -0800728
James Hawkins1bfcaec2017-05-19 14:27:27 -0700729 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
730 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
731
732 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch);
733 RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms);
James Hawkinsc08e9962016-03-11 14:59:50 -0800734}
735
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800736// Records the boot_reason metric by querying the ro.boot.bootreason system
737// property.
738void RecordBootReason() {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700739 const std::string reason(GetProperty(bootloader_reboot_reason_property));
James Hawkins5240f202017-09-15 16:01:57 -0700740 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
741 android::metricslogger::FIELD_PLATFORM_REASON,
742 reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700743
744 // Log the raw bootloader_boot_reason property value.
745 int32_t boot_reason = BootReasonStrToEnum(reason);
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800746 BootEventRecordStore boot_event_store;
747 boot_event_store.AddBootEventWithValue("boot_reason", boot_reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700748
749 // Log the scrubbed system_boot_reason.
750 const std::string system_reason(BootReasonStrToReason(reason));
751 int32_t system_boot_reason = BootReasonStrToEnum(system_reason);
752 boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason);
753
754 // Record the scrubbed system_boot_reason to the property
755 SetProperty(system_reboot_reason_property, system_reason);
756 if (reason == "") {
757 SetProperty(bootloader_reboot_reason_property, system_reason);
758 }
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800759}
760
James Hawkins500d7152016-02-16 15:05:54 -0800761// Records two metrics related to the user resetting a device: the time at
762// which the device is reset, and the time since the user last reset the
763// device. The former is only set once per-factory reset.
764void RecordFactoryReset() {
765 BootEventRecordStore boot_event_store;
766 BootEventRecordStore::BootEventRecord record;
767
768 time_t current_time_utc = time(nullptr);
769
James Hawkins0660b302016-03-08 16:18:15 -0800770 if (current_time_utc < 0) {
771 // UMA does not display negative values in buckets, so convert to positive.
James Hawkins9aec9262017-01-31 11:42:24 -0800772 android::metricslogger::LogHistogram(
James Hawkinsfff95ba2016-03-29 16:13:49 -0700773 "factory_reset_current_time_failure", std::abs(current_time_utc));
774
James Hawkins9aec9262017-01-31 11:42:24 -0800775 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700776 // is losing records somehow.
777 boot_event_store.AddBootEventWithValue(
778 "factory_reset_current_time_failure", std::abs(current_time_utc));
James Hawkins0660b302016-03-08 16:18:15 -0800779 return;
780 } else {
James Hawkins9aec9262017-01-31 11:42:24 -0800781 android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700782
James Hawkins9aec9262017-01-31 11:42:24 -0800783 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700784 // is losing records somehow.
785 boot_event_store.AddBootEventWithValue(
786 "factory_reset_current_time", current_time_utc);
James Hawkins0660b302016-03-08 16:18:15 -0800787 }
788
James Hawkins500d7152016-02-16 15:05:54 -0800789 // The factory_reset boot event does not exist after the device is reset, so
790 // use this signal to mark the time of the factory reset.
791 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
792 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
James Hawkins3bf9b142016-03-03 14:50:24 -0800793
794 // Don't log the time_since_factory_reset until some time has elapsed.
795 // The data is not meaningful yet and skews the histogram buckets.
James Hawkins500d7152016-02-16 15:05:54 -0800796 return;
797 }
798
799 // Calculate and record the difference in time between now and the
800 // factory_reset time.
801 time_t factory_reset_utc = record.second;
James Hawkins9aec9262017-01-31 11:42:24 -0800802 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700803
James Hawkins9aec9262017-01-31 11:42:24 -0800804 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700805 // is losing records somehow.
806 boot_event_store.AddBootEventWithValue(
807 "factory_reset_record_value", factory_reset_utc);
808
James Hawkins500d7152016-02-16 15:05:54 -0800809 time_t time_since_factory_reset = difftime(current_time_utc,
810 factory_reset_utc);
811 boot_event_store.AddBootEventWithValue("time_since_factory_reset",
812 time_since_factory_reset);
813}
814
James Hawkinsabd73e62016-01-19 15:10:38 -0800815} // namespace
816
817int main(int argc, char **argv) {
818 android::base::InitLogging(argv);
819
820 const std::string cmd_line = GetCommandLine(argc, argv);
821 LOG(INFO) << "Service started: " << cmd_line;
822
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800823 int option_index = 0;
James Hawkinsc6275582016-03-22 10:47:44 -0700824 static const char value_str[] = "value";
James Hawkinsc08e9962016-03-11 14:59:50 -0800825 static const char boot_complete_str[] = "record_boot_complete";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800826 static const char boot_reason_str[] = "record_boot_reason";
James Hawkins53684ea2016-02-23 16:18:19 -0800827 static const char factory_reset_str[] = "record_time_since_factory_reset";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800828 static const struct option long_options[] = {
829 { "help", no_argument, NULL, 'h' },
830 { "log", no_argument, NULL, 'l' },
831 { "print", no_argument, NULL, 'p' },
832 { "record", required_argument, NULL, 'r' },
James Hawkinsc6275582016-03-22 10:47:44 -0700833 { value_str, required_argument, NULL, 0 },
James Hawkinsc08e9962016-03-11 14:59:50 -0800834 { boot_complete_str, no_argument, NULL, 0 },
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800835 { boot_reason_str, no_argument, NULL, 0 },
James Hawkins500d7152016-02-16 15:05:54 -0800836 { factory_reset_str, no_argument, NULL, 0 },
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800837 { NULL, 0, NULL, 0 }
838 };
839
James Hawkinsc6275582016-03-22 10:47:44 -0700840 std::string boot_event;
841 std::string value;
James Hawkinsabd73e62016-01-19 15:10:38 -0800842 int opt = 0;
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800843 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800844 switch (opt) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800845 // This case handles long options which have no single-character mapping.
846 case 0: {
847 const std::string option_name = long_options[option_index].name;
James Hawkinsc6275582016-03-22 10:47:44 -0700848 if (option_name == value_str) {
849 // |optarg| is an external variable set by getopt representing
850 // the option argument.
851 value = optarg;
852 } else if (option_name == boot_complete_str) {
James Hawkinsc08e9962016-03-11 14:59:50 -0800853 RecordBootComplete();
854 } else if (option_name == boot_reason_str) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800855 RecordBootReason();
James Hawkins500d7152016-02-16 15:05:54 -0800856 } else if (option_name == factory_reset_str) {
857 RecordFactoryReset();
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800858 } else {
859 LOG(ERROR) << "Invalid option: " << option_name;
860 }
861 break;
862 }
863
James Hawkinsabd73e62016-01-19 15:10:38 -0800864 case 'h': {
865 ShowHelp(argv[0]);
866 break;
867 }
868
869 case 'l': {
870 LogBootEvents();
871 break;
872 }
873
874 case 'p': {
875 PrintBootEvents();
876 break;
877 }
878
879 case 'r': {
880 // |optarg| is an external variable set by getopt representing
881 // the option argument.
James Hawkinsc6275582016-03-22 10:47:44 -0700882 boot_event = optarg;
James Hawkinsabd73e62016-01-19 15:10:38 -0800883 break;
884 }
885
886 default: {
887 DCHECK_EQ(opt, '?');
888
889 // |optopt| is an external variable set by getopt representing
890 // the value of the invalid option.
891 LOG(ERROR) << "Invalid option: " << optopt;
892 ShowHelp(argv[0]);
893 return EXIT_FAILURE;
894 }
895 }
896 }
897
James Hawkinsc6275582016-03-22 10:47:44 -0700898 if (!boot_event.empty()) {
899 RecordBootEventFromCommandLine(boot_event, value);
900 }
901
James Hawkinsabd73e62016-01-19 15:10:38 -0800902 return 0;
903}