Binding on-demand #12: Log and unbind dangling TransportClients (3184cc99) · Commits · e / os / android_frameworks_base

services/backup/java/com/android/server/backup/transport/TransportClient.java

+178 −75

Original line number	Diff line number	Diff line
		@@ -33,7 +33,7 @@ import android.os.UserHandle;
		import android.text.format.DateFormat;
		import android.util.ArrayMap;
		import android.util.EventLog;
		import android.util.Log;
		import android.util.Slog;

		import com.android.internal.annotations.GuardedBy;
		import com.android.internal.annotations.VisibleForTesting;
		@@ -41,9 +41,13 @@ import com.android.internal.backup.IBackupTransport;
		import com.android.internal.util.Preconditions;
		import com.android.server.EventLogTags;
		import com.android.server.backup.TransportManager;
		import com.android.server.backup.transport.TransportUtils.Priority;

		import dalvik.system.CloseGuard;

		import java.lang.annotation.Retention;
		import java.lang.annotation.RetentionPolicy;
		import java.lang.ref.WeakReference;
		import java.util.Collections;
		import java.util.LinkedList;
		import java.util.List;
		@@ -70,17 +74,20 @@ import java.util.concurrent.ExecutionException;
		* @see TransportManager
		*/
		public class TransportClient {
		private static final String TAG = "TransportClient";
		@VisibleForTesting static final String TAG = "TransportClient";
		private static final int LOG_BUFFER_SIZE = 5;

		private final Context mContext;
		private final Intent mBindIntent;
		private final ServiceConnection mConnection;
		private final String mIdentifier;
		private final String mCreatorLogString;
		private final ComponentName mTransportComponent;
		private final Handler mListenerHandler;
		private final String mPrefixForLog;
		private final Object mStateLock = new Object();
		private final Object mLogBufferLock = new Object();
		private final CloseGuard mCloseGuard = CloseGuard.get();

		@GuardedBy("mLogBufferLock")
		private final List<String> mLogBuffer = new LinkedList<>();
		@@ -99,12 +106,14 @@ public class TransportClient {
		Context context,
		Intent bindIntent,
		ComponentName transportComponent,
		String identifier) {
		String identifier,
		String caller) {
		this(
		context,
		bindIntent,
		transportComponent,
		identifier,
		caller,
		new Handler(Looper.getMainLooper()));
		}

		@@ -114,79 +123,27 @@ public class TransportClient {
		Intent bindIntent,
		ComponentName transportComponent,
		String identifier,
		String caller,
		Handler listenerHandler) {
		mContext = context;
		mTransportComponent = transportComponent;
		mBindIntent = bindIntent;
		mIdentifier = identifier;
		mCreatorLogString = caller;
		mListenerHandler = listenerHandler;
		mConnection = new TransportConnection(context, this);

		// For logging
		String classNameForLog = mTransportComponent.getShortClassName().replaceFirst(".*\\.", "");
		mPrefixForLog = classNameForLog + "#" + mIdentifier + ":";

		mCloseGuard.open("markAsDisposed");
		}

		public ComponentName getTransportComponent() {
		return mTransportComponent;
		}

		// Calls to onServiceDisconnected() or onBindingDied() turn TransportClient UNUSABLE. After one
		// of these calls, if a binding happen again the new service can be a different instance. Since
		// transports are stateful, we don't want a new instance responding for an old instance's state.
		private ServiceConnection mConnection =
		new ServiceConnection() {
		@Override
		public void onServiceConnected(ComponentName componentName, IBinder binder) {
		IBackupTransport transport = IBackupTransport.Stub.asInterface(binder);
		synchronized (mStateLock) {
		checkStateIntegrityLocked();

		if (mState != State.UNUSABLE) {
		log(Log.DEBUG, "Transport connected");
		setStateLocked(State.CONNECTED, transport);
		notifyListenersAndClearLocked(transport);
		}
		}
		}

		@Override
		public void onServiceDisconnected(ComponentName componentName) {
		synchronized (mStateLock) {
		log(Log.ERROR, "Service disconnected: client UNUSABLE");
		setStateLocked(State.UNUSABLE, null);
		// After unbindService() no calls back to mConnection
		mContext.unbindService(this);
		}
		}

		@Override
		public void onBindingDied(ComponentName name) {
		synchronized (mStateLock) {
		checkStateIntegrityLocked();

		log(Log.ERROR, "Binding died: client UNUSABLE");
		// After unbindService() no calls back to mConnection
		switch (mState) {
		case State.UNUSABLE:
		break;
		case State.IDLE:
		log(Log.ERROR, "Unexpected state transition IDLE => UNUSABLE");
		setStateLocked(State.UNUSABLE, null);
		break;
		case State.BOUND_AND_CONNECTING:
		setStateLocked(State.UNUSABLE, null);
		mContext.unbindService(this);
		notifyListenersAndClearLocked(null);
		break;
		case State.CONNECTED:
		setStateLocked(State.UNUSABLE, null);
		mContext.unbindService(this);
		break;
		}
		}
		}
		};

		/**
		* Attempts to connect to the transport (if needed).
		*
		@@ -240,7 +197,7 @@ public class TransportClient {

		switch (mState) {
		case State.UNUSABLE:
		log(Log.WARN, caller, "Async connect: UNUSABLE client");
		log(Priority.WARN, caller, "Async connect: UNUSABLE client");
		notifyListener(listener, null, caller);
		break;
		case State.IDLE:
		@@ -254,22 +211,25 @@ public class TransportClient {
		// We don't need to set a time-out because we are guaranteed to get a call
		// back in ServiceConnection, either an onServiceConnected() or
		// onBindingDied().
		log(Log.DEBUG, caller, "Async connect: service bound, connecting");
		log(Priority.DEBUG, caller, "Async connect: service bound, connecting");
		setStateLocked(State.BOUND_AND_CONNECTING, null);
		mListeners.put(listener, caller);
		} else {
		log(Log.ERROR, "Async connect: bindService returned false");
		log(Priority.ERROR, "Async connect: bindService returned false");
		// mState remains State.IDLE
		mContext.unbindService(mConnection);
		notifyListener(listener, null, caller);
		}
		break;
		case State.BOUND_AND_CONNECTING:
		log(Log.DEBUG, caller, "Async connect: already connecting, adding listener");
		log(
		Priority.DEBUG,
		caller,
		"Async connect: already connecting, adding listener");
		mListeners.put(listener, caller);
		break;
		case State.CONNECTED:
		log(Log.DEBUG, caller, "Async connect: reusing transport");
		log(Priority.DEBUG, caller, "Async connect: reusing transport");
		notifyListener(listener, mTransport, caller);
		break;
		}
		@@ -286,7 +246,7 @@ public class TransportClient {
		synchronized (mStateLock) {
		checkStateIntegrityLocked();

		log(Log.DEBUG, caller, "Unbind requested (was " + stateToString(mState) + ")");
		log(Priority.DEBUG, caller, "Unbind requested (was " + stateToString(mState) + ")");
		switch (mState) {
		case State.UNUSABLE:
		case State.IDLE:
		@@ -305,6 +265,15 @@ public class TransportClient {
		}
		}

		/** Marks this TransportClient as disposed, allowing it to be GC'ed without warnings. */
		public void markAsDisposed() {
		synchronized (mStateLock) {
		Preconditions.checkState(
		mState < State.BOUND_AND_CONNECTING, "Can't mark as disposed if still bound");
		mCloseGuard.close();
		}
		}

		/**
		* Attempts to connect to the transport (if needed) and returns it.
		*
		@@ -335,14 +304,14 @@ public class TransportClient {

		IBackupTransport transport = mTransport;
		if (transport != null) {
		log(Log.INFO, caller, "Sync connect: reusing transport");
		log(Priority.DEBUG, caller, "Sync connect: reusing transport");
		return transport;
		}

		// If it's already UNUSABLE we return straight away, no need to go to main-thread
		synchronized (mStateLock) {
		if (mState == State.UNUSABLE) {
		log(Log.WARN, caller, "Sync connect: UNUSABLE client");
		log(Priority.WARN, caller, "Sync connect: UNUSABLE client");
		return null;
		}
		}
		@@ -352,14 +321,14 @@ public class TransportClient {
		(requestedTransport, transportClient) ->
		transportFuture.complete(requestedTransport);

		log(Log.DEBUG, caller, "Sync connect: calling async");
		log(Priority.DEBUG, caller, "Sync connect: calling async");
		connectAsync(requestListener, caller);

		try {
		return transportFuture.get();
		} catch (InterruptedException \| ExecutionException e) {
		String error = e.getClass().getSimpleName();
		log(Log.ERROR, caller, error + " while waiting for transport: " + e.getMessage());
		log(Priority.ERROR, caller, error + " while waiting for transport: " + e.getMessage());
		return null;
		}
		}
		@@ -379,7 +348,7 @@ public class TransportClient {
		public IBackupTransport connectOrThrow(String caller) throws TransportNotAvailableException {
		IBackupTransport transport = connect(caller);
		if (transport == null) {
		log(Log.ERROR, caller, "Transport connection failed");
		log(Priority.ERROR, caller, "Transport connection failed");
		throw new TransportNotAvailableException();
		}
		return transport;
		@@ -398,7 +367,7 @@ public class TransportClient {
		throws TransportNotAvailableException {
		IBackupTransport transport = mTransport;
		if (transport == null) {
		log(Log.ERROR, caller, "Transport not connected");
		log(Priority.ERROR, caller, "Transport not connected");
		throw new TransportNotAvailableException();
		}
		return transport;
		@@ -413,12 +382,92 @@ public class TransportClient {
		+ "}";
		}

		@Override
		protected void finalize() throws Throwable {
		synchronized (mStateLock) {
		mCloseGuard.warnIfOpen();
		if (mState >= State.BOUND_AND_CONNECTING) {
		String callerLogString = "TransportClient.finalize()";
		log(
		Priority.ERROR,
		callerLogString,
		"Dangling TransportClient created in [" + mCreatorLogString + "] being "
		+ "GC'ed. Left bound, unbinding...");
		try {
		unbind(callerLogString);
		} catch (IllegalStateException e) {
		// May throw because there may be a race between this method being called and
		// the framework calling any method on the connection with the weak reference
		// there already cleared. In this case the connection will unbind before this
		// is called. This is fine.
		}
		}
		}
		}

		private void onServiceConnected(IBinder binder) {
		IBackupTransport transport = IBackupTransport.Stub.asInterface(binder);
		synchronized (mStateLock) {
		checkStateIntegrityLocked();

		if (mState != State.UNUSABLE) {
		log(Priority.DEBUG, "Transport connected");
		setStateLocked(State.CONNECTED, transport);
		notifyListenersAndClearLocked(transport);
		}
		}
		}

		/**
		* If we are called here the TransportClient becomes UNUSABLE. After one of these calls, if a
		* binding happen again the new service can be a different instance. Since transports are
		* stateful, we don't want a new instance responding for an old instance's state.
		*/
		private void onServiceDisconnected() {
		synchronized (mStateLock) {
		log(Priority.ERROR, "Service disconnected: client UNUSABLE");
		setStateLocked(State.UNUSABLE, null);
		// After unbindService() no calls back to mConnection
		mContext.unbindService(mConnection);
		}
		}

		/**
		* If we are called here the TransportClient becomes UNUSABLE for the same reason as in {@link
		* #onServiceDisconnected()}.
		*/
		private void onBindingDied() {
		synchronized (mStateLock) {
		checkStateIntegrityLocked();

		log(Priority.ERROR, "Binding died: client UNUSABLE");
		// After unbindService() no calls back to mConnection
		switch (mState) {
		case State.UNUSABLE:
		break;
		case State.IDLE:
		log(Priority.ERROR, "Unexpected state transition IDLE => UNUSABLE");
		setStateLocked(State.UNUSABLE, null);
		break;
		case State.BOUND_AND_CONNECTING:
		setStateLocked(State.UNUSABLE, null);
		mContext.unbindService(mConnection);
		notifyListenersAndClearLocked(null);
		break;
		case State.CONNECTED:
		setStateLocked(State.UNUSABLE, null);
		mContext.unbindService(mConnection);
		break;
		}
		}
		}

		private void notifyListener(
		TransportConnectionListener listener,
		@Nullable IBackupTransport transport,
		String caller) {
		String transportString = (transport != null) ? "IBackupTransport" : "null";
		log(Log.INFO, "Notifying [" + caller + "] transport = " + transportString);
		log(Priority.INFO, "Notifying [" + caller + "] transport = " + transportString);
		mListenerHandler.post(() -> listener.onTransportConnectionResult(transport, this));
		}

		@@ -434,7 +483,7 @@ public class TransportClient {

		@GuardedBy("mStateLock")
		private void setStateLocked(@State int state, @Nullable IBackupTransport transport) {
		log(Log.VERBOSE, "State: " + stateToString(mState) + " => " + stateToString(state));
		log(Priority.VERBOSE, "State: " + stateToString(mState) + " => " + stateToString(state));
		onStateTransition(mState, state);
		mState = state;
		mTransport = transport;
		@@ -503,7 +552,7 @@ public class TransportClient {

		private void checkState(boolean assertion, String message) {
		if (!assertion) {
		log(Log.ERROR, message);
		log(Priority.ERROR, message);
		}
		}

		@@ -560,9 +609,63 @@ public class TransportClient {
		@IntDef({State.UNUSABLE, State.IDLE, State.BOUND_AND_CONNECTING, State.CONNECTED})
		@Retention(RetentionPolicy.SOURCE)
		private @interface State {
		// Constant values MUST be in order
		int UNUSABLE = 0;
		int IDLE = 1;
		int BOUND_AND_CONNECTING = 2;
		int CONNECTED = 3;
		}

		/**
		* This class is a proxy to TransportClient methods that doesn't hold a strong reference to the
		* TransportClient, allowing it to be GC'ed. If the reference was lost it logs a message.
		*/
		private static class TransportConnection implements ServiceConnection {
		private final Context mContext;
		private final WeakReference<TransportClient> mTransportClientRef;

		private TransportConnection(Context context, TransportClient transportClient) {
		mContext = context;
		mTransportClientRef = new WeakReference<>(transportClient);
		}

		@Override
		public void onServiceConnected(ComponentName transportComponent, IBinder binder) {
		TransportClient transportClient = mTransportClientRef.get();
		if (transportClient == null) {
		referenceLost("TransportConnection.onServiceConnected()");
		return;
		}
		transportClient.onServiceConnected(binder);
		}

		@Override
		public void onServiceDisconnected(ComponentName transportComponent) {
		TransportClient transportClient = mTransportClientRef.get();
		if (transportClient == null) {
		referenceLost("TransportConnection.onServiceDisconnected()");
		return;
		}
		transportClient.onServiceDisconnected();
		}

		@Override
		public void onBindingDied(ComponentName transportComponent) {
		TransportClient transportClient = mTransportClientRef.get();
		if (transportClient == null) {
		referenceLost("TransportConnection.onBindingDied()");
		return;
		}
		transportClient.onBindingDied();
		}

		/** @see TransportClient#finalize() */
		private void referenceLost(String caller) {
		mContext.unbindService(this);
		TransportUtils.log(
		Priority.INFO,
		TAG,
		caller + " called but TransportClient reference has been GC'ed");
		}
		}
		}

services/backup/java/com/android/server/backup/transport/TransportClientManager.java

+12 −4

Original line number	Diff line number	Diff line
		@@ -22,8 +22,10 @@ import static com.android.server.backup.transport.TransportUtils.formatMessage;
		import android.content.ComponentName;
		import android.content.Context;
		import android.content.Intent;
		import android.util.Log;

		import com.android.server.backup.TransportManager;
		import com.android.server.backup.transport.TransportUtils.Priority;

		import java.io.PrintWriter;
		import java.util.Map;
		import java.util.WeakHashMap;
		@@ -63,11 +65,14 @@ public class TransportClientManager {
		mContext,
		bindIntent,
		transportComponent,
		Integer.toString(mTransportClientsCreated));
		Integer.toString(mTransportClientsCreated),
		caller);
		mTransportClientsCallerMap.put(transportClient, caller);
		mTransportClientsCreated++;
		TransportUtils.log(
		Log.DEBUG, TAG, formatMessage(null, caller, "Retrieving " + transportClient));
		Priority.DEBUG,
		TAG,
		formatMessage(null, caller, "Retrieving " + transportClient));
		return transportClient;
		}
		}
		@@ -82,9 +87,12 @@ public class TransportClientManager {
		*/
		public void disposeOfTransportClient(TransportClient transportClient, String caller) {
		transportClient.unbind(caller);
		transportClient.markAsDisposed();
		synchronized (mTransportClientsLock) {
		TransportUtils.log(
		Log.DEBUG, TAG, formatMessage(null, caller, "Disposing of " + transportClient));
		Priority.DEBUG,
		TAG,
		formatMessage(null, caller, "Disposing of " + transportClient));
		mTransportClientsCallerMap.remove(transportClient);
		}
		}

