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