blob: 63b36f40cc3484bd93f94ae9875d825c66852bea [file] [log] [blame]
James Hawkinsabd73e62016-01-19 15:10:38 -08001/*
2 * Copyright (C) 2016 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17// The bootstat command provides options to persist boot events with the current
18// timestamp, dump the persisted events, and log all events to EventLog to be
19// uploaded to Android log storage via Tron.
20
James Hawkinsa4a1a4a2016-02-09 15:32:38 -080021#include <getopt.h>
Mark Salyzynb304f6d2017-08-04 13:35:51 -070022#include <sys/klog.h>
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -070023#include <unistd.h>
Mark Salyzynff2dcd92016-09-28 15:54:45 -070024
James Hawkinse78ea772017-03-24 11:43:02 -070025#include <chrono>
James Hawkins0660b302016-03-08 16:18:15 -080026#include <cmath>
James Hawkinsabd73e62016-01-19 15:10:38 -080027#include <cstddef>
28#include <cstdio>
James Hawkins500d7152016-02-16 15:05:54 -080029#include <ctime>
James Hawkinsa4a1a4a2016-02-09 15:32:38 -080030#include <map>
James Hawkinsabd73e62016-01-19 15:10:38 -080031#include <memory>
32#include <string>
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.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -070064void RecordBootEventFromCommandLine(const std::string& event, const std::string& value_str) {
James Hawkinsc6275582016-03-22 10:47:44 -070065 BootEventRecordStore boot_event_store;
66 if (!value_str.empty()) {
67 int32_t value = 0;
Elliott Hughesda46b392016-10-11 17:09:00 -070068 if (android::base::ParseInt(value_str, &value)) {
James Hawkins4dded612016-07-28 11:50:23 -070069 boot_event_store.AddBootEventWithValue(event, value);
70 }
James Hawkinsc6275582016-03-22 10:47:44 -070071 } else {
72 boot_event_store.AddBootEvent(event);
73 }
74}
75
James Hawkinsabd73e62016-01-19 15:10:38 -080076void PrintBootEvents() {
77 printf("Boot events:\n");
78 printf("------------\n");
79
80 BootEventRecordStore boot_event_store;
81 auto events = boot_event_store.GetAllBootEvents();
82 for (auto i = events.cbegin(); i != events.cend(); ++i) {
83 printf("%s\t%d\n", i->first.c_str(), i->second);
84 }
85}
86
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -070087void ShowHelp(const char* cmd) {
James Hawkinsabd73e62016-01-19 15:10:38 -080088 fprintf(stderr, "Usage: %s [options]\n", cmd);
89 fprintf(stderr,
90 "options include:\n"
Yongqin Liu78b2b942017-07-07 13:26:49 +080091 " -h, --help Show this help\n"
92 " -l, --log Log all metrics to logstorage\n"
93 " -p, --print Dump the boot event records to the console\n"
94 " -r, --record Record the timestamp of a named boot event\n"
95 " --value Optional value to associate with the boot event\n"
96 " --record_boot_complete Record metrics related to the time for the device boot\n"
97 " --record_boot_reason Record the reason why the device booted\n"
James Hawkins53684ea2016-02-23 16:18:19 -080098 " --record_time_since_factory_reset Record the time since the device was reset\n");
James Hawkinsabd73e62016-01-19 15:10:38 -080099}
100
101// Constructs a readable, printable string from the givencommand line
102// arguments.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700103std::string GetCommandLine(int argc, char** argv) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800104 std::string cmd;
105 for (int i = 0; i < argc; ++i) {
106 cmd += argv[i];
107 cmd += " ";
108 }
109
110 return cmd;
111}
112
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800113// Convenience wrapper over the property API that returns an
114// std::string.
115std::string GetProperty(const char* key) {
116 std::vector<char> temp(PROPERTY_VALUE_MAX);
117 const int len = property_get(key, &temp[0], nullptr);
118 if (len < 0) {
119 return "";
120 }
121 return std::string(&temp[0], len);
122}
123
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700124void SetProperty(const char* key, const std::string& val) {
125 property_set(key, val.c_str());
126}
127
128void SetProperty(const char* key, const char* val) {
129 property_set(key, val);
130}
131
James Hawkins25f71222017-10-10 16:37:05 -0700132constexpr int32_t kEmptyBootReason = 0;
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 = {
James Hawkins25f71222017-10-10 16:37:05 -0700140 {"empty", kEmptyBootReason},
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700141 {"unknown", kUnknownBootReason},
142 {"normal", 2},
143 {"recovery", 3},
144 {"reboot", 4},
145 {"PowerKey", 5},
146 {"hard_reset", 6},
147 {"kernel_panic", 7},
148 {"rpm_err", 8},
149 {"hw_reset", 9},
150 {"tz_err", 10},
151 {"adsp_err", 11},
152 {"modem_err", 12},
153 {"mba_err", 13},
154 {"Watchdog", 14},
155 {"Panic", 15},
156 {"power_key", 16},
157 {"power_on", 17},
158 {"Reboot", 18},
159 {"rtc", 19},
160 {"edl", 20},
161 {"oem_pon1", 21},
162 {"oem_powerkey", 22},
163 {"oem_unknown_reset", 23},
164 {"srto: HWWDT reset SC", 24},
165 {"srto: HWWDT reset platform", 25},
166 {"srto: bootloader", 26},
167 {"srto: kernel panic", 27},
168 {"srto: kernel watchdog reset", 28},
169 {"srto: normal", 29},
170 {"srto: reboot", 30},
171 {"srto: reboot-bootloader", 31},
172 {"srto: security watchdog reset", 32},
173 {"srto: wakesrc", 33},
174 {"srto: watchdog", 34},
175 {"srto:1-1", 35},
176 {"srto:omap_hsmm", 36},
177 {"srto:phy0", 37},
178 {"srto:rtc0", 38},
179 {"srto:touchpad", 39},
180 {"watchdog", 40},
181 {"watchdogr", 41},
182 {"wdog_bark", 42},
183 {"wdog_bite", 43},
184 {"wdog_reset", 44},
185 {"shutdown,", 45}, // Trailing comma is intentional.
186 {"shutdown,userrequested", 46},
187 {"reboot,bootloader", 47},
188 {"reboot,cold", 48},
189 {"reboot,recovery", 49},
190 {"thermal_shutdown", 50},
191 {"s3_wakeup", 51},
192 {"kernel_panic,sysrq", 52},
193 {"kernel_panic,NULL", 53},
194 {"kernel_panic,BUG", 54},
195 {"bootloader", 55},
196 {"cold", 56},
197 {"hard", 57},
198 {"warm", 58},
199 {"recovery", 59},
200 {"thermal-shutdown", 60},
201 {"shutdown,thermal", 61},
202 {"shutdown,battery", 62},
203 {"reboot,ota", 63},
204 {"reboot,factory_reset", 64},
205 {"reboot,", 65},
206 {"reboot,shell", 66},
207 {"reboot,adb", 67},
Mark Salyzyn9033bf52017-09-21 11:30:29 -0700208 {"reboot,userrequested", 68},
Mark Salyzyn161b8622017-09-26 08:26:12 -0700209 {"shutdown,container", 69}, // Host OS asking Android Container to shutdown
Mark Salyzyn243fa292017-10-11 09:02:04 -0700210 {"cold,powerkey", 70},
211 {"warm,s3_wakeup", 71},
212 {"hard,hw_reset", 72},
213 {"shutdown,suspend", 73}, // Suspend to RAM
214 {"shutdown,hibernate", 74}, // Suspend to DISK
James Hawkins34073b52017-10-17 15:53:27 -0700215 {"power_on_key", 75},
216 {"reboot_by_key", 76},
217 {"wdt_by_pass_pwk", 77},
218 {"reboot_longkey", 78},
219 {"powerkey", 79},
220 {"usb", 80},
221 {"wdt", 81},
222 {"tool_by_pass_pwk", 82},
223 {"2sec_reboot", 83},
224 {"reboot,by_key", 84},
225 {"reboot,longkey", 85},
Mark Salyzyncabbe4f2017-10-23 13:52:39 -0700226 {"reboot,2sec", 86},
Mark Salyzync89f9da2017-10-24 15:35:34 -0700227 {"shutdown,thermal,battery", 87},
Mark Salyzyn72a8ea32017-10-25 09:23:19 -0700228 {"reboot,its_just_so_hard", 88}, // produced by boot_reason_test
229 {"reboot,Its Just So Hard", 89}, // produced by boot_reason_test
James Hawkins8ac79bc2017-10-31 10:07:34 -0700230 {"usb", 90},
James Hawkins74b17582017-11-20 14:13:41 -0800231 {"charge", 91},
232 {"oem_tz_crash", 92},
233 {"uvlo", 93},
234 {"oem_ps_hold", 94},
235 {"abnormal_reset", 95},
236 {"oemerr_unknown", 96},
237 {"reboot_fastboot_mode", 97},
James Hawkins5f85f832017-11-29 14:30:06 -0800238 {"watchdog_apps_bite", 98},
239 {"xpu_err", 99},
240 {"power_on_usb", 100},
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800241};
242
243// Converts a string value representing the reason the system booted to an
244// integer representation. This is necessary for logging the boot_reason metric
245// via Tron, which does not accept non-integer buckets in histograms.
246int32_t BootReasonStrToEnum(const std::string& boot_reason) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800247 auto mapping = kBootReasonMap.find(boot_reason);
248 if (mapping != kBootReasonMap.end()) {
249 return mapping->second;
250 }
251
James Hawkins25f71222017-10-10 16:37:05 -0700252 if (boot_reason.empty()) {
253 return kEmptyBootReason;
254 }
255
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800256 LOG(INFO) << "Unknown boot reason: " << boot_reason;
257 return kUnknownBootReason;
258}
259
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700260// Canonical list of supported primary reboot reasons.
261const std::vector<const std::string> knownReasons = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700262 // clang-format off
263 // kernel
264 "watchdog",
265 "kernel_panic",
266 // strong
267 "recovery", // Should not happen from ro.boot.bootreason
268 "bootloader", // Should not happen from ro.boot.bootreason
269 // blunt
270 "cold",
271 "hard",
272 "warm",
Mark Salyzyn62909822017-10-09 09:27:16 -0700273 // super blunt
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700274 "shutdown", // Can not happen from ro.boot.bootreason
275 "reboot", // Default catch-all for anything unknown
276 // clang-format on
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700277};
278
279// Returns true if the supplied reason prefix is considered detailed enough.
280bool isStrongRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700281 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700282 if (s == "cold") break;
283 // Prefix defined as terminated by a nul or comma (,).
284 if (android::base::StartsWith(r, s.c_str()) &&
285 ((r.length() == s.length()) || (r[s.length()] == ','))) {
286 return true;
287 }
288 }
289 return false;
290}
291
292// Returns true if the supplied reason prefix is associated with the kernel.
293bool isKernelRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700294 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700295 if (s == "recovery") break;
296 // Prefix defined as terminated by a nul or comma (,).
297 if (android::base::StartsWith(r, s.c_str()) &&
298 ((r.length() == s.length()) || (r[s.length()] == ','))) {
299 return true;
300 }
301 }
302 return false;
303}
304
305// Returns true if the supplied reason prefix is considered known.
306bool isKnownRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700307 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700308 // Prefix defined as terminated by a nul or comma (,).
309 if (android::base::StartsWith(r, s.c_str()) &&
310 ((r.length() == s.length()) || (r[s.length()] == ','))) {
311 return true;
312 }
313 }
314 return false;
315}
316
317// If the reboot reason should be improved, report true if is too blunt.
318bool isBluntRebootReason(const std::string& r) {
319 if (isStrongRebootReason(r)) return false;
320
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700321 if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700322
323 size_t pos = 0;
324 while ((pos = r.find(',', pos)) != std::string::npos) {
325 ++pos;
326 std::string next(r.substr(pos));
327 if (next.length() == 0) break;
328 if (next[0] == ',') continue;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700329 if (!isKnownRebootReason(next)) return false; // Unknown subreason is good.
330 if (isStrongRebootReason(next)) return false; // eg: reboot,reboot
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700331 }
332 return true;
333}
334
Mark Salyzyn64610892017-09-18 10:41:14 -0700335bool readPstoreConsole(std::string& console) {
336 if (android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0", &console)) {
337 return true;
338 }
339 return android::base::ReadFileToString("/sys/fs/pstore/console-ramoops", &console);
340}
341
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700342// Implement a variant of std::string::rfind that is resilient to errors in
343// the data stream being inspected.
344class pstoreConsole {
345 private:
346 const size_t kBitErrorRate = 8; // number of bits per error
347 const std::string& console;
348
349 // Number of bits that differ between the two arguments l and r.
350 // Returns zero if the values for l and r are identical.
351 size_t numError(uint8_t l, uint8_t r) const { return std::bitset<8>(l ^ r).count(); }
352
353 // A string comparison function, reports the number of errors discovered
354 // in the match to a maximum of the bitLength / kBitErrorRate, at that
355 // point returning npos to indicate match is too poor.
356 //
357 // Since called in rfind which works backwards, expect cache locality will
358 // help if we check in reverse here as well for performance.
359 //
360 // Assumption: l (from console.c_str() + pos) is long enough to house
361 // _r.length(), checked in rfind caller below.
362 //
363 size_t numError(size_t pos, const std::string& _r) const {
364 const char* l = console.c_str() + pos;
365 const char* r = _r.c_str();
366 size_t n = _r.length();
367 const uint8_t* le = reinterpret_cast<const uint8_t*>(l) + n;
368 const uint8_t* re = reinterpret_cast<const uint8_t*>(r) + n;
369 size_t count = 0;
370 n = 0;
371 do {
372 // individual character bit error rate > threshold + slop
373 size_t num = numError(*--le, *--re);
374 if (num > ((8 + kBitErrorRate) / kBitErrorRate)) return std::string::npos;
375 // total bit error rate > threshold + slop
376 count += num;
377 ++n;
378 if (count > ((n * 8 + kBitErrorRate - (n > 2)) / kBitErrorRate)) {
379 return std::string::npos;
380 }
381 } while (le != reinterpret_cast<const uint8_t*>(l));
382 return count;
383 }
384
385 public:
386 explicit pstoreConsole(const std::string& console) : console(console) {}
387 // scope of argument must be equal to or greater than scope of pstoreConsole
388 explicit pstoreConsole(const std::string&& console) = delete;
389 explicit pstoreConsole(std::string&& console) = delete;
390
391 // Our implementation of rfind, use exact match first, then resort to fuzzy.
392 size_t rfind(const std::string& needle) const {
393 size_t pos = console.rfind(needle); // exact match?
394 if (pos != std::string::npos) return pos;
395
396 // Check to make sure needle fits in console string.
397 pos = console.length();
398 if (needle.length() > pos) return std::string::npos;
399 pos -= needle.length();
400 // fuzzy match to maximum kBitErrorRate
401 do {
402 if (numError(pos, needle) != std::string::npos) return pos;
403 } while (pos-- != 0);
404 return std::string::npos;
405 }
406
407 // Our implementation of find, use only fuzzy match.
408 size_t find(const std::string& needle, size_t start = 0) const {
409 // Check to make sure needle fits in console string.
410 if (needle.length() > console.length()) return std::string::npos;
411 const size_t last_pos = console.length() - needle.length();
412 // fuzzy match to maximum kBitErrorRate
413 for (size_t pos = start; pos <= last_pos; ++pos) {
414 if (numError(pos, needle) != std::string::npos) return pos;
415 }
416 return std::string::npos;
417 }
418};
419
420// If bit error match to needle, correct it.
421// Return true if any corrections were discovered and applied.
422bool correctForBer(std::string& reason, const std::string& needle) {
423 bool corrected = false;
424 if (reason.length() < needle.length()) return corrected;
425 const pstoreConsole console(reason);
426 const size_t last_pos = reason.length() - needle.length();
427 for (size_t pos = 0; pos <= last_pos; pos += needle.length()) {
428 pos = console.find(needle, pos);
429 if (pos == std::string::npos) break;
430
431 // exact match has no malice
432 if (needle == reason.substr(pos, needle.length())) continue;
433
434 corrected = true;
435 reason = reason.substr(0, pos) + needle + reason.substr(pos + needle.length());
436 }
437 return corrected;
438}
439
440bool addKernelPanicSubReason(const pstoreConsole& console, std::string& ret) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700441 // Check for kernel panic types to refine information
442 if (console.rfind("SysRq : Trigger a crash") != std::string::npos) {
443 // Can not happen, except on userdebug, during testing/debugging.
444 ret = "kernel_panic,sysrq";
445 return true;
446 }
447 if (console.rfind("Unable to handle kernel NULL pointer dereference at virtual address") !=
448 std::string::npos) {
449 ret = "kernel_panic,NULL";
450 return true;
451 }
452 if (console.rfind("Kernel BUG at ") != std::string::npos) {
453 ret = "kernel_panic,BUG";
454 return true;
455 }
456 return false;
457}
458
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700459bool addKernelPanicSubReason(const std::string& content, std::string& ret) {
460 return addKernelPanicSubReason(pstoreConsole(content), ret);
461}
462
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700463// std::transform Helper callback functions:
464// Converts a string value representing the reason the system booted to a
465// string complying with Android system standard reason.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700466char tounderline(char c) {
467 return ::isblank(c) ? '_' : c;
468}
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700469
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700470char toprintable(char c) {
471 return ::isprint(c) ? c : '?';
472}
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700473
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700474// Cleanup boot_reason regarding acceptable character set
475void transformReason(std::string& reason) {
476 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
477 std::transform(reason.begin(), reason.end(), reason.begin(), tounderline);
478 std::transform(reason.begin(), reason.end(), reason.begin(), toprintable);
479}
480
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700481const char system_reboot_reason_property[] = "sys.boot.reason";
482const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
483const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
484
485// Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
486std::string BootReasonStrToReason(const std::string& boot_reason) {
Mark Salyzyna16e4372017-09-20 08:36:12 -0700487 static const size_t max_reason_length = 256;
488
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700489 std::string ret(GetProperty(system_reboot_reason_property));
490 std::string reason(boot_reason);
491 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
492 if (reason == ret) ret = "";
493
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700494 transformReason(reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700495
496 // Is the current system boot reason sys.boot.reason valid?
497 if (!isKnownRebootReason(ret)) ret = "";
498
499 if (ret == "") {
500 // Is the bootloader boot reason ro.boot.bootreason known?
501 std::vector<std::string> words(android::base::Split(reason, ",_-"));
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700502 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700503 std::string blunt;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700504 for (auto& r : words) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700505 if (r == s) {
506 if (isBluntRebootReason(s)) {
507 blunt = s;
508 } else {
509 ret = s;
510 break;
511 }
512 }
513 }
514 if (ret == "") ret = blunt;
515 if (ret != "") break;
516 }
517 }
518
519 if (ret == "") {
520 // A series of checks to take some officially unsupported reasons
521 // reported by the bootloader and find some logical and canonical
522 // sense. In an ideal world, we would require those bootloaders
523 // to behave and follow our standards.
524 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700525 {"watchdog", "wdog"},
526 {"cold,powerkey", "powerkey"},
527 {"kernel_panic", "panic"},
528 {"shutdown,thermal", "thermal"},
529 {"warm,s3_wakeup", "s3_wakeup"},
530 {"hard,hw_reset", "hw_reset"},
Mark Salyzyncabbe4f2017-10-23 13:52:39 -0700531 {"reboot,2sec", "2sec_reboot"},
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700532 {"bootloader", ""},
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700533 };
534
535 // Either the primary or alias is found _somewhere_ in the reason string.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700536 for (auto& s : aliasReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700537 if (reason.find(s.first) != std::string::npos) {
538 ret = s.first;
539 break;
540 }
541 if (s.second.size() && (reason.find(s.second) != std::string::npos)) {
542 ret = s.first;
543 break;
544 }
545 }
546 }
547
548 // If watchdog is the reason, see if there is a security angle?
549 if (ret == "watchdog") {
550 if (reason.find("sec") != std::string::npos) {
551 ret += ",security";
552 }
553 }
554
Mark Salyzyn64610892017-09-18 10:41:14 -0700555 if (ret == "kernel_panic") {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700556 // Check to see if last klog has some refinement hints.
557 std::string content;
Mark Salyzyn64610892017-09-18 10:41:14 -0700558 if (readPstoreConsole(content)) {
559 addKernelPanicSubReason(content, ret);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700560 }
Mark Salyzyn64610892017-09-18 10:41:14 -0700561 } else if (isBluntRebootReason(ret)) {
562 // Check the other available reason resources if the reason is still blunt.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700563
Mark Salyzyn64610892017-09-18 10:41:14 -0700564 // Check to see if last klog has some refinement hints.
565 std::string content;
566 if (readPstoreConsole(content)) {
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700567 const pstoreConsole console(content);
Mark Salyzyn64610892017-09-18 10:41:14 -0700568 // The toybox reboot command used directly (unlikely)? But also
569 // catches init's response to Android's more controlled reboot command.
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700570 if (console.rfind("reboot: Power down") != std::string::npos) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700571 ret = "shutdown"; // Still too blunt, but more accurate.
572 // ToDo: init should record the shutdown reason to kernel messages ala:
573 // init: shutdown system with command 'last_reboot_reason'
574 // so that if pstore has persistence we can get some details
575 // that could be missing in last_reboot_reason_property.
576 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700577
Mark Salyzyn64610892017-09-18 10:41:14 -0700578 static const char cmd[] = "reboot: Restarting system with command '";
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700579 size_t pos = console.rfind(cmd);
Mark Salyzyn64610892017-09-18 10:41:14 -0700580 if (pos != std::string::npos) {
581 pos += strlen(cmd);
Mark Salyzyna16e4372017-09-20 08:36:12 -0700582 std::string subReason(content.substr(pos, max_reason_length));
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700583 // Correct against any known strings that Bit Error Match
584 for (const auto& s : knownReasons) {
585 correctForBer(subReason, s);
586 }
587 for (const auto& m : kBootReasonMap) {
588 if (m.first.length() <= strlen("cold")) continue; // too short?
589 if (correctForBer(subReason, m.first + "'")) continue;
590 if (m.first.length() <= strlen("reboot,cold")) continue; // short?
591 if (!android::base::StartsWith(m.first, "reboot,")) continue;
592 correctForBer(subReason, m.first.substr(strlen("reboot,")) + "'");
593 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700594 for (pos = 0; pos < subReason.length(); ++pos) {
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700595 char c = subReason[pos];
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700596 // #, &, %, / are common single bit error for ' that we can block
597 if (!::isprint(c) || (c == '\'') || (c == '#') || (c == '&') || (c == '%') || (c == '/')) {
Mark Salyzyna16e4372017-09-20 08:36:12 -0700598 subReason.erase(pos);
599 break;
600 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700601 }
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700602 transformReason(subReason);
Mark Salyzyn64610892017-09-18 10:41:14 -0700603 if (subReason != "") { // Will not land "reboot" as that is too blunt.
604 if (isKernelRebootReason(subReason)) {
605 ret = "reboot," + subReason; // User space can't talk kernel reasons.
Mark Salyzyndafced92017-09-20 08:37:46 -0700606 } else if (isKnownRebootReason(subReason)) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700607 ret = subReason;
Mark Salyzyndafced92017-09-20 08:37:46 -0700608 } else {
609 ret = "reboot," + subReason; // legitimize unknown reasons
Mark Salyzyn64610892017-09-18 10:41:14 -0700610 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700611 }
612 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700613
Mark Salyzyn64610892017-09-18 10:41:14 -0700614 // Check for kernel panics, allowed to override reboot command.
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700615 if (!addKernelPanicSubReason(console, ret) &&
Mark Salyzyn64610892017-09-18 10:41:14 -0700616 // check for long-press power down
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700617 ((console.rfind("Power held for ") != std::string::npos) ||
618 (console.rfind("charger: [") != std::string::npos))) {
Mark Salyzyn64610892017-09-18 10:41:14 -0700619 ret = "cold";
620 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700621 }
622
623 // The following battery test should migrate to a default system health HAL
624
625 // Let us not worry if the reboot command was issued, for the cases of
626 // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard.
627 // Same for bootloader and ro.boot.bootreasons of this set, but a dead
628 // battery could conceivably lead to these, so worthy of override.
629 if (isBluntRebootReason(ret)) {
630 // Heuristic to determine if shutdown possibly because of a dead battery?
631 // Really a hail-mary pass to find it in last klog content ...
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700632 static const int battery_dead_threshold = 2; // percent
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700633 static const char battery[] = "healthd: battery l=";
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700634 const pstoreConsole console(content);
635 size_t pos = console.rfind(battery); // last one
Mark Salyzyna16e4372017-09-20 08:36:12 -0700636 std::string digits;
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700637 if (pos != std::string::npos) {
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700638 digits = content.substr(pos + strlen(battery), strlen("100 "));
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700639 // correct common errors
640 correctForBer(digits, "100 ");
641 if (digits[0] == '!') digits[0] = '1';
642 if (digits[1] == '!') digits[1] = '1';
Mark Salyzyna16e4372017-09-20 08:36:12 -0700643 }
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700644 const char* endptr = digits.c_str();
645 unsigned level = 0;
646 while (::isdigit(*endptr)) {
647 level *= 10;
648 level += *endptr++ - '0';
649 // make sure no leading zeros, except zero itself, and range check.
650 if ((level == 0) || (level > 100)) break;
651 }
Mark Salyzyn293cb3b2017-09-20 08:37:46 -0700652 // example bit error rate issues for 10%
653 // 'l=10 ' no bits in error
654 // 'l=00 ' single bit error (fails above)
655 // 'l=1 ' single bit error
656 // 'l=0 ' double bit error
657 // There are others, not typically critical because of 2%
658 // battery_dead_threshold. KISS check, make sure second
659 // character after digit sequence is not a space.
660 if ((level <= 100) && (endptr != digits.c_str()) && (endptr[0] == ' ') && (endptr[1] != ' ')) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700661 LOG(INFO) << "Battery level at shutdown " << level << "%";
662 if (level <= battery_dead_threshold) {
663 ret = "shutdown,battery";
664 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700665 } else { // Most likely
666 digits = ""; // reset digits
667
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700668 // Content buffer no longer will have console data. Beware if more
669 // checks added below, that depend on parsing console content.
670 content = "";
671
672 LOG(DEBUG) << "Can not find last low battery in last console messages";
673 android_logcat_context ctx = create_android_logcat();
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700674 FILE* fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d");
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700675 if (fp != nullptr) {
676 android::base::ReadFdToString(fileno(fp), &content);
677 }
678 android_logcat_pclose(&ctx, fp);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700679 static const char logcat_battery[] = "W/healthd ( 0): battery l=";
680 const char* match = logcat_battery;
681
682 if (content == "") {
683 // Service logd.klog not running, go to smaller buffer in the kernel.
684 int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0);
685 if (rc > 0) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700686 ssize_t len = rc + 1024; // 1K Margin should it grow between calls.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700687 std::unique_ptr<char[]> buf(new char[len]);
688 rc = klogctl(KLOG_READ_ALL, buf.get(), len);
689 if (rc < len) {
690 len = rc + 1;
691 }
692 buf[--len] = '\0';
693 content = buf.get();
694 }
695 match = battery;
696 }
697
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700698 pos = content.find(match); // The first one it finds.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700699 if (pos != std::string::npos) {
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700700 digits = content.substr(pos + strlen(match), strlen("100 "));
Mark Salyzyna16e4372017-09-20 08:36:12 -0700701 }
Mark Salyzyn747c0e62017-09-20 08:37:46 -0700702 endptr = digits.c_str();
703 level = 0;
704 while (::isdigit(*endptr)) {
705 level *= 10;
706 level += *endptr++ - '0';
707 // make sure no leading zeros, except zero itself, and range check.
708 if ((level == 0) || (level > 100)) break;
709 }
Mark Salyzyna16e4372017-09-20 08:36:12 -0700710 if ((level <= 100) && (endptr != digits.c_str()) && (*endptr == ' ')) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700711 LOG(INFO) << "Battery level at startup " << level << "%";
712 if (level <= battery_dead_threshold) {
713 ret = "shutdown,battery";
714 }
715 } else {
716 LOG(DEBUG) << "Can not find first battery level in dmesg or logcat";
717 }
718 }
719 }
720
721 // Is there a controlled shutdown hint in last_reboot_reason_property?
722 if (isBluntRebootReason(ret)) {
723 // Content buffer no longer will have console data. Beware if more
724 // checks added below, that depend on parsing console content.
725 content = GetProperty(last_reboot_reason_property);
Mark Salyzyn88d692c2017-09-20 08:37:46 -0700726 transformReason(content);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700727
Mark Salyzyn62909822017-10-09 09:27:16 -0700728 // Anything in last is better than 'super-blunt' reboot or shutdown.
729 if ((ret == "") || (ret == "reboot") || (ret == "shutdown") || !isBluntRebootReason(content)) {
730 ret = content;
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700731 }
732 }
733
734 // Other System Health HAL reasons?
735
736 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
737 // possibly offer hardware-specific clues from the PMIC.
738 }
739
740 // If unknown left over from above, make it "reboot,<boot_reason>"
741 if (ret == "") {
742 ret = "reboot";
743 if (android::base::StartsWith(reason, "reboot")) {
744 reason = reason.substr(strlen("reboot"));
Mark Salyzyn0af71a52017-10-05 13:58:04 -0700745 while ((reason[0] == ',') || (reason[0] == '_')) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700746 reason = reason.substr(1);
747 }
748 }
749 if (reason != "") {
750 ret += ",";
751 ret += reason;
752 }
753 }
754
755 LOG(INFO) << "Canonical boot reason: " << ret;
756 if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) {
757 // Rewrite as it must be old news, kernel reasons trump user space.
758 SetProperty(last_reboot_reason_property, ret);
759 }
760 return ret;
761}
762
James Hawkinsb9cf7712016-04-08 15:32:19 -0700763// Returns the appropriate metric key prefix for the boot_complete metric such
764// that boot metrics after a system update are labeled as ota_boot_complete;
765// otherwise, they are labeled as boot_complete. This method encapsulates the
766// bookkeeping required to track when a system update has occurred by storing
767// the UTC timestamp of the system build date and comparing against the current
768// system build date.
769std::string CalculateBootCompletePrefix() {
770 static const std::string kBuildDateKey = "build_date";
771 std::string boot_complete_prefix = "boot_complete";
772
773 std::string build_date_str = GetProperty("ro.build.date.utc");
James Hawkins4dded612016-07-28 11:50:23 -0700774 int32_t build_date;
Elliott Hughesda46b392016-10-11 17:09:00 -0700775 if (!android::base::ParseInt(build_date_str, &build_date)) {
James Hawkins4dded612016-07-28 11:50:23 -0700776 return std::string();
777 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700778
779 BootEventRecordStore boot_event_store;
780 BootEventRecordStore::BootEventRecord record;
James Hawkins0bc4ad42017-05-30 15:03:15 -0700781 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
782 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
783 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700784 LOG(INFO) << "Canonical boot reason: reboot,factory_reset";
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700785 SetProperty(system_reboot_reason_property, "reboot,factory_reset");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700786 } else if (build_date != record.second) {
James Hawkinsb9cf7712016-04-08 15:32:19 -0700787 boot_complete_prefix = "ota_" + boot_complete_prefix;
788 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700789 LOG(INFO) << "Canonical boot reason: reboot,ota";
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700790 SetProperty(system_reboot_reason_property, "reboot,ota");
James Hawkinsb9cf7712016-04-08 15:32:19 -0700791 }
792
793 return boot_complete_prefix;
794}
795
James Hawkinsef0a0902017-01-06 14:38:23 -0800796// Records the value of a given ro.boottime.init property in milliseconds.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700797void RecordInitBootTimeProp(BootEventRecordStore* boot_event_store, const char* property) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800798 std::string value = GetProperty(property);
799
James Hawkins27c05222017-01-26 11:55:44 -0800800 int32_t time_in_ms;
801 if (android::base::ParseInt(value, &time_in_ms)) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800802 boot_event_store->AddBootEventWithValue(property, time_in_ms);
803 }
804}
805
James Hawkins1bfcaec2017-05-19 14:27:27 -0700806// A map from bootloader timing stage to the time that stage took during boot.
807typedef std::map<std::string, int32_t> BootloaderTimingMap;
808
809// Returns a mapping from bootloader stage names to the time those stages
810// took to boot.
811const BootloaderTimingMap GetBootLoaderTimings() {
812 BootloaderTimingMap timings;
813
814 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
815 // where timeN is in milliseconds.
James Hawkinsbe46fd12017-02-02 16:21:25 -0800816 std::string value = GetProperty("ro.boot.boottime");
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800817 if (value.empty()) {
818 // ro.boot.boottime is not reported on all devices.
James Hawkins1bfcaec2017-05-19 14:27:27 -0700819 return BootloaderTimingMap();
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800820 }
James Hawkinsbe46fd12017-02-02 16:21:25 -0800821
822 auto stages = android::base::Split(value, ",");
James Hawkins1bfcaec2017-05-19 14:27:27 -0700823 for (const auto& stageTiming : stages) {
James Hawkinsbe46fd12017-02-02 16:21:25 -0800824 // |stageTiming| is of the form 'stage:time'.
825 auto stageTimingValues = android::base::Split(stageTiming, ":");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700826 DCHECK_EQ(2U, stageTimingValues.size());
James Hawkinsbe46fd12017-02-02 16:21:25 -0800827
828 std::string stageName = stageTimingValues[0];
829 int32_t time_ms;
830 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700831 timings[stageName] = time_ms;
James Hawkinsbe46fd12017-02-02 16:21:25 -0800832 }
833 }
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800834
James Hawkins1bfcaec2017-05-19 14:27:27 -0700835 return timings;
836}
837
838// Parses and records the set of bootloader stages and associated boot times
839// from the ro.boot.boottime system property.
840void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
841 const BootloaderTimingMap& bootloader_timings) {
842 int32_t total_time = 0;
843 for (const auto& timing : bootloader_timings) {
844 total_time += timing.second;
845 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
846 }
847
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800848 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
James Hawkinsbe46fd12017-02-02 16:21:25 -0800849}
850
James Hawkins1bfcaec2017-05-19 14:27:27 -0700851// Records the closest estimation to the absolute device boot time, i.e.,
852// from power on to boot_complete, including bootloader times.
853void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
854 const BootloaderTimingMap& bootloader_timings,
855 std::chrono::milliseconds uptime) {
856 int32_t bootloader_time_ms = 0;
857
858 for (const auto& timing : bootloader_timings) {
859 if (timing.first.compare("SW") != 0) {
860 bootloader_time_ms += timing.second;
861 }
862 }
863
864 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
865 auto absolute_total =
866 std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime);
867 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count());
868}
869
James Hawkinsc08e9962016-03-11 14:59:50 -0800870// Records several metrics related to the time it takes to boot the device,
871// including disambiguating boot time on encrypted or non-encrypted devices.
872void RecordBootComplete() {
873 BootEventRecordStore boot_event_store;
James Hawkinsb9cf7712016-04-08 15:32:19 -0700874 BootEventRecordStore::BootEventRecord record;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700875
James Hawkins1bfcaec2017-05-19 14:27:27 -0700876 auto time_since_epoch = android::base::boot_clock::now().time_since_epoch();
877 auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700878 time_t current_time_utc = time(nullptr);
879
880 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
881 time_t last_boot_time_utc = record.second;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700882 time_t time_since_last_boot = difftime(current_time_utc, last_boot_time_utc);
883 boot_event_store.AddBootEventWithValue("time_since_last_boot", time_since_last_boot);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700884 }
885
886 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
James Hawkinsc08e9962016-03-11 14:59:50 -0800887
James Hawkinsb9cf7712016-04-08 15:32:19 -0700888 // The boot_complete metric has two variants: boot_complete and
889 // ota_boot_complete. The latter signifies that the device is booting after
890 // a system update.
891 std::string boot_complete_prefix = CalculateBootCompletePrefix();
James Hawkins4dded612016-07-28 11:50:23 -0700892 if (boot_complete_prefix.empty()) {
893 // The system is hosed because the build date property could not be read.
894 return;
895 }
James Hawkinsc08e9962016-03-11 14:59:50 -0800896
897 // post_decrypt_time_elapsed is only logged on encrypted devices.
898 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
899 // Log the amount of time elapsed until the device is decrypted, which
900 // includes the variable amount of time the user takes to enter the
901 // decryption password.
James Hawkinse78ea772017-03-24 11:43:02 -0700902 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800903
904 // Subtract the decryption time to normalize the boot cycle timing.
James Hawkinse78ea772017-03-24 11:43:02 -0700905 std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second);
James Hawkinsb9cf7712016-04-08 15:32:19 -0700906 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
James Hawkinse78ea772017-03-24 11:43:02 -0700907 boot_complete.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800908 } else {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700909 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800910 }
911
912 // Record the total time from device startup to boot complete, regardless of
913 // encryption state.
James Hawkinse78ea772017-03-24 11:43:02 -0700914 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count());
James Hawkinsef0a0902017-01-06 14:38:23 -0800915
916 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
917 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
918 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
James Hawkinsbe46fd12017-02-02 16:21:25 -0800919
James Hawkins1bfcaec2017-05-19 14:27:27 -0700920 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
921 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
922
923 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch);
924 RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms);
James Hawkinsc08e9962016-03-11 14:59:50 -0800925}
926
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800927// Records the boot_reason metric by querying the ro.boot.bootreason system
928// property.
929void RecordBootReason() {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700930 const std::string reason(GetProperty(bootloader_reboot_reason_property));
James Hawkins25f71222017-10-10 16:37:05 -0700931
932 if (reason.empty()) {
933 // Log an empty boot reason value as '<EMPTY>' to ensure the value is intentional
934 // (and not corruption anywhere else in the reporting pipeline).
935 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
936 android::metricslogger::FIELD_PLATFORM_REASON, "<EMPTY>");
937 } else {
938 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
939 android::metricslogger::FIELD_PLATFORM_REASON, reason);
940 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700941
942 // Log the raw bootloader_boot_reason property value.
943 int32_t boot_reason = BootReasonStrToEnum(reason);
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800944 BootEventRecordStore boot_event_store;
945 boot_event_store.AddBootEventWithValue("boot_reason", boot_reason);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700946
947 // Log the scrubbed system_boot_reason.
948 const std::string system_reason(BootReasonStrToReason(reason));
949 int32_t system_boot_reason = BootReasonStrToEnum(system_reason);
950 boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason);
951
952 // Record the scrubbed system_boot_reason to the property
953 SetProperty(system_reboot_reason_property, system_reason);
954 if (reason == "") {
955 SetProperty(bootloader_reboot_reason_property, system_reason);
956 }
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800957}
958
James Hawkins500d7152016-02-16 15:05:54 -0800959// Records two metrics related to the user resetting a device: the time at
960// which the device is reset, and the time since the user last reset the
961// device. The former is only set once per-factory reset.
962void RecordFactoryReset() {
963 BootEventRecordStore boot_event_store;
964 BootEventRecordStore::BootEventRecord record;
965
966 time_t current_time_utc = time(nullptr);
967
James Hawkins0660b302016-03-08 16:18:15 -0800968 if (current_time_utc < 0) {
969 // UMA does not display negative values in buckets, so convert to positive.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700970 android::metricslogger::LogHistogram("factory_reset_current_time_failure",
971 std::abs(current_time_utc));
James Hawkinsfff95ba2016-03-29 16:13:49 -0700972
James Hawkins9aec9262017-01-31 11:42:24 -0800973 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700974 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700975 boot_event_store.AddBootEventWithValue("factory_reset_current_time_failure",
976 std::abs(current_time_utc));
James Hawkins0660b302016-03-08 16:18:15 -0800977 return;
978 } else {
James Hawkins9aec9262017-01-31 11:42:24 -0800979 android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700980
James Hawkins9aec9262017-01-31 11:42:24 -0800981 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700982 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700983 boot_event_store.AddBootEventWithValue("factory_reset_current_time", current_time_utc);
James Hawkins0660b302016-03-08 16:18:15 -0800984 }
985
James Hawkins500d7152016-02-16 15:05:54 -0800986 // The factory_reset boot event does not exist after the device is reset, so
987 // use this signal to mark the time of the factory reset.
988 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
989 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
James Hawkins3bf9b142016-03-03 14:50:24 -0800990
991 // Don't log the time_since_factory_reset until some time has elapsed.
992 // The data is not meaningful yet and skews the histogram buckets.
James Hawkins500d7152016-02-16 15:05:54 -0800993 return;
994 }
995
996 // Calculate and record the difference in time between now and the
997 // factory_reset time.
998 time_t factory_reset_utc = record.second;
James Hawkins9aec9262017-01-31 11:42:24 -0800999 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -07001000
James Hawkins9aec9262017-01-31 11:42:24 -08001001 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -07001002 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001003 boot_event_store.AddBootEventWithValue("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -07001004
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001005 time_t time_since_factory_reset = difftime(current_time_utc, factory_reset_utc);
1006 boot_event_store.AddBootEventWithValue("time_since_factory_reset", time_since_factory_reset);
James Hawkins500d7152016-02-16 15:05:54 -08001007}
1008
James Hawkinsabd73e62016-01-19 15:10:38 -08001009} // namespace
1010
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001011int main(int argc, char** argv) {
James Hawkinsabd73e62016-01-19 15:10:38 -08001012 android::base::InitLogging(argv);
1013
1014 const std::string cmd_line = GetCommandLine(argc, argv);
1015 LOG(INFO) << "Service started: " << cmd_line;
1016
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001017 int option_index = 0;
James Hawkinsc6275582016-03-22 10:47:44 -07001018 static const char value_str[] = "value";
James Hawkinsc08e9962016-03-11 14:59:50 -08001019 static const char boot_complete_str[] = "record_boot_complete";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001020 static const char boot_reason_str[] = "record_boot_reason";
James Hawkins53684ea2016-02-23 16:18:19 -08001021 static const char factory_reset_str[] = "record_time_since_factory_reset";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001022 static const struct option long_options[] = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -07001023 // clang-format off
1024 { "help", no_argument, NULL, 'h' },
1025 { "log", no_argument, NULL, 'l' },
1026 { "print", no_argument, NULL, 'p' },
1027 { "record", required_argument, NULL, 'r' },
1028 { value_str, required_argument, NULL, 0 },
1029 { boot_complete_str, no_argument, NULL, 0 },
1030 { boot_reason_str, no_argument, NULL, 0 },
1031 { factory_reset_str, no_argument, NULL, 0 },
1032 { NULL, 0, NULL, 0 }
1033 // clang-format on
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001034 };
1035
James Hawkinsc6275582016-03-22 10:47:44 -07001036 std::string boot_event;
1037 std::string value;
James Hawkinsabd73e62016-01-19 15:10:38 -08001038 int opt = 0;
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001039 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
James Hawkinsabd73e62016-01-19 15:10:38 -08001040 switch (opt) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001041 // This case handles long options which have no single-character mapping.
1042 case 0: {
1043 const std::string option_name = long_options[option_index].name;
James Hawkinsc6275582016-03-22 10:47:44 -07001044 if (option_name == value_str) {
1045 // |optarg| is an external variable set by getopt representing
1046 // the option argument.
1047 value = optarg;
1048 } else if (option_name == boot_complete_str) {
James Hawkinsc08e9962016-03-11 14:59:50 -08001049 RecordBootComplete();
1050 } else if (option_name == boot_reason_str) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001051 RecordBootReason();
James Hawkins500d7152016-02-16 15:05:54 -08001052 } else if (option_name == factory_reset_str) {
1053 RecordFactoryReset();
James Hawkinsa4a1a4a2016-02-09 15:32:38 -08001054 } else {
1055 LOG(ERROR) << "Invalid option: " << option_name;
1056 }
1057 break;
1058 }
1059
James Hawkinsabd73e62016-01-19 15:10:38 -08001060 case 'h': {
1061 ShowHelp(argv[0]);
1062 break;
1063 }
1064
1065 case 'l': {
1066 LogBootEvents();
1067 break;
1068 }
1069
1070 case 'p': {
1071 PrintBootEvents();
1072 break;
1073 }
1074
1075 case 'r': {
1076 // |optarg| is an external variable set by getopt representing
1077 // the option argument.
James Hawkinsc6275582016-03-22 10:47:44 -07001078 boot_event = optarg;
James Hawkinsabd73e62016-01-19 15:10:38 -08001079 break;
1080 }
1081
1082 default: {
1083 DCHECK_EQ(opt, '?');
1084
1085 // |optopt| is an external variable set by getopt representing
1086 // the value of the invalid option.
1087 LOG(ERROR) << "Invalid option: " << optopt;
1088 ShowHelp(argv[0]);
1089 return EXIT_FAILURE;
1090 }
1091 }
1092 }
1093
James Hawkinsc6275582016-03-22 10:47:44 -07001094 if (!boot_event.empty()) {
1095 RecordBootEventFromCommandLine(boot_event, value);
1096 }
1097
James Hawkinsabd73e62016-01-19 15:10:38 -08001098 return 0;
1099}