[Android Crash Reporting] Simplify crash report upload code.

chrome/android/java/src/org/chromium/chrome/browser/DeferredStartupHandler.java

Index: chrome/android/java/src/org/chromium/chrome/browser/DeferredStartupHandler.java
diff --git a/chrome/android/java/src/org/chromium/chrome/browser/DeferredStartupHandler.java b/chrome/android/java/src/org/chromium/chrome/browser/DeferredStartupHandler.java
index 71d5da9513554c25f32587b26374b7d622060694..df22ec83e3b7e80700d738367014b4589f73b119 100644
--- a/chrome/android/java/src/org/chromium/chrome/browser/DeferredStartupHandler.java
+++ b/chrome/android/java/src/org/chromium/chrome/browser/DeferredStartupHandler.java
@@ -19,6 +19,7 @@ import android.view.inputmethod.InputMethodSubtype;
 import org.chromium.base.CommandLine;
 import org.chromium.base.ContextUtils;
 import org.chromium.base.FieldTrialList;
+import org.chromium.base.Log;
 import org.chromium.base.PowerMonitor;
 import org.chromium.base.SysUtils;
 import org.chromium.base.ThreadUtils;
@@ -26,6 +27,7 @@ import org.chromium.base.TraceEvent;
 import org.chromium.base.VisibleForTesting;
 import org.chromium.base.metrics.RecordHistogram;
 import org.chromium.chrome.browser.bookmarkswidget.BookmarkWidgetProvider;
+import org.chromium.chrome.browser.crash.LogcatExtractionRunnable;
 import org.chromium.chrome.browser.crash.MinidumpUploadService;
 import org.chromium.chrome.browser.init.ProcessInitializationHandler;
 import org.chromium.chrome.browser.locale.LocaleManager;
@@ -48,7 +50,10 @@ import org.chromium.chrome.browser.webapps.WebappRegistry;
 import org.chromium.components.minidump_uploader.CrashFileManager;
 import org.chromium.content.browser.ChildProcessLauncher;
 
+import java.io.File;
 import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.Date;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.Locale;
