1 /* 2 * Copyright (C) 2009 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 17 package com.android.server; 18 19 import static android.system.OsConstants.O_RDONLY; 20 21 import android.content.BroadcastReceiver; 22 import android.content.Context; 23 import android.content.Intent; 24 import android.content.pm.IPackageManager; 25 import android.os.Build; 26 import android.os.DropBoxManager; 27 import android.os.Environment; 28 import android.os.FileUtils; 29 import android.os.MessageQueue.OnFileDescriptorEventListener; 30 import android.os.RecoverySystem; 31 import android.os.RemoteException; 32 import android.os.ServiceManager; 33 import android.os.SystemProperties; 34 import android.os.storage.StorageManager; 35 import android.provider.Downloads; 36 import android.system.ErrnoException; 37 import android.system.Os; 38 import android.text.TextUtils; 39 import android.util.AtomicFile; 40 import android.util.EventLog; 41 import android.util.Slog; 42 import android.util.TypedXmlPullParser; 43 import android.util.TypedXmlSerializer; 44 import android.util.Xml; 45 46 import com.android.internal.annotations.VisibleForTesting; 47 import com.android.internal.logging.MetricsLogger; 48 import com.android.internal.util.FrameworkStatsLog; 49 import com.android.internal.util.XmlUtils; 50 51 import org.xmlpull.v1.XmlPullParser; 52 import org.xmlpull.v1.XmlPullParserException; 53 54 import java.io.BufferedReader; 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.io.InputStreamReader; 62 import java.util.ArrayList; 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 88 // The pre-froyo package and class of the system updater, which 89 // ran in the system process. We need to remove its packages here 90 // in order to clean up after a pre-froyo-to-froyo update. 91 private static final String OLD_UPDATER_PACKAGE = 92 "com.google.android.systemupdater"; 93 private static final String OLD_UPDATER_CLASS = 94 "com.google.android.systemupdater.SystemUpdateReceiver"; 95 96 private static final String LOG_FILES_FILE = "log-files.xml"; 97 private static final AtomicFile sFile = new AtomicFile(new File( 98 Environment.getDataSystemDirectory(), LOG_FILES_FILE), "log-files"); 99 private static final String LAST_HEADER_FILE = "last-header.txt"; 100 private static final File lastHeaderFile = new File( 101 Environment.getDataSystemDirectory(), LAST_HEADER_FILE); 102 103 // example: fs_stat,/dev/block/platform/soc/by-name/userdata,0x5 104 private static final String FS_STAT_PATTERN = "fs_stat,[^,]*/([^/,]+),(0x[0-9a-fA-F]+)"; 105 private static final int FS_STAT_FS_FIXED = 0x400; // should match with fs_mgr.cpp:FsStatFlags 106 private static final String FSCK_PASS_PATTERN = "Pass ([1-9]E?):"; 107 private static final String FSCK_TREE_OPTIMIZATION_PATTERN = 108 "Inode [0-9]+ extent tree.*could be shorter"; 109 private static final String FSCK_FS_MODIFIED = "FILE SYSTEM WAS MODIFIED"; 110 // ro.boottime.init.mount_all. + postfix for mount_all duration 111 private static final String[] MOUNT_DURATION_PROPS_POSTFIX = 112 new String[] { "early", "default", "late" }; 113 // for reboot, fs shutdown time is recorded in last_kmsg. 114 private static final String[] LAST_KMSG_FILES = 115 new String[] { "/sys/fs/pstore/console-ramoops", "/proc/last_kmsg" }; 116 // first: fs shutdown time in ms, second: umount status defined in init/reboot.h 117 private static final String LAST_SHUTDOWN_TIME_PATTERN = 118 "powerctl_shutdown_time_ms:([0-9]+):([0-9]+)"; 119 private static final int UMOUNT_STATUS_NOT_AVAILABLE = 4; // should match with init/reboot.h 120 121 // Location of file with metrics recorded during shutdown 122 private static final String SHUTDOWN_METRICS_FILE = "/data/system/shutdown-metrics.txt"; 123 124 private static final String SHUTDOWN_TRON_METRICS_PREFIX = "shutdown_"; 125 private static final String METRIC_SYSTEM_SERVER = "shutdown_system_server"; 126 private static final String METRIC_SHUTDOWN_TIME_START = "begin_shutdown"; 127 128 // Location of ftrace pipe for notifications from kernel memory tools like KFENCE and KASAN. 129 private static final String ERROR_REPORT_TRACE_PIPE = 130 "/sys/kernel/tracing/instances/bootreceiver/trace_pipe"; 131 // Stop after sending this many reports. See http://b/182159975. 132 private static final int MAX_ERROR_REPORTS = 8; 133 private static int sSentReports = 0; 134 // Avoid reporing the same bug from processDmesg() twice. 135 private static String sLastReportedBug = null; 136 137 @Override onReceive(final Context context, Intent intent)138 public void onReceive(final Context context, Intent intent) { 139 // Log boot events in the background to avoid blocking the main thread with I/O 140 new Thread() { 141 @Override 142 public void run() { 143 try { 144 logBootEvents(context); 145 } catch (Exception e) { 146 Slog.e(TAG, "Can't log boot events", e); 147 } 148 try { 149 boolean onlyCore = false; 150 try { 151 onlyCore = IPackageManager.Stub.asInterface(ServiceManager.getService( 152 "package")).isOnlyCoreApps(); 153 } catch (RemoteException e) { 154 } 155 if (!onlyCore) { 156 removeOldUpdatePackages(context); 157 } 158 } catch (Exception e) { 159 Slog.e(TAG, "Can't remove old update packages", e); 160 } 161 162 } 163 }.start(); 164 165 FileDescriptor tracefd = null; 166 try { 167 tracefd = Os.open(ERROR_REPORT_TRACE_PIPE, O_RDONLY, 0600); 168 } catch (ErrnoException e) { 169 Slog.wtf(TAG, "Could not open " + ERROR_REPORT_TRACE_PIPE, e); 170 return; 171 } 172 173 /* 174 * Event listener to watch for memory tool error reports. 175 * We read from /sys/kernel/tracing/instances/bootreceiver/trace_pipe (set up by the 176 * system), which will print an ftrace event when a memory corruption is detected in the 177 * kernel. 178 * When an error is detected, we run the dmesg shell command and process its output. 179 */ 180 OnFileDescriptorEventListener traceCallback = new OnFileDescriptorEventListener() { 181 final int mBufferSize = 1024; 182 byte[] mTraceBuffer = new byte[mBufferSize]; 183 @Override 184 public int onFileDescriptorEvents(FileDescriptor fd, int events) { 185 /* 186 * Read from the tracing pipe set up to monitor the error_report_end events. 187 * When a tracing event occurs, the kernel writes a short (~100 bytes) line to the 188 * pipe, e.g.: 189 * ...-11210 [004] d..1 285.322307: error_report_end: [kfence] ffffff8938a05000 190 * The buffer size we use for reading should be enough to read the whole 191 * line, but to be on the safe side we keep reading until the buffer 192 * contains a '\n' character. In the unlikely case of a very buggy kernel 193 * the buffer may contain multiple tracing events that cannot be attributed 194 * to particular error reports. In that case the latest error report 195 * residing in dmesg is picked. 196 */ 197 try { 198 int nbytes = Os.read(fd, mTraceBuffer, 0, mBufferSize); 199 if (nbytes > 0) { 200 String readStr = new String(mTraceBuffer); 201 if (readStr.indexOf("\n") == -1) { 202 return OnFileDescriptorEventListener.EVENT_INPUT; 203 } 204 processDmesg(context); 205 } 206 } catch (Exception e) { 207 Slog.wtf(TAG, "Error processing dmesg output", 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 219 /** 220 * Check whether it is safe to collect this dmesg line or not. 221 * 222 * We only consider lines belonging to KASAN or KFENCE reports, but those may still contain 223 * user information, namely the process name: 224 * 225 * [ 69.547684] [ T6006]c7 6006 CPU: 7 PID: 6006 Comm: sh Tainted: G S C O ... 226 * 227 * hardware information: 228 * 229 * [ 69.558923] [ T6006]c7 6006 Hardware name: <REDACTED> 230 * 231 * or register dump (in KASAN reports only): 232 * 233 * ... RIP: 0033:0x7f96443109da 234 * ... RSP: 002b:00007ffcf0b51b08 EFLAGS: 00000202 ORIG_RAX: 00000000000000af 235 * ... RAX: ffffffffffffffda RBX: 000055dc3ee521a0 RCX: 00007f96443109da 236 * 237 * (on x86_64) 238 * 239 * ... pc : lpm_cpuidle_enter+0x258/0x384 240 * ... lr : lpm_cpuidle_enter+0x1d4/0x384 241 * ... sp : ffffff800820bea0 242 * ... x29: ffffff800820bea0 x28: ffffffc2305f3ce0 243 * ... ... 244 * ... x9 : 0000000000000001 x8 : 0000000000000000 245 * (on ARM64) 246 * 247 * We therefore omit the lines that contain "Comm:", "Hardware name:", or match the general 248 * purpose register regexp. 249 * 250 * @param line single line of `dmesg` output. 251 * @return updated line with sensitive data removed, or null if the line must be skipped. 252 */ stripSensitiveData(String line)253 public static String stripSensitiveData(String line) { 254 /* 255 * General purpose register names begin with "R" on x86_64 and "x" on ARM64. The letter is 256 * followed by two symbols (numbers, letters or spaces) and a colon, which is followed by a 257 * 16-digit hex number. The optional "_" prefix accounts for ORIG_RAX on x86. 258 */ 259 final String registerRegex = "[ _][Rx]..: [0-9a-f]{16}"; 260 final Pattern registerPattern = Pattern.compile(registerRegex); 261 262 final String corruptionRegex = "Detected corrupted memory at 0x[0-9a-f]+"; 263 final Pattern corruptionPattern = Pattern.compile(corruptionRegex); 264 265 if (line.contains("Comm: ") || line.contains("Hardware name: ")) return null; 266 if (registerPattern.matcher(line).find()) return null; 267 268 Matcher cm = corruptionPattern.matcher(line); 269 if (cm.find()) return cm.group(0); 270 return line; 271 } 272 273 /* 274 * Search dmesg output for the last error report from KFENCE or KASAN and copy it to Dropbox. 275 * 276 * Example report printed by the kernel (redacted to fit into 100 column limit): 277 * [ 69.236673] [ T6006]c7 6006 ========================================================= 278 * [ 69.245688] [ T6006]c7 6006 BUG: KFENCE: out-of-bounds in kfence_handle_page_fault 279 * [ 69.245688] [ T6006]c7 6006 280 * [ 69.257816] [ T6006]c7 6006 Out-of-bounds access at 0xffffffca75c45000 (...) 281 * [ 69.267102] [ T6006]c7 6006 kfence_handle_page_fault+0x1bc/0x208 282 * [ 69.273536] [ T6006]c7 6006 __do_kernel_fault+0xa8/0x11c 283 * ... 284 * [ 69.355427] [ T6006]c7 6006 kfence-#2 [0xffffffca75c46f30-0xffffffca75c46fff, ... 285 * [ 69.366938] [ T6006]c7 6006 __d_alloc+0x3c/0x1b4 286 * [ 69.371946] [ T6006]c7 6006 d_alloc_parallel+0x48/0x538 287 * [ 69.377578] [ T6006]c7 6006 __lookup_slow+0x60/0x15c 288 * ... 289 * [ 69.547684] [ T6006]c7 6006 CPU: 7 PID: 6006 Comm: sh Tainted: G S C O ... 290 * [ 69.558923] [ T6006]c7 6006 Hardware name: <REDACTED> 291 * [ 69.567059] [ T6006]c7 6006 ========================================================= 292 * 293 * We rely on the kernel printing task/CPU ID for every log line (CONFIG_PRINTK_CALLER=y). 294 * E.g. for the above report the task ID is T6006. Report lines may interleave with lines 295 * printed by other kernel tasks, which will have different task IDs, so in order to collect 296 * the report we: 297 * - find the next occurrence of the "BUG: " line in the kernel log, parse it to obtain the 298 * task ID and the tool name; 299 * - scan the rest of dmesg output and pick every line that has the same task ID, until we 300 * encounter a horizontal ruler, i.e.: 301 * [ 69.567059] [ T6006]c7 6006 ====================================================== 302 * - add that line to the error report, unless it contains sensitive information (see 303 * logLinePotentiallySensitive()) 304 * - repeat the above steps till the last report is found. 305 */ processDmesg(Context ctx)306 private void processDmesg(Context ctx) throws IOException { 307 if (sSentReports == MAX_ERROR_REPORTS) return; 308 /* 309 * Only SYSTEM_KASAN_ERROR_REPORT and SYSTEM_KFENCE_ERROR_REPORT are supported at the 310 * moment. 311 */ 312 final String[] bugTypes = new String[] { "KASAN", "KFENCE" }; 313 final String tsRegex = "^\\[[^]]+\\] "; 314 final String bugRegex = 315 tsRegex + "\\[([^]]+)\\].*BUG: (" + String.join("|", bugTypes) + "):"; 316 final Pattern bugPattern = Pattern.compile(bugRegex); 317 318 Process p = new ProcessBuilder("/system/bin/timeout", "-k", "90s", "60s", 319 "dmesg").redirectErrorStream(true).start(); 320 BufferedReader reader = new BufferedReader(new InputStreamReader(p.getInputStream())); 321 String line = null; 322 String task = null; 323 String tool = null; 324 String bugTitle = null; 325 Pattern reportPattern = null; 326 ArrayList<String> currentReport = null; 327 String lastReport = null; 328 329 while ((line = reader.readLine()) != null) { 330 if (currentReport == null) { 331 Matcher bm = bugPattern.matcher(line); 332 if (!bm.find()) continue; 333 task = bm.group(1); 334 tool = bm.group(2); 335 bugTitle = line; 336 currentReport = new ArrayList<String>(); 337 currentReport.add(line); 338 String reportRegex = tsRegex + "\\[" + task + "\\].*"; 339 reportPattern = Pattern.compile(reportRegex); 340 continue; 341 } 342 Matcher rm = reportPattern.matcher(line); 343 if (!rm.matches()) continue; 344 if ((line = stripSensitiveData(line)) == null) continue; 345 if (line.contains("================================")) { 346 lastReport = String.join("\n", currentReport); 347 currentReport = null; 348 continue; 349 } 350 currentReport.add(line); 351 } 352 if (lastReport == null) { 353 Slog.w(TAG, "Could not find report in dmesg."); 354 return; 355 } 356 357 // Avoid sending the same bug report twice. 358 if (bugTitle.equals(sLastReportedBug)) return; 359 360 final String reportTag = "SYSTEM_" + tool + "_ERROR_REPORT"; 361 final DropBoxManager db = ctx.getSystemService(DropBoxManager.class); 362 final String headers = getCurrentBootHeaders(); 363 final String reportText = headers + lastReport; 364 365 addTextToDropBox(db, reportTag, reportText, "/dev/kmsg", LOG_SIZE); 366 sLastReportedBug = bugTitle; 367 sSentReports++; 368 } 369 removeOldUpdatePackages(Context context)370 private void removeOldUpdatePackages(Context context) { 371 Downloads.removeAllDownloadsByPackage(context, OLD_UPDATER_PACKAGE, OLD_UPDATER_CLASS); 372 } 373 getPreviousBootHeaders()374 private static String getPreviousBootHeaders() { 375 try { 376 return FileUtils.readTextFile(lastHeaderFile, 0, null); 377 } catch (IOException e) { 378 return null; 379 } 380 } 381 getCurrentBootHeaders()382 private static String getCurrentBootHeaders() throws IOException { 383 return new StringBuilder(512) 384 .append("Build: ").append(Build.FINGERPRINT).append("\n") 385 .append("Hardware: ").append(Build.BOARD).append("\n") 386 .append("Revision: ") 387 .append(SystemProperties.get("ro.revision", "")).append("\n") 388 .append("Bootloader: ").append(Build.BOOTLOADER).append("\n") 389 .append("Radio: ").append(Build.getRadioVersion()).append("\n") 390 .append("Kernel: ") 391 .append(FileUtils.readTextFile(new File("/proc/version"), 1024, "...\n")) 392 .append("\n").toString(); 393 } 394 395 getBootHeadersToLogAndUpdate()396 private static String getBootHeadersToLogAndUpdate() throws IOException { 397 final String oldHeaders = getPreviousBootHeaders(); 398 final String newHeaders = getCurrentBootHeaders(); 399 400 try { 401 FileUtils.stringToFile(lastHeaderFile, newHeaders); 402 } catch (IOException e) { 403 Slog.e(TAG, "Error writing " + lastHeaderFile, e); 404 } 405 406 if (oldHeaders == null) { 407 // If we failed to read the old headers, use the current headers 408 // but note this in the headers so we know 409 return "isPrevious: false\n" + newHeaders; 410 } 411 412 return "isPrevious: true\n" + oldHeaders; 413 } 414 logBootEvents(Context ctx)415 private void logBootEvents(Context ctx) throws IOException { 416 final DropBoxManager db = (DropBoxManager) ctx.getSystemService(Context.DROPBOX_SERVICE); 417 final String headers = getBootHeadersToLogAndUpdate(); 418 final String bootReason = SystemProperties.get("ro.boot.bootreason", null); 419 420 String recovery = RecoverySystem.handleAftermath(ctx); 421 if (recovery != null && db != null) { 422 db.addText("SYSTEM_RECOVERY_LOG", headers + recovery); 423 } 424 425 String lastKmsgFooter = ""; 426 if (bootReason != null) { 427 lastKmsgFooter = new StringBuilder(512) 428 .append("\n") 429 .append("Boot info:\n") 430 .append("Last boot reason: ").append(bootReason).append("\n") 431 .toString(); 432 } 433 434 HashMap<String, Long> timestamps = readTimestamps(); 435 436 if (SystemProperties.getLong("ro.runtime.firstboot", 0) == 0) { 437 if (StorageManager.inCryptKeeperBounce()) { 438 // Encrypted, first boot to get PIN/pattern/password so data is tmpfs 439 // Don't set ro.runtime.firstboot so that we will do this again 440 // when data is properly mounted 441 } else { 442 String now = Long.toString(System.currentTimeMillis()); 443 SystemProperties.set("ro.runtime.firstboot", now); 444 } 445 if (db != null) db.addText("SYSTEM_BOOT", headers); 446 447 // Negative sizes mean to take the *tail* of the file (see FileUtils.readTextFile()) 448 addLastkToDropBox(db, timestamps, headers, lastKmsgFooter, 449 "/proc/last_kmsg", -LASTK_LOG_SIZE, "SYSTEM_LAST_KMSG"); 450 addLastkToDropBox(db, timestamps, headers, lastKmsgFooter, 451 "/sys/fs/pstore/console-ramoops", -LASTK_LOG_SIZE, "SYSTEM_LAST_KMSG"); 452 addLastkToDropBox(db, timestamps, headers, lastKmsgFooter, 453 "/sys/fs/pstore/console-ramoops-0", -LASTK_LOG_SIZE, "SYSTEM_LAST_KMSG"); 454 addFileToDropBox(db, timestamps, headers, "/cache/recovery/log", -LOG_SIZE, 455 "SYSTEM_RECOVERY_LOG"); 456 addFileToDropBox(db, timestamps, headers, "/cache/recovery/last_kmsg", 457 -LOG_SIZE, "SYSTEM_RECOVERY_KMSG"); 458 addAuditErrorsToDropBox(db, timestamps, headers, -LOG_SIZE, "SYSTEM_AUDIT"); 459 } else { 460 if (db != null) db.addText("SYSTEM_RESTART", headers); 461 } 462 // log always available fs_stat last so that logcat collecting tools can wait until 463 // fs_stat to get all file system metrics. 464 logFsShutdownTime(); 465 logFsMountTime(); 466 addFsckErrorsToDropBoxAndLogFsStat(db, timestamps, headers, -LOG_SIZE, "SYSTEM_FSCK"); 467 logSystemServerShutdownTimeMetrics(); 468 writeTimestamps(timestamps); 469 } 470 471 /** 472 * Add a tombstone to the DropBox. 473 * 474 * @param ctx Context 475 * @param tombstone path to the tombstone 476 */ addTombstoneToDropBox(Context ctx, File tombstone, boolean proto)477 public static void addTombstoneToDropBox(Context ctx, File tombstone, boolean proto) { 478 final DropBoxManager db = ctx.getSystemService(DropBoxManager.class); 479 if (db == null) { 480 Slog.e(TAG, "Can't log tombstone: DropBoxManager not available"); 481 return; 482 } 483 484 HashMap<String, Long> timestamps = readTimestamps(); 485 try { 486 if (proto) { 487 db.addFile(TAG_TOMBSTONE_PROTO, tombstone, 0); 488 } else { 489 final String headers = getBootHeadersToLogAndUpdate(); 490 addFileToDropBox(db, timestamps, headers, tombstone.getPath(), LOG_SIZE, 491 TAG_TOMBSTONE); 492 } 493 } catch (IOException e) { 494 Slog.e(TAG, "Can't log tombstone", e); 495 } 496 writeTimestamps(timestamps); 497 } 498 addLastkToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String footers, String filename, int maxSize, String tag)499 private static void addLastkToDropBox( 500 DropBoxManager db, HashMap<String, Long> timestamps, 501 String headers, String footers, String filename, int maxSize, 502 String tag) throws IOException { 503 int extraSize = headers.length() + TAG_TRUNCATED.length() + footers.length(); 504 // GMSCore will do 2nd truncation to be 192KiB 505 // LASTK_LOG_SIZE + extraSize must be less than GMSCORE_LASTK_LOG_SIZE 506 if (LASTK_LOG_SIZE + extraSize > GMSCORE_LASTK_LOG_SIZE) { 507 if (GMSCORE_LASTK_LOG_SIZE > extraSize) { 508 maxSize = -(GMSCORE_LASTK_LOG_SIZE - extraSize); 509 } else { 510 maxSize = 0; 511 } 512 } 513 addFileWithFootersToDropBox(db, timestamps, headers, footers, filename, maxSize, tag); 514 } 515 addFileToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String filename, int maxSize, String tag)516 private static void addFileToDropBox( 517 DropBoxManager db, HashMap<String, Long> timestamps, 518 String headers, String filename, int maxSize, String tag) throws IOException { 519 addFileWithFootersToDropBox(db, timestamps, headers, "", filename, maxSize, tag); 520 } 521 addFileWithFootersToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String footers, String filename, int maxSize, String tag)522 private static void addFileWithFootersToDropBox( 523 DropBoxManager db, HashMap<String, Long> timestamps, 524 String headers, String footers, String filename, int maxSize, 525 String tag) throws IOException { 526 if (db == null || !db.isTagEnabled(tag)) return; // Logging disabled 527 528 File file = new File(filename); 529 long fileTime = file.lastModified(); 530 if (fileTime <= 0) return; // File does not exist 531 532 if (timestamps.containsKey(filename) && timestamps.get(filename) == fileTime) { 533 return; // Already logged this particular file 534 } 535 536 timestamps.put(filename, fileTime); 537 538 539 String fileContents = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 540 String text = headers + fileContents + footers; 541 // Create an additional report for system server native crashes, with a special tag. 542 if (tag.equals(TAG_TOMBSTONE) && fileContents.contains(">>> system_server <<<")) { 543 addTextToDropBox(db, "system_server_native_crash", text, filename, maxSize); 544 } 545 if (tag.equals(TAG_TOMBSTONE)) { 546 FrameworkStatsLog.write(FrameworkStatsLog.TOMB_STONE_OCCURRED); 547 } 548 addTextToDropBox(db, tag, text, filename, maxSize); 549 } 550 addTextToDropBox(DropBoxManager db, String tag, String text, String filename, int maxSize)551 private static void addTextToDropBox(DropBoxManager db, String tag, String text, 552 String filename, int maxSize) { 553 Slog.i(TAG, "Copying " + filename + " to DropBox (" + tag + ")"); 554 db.addText(tag, text); 555 EventLog.writeEvent(DropboxLogTags.DROPBOX_FILE_COPY, filename, maxSize, tag); 556 } 557 addAuditErrorsToDropBox(DropBoxManager db, HashMap<String, Long> timestamps, String headers, int maxSize, String tag)558 private static void addAuditErrorsToDropBox(DropBoxManager db, 559 HashMap<String, Long> timestamps, String headers, int maxSize, String tag) 560 throws IOException { 561 if (db == null || !db.isTagEnabled(tag)) return; // Logging disabled 562 Slog.i(TAG, "Copying audit failures to DropBox"); 563 564 File file = new File("/proc/last_kmsg"); 565 long fileTime = file.lastModified(); 566 if (fileTime <= 0) { 567 file = new File("/sys/fs/pstore/console-ramoops"); 568 fileTime = file.lastModified(); 569 if (fileTime <= 0) { 570 file = new File("/sys/fs/pstore/console-ramoops-0"); 571 fileTime = file.lastModified(); 572 } 573 } 574 575 if (fileTime <= 0) return; // File does not exist 576 577 if (timestamps.containsKey(tag) && timestamps.get(tag) == fileTime) { 578 return; // Already logged this particular file 579 } 580 581 timestamps.put(tag, fileTime); 582 583 String log = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 584 StringBuilder sb = new StringBuilder(); 585 for (String line : log.split("\n")) { 586 if (line.contains("audit")) { 587 sb.append(line + "\n"); 588 } 589 } 590 Slog.i(TAG, "Copied " + sb.toString().length() + " worth of audits to DropBox"); 591 db.addText(tag, headers + sb.toString()); 592 } 593 addFsckErrorsToDropBoxAndLogFsStat(DropBoxManager db, HashMap<String, Long> timestamps, String headers, int maxSize, String tag)594 private static void addFsckErrorsToDropBoxAndLogFsStat(DropBoxManager db, 595 HashMap<String, Long> timestamps, String headers, int maxSize, String tag) 596 throws IOException { 597 boolean uploadEnabled = true; 598 if (db == null || !db.isTagEnabled(tag)) { 599 uploadEnabled = false; 600 } 601 boolean uploadNeeded = false; 602 Slog.i(TAG, "Checking for fsck errors"); 603 604 File file = new File("/dev/fscklogs/log"); 605 long fileTime = file.lastModified(); 606 if (fileTime <= 0) return; // File does not exist 607 608 String log = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 609 Pattern pattern = Pattern.compile(FS_STAT_PATTERN); 610 String lines[] = log.split("\n"); 611 int lineNumber = 0; 612 int lastFsStatLineNumber = 0; 613 for (String line : lines) { // should check all lines 614 if (line.contains(FSCK_FS_MODIFIED)) { 615 uploadNeeded = true; 616 } else if (line.contains("fs_stat")){ 617 Matcher matcher = pattern.matcher(line); 618 if (matcher.find()) { 619 handleFsckFsStat(matcher, lines, lastFsStatLineNumber, lineNumber); 620 lastFsStatLineNumber = lineNumber; 621 } else { 622 Slog.w(TAG, "cannot parse fs_stat:" + line); 623 } 624 } 625 lineNumber++; 626 } 627 628 if (uploadEnabled && uploadNeeded ) { 629 addFileToDropBox(db, timestamps, headers, "/dev/fscklogs/log", maxSize, tag); 630 } 631 632 // Remove the file so we don't re-upload if the runtime restarts. 633 file.delete(); 634 } 635 logFsMountTime()636 private static void logFsMountTime() { 637 for (String propPostfix : MOUNT_DURATION_PROPS_POSTFIX) { 638 int duration = SystemProperties.getInt("ro.boottime.init.mount_all." + propPostfix, 0); 639 if (duration != 0) { 640 int eventType; 641 switch (propPostfix) { 642 case "early": 643 eventType = 644 FrameworkStatsLog 645 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_EARLY_DURATION; 646 break; 647 case "default": 648 eventType = 649 FrameworkStatsLog 650 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_DEFAULT_DURATION; 651 break; 652 case "late": 653 eventType = 654 FrameworkStatsLog 655 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_LATE_DURATION; 656 break; 657 default: 658 continue; 659 } 660 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, 661 eventType, duration); 662 } 663 } 664 } 665 666 // TODO b/64815357 Move to bootstat.cpp and log AbsoluteRebootTime logSystemServerShutdownTimeMetrics()667 private static void logSystemServerShutdownTimeMetrics() { 668 File metricsFile = new File(SHUTDOWN_METRICS_FILE); 669 String metricsStr = null; 670 if (metricsFile.exists()) { 671 try { 672 metricsStr = FileUtils.readTextFile(metricsFile, 0, null); 673 } catch (IOException e) { 674 Slog.e(TAG, "Problem reading " + metricsFile, e); 675 } 676 } 677 if (!TextUtils.isEmpty(metricsStr)) { 678 String reboot = null; 679 String reason = null; 680 String start_time = null; 681 String duration = null; 682 String[] array = metricsStr.split(","); 683 for (String keyValueStr : array) { 684 String[] keyValue = keyValueStr.split(":"); 685 if (keyValue.length != 2) { 686 Slog.e(TAG, "Wrong format of shutdown metrics - " + metricsStr); 687 continue; 688 } 689 // Ignore keys that are not indended for tron 690 if (keyValue[0].startsWith(SHUTDOWN_TRON_METRICS_PREFIX)) { 691 logTronShutdownMetric(keyValue[0], keyValue[1]); 692 if (keyValue[0].equals(METRIC_SYSTEM_SERVER)) { 693 duration = keyValue[1]; 694 } 695 } 696 if (keyValue[0].equals("reboot")) { 697 reboot = keyValue[1]; 698 } else if (keyValue[0].equals("reason")) { 699 reason = keyValue[1]; 700 } else if (keyValue[0].equals(METRIC_SHUTDOWN_TIME_START)) { 701 start_time = keyValue[1]; 702 } 703 } 704 logStatsdShutdownAtom(reboot, reason, start_time, duration); 705 } 706 metricsFile.delete(); 707 } 708 logTronShutdownMetric(String metricName, String valueStr)709 private static void logTronShutdownMetric(String metricName, String valueStr) { 710 int value; 711 try { 712 value = Integer.parseInt(valueStr); 713 } catch (NumberFormatException e) { 714 Slog.e(TAG, "Cannot parse metric " + metricName + " int value - " + valueStr); 715 return; 716 } 717 if (value >= 0) { 718 MetricsLogger.histogram(null, metricName, value); 719 } 720 } 721 logStatsdShutdownAtom( String rebootStr, String reasonStr, String startStr, String durationStr)722 private static void logStatsdShutdownAtom( 723 String rebootStr, String reasonStr, String startStr, String durationStr) { 724 boolean reboot = false; 725 String reason = "<EMPTY>"; 726 long start = 0; 727 long duration = 0; 728 729 if (rebootStr != null) { 730 if (rebootStr.equals("y")) { 731 reboot = true; 732 } else if (!rebootStr.equals("n")) { 733 Slog.e(TAG, "Unexpected value for reboot : " + rebootStr); 734 } 735 } else { 736 Slog.e(TAG, "No value received for reboot"); 737 } 738 739 if (reasonStr != null) { 740 reason = reasonStr; 741 } else { 742 Slog.e(TAG, "No value received for shutdown reason"); 743 } 744 745 if (startStr != null) { 746 try { 747 start = Long.parseLong(startStr); 748 } catch (NumberFormatException e) { 749 Slog.e(TAG, "Cannot parse shutdown start time: " + startStr); 750 } 751 } else { 752 Slog.e(TAG, "No value received for shutdown start time"); 753 } 754 755 if (durationStr != null) { 756 try { 757 duration = Long.parseLong(durationStr); 758 } catch (NumberFormatException e) { 759 Slog.e(TAG, "Cannot parse shutdown duration: " + startStr); 760 } 761 } else { 762 Slog.e(TAG, "No value received for shutdown duration"); 763 } 764 765 FrameworkStatsLog.write(FrameworkStatsLog.SHUTDOWN_SEQUENCE_REPORTED, reboot, reason, start, 766 duration); 767 } 768 logFsShutdownTime()769 private static void logFsShutdownTime() { 770 File f = null; 771 for (String fileName : LAST_KMSG_FILES) { 772 File file = new File(fileName); 773 if (!file.exists()) continue; 774 f = file; 775 break; 776 } 777 if (f == null) { // no last_kmsg 778 return; 779 } 780 781 final int maxReadSize = 16*1024; 782 // last_kmsg can be very big, so only parse the last part 783 String lines; 784 try { 785 lines = FileUtils.readTextFile(f, -maxReadSize, null); 786 } catch (IOException e) { 787 Slog.w(TAG, "cannot read last msg", e); 788 return; 789 } 790 Pattern pattern = Pattern.compile(LAST_SHUTDOWN_TIME_PATTERN, Pattern.MULTILINE); 791 Matcher matcher = pattern.matcher(lines); 792 if (matcher.find()) { 793 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, 794 FrameworkStatsLog.BOOT_TIME_EVENT_DURATION__EVENT__SHUTDOWN_DURATION, 795 Integer.parseInt(matcher.group(1))); 796 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 797 FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE__EVENT__SHUTDOWN_UMOUNT_STAT, 798 Integer.parseInt(matcher.group(2))); 799 Slog.i(TAG, "boot_fs_shutdown," + matcher.group(1) + "," + matcher.group(2)); 800 } else { // not found 801 // This can happen when a device has too much kernel log after file system unmount 802 // ,exceeding maxReadSize. And having that much kernel logging can affect overall 803 // performance as well. So it is better to fix the kernel to reduce the amount of log. 804 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 805 FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE__EVENT__SHUTDOWN_UMOUNT_STAT, 806 UMOUNT_STATUS_NOT_AVAILABLE); 807 Slog.w(TAG, "boot_fs_shutdown, string not found"); 808 } 809 } 810 811 /** 812 * Fix fs_stat from e2fsck. 813 * For now, only handle the case of quota warning caused by tree optimization. Clear fs fix 814 * flag (=0x400) caused by that. 815 * 816 * @param partition partition name 817 * @param statOrg original stat reported from e2fsck log 818 * @param lines e2fsck logs broken down into lines 819 * @param startLineNumber start line to parse 820 * @param endLineNumber end line. exclusive. 821 * @return updated fs_stat. For tree optimization, will clear bit 0x400. 822 */ 823 @VisibleForTesting fixFsckFsStat(String partition, int statOrg, String[] lines, int startLineNumber, int endLineNumber)824 public static int fixFsckFsStat(String partition, int statOrg, String[] lines, 825 int startLineNumber, int endLineNumber) { 826 int stat = statOrg; 827 if ((stat & FS_STAT_FS_FIXED) != 0) { 828 // fs was fixed. should check if quota warning was caused by tree optimization. 829 // This is not a real fix but optimization, so should not be counted as a fs fix. 830 Pattern passPattern = Pattern.compile(FSCK_PASS_PATTERN); 831 Pattern treeOptPattern = Pattern.compile(FSCK_TREE_OPTIMIZATION_PATTERN); 832 String currentPass = ""; 833 boolean foundTreeOptimization = false; 834 boolean foundQuotaFix = false; 835 boolean foundTimestampAdjustment = false; 836 boolean foundOtherFix = false; 837 String otherFixLine = null; 838 for (int i = startLineNumber; i < endLineNumber; i++) { 839 String line = lines[i]; 840 if (line.contains(FSCK_FS_MODIFIED)) { // no need to parse above this 841 break; 842 } else if (line.startsWith("Pass ")) { 843 Matcher matcher = passPattern.matcher(line); 844 if (matcher.find()) { 845 currentPass = matcher.group(1); 846 } 847 } else if (line.startsWith("Inode ")) { 848 Matcher matcher = treeOptPattern.matcher(line); 849 if (matcher.find() && currentPass.equals("1")) { 850 foundTreeOptimization = true; 851 Slog.i(TAG, "fs_stat, partition:" + partition + " found tree optimization:" 852 + line); 853 } else { 854 foundOtherFix = true; 855 otherFixLine = line; 856 break; 857 } 858 } else if (line.startsWith("[QUOTA WARNING]") && currentPass.equals("5")) { 859 Slog.i(TAG, "fs_stat, partition:" + partition + " found quota warning:" 860 + line); 861 foundQuotaFix = true; 862 if (!foundTreeOptimization) { // only quota warning, this is real fix. 863 otherFixLine = line; 864 break; 865 } 866 } else if (line.startsWith("Update quota info") && currentPass.equals("5")) { 867 // follows "[QUOTA WARNING]", ignore 868 } else if (line.startsWith("Timestamp(s) on inode") && 869 line.contains("beyond 2310-04-04 are likely pre-1970") && 870 currentPass.equals("1")) { 871 Slog.i(TAG, "fs_stat, partition:" + partition + " found timestamp adjustment:" 872 + line); 873 // followed by next line, "Fix? yes" 874 if (lines[i + 1].contains("Fix? yes")) { 875 i++; 876 } 877 foundTimestampAdjustment = true; 878 } else { 879 line = line.trim(); 880 // ignore empty msg or any msg before Pass 1 881 if (!line.isEmpty() && !currentPass.isEmpty()) { 882 foundOtherFix = true; 883 otherFixLine = line; 884 break; 885 } 886 } 887 } 888 if (foundOtherFix) { 889 if (otherFixLine != null) { 890 Slog.i(TAG, "fs_stat, partition:" + partition + " fix:" + otherFixLine); 891 } 892 } else if (foundQuotaFix && !foundTreeOptimization) { 893 Slog.i(TAG, "fs_stat, got quota fix without tree optimization, partition:" + 894 partition); 895 } else if ((foundTreeOptimization && foundQuotaFix) || foundTimestampAdjustment) { 896 // not a real fix, so clear it. 897 Slog.i(TAG, "fs_stat, partition:" + partition + " fix ignored"); 898 stat &= ~FS_STAT_FS_FIXED; 899 } 900 } 901 return stat; 902 } 903 handleFsckFsStat(Matcher match, String[] lines, int startLineNumber, int endLineNumber)904 private static void handleFsckFsStat(Matcher match, String[] lines, int startLineNumber, 905 int endLineNumber) { 906 String partition = match.group(1); 907 int stat; 908 try { 909 stat = Integer.decode(match.group(2)); 910 } catch (NumberFormatException e) { 911 Slog.w(TAG, "cannot parse fs_stat: partition:" + partition + " stat:" + match.group(2)); 912 return; 913 } 914 stat = fixFsckFsStat(partition, stat, lines, startLineNumber, endLineNumber); 915 if ("userdata".equals(partition) || "data".equals(partition)) { 916 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 917 FrameworkStatsLog 918 .BOOT_TIME_EVENT_ERROR_CODE__EVENT__FS_MGR_FS_STAT_DATA_PARTITION, 919 stat); 920 } 921 Slog.i(TAG, "fs_stat, partition:" + partition + " stat:0x" + Integer.toHexString(stat)); 922 } 923 readTimestamps()924 private static HashMap<String, Long> readTimestamps() { 925 synchronized (sFile) { 926 HashMap<String, Long> timestamps = new HashMap<String, Long>(); 927 boolean success = false; 928 try (final FileInputStream stream = sFile.openRead()) { 929 TypedXmlPullParser parser = Xml.resolvePullParser(stream); 930 931 int type; 932 while ((type = parser.next()) != XmlPullParser.START_TAG 933 && type != XmlPullParser.END_DOCUMENT) { 934 ; 935 } 936 937 if (type != XmlPullParser.START_TAG) { 938 throw new IllegalStateException("no start tag found"); 939 } 940 941 int outerDepth = parser.getDepth(); // Skip the outer <log-files> tag. 942 while ((type = parser.next()) != XmlPullParser.END_DOCUMENT 943 && (type != XmlPullParser.END_TAG || parser.getDepth() > outerDepth)) { 944 if (type == XmlPullParser.END_TAG || type == XmlPullParser.TEXT) { 945 continue; 946 } 947 948 String tagName = parser.getName(); 949 if (tagName.equals("log")) { 950 final String filename = parser.getAttributeValue(null, "filename"); 951 final long timestamp = parser.getAttributeLong(null, "timestamp"); 952 timestamps.put(filename, timestamp); 953 } else { 954 Slog.w(TAG, "Unknown tag: " + parser.getName()); 955 XmlUtils.skipCurrentTag(parser); 956 } 957 } 958 success = true; 959 } catch (FileNotFoundException e) { 960 Slog.i(TAG, "No existing last log timestamp file " + sFile.getBaseFile() + 961 "; starting empty"); 962 } catch (IOException e) { 963 Slog.w(TAG, "Failed parsing " + e); 964 } catch (IllegalStateException e) { 965 Slog.w(TAG, "Failed parsing " + e); 966 } catch (NullPointerException e) { 967 Slog.w(TAG, "Failed parsing " + e); 968 } catch (XmlPullParserException e) { 969 Slog.w(TAG, "Failed parsing " + e); 970 } finally { 971 if (!success) { 972 timestamps.clear(); 973 } 974 } 975 return timestamps; 976 } 977 } 978 writeTimestamps(HashMap<String, Long> timestamps)979 private static void writeTimestamps(HashMap<String, Long> timestamps) { 980 synchronized (sFile) { 981 final FileOutputStream stream; 982 try { 983 stream = sFile.startWrite(); 984 } catch (IOException e) { 985 Slog.w(TAG, "Failed to write timestamp file: " + e); 986 return; 987 } 988 989 try { 990 TypedXmlSerializer out = Xml.resolveSerializer(stream); 991 out.startDocument(null, true); 992 out.startTag(null, "log-files"); 993 994 Iterator<String> itor = timestamps.keySet().iterator(); 995 while (itor.hasNext()) { 996 String filename = itor.next(); 997 out.startTag(null, "log"); 998 out.attribute(null, "filename", filename); 999 out.attributeLong(null, "timestamp", timestamps.get(filename)); 1000 out.endTag(null, "log"); 1001 } 1002 1003 out.endTag(null, "log-files"); 1004 out.endDocument(); 1005 1006 sFile.finishWrite(stream); 1007 } catch (IOException e) { 1008 Slog.w(TAG, "Failed to write timestamp file, using the backup: " + e); 1009 sFile.failWrite(stream); 1010 } 1011 } 1012 } 1013 } 1014