services/backup/java/com/android/server/backup/transport/TransportUtils.java

+24 −3

Original line number	Diff line number	Diff line
		@@ -16,6 +16,7 @@

		package com.android.server.backup.transport;

		import android.annotation.IntDef;
		import android.annotation.Nullable;
		import android.os.DeadObjectException;
		import android.util.Log;
		@@ -23,6 +24,9 @@ import android.util.Slog;

		import com.android.internal.backup.IBackupTransport;

		import java.lang.annotation.Retention;
		import java.lang.annotation.RetentionPolicy;

		/** Utility methods for transport-related operations. */
		public class TransportUtils {
		private static final String TAG = "TransportUtils";
		@@ -34,14 +38,16 @@ public class TransportUtils {
		public static IBackupTransport checkTransportNotNull(@Nullable IBackupTransport transport)
		throws TransportNotAvailableException {
		if (transport == null) {
		log(Log.ERROR, TAG, "Transport not available");
		log(Priority.ERROR, TAG, "Transport not available");
		throw new TransportNotAvailableException();
		}
		return transport;
		}

		static void log(int priority, String tag, String message) {
		if (Log.isLoggable(tag, priority)) {
		static void log(@Priority int priority, String tag, String message) {
		if (priority == Priority.WTF) {
		Slog.wtf(tag, message);
		} else if (Log.isLoggable(tag, priority)) {
		Slog.println(priority, tag, message);
		}
		}
		@@ -57,5 +63,20 @@ public class TransportUtils {
		return string.append(message).toString();
		}

		/**
		* Create our own constants so we can log WTF using the same APIs. Except for {@link
		* Priority#WTF} all the others have the same value, so can be used directly
		*/
		@IntDef({Priority.VERBOSE, Priority.DEBUG, Priority.INFO, Priority.WARN, Priority.WTF})
		@Retention(RetentionPolicy.SOURCE)
		@interface Priority {
		int VERBOSE = Log.VERBOSE;
		int DEBUG = Log.DEBUG;
		int INFO = Log.INFO;
		int WARN = Log.WARN;
		int ERROR = Log.ERROR;
		int WTF = -1;
		}

		private TransportUtils() {}
		}

services/robotests/src/com/android/server/backup/testing/TestUtils.java

+17 −0

Original line number	Diff line number	Diff line
		@@ -16,11 +16,28 @@

		package com.android.server.backup.testing;

		import static com.google.common.truth.Truth.assertThat;


		import com.android.internal.util.FunctionalUtils.ThrowingRunnable;

		import org.robolectric.shadows.ShadowLog;

		import java.util.concurrent.Callable;

		public class TestUtils {
		/** Reset logcat with {@link ShadowLog#reset()} before the test case */
		public static void assertLogcatAtMost(String tag, int level) {
		assertThat(ShadowLog.getLogsForTag(tag).stream().allMatch(logItem -> logItem.type <= level))
		.isTrue();
		}

		/** Reset logcat with {@link ShadowLog#reset()} before the test case */
		public static void assertLogcatAtLeast(String tag, int level) {
		assertThat(ShadowLog.getLogsForTag(tag).stream().anyMatch(logItem -> logItem.type >= level))
		.isTrue();
		}

		/**
		* Calls {@link Runnable#run()} and returns if no exception is thrown. Otherwise, if the
		* exception is unchecked, rethrow it; if it's checked wrap in a {@link RuntimeException} and

services/robotests/src/com/android/server/backup/transport/TransportClientTest.java

+158 −22

File changed.

Preview size limit exceeded, changes collapsed.