@@ -59,7 +64,7 @@ import java.util.concurrent.TimeUnit;
  * Handler for application level tasks to be completed on deferred startup.
  */
 public class DeferredStartupHandler {
-    private static final String TAG = "DeferredStartupHandler";
+    private static final String TAG = "DeferredStartup";
     /** Prevents race conditions when deleting snapshot database. */
     private static final Object SNAPSHOT_DATABASE_LOCK = new Object();
     private static final String SNAPSHOT_DATABASE_REMOVED = "snapshot_database_removed";
@@ -243,24 +248,13 @@ public class DeferredStartupHandler {
             protected Void doInBackground(Void... params) {
                 try {
                     TraceEvent.begin("ChromeBrowserInitializer.onDeferredStartup.doInBackground");
-                    mAsyncTaskStartTime = SystemClock.uptimeMillis();
 
-                    boolean crashDumpDisabled = CommandLine.getInstance().hasSwitch(
-                            ChromeSwitches.DISABLE_CRASH_DUMP_UPLOAD);
-                    if (!crashDumpDisabled) {
-                        RecordHistogram.recordLongTimesHistogram(
-                                "UMA.Debug.EnableCrashUpload.Uptime3",
-                                mAsyncTaskStartTime - UmaUtils.getForegroundStartTime(),
-                                TimeUnit.MILLISECONDS);
-                        PrivacyPreferencesManager.getInstance().enablePotentialCrashUploading();
-                        MinidumpUploadService.tryUploadAllCrashDumps(mAppContext);
-                    }
-                    CrashFileManager crashFileManager =
-                            new CrashFileManager(mAppContext.getCacheDir());
-                    crashFileManager.cleanOutAllNonFreshMinidumpFiles();
+                    mAsyncTaskStartTime = SystemClock.uptimeMillis();
+                    RecordHistogram.recordLongTimesHistogram("UMA.Debug.EnableCrashUpload.Uptime3",
+                            mAsyncTaskStartTime - UmaUtils.getForegroundStartTime(),
+                            TimeUnit.MILLISECONDS);

[Maria, 2017/03/07 06:36:39]

looks like you are changing the semantics of when this histogram is reported to
include users who opted out of crash uploading. I don't think we should do that.

[Ilya Sherman, 2017/03/08 02:32:44]

Done.  Good catch!  I misread when this histogram was recorded and what it
means.

 
-                    MinidumpUploadService.storeBreakpadUploadStatsInUma(
-                            ChromePreferenceManager.getInstance());
+                    initCrashReporting();
 
                     // Initialize the WebappRegistry if it's not already initialized. Must be in
                     // async task due to shared preferences disk access on N.
@@ -303,6 +297,75 @@ public class DeferredStartupHandler {
         }.executeOnExecutor(AsyncTask.THREAD_POOL_EXECUTOR);
     }
 
+    /**
+     * Initializes the crash reporting system. More specifically, enables the crash reporting system
+     * if it is user-permitted, and initiates uploading of any pending crash reports. Also updates
+     * some UMA metrics and performs cleanup in the local crash minidump storage directory.
+     */
+    private void initCrashReporting() {
+        // Perform cleanup prior to checking whether crash reporting is enabled, so that users who
+        // disable crash reporting are still able to eventually recover disk space dedicated to
+        // storing pending crash reports.
+        CrashFileManager crashFileManager = new CrashFileManager(mAppContext.getCacheDir());
+        crashFileManager.cleanOutAllNonFreshMinidumpFiles();
+
+        // Likewise, there might be pending metrics from previous runs when crash reporting was
+        // enabled.
+        MinidumpUploadService.storeBreakpadUploadStatsInUma(ChromePreferenceManager.getInstance());
+
+        // Now check whether crash reporting is enable. If it is, broadcast the appropriate

[Maria, 2017/03/07 06:36:39]

nit: enable -> enabled

[Ilya Sherman, 2017/03/08 02:32:44]

Done.

+        // permisison.

[gsennton, 2017/03/07 18:32:04]

nit: permisison -> permission

[Ilya Sherman, 2017/03/08 02:32:44]

Done.

+        boolean crashReportingDisabled =
+                CommandLine.getInstance().hasSwitch(ChromeSwitches.DISABLE_CRASH_DUMP_UPLOAD);
+        if (crashReportingDisabled) {

[Maria, 2017/03/07 06:36:39]

nit: feel free to use 

if (crashReportingDisabled) return; 

one-liner. This is common style in clank code.

[Ilya Sherman, 2017/03/08 02:32:44]

Done.  Yay!  This was bugging me, but I wasn't sure whether it was acceptable to
collapse the code to a single line =)

+            return;
+        }
+        PrivacyPreferencesManager.getInstance().enablePotentialCrashUploading();
+
+        // Finally, uploading any pending crash reports.
+        File[] minidumps =
+                crashFileManager.getAllMinidumpFiles(MinidumpUploadService.MAX_TRIES_ALLOWED);
+        if (minidumps.length == 0) {

[Maria, 2017/03/07 06:36:39]

ditto

[Ilya Sherman, 2017/03/08 02:32:44]

Done.

+            return;
+        }
+
+        Log.i(TAG, "Attempting to upload accumulated crash dumps.");

[Maria, 2017/03/07 06:36:39]

Might as well log how many there are

[Ilya Sherman, 2017/03/08 02:32:44]

Done.

+        if (!doesCrashMinidumpNeedLogcat(minidumps[0])) {

[Maria, 2017/03/07 06:36:39]

Do we have some sort of guarantee on what the first minidump returned is? Do we
now just attach logcat to one random minidump? I think it would make sense to
attach to the freshest dump.

[gsennton, 2017/03/07 18:32:04]

Please double-check whether the first minidump here is the newest or the oldest
one (I remember that I was surprised about the order at some point but can't
remember which way it is from the top of my head).

Also, why only attach the logcat to the most recent (I assume) one?

[Ilya Sherman, 2017/03/08 02:32:44]

I've double-checked that this is indeed the freshest minidump.

I chose to attach the logcat to just the most recent crash for a couple of
reasons: (1) We always grab the most recent logcat output, so it seems most
likely to be relevant to the most recent crash; and (2) honestly, I'd expect it
to almost never happen that we have multiple pending crash reports that need
logcat output attached.  Given that, I didn't want to support the extra
complexity needed to attach logcat output to all the pending minidumps.

That said, if y'all think it's worth a bit of extra complexity, we certainly
could cover all of the minidumps.

[gsennton, 2017/03/08 15:18:41]

I would say there are two different scenarios we care about here:
1. Chrome crashing over and over again (the user hits a reproducible crash) - in
this case the logcat would probably be relevant for all of the queued minidump
uploads, unless they are uploaded directly after the crash occurs (and I believe
it would be nice with a logcat attached to each report here - I guess the
investigator could look up the client ID to try to find reports close in time
but I doubt investigators will do this in general).
2. Chrome hits several independent/unrelated crashes within the logcat-keeping
time (15 minutes, or 12 hours or w/e), and won't upload each report directly
(e.g. because we don't have WiFi). I have no idea how often this happens, but
with a logcat-keeping time of ~12 hours this seems like it could happen every
now and then (especially on Canary/Dev/Beta).

Again, I don't really know how likely these events are.. it would be nice with a
dremel query telling us how often the same device crashes twice within a short
time-period ;)

[Ilya Sherman, 2017/03/09 01:08:45]

It would have to be a crash that brings down the browser process before we have
a chance to attach the logcat output -- so most likely, a crash on startup. 
It's certainly possible!  But I'd worry that attaching the logcat output to the
first crash in a series might be confusing, since it might have future output. 
(It would make more sense if we do something smarter, along the lines of
attaching logcat output up to the timestamp of the crash.  That's harder to
implement correctly, though =))
Again, these would pretty much need to be crashes on startup.  Once the logcat
output is attached, we don't need to worry about that particular minidump
anymore -- it's never detached =)

+            MinidumpUploadService.tryUploadAllCrashDumps(mAppContext);
+        } else {

[gsennton, 2017/03/07 18:32:04]

Would you mind switching the if- and else-statements here? IMO it is more clear
when the if-statement doesn't include a negation.

[Ilya Sherman, 2017/03/08 02:32:44]

I can do that, but let me run this by you first: WDYT of the code with some
named variables extracted?  I generally prefer to have the shorter/simpler
branch come first, for scannability.  But if you think it's still less clear
this way, I'm happy to swap the order.

[gsennton, 2017/03/08 15:18:41]

What do you mean by "some named variables extracted" in this case? (could you
provide an example)
I don't have a super-strong opinion here (and especially don't want to block the
whole CL on this), go with what you feel is right.
Note: one option could be to do something like

if (doesCrashMinidumpNeedLogcat(minidumps[0])) {
    AsyncTask.THREAD_POOL_EXECUTOR.execute(
            new LogcatExtractionRunnable(mAppContext, minidumps[0]));
} else {
    MinidumpUploadService.tryUploadCrashDump(mAppContext, minidumps[0]);
}
List<File> remainingMinidumps = Arrays.asList(minidumps).subList(1,
minidumps.length);
for (File minidump : remainingMinidumps) {
    MinidumpUploadService.tryUploadCrashDump(mAppContext, minidump);
}

[Ilya Sherman, 2017/03/09 01:08:45]

I meant what I included in the latest patch set ;-)
Yeah, I think that's a better way to write it, at least for the current CL.  I
was kind of thinking about this with the next CL in mind, but can wait to cross
that bridge until I actually come to it =)  Thanks for the suggestion!  Done.

+            AsyncTask.THREAD_POOL_EXECUTOR.execute(
+                    new LogcatExtractionRunnable(mAppContext, minidumps[0]));
+
+            // TODO(isherman): Once there is support implemented for the JobScheduler API, we should
+            // only explicitly upload the remaining files here if not using that API. If we *are*
+            // using the JobScheduler API, then the JobScheduler will schedule uploads for all of
+            // the available minidumps once the logcat is attached.
+            List<File> remainingMinidumps = Arrays.asList(minidumps).subList(1, minidumps.length);
+            for (File minidump : remainingMinidumps) {
+                MinidumpUploadService.tryUploadCrashDump(mAppContext, minidump);
+            }
+        }
+    }
+
+    /**
+     * Returns whether or not it's appropriate to try to extract recent logcat output and include
+     * that logcat output alongside the given {@param minidump} in a crash report. Logcat output
+     * should only be extracted if (a) it hasn't already been extracted for this minidump file, and
+     * (b) the minidump is fairly fresh. The freshness check is important for two reasons: (1) First
+     * of all, it helps avoid including irrelevant logcat output for a crash report. (2) Secondly,
+     * it provides a cool-off period that can help circumvent a possible infinite crash loop, if the

[gsennton, 2017/03/07 18:32:04]

The cool-off period, is that the infinite period after the first duration
(currently an hour) where we can attach a logcat?

[Ilya Sherman, 2017/03/08 02:32:44]

Right.  I updated the comment to hopefully clarify a bit -- please let me know
if it's still not quite clear.

+     * code responsible for extracting and appending the logcat content is itself crashing.
+     * @return Whether to try to include logcat output in the crash report corresponding to the
+     *         given minidump.
+     */
+    private boolean doesCrashMinidumpNeedLogcat(File minidump) {
+        if (!CrashFileManager.isMinidumpMIMEFirstTry(minidump.getName())) return false;
+
+        long ageInMillis = new Date().getTime() - minidump.lastModified();
+        long ageInHours = TimeUnit.HOURS.convert(ageInMillis, TimeUnit.MILLISECONDS);
+        return ageInHours < 1;

[Maria, 2017/03/07 06:36:39]

How did you choose the duration? I would absolutely support this being much
shorter, e.g. 15 minutes. 

[gsennton, 2017/03/07 18:32:04]

What's the reasoning behind such a short duration? Looking at a logcat dump from
my personal phone (running O - so probably a lot spammier than a regular user),
I can see system output back to 4 and a half hours before the current time.
I would not be surprised if a normal user could see logcat output 24+ hours
after it is logged.

[Maria, 2017/03/07 20:04:57]

The problem is that we only grab 256 lines from the log. On my personal user
build N device that covers less than one minute of logs (and all I did was turn
the screen on). 

I was just thinking if we are crashing and this is the way the user gets back
into their Chrome, shorter is better. I guess I don't have a good feel for the
duration between the browser crashes and Chrome is reopened again as well as how
often we get good logs in that scenario.

[Ilya Sherman, 2017/03/08 02:32:44]

I picked semi-randomly :P  I'm happy to start with a 15-minute period, and
adjust that if we find that logcat output is too often missing.  Conversely, I'm
also content with increasing the period to something longer, if we believe
there's useful data that will be extracted.  I think the likelihood of the code
entering an infinite crash loop is relatively low, so I'm okay with making the
tradeoff in favor of better logcat data.

[Maria, 2017/03/08 06:18:47]

Hmm, one thing I thought of: logcat data returned for an application would only
contain log entries generated by the same application. So in theory even though
we only get last 256 lines, we may be able to get the last crash even much later
because those would be the last Chrome-generated log lines.

I think this convinces me to go back on my suggestion to make this smaller --
let's do what Gustav suggested and make it longer.

[Ilya Sherman, 2017/03/08 09:12:30]

Okay, sounds good.  Any specific suggestions on how long to make it?  ~12 hours?

[gsennton, 2017/03/08 15:18:41]

Ideally we would just read the time-stamp of the first line of logcat we read
and check whether that is before (or slightly after) the time of the minidump
generation? But I guess doing so will be brittle?

Otherwise it would be great to count the time chrome has been active rather than
the real-life time that has passed (using something like
UsageStatsManager.queryUsageStats() - if that makes sense - though that API was
introduced in API level 21).

[if none of the above sound promising - or if you feel like implementing one of
those for 59 instead] 12 hours sounds fairly reasonable to me :P
(maybe run a logcat dump on your own personal device to check how far back in
time you reach with 256 lines of Chrome-logs?)

[Ilya Sherman, 2017/03/09 01:08:45]

I'm not sure whether it's brittle, but it's harder to implement correctly, given
how we buffer the logcat output.  I think it's probably the right direction, but
I'd prefer not to try to land something like this for M58 =)
That would likely make the escape-hatch not very viable.  Plus, the relevant
question is mostly "Is there still Chrome data in the logcat, or has it all aged
out?"  The logcat is a shared resource, and data could age out based on other
app use.

+    }
+
     private void startModerateBindingManagementIfNeeded() {
         // Moderate binding doesn't apply to low end devices.
         if (SysUtils.isLowEndDevice()) return;