Add locallog to reveal the binding flakiness in CarrierServiceBindHelper
CarrierServiceBindHelper maitains the persistent binding
from phone to carrier app like Tycho. The binding is critical
on Fi's functionality. Over years, issues shows the binding
has broken status without details reveal how it reach there.
With locallog, more debug info may help to resolve the issue.
Bug: 72225685
Test: atest CarrierServiceBindHelperTest
Change-Id: I4e7e4a7197e8042aa3a0957882d5f23ddcd9497c
diff --git a/src/java/com/android/internal/telephony/CarrierServiceBindHelper.java b/src/java/com/android/internal/telephony/CarrierServiceBindHelper.java
index 69d59af..817a461 100644
--- a/src/java/com/android/internal/telephony/CarrierServiceBindHelper.java
+++ b/src/java/com/android/internal/telephony/CarrierServiceBindHelper.java
@@ -38,6 +38,7 @@
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 @@
@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 @@
@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 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 @@
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 @@
}
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 @@
);
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 @@
// 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 @@
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 @@
| Context.BIND_INCLUDE_CAPABILITIES,
(r) -> mHandler.post(r),
connection)) {
- log("service bound");
+ logdWithLocalLog("service bound");
mServiceBound = true;
return;
}
@@ -294,8 +300,8 @@
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 @@
// 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 @@
// 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 @@
@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 @@
// 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 @@
}
}
- 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);
}
}