Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit ecc64af2 authored by Rambo Wang's avatar Rambo Wang
Browse files

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
parent 633de1fa

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);

    }

}