fix service binding

there were cases where we wouldn't bind when we should. also, add
some additional debug to better track potential connection issues.

Change-Id: I381da24f490e3102817a14428ef1a63982f33d19
Fixes: 37122153
Test: kill/upgrade GMS to ensure we re-bind in a timely manner

diff --git a/core/java/android/app/InstantAppResolverService.java b/core/java/android/app/InstantAppResolverService.java
index 88399e5..c5dc86c 100644 (file)
--- a/core/java/android/app/InstantAppResolverService.java
+++ b/core/java/android/app/InstantAppResolverService.java
@@ -91,6 +91,9 @@ public abstract class InstantAppResolverService extends Service {
             @Override
             public void getInstantAppResolveInfoList(
                     int digestPrefix[], String token, int sequence, IRemoteCallback callback) {
+                if (DEBUG_EPHEMERAL) {
+                    Slog.v(TAG, "[" + token + "] Phase1 called; posting");
+                }
                 final SomeArgs args = SomeArgs.obtain();
                 args.arg1 = callback;
                 args.arg2 = digestPrefix;
@@ -103,6 +106,9 @@ public abstract class InstantAppResolverService extends Service {
             @Override
             public void getInstantAppIntentFilterList(
                     int digestPrefix[], String token, String hostName, IRemoteCallback callback) {
+                if (DEBUG_EPHEMERAL) {
+                    Slog.v(TAG, "[" + token + "] Phase2 called; posting");
+                }
                 final SomeArgs args = SomeArgs.obtain();
                 args.arg1 = callback;
                 args.arg2 = digestPrefix;
@@ -140,7 +146,7 @@ public abstract class InstantAppResolverService extends Service {
     void _onGetInstantAppResolveInfo(int[] digestPrefix, String token,
             InstantAppResolutionCallback callback) {
         if (DEBUG_EPHEMERAL) {
-            Slog.d(TAG, "Instant resolver; getInstantAppResolveInfo;"
+            Slog.d(TAG, "[" + token + "] Phase1 request;"
                     + " prefix: " + Arrays.toString(digestPrefix));
         }
         onGetInstantAppResolveInfo(digestPrefix, token, callback);
@@ -149,7 +155,7 @@ public abstract class InstantAppResolverService extends Service {
     void _onGetInstantAppIntentFilter(int digestPrefix[], String token, String hostName,
             InstantAppResolutionCallback callback) {
         if (DEBUG_EPHEMERAL) {
-            Slog.d(TAG, "Instant resolver; getInstantAppIntentFilter;"
+            Slog.d(TAG, "[" + token + "] Phase2 request;"
                     + " prefix: " + Arrays.toString(digestPrefix));
         }
         onGetInstantAppIntentFilter(digestPrefix, token, callback);

diff --git a/services/core/java/com/android/server/pm/EphemeralResolverConnection.java b/services/core/java/com/android/server/pm/EphemeralResolverConnection.java
index 21d78ee..9d08004 100644 (file)
--- a/services/core/java/com/android/server/pm/EphemeralResolverConnection.java
+++ b/services/core/java/com/android/server/pm/EphemeralResolverConnection.java
@@ -35,6 +35,7 @@ import android.os.UserHandle;
 import android.util.Slog;
 import android.util.TimedRemoteCaller;
 
+import com.android.internal.annotations.GuardedBy;
 import com.android.internal.os.TransferPipe;
 
 import java.io.FileDescriptor;
@@ -53,7 +54,9 @@ final class EphemeralResolverConnection implements DeathRecipient {
     private static final String TAG = "PackageManager";
     // This is running in a critical section and the timeout must be sufficiently low
     private static final long BIND_SERVICE_TIMEOUT_MS =
-            ("eng".equals(Build.TYPE)) ? 300 : 200;
+            ("eng".equals(Build.TYPE)) ? 500 : 300;
+    private static final long CALL_SERVICE_TIMEOUT_MS =
+            ("eng".equals(Build.TYPE)) ? 200 : 100;
     private static final boolean DEBUG_EPHEMERAL = Build.IS_DEBUGGABLE;
 
     private final Object mLock = new Object();
@@ -64,7 +67,9 @@ final class EphemeralResolverConnection implements DeathRecipient {
     /** Intent used to bind to the service */
     private final Intent mIntent;
 
-    private volatile boolean mBindRequested;
+    @GuardedBy("mLock")
+    private volatile boolean mIsBinding;
+    @GuardedBy("mLock")
     private IInstantAppResolver mRemoteInstance;
 
     public EphemeralResolverConnection(
@@ -76,11 +81,18 @@ final class EphemeralResolverConnection implements DeathRecipient {
     public final List<InstantAppResolveInfo> getInstantAppResolveInfoList(int hashPrefix[],
             String token) {
         throwIfCalledOnMainThread();
+        IInstantAppResolver target = null;
         try {
-            return mGetEphemeralResolveInfoCaller.getEphemeralResolveInfoList(
-                    getRemoteInstanceLazy(), hashPrefix, token);
-        } catch (RemoteException re) {
-        } catch (TimeoutException te) {
+            target = getRemoteInstanceLazy(token);
+            return mGetEphemeralResolveInfoCaller
+                    .getEphemeralResolveInfoList(target, hashPrefix, token);
+        } catch (RemoteException e) {
+        } catch (InterruptedException | TimeoutException e) {
+            if (target == null) {
+                Slog.w(TAG, "[" + token + "] Timeout! Phase1 binding to instant app resolver");
+            } else {
+                Slog.w(TAG, "[" + token + "] Timeout! Phase1 resolving instant app");
+            }
         } finally {
             synchronized (mLock) {
                 mLock.notifyAll();
@@ -107,70 +119,73 @@ final class EphemeralResolverConnection implements DeathRecipient {
             }
         };
         try {
-            getRemoteInstanceLazy()
+            getRemoteInstanceLazy(token)
                     .getInstantAppIntentFilterList(hashPrefix, token, hostName, remoteCallback);
-        } catch (RemoteException re) {
-        } catch (TimeoutException te) {
+        } catch (RemoteException e) {
+        } catch (InterruptedException | TimeoutException e) {
+            Slog.w(TAG, "[" + token + "] Timeout! Phase2 binding to instant app resolver");
         }
     }
 
-    public void dump(FileDescriptor fd, PrintWriter pw, String prefix) {
-        synchronized (mLock) {
-            pw.append(prefix).append("bound=")
-                    .append((mRemoteInstance != null) ? "true" : "false").println();
-
-            pw.flush();
-            try {
-                TransferPipe.dumpAsync(getRemoteInstanceLazy().asBinder(), fd,
-                        new String[] { prefix });
-            } catch (IOException | TimeoutException | RemoteException e) {
-                pw.println("Failed to dump remote instance: " + e);
-            }
-        }
-    }
-
-    private IInstantAppResolver getRemoteInstanceLazy() throws TimeoutException {
+    private IInstantAppResolver getRemoteInstanceLazy(String token)
+            throws TimeoutException, InterruptedException {
         synchronized (mLock) {
             if (mRemoteInstance != null) {
                 return mRemoteInstance;
             }
-            bindLocked();
+            bindLocked(token);
             return mRemoteInstance;
         }
     }
 
-    private void bindLocked() throws TimeoutException {
-        if (mRemoteInstance != null) {
-            return;
-        }
-
-        if (!mBindRequested) {
-            mBindRequested = true;
-            if (DEBUG_EPHEMERAL) {
-                Slog.d(TAG, "Binding to resolver service");
-            }
-            mContext.bindServiceAsUser(mIntent, mServiceConnection,
-                    Context.BIND_AUTO_CREATE | Context.BIND_FOREGROUND_SERVICE, UserHandle.SYSTEM);
-        }
-
+    private void waitForBind(String token) throws TimeoutException, InterruptedException {
         final long startMillis = SystemClock.uptimeMillis();
-        while (true) {
+        while (mIsBinding) {
             if (mRemoteInstance != null) {
                 break;
             }
             final long elapsedMillis = SystemClock.uptimeMillis() - startMillis;
             final long remainingMillis = BIND_SERVICE_TIMEOUT_MS - elapsedMillis;
             if (remainingMillis <= 0) {
-                throw new TimeoutException("Didn't bind to resolver in time.");
-            }
-            try {
-                mLock.wait(remainingMillis);
-            } catch (InterruptedException ie) {
-                /* ignore */
+                throw new TimeoutException("[" + token + "] Didn't bind to resolver in time!");
             }
+            mLock.wait(remainingMillis);
         }
+    }
 
-        mLock.notifyAll();
+    private void bindLocked(String token) throws TimeoutException, InterruptedException {
+        if (DEBUG_EPHEMERAL && mIsBinding && mRemoteInstance == null) {
+            Slog.i(TAG, "[" + token + "] Previous bind timed out; waiting for connection");
+        }
+        try {
+            waitForBind(token);
+        } catch (TimeoutException e) {
+            if (DEBUG_EPHEMERAL) {
+                Slog.i(TAG, "[" + token + "] Previous connection never established; rebinding");
+            }
+            mContext.unbindService(mServiceConnection);
+        }
+        if (mRemoteInstance != null) {
+            return;
+        }
+        mIsBinding = true;
+        if (DEBUG_EPHEMERAL) {
+            Slog.v(TAG, "[" + token + "] Binding to instant app resolver");
+        }
+        boolean wasBound = false;
+        try {
+            final int flags = Context.BIND_AUTO_CREATE | Context.BIND_FOREGROUND_SERVICE;
+            wasBound = mContext
+                    .bindServiceAsUser(mIntent, mServiceConnection, flags, UserHandle.SYSTEM);
+            if (wasBound) {
+                waitForBind(token);
+            } else {
+                Slog.w(TAG, "[" + token + "] Failed to bind to: " + mIntent);
+            }
+        } finally {
+            mIsBinding = wasBound && mRemoteInstance == null;
+            mLock.notifyAll();
+        }
     }
 
     private void throwIfCalledOnMainThread() {
@@ -182,13 +197,18 @@ final class EphemeralResolverConnection implements DeathRecipient {
     @Override
     public void binderDied() {
         if (DEBUG_EPHEMERAL) {
-            Slog.d(TAG, "Binder died");
+            Slog.d(TAG, "Binder to instant app resolver died");
         }
+        synchronized (mLock) {
+            handleBinderDiedLocked();
+        }
+    }
+
+    private void handleBinderDiedLocked() {
         if (mRemoteInstance != null) {
             mRemoteInstance.asBinder().unlinkToDeath(this, 0 /*flags*/);
         }
         mRemoteInstance = null;
-        mBindRequested = false;
     }
 
     /**
@@ -203,13 +223,15 @@ final class EphemeralResolverConnection implements DeathRecipient {
         @Override
         public void onServiceConnected(ComponentName name, IBinder service) {
             if (DEBUG_EPHEMERAL) {
-                Slog.d(TAG, "Service connected");
+                Slog.d(TAG, "Connected to instant app resolver");
             }
             synchronized (mLock) {
+                mRemoteInstance = IInstantAppResolver.Stub.asInterface(service);
+                mIsBinding = false;
                 try {
                     service.linkToDeath(EphemeralResolverConnection.this, 0 /*flags*/);
-                    mRemoteInstance = IInstantAppResolver.Stub.asInterface(service);
                 } catch (RemoteException e) {
+                    handleBinderDiedLocked();
                 }
                 mLock.notifyAll();
             }
@@ -218,10 +240,10 @@ final class EphemeralResolverConnection implements DeathRecipient {
         @Override
         public void onServiceDisconnected(ComponentName name) {
             if (DEBUG_EPHEMERAL) {
-                Slog.d(TAG, "Service disconnected");
+                Slog.d(TAG, "Disconnected from instant app resolver");
             }
             synchronized (mLock) {
-                mRemoteInstance = null;
+                handleBinderDiedLocked();
             }
         }
     }
@@ -231,7 +253,7 @@ final class EphemeralResolverConnection implements DeathRecipient {
         private final IRemoteCallback mCallback;
 
         public GetEphemeralResolveInfoCaller() {
-            super(BIND_SERVICE_TIMEOUT_MS);
+            super(CALL_SERVICE_TIMEOUT_MS);
             mCallback = new IRemoteCallback.Stub() {
                     @Override
                     public void sendResult(Bundle data) throws RemoteException {

diff --git a/services/core/java/com/android/server/pm/InstantAppResolver.java b/services/core/java/com/android/server/pm/InstantAppResolver.java
index 6f593b0..b56db04 100644 (file)
--- a/services/core/java/com/android/server/pm/InstantAppResolver.java
+++ b/services/core/java/com/android/server/pm/InstantAppResolver.java
@@ -74,11 +74,11 @@ public abstract class InstantAppResolver {
 
     public static AuxiliaryResolveInfo doInstantAppResolutionPhaseOne(Context context,
             EphemeralResolverConnection connection, InstantAppRequest requestObj) {
-        if (DEBUG_EPHEMERAL) {
-            Log.d(TAG, "Resolving phase 1");
-        }
         final long startTime = System.currentTimeMillis();
         final String token = UUID.randomUUID().toString();
+        if (DEBUG_EPHEMERAL) {
+            Log.d(TAG, "[" + token + "] Resolving phase 1");
+        }
         final Intent intent = requestObj.origIntent;
         final InstantAppDigest digest =
                 new InstantAppDigest(intent.getData().getHost(), 5 /*maxDigests*/);
@@ -89,7 +89,7 @@ public abstract class InstantAppResolver {
         if (instantAppResolveInfoList == null || instantAppResolveInfoList.size() == 0) {
             // No hash prefix match; there are no instant apps for this domain.
             if (DEBUG_EPHEMERAL) {
-                Log.d(TAG, "No results returned");
+                Log.d(TAG, "[" + token + "] No results returned");
             }
             return null;
         }
@@ -98,21 +98,24 @@ public abstract class InstantAppResolver {
                 intent.getPackage(), digest, token);
         logMetrics(ACTION_INSTANT_APP_RESOLUTION_PHASE_ONE, startTime, token,
                 RESOLUTION_SUCCESS);
+        if (DEBUG_EPHEMERAL && resolveInfo == null) {
+            Log.d(TAG, "[" + token + "] No results matched");
+        }
         return resolveInfo;
     }
 
     public static void doInstantAppResolutionPhaseTwo(Context context,
             EphemeralResolverConnection connection, InstantAppRequest requestObj,
             ActivityInfo instantAppInstaller, Handler callbackHandler) {
+        final long startTime = System.currentTimeMillis();
+        final String token = requestObj.responseObj.token;
         if (DEBUG_EPHEMERAL) {
-            Log.d(TAG, "Resolving phase 2");
+            Log.d(TAG, "[" + token + "] Resolving phase 2");
         }
-        final long startTime = System.currentTimeMillis();
         final Intent intent = requestObj.origIntent;
         final String hostName = intent.getData().getHost();
         final InstantAppDigest digest = new InstantAppDigest(hostName, 5 /*maxDigests*/);
         final int[] shaPrefix = digest.getDigestPrefix();
-        final String token = requestObj.responseObj.token;
 
         final PhaseTwoCallback callback = new PhaseTwoCallback() {
             @Override
@@ -285,12 +288,16 @@ public abstract class InstantAppResolver {
                 if (!matchedResolveInfoList.isEmpty()) {
                     if (DEBUG_EPHEMERAL) {
                         final AuxiliaryResolveInfo info = matchedResolveInfoList.get(0);
-                        Log.d(TAG, "Found match;"
+                        Log.d(TAG, "[" + token + "] Found match;"
                                 + " package: " + info.packageName
                                 + ", split: " + info.splitName
                                 + ", versionCode: " + info.versionCode);
                     }
                     return matchedResolveInfoList.get(0);
+                } else if (DEBUG_EPHEMERAL) {
+                    Log.d(TAG, "[" + token + "] No matches found"
+                            + " package: " + instantAppInfo.getPackageName()
+                            + ", versionCode: " + instantAppInfo.getVersionCode());
                 }
             }
         }