blob: ce28059be2c603ceab90adbe60462f940e56f459 [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 Hawkins6f74c0b2016-02-12 15:49:16 -0800132constexpr int32_t kUnknownBootReason = 1;
133
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800134// A mapping from boot reason string, as read from the ro.boot.bootreason
135// system property, to a unique integer ID. Viewers of log data dashboards for
136// the boot_reason metric may refer to this mapping to discern the histogram
137// values.
James Hawkins6f74c0b2016-02-12 15:49:16 -0800138const std::map<std::string, int32_t> kBootReasonMap = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700139 {"unknown", kUnknownBootReason},
140 {"normal", 2},
141 {"recovery", 3},
142 {"reboot", 4},
143 {"PowerKey", 5},
144 {"hard_reset", 6},
145 {"kernel_panic", 7},
146 {"rpm_err", 8},
147 {"hw_reset", 9},
148 {"tz_err", 10},
149 {"adsp_err", 11},
150 {"modem_err", 12},
151 {"mba_err", 13},
152 {"Watchdog", 14},
153 {"Panic", 15},
154 {"power_key", 16},
155 {"power_on", 17},
156 {"Reboot", 18},
157 {"rtc", 19},
158 {"edl", 20},
159 {"oem_pon1", 21},
160 {"oem_powerkey", 22},
161 {"oem_unknown_reset", 23},
162 {"srto: HWWDT reset SC", 24},
163 {"srto: HWWDT reset platform", 25},
164 {"srto: bootloader", 26},
165 {"srto: kernel panic", 27},
166 {"srto: kernel watchdog reset", 28},
167 {"srto: normal", 29},
168 {"srto: reboot", 30},
169 {"srto: reboot-bootloader", 31},
170 {"srto: security watchdog reset", 32},
171 {"srto: wakesrc", 33},
172 {"srto: watchdog", 34},
173 {"srto:1-1", 35},
174 {"srto:omap_hsmm", 36},
175 {"srto:phy0", 37},
176 {"srto:rtc0", 38},
177 {"srto:touchpad", 39},
178 {"watchdog", 40},
179 {"watchdogr", 41},
180 {"wdog_bark", 42},
181 {"wdog_bite", 43},
182 {"wdog_reset", 44},
183 {"shutdown,", 45}, // Trailing comma is intentional.
184 {"shutdown,userrequested", 46},
185 {"reboot,bootloader", 47},
186 {"reboot,cold", 48},
187 {"reboot,recovery", 49},
188 {"thermal_shutdown", 50},
189 {"s3_wakeup", 51},
190 {"kernel_panic,sysrq", 52},
191 {"kernel_panic,NULL", 53},
192 {"kernel_panic,BUG", 54},
193 {"bootloader", 55},
194 {"cold", 56},
195 {"hard", 57},
196 {"warm", 58},
197 {"recovery", 59},
198 {"thermal-shutdown", 60},
199 {"shutdown,thermal", 61},
200 {"shutdown,battery", 62},
201 {"reboot,ota", 63},
202 {"reboot,factory_reset", 64},
203 {"reboot,", 65},
204 {"reboot,shell", 66},
205 {"reboot,adb", 67},
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800206};
207
208// Converts a string value representing the reason the system booted to an
209// integer representation. This is necessary for logging the boot_reason metric
210// via Tron, which does not accept non-integer buckets in histograms.
211int32_t BootReasonStrToEnum(const std::string& boot_reason) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800212 auto mapping = kBootReasonMap.find(boot_reason);
213 if (mapping != kBootReasonMap.end()) {
214 return mapping->second;
215 }
216
217 LOG(INFO) << "Unknown boot reason: " << boot_reason;
218 return kUnknownBootReason;
219}
220
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700221// Canonical list of supported primary reboot reasons.
222const std::vector<const std::string> knownReasons = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700223 // clang-format off
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 // clang-format on
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700237};
238
239// Returns true if the supplied reason prefix is considered detailed enough.
240bool isStrongRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700241 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700242 if (s == "cold") break;
243 // Prefix defined as terminated by a nul or comma (,).
244 if (android::base::StartsWith(r, s.c_str()) &&
245 ((r.length() == s.length()) || (r[s.length()] == ','))) {
246 return true;
247 }
248 }
249 return false;
250}
251
252// Returns true if the supplied reason prefix is associated with the kernel.
253bool isKernelRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700254 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700255 if (s == "recovery") break;
256 // Prefix defined as terminated by a nul or comma (,).
257 if (android::base::StartsWith(r, s.c_str()) &&
258 ((r.length() == s.length()) || (r[s.length()] == ','))) {
259 return true;
260 }
261 }
262 return false;
263}
264
265// Returns true if the supplied reason prefix is considered known.
266bool isKnownRebootReason(const std::string& r) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700267 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700268 // Prefix defined as terminated by a nul or comma (,).
269 if (android::base::StartsWith(r, s.c_str()) &&
270 ((r.length() == s.length()) || (r[s.length()] == ','))) {
271 return true;
272 }
273 }
274 return false;
275}
276
277// If the reboot reason should be improved, report true if is too blunt.
278bool isBluntRebootReason(const std::string& r) {
279 if (isStrongRebootReason(r)) return false;
280
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700281 if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700282
283 size_t pos = 0;
284 while ((pos = r.find(',', pos)) != std::string::npos) {
285 ++pos;
286 std::string next(r.substr(pos));
287 if (next.length() == 0) break;
288 if (next[0] == ',') continue;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700289 if (!isKnownRebootReason(next)) return false; // Unknown subreason is good.
290 if (isStrongRebootReason(next)) return false; // eg: reboot,reboot
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700291 }
292 return true;
293}
294
Mark Salyzyn64610892017-09-18 10:41:14 -0700295bool readPstoreConsole(std::string& console) {
296 if (android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0", &console)) {
297 return true;
298 }
299 return android::base::ReadFileToString("/sys/fs/pstore/console-ramoops", &console);
300}
301
302bool addKernelPanicSubReason(const std::string& console, std::string& ret) {
303 // Check for kernel panic types to refine information
304 if (console.rfind("SysRq : Trigger a crash") != std::string::npos) {
305 // Can not happen, except on userdebug, during testing/debugging.
306 ret = "kernel_panic,sysrq";
307 return true;
308 }
309 if (console.rfind("Unable to handle kernel NULL pointer dereference at virtual address") !=
310 std::string::npos) {
311 ret = "kernel_panic,NULL";
312 return true;
313 }
314 if (console.rfind("Kernel BUG at ") != std::string::npos) {
315 ret = "kernel_panic,BUG";
316 return true;
317 }
318 return false;
319}
320
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700321// std::transform Helper callback functions:
322// Converts a string value representing the reason the system booted to a
323// string complying with Android system standard reason.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700324char tounderline(char c) {
325 return ::isblank(c) ? '_' : c;
326}
327char toprintable(char c) {
328 return ::isprint(c) ? c : '?';
329}
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700330
331const char system_reboot_reason_property[] = "sys.boot.reason";
332const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY;
333const char bootloader_reboot_reason_property[] = "ro.boot.bootreason";
334
335// Scrub, Sanitize, Standardize and Enhance the boot reason string supplied.
336std::string BootReasonStrToReason(const std::string& boot_reason) {
337 std::string ret(GetProperty(system_reboot_reason_property));
338 std::string reason(boot_reason);
339 // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate
340 if (reason == ret) ret = "";
341
342 // Cleanup boot_reason regarding acceptable character set
343 std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower);
344 std::transform(reason.begin(), reason.end(), reason.begin(), tounderline);
345 std::transform(reason.begin(), reason.end(), reason.begin(), toprintable);
346
347 // Is the current system boot reason sys.boot.reason valid?
348 if (!isKnownRebootReason(ret)) ret = "";
349
350 if (ret == "") {
351 // Is the bootloader boot reason ro.boot.bootreason known?
352 std::vector<std::string> words(android::base::Split(reason, ",_-"));
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700353 for (auto& s : knownReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700354 std::string blunt;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700355 for (auto& r : words) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700356 if (r == s) {
357 if (isBluntRebootReason(s)) {
358 blunt = s;
359 } else {
360 ret = s;
361 break;
362 }
363 }
364 }
365 if (ret == "") ret = blunt;
366 if (ret != "") break;
367 }
368 }
369
370 if (ret == "") {
371 // A series of checks to take some officially unsupported reasons
372 // reported by the bootloader and find some logical and canonical
373 // sense. In an ideal world, we would require those bootloaders
374 // to behave and follow our standards.
375 static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700376 {"watchdog", "wdog"},
377 {"cold,powerkey", "powerkey"},
378 {"kernel_panic", "panic"},
379 {"shutdown,thermal", "thermal"},
380 {"warm,s3_wakeup", "s3_wakeup"},
381 {"hard,hw_reset", "hw_reset"},
382 {"bootloader", ""},
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700383 };
384
385 // Either the primary or alias is found _somewhere_ in the reason string.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700386 for (auto& s : aliasReasons) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700387 if (reason.find(s.first) != std::string::npos) {
388 ret = s.first;
389 break;
390 }
391 if (s.second.size() && (reason.find(s.second) != std::string::npos)) {
392 ret = s.first;
393 break;
394 }
395 }
396 }
397
398 // If watchdog is the reason, see if there is a security angle?
399 if (ret == "watchdog") {
400 if (reason.find("sec") != std::string::npos) {
401 ret += ",security";
402 }
403 }
404
Mark Salyzyn64610892017-09-18 10:41:14 -0700405 if (ret == "kernel_panic") {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700406 // Check to see if last klog has some refinement hints.
407 std::string content;
Mark Salyzyn64610892017-09-18 10:41:14 -0700408 if (readPstoreConsole(content)) {
409 addKernelPanicSubReason(content, ret);
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700410 }
Mark Salyzyn64610892017-09-18 10:41:14 -0700411 } else if (isBluntRebootReason(ret)) {
412 // Check the other available reason resources if the reason is still blunt.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700413
Mark Salyzyn64610892017-09-18 10:41:14 -0700414 // Check to see if last klog has some refinement hints.
415 std::string content;
416 if (readPstoreConsole(content)) {
417 // The toybox reboot command used directly (unlikely)? But also
418 // catches init's response to Android's more controlled reboot command.
419 if (content.rfind("reboot: Power down") != std::string::npos) {
420 ret = "shutdown"; // Still too blunt, but more accurate.
421 // ToDo: init should record the shutdown reason to kernel messages ala:
422 // init: shutdown system with command 'last_reboot_reason'
423 // so that if pstore has persistence we can get some details
424 // that could be missing in last_reboot_reason_property.
425 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700426
Mark Salyzyn64610892017-09-18 10:41:14 -0700427 static const char cmd[] = "reboot: Restarting system with command '";
428 size_t pos = content.rfind(cmd);
429 if (pos != std::string::npos) {
430 pos += strlen(cmd);
431 std::string subReason(content.substr(pos));
432 pos = subReason.find('\'');
433 if (pos != std::string::npos) subReason.erase(pos);
434 if (subReason != "") { // Will not land "reboot" as that is too blunt.
435 if (isKernelRebootReason(subReason)) {
436 ret = "reboot," + subReason; // User space can't talk kernel reasons.
437 } else {
438 ret = subReason;
439 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700440 }
441 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700442
Mark Salyzyn64610892017-09-18 10:41:14 -0700443 // Check for kernel panics, allowed to override reboot command.
444 if (!addKernelPanicSubReason(content, ret) &&
445 // check for long-press power down
446 ((content.rfind("Power held for ") != std::string::npos) ||
447 (content.rfind("charger: [") != std::string::npos))) {
448 ret = "cold";
449 }
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700450 }
451
452 // The following battery test should migrate to a default system health HAL
453
454 // Let us not worry if the reboot command was issued, for the cases of
455 // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard.
456 // Same for bootloader and ro.boot.bootreasons of this set, but a dead
457 // battery could conceivably lead to these, so worthy of override.
458 if (isBluntRebootReason(ret)) {
459 // Heuristic to determine if shutdown possibly because of a dead battery?
460 // Really a hail-mary pass to find it in last klog content ...
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700461 static const int battery_dead_threshold = 2; // percent
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700462 static const char battery[] = "healthd: battery l=";
Mark Salyzyn64610892017-09-18 10:41:14 -0700463 size_t pos = content.rfind(battery); // last one
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700464 if (pos != std::string::npos) {
465 int level = atoi(content.substr(pos + strlen(battery)).c_str());
466 LOG(INFO) << "Battery level at shutdown " << level << "%";
467 if (level <= battery_dead_threshold) {
468 ret = "shutdown,battery";
469 }
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700470 } else { // Most likely
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700471 // Content buffer no longer will have console data. Beware if more
472 // checks added below, that depend on parsing console content.
473 content = "";
474
475 LOG(DEBUG) << "Can not find last low battery in last console messages";
476 android_logcat_context ctx = create_android_logcat();
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700477 FILE* fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d");
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700478 if (fp != nullptr) {
479 android::base::ReadFdToString(fileno(fp), &content);
480 }
481 android_logcat_pclose(&ctx, fp);
482 android_logcat_destroy(&ctx);
483 static const char logcat_battery[] = "W/healthd ( 0): battery l=";
484 const char* match = logcat_battery;
485
486 if (content == "") {
487 // Service logd.klog not running, go to smaller buffer in the kernel.
488 int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0);
489 if (rc > 0) {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700490 ssize_t len = rc + 1024; // 1K Margin should it grow between calls.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700491 std::unique_ptr<char[]> buf(new char[len]);
492 rc = klogctl(KLOG_READ_ALL, buf.get(), len);
493 if (rc < len) {
494 len = rc + 1;
495 }
496 buf[--len] = '\0';
497 content = buf.get();
498 }
499 match = battery;
500 }
501
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700502 pos = content.find(match); // The first one it finds.
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700503 if (pos != std::string::npos) {
504 pos += strlen(match);
505 int level = atoi(content.substr(pos).c_str());
506 LOG(INFO) << "Battery level at startup " << level << "%";
507 if (level <= battery_dead_threshold) {
508 ret = "shutdown,battery";
509 }
510 } else {
511 LOG(DEBUG) << "Can not find first battery level in dmesg or logcat";
512 }
513 }
514 }
515
516 // Is there a controlled shutdown hint in last_reboot_reason_property?
517 if (isBluntRebootReason(ret)) {
518 // Content buffer no longer will have console data. Beware if more
519 // checks added below, that depend on parsing console content.
520 content = GetProperty(last_reboot_reason_property);
521
522 // String is either "reboot,<reason>" or "shutdown,<reason>".
523 // We will set if default reasons, only override with detail if thermal.
Mark Salyzyn08b02562017-09-18 10:07:07 -0700524 if ((android::base::StartsWith(content, ret.c_str()) && (content[ret.length()] == ',')) ||
525 !isBluntRebootReason(content)) {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700526 // Ok, we want it, let's squash it if secondReason is known.
Mark Salyzyn64610892017-09-18 10:41:14 -0700527 size_t pos = content.find(',');
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700528 if (pos != std::string::npos) {
529 ++pos;
530 std::string secondReason(content.substr(pos));
531 ret = isKnownRebootReason(secondReason) ? secondReason : content;
532 } else {
533 ret = content;
534 }
535 }
536 }
537
538 // Other System Health HAL reasons?
539
540 // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to
541 // possibly offer hardware-specific clues from the PMIC.
542 }
543
544 // If unknown left over from above, make it "reboot,<boot_reason>"
545 if (ret == "") {
546 ret = "reboot";
547 if (android::base::StartsWith(reason, "reboot")) {
548 reason = reason.substr(strlen("reboot"));
549 while (reason[0] == ',') {
550 reason = reason.substr(1);
551 }
552 }
553 if (reason != "") {
554 ret += ",";
555 ret += reason;
556 }
557 }
558
559 LOG(INFO) << "Canonical boot reason: " << ret;
560 if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) {
561 // Rewrite as it must be old news, kernel reasons trump user space.
562 SetProperty(last_reboot_reason_property, ret);
563 }
564 return ret;
565}
566
James Hawkinsb9cf7712016-04-08 15:32:19 -0700567// Returns the appropriate metric key prefix for the boot_complete metric such
568// that boot metrics after a system update are labeled as ota_boot_complete;
569// otherwise, they are labeled as boot_complete. This method encapsulates the
570// bookkeeping required to track when a system update has occurred by storing
571// the UTC timestamp of the system build date and comparing against the current
572// system build date.
573std::string CalculateBootCompletePrefix() {
574 static const std::string kBuildDateKey = "build_date";
575 std::string boot_complete_prefix = "boot_complete";
576
577 std::string build_date_str = GetProperty("ro.build.date.utc");
James Hawkins4dded612016-07-28 11:50:23 -0700578 int32_t build_date;
Elliott Hughesda46b392016-10-11 17:09:00 -0700579 if (!android::base::ParseInt(build_date_str, &build_date)) {
James Hawkins4dded612016-07-28 11:50:23 -0700580 return std::string();
581 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700582
583 BootEventRecordStore boot_event_store;
584 BootEventRecordStore::BootEventRecord record;
James Hawkins0bc4ad42017-05-30 15:03:15 -0700585 if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) {
586 boot_complete_prefix = "factory_reset_" + boot_complete_prefix;
587 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700588 LOG(INFO) << "Canonical boot reason: reboot,factory_reset";
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700589 SetProperty(system_reboot_reason_property, "reboot,factory_reset");
590 if (GetProperty(bootloader_reboot_reason_property) == "") {
591 SetProperty(bootloader_reboot_reason_property, "reboot,factory_reset");
592 }
James Hawkins0bc4ad42017-05-30 15:03:15 -0700593 } else if (build_date != record.second) {
James Hawkinsb9cf7712016-04-08 15:32:19 -0700594 boot_complete_prefix = "ota_" + boot_complete_prefix;
595 boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date);
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700596 LOG(INFO) << "Canonical boot reason: reboot,ota";
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700597 SetProperty(system_reboot_reason_property, "reboot,ota");
598 if (GetProperty(bootloader_reboot_reason_property) == "") {
599 SetProperty(bootloader_reboot_reason_property, "reboot,ota");
600 }
James Hawkinsb9cf7712016-04-08 15:32:19 -0700601 }
602
603 return boot_complete_prefix;
604}
605
James Hawkinsef0a0902017-01-06 14:38:23 -0800606// Records the value of a given ro.boottime.init property in milliseconds.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700607void RecordInitBootTimeProp(BootEventRecordStore* boot_event_store, const char* property) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800608 std::string value = GetProperty(property);
609
James Hawkins27c05222017-01-26 11:55:44 -0800610 int32_t time_in_ms;
611 if (android::base::ParseInt(value, &time_in_ms)) {
James Hawkinsef0a0902017-01-06 14:38:23 -0800612 boot_event_store->AddBootEventWithValue(property, time_in_ms);
613 }
614}
615
James Hawkins1bfcaec2017-05-19 14:27:27 -0700616// A map from bootloader timing stage to the time that stage took during boot.
617typedef std::map<std::string, int32_t> BootloaderTimingMap;
618
619// Returns a mapping from bootloader stage names to the time those stages
620// took to boot.
621const BootloaderTimingMap GetBootLoaderTimings() {
622 BootloaderTimingMap timings;
623
624 // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN',
625 // where timeN is in milliseconds.
James Hawkinsbe46fd12017-02-02 16:21:25 -0800626 std::string value = GetProperty("ro.boot.boottime");
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800627 if (value.empty()) {
628 // ro.boot.boottime is not reported on all devices.
James Hawkins1bfcaec2017-05-19 14:27:27 -0700629 return BootloaderTimingMap();
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800630 }
James Hawkinsbe46fd12017-02-02 16:21:25 -0800631
632 auto stages = android::base::Split(value, ",");
James Hawkins1bfcaec2017-05-19 14:27:27 -0700633 for (const auto& stageTiming : stages) {
James Hawkinsbe46fd12017-02-02 16:21:25 -0800634 // |stageTiming| is of the form 'stage:time'.
635 auto stageTimingValues = android::base::Split(stageTiming, ":");
James Hawkins0bc4ad42017-05-30 15:03:15 -0700636 DCHECK_EQ(2U, stageTimingValues.size());
James Hawkinsbe46fd12017-02-02 16:21:25 -0800637
638 std::string stageName = stageTimingValues[0];
639 int32_t time_ms;
640 if (android::base::ParseInt(stageTimingValues[1], &time_ms)) {
James Hawkins1bfcaec2017-05-19 14:27:27 -0700641 timings[stageName] = time_ms;
James Hawkinsbe46fd12017-02-02 16:21:25 -0800642 }
643 }
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800644
James Hawkins1bfcaec2017-05-19 14:27:27 -0700645 return timings;
646}
647
648// Parses and records the set of bootloader stages and associated boot times
649// from the ro.boot.boottime system property.
650void RecordBootloaderTimings(BootEventRecordStore* boot_event_store,
651 const BootloaderTimingMap& bootloader_timings) {
652 int32_t total_time = 0;
653 for (const auto& timing : bootloader_timings) {
654 total_time += timing.second;
655 boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second);
656 }
657
James Hawkins6b5c5aa2017-02-16 11:53:03 -0800658 boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time);
James Hawkinsbe46fd12017-02-02 16:21:25 -0800659}
660
James Hawkins1bfcaec2017-05-19 14:27:27 -0700661// Records the closest estimation to the absolute device boot time, i.e.,
662// from power on to boot_complete, including bootloader times.
663void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store,
664 const BootloaderTimingMap& bootloader_timings,
665 std::chrono::milliseconds uptime) {
666 int32_t bootloader_time_ms = 0;
667
668 for (const auto& timing : bootloader_timings) {
669 if (timing.first.compare("SW") != 0) {
670 bootloader_time_ms += timing.second;
671 }
672 }
673
674 auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms);
675 auto absolute_total =
676 std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime);
677 boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count());
678}
679
James Hawkinsc08e9962016-03-11 14:59:50 -0800680// Records several metrics related to the time it takes to boot the device,
681// including disambiguating boot time on encrypted or non-encrypted devices.
682void RecordBootComplete() {
683 BootEventRecordStore boot_event_store;
James Hawkinsb9cf7712016-04-08 15:32:19 -0700684 BootEventRecordStore::BootEventRecord record;
James Hawkins2d8b3e62016-04-14 14:13:20 -0700685
James Hawkins1bfcaec2017-05-19 14:27:27 -0700686 auto time_since_epoch = android::base::boot_clock::now().time_since_epoch();
687 auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700688 time_t current_time_utc = time(nullptr);
689
690 if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) {
691 time_t last_boot_time_utc = record.second;
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700692 time_t time_since_last_boot = difftime(current_time_utc, last_boot_time_utc);
693 boot_event_store.AddBootEventWithValue("time_since_last_boot", time_since_last_boot);
James Hawkins2d8b3e62016-04-14 14:13:20 -0700694 }
695
696 boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc);
James Hawkinsc08e9962016-03-11 14:59:50 -0800697
James Hawkinsb9cf7712016-04-08 15:32:19 -0700698 // The boot_complete metric has two variants: boot_complete and
699 // ota_boot_complete. The latter signifies that the device is booting after
700 // a system update.
701 std::string boot_complete_prefix = CalculateBootCompletePrefix();
James Hawkins4dded612016-07-28 11:50:23 -0700702 if (boot_complete_prefix.empty()) {
703 // The system is hosed because the build date property could not be read.
704 return;
705 }
James Hawkinsc08e9962016-03-11 14:59:50 -0800706
707 // post_decrypt_time_elapsed is only logged on encrypted devices.
708 if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) {
709 // Log the amount of time elapsed until the device is decrypted, which
710 // includes the variable amount of time the user takes to enter the
711 // decryption password.
James Hawkinse78ea772017-03-24 11:43:02 -0700712 boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800713
714 // Subtract the decryption time to normalize the boot cycle timing.
James Hawkinse78ea772017-03-24 11:43:02 -0700715 std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second);
James Hawkinsb9cf7712016-04-08 15:32:19 -0700716 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt",
James Hawkinse78ea772017-03-24 11:43:02 -0700717 boot_complete.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800718 } else {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700719 boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption", uptime.count());
James Hawkinsc08e9962016-03-11 14:59:50 -0800720 }
721
722 // Record the total time from device startup to boot complete, regardless of
723 // encryption state.
James Hawkinse78ea772017-03-24 11:43:02 -0700724 boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count());
James Hawkinsef0a0902017-01-06 14:38:23 -0800725
726 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init");
727 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux");
728 RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait");
James Hawkinsbe46fd12017-02-02 16:21:25 -0800729
James Hawkins1bfcaec2017-05-19 14:27:27 -0700730 const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings();
731 RecordBootloaderTimings(&boot_event_store, bootloader_timings);
732
733 auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch);
734 RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms);
James Hawkinsc08e9962016-03-11 14:59:50 -0800735}
736
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800737// Records the boot_reason metric by querying the ro.boot.bootreason system
738// property.
739void RecordBootReason() {
Mark Salyzynb304f6d2017-08-04 13:35:51 -0700740 const std::string reason(GetProperty(bootloader_reboot_reason_property));
James Hawkins5240f202017-09-15 16:01:57 -0700741 android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT,
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700742 android::metricslogger::FIELD_PLATFORM_REASON, 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.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700772 android::metricslogger::LogHistogram("factory_reset_current_time_failure",
773 std::abs(current_time_utc));
James Hawkinsfff95ba2016-03-29 16:13:49 -0700774
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.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700777 boot_event_store.AddBootEventWithValue("factory_reset_current_time_failure",
778 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.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700785 boot_event_store.AddBootEventWithValue("factory_reset_current_time", current_time_utc);
James Hawkins0660b302016-03-08 16:18:15 -0800786 }
787
James Hawkins500d7152016-02-16 15:05:54 -0800788 // The factory_reset boot event does not exist after the device is reset, so
789 // use this signal to mark the time of the factory reset.
790 if (!boot_event_store.GetBootEvent("factory_reset", &record)) {
791 boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc);
James Hawkins3bf9b142016-03-03 14:50:24 -0800792
793 // Don't log the time_since_factory_reset until some time has elapsed.
794 // The data is not meaningful yet and skews the histogram buckets.
James Hawkins500d7152016-02-16 15:05:54 -0800795 return;
796 }
797
798 // Calculate and record the difference in time between now and the
799 // factory_reset time.
800 time_t factory_reset_utc = record.second;
James Hawkins9aec9262017-01-31 11:42:24 -0800801 android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700802
James Hawkins9aec9262017-01-31 11:42:24 -0800803 // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram
James Hawkinsfff95ba2016-03-29 16:13:49 -0700804 // is losing records somehow.
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700805 boot_event_store.AddBootEventWithValue("factory_reset_record_value", factory_reset_utc);
James Hawkinsfff95ba2016-03-29 16:13:49 -0700806
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700807 time_t time_since_factory_reset = difftime(current_time_utc, factory_reset_utc);
808 boot_event_store.AddBootEventWithValue("time_since_factory_reset", time_since_factory_reset);
James Hawkins500d7152016-02-16 15:05:54 -0800809}
810
James Hawkinsabd73e62016-01-19 15:10:38 -0800811} // namespace
812
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700813int main(int argc, char** argv) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800814 android::base::InitLogging(argv);
815
816 const std::string cmd_line = GetCommandLine(argc, argv);
817 LOG(INFO) << "Service started: " << cmd_line;
818
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800819 int option_index = 0;
James Hawkinsc6275582016-03-22 10:47:44 -0700820 static const char value_str[] = "value";
James Hawkinsc08e9962016-03-11 14:59:50 -0800821 static const char boot_complete_str[] = "record_boot_complete";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800822 static const char boot_reason_str[] = "record_boot_reason";
James Hawkins53684ea2016-02-23 16:18:19 -0800823 static const char factory_reset_str[] = "record_time_since_factory_reset";
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800824 static const struct option long_options[] = {
Mark Salyzyn14b1e6d2017-09-18 10:41:14 -0700825 // clang-format off
826 { "help", no_argument, NULL, 'h' },
827 { "log", no_argument, NULL, 'l' },
828 { "print", no_argument, NULL, 'p' },
829 { "record", required_argument, NULL, 'r' },
830 { value_str, required_argument, NULL, 0 },
831 { boot_complete_str, no_argument, NULL, 0 },
832 { boot_reason_str, no_argument, NULL, 0 },
833 { factory_reset_str, no_argument, NULL, 0 },
834 { NULL, 0, NULL, 0 }
835 // clang-format on
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800836 };
837
James Hawkinsc6275582016-03-22 10:47:44 -0700838 std::string boot_event;
839 std::string value;
James Hawkinsabd73e62016-01-19 15:10:38 -0800840 int opt = 0;
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800841 while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) {
James Hawkinsabd73e62016-01-19 15:10:38 -0800842 switch (opt) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800843 // This case handles long options which have no single-character mapping.
844 case 0: {
845 const std::string option_name = long_options[option_index].name;
James Hawkinsc6275582016-03-22 10:47:44 -0700846 if (option_name == value_str) {
847 // |optarg| is an external variable set by getopt representing
848 // the option argument.
849 value = optarg;
850 } else if (option_name == boot_complete_str) {
James Hawkinsc08e9962016-03-11 14:59:50 -0800851 RecordBootComplete();
852 } else if (option_name == boot_reason_str) {
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800853 RecordBootReason();
James Hawkins500d7152016-02-16 15:05:54 -0800854 } else if (option_name == factory_reset_str) {
855 RecordFactoryReset();
James Hawkinsa4a1a4a2016-02-09 15:32:38 -0800856 } else {
857 LOG(ERROR) << "Invalid option: " << option_name;
858 }
859 break;
860 }
861
James Hawkinsabd73e62016-01-19 15:10:38 -0800862 case 'h': {
863 ShowHelp(argv[0]);
864 break;
865 }
866
867 case 'l': {
868 LogBootEvents();
869 break;
870 }
871
872 case 'p': {
873 PrintBootEvents();
874 break;
875 }
876
877 case 'r': {
878 // |optarg| is an external variable set by getopt representing
879 // the option argument.
James Hawkinsc6275582016-03-22 10:47:44 -0700880 boot_event = optarg;
James Hawkinsabd73e62016-01-19 15:10:38 -0800881 break;
882 }
883
884 default: {
885 DCHECK_EQ(opt, '?');
886
887 // |optopt| is an external variable set by getopt representing
888 // the value of the invalid option.
889 LOG(ERROR) << "Invalid option: " << optopt;
890 ShowHelp(argv[0]);
891 return EXIT_FAILURE;
892 }
893 }
894 }
895
James Hawkinsc6275582016-03-22 10:47:44 -0700896 if (!boot_event.empty()) {
897 RecordBootEventFromCommandLine(boot_event, value);
898 }
899
James Hawkinsabd73e62016-01-19 15:10:38 -0800900 return 0;
901}