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