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 final String bootReason = SystemProperties.get("ro.boot.bootreason", null); 480 HashMap<String, Long> timestamps = readTimestamps(); 481 try { 482 if (proto) { 483 db.addFile(TAG_TOMBSTONE_PROTO, tombstone, 0); 484 } else { 485 final String headers = getBootHeadersToLogAndUpdate(); 486 addFileToDropBox(db, timestamps, headers, tombstone.getPath(), LOG_SIZE, 487 TAG_TOMBSTONE); 488 } 489 } catch (IOException e) { 490 Slog.e(TAG, "Can't log tombstone", e); 491 } 492 writeTimestamps(timestamps); 493 } 494 addLastkToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String footers, String filename, int maxSize, String tag)495 private static void addLastkToDropBox( 496 DropBoxManager db, HashMap<String, Long> timestamps, 497 String headers, String footers, String filename, int maxSize, 498 String tag) throws IOException { 499 int extraSize = headers.length() + TAG_TRUNCATED.length() + footers.length(); 500 // GMSCore will do 2nd truncation to be 192KiB 501 // LASTK_LOG_SIZE + extraSize must be less than GMSCORE_LASTK_LOG_SIZE 502 if (LASTK_LOG_SIZE + extraSize > GMSCORE_LASTK_LOG_SIZE) { 503 if (GMSCORE_LASTK_LOG_SIZE > extraSize) { 504 maxSize = -(GMSCORE_LASTK_LOG_SIZE - extraSize); 505 } else { 506 maxSize = 0; 507 } 508 } 509 addFileWithFootersToDropBox(db, timestamps, headers, footers, filename, maxSize, tag); 510 } 511 addFileToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String filename, int maxSize, String tag)512 private static void addFileToDropBox( 513 DropBoxManager db, HashMap<String, Long> timestamps, 514 String headers, String filename, int maxSize, String tag) throws IOException { 515 addFileWithFootersToDropBox(db, timestamps, headers, "", filename, maxSize, tag); 516 } 517 addFileWithFootersToDropBox( DropBoxManager db, HashMap<String, Long> timestamps, String headers, String footers, String filename, int maxSize, String tag)518 private static void addFileWithFootersToDropBox( 519 DropBoxManager db, HashMap<String, Long> timestamps, 520 String headers, String footers, String filename, int maxSize, 521 String tag) throws IOException { 522 if (db == null || !db.isTagEnabled(tag)) return; // Logging disabled 523 524 File file = new File(filename); 525 long fileTime = file.lastModified(); 526 if (fileTime <= 0) return; // File does not exist 527 528 if (timestamps.containsKey(filename) && timestamps.get(filename) == fileTime) { 529 return; // Already logged this particular file 530 } 531 532 timestamps.put(filename, fileTime); 533 534 535 String fileContents = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 536 String text = headers + fileContents + footers; 537 // Create an additional report for system server native crashes, with a special tag. 538 if (tag.equals(TAG_TOMBSTONE) && fileContents.contains(">>> system_server <<<")) { 539 addTextToDropBox(db, "system_server_native_crash", text, filename, maxSize); 540 } 541 if (tag.equals(TAG_TOMBSTONE)) { 542 FrameworkStatsLog.write(FrameworkStatsLog.TOMB_STONE_OCCURRED); 543 } 544 addTextToDropBox(db, tag, text, filename, maxSize); 545 } 546 addTextToDropBox(DropBoxManager db, String tag, String text, String filename, int maxSize)547 private static void addTextToDropBox(DropBoxManager db, String tag, String text, 548 String filename, int maxSize) { 549 Slog.i(TAG, "Copying " + filename + " to DropBox (" + tag + ")"); 550 db.addText(tag, text); 551 EventLog.writeEvent(DropboxLogTags.DROPBOX_FILE_COPY, filename, maxSize, tag); 552 } 553 addAuditErrorsToDropBox(DropBoxManager db, HashMap<String, Long> timestamps, String headers, int maxSize, String tag)554 private static void addAuditErrorsToDropBox(DropBoxManager db, 555 HashMap<String, Long> timestamps, String headers, int maxSize, String tag) 556 throws IOException { 557 if (db == null || !db.isTagEnabled(tag)) return; // Logging disabled 558 Slog.i(TAG, "Copying audit failures to DropBox"); 559 560 File file = new File("/proc/last_kmsg"); 561 long fileTime = file.lastModified(); 562 if (fileTime <= 0) { 563 file = new File("/sys/fs/pstore/console-ramoops"); 564 fileTime = file.lastModified(); 565 if (fileTime <= 0) { 566 file = new File("/sys/fs/pstore/console-ramoops-0"); 567 fileTime = file.lastModified(); 568 } 569 } 570 571 if (fileTime <= 0) return; // File does not exist 572 573 if (timestamps.containsKey(tag) && timestamps.get(tag) == fileTime) { 574 return; // Already logged this particular file 575 } 576 577 timestamps.put(tag, fileTime); 578 579 String log = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 580 StringBuilder sb = new StringBuilder(); 581 for (String line : log.split("\n")) { 582 if (line.contains("audit")) { 583 sb.append(line + "\n"); 584 } 585 } 586 Slog.i(TAG, "Copied " + sb.toString().length() + " worth of audits to DropBox"); 587 db.addText(tag, headers + sb.toString()); 588 } 589 addFsckErrorsToDropBoxAndLogFsStat(DropBoxManager db, HashMap<String, Long> timestamps, String headers, int maxSize, String tag)590 private static void addFsckErrorsToDropBoxAndLogFsStat(DropBoxManager db, 591 HashMap<String, Long> timestamps, String headers, int maxSize, String tag) 592 throws IOException { 593 boolean uploadEnabled = true; 594 if (db == null || !db.isTagEnabled(tag)) { 595 uploadEnabled = false; 596 } 597 boolean uploadNeeded = false; 598 Slog.i(TAG, "Checking for fsck errors"); 599 600 File file = new File("/dev/fscklogs/log"); 601 long fileTime = file.lastModified(); 602 if (fileTime <= 0) return; // File does not exist 603 604 String log = FileUtils.readTextFile(file, maxSize, TAG_TRUNCATED); 605 Pattern pattern = Pattern.compile(FS_STAT_PATTERN); 606 String lines[] = log.split("\n"); 607 int lineNumber = 0; 608 int lastFsStatLineNumber = 0; 609 for (String line : lines) { // should check all lines 610 if (line.contains(FSCK_FS_MODIFIED)) { 611 uploadNeeded = true; 612 } else if (line.contains("fs_stat")){ 613 Matcher matcher = pattern.matcher(line); 614 if (matcher.find()) { 615 handleFsckFsStat(matcher, lines, lastFsStatLineNumber, lineNumber); 616 lastFsStatLineNumber = lineNumber; 617 } else { 618 Slog.w(TAG, "cannot parse fs_stat:" + line); 619 } 620 } 621 lineNumber++; 622 } 623 624 if (uploadEnabled && uploadNeeded ) { 625 addFileToDropBox(db, timestamps, headers, "/dev/fscklogs/log", maxSize, tag); 626 } 627 628 // Remove the file so we don't re-upload if the runtime restarts. 629 file.delete(); 630 } 631 logFsMountTime()632 private static void logFsMountTime() { 633 for (String propPostfix : MOUNT_DURATION_PROPS_POSTFIX) { 634 int duration = SystemProperties.getInt("ro.boottime.init.mount_all." + propPostfix, 0); 635 if (duration != 0) { 636 int eventType; 637 switch (propPostfix) { 638 case "early": 639 eventType = 640 FrameworkStatsLog 641 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_EARLY_DURATION; 642 break; 643 case "default": 644 eventType = 645 FrameworkStatsLog 646 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_DEFAULT_DURATION; 647 break; 648 case "late": 649 eventType = 650 FrameworkStatsLog 651 .BOOT_TIME_EVENT_DURATION__EVENT__MOUNT_LATE_DURATION; 652 break; 653 default: 654 continue; 655 } 656 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, 657 eventType, duration); 658 } 659 } 660 } 661 662 // TODO b/64815357 Move to bootstat.cpp and log AbsoluteRebootTime logSystemServerShutdownTimeMetrics()663 private static void logSystemServerShutdownTimeMetrics() { 664 File metricsFile = new File(SHUTDOWN_METRICS_FILE); 665 String metricsStr = null; 666 if (metricsFile.exists()) { 667 try { 668 metricsStr = FileUtils.readTextFile(metricsFile, 0, null); 669 } catch (IOException e) { 670 Slog.e(TAG, "Problem reading " + metricsFile, e); 671 } 672 } 673 if (!TextUtils.isEmpty(metricsStr)) { 674 String reboot = null; 675 String reason = null; 676 String start_time = null; 677 String duration = null; 678 String[] array = metricsStr.split(","); 679 for (String keyValueStr : array) { 680 String[] keyValue = keyValueStr.split(":"); 681 if (keyValue.length != 2) { 682 Slog.e(TAG, "Wrong format of shutdown metrics - " + metricsStr); 683 continue; 684 } 685 // Ignore keys that are not indended for tron 686 if (keyValue[0].startsWith(SHUTDOWN_TRON_METRICS_PREFIX)) { 687 logTronShutdownMetric(keyValue[0], keyValue[1]); 688 if (keyValue[0].equals(METRIC_SYSTEM_SERVER)) { 689 duration = keyValue[1]; 690 } 691 } 692 if (keyValue[0].equals("reboot")) { 693 reboot = keyValue[1]; 694 } else if (keyValue[0].equals("reason")) { 695 reason = keyValue[1]; 696 } else if (keyValue[0].equals(METRIC_SHUTDOWN_TIME_START)) { 697 start_time = keyValue[1]; 698 } 699 } 700 logStatsdShutdownAtom(reboot, reason, start_time, duration); 701 } 702 metricsFile.delete(); 703 } 704 logTronShutdownMetric(String metricName, String valueStr)705 private static void logTronShutdownMetric(String metricName, String valueStr) { 706 int value; 707 try { 708 value = Integer.parseInt(valueStr); 709 } catch (NumberFormatException e) { 710 Slog.e(TAG, "Cannot parse metric " + metricName + " int value - " + valueStr); 711 return; 712 } 713 if (value >= 0) { 714 MetricsLogger.histogram(null, metricName, value); 715 } 716 } 717 logStatsdShutdownAtom( String rebootStr, String reasonStr, String startStr, String durationStr)718 private static void logStatsdShutdownAtom( 719 String rebootStr, String reasonStr, String startStr, String durationStr) { 720 boolean reboot = false; 721 String reason = "<EMPTY>"; 722 long start = 0; 723 long duration = 0; 724 725 if (rebootStr != null) { 726 if (rebootStr.equals("y")) { 727 reboot = true; 728 } else if (!rebootStr.equals("n")) { 729 Slog.e(TAG, "Unexpected value for reboot : " + rebootStr); 730 } 731 } else { 732 Slog.e(TAG, "No value received for reboot"); 733 } 734 735 if (reasonStr != null) { 736 reason = reasonStr; 737 } else { 738 Slog.e(TAG, "No value received for shutdown reason"); 739 } 740 741 if (startStr != null) { 742 try { 743 start = Long.parseLong(startStr); 744 } catch (NumberFormatException e) { 745 Slog.e(TAG, "Cannot parse shutdown start time: " + startStr); 746 } 747 } else { 748 Slog.e(TAG, "No value received for shutdown start time"); 749 } 750 751 if (durationStr != null) { 752 try { 753 duration = Long.parseLong(durationStr); 754 } catch (NumberFormatException e) { 755 Slog.e(TAG, "Cannot parse shutdown duration: " + startStr); 756 } 757 } else { 758 Slog.e(TAG, "No value received for shutdown duration"); 759 } 760 761 FrameworkStatsLog.write(FrameworkStatsLog.SHUTDOWN_SEQUENCE_REPORTED, reboot, reason, start, 762 duration); 763 } 764 logFsShutdownTime()765 private static void logFsShutdownTime() { 766 File f = null; 767 for (String fileName : LAST_KMSG_FILES) { 768 File file = new File(fileName); 769 if (!file.exists()) continue; 770 f = file; 771 break; 772 } 773 if (f == null) { // no last_kmsg 774 return; 775 } 776 777 final int maxReadSize = 16*1024; 778 // last_kmsg can be very big, so only parse the last part 779 String lines; 780 try { 781 lines = FileUtils.readTextFile(f, -maxReadSize, null); 782 } catch (IOException e) { 783 Slog.w(TAG, "cannot read last msg", e); 784 return; 785 } 786 Pattern pattern = Pattern.compile(LAST_SHUTDOWN_TIME_PATTERN, Pattern.MULTILINE); 787 Matcher matcher = pattern.matcher(lines); 788 if (matcher.find()) { 789 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_DURATION_REPORTED, 790 FrameworkStatsLog.BOOT_TIME_EVENT_DURATION__EVENT__SHUTDOWN_DURATION, 791 Integer.parseInt(matcher.group(1))); 792 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 793 FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE__EVENT__SHUTDOWN_UMOUNT_STAT, 794 Integer.parseInt(matcher.group(2))); 795 Slog.i(TAG, "boot_fs_shutdown," + matcher.group(1) + "," + matcher.group(2)); 796 } else { // not found 797 // This can happen when a device has too much kernel log after file system unmount 798 // ,exceeding maxReadSize. And having that much kernel logging can affect overall 799 // performance as well. So it is better to fix the kernel to reduce the amount of log. 800 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 801 FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE__EVENT__SHUTDOWN_UMOUNT_STAT, 802 UMOUNT_STATUS_NOT_AVAILABLE); 803 Slog.w(TAG, "boot_fs_shutdown, string not found"); 804 } 805 } 806 807 /** 808 * Fix fs_stat from e2fsck. 809 * For now, only handle the case of quota warning caused by tree optimization. Clear fs fix 810 * flag (=0x400) caused by that. 811 * 812 * @param partition partition name 813 * @param statOrg original stat reported from e2fsck log 814 * @param lines e2fsck logs broken down into lines 815 * @param startLineNumber start line to parse 816 * @param endLineNumber end line. exclusive. 817 * @return updated fs_stat. For tree optimization, will clear bit 0x400. 818 */ 819 @VisibleForTesting fixFsckFsStat(String partition, int statOrg, String[] lines, int startLineNumber, int endLineNumber)820 public static int fixFsckFsStat(String partition, int statOrg, String[] lines, 821 int startLineNumber, int endLineNumber) { 822 int stat = statOrg; 823 if ((stat & FS_STAT_FS_FIXED) != 0) { 824 // fs was fixed. should check if quota warning was caused by tree optimization. 825 // This is not a real fix but optimization, so should not be counted as a fs fix. 826 Pattern passPattern = Pattern.compile(FSCK_PASS_PATTERN); 827 Pattern treeOptPattern = Pattern.compile(FSCK_TREE_OPTIMIZATION_PATTERN); 828 String currentPass = ""; 829 boolean foundTreeOptimization = false; 830 boolean foundQuotaFix = false; 831 boolean foundTimestampAdjustment = false; 832 boolean foundOtherFix = false; 833 String otherFixLine = null; 834 for (int i = startLineNumber; i < endLineNumber; i++) { 835 String line = lines[i]; 836 if (line.contains(FSCK_FS_MODIFIED)) { // no need to parse above this 837 break; 838 } else if (line.startsWith("Pass ")) { 839 Matcher matcher = passPattern.matcher(line); 840 if (matcher.find()) { 841 currentPass = matcher.group(1); 842 } 843 } else if (line.startsWith("Inode ")) { 844 Matcher matcher = treeOptPattern.matcher(line); 845 if (matcher.find() && currentPass.equals("1")) { 846 foundTreeOptimization = true; 847 Slog.i(TAG, "fs_stat, partition:" + partition + " found tree optimization:" 848 + line); 849 } else { 850 foundOtherFix = true; 851 otherFixLine = line; 852 break; 853 } 854 } else if (line.startsWith("[QUOTA WARNING]") && currentPass.equals("5")) { 855 Slog.i(TAG, "fs_stat, partition:" + partition + " found quota warning:" 856 + line); 857 foundQuotaFix = true; 858 if (!foundTreeOptimization) { // only quota warning, this is real fix. 859 otherFixLine = line; 860 break; 861 } 862 } else if (line.startsWith("Update quota info") && currentPass.equals("5")) { 863 // follows "[QUOTA WARNING]", ignore 864 } else if (line.startsWith("Timestamp(s) on inode") && 865 line.contains("beyond 2310-04-04 are likely pre-1970") && 866 currentPass.equals("1")) { 867 Slog.i(TAG, "fs_stat, partition:" + partition + " found timestamp adjustment:" 868 + line); 869 // followed by next line, "Fix? yes" 870 if (lines[i + 1].contains("Fix? yes")) { 871 i++; 872 } 873 foundTimestampAdjustment = true; 874 } else { 875 line = line.trim(); 876 // ignore empty msg or any msg before Pass 1 877 if (!line.isEmpty() && !currentPass.isEmpty()) { 878 foundOtherFix = true; 879 otherFixLine = line; 880 break; 881 } 882 } 883 } 884 if (foundOtherFix) { 885 if (otherFixLine != null) { 886 Slog.i(TAG, "fs_stat, partition:" + partition + " fix:" + otherFixLine); 887 } 888 } else if (foundQuotaFix && !foundTreeOptimization) { 889 Slog.i(TAG, "fs_stat, got quota fix without tree optimization, partition:" + 890 partition); 891 } else if ((foundTreeOptimization && foundQuotaFix) || foundTimestampAdjustment) { 892 // not a real fix, so clear it. 893 Slog.i(TAG, "fs_stat, partition:" + partition + " fix ignored"); 894 stat &= ~FS_STAT_FS_FIXED; 895 } 896 } 897 return stat; 898 } 899 handleFsckFsStat(Matcher match, String[] lines, int startLineNumber, int endLineNumber)900 private static void handleFsckFsStat(Matcher match, String[] lines, int startLineNumber, 901 int endLineNumber) { 902 String partition = match.group(1); 903 int stat; 904 try { 905 stat = Integer.decode(match.group(2)); 906 } catch (NumberFormatException e) { 907 Slog.w(TAG, "cannot parse fs_stat: partition:" + partition + " stat:" + match.group(2)); 908 return; 909 } 910 stat = fixFsckFsStat(partition, stat, lines, startLineNumber, endLineNumber); 911 if ("userdata".equals(partition) || "data".equals(partition)) { 912 FrameworkStatsLog.write(FrameworkStatsLog.BOOT_TIME_EVENT_ERROR_CODE_REPORTED, 913 FrameworkStatsLog 914 .BOOT_TIME_EVENT_ERROR_CODE__EVENT__FS_MGR_FS_STAT_DATA_PARTITION, 915 stat); 916 } 917 Slog.i(TAG, "fs_stat, partition:" + partition + " stat:0x" + Integer.toHexString(stat)); 918 } 919 readTimestamps()920 private static HashMap<String, Long> readTimestamps() { 921 synchronized (sFile) { 922 HashMap<String, Long> timestamps = new HashMap<String, Long>(); 923 boolean success = false; 924 try (final FileInputStream stream = sFile.openRead()) { 925 TypedXmlPullParser parser = Xml.resolvePullParser(stream); 926 927 int type; 928 while ((type = parser.next()) != XmlPullParser.START_TAG 929 && type != XmlPullParser.END_DOCUMENT) { 930 ; 931 } 932 933 if (type != XmlPullParser.START_TAG) { 934 throw new IllegalStateException("no start tag found"); 935 } 936 937 int outerDepth = parser.getDepth(); // Skip the outer <log-files> tag. 938 while ((type = parser.next()) != XmlPullParser.END_DOCUMENT 939 && (type != XmlPullParser.END_TAG || parser.getDepth() > outerDepth)) { 940 if (type == XmlPullParser.END_TAG || type == XmlPullParser.TEXT) { 941 continue; 942 } 943 944 String tagName = parser.getName(); 945 if (tagName.equals("log")) { 946 final String filename = parser.getAttributeValue(null, "filename"); 947 final long timestamp = parser.getAttributeLong(null, "timestamp"); 948 timestamps.put(filename, timestamp); 949 } else { 950 Slog.w(TAG, "Unknown tag: " + parser.getName()); 951 XmlUtils.skipCurrentTag(parser); 952 } 953 } 954 success = true; 955 } catch (FileNotFoundException e) { 956 Slog.i(TAG, "No existing last log timestamp file " + sFile.getBaseFile() + 957 "; starting empty"); 958 } catch (IOException e) { 959 Slog.w(TAG, "Failed parsing " + e); 960 } catch (IllegalStateException e) { 961 Slog.w(TAG, "Failed parsing " + e); 962 } catch (NullPointerException e) { 963 Slog.w(TAG, "Failed parsing " + e); 964 } catch (XmlPullParserException e) { 965 Slog.w(TAG, "Failed parsing " + e); 966 } finally { 967 if (!success) { 968 timestamps.clear(); 969 } 970 } 971 return timestamps; 972 } 973 } 974 writeTimestamps(HashMap<String, Long> timestamps)975 private static void writeTimestamps(HashMap<String, Long> timestamps) { 976 synchronized (sFile) { 977 final FileOutputStream stream; 978 try { 979 stream = sFile.startWrite(); 980 } catch (IOException e) { 981 Slog.w(TAG, "Failed to write timestamp file: " + e); 982 return; 983 } 984 985 try { 986 TypedXmlSerializer out = Xml.resolveSerializer(stream); 987 out.startDocument(null, true); 988 out.startTag(null, "log-files"); 989 990 Iterator<String> itor = timestamps.keySet().iterator(); 991 while (itor.hasNext()) { 992 String filename = itor.next(); 993 out.startTag(null, "log"); 994 out.attribute(null, "filename", filename); 995 out.attributeLong(null, "timestamp", timestamps.get(filename)); 996 out.endTag(null, "log"); 997 } 998 999 out.endTag(null, "log-files"); 1000 out.endDocument(); 1001 1002 sFile.finishWrite(stream); 1003 } catch (IOException e) { 1004 Slog.w(TAG, "Failed to write timestamp file, using the backup: " + e); 1005 sFile.failWrite(stream); 1006 } 1007 } 1008 } 1009 } 1010