Merge "Add locallog to reveal the binding flakiness in CarrierServiceBindHelper" (c024f16a) · Commits · e / os / android_frameworks_opt_telephony

src/java/com/android/internal/telephony/CarrierServiceBindHelper.java

+39 −24

Original line number	Diff line number	Diff line
		@@ -38,6 +38,7 @@ import android.service.carrier.CarrierService;
		import android.telephony.SubscriptionManager;
		import android.telephony.TelephonyManager;
		import android.text.TextUtils;
		import android.util.LocalLog;
		import android.util.Log;
		import android.util.SparseArray;

		@@ -68,6 +69,7 @@ public class CarrierServiceBindHelper {
		@VisibleForTesting
		public SparseArray<String> mLastSimState = new SparseArray<>();
		private final PackageChangeReceiver mPackageMonitor = new CarrierServicePackageMonitor();
		private final LocalLog mLocalLog = new LocalLog(100);

		// whether we have successfully bound to the service
		private boolean mServiceBound = false;
		@@ -76,7 +78,7 @@ public class CarrierServiceBindHelper {
		@Override
		public void onReceive(Context context, Intent intent) {
		final String action = intent.getAction();
		log("Received " + action);
		logdWithLocalLog("Received " + action);

		if (Intent.ACTION_USER_UNLOCKED.equals(action)) {
		// On user unlock, new components might become available, so reevaluate all
		@@ -101,20 +103,21 @@ public class CarrierServiceBindHelper {
		public void handleMessage(Message msg) {
		int phoneId;
		AppBinding binding;
		log("mHandler: " + msg.what);
		logdWithLocalLog("mHandler: " + msg.what);

		switch (msg.what) {
		case EVENT_REBIND:
		phoneId = (int) msg.obj;
		binding = mBindings.get(phoneId);
		if (binding == null) return;
		log("Rebinding if necessary for phoneId: " + binding.getPhoneId());
		logdWithLocalLog("Rebinding if necessary for phoneId: " + binding.getPhoneId());
		binding.rebind();
		break;
		case EVENT_PERFORM_IMMEDIATE_UNBIND:
		phoneId = (int) msg.obj;
		binding = mBindings.get(phoneId);
		if (binding == null) return;
		logdWithLocalLog("Unbind immediate with phoneId: " + binding.getPhoneId());
		binding.performImmediateUnbind();
		break;
		case EVENT_MULTI_SIM_CONFIG_CHANGED:
		@@ -141,7 +144,7 @@ public class CarrierServiceBindHelper {
		new IntentFilter(Intent.ACTION_USER_UNLOCKED), null /* broadcastPermission */,
		mHandler);
		} catch (PackageManager.NameNotFoundException e) {
		loge("Package name not found: " + e.getMessage());
		logeWithLocalLog("Package name not found: " + e.getMessage());
		}
		}

		@@ -166,7 +169,7 @@ public class CarrierServiceBindHelper {
		}

		void updateForPhoneId(int phoneId, String simState) {
		log("update binding for phoneId: " + phoneId + " simState: " + simState);
		logdWithLocalLog("update binding for phoneId: " + phoneId + " simState: " + simState);
		if (!SubscriptionManager.isValidPhoneId(phoneId)) {
		return;
		}
		@@ -218,13 +221,13 @@ public class CarrierServiceBindHelper {
		);

		if (carrierPackageNames == null \|\| carrierPackageNames.size() <= 0) {
		log("No carrier app for: " + phoneId);
		logdWithLocalLog("No carrier app for: " + phoneId);
		// Unbind after a delay in case this is a temporary blip in carrier privileges.
		unbind(false /* immediate */);
		return;
		}

		log("Found carrier app: " + carrierPackageNames);
		logdWithLocalLog("Found carrier app: " + carrierPackageNames);
		String candidateCarrierPackage = carrierPackageNames.get(0);
		// If we are binding to a different package, unbind immediately from the current one.
		if (!TextUtils.equals(carrierPackage, candidateCarrierPackage)) {
		@@ -249,15 +252,18 @@ public class CarrierServiceBindHelper {
		// Only bind if the service wants it
		if (metadata == null \|\|
		!metadata.getBoolean("android.service.carrier.LONG_LIVED_BINDING", false)) {
		log("Carrier app does not want a long lived binding");
		logdWithLocalLog("Carrier app does not want a long lived binding");
		unbind(true /* immediate */);
		return;
		}

		if (!TextUtils.equals(carrierServiceClass, candidateServiceClass)) {
		logdWithLocalLog("CarrierService class changed, unbind immediately.");
		// Unbind immediately if the carrier service component has changed.
		unbind(true /* immediate */);
		} else if (connection != null) {
		logdWithLocalLog(
		"CarrierService class unchanged with connection up, cancelScheduledUnbind");
		// Component is unchanged and connection is up - do nothing, but cancel any
		// scheduled unbinds.
		cancelScheduledUnbind();
		@@ -267,7 +273,7 @@ public class CarrierServiceBindHelper {
		carrierPackage = candidateCarrierPackage;
		carrierServiceClass = candidateServiceClass;

		log("Binding to " + carrierPackage + " for phone " + phoneId);
		logdWithLocalLog("Binding to " + carrierPackage + " for phone " + phoneId);

		// Log debug information
		bindCount++;
		@@ -284,7 +290,7 @@ public class CarrierServiceBindHelper {
		\| Context.BIND_INCLUDE_CAPABILITIES,
		(r) -> mHandler.post(r),
		connection)) {
		log("service bound");
		logdWithLocalLog("service bound");
		mServiceBound = true;
		return;
		}
		@@ -294,8 +300,8 @@ public class CarrierServiceBindHelper {
		error = ex.getMessage();
		}

		log("Unable to bind to " + carrierPackage + " for phone " + phoneId +
		". Error: " + error);
		logdWithLocalLog("Unable to bind to " + carrierPackage + " for phone " + phoneId
		+ ". Error: " + error);
		unbind(true /* immediate */);
		}

		@@ -318,12 +324,13 @@ public class CarrierServiceBindHelper {
		// not running anyway and it may be a permanent disconnection (e.g. the app was
		// disabled).
		if (immediate \|\| !connection.connected) {
		logdWithLocalLog("unbind immediately or with disconnected connection");
		cancelScheduledUnbind();
		performImmediateUnbind();
		} else if (mUnbindScheduledUptimeMillis == -1) {
		long currentUptimeMillis = SystemClock.uptimeMillis();
		mUnbindScheduledUptimeMillis = currentUptimeMillis + UNBIND_DELAY_MILLIS;
		log("Scheduling unbind in " + UNBIND_DELAY_MILLIS + " millis");
		logdWithLocalLog("Scheduling unbind in " + UNBIND_DELAY_MILLIS + " millis");
		mHandler.sendMessageAtTime(
		mHandler.obtainMessage(EVENT_PERFORM_IMMEDIATE_UNBIND, phoneId),
		mUnbindScheduledUptimeMillis);
		@@ -341,22 +348,23 @@ public class CarrierServiceBindHelper {

		// Actually unbind
		if (mServiceBound) {
		log("Unbinding from carrier app");
		logdWithLocalLog("Unbinding from carrier app");
		mServiceBound = false;
		try {
		mContext.unbindService(connection);
		} catch (IllegalArgumentException e) {
		//TODO(b/151328766): Figure out why we unbind without binding
		loge("Tried to unbind without binding e=" + e);
		logeWithLocalLog("Tried to unbind without binding e=" + e);
		}
		} else {
		log("Not bound, skipping unbindService call");
		logdWithLocalLog("Not bound, skipping unbindService call");
		}
		connection = null;
		mUnbindScheduledUptimeMillis = -1;
		}

		private void cancelScheduledUnbind() {
		logdWithLocalLog("cancelScheduledUnbind");
		mHandler.removeMessages(EVENT_PERFORM_IMMEDIATE_UNBIND);
		mUnbindScheduledUptimeMillis = -1;
		}
		@@ -378,25 +386,25 @@ public class CarrierServiceBindHelper {

		@Override
		public void onServiceConnected(ComponentName name, IBinder service) {
		log("Connected to carrier app: " + name.flattenToString());
		logdWithLocalLog("Connected to carrier app: " + name.flattenToString());
		connected = true;
		}

		@Override
		public void onServiceDisconnected(ComponentName name) {
		log("Disconnected from carrier app: " + name.flattenToString());
		logdWithLocalLog("Disconnected from carrier app: " + name.flattenToString());
		connected = false;
		}

		@Override
		public void onBindingDied(ComponentName name) {
		log("Binding from carrier app died: " + name.flattenToString());
		logdWithLocalLog("Binding from carrier app died: " + name.flattenToString());
		connected = false;
		}

		@Override
		public void onNullBinding(ComponentName name) {
		log("Null binding from carrier app: " + name.flattenToString());
		logdWithLocalLog("Null binding from carrier app: " + name.flattenToString());
		connected = false;
		}

		@@ -446,7 +454,8 @@ public class CarrierServiceBindHelper {
		// is unset, in case this package change resulted in a new carrier package becoming
		// available for binding.
		if (isBindingForPackage) {
		log(carrierPackageName + " changed and corresponds to a phone. Rebinding.");
		logdWithLocalLog(
		carrierPackageName + " changed and corresponds to a phone. Rebinding.");
		}
		if (appBindingPackage == null \|\| isBindingForPackage) {
		if (forceUnbind) {
		@@ -458,16 +467,22 @@ public class CarrierServiceBindHelper {
		}
		}

		private static void log(String message) {
		Log.d(LOG_TAG, message);
		private void logdWithLocalLog(String msg) {
		Log.d(LOG_TAG, msg);
		mLocalLog.log(msg);
		}

		private static void loge(String message) { Log.e(LOG_TAG, message); }
		private void logeWithLocalLog(String msg) {
		Log.e(LOG_TAG, msg);
		mLocalLog.log(msg);
		}

		public void dump(FileDescriptor fd, PrintWriter pw, String[] args) {
		pw.println("CarrierServiceBindHelper:");
		for (int i = 0; i < mBindings.size(); i++) {
		mBindings.get(i).dump(fd, pw, args);
		}
		pw.println("CarrierServiceBindHelperLogs=");
		mLocalLog.dump(fd, pw, args);
		}
		}