Merge "StrictMode: gather and return violating stacks in Binder replies" into gingerbread

core/java/android/app/ApplicationErrorReport.java

@@ -27,6 +27,7 @@ import android.os.Parcelable;
 import android.os.SystemProperties;
 import android.provider.Settings;
 import android.util.Printer;
+
 import java.io.PrintWriter;
 import java.io.StringWriter;
 

core/java/android/database/DatabaseUtils.java

@@ -108,7 +108,7 @@ public class DatabaseUtils {
      * @see Parcel#readException
      */
     public static final void readExceptionFromParcel(Parcel reply) {
-        int code = reply.readInt();
+        int code = reply.readExceptionCode();
         if (code == 0) return;
         String msg = reply.readString();
         DatabaseUtils.readExceptionFromParcel(reply, msg, code);
@@ -116,7 +116,7 @@ public class DatabaseUtils {
 
     public static void readExceptionWithFileNotFoundExceptionFromParcel(
             Parcel reply) throws FileNotFoundException {
-        int code = reply.readInt();
+        int code = reply.readExceptionCode();
         if (code == 0) return;
         String msg = reply.readString();
         if (code == 1) {
@@ -128,7 +128,7 @@ public class DatabaseUtils {
 
     public static void readExceptionWithOperationApplicationExceptionFromParcel(
             Parcel reply) throws OperationApplicationException {
-        int code = reply.readInt();
+        int code = reply.readExceptionCode();
         if (code == 0) return;
         String msg = reply.readString();
         if (code == 10) {

core/java/android/os/Binder.java

@@ -299,6 +299,8 @@ public class Binder implements IBinder {
     
     private native final void init();
     private native final void destroy();
+
+    // Entry point from android_util_Binder.cpp's onTransact
     private boolean execTransact(int code, int dataObj, int replyObj,
             int flags) {
         Parcel data = Parcel.obtain(dataObj);

core/java/android/os/Parcel.java

@@ -176,6 +176,7 @@ import java.util.Set;
  */
 public final class Parcel {
     private static final boolean DEBUG_RECYCLE = false;
+    private static final String TAG = "Parcel";
 
     @SuppressWarnings({"UnusedDeclaration"})
     private int mObject; // used by native code
@@ -214,12 +215,14 @@ public final class Parcel {
     private static final int VAL_BOOLEANARRAY = 23;
     private static final int VAL_CHARSEQUENCEARRAY = 24;
 
+    // The initial int32 in a Binder call's reply Parcel header:
     private static final int EX_SECURITY = -1;
     private static final int EX_BAD_PARCELABLE = -2;
     private static final int EX_ILLEGAL_ARGUMENT = -3;
     private static final int EX_NULL_POINTER = -4;
     private static final int EX_ILLEGAL_STATE = -5;
-    
+    private static final int EX_HAS_REPLY_HEADER = -128;  // special; see below
+
     public final static Parcelable.Creator<String> STRING_CREATOR
              = new Parcelable.Creator<String>() {
         public String createFromParcel(Parcel source) {
@@ -1216,7 +1219,31 @@ public final class Parcel {
      * @see #readException
      */
     public final void writeNoException() {
-        writeInt(0);
+        // Despite the name of this function ("write no exception"),
+        // it should instead be thought of as "write the RPC response
+        // header", but because this function name is written out by
+        // the AIDL compiler, we're not going to rename it.
+        //
+        // The response header, in the non-exception case (see also
+        // writeException above, also called by the AIDL compiler), is
+        // either a 0 (the default case), or EX_HAS_REPLY_HEADER if
+        // StrictMode has gathered up violations that have occurred
+        // during a Binder call, in which case we write out the number
+        // of violations and their details, serialized, before the
+        // actual RPC respons data.  The receiving end of this is
+        // readException(), below.
+        if (StrictMode.hasGatheredViolations()) {
+            writeInt(EX_HAS_REPLY_HEADER);
+            final int sizePosition = dataPosition();
+            writeInt(0);  // total size of fat header, to be filled in later
+            StrictMode.writeGatheredViolationsToParcel(this);
+            final int payloadPosition = dataPosition();
+            setDataPosition(sizePosition);
+            writeInt(payloadPosition - sizePosition);  // header size
+            setDataPosition(payloadPosition);
+        } else {
+            writeInt(0);
+        }
     }
 
     /**
@@ -1229,10 +1256,44 @@ public final class Parcel {
      * @see #writeNoException
      */
     public final void readException() {
+        int code = readExceptionCode();
+        if (code != 0) {
+            String msg = readString();
+            readException(code, msg);
+        }
+    }
+
+    /**
+     * Parses the header of a Binder call's response Parcel and
+     * returns the exception code.  Deals with lite or fat headers.
+     * In the common successful case, this header is generally zero.
+     * In less common cases, it's a small negative number and will be
+     * followed by an error string.
+     *
+     * This exists purely for android.database.DatabaseUtils and
+     * insulating it from having to handle fat headers as returned by
+     * e.g. StrictMode-induced RPC responses.
+     *
+     * @hide
+     */
+    public final int readExceptionCode() {
         int code = readInt();
-        if (code == 0) return;
+        if (code == EX_HAS_REPLY_HEADER) {
-        String msg = readString();
+            int headerSize = readInt();
-        readException(code, msg);
+            if (headerSize == 0) {
+                Log.e(TAG, "Unexpected zero-sized Parcel reply header.");
+            } else {
+                // Currently the only thing in the header is StrictMode stacks,
+                // but discussions around event/RPC tracing suggest we might
+                // put that here too.  If so, switch on sub-header tags here.
+                // But for now, just parse out the StrictMode stuff.
+                StrictMode.readAndHandleBinderCallViolations(this);
+            }
+            // And fat response headers are currently only used when
+            // there are no exceptions, so return no error:
+            return 0;
+        }
+        return code;
     }
 
     /**
@@ -1872,13 +1933,13 @@ public final class Parcel {
                     creator = (Parcelable.Creator)f.get(null);
                 }
                 catch (IllegalAccessException e) {
-                    Log.e("Parcel", "Class not found when unmarshalling: "
+                    Log.e(TAG, "Class not found when unmarshalling: "
                                         + name + ", e: " + e);
                     throw new BadParcelableException(
                             "IllegalAccessException when unmarshalling: " + name);
                 }
                 catch (ClassNotFoundException e) {
-                    Log.e("Parcel", "Class not found when unmarshalling: "
+                    Log.e(TAG, "Class not found when unmarshalling: "
                                         + name + ", e: " + e);
                     throw new BadParcelableException(
                             "ClassNotFoundException when unmarshalling: " + name);
@@ -1983,7 +2044,7 @@ public final class Parcel {
         if (DEBUG_RECYCLE) {
             mStack = new RuntimeException();
         }
-        //Log.i("Parcel", "Initializing obj=0x" + Integer.toHexString(obj), mStack);
+        //Log.i(TAG, "Initializing obj=0x" + Integer.toHexString(obj), mStack);
         init(obj);
     }
 
@@ -1991,7 +2052,7 @@ public final class Parcel {
     protected void finalize() throws Throwable {
         if (DEBUG_RECYCLE) {
             if (mStack != null) {
-                Log.w("Parcel", "Client did not call Parcel.recycle()", mStack);
+                Log.w(TAG, "Client did not call Parcel.recycle()", mStack);
             }
         }
         destroy();
@@ -2015,7 +2076,7 @@ public final class Parcel {
         ClassLoader loader) {
         while (N > 0) {
             Object value = readValue(loader);
-            //Log.d("Parcel", "Unmarshalling value=" + value);
+            //Log.d(TAG, "Unmarshalling value=" + value);
             outVal.add(value);
             N--;
         }
@@ -2025,7 +2086,7 @@ public final class Parcel {
         ClassLoader loader) {
         for (int i = 0; i < N; i++) {
             Object value = readValue(loader);
-            //Log.d("Parcel", "Unmarshalling value=" + value);
+            //Log.d(TAG, "Unmarshalling value=" + value);
             outVal[i] = value;
         }
     }
@@ -2035,7 +2096,7 @@ public final class Parcel {
         while (N > 0) {
             int key = readInt();
             Object value = readValue(loader);
-            //Log.i("Parcel", "Unmarshalling key=" + key + " value=" + value);
+            //Log.i(TAG, "Unmarshalling key=" + key + " value=" + value);
             outVal.append(key, value);
             N--;
         }
@@ -2046,7 +2107,7 @@ public final class Parcel {
         while (N > 0) {
             int key = readInt();
             boolean value = this.readByte() == 1;
-            //Log.i("Parcel", "Unmarshalling key=" + key + " value=" + value);
+            //Log.i(TAG, "Unmarshalling key=" + key + " value=" + value);
             outVal.append(key, value);
             N--;
         }

core/java/android/os/StrictMode.java

@@ -23,6 +23,9 @@ import com.android.internal.os.RuntimeInit;
 
 import dalvik.system.BlockGuard;
 
+import java.io.PrintWriter;
+import java.io.StringWriter;
+import java.util.ArrayList;
 import java.util.HashMap;
 
 /**
@@ -31,6 +34,7 @@ import java.util.HashMap;
  */
 public final class StrictMode {
     private static final String TAG = "StrictMode";
+    private static final boolean LOG_V = false;
 
     // Only log a duplicate stack trace to the logs every second.
     private static final long MIN_LOG_INTERVAL_MS = 1000;
@@ -85,6 +89,19 @@ public final class StrictMode {
             PENALTY_LOG | PENALTY_DIALOG |
             PENALTY_DROPBOX | PENALTY_DEATH;
 
+    /**
+     * Log of strict mode violation stack traces that have occurred
+     * during a Binder call, to be serialized back later to the caller
+     * via Parcel.writeNoException() (amusingly) where the caller can
+     * choose how to react.
+     */
+    private static ThreadLocal<ArrayList<ApplicationErrorReport.CrashInfo>> gatheredViolations =
+            new ThreadLocal<ArrayList<ApplicationErrorReport.CrashInfo>>() {
+        @Override protected ArrayList<ApplicationErrorReport.CrashInfo> initialValue() {
+            return new ArrayList<ApplicationErrorReport.CrashInfo>(1);
+        }
+    };
+
     /**
      * Sets the policy for what actions the current thread is denied,
      * as well as the penalty for violating the policy.
@@ -118,6 +135,24 @@ public final class StrictMode {
         }
     }
 
+    private static class StrictModeNetworkViolation extends BlockGuard.BlockGuardPolicyException {
+        public StrictModeNetworkViolation(int policyMask) {
+            super(policyMask, DISALLOW_NETWORK);
+        }
+    }
+
+    private static class StrictModeDiskReadViolation extends BlockGuard.BlockGuardPolicyException {
+        public StrictModeDiskReadViolation(int policyMask) {
+            super(policyMask, DISALLOW_DISK_READ);
+        }
+    }
+
+    private static class StrictModeDiskWriteViolation extends BlockGuard.BlockGuardPolicyException {
+        public StrictModeDiskWriteViolation(int policyMask) {
+            super(policyMask, DISALLOW_DISK_WRITE);
+        }
+    }
+
     /**
      * Returns the bitmask of the current thread's blocking policy.
      *
@@ -127,6 +162,52 @@ public final class StrictMode {
         return BlockGuard.getThreadPolicy().getPolicyMask();
     }
 
+    /**
+     * Parses the BlockGuard policy mask out from the Exception's
+     * getMessage() String value.  Kinda gross, but least
+     * invasive.  :/
+     *
+     * Input is of form "policy=137 violation=64"
+     *
+     * Returns 0 on failure, which is a valid policy, but not a
+     * valid policy during a violation (else there must've been
+     * some policy in effect to violate).
+     */
+    private static int parsePolicyFromMessage(String message) {
+        if (message == null || !message.startsWith("policy=")) {
+            return 0;
+        }
+        int spaceIndex = message.indexOf(' ');
+        if (spaceIndex == -1) {
+            return 0;
+        }
+        String policyString = message.substring(7, spaceIndex);
+        try {
+            return Integer.valueOf(policyString).intValue();
+        } catch (NumberFormatException e) {
+            return 0;
+        }
+    }
+
+    /**
+     * Like parsePolicyFromMessage(), but returns the violation.
+     */
+    private static int parseViolationFromMessage(String message) {
+        if (message == null) {
+            return 0;
+        }
+        int violationIndex = message.indexOf("violation=");
+        if (violationIndex == -1) {
+            return 0;
+        }
+        String violationString = message.substring(violationIndex + 10);
+        try {
+            return Integer.valueOf(violationString).intValue();
+        } catch (NumberFormatException e) {
+            return 0;
+        }
+    }
+
     private static class AndroidBlockGuardPolicy implements BlockGuard.Policy {
         private int mPolicyMask;
 
@@ -139,6 +220,11 @@ public final class StrictMode {
             mPolicyMask = policyMask;
         }
 
+        @Override
+        public String toString() {
+            return "AndroidBlockGuardPolicy; mPolicyMask=" + mPolicyMask;
+        }
+
         // Part of BlockGuard.Policy interface:
         public int getPolicyMask() {
             return mPolicyMask;
@@ -149,7 +235,7 @@ public final class StrictMode {
             if ((mPolicyMask & DISALLOW_DISK_WRITE) == 0) {
                 return;
             }
-            handleViolation(DISALLOW_DISK_WRITE);
+            startHandlingViolationException(new StrictModeDiskWriteViolation(mPolicyMask));
         }
 
         // Part of BlockGuard.Policy interface:
@@ -157,7 +243,7 @@ public final class StrictMode {
             if ((mPolicyMask & DISALLOW_DISK_READ) == 0) {
                 return;
             }
-            handleViolation(DISALLOW_DISK_READ);
+            startHandlingViolationException(new StrictModeDiskReadViolation(mPolicyMask));
         }
 
         // Part of BlockGuard.Policy interface:
@@ -165,17 +251,23 @@ public final class StrictMode {
             if ((mPolicyMask & DISALLOW_NETWORK) == 0) {
                 return;
             }
-            handleViolation(DISALLOW_NETWORK);
+            startHandlingViolationException(new StrictModeNetworkViolation(mPolicyMask));
         }
 
         public void setPolicyMask(int policyMask) {
             mPolicyMask = policyMask;
         }
 
-        private void handleViolation(int violationBit) {
+        // Start handling a violation that just started and hasn't
-            final BlockGuard.BlockGuardPolicyException violation =
+        // actually run yet (e.g. no disk write or network operation
-                    new BlockGuard.BlockGuardPolicyException(mPolicyMask, violationBit);
+        // has yet occurred).  This sees if we're in an event loop
-            violation.fillInStackTrace();
+        // thread and, if so, uses it to roughly measure how long the
+        // violation took.
+        void startHandlingViolationException(BlockGuard.BlockGuardPolicyException e) {
+            e.fillInStackTrace();
+            final ApplicationErrorReport.CrashInfo crashInfo = new ApplicationErrorReport.CrashInfo(e);
+            crashInfo.durationMillis = -1;  // unknown
+            final int savedPolicy = mPolicyMask;
 
             Looper looper = Looper.myLooper();
             if (looper == null) {
@@ -183,38 +275,50 @@ public final class StrictMode {
                 // violation takes place.  This case should be rare,
                 // as most users will care about timing violations
                 // that happen on their main UI thread.
-                handleViolationWithTime(violation, -1L /* no time */);
+                handleViolation(crashInfo, savedPolicy);
             } else {
                 MessageQueue queue = Looper.myQueue();
                 final long violationTime = SystemClock.uptimeMillis();
                 queue.addIdleHandler(new MessageQueue.IdleHandler() {
                         public boolean queueIdle() {
                             long afterViolationTime = SystemClock.uptimeMillis();
-                            handleViolationWithTime(violation, afterViolationTime - violationTime);
+                            crashInfo.durationMillis = afterViolationTime - violationTime;
+                            handleViolation(crashInfo, savedPolicy);
                             return false;  // remove this idle handler from the array
                         }
                     });
             }
+
         }
 
-        private void handleViolationWithTime(
+        // Note: It's possible (even quite likely) that the
-            BlockGuard.BlockGuardPolicyException violation,
+        // thread-local policy mask has changed from the time the
-            long durationMillis) {
+        // violation fired and now (after the violating code ran) due
+        // to people who push/pop temporary policy in regions of code,
+        // hence the policy being passed around.
+        void handleViolation(
+            final ApplicationErrorReport.CrashInfo crashInfo,
+            int policy) {
+            if (crashInfo.stackTrace == null) {
+                Log.d(TAG, "unexpected null stacktrace");
+                return;
+            }
 
-            // It's possible (even quite likely) that mPolicyMask has
+            if (LOG_V) Log.d(TAG, "handleViolation; policy=" + policy);
-            // changed from the time the violation fired and now
-            // (after the violating code ran) due to people who
-            // push/pop temporary policy in regions of code.  So use
-            // the old policy here.
-            int policy = violation.getPolicy();
-
-            // Not _really_ a Crash, but we use the same data structure...
-            ApplicationErrorReport.CrashInfo crashInfo =
-                    new ApplicationErrorReport.CrashInfo(violation);
-            crashInfo.durationMillis = durationMillis;
 
             if ((policy & PENALTY_GATHER) != 0) {
-                Log.d(TAG, "StrictMode violation via Binder call; ignoring for now.");
+                ArrayList<ApplicationErrorReport.CrashInfo> violations = gatheredViolations.get();
+                if (violations.size() >= 5) {
+                    // Too many.  In a loop or something?  Don't gather them all.
+                    return;
+                }
+                for (ApplicationErrorReport.CrashInfo previous : violations) {
+                    if (crashInfo.stackTrace.equals(previous.stackTrace)) {
+                        // Duplicate. Don't log.
+                        return;
+                    }
+                }
+                violations.add(crashInfo);
                 return;
             }
 
@@ -231,11 +335,11 @@ public final class StrictMode {
 
             if ((policy & PENALTY_LOG) != 0 &&
                 timeSinceLastViolationMillis > MIN_LOG_INTERVAL_MS) {
-                if (durationMillis != -1) {
+                if (crashInfo.durationMillis != -1) {
-                    Log.d(TAG, "StrictMode policy violation; ~duration=" + durationMillis + " ms",
+                    Log.d(TAG, "StrictMode policy violation; ~duration=" +
-                          violation);
+                          crashInfo.durationMillis + " ms: " + crashInfo.stackTrace);
                 } else {
-                    Log.d(TAG, "StrictMode policy violation.", violation);
+                    Log.d(TAG, "StrictMode policy violation: " + crashInfo.stackTrace);
                 }
             }
 
@@ -255,7 +359,8 @@ public final class StrictMode {
             }
 
             if (violationMask != 0) {
-                violationMask |= violation.getPolicyViolation();
+                int violationBit = parseViolationFromMessage(crashInfo.exceptionMessage);
+                violationMask |= violationBit;
                 final int savedPolicy = getThreadBlockingPolicy();
                 try {
                     // First, remove any policy before we call into the Activity Manager,
@@ -267,7 +372,7 @@ public final class StrictMode {
                     ActivityManagerNative.getDefault().handleApplicationStrictModeViolation(
                         RuntimeInit.getApplicationObject(),
                         violationMask,
-                        new ApplicationErrorReport.CrashInfo(violation));
+                        crashInfo);
                 } catch (RemoteException e) {
                     Log.e(TAG, "RemoteException trying to handle StrictMode violation", e);
                 } finally {
@@ -284,6 +389,68 @@ public final class StrictMode {
         }
     }
 
+    /**
+     * Called from Parcel.writeNoException()
+     */
+    /* package */ static boolean hasGatheredViolations() {
+        return !gatheredViolations.get().isEmpty();
+    }
+
+    /**
+     * Called from Parcel.writeNoException()
+     */
+    /* package */ static void writeGatheredViolationsToParcel(Parcel p) {
+        ArrayList<ApplicationErrorReport.CrashInfo> violations = gatheredViolations.get();
+        p.writeInt(violations.size());
+        for (int i = 0; i < violations.size(); ++i) {
+            violations.get(i).writeToParcel(p, 0 /* unused flags? */);
+        }
+
+        if (LOG_V) Log.d(TAG, "wrote violations to response parcel; num=" + violations.size());
+        violations.clear();
+    }
+
+    private static class LogStackTrace extends Exception {}
+
+    /**
+     * Called from Parcel.readException() when the exception is EX_STRICT_MODE_VIOLATIONS,
+     * we here read back all the encoded violations.
+     */
+    /* package */ static void readAndHandleBinderCallViolations(Parcel p) {
+        // Our own stack trace to append
+        Exception e = new LogStackTrace();
+        StringWriter sw = new StringWriter();
+        e.printStackTrace(new PrintWriter(sw));
+        String ourStack = sw.toString();
+
+        int policyMask = getThreadBlockingPolicy();
+
+        int numViolations = p.readInt();
+        for (int i = 0; i < numViolations; ++i) {
+            if (LOG_V) Log.d(TAG, "strict mode violation stacks read from binder call.  i=" + i);
+            ApplicationErrorReport.CrashInfo crashInfo = new ApplicationErrorReport.CrashInfo(p);
+            crashInfo.stackTrace += "# via Binder call with stack:\n" + ourStack;
+
+            // Unlike the in-process violations in which case we
+            // trigger an error _before_ the thing occurs, in this
+            // case the violating thing has already occurred, so we
+            // can't use our heuristic of waiting for the next event
+            // loop idle cycle to measure the approximate violation
+            // duration.  Instead, just skip that step and use -1
+            // (unknown duration) for now.
+            // TODO: keep a thread-local on remote process of first
+            // violation time's uptimeMillis, and when writing that
+            // back out in Parcel reply, include in the header the
+            // violation time and use it here.
+            crashInfo.durationMillis = -1;
+
+            BlockGuard.Policy policy = BlockGuard.getThreadPolicy();
+            if (policy instanceof AndroidBlockGuardPolicy) {
+                ((AndroidBlockGuardPolicy) policy).handleViolation(crashInfo, policyMask);
+            }
+        }
+    }
+
     /**
      * Called from android_util_Binder.cpp's
      * android_os_Parcel_enforceInterface when an incoming Binder call

libs/binder/Parcel.cpp

@@ -51,6 +51,9 @@
 // Note: must be kept in sync with android/os/StrictMode.java's PENALTY_GATHER
 #define STRICT_MODE_PENALTY_GATHER 0x100
 
+// Note: must be kept in sync with android/os/Parcel.java's EX_HAS_REPLY_HEADER
+#define EX_HAS_REPLY_HEADER -128
+
 // XXX This can be made public if we want to provide
 // support for typed data.
 struct small_flat_data
@@ -959,7 +962,15 @@ wp<IBinder> Parcel::readWeakBinder() const
 int32_t Parcel::readExceptionCode() const
 {
   int32_t exception_code = readAligned<int32_t>();
-  // TODO: skip over the response header here, once that's in.
+  if (exception_code == EX_HAS_REPLY_HEADER) {
+    int32_t header_size = readAligned<int32_t>();
+    // Skip over fat responses headers.  Not used (or propagated) in
+    // native code
+    setDataPosition(dataPosition() + header_size);
+    // And fat response headers are currently only used when there are no
+    // exceptions, so return no error:
+    return 0;
+  }
   return exception_code;
 }