1 /* 2 * Copyright (C) 2009 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 package com.android.server; 18 19 import static android.system.OsConstants.O_RDONLY; 20 21 import android.content.BroadcastReceiver; 22 import android.content.Context; 23 import android.content.Intent; 24 import android.content.pm.IPackageManager; 25 import android.os.Build; 26 import android.os.DropBoxManager; 27 import android.os.Environment; 28 import android.os.FileUtils; 29 import android.os.MessageQueue.OnFileDescriptorEventListener; 30 import android.os.RecoverySystem; 31 import android.os.RemoteException; 32 import android.os.ServiceManager; 33 import android.os.SystemProperties; 34 import android.provider.Downloads; 35 import android.system.ErrnoException; 36 import android.system.Os; 37 import android.text.TextUtils; 38 import android.util.AtomicFile; 39 import android.util.EventLog; 40 import android.util.Slog; 41 import android.util.TypedXmlPullParser; 42 import android.util.TypedXmlSerializer; 43 import android.util.Xml; 44 45 import com.android.internal.annotations.VisibleForTesting; 46 import com.android.internal.logging.MetricsLogger; 47 import com.android.internal.util.FrameworkStatsLog; 48 import com.android.internal.util.XmlUtils; 49 import com.android.server.am.DropboxRateLimiter; 50 51 import org.xmlpull.v1.XmlPullParser; 52 import org.xmlpull.v1.XmlPullParserException; 53 54 import java.io.File; 55 import java.io.FileDescriptor; 56 import java.io.FileInputStream; 57 import java.io.FileNotFoundException; 58 import java.io.FileOutputStream; 59 import java.io.IOException; 60 import java.util.HashMap; 61 import java.util.Iterator; 62 import java.util.regex.Matcher; 63 import java.util.regex.Pattern; 64 65 /** 66 * Performs a number of miscellaneous, non-system-critical actions 67 * after the system has finished booting. 68 */ 69 public class BootReceiver extends BroadcastReceiver { 70 private static final String TAG = "BootReceiver"; 71 72 private static final String TAG_TRUNCATED = "[[TRUNCATED]]\n"; 73 74 // Maximum size of a logged event (files get truncated if they're longer). 75 // Give userdebug builds a larger max to capture extra debug, esp. for last_kmsg. 76 private static final int LOG_SIZE = 77 SystemProperties.getInt("ro.debuggable", 0) == 1 ? 98304 : 65536; 78 private static final int LASTK_LOG_SIZE = 79 SystemProperties.getInt("ro.debuggable", 0) == 1 ? 196608 : 65536; 80 private static final int GMSCORE_LASTK_LOG_SIZE = 196608; 81 82 private static final String TAG_TOMBSTONE = "SYSTEM_TOMBSTONE"; 83 private static final String TAG_TOMBSTONE_PROTO = "SYSTEM_TOMBSTONE_PROTO"; 84 85 // The pre-froyo package and class of the system updater, which 86 // ran in the system process. We need to remove its packages here 87 // in order to clean up after a pre-froyo-to-froyo update. 88 private static final String OLD_UPDATER_PACKAGE = 89 "com.google.android.systemupdater"; 90 private static final String OLD_UPDATER_CLASS = 91 "com.google.android.systemupdater.SystemUpdateReceiver"; 92 93 private static final String LOG_FILES_FILE = "log-files.xml"; 94 private static final AtomicFile sFile = new AtomicFile(new File( 95 Environment.getDataSystemDirectory(), LOG_FILES_FILE), "log-files"); 96 private static final String LAST_HEADER_FILE = "last-header.txt"; 97 private static final File lastHeaderFile = new File( 98 Environment.getDataSystemDirectory(), LAST_HEADER_FILE); 99 100 // example: fs_stat,/dev/block/platform/soc/by-name/userdata,0x5 101 private static final String FS_STAT_PATTERN = "fs_stat,[^,]*/([^/,]+),(0x[0-9a-fA-F]+)"; 102 private static final int FS_STAT_FS_FIXED = 0x400; // should match with fs_mgr.cpp:FsStatFlags 103 private static final String FSCK_PASS_PATTERN = "Pass ([1-9]E?):"; 104 private static final String FSCK_TREE_OPTIMIZATION_PATTERN = 105 "Inode [0-9]+ extent tree.*could be shorter"; 106 private static final String FSCK_FS_MODIFIED = "FILE SYSTEM WAS MODIFIED"; 107 // ro.boottime.init.mount_all. + postfix for mount_all duration 108 private static final String[] MOUNT_DURATION_PROPS_POSTFIX = 109 new String[] { "early", "default", "late" }; 110 // for reboot, fs shutdown time is recorded in last_kmsg. 111 private static final String[] LAST_KMSG_FILES = 112 new String[] { "/sys/fs/pstore/console-ramoops", "/proc/last_kmsg" }; 113 // first: fs shutdown time in ms, second: umount status defined in init/reboot.h 114 private static final String LAST_SHUTDOWN_TIME_PATTERN = 115 "powerctl_shutdown_time_ms:([0-9]+):([0-9]+)"; 116 private static final int UMOUNT_STATUS_NOT_AVAILABLE = 4; // should match with init/reboot.h 117 118 // Location of file with metrics recorded during shutdown 119 private static final String SHUTDOWN_METRICS_FILE = "/data/system/shutdown-metrics.txt"; 120 121 private static final String SHUTDOWN_TRON_METRICS_PREFIX = "shutdown_"; 122 private static final String METRIC_SYSTEM_SERVER = "shutdown_system_server"; 123 private static final String METRIC_SHUTDOWN_TIME_START = "begin_shutdown"; 124 125 // Location of ftrace pipe for notifications from kernel memory tools like KFENCE and KASAN. 126 private static final String ERROR_REPORT_TRACE_PIPE = 127 "/sys/kernel/tracing/instances/bootreceiver/trace_pipe"; 128 // Stop after sending too many reports. See http://b/182159975. 129 private static final int MAX_ERROR_REPORTS = 8; 130 private static int sSentReports = 0; 131 132 @Override onReceive(final Context context, Intent intent)133 public void onReceive(final Context context, Intent intent) { 134 // Log boot events in the background to avoid blocking the main thread with I/O 135 new Thread() { 136 @Override 137 public void run() { 138 try { 139 logBootEvents(context); 140 } catch (Exception e) { 141 Slog.e(TAG, "Can't log boot events", e); 142 } 143 try { 144 boolean onlyCore = false; 145 try { 146 onlyCore = IPackageManager.Stub.asInterface(ServiceManager.getService( 147 "package")).isOnlyCoreApps(); 148 } catch (RemoteException e) { 149 } 150 if (!onlyCore) { 151 removeOldUpdatePackages(context); 152 } 153 } catch (Exception e) { 154 Slog.e(TAG, "Can't remove old update packages", e); 155 } 156 157 } 158 }.start(); 159 160 FileDescriptor tracefd = null; 161 try { 162 tracefd = Os.open(ERROR_REPORT_TRACE_PIPE, O_RDONLY, 0600); 163 } catch (ErrnoException e) { 164 Slog.wtf(TAG, "Could not open " + ERROR_REPORT_TRACE_PIPE, e); 165 return; 166 } 167 168 /* 169 * Event listener to watch for memory tool error reports. 170 * We read from /sys/kernel/tracing/instances/bootreceiver/trace_pipe (set up by the 171 * system), which will print an ftrace event when a memory corruption is detected in the 172 * kernel. 173 * When an error is detected, we set the dmesg.start system property to notify dmesgd 174 * about a new error. 175 */ 176 OnFileDescriptorEventListener traceCallback = new OnFileDescriptorEventListener() { 177 final int mBufferSize = 1024; 178 byte[] mTraceBuffer = new byte[mBufferSize]; 179 @Override 180 public int onFileDescriptorEvents(FileDescriptor fd, int events) { 181 /* 182 * Read from the tracing pipe set up to monitor the error_report_end events. 183 * When a tracing event occurs, the kernel writes a short (~100 bytes) line to the 184 * pipe, e.g.: 185 * ...-11210 [004] d..1 285.322307: error_report_end: [kfence] ffffff8938a05000 186 * The buffer size we use for reading should be enough to read the whole 187 * line, but to be on the safe side we keep reading until the buffer 188 * contains a '\n' character. In the unlikely case of a very buggy kernel 189 * the buffer may contain multiple tracing events that cannot be attributed 190 * to particular error reports. dmesgd will take care of all errors. 191 */ 192 try { 193 int nbytes = Os.read(fd, mTraceBuffer, 0, mBufferSize); 194 if (nbytes > 0) { 195 String readStr = new String(mTraceBuffer); 196 if (readStr.indexOf("\n") == -1) { 197 return OnFileDescriptorEventListener.EVENT_INPUT; 198 } 199 if (sSentReports < MAX_ERROR_REPORTS) { 200 SystemProperties.set("dmesgd.start", "1"); 201 sSentReports++; 202 } 203 } 204 } catch (Exception e) { 205 Slog.wtf(TAG, "Error watching for trace events", e); 206 return 0; // Unregister the handler. 207 } 208 return OnFileDescriptorEventListener.EVENT_INPUT; 209 } 210 }; 211 212 IoThread.get().getLooper().getQueue().addOnFileDescriptorEventListener( 213 tracefd, OnFileDescriptorEventListener.EVENT_INPUT, traceCallback); 214 215 } 216 removeOldUpdatePackages(Context context)217 private void removeOldUpdatePackages(Context context) { 218 Downloads.removeAllDownloadsByPackage(context, OLD_UPDATER_PACKAGE, OLD_UPDATER_CLASS); 219 } 220 getPreviousBootHeaders()221 private static String getPreviousBootHeaders() { 222 try { 223 return FileUtils.readTextFile(lastHeaderFile, 0, null); 224 } catch (IOException e) { 225 return null; 226 } 227 } 228 getCurrentBootHeaders()229 private static String getCurrentBootHeaders() throws IOException { 230 return new StringBuilder(512) 231 .append("Build: ").append(Build.FINGERPRINT).append("\n") 232 .append("Hardware: ").append(Build.BOARD).append("\n") 233 .append("Revision: ") 234 .append(SystemProperties.get("ro.revision", "")).append("\n") 235 .append("Bootloader: ").append(Build.BOOTLOADER).append("\n") 236 .append("Radio: ").append(Build.getRadioVersion()).append("\n") 237 .append("Kernel: ") 238 .append(FileUtils.readTextFile(new File("/proc/version"), 1024, "...\n")) 239 .append("\n").toString(); 240 } 241 242 getBootHeadersToLogAndUpdate()243 private static String getBootHeadersToLogAndUpdate() throws IOException { 244 final String oldHeaders = getPreviousBootHeaders(); 245 final String newHeaders = getCurrentBootHeaders(); 246 247 try { 248 FileUtils.stringToFile(lastHeaderFile, newHeaders); 249 } catch (IOException e) { 250 Slog.e(TAG, "Error writing " + lastHeaderFile, e); 251 } 252 253 if (oldHeaders == null) { 254 // If we failed to read the old headers, use the current headers 255 // but note this in the headers so we know 256 return "isPrevious: false\n" + newHeaders; 257 } 258 259 return "isPrevious: true\n" + oldHeaders; 260 } 261 logBootEvents(Context ctx)262 private void logBootEvents(Context ctx) throws IOException { 263 final DropBoxManager db = (DropBoxManager) ctx.getSystemService(Context.DROPBOX_SERVICE); 264 final String headers = getBootHeadersToLogAndUpdate(); 265 final String bootReason = SystemProperties.get("ro.boot.bootreason", null); 266 267 String recovery = RecoverySystem.handleAftermath(ctx); 268 if (recovery != null && db != null) { 269 db.addText("SYSTEM_RECOVERY_LOG", headers + recovery); 270 } 271 272 String lastKmsgFooter = ""; 273 if (bootReason != null) { 274 lastKmsgFooter = new StringBuilder(512) 275 .append("\n") 276 .append("Boot info:\n") 277 .append("Last boot reason: ").append(bootReason).append("\n") 278 .toString(); 279 } 280 281 HashMap<String, Long> timestamps = readTimestamps(); 282 283 if (SystemProperties.getLong("ro.runtime.firstboot", 0) == 0) { 284 String now = Long.toString(System.currentTimeMillis()); 285 SystemProperties.set("ro.runtime.firstboot", now); 286 if (db != null) db.addText("SYSTEM_BOOT", headers); 287 288 // Negative sizes mean to take the *tail* of the file (see FileUtils.readTextFile()) 289 addLastkToDropBox(db, timestamps, headers, lastKmsgFooter, 290 "/proc/last_kmsg", -LASTK_LOG_SIZE, "SYSTEM_LAST_KMSG"); 291 addLastkToDropBox(db, timestamps, headers, lastKmsgFooter, 292 "/sys/fs/pstore/console-ramoops", -LASTK_LOG_SIZE, "SYSTEM_LAST_KMSG"); 293 addLastkToDropBox(db, timestamps, headers, lastKmsgFooter, 294 "/sys/fs/pstore/console-ramoops-0", -LASTK_LOG_SIZE, "SYSTEM_LAST_KMSG"); 295 addFileToDropBox(db, timestamps, headers, "/cache/recovery/log", -LOG_SIZE, 296 "SYSTEM_RECOVERY_LOG"); 297 addFileToDropBox(db, timestamps, headers, "/cache/recovery/last_kmsg", 298 -LOG_SIZE, "SYSTEM_RECOVERY_KMSG"); 299 addAuditErrorsToDropBox(db, timestamps, headers, -LOG_SIZE, "SYSTEM_AUDIT"); 300 } else { 301 if (db != null) db.addText("SYSTEM_RESTART", headers); 302 } 303 // log always available fs_stat last so that logcat collecting tools can wait until 304 // fs_stat to get all file system metrics. 305 logFsShutdownTime(); 306 logFsMountTime(); 307 addFsckErrorsToDropBoxAndLogFsStat(db, timestamps, headers, -LOG_SIZE, "SYSTEM_FSCK"); 308 logSystemServerShutdownTimeMetrics(); 309 writeTimestamps(timestamps); 310 } 311 312 private static final DropboxRateLimiter sDropboxRateLimiter = new DropboxRateLimiter(); 313 314 /** 315 * Add a tombstone to the DropBox. 316 * 317 * @param ctx Context 318 * @param tombstone path to the tombstone 319 * @param proto whether the tombstone is stored as proto 320 * @param processName the name of the process corresponding to the tombstone 321 */ addTombstoneToDropBox( Context ctx, File tombstone, boolean proto, String processName)322 public static void addTombstoneToDropBox( 323 Context ctx, File tombstone, boolean proto, String processName) { 324 final DropBoxManager db = ctx.getSystemService(DropBoxManager.class); 325 if (db == null) { 326 Slog.e(TAG, "Can't log tombstone: DropBoxManager not available"); 327 return; 328 } 329 330 // Check if we should rate limit and abort early if needed. Do this for both proto and 331 // non-proto tombstones, even though proto tombstones do not support including the counter 332 // of events dropped since rate limiting activated yet. 333 DropboxRateLimiter.RateLimitResult rateLimitResult = 334 sDropboxRateLimiter.shouldRateLimit(TAG_TOMBSTONE, processName); 335 if (rateLimitResult.shouldRateLimit()) return; 336 337 HashMap<String, Long> timestamps = readTimestamps(); 338 try { 339 if (proto) { 340 if (recordFileTimestamp(tombstone, timestamps)) { 341 db.addFile(TAG_TOMBSTONE_PROTO, tombstone, 0); 342 } 343 } else { 344 // Add the header indicating how many events have been dropped due to rate limiting. 345 final String headers = getBootHeadersToLogAndUpdate() 346 + rateLimitResult.createHeader(); 347 addFileToDropBox(db, timestamps, headers, tombstone.getPath(), LOG_SIZE, 348 TAG_TOMBSTONE); 349 } 350 } catch (IOException e) { 351 Slog.e(TAG, "Can't log tombstone", e); 352 } 353 writeTimestamps(timestamps); 354 } 355 addLastkToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String footers, String filename, int maxSize, String tag)356 private static void addLastkToDropBox( 357 DropBoxManager db, HashMap<String, Long> timestamps, 358 String headers, String footers, String filename, int maxSize, 359 String tag) throws IOException { 360 int extraSize = headers.length() + TAG_TRUNCATED.length() + footers.length(); 361 // GMSCore will do 2nd truncation to be 192KiB 362 // LASTK_LOG_SIZE + extraSize must be less than GMSCORE_LASTK_LOG_SIZE 363 if (LASTK_LOG_SIZE + extraSize > GMSCORE_LASTK_LOG_SIZE) { 364 if (GMSCORE_LASTK_LOG_SIZE > extraSize) { 365 maxSize = -(GMSCORE_LASTK_LOG_SIZE - extraSize); 366 } else { 367 maxSize = 0; 368 } 369 } 370 addFileWithFootersToDropBox(db, timestamps, headers, footers, filename, maxSize, tag); 371 } 372 addFileToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String filename, int maxSize, String tag)373 private static void addFileToDropBox( 374 DropBoxManager db, HashMap<String, Long> timestamps, 375 String headers, String filename, int maxSize, String tag) throws IOException { 376 addFileWithFootersToDropBox(db, timestamps, headers, "", filename, maxSize, tag); 377 } 378 addFileWithFootersToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String footers, String filename, int maxSize, String tag)379 private static void addFileWithFootersToDropBox( 380 DropBoxManager db, HashMap<String, Long> timestamps, 381 String headers, String footers, String filename, int maxSize, 382 String tag) throws IOException { 383 if (db == null || !db.isTagEnabled(tag)) return; // Logging disabled 384 385 File file = new File(filename); 386 if (!recordFileTimestamp(file, timestamps)) { 387 return; 388 } 389 390 String fileContents = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 391 String text = headers + fileContents + footers; 392 // Create an additional report for system server native crashes, with a special tag. 393 if (tag.equals(TAG_TOMBSTONE) && fileContents.contains(">>> system_server <<<")) { 394 addTextToDropBox(db, "system_server_native_crash", text, filename, maxSize); 395 } 396 if (tag.equals(TAG_TOMBSTONE)) { 397 FrameworkStatsLog.write(FrameworkStatsLog.TOMB_STONE_OCCURRED); 398 } 399 addTextToDropBox(db, tag, text, filename, maxSize); 400 } 401 recordFileTimestamp(File file, HashMap<String, Long> timestamps)402 private static boolean recordFileTimestamp(File file, HashMap<String, Long> timestamps) { 403 final long fileTime = file.lastModified(); 404 if (fileTime <= 0) return false; // File does not exist 405 406 final String filename = file.getPath(); 407 if (timestamps.containsKey(filename) && timestamps.get(filename) == fileTime) { 408 return false; // Already logged this particular file 409 } 410 411 timestamps.put(filename, fileTime); 412 return true; 413 } 414 addTextToDropBox(DropBoxManager db, String tag, String text, String filename, int maxSize)415 private static void addTextToDropBox(DropBoxManager db, String tag, String text, 416 String filename, int maxSize) { 417 Slog.i(TAG, "Copying " + filename + " to DropBox (" + tag + ")"); 418 db.addText(tag, text); 419 EventLog.writeEvent(DropboxLogTags.DROPBOX_FILE_COPY, filename, maxSize, tag); 420 } 421 addAuditErrorsToDropBox(DropBoxManager db, HashMap<String, Long> timestamps, String headers, int maxSize, String tag)422 private static void addAuditErrorsToDropBox(DropBoxManager db, 423 HashMap<String, Long> timestamps, String headers, int maxSize, String tag) 424 throws IOException { 425 if (db == null || !db.isTagEnabled(tag)) return; // Logging disabled 426 Slog.i(TAG, "Copying audit failures to DropBox"); 427 428 File file = new File("/proc/last_kmsg"); 429 long fileTime = file.lastModified(); 430 if (fileTime <= 0) { 431 file = new File("/sys/fs/pstore/console-ramoops"); 432 fileTime = file.lastModified(); 433 if (fileTime <= 0) { 434 file = new File("/sys/fs/pstore/console-ramoops-0"); 435 fileTime = file.lastModified(); 436 } 437 } 438 439 if (fileTime <= 0) return; // File does not exist 440 441 if (timestamps.containsKey(tag) && timestamps.get(tag) == fileTime) { 442 return; // Already logged this particular file 443 } 444 445 timestamps.put(tag, fileTime); 446 447 String log = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 448 StringBuilder sb = new StringBuilder(); 449 for (String line : log.split("\n")) { 450 if (line.contains("audit")) { 451 sb.append(line + "\n"); 452 } 453 } 454 Slog.i(TAG, "Copied " + sb.toString().length() + " worth of audits to DropBox"); 455 db.addText(tag, headers + sb.toString()); 456 } 457 addFsckErrorsToDropBoxAndLogFsStat(DropBoxManager db, HashMap<String, Long> timestamps, String headers, int maxSize, String tag)458 private static void addFsckErrorsToDropBoxAndLogFsStat(DropBoxManager db, 459 HashMap<String, Long> timestamps, String headers, int maxSize, String tag) 460 throws IOException { 461 boolean uploadEnabled = true; 462 if (db == null || !db.isTagEnabled(tag)) { 463 uploadEnabled = false; 464 } 465 boolean uploadNeeded = false; 466 Slog.i(TAG, "Checking for fsck errors"); 467 468 File file = new File("/dev/fscklogs/log"); 469 long fileTime = file.lastModified(); 470 if (fileTime <= 0) return; // File does not exist 471 472 String log = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 473 Pattern pattern = Pattern.compile(FS_STAT_PATTERN); 474 String lines[] = log.split("\n"); 475 int lineNumber = 0; 476 int lastFsStatLineNumber = 0; 477 for (String line : lines) { // should check all lines 478 if (line.contains(FSCK_FS_MODIFIED)) { 479 uploadNeeded = true; 480 } else if (line.contains("fs_stat")){ 481 Matcher matcher = pattern.matcher(line); 482 if (matcher.find()) { 483 handleFsckFsStat(matcher, lines, lastFsStatLineNumber, lineNumber); 484 lastFsStatLineNumber = lineNumber; 485 } else { 486 Slog.w(TAG, "cannot parse fs_stat:" + line); 487 } 488 } 489 lineNumber++; 490 } 491 492 if (uploadEnabled && uploadNeeded ) { 493 addFileToDropBox(db, timestamps, headers, "/dev/fscklogs/log", maxSize, tag); 494 } 495 496 // Remove the file so we don't re-upload if the runtime restarts. 497 file.delete(); 498 } 499 logFsMountTime()500 private static void logFsMountTime() { 501 for (String propPostfix : MOUNT_DURATION_PROPS_POSTFIX) { 502 int duration = SystemProperties.getInt("ro.boottime.init.mount_all." + propPostfix, 0); 503 if (duration != 0) { 504 int eventType; 505 switch (propPostfix) { 506 case "early": 507 eventType = 508 FrameworkStatsLog 509 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_EARLY_DURATION; 510 break; 511 case "default": 512 eventType = 513 FrameworkStatsLog 514 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_DEFAULT_DURATION; 515 break; 516 case "late": 517 eventType = 518 FrameworkStatsLog 519 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_LATE_DURATION; 520 break; 521 default: 522 continue; 523 } 524 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, 525 eventType, duration); 526 } 527 } 528 } 529 530 // TODO b/64815357 Move to bootstat.cpp and log AbsoluteRebootTime logSystemServerShutdownTimeMetrics()531 private static void logSystemServerShutdownTimeMetrics() { 532 File metricsFile = new File(SHUTDOWN_METRICS_FILE); 533 String metricsStr = null; 534 if (metricsFile.exists()) { 535 try { 536 metricsStr = FileUtils.readTextFile(metricsFile, 0, null); 537 } catch (IOException e) { 538 Slog.e(TAG, "Problem reading " + metricsFile, e); 539 } 540 } 541 if (!TextUtils.isEmpty(metricsStr)) { 542 String reboot = null; 543 String reason = null; 544 String start_time = null; 545 String duration = null; 546 String[] array = metricsStr.split(","); 547 for (String keyValueStr : array) { 548 String[] keyValue = keyValueStr.split(":"); 549 if (keyValue.length != 2) { 550 Slog.e(TAG, "Wrong format of shutdown metrics - " + metricsStr); 551 continue; 552 } 553 // Ignore keys that are not indended for tron 554 if (keyValue[0].startsWith(SHUTDOWN_TRON_METRICS_PREFIX)) { 555 logTronShutdownMetric(keyValue[0], keyValue[1]); 556 if (keyValue[0].equals(METRIC_SYSTEM_SERVER)) { 557 duration = keyValue[1]; 558 } 559 } 560 if (keyValue[0].equals("reboot")) { 561 reboot = keyValue[1]; 562 } else if (keyValue[0].equals("reason")) { 563 reason = keyValue[1]; 564 } else if (keyValue[0].equals(METRIC_SHUTDOWN_TIME_START)) { 565 start_time = keyValue[1]; 566 } 567 } 568 logStatsdShutdownAtom(reboot, reason, start_time, duration); 569 } 570 metricsFile.delete(); 571 } 572 logTronShutdownMetric(String metricName, String valueStr)573 private static void logTronShutdownMetric(String metricName, String valueStr) { 574 int value; 575 try { 576 value = Integer.parseInt(valueStr); 577 } catch (NumberFormatException e) { 578 Slog.e(TAG, "Cannot parse metric " + metricName + " int value - " + valueStr); 579 return; 580 } 581 if (value >= 0) { 582 MetricsLogger.histogram(null, metricName, value); 583 } 584 } 585 logStatsdShutdownAtom( String rebootStr, String reasonStr, String startStr, String durationStr)586 private static void logStatsdShutdownAtom( 587 String rebootStr, String reasonStr, String startStr, String durationStr) { 588 boolean reboot = false; 589 String reason = "<EMPTY>"; 590 long start = 0; 591 long duration = 0; 592 593 if (rebootStr != null) { 594 if (rebootStr.equals("y")) { 595 reboot = true; 596 } else if (!rebootStr.equals("n")) { 597 Slog.e(TAG, "Unexpected value for reboot : " + rebootStr); 598 } 599 } else { 600 Slog.e(TAG, "No value received for reboot"); 601 } 602 603 if (reasonStr != null) { 604 reason = reasonStr; 605 } else { 606 Slog.e(TAG, "No value received for shutdown reason"); 607 } 608 609 if (startStr != null) { 610 try { 611 start = Long.parseLong(startStr); 612 } catch (NumberFormatException e) { 613 Slog.e(TAG, "Cannot parse shutdown start time: " + startStr); 614 } 615 } else { 616 Slog.e(TAG, "No value received for shutdown start time"); 617 } 618 619 if (durationStr != null) { 620 try { 621 duration = Long.parseLong(durationStr); 622 } catch (NumberFormatException e) { 623 Slog.e(TAG, "Cannot parse shutdown duration: " + startStr); 624 } 625 } else { 626 Slog.e(TAG, "No value received for shutdown duration"); 627 } 628 629 FrameworkStatsLog.write(FrameworkStatsLog.SHUTDOWN_SEQUENCE_REPORTED, reboot, reason, start, 630 duration); 631 } 632 logFsShutdownTime()633 private static void logFsShutdownTime() { 634 File f = null; 635 for (String fileName : LAST_KMSG_FILES) { 636 File file = new File(fileName); 637 if (!file.exists()) continue; 638 f = file; 639 break; 640 } 641 if (f == null) { // no last_kmsg 642 return; 643 } 644 645 final int maxReadSize = 16*1024; 646 // last_kmsg can be very big, so only parse the last part 647 String lines; 648 try { 649 lines = FileUtils.readTextFile(f, -maxReadSize, null); 650 } catch (IOException e) { 651 Slog.w(TAG, "cannot read last msg", e); 652 return; 653 } 654 Pattern pattern = Pattern.compile(LAST_SHUTDOWN_TIME_PATTERN, Pattern.MULTILINE); 655 Matcher matcher = pattern.matcher(lines); 656 if (matcher.find()) { 657 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, 658 FrameworkStatsLog.BOOT_TIME_EVENT_DURATION__EVENT__SHUTDOWN_DURATION, 659 Integer.parseInt(matcher.group(1))); 660 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 661 FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE__EVENT__SHUTDOWN_UMOUNT_STAT, 662 Integer.parseInt(matcher.group(2))); 663 Slog.i(TAG, "boot_fs_shutdown," + matcher.group(1) + "," + matcher.group(2)); 664 } else { // not found 665 // This can happen when a device has too much kernel log after file system unmount 666 // ,exceeding maxReadSize. And having that much kernel logging can affect overall 667 // performance as well. So it is better to fix the kernel to reduce the amount of log. 668 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 669 FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE__EVENT__SHUTDOWN_UMOUNT_STAT, 670 UMOUNT_STATUS_NOT_AVAILABLE); 671 Slog.w(TAG, "boot_fs_shutdown, string not found"); 672 } 673 } 674 675 /** 676 * Fix fs_stat from e2fsck. 677 * For now, only handle the case of quota warning caused by tree optimization. Clear fs fix 678 * flag (=0x400) caused by that. 679 * 680 * @param partition partition name 681 * @param statOrg original stat reported from e2fsck log 682 * @param lines e2fsck logs broken down into lines 683 * @param startLineNumber start line to parse 684 * @param endLineNumber end line. exclusive. 685 * @return updated fs_stat. For tree optimization, will clear bit 0x400. 686 */ 687 @VisibleForTesting fixFsckFsStat(String partition, int statOrg, String[] lines, int startLineNumber, int endLineNumber)688 public static int fixFsckFsStat(String partition, int statOrg, String[] lines, 689 int startLineNumber, int endLineNumber) { 690 int stat = statOrg; 691 if ((stat & FS_STAT_FS_FIXED) != 0) { 692 // fs was fixed. should check if quota warning was caused by tree optimization. 693 // This is not a real fix but optimization, so should not be counted as a fs fix. 694 Pattern passPattern = Pattern.compile(FSCK_PASS_PATTERN); 695 Pattern treeOptPattern = Pattern.compile(FSCK_TREE_OPTIMIZATION_PATTERN); 696 String currentPass = ""; 697 boolean foundTreeOptimization = false; 698 boolean foundQuotaFix = false; 699 boolean foundTimestampAdjustment = false; 700 boolean foundOtherFix = false; 701 String otherFixLine = null; 702 for (int i = startLineNumber; i < endLineNumber; i++) { 703 String line = lines[i]; 704 if (line.contains(FSCK_FS_MODIFIED)) { // no need to parse above this 705 break; 706 } else if (line.startsWith("Pass ")) { 707 Matcher matcher = passPattern.matcher(line); 708 if (matcher.find()) { 709 currentPass = matcher.group(1); 710 } 711 } else if (line.startsWith("Inode ")) { 712 Matcher matcher = treeOptPattern.matcher(line); 713 if (matcher.find() && currentPass.equals("1")) { 714 foundTreeOptimization = true; 715 Slog.i(TAG, "fs_stat, partition:" + partition + " found tree optimization:" 716 + line); 717 } else { 718 foundOtherFix = true; 719 otherFixLine = line; 720 break; 721 } 722 } else if (line.startsWith("[QUOTA WARNING]") && currentPass.equals("5")) { 723 Slog.i(TAG, "fs_stat, partition:" + partition + " found quota warning:" 724 + line); 725 foundQuotaFix = true; 726 if (!foundTreeOptimization) { // only quota warning, this is real fix. 727 otherFixLine = line; 728 break; 729 } 730 } else if (line.startsWith("Update quota info") && currentPass.equals("5")) { 731 // follows "[QUOTA WARNING]", ignore 732 } else if (line.startsWith("Timestamp(s) on inode") && 733 line.contains("beyond 2310-04-04 are likely pre-1970") && 734 currentPass.equals("1")) { 735 Slog.i(TAG, "fs_stat, partition:" + partition + " found timestamp adjustment:" 736 + line); 737 // followed by next line, "Fix? yes" 738 if (lines[i + 1].contains("Fix? yes")) { 739 i++; 740 } 741 foundTimestampAdjustment = true; 742 } else { 743 line = line.trim(); 744 // ignore empty msg or any msg before Pass 1 745 if (!line.isEmpty() && !currentPass.isEmpty()) { 746 foundOtherFix = true; 747 otherFixLine = line; 748 break; 749 } 750 } 751 } 752 if (foundOtherFix) { 753 if (otherFixLine != null) { 754 Slog.i(TAG, "fs_stat, partition:" + partition + " fix:" + otherFixLine); 755 } 756 } else if (foundQuotaFix && !foundTreeOptimization) { 757 Slog.i(TAG, "fs_stat, got quota fix without tree optimization, partition:" + 758 partition); 759 } else if ((foundTreeOptimization && foundQuotaFix) || foundTimestampAdjustment) { 760 // not a real fix, so clear it. 761 Slog.i(TAG, "fs_stat, partition:" + partition + " fix ignored"); 762 stat &= ~FS_STAT_FS_FIXED; 763 } 764 } 765 return stat; 766 } 767 handleFsckFsStat(Matcher match, String[] lines, int startLineNumber, int endLineNumber)768 private static void handleFsckFsStat(Matcher match, String[] lines, int startLineNumber, 769 int endLineNumber) { 770 String partition = match.group(1); 771 int stat; 772 try { 773 stat = Integer.decode(match.group(2)); 774 } catch (NumberFormatException e) { 775 Slog.w(TAG, "cannot parse fs_stat: partition:" + partition + " stat:" + match.group(2)); 776 return; 777 } 778 stat = fixFsckFsStat(partition, stat, lines, startLineNumber, endLineNumber); 779 if ("userdata".equals(partition) || "data".equals(partition)) { 780 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 781 FrameworkStatsLog 782 .BOOT_TIME_EVENT_ERROR_CODE__EVENT__FS_MGR_FS_STAT_DATA_PARTITION, 783 stat); 784 } 785 Slog.i(TAG, "fs_stat, partition:" + partition + " stat:0x" + Integer.toHexString(stat)); 786 } 787 readTimestamps()788 private static HashMap<String, Long> readTimestamps() { 789 synchronized (sFile) { 790 HashMap<String, Long> timestamps = new HashMap<String, Long>(); 791 boolean success = false; 792 try (final FileInputStream stream = sFile.openRead()) { 793 TypedXmlPullParser parser = Xml.resolvePullParser(stream); 794 795 int type; 796 while ((type = parser.next()) != XmlPullParser.START_TAG 797 && type != XmlPullParser.END_DOCUMENT) { 798 ; 799 } 800 801 if (type != XmlPullParser.START_TAG) { 802 throw new IllegalStateException("no start tag found"); 803 } 804 805 int outerDepth = parser.getDepth(); // Skip the outer <log-files> tag. 806 while ((type = parser.next()) != XmlPullParser.END_DOCUMENT 807 && (type != XmlPullParser.END_TAG || parser.getDepth() > outerDepth)) { 808 if (type == XmlPullParser.END_TAG || type == XmlPullParser.TEXT) { 809 continue; 810 } 811 812 String tagName = parser.getName(); 813 if (tagName.equals("log")) { 814 final String filename = parser.getAttributeValue(null, "filename"); 815 final long timestamp = parser.getAttributeLong(null, "timestamp"); 816 timestamps.put(filename, timestamp); 817 } else { 818 Slog.w(TAG, "Unknown tag: " + parser.getName()); 819 XmlUtils.skipCurrentTag(parser); 820 } 821 } 822 success = true; 823 } catch (FileNotFoundException e) { 824 Slog.i(TAG, "No existing last log timestamp file " + sFile.getBaseFile() + 825 "; starting empty"); 826 } catch (IOException e) { 827 Slog.w(TAG, "Failed parsing " + e); 828 } catch (IllegalStateException e) { 829 Slog.w(TAG, "Failed parsing " + e); 830 } catch (NullPointerException e) { 831 Slog.w(TAG, "Failed parsing " + e); 832 } catch (XmlPullParserException e) { 833 Slog.w(TAG, "Failed parsing " + e); 834 } finally { 835 if (!success) { 836 timestamps.clear(); 837 } 838 } 839 return timestamps; 840 } 841 } 842 writeTimestamps(HashMap<String, Long> timestamps)843 private static void writeTimestamps(HashMap<String, Long> timestamps) { 844 synchronized (sFile) { 845 final FileOutputStream stream; 846 try { 847 stream = sFile.startWrite(); 848 } catch (IOException e) { 849 Slog.w(TAG, "Failed to write timestamp file: " + e); 850 return; 851 } 852 853 try { 854 TypedXmlSerializer out = Xml.resolveSerializer(stream); 855 out.startDocument(null, true); 856 out.startTag(null, "log-files"); 857 858 Iterator<String> itor = timestamps.keySet().iterator(); 859 while (itor.hasNext()) { 860 String filename = itor.next(); 861 out.startTag(null, "log"); 862 out.attribute(null, "filename", filename); 863 out.attributeLong(null, "timestamp", timestamps.get(filename)); 864 out.endTag(null, "log"); 865 } 866 867 out.endTag(null, "log-files"); 868 out.endDocument(); 869 870 sFile.finishWrite(stream); 871 } catch (IOException e) { 872 Slog.w(TAG, "Failed to write timestamp file, using the backup: " + e); 873 sFile.failWrite(stream); 874 } 875 } 876 } 877 } 878