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