James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 1 | /* |
| 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 Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 21 | #include <getopt.h> |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 22 | #include <sys/klog.h> |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 23 | #include <unistd.h> |
Mark Salyzyn | ff2dcd9 | 2016-09-28 15:54:45 -0700 | [diff] [blame] | 24 | |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 25 | #include <chrono> |
James Hawkins | 0660b30 | 2016-03-08 16:18:15 -0800 | [diff] [blame] | 26 | #include <cmath> |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 27 | #include <cstddef> |
| 28 | #include <cstdio> |
James Hawkins | 500d715 | 2016-02-16 15:05:54 -0800 | [diff] [blame] | 29 | #include <ctime> |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 30 | #include <map> |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 31 | #include <memory> |
| 32 | #include <string> |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 33 | #include <vector> |
Mark Salyzyn | ff2dcd9 | 2016-09-28 15:54:45 -0700 | [diff] [blame] | 34 | |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 35 | #include <android-base/chrono_utils.h> |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 36 | #include <android-base/file.h> |
James Hawkins | eabe08b | 2016-01-19 16:54:35 -0800 | [diff] [blame] | 37 | #include <android-base/logging.h> |
James Hawkins | 4dded61 | 2016-07-28 11:50:23 -0700 | [diff] [blame] | 38 | #include <android-base/parseint.h> |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 39 | #include <android-base/strings.h> |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 40 | #include <android/log.h> |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 41 | #include <cutils/android_reboot.h> |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 42 | #include <cutils/properties.h> |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 43 | #include <log/logcat.h> |
James Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 44 | #include <metricslogger/metrics_logger.h> |
Mark Salyzyn | ff2dcd9 | 2016-09-28 15:54:45 -0700 | [diff] [blame] | 45 | |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 46 | #include "boot_event_record_store.h" |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 47 | |
| 48 | namespace { |
| 49 | |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 50 | // Scans the boot event record store for record files and logs each boot event |
| 51 | // via EventLog. |
| 52 | void 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 Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 57 | android::metricslogger::LogHistogram(i->first, i->second); |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 58 | } |
| 59 | } |
| 60 | |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 61 | // 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 Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 64 | void RecordBootEventFromCommandLine(const std::string& event, const std::string& value_str) { |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 65 | BootEventRecordStore boot_event_store; |
| 66 | if (!value_str.empty()) { |
| 67 | int32_t value = 0; |
Elliott Hughes | da46b39 | 2016-10-11 17:09:00 -0700 | [diff] [blame] | 68 | if (android::base::ParseInt(value_str, &value)) { |
James Hawkins | 4dded61 | 2016-07-28 11:50:23 -0700 | [diff] [blame] | 69 | boot_event_store.AddBootEventWithValue(event, value); |
| 70 | } |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 71 | } else { |
| 72 | boot_event_store.AddBootEvent(event); |
| 73 | } |
| 74 | } |
| 75 | |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 76 | void 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 Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 87 | void ShowHelp(const char* cmd) { |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 88 | fprintf(stderr, "Usage: %s [options]\n", cmd); |
| 89 | fprintf(stderr, |
| 90 | "options include:\n" |
Yongqin Liu | 78b2b94 | 2017-07-07 13:26:49 +0800 | [diff] [blame] | 91 | " -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 Hawkins | 53684ea | 2016-02-23 16:18:19 -0800 | [diff] [blame] | 98 | " --record_time_since_factory_reset Record the time since the device was reset\n"); |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 99 | } |
| 100 | |
| 101 | // Constructs a readable, printable string from the givencommand line |
| 102 | // arguments. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 103 | std::string GetCommandLine(int argc, char** argv) { |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 104 | 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 Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 113 | // Convenience wrapper over the property API that returns an |
| 114 | // std::string. |
| 115 | std::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 Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 124 | void SetProperty(const char* key, const std::string& val) { |
| 125 | property_set(key, val.c_str()); |
| 126 | } |
| 127 | |
| 128 | void SetProperty(const char* key, const char* val) { |
| 129 | property_set(key, val); |
| 130 | } |
| 131 | |
James Hawkins | 25f7122 | 2017-10-10 16:37:05 -0700 | [diff] [blame] | 132 | constexpr int32_t kEmptyBootReason = 0; |
James Hawkins | 6f74c0b | 2016-02-12 15:49:16 -0800 | [diff] [blame] | 133 | constexpr int32_t kUnknownBootReason = 1; |
| 134 | |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 135 | // 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 Hawkins | 6f74c0b | 2016-02-12 15:49:16 -0800 | [diff] [blame] | 139 | const std::map<std::string, int32_t> kBootReasonMap = { |
James Hawkins | 25f7122 | 2017-10-10 16:37:05 -0700 | [diff] [blame] | 140 | {"empty", kEmptyBootReason}, |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 141 | {"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 Salyzyn | 9033bf5 | 2017-09-21 11:30:29 -0700 | [diff] [blame] | 208 | {"reboot,userrequested", 68}, |
Mark Salyzyn | 161b862 | 2017-09-26 08:26:12 -0700 | [diff] [blame] | 209 | {"shutdown,container", 69}, // Host OS asking Android Container to shutdown |
Mark Salyzyn | 243fa29 | 2017-10-11 09:02:04 -0700 | [diff] [blame] | 210 | {"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 Hawkins | 34073b5 | 2017-10-17 15:53:27 -0700 | [diff] [blame] | 215 | {"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 Salyzyn | cabbe4f | 2017-10-23 13:52:39 -0700 | [diff] [blame] | 226 | {"reboot,2sec", 86}, |
Mark Salyzyn | c89f9da | 2017-10-24 15:35:34 -0700 | [diff] [blame] | 227 | {"shutdown,thermal,battery", 87}, |
Mark Salyzyn | 72a8ea3 | 2017-10-25 09:23:19 -0700 | [diff] [blame] | 228 | {"reboot,its_just_so_hard", 88}, // produced by boot_reason_test |
| 229 | {"reboot,Its Just So Hard", 89}, // produced by boot_reason_test |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 230 | }; |
| 231 | |
| 232 | // Converts a string value representing the reason the system booted to an |
| 233 | // integer representation. This is necessary for logging the boot_reason metric |
| 234 | // via Tron, which does not accept non-integer buckets in histograms. |
| 235 | int32_t BootReasonStrToEnum(const std::string& boot_reason) { |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 236 | auto mapping = kBootReasonMap.find(boot_reason); |
| 237 | if (mapping != kBootReasonMap.end()) { |
| 238 | return mapping->second; |
| 239 | } |
| 240 | |
James Hawkins | 25f7122 | 2017-10-10 16:37:05 -0700 | [diff] [blame] | 241 | if (boot_reason.empty()) { |
| 242 | return kEmptyBootReason; |
| 243 | } |
| 244 | |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 245 | LOG(INFO) << "Unknown boot reason: " << boot_reason; |
| 246 | return kUnknownBootReason; |
| 247 | } |
| 248 | |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 249 | // Canonical list of supported primary reboot reasons. |
| 250 | const std::vector<const std::string> knownReasons = { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 251 | // clang-format off |
| 252 | // kernel |
| 253 | "watchdog", |
| 254 | "kernel_panic", |
| 255 | // strong |
| 256 | "recovery", // Should not happen from ro.boot.bootreason |
| 257 | "bootloader", // Should not happen from ro.boot.bootreason |
| 258 | // blunt |
| 259 | "cold", |
| 260 | "hard", |
| 261 | "warm", |
Mark Salyzyn | 6290982 | 2017-10-09 09:27:16 -0700 | [diff] [blame] | 262 | // super blunt |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 263 | "shutdown", // Can not happen from ro.boot.bootreason |
| 264 | "reboot", // Default catch-all for anything unknown |
| 265 | // clang-format on |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 266 | }; |
| 267 | |
| 268 | // Returns true if the supplied reason prefix is considered detailed enough. |
| 269 | bool isStrongRebootReason(const std::string& r) { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 270 | for (auto& s : knownReasons) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 271 | if (s == "cold") break; |
| 272 | // Prefix defined as terminated by a nul or comma (,). |
| 273 | if (android::base::StartsWith(r, s.c_str()) && |
| 274 | ((r.length() == s.length()) || (r[s.length()] == ','))) { |
| 275 | return true; |
| 276 | } |
| 277 | } |
| 278 | return false; |
| 279 | } |
| 280 | |
| 281 | // Returns true if the supplied reason prefix is associated with the kernel. |
| 282 | bool isKernelRebootReason(const std::string& r) { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 283 | for (auto& s : knownReasons) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 284 | if (s == "recovery") break; |
| 285 | // Prefix defined as terminated by a nul or comma (,). |
| 286 | if (android::base::StartsWith(r, s.c_str()) && |
| 287 | ((r.length() == s.length()) || (r[s.length()] == ','))) { |
| 288 | return true; |
| 289 | } |
| 290 | } |
| 291 | return false; |
| 292 | } |
| 293 | |
| 294 | // Returns true if the supplied reason prefix is considered known. |
| 295 | bool isKnownRebootReason(const std::string& r) { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 296 | for (auto& s : knownReasons) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 297 | // Prefix defined as terminated by a nul or comma (,). |
| 298 | if (android::base::StartsWith(r, s.c_str()) && |
| 299 | ((r.length() == s.length()) || (r[s.length()] == ','))) { |
| 300 | return true; |
| 301 | } |
| 302 | } |
| 303 | return false; |
| 304 | } |
| 305 | |
| 306 | // If the reboot reason should be improved, report true if is too blunt. |
| 307 | bool isBluntRebootReason(const std::string& r) { |
| 308 | if (isStrongRebootReason(r)) return false; |
| 309 | |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 310 | if (!isKnownRebootReason(r)) return true; // Can not support unknown as detail |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 311 | |
| 312 | size_t pos = 0; |
| 313 | while ((pos = r.find(',', pos)) != std::string::npos) { |
| 314 | ++pos; |
| 315 | std::string next(r.substr(pos)); |
| 316 | if (next.length() == 0) break; |
| 317 | if (next[0] == ',') continue; |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 318 | if (!isKnownRebootReason(next)) return false; // Unknown subreason is good. |
| 319 | if (isStrongRebootReason(next)) return false; // eg: reboot,reboot |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 320 | } |
| 321 | return true; |
| 322 | } |
| 323 | |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 324 | bool readPstoreConsole(std::string& console) { |
| 325 | if (android::base::ReadFileToString("/sys/fs/pstore/console-ramoops-0", &console)) { |
| 326 | return true; |
| 327 | } |
| 328 | return android::base::ReadFileToString("/sys/fs/pstore/console-ramoops", &console); |
| 329 | } |
| 330 | |
| 331 | bool addKernelPanicSubReason(const std::string& console, std::string& ret) { |
| 332 | // Check for kernel panic types to refine information |
| 333 | if (console.rfind("SysRq : Trigger a crash") != std::string::npos) { |
| 334 | // Can not happen, except on userdebug, during testing/debugging. |
| 335 | ret = "kernel_panic,sysrq"; |
| 336 | return true; |
| 337 | } |
| 338 | if (console.rfind("Unable to handle kernel NULL pointer dereference at virtual address") != |
| 339 | std::string::npos) { |
| 340 | ret = "kernel_panic,NULL"; |
| 341 | return true; |
| 342 | } |
| 343 | if (console.rfind("Kernel BUG at ") != std::string::npos) { |
| 344 | ret = "kernel_panic,BUG"; |
| 345 | return true; |
| 346 | } |
| 347 | return false; |
| 348 | } |
| 349 | |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 350 | // std::transform Helper callback functions: |
| 351 | // Converts a string value representing the reason the system booted to a |
| 352 | // string complying with Android system standard reason. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 353 | char tounderline(char c) { |
| 354 | return ::isblank(c) ? '_' : c; |
| 355 | } |
Mark Salyzyn | 88d692c | 2017-09-20 08:37:46 -0700 | [diff] [blame] | 356 | |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 357 | char toprintable(char c) { |
| 358 | return ::isprint(c) ? c : '?'; |
| 359 | } |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 360 | |
Mark Salyzyn | 88d692c | 2017-09-20 08:37:46 -0700 | [diff] [blame] | 361 | // Cleanup boot_reason regarding acceptable character set |
| 362 | void transformReason(std::string& reason) { |
| 363 | std::transform(reason.begin(), reason.end(), reason.begin(), ::tolower); |
| 364 | std::transform(reason.begin(), reason.end(), reason.begin(), tounderline); |
| 365 | std::transform(reason.begin(), reason.end(), reason.begin(), toprintable); |
| 366 | } |
| 367 | |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 368 | const char system_reboot_reason_property[] = "sys.boot.reason"; |
| 369 | const char last_reboot_reason_property[] = LAST_REBOOT_REASON_PROPERTY; |
| 370 | const char bootloader_reboot_reason_property[] = "ro.boot.bootreason"; |
| 371 | |
| 372 | // Scrub, Sanitize, Standardize and Enhance the boot reason string supplied. |
| 373 | std::string BootReasonStrToReason(const std::string& boot_reason) { |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 374 | static const size_t max_reason_length = 256; |
| 375 | |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 376 | std::string ret(GetProperty(system_reboot_reason_property)); |
| 377 | std::string reason(boot_reason); |
| 378 | // If sys.boot.reason == ro.boot.bootreason, let's re-evaluate |
| 379 | if (reason == ret) ret = ""; |
| 380 | |
Mark Salyzyn | 88d692c | 2017-09-20 08:37:46 -0700 | [diff] [blame] | 381 | transformReason(reason); |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 382 | |
| 383 | // Is the current system boot reason sys.boot.reason valid? |
| 384 | if (!isKnownRebootReason(ret)) ret = ""; |
| 385 | |
| 386 | if (ret == "") { |
| 387 | // Is the bootloader boot reason ro.boot.bootreason known? |
| 388 | std::vector<std::string> words(android::base::Split(reason, ",_-")); |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 389 | for (auto& s : knownReasons) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 390 | std::string blunt; |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 391 | for (auto& r : words) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 392 | if (r == s) { |
| 393 | if (isBluntRebootReason(s)) { |
| 394 | blunt = s; |
| 395 | } else { |
| 396 | ret = s; |
| 397 | break; |
| 398 | } |
| 399 | } |
| 400 | } |
| 401 | if (ret == "") ret = blunt; |
| 402 | if (ret != "") break; |
| 403 | } |
| 404 | } |
| 405 | |
| 406 | if (ret == "") { |
| 407 | // A series of checks to take some officially unsupported reasons |
| 408 | // reported by the bootloader and find some logical and canonical |
| 409 | // sense. In an ideal world, we would require those bootloaders |
| 410 | // to behave and follow our standards. |
| 411 | static const std::vector<std::pair<const std::string, const std::string>> aliasReasons = { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 412 | {"watchdog", "wdog"}, |
| 413 | {"cold,powerkey", "powerkey"}, |
| 414 | {"kernel_panic", "panic"}, |
| 415 | {"shutdown,thermal", "thermal"}, |
| 416 | {"warm,s3_wakeup", "s3_wakeup"}, |
| 417 | {"hard,hw_reset", "hw_reset"}, |
Mark Salyzyn | cabbe4f | 2017-10-23 13:52:39 -0700 | [diff] [blame] | 418 | {"reboot,2sec", "2sec_reboot"}, |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 419 | {"bootloader", ""}, |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 420 | }; |
| 421 | |
| 422 | // Either the primary or alias is found _somewhere_ in the reason string. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 423 | for (auto& s : aliasReasons) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 424 | if (reason.find(s.first) != std::string::npos) { |
| 425 | ret = s.first; |
| 426 | break; |
| 427 | } |
| 428 | if (s.second.size() && (reason.find(s.second) != std::string::npos)) { |
| 429 | ret = s.first; |
| 430 | break; |
| 431 | } |
| 432 | } |
| 433 | } |
| 434 | |
| 435 | // If watchdog is the reason, see if there is a security angle? |
| 436 | if (ret == "watchdog") { |
| 437 | if (reason.find("sec") != std::string::npos) { |
| 438 | ret += ",security"; |
| 439 | } |
| 440 | } |
| 441 | |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 442 | if (ret == "kernel_panic") { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 443 | // Check to see if last klog has some refinement hints. |
| 444 | std::string content; |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 445 | if (readPstoreConsole(content)) { |
| 446 | addKernelPanicSubReason(content, ret); |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 447 | } |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 448 | } else if (isBluntRebootReason(ret)) { |
| 449 | // Check the other available reason resources if the reason is still blunt. |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 450 | |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 451 | // Check to see if last klog has some refinement hints. |
| 452 | std::string content; |
| 453 | if (readPstoreConsole(content)) { |
| 454 | // The toybox reboot command used directly (unlikely)? But also |
| 455 | // catches init's response to Android's more controlled reboot command. |
| 456 | if (content.rfind("reboot: Power down") != std::string::npos) { |
| 457 | ret = "shutdown"; // Still too blunt, but more accurate. |
| 458 | // ToDo: init should record the shutdown reason to kernel messages ala: |
| 459 | // init: shutdown system with command 'last_reboot_reason' |
| 460 | // so that if pstore has persistence we can get some details |
| 461 | // that could be missing in last_reboot_reason_property. |
| 462 | } |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 463 | |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 464 | static const char cmd[] = "reboot: Restarting system with command '"; |
| 465 | size_t pos = content.rfind(cmd); |
| 466 | if (pos != std::string::npos) { |
| 467 | pos += strlen(cmd); |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 468 | std::string subReason(content.substr(pos, max_reason_length)); |
| 469 | for (pos = 0; pos < subReason.length(); ++pos) { |
Mark Salyzyn | 88d692c | 2017-09-20 08:37:46 -0700 | [diff] [blame] | 470 | char c = subReason[pos]; |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 471 | if (!::isprint(c) || (c == '\'')) { |
| 472 | subReason.erase(pos); |
| 473 | break; |
| 474 | } |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 475 | } |
Mark Salyzyn | 88d692c | 2017-09-20 08:37:46 -0700 | [diff] [blame] | 476 | transformReason(subReason); |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 477 | if (subReason != "") { // Will not land "reboot" as that is too blunt. |
| 478 | if (isKernelRebootReason(subReason)) { |
| 479 | ret = "reboot," + subReason; // User space can't talk kernel reasons. |
Mark Salyzyn | dafced9 | 2017-09-20 08:37:46 -0700 | [diff] [blame^] | 480 | } else if (isKnownRebootReason(subReason)) { |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 481 | ret = subReason; |
Mark Salyzyn | dafced9 | 2017-09-20 08:37:46 -0700 | [diff] [blame^] | 482 | } else { |
| 483 | ret = "reboot," + subReason; // legitimize unknown reasons |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 484 | } |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 485 | } |
| 486 | } |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 487 | |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 488 | // Check for kernel panics, allowed to override reboot command. |
| 489 | if (!addKernelPanicSubReason(content, ret) && |
| 490 | // check for long-press power down |
| 491 | ((content.rfind("Power held for ") != std::string::npos) || |
| 492 | (content.rfind("charger: [") != std::string::npos))) { |
| 493 | ret = "cold"; |
| 494 | } |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 495 | } |
| 496 | |
| 497 | // The following battery test should migrate to a default system health HAL |
| 498 | |
| 499 | // Let us not worry if the reboot command was issued, for the cases of |
| 500 | // reboot -p, reboot <no reason>, reboot cold, reboot warm and reboot hard. |
| 501 | // Same for bootloader and ro.boot.bootreasons of this set, but a dead |
| 502 | // battery could conceivably lead to these, so worthy of override. |
| 503 | if (isBluntRebootReason(ret)) { |
| 504 | // Heuristic to determine if shutdown possibly because of a dead battery? |
| 505 | // Really a hail-mary pass to find it in last klog content ... |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 506 | static const int battery_dead_threshold = 2; // percent |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 507 | static const char battery[] = "healthd: battery l="; |
Mark Salyzyn | 6461089 | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 508 | size_t pos = content.rfind(battery); // last one |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 509 | std::string digits; |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 510 | if (pos != std::string::npos) { |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 511 | digits = content.substr(pos + strlen(battery)); |
| 512 | } |
| 513 | char* endptr = NULL; |
| 514 | unsigned long long level = strtoull(digits.c_str(), &endptr, 10); |
| 515 | if ((level <= 100) && (endptr != digits.c_str()) && (*endptr == ' ')) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 516 | LOG(INFO) << "Battery level at shutdown " << level << "%"; |
| 517 | if (level <= battery_dead_threshold) { |
| 518 | ret = "shutdown,battery"; |
| 519 | } |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 520 | } else { // Most likely |
| 521 | digits = ""; // reset digits |
| 522 | |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 523 | // Content buffer no longer will have console data. Beware if more |
| 524 | // checks added below, that depend on parsing console content. |
| 525 | content = ""; |
| 526 | |
| 527 | LOG(DEBUG) << "Can not find last low battery in last console messages"; |
| 528 | android_logcat_context ctx = create_android_logcat(); |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 529 | FILE* fp = android_logcat_popen(&ctx, "logcat -b kernel -v brief -d"); |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 530 | if (fp != nullptr) { |
| 531 | android::base::ReadFdToString(fileno(fp), &content); |
| 532 | } |
| 533 | android_logcat_pclose(&ctx, fp); |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 534 | static const char logcat_battery[] = "W/healthd ( 0): battery l="; |
| 535 | const char* match = logcat_battery; |
| 536 | |
| 537 | if (content == "") { |
| 538 | // Service logd.klog not running, go to smaller buffer in the kernel. |
| 539 | int rc = klogctl(KLOG_SIZE_BUFFER, nullptr, 0); |
| 540 | if (rc > 0) { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 541 | ssize_t len = rc + 1024; // 1K Margin should it grow between calls. |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 542 | std::unique_ptr<char[]> buf(new char[len]); |
| 543 | rc = klogctl(KLOG_READ_ALL, buf.get(), len); |
| 544 | if (rc < len) { |
| 545 | len = rc + 1; |
| 546 | } |
| 547 | buf[--len] = '\0'; |
| 548 | content = buf.get(); |
| 549 | } |
| 550 | match = battery; |
| 551 | } |
| 552 | |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 553 | pos = content.find(match); // The first one it finds. |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 554 | if (pos != std::string::npos) { |
Mark Salyzyn | a16e437 | 2017-09-20 08:36:12 -0700 | [diff] [blame] | 555 | digits = content.substr(pos + strlen(match)); |
| 556 | } |
| 557 | endptr = NULL; |
| 558 | level = strtoull(digits.c_str(), &endptr, 10); |
| 559 | if ((level <= 100) && (endptr != digits.c_str()) && (*endptr == ' ')) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 560 | LOG(INFO) << "Battery level at startup " << level << "%"; |
| 561 | if (level <= battery_dead_threshold) { |
| 562 | ret = "shutdown,battery"; |
| 563 | } |
| 564 | } else { |
| 565 | LOG(DEBUG) << "Can not find first battery level in dmesg or logcat"; |
| 566 | } |
| 567 | } |
| 568 | } |
| 569 | |
| 570 | // Is there a controlled shutdown hint in last_reboot_reason_property? |
| 571 | if (isBluntRebootReason(ret)) { |
| 572 | // Content buffer no longer will have console data. Beware if more |
| 573 | // checks added below, that depend on parsing console content. |
| 574 | content = GetProperty(last_reboot_reason_property); |
Mark Salyzyn | 88d692c | 2017-09-20 08:37:46 -0700 | [diff] [blame] | 575 | transformReason(content); |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 576 | |
Mark Salyzyn | 6290982 | 2017-10-09 09:27:16 -0700 | [diff] [blame] | 577 | // Anything in last is better than 'super-blunt' reboot or shutdown. |
| 578 | if ((ret == "") || (ret == "reboot") || (ret == "shutdown") || !isBluntRebootReason(content)) { |
| 579 | ret = content; |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 580 | } |
| 581 | } |
| 582 | |
| 583 | // Other System Health HAL reasons? |
| 584 | |
| 585 | // ToDo: /proc/sys/kernel/boot_reason needs a HAL interface to |
| 586 | // possibly offer hardware-specific clues from the PMIC. |
| 587 | } |
| 588 | |
| 589 | // If unknown left over from above, make it "reboot,<boot_reason>" |
| 590 | if (ret == "") { |
| 591 | ret = "reboot"; |
| 592 | if (android::base::StartsWith(reason, "reboot")) { |
| 593 | reason = reason.substr(strlen("reboot")); |
Mark Salyzyn | 0af71a5 | 2017-10-05 13:58:04 -0700 | [diff] [blame] | 594 | while ((reason[0] == ',') || (reason[0] == '_')) { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 595 | reason = reason.substr(1); |
| 596 | } |
| 597 | } |
| 598 | if (reason != "") { |
| 599 | ret += ","; |
| 600 | ret += reason; |
| 601 | } |
| 602 | } |
| 603 | |
| 604 | LOG(INFO) << "Canonical boot reason: " << ret; |
| 605 | if (isKernelRebootReason(ret) && (GetProperty(last_reboot_reason_property) != "")) { |
| 606 | // Rewrite as it must be old news, kernel reasons trump user space. |
| 607 | SetProperty(last_reboot_reason_property, ret); |
| 608 | } |
| 609 | return ret; |
| 610 | } |
| 611 | |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 612 | // Returns the appropriate metric key prefix for the boot_complete metric such |
| 613 | // that boot metrics after a system update are labeled as ota_boot_complete; |
| 614 | // otherwise, they are labeled as boot_complete. This method encapsulates the |
| 615 | // bookkeeping required to track when a system update has occurred by storing |
| 616 | // the UTC timestamp of the system build date and comparing against the current |
| 617 | // system build date. |
| 618 | std::string CalculateBootCompletePrefix() { |
| 619 | static const std::string kBuildDateKey = "build_date"; |
| 620 | std::string boot_complete_prefix = "boot_complete"; |
| 621 | |
| 622 | std::string build_date_str = GetProperty("ro.build.date.utc"); |
James Hawkins | 4dded61 | 2016-07-28 11:50:23 -0700 | [diff] [blame] | 623 | int32_t build_date; |
Elliott Hughes | da46b39 | 2016-10-11 17:09:00 -0700 | [diff] [blame] | 624 | if (!android::base::ParseInt(build_date_str, &build_date)) { |
James Hawkins | 4dded61 | 2016-07-28 11:50:23 -0700 | [diff] [blame] | 625 | return std::string(); |
| 626 | } |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 627 | |
| 628 | BootEventRecordStore boot_event_store; |
| 629 | BootEventRecordStore::BootEventRecord record; |
James Hawkins | 0bc4ad4 | 2017-05-30 15:03:15 -0700 | [diff] [blame] | 630 | if (!boot_event_store.GetBootEvent(kBuildDateKey, &record)) { |
| 631 | boot_complete_prefix = "factory_reset_" + boot_complete_prefix; |
| 632 | boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date); |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 633 | LOG(INFO) << "Canonical boot reason: reboot,factory_reset"; |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 634 | SetProperty(system_reboot_reason_property, "reboot,factory_reset"); |
James Hawkins | 0bc4ad4 | 2017-05-30 15:03:15 -0700 | [diff] [blame] | 635 | } else if (build_date != record.second) { |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 636 | boot_complete_prefix = "ota_" + boot_complete_prefix; |
| 637 | boot_event_store.AddBootEventWithValue(kBuildDateKey, build_date); |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 638 | LOG(INFO) << "Canonical boot reason: reboot,ota"; |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 639 | SetProperty(system_reboot_reason_property, "reboot,ota"); |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 640 | } |
| 641 | |
| 642 | return boot_complete_prefix; |
| 643 | } |
| 644 | |
James Hawkins | ef0a090 | 2017-01-06 14:38:23 -0800 | [diff] [blame] | 645 | // Records the value of a given ro.boottime.init property in milliseconds. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 646 | void RecordInitBootTimeProp(BootEventRecordStore* boot_event_store, const char* property) { |
James Hawkins | ef0a090 | 2017-01-06 14:38:23 -0800 | [diff] [blame] | 647 | std::string value = GetProperty(property); |
| 648 | |
James Hawkins | 27c0522 | 2017-01-26 11:55:44 -0800 | [diff] [blame] | 649 | int32_t time_in_ms; |
| 650 | if (android::base::ParseInt(value, &time_in_ms)) { |
James Hawkins | ef0a090 | 2017-01-06 14:38:23 -0800 | [diff] [blame] | 651 | boot_event_store->AddBootEventWithValue(property, time_in_ms); |
| 652 | } |
| 653 | } |
| 654 | |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 655 | // A map from bootloader timing stage to the time that stage took during boot. |
| 656 | typedef std::map<std::string, int32_t> BootloaderTimingMap; |
| 657 | |
| 658 | // Returns a mapping from bootloader stage names to the time those stages |
| 659 | // took to boot. |
| 660 | const BootloaderTimingMap GetBootLoaderTimings() { |
| 661 | BootloaderTimingMap timings; |
| 662 | |
| 663 | // |ro.boot.boottime| is of the form 'stage1:time1,...,stageN:timeN', |
| 664 | // where timeN is in milliseconds. |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 665 | std::string value = GetProperty("ro.boot.boottime"); |
James Hawkins | 6b5c5aa | 2017-02-16 11:53:03 -0800 | [diff] [blame] | 666 | if (value.empty()) { |
| 667 | // ro.boot.boottime is not reported on all devices. |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 668 | return BootloaderTimingMap(); |
James Hawkins | 6b5c5aa | 2017-02-16 11:53:03 -0800 | [diff] [blame] | 669 | } |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 670 | |
| 671 | auto stages = android::base::Split(value, ","); |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 672 | for (const auto& stageTiming : stages) { |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 673 | // |stageTiming| is of the form 'stage:time'. |
| 674 | auto stageTimingValues = android::base::Split(stageTiming, ":"); |
James Hawkins | 0bc4ad4 | 2017-05-30 15:03:15 -0700 | [diff] [blame] | 675 | DCHECK_EQ(2U, stageTimingValues.size()); |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 676 | |
| 677 | std::string stageName = stageTimingValues[0]; |
| 678 | int32_t time_ms; |
| 679 | if (android::base::ParseInt(stageTimingValues[1], &time_ms)) { |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 680 | timings[stageName] = time_ms; |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 681 | } |
| 682 | } |
James Hawkins | 6b5c5aa | 2017-02-16 11:53:03 -0800 | [diff] [blame] | 683 | |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 684 | return timings; |
| 685 | } |
| 686 | |
| 687 | // Parses and records the set of bootloader stages and associated boot times |
| 688 | // from the ro.boot.boottime system property. |
| 689 | void RecordBootloaderTimings(BootEventRecordStore* boot_event_store, |
| 690 | const BootloaderTimingMap& bootloader_timings) { |
| 691 | int32_t total_time = 0; |
| 692 | for (const auto& timing : bootloader_timings) { |
| 693 | total_time += timing.second; |
| 694 | boot_event_store->AddBootEventWithValue("boottime.bootloader." + timing.first, timing.second); |
| 695 | } |
| 696 | |
James Hawkins | 6b5c5aa | 2017-02-16 11:53:03 -0800 | [diff] [blame] | 697 | boot_event_store->AddBootEventWithValue("boottime.bootloader.total", total_time); |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 698 | } |
| 699 | |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 700 | // Records the closest estimation to the absolute device boot time, i.e., |
| 701 | // from power on to boot_complete, including bootloader times. |
| 702 | void RecordAbsoluteBootTime(BootEventRecordStore* boot_event_store, |
| 703 | const BootloaderTimingMap& bootloader_timings, |
| 704 | std::chrono::milliseconds uptime) { |
| 705 | int32_t bootloader_time_ms = 0; |
| 706 | |
| 707 | for (const auto& timing : bootloader_timings) { |
| 708 | if (timing.first.compare("SW") != 0) { |
| 709 | bootloader_time_ms += timing.second; |
| 710 | } |
| 711 | } |
| 712 | |
| 713 | auto bootloader_duration = std::chrono::milliseconds(bootloader_time_ms); |
| 714 | auto absolute_total = |
| 715 | std::chrono::duration_cast<std::chrono::seconds>(bootloader_duration + uptime); |
| 716 | boot_event_store->AddBootEventWithValue("absolute_boot_time", absolute_total.count()); |
| 717 | } |
| 718 | |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 719 | // Records several metrics related to the time it takes to boot the device, |
| 720 | // including disambiguating boot time on encrypted or non-encrypted devices. |
| 721 | void RecordBootComplete() { |
| 722 | BootEventRecordStore boot_event_store; |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 723 | BootEventRecordStore::BootEventRecord record; |
James Hawkins | 2d8b3e6 | 2016-04-14 14:13:20 -0700 | [diff] [blame] | 724 | |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 725 | auto time_since_epoch = android::base::boot_clock::now().time_since_epoch(); |
| 726 | auto uptime = std::chrono::duration_cast<std::chrono::seconds>(time_since_epoch); |
James Hawkins | 2d8b3e6 | 2016-04-14 14:13:20 -0700 | [diff] [blame] | 727 | time_t current_time_utc = time(nullptr); |
| 728 | |
| 729 | if (boot_event_store.GetBootEvent("last_boot_time_utc", &record)) { |
| 730 | time_t last_boot_time_utc = record.second; |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 731 | time_t time_since_last_boot = difftime(current_time_utc, last_boot_time_utc); |
| 732 | boot_event_store.AddBootEventWithValue("time_since_last_boot", time_since_last_boot); |
James Hawkins | 2d8b3e6 | 2016-04-14 14:13:20 -0700 | [diff] [blame] | 733 | } |
| 734 | |
| 735 | boot_event_store.AddBootEventWithValue("last_boot_time_utc", current_time_utc); |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 736 | |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 737 | // The boot_complete metric has two variants: boot_complete and |
| 738 | // ota_boot_complete. The latter signifies that the device is booting after |
| 739 | // a system update. |
| 740 | std::string boot_complete_prefix = CalculateBootCompletePrefix(); |
James Hawkins | 4dded61 | 2016-07-28 11:50:23 -0700 | [diff] [blame] | 741 | if (boot_complete_prefix.empty()) { |
| 742 | // The system is hosed because the build date property could not be read. |
| 743 | return; |
| 744 | } |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 745 | |
| 746 | // post_decrypt_time_elapsed is only logged on encrypted devices. |
| 747 | if (boot_event_store.GetBootEvent("post_decrypt_time_elapsed", &record)) { |
| 748 | // Log the amount of time elapsed until the device is decrypted, which |
| 749 | // includes the variable amount of time the user takes to enter the |
| 750 | // decryption password. |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 751 | boot_event_store.AddBootEventWithValue("boot_decryption_complete", uptime.count()); |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 752 | |
| 753 | // Subtract the decryption time to normalize the boot cycle timing. |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 754 | std::chrono::seconds boot_complete = std::chrono::seconds(uptime.count() - record.second); |
James Hawkins | b9cf771 | 2016-04-08 15:32:19 -0700 | [diff] [blame] | 755 | boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_post_decrypt", |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 756 | boot_complete.count()); |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 757 | } else { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 758 | boot_event_store.AddBootEventWithValue(boot_complete_prefix + "_no_encryption", uptime.count()); |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 759 | } |
| 760 | |
| 761 | // Record the total time from device startup to boot complete, regardless of |
| 762 | // encryption state. |
James Hawkins | e78ea77 | 2017-03-24 11:43:02 -0700 | [diff] [blame] | 763 | boot_event_store.AddBootEventWithValue(boot_complete_prefix, uptime.count()); |
James Hawkins | ef0a090 | 2017-01-06 14:38:23 -0800 | [diff] [blame] | 764 | |
| 765 | RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init"); |
| 766 | RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.selinux"); |
| 767 | RecordInitBootTimeProp(&boot_event_store, "ro.boottime.init.cold_boot_wait"); |
James Hawkins | be46fd1 | 2017-02-02 16:21:25 -0800 | [diff] [blame] | 768 | |
James Hawkins | 1bfcaec | 2017-05-19 14:27:27 -0700 | [diff] [blame] | 769 | const BootloaderTimingMap bootloader_timings = GetBootLoaderTimings(); |
| 770 | RecordBootloaderTimings(&boot_event_store, bootloader_timings); |
| 771 | |
| 772 | auto uptime_ms = std::chrono::duration_cast<std::chrono::milliseconds>(time_since_epoch); |
| 773 | RecordAbsoluteBootTime(&boot_event_store, bootloader_timings, uptime_ms); |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 774 | } |
| 775 | |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 776 | // Records the boot_reason metric by querying the ro.boot.bootreason system |
| 777 | // property. |
| 778 | void RecordBootReason() { |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 779 | const std::string reason(GetProperty(bootloader_reboot_reason_property)); |
James Hawkins | 25f7122 | 2017-10-10 16:37:05 -0700 | [diff] [blame] | 780 | |
| 781 | if (reason.empty()) { |
| 782 | // Log an empty boot reason value as '<EMPTY>' to ensure the value is intentional |
| 783 | // (and not corruption anywhere else in the reporting pipeline). |
| 784 | android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT, |
| 785 | android::metricslogger::FIELD_PLATFORM_REASON, "<EMPTY>"); |
| 786 | } else { |
| 787 | android::metricslogger::LogMultiAction(android::metricslogger::ACTION_BOOT, |
| 788 | android::metricslogger::FIELD_PLATFORM_REASON, reason); |
| 789 | } |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 790 | |
| 791 | // Log the raw bootloader_boot_reason property value. |
| 792 | int32_t boot_reason = BootReasonStrToEnum(reason); |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 793 | BootEventRecordStore boot_event_store; |
| 794 | boot_event_store.AddBootEventWithValue("boot_reason", boot_reason); |
Mark Salyzyn | b304f6d | 2017-08-04 13:35:51 -0700 | [diff] [blame] | 795 | |
| 796 | // Log the scrubbed system_boot_reason. |
| 797 | const std::string system_reason(BootReasonStrToReason(reason)); |
| 798 | int32_t system_boot_reason = BootReasonStrToEnum(system_reason); |
| 799 | boot_event_store.AddBootEventWithValue("system_boot_reason", system_boot_reason); |
| 800 | |
| 801 | // Record the scrubbed system_boot_reason to the property |
| 802 | SetProperty(system_reboot_reason_property, system_reason); |
| 803 | if (reason == "") { |
| 804 | SetProperty(bootloader_reboot_reason_property, system_reason); |
| 805 | } |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 806 | } |
| 807 | |
James Hawkins | 500d715 | 2016-02-16 15:05:54 -0800 | [diff] [blame] | 808 | // Records two metrics related to the user resetting a device: the time at |
| 809 | // which the device is reset, and the time since the user last reset the |
| 810 | // device. The former is only set once per-factory reset. |
| 811 | void RecordFactoryReset() { |
| 812 | BootEventRecordStore boot_event_store; |
| 813 | BootEventRecordStore::BootEventRecord record; |
| 814 | |
| 815 | time_t current_time_utc = time(nullptr); |
| 816 | |
James Hawkins | 0660b30 | 2016-03-08 16:18:15 -0800 | [diff] [blame] | 817 | if (current_time_utc < 0) { |
| 818 | // UMA does not display negative values in buckets, so convert to positive. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 819 | android::metricslogger::LogHistogram("factory_reset_current_time_failure", |
| 820 | std::abs(current_time_utc)); |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 821 | |
James Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 822 | // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 823 | // is losing records somehow. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 824 | boot_event_store.AddBootEventWithValue("factory_reset_current_time_failure", |
| 825 | std::abs(current_time_utc)); |
James Hawkins | 0660b30 | 2016-03-08 16:18:15 -0800 | [diff] [blame] | 826 | return; |
| 827 | } else { |
James Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 828 | android::metricslogger::LogHistogram("factory_reset_current_time", current_time_utc); |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 829 | |
James Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 830 | // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 831 | // is losing records somehow. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 832 | boot_event_store.AddBootEventWithValue("factory_reset_current_time", current_time_utc); |
James Hawkins | 0660b30 | 2016-03-08 16:18:15 -0800 | [diff] [blame] | 833 | } |
| 834 | |
James Hawkins | 500d715 | 2016-02-16 15:05:54 -0800 | [diff] [blame] | 835 | // The factory_reset boot event does not exist after the device is reset, so |
| 836 | // use this signal to mark the time of the factory reset. |
| 837 | if (!boot_event_store.GetBootEvent("factory_reset", &record)) { |
| 838 | boot_event_store.AddBootEventWithValue("factory_reset", current_time_utc); |
James Hawkins | 3bf9b14 | 2016-03-03 14:50:24 -0800 | [diff] [blame] | 839 | |
| 840 | // Don't log the time_since_factory_reset until some time has elapsed. |
| 841 | // The data is not meaningful yet and skews the histogram buckets. |
James Hawkins | 500d715 | 2016-02-16 15:05:54 -0800 | [diff] [blame] | 842 | return; |
| 843 | } |
| 844 | |
| 845 | // Calculate and record the difference in time between now and the |
| 846 | // factory_reset time. |
| 847 | time_t factory_reset_utc = record.second; |
James Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 848 | android::metricslogger::LogHistogram("factory_reset_record_value", factory_reset_utc); |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 849 | |
James Hawkins | 9aec926 | 2017-01-31 11:42:24 -0800 | [diff] [blame] | 850 | // Logging via BootEventRecordStore to see if using android::metricslogger::LogHistogram |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 851 | // is losing records somehow. |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 852 | boot_event_store.AddBootEventWithValue("factory_reset_record_value", factory_reset_utc); |
James Hawkins | fff95ba | 2016-03-29 16:13:49 -0700 | [diff] [blame] | 853 | |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 854 | time_t time_since_factory_reset = difftime(current_time_utc, factory_reset_utc); |
| 855 | boot_event_store.AddBootEventWithValue("time_since_factory_reset", time_since_factory_reset); |
James Hawkins | 500d715 | 2016-02-16 15:05:54 -0800 | [diff] [blame] | 856 | } |
| 857 | |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 858 | } // namespace |
| 859 | |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 860 | int main(int argc, char** argv) { |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 861 | android::base::InitLogging(argv); |
| 862 | |
| 863 | const std::string cmd_line = GetCommandLine(argc, argv); |
| 864 | LOG(INFO) << "Service started: " << cmd_line; |
| 865 | |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 866 | int option_index = 0; |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 867 | static const char value_str[] = "value"; |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 868 | static const char boot_complete_str[] = "record_boot_complete"; |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 869 | static const char boot_reason_str[] = "record_boot_reason"; |
James Hawkins | 53684ea | 2016-02-23 16:18:19 -0800 | [diff] [blame] | 870 | static const char factory_reset_str[] = "record_time_since_factory_reset"; |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 871 | static const struct option long_options[] = { |
Mark Salyzyn | 14b1e6d | 2017-09-18 10:41:14 -0700 | [diff] [blame] | 872 | // clang-format off |
| 873 | { "help", no_argument, NULL, 'h' }, |
| 874 | { "log", no_argument, NULL, 'l' }, |
| 875 | { "print", no_argument, NULL, 'p' }, |
| 876 | { "record", required_argument, NULL, 'r' }, |
| 877 | { value_str, required_argument, NULL, 0 }, |
| 878 | { boot_complete_str, no_argument, NULL, 0 }, |
| 879 | { boot_reason_str, no_argument, NULL, 0 }, |
| 880 | { factory_reset_str, no_argument, NULL, 0 }, |
| 881 | { NULL, 0, NULL, 0 } |
| 882 | // clang-format on |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 883 | }; |
| 884 | |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 885 | std::string boot_event; |
| 886 | std::string value; |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 887 | int opt = 0; |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 888 | while ((opt = getopt_long(argc, argv, "hlpr:", long_options, &option_index)) != -1) { |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 889 | switch (opt) { |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 890 | // This case handles long options which have no single-character mapping. |
| 891 | case 0: { |
| 892 | const std::string option_name = long_options[option_index].name; |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 893 | if (option_name == value_str) { |
| 894 | // |optarg| is an external variable set by getopt representing |
| 895 | // the option argument. |
| 896 | value = optarg; |
| 897 | } else if (option_name == boot_complete_str) { |
James Hawkins | c08e996 | 2016-03-11 14:59:50 -0800 | [diff] [blame] | 898 | RecordBootComplete(); |
| 899 | } else if (option_name == boot_reason_str) { |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 900 | RecordBootReason(); |
James Hawkins | 500d715 | 2016-02-16 15:05:54 -0800 | [diff] [blame] | 901 | } else if (option_name == factory_reset_str) { |
| 902 | RecordFactoryReset(); |
James Hawkins | a4a1a4a | 2016-02-09 15:32:38 -0800 | [diff] [blame] | 903 | } else { |
| 904 | LOG(ERROR) << "Invalid option: " << option_name; |
| 905 | } |
| 906 | break; |
| 907 | } |
| 908 | |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 909 | case 'h': { |
| 910 | ShowHelp(argv[0]); |
| 911 | break; |
| 912 | } |
| 913 | |
| 914 | case 'l': { |
| 915 | LogBootEvents(); |
| 916 | break; |
| 917 | } |
| 918 | |
| 919 | case 'p': { |
| 920 | PrintBootEvents(); |
| 921 | break; |
| 922 | } |
| 923 | |
| 924 | case 'r': { |
| 925 | // |optarg| is an external variable set by getopt representing |
| 926 | // the option argument. |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 927 | boot_event = optarg; |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 928 | break; |
| 929 | } |
| 930 | |
| 931 | default: { |
| 932 | DCHECK_EQ(opt, '?'); |
| 933 | |
| 934 | // |optopt| is an external variable set by getopt representing |
| 935 | // the value of the invalid option. |
| 936 | LOG(ERROR) << "Invalid option: " << optopt; |
| 937 | ShowHelp(argv[0]); |
| 938 | return EXIT_FAILURE; |
| 939 | } |
| 940 | } |
| 941 | } |
| 942 | |
James Hawkins | c627558 | 2016-03-22 10:47:44 -0700 | [diff] [blame] | 943 | if (!boot_event.empty()) { |
| 944 | RecordBootEventFromCommandLine(boot_event, value); |
| 945 | } |
| 946 | |
James Hawkins | abd73e6 | 2016-01-19 15:10:38 -0800 | [diff] [blame] | 947 | return 0; |
| 948 | } |