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

Commit 707644d8 authored by Tyler Gunn's avatar Tyler Gunn
Browse files

Enhance ImsPhoneCall/Tracker logging and fix swap on bad state change 

ImsPhoneConnection:
- Added check in update() to ensure we skip the update if we are putting
the call into an ACTIVE state, but there is a pending request to
hold the ImsCall.  This is really a bug in the RIL; we are NOT getting
the callSessionHeld callback when putting a recently formed conference
call into the background.  Without this check, we end up detaching the
ImsPhoneConnection from the "background" ImsPhoneCall and attaching it
to the "foreground" ImsPhoneConnection, which causes a scenario where there
are multiple active calls at the same time.  I will file a bug against
the RIL to fix this missing state reporting.

ImsPhoneCallTracker:
- in switchWaitingOrHoldingAndActive check for the case where we are
holding a foreground call and reset the flag indicating we're expecting
to see a resume.  This wasn't causing the bug I was working on but I
can see how it might have undesirable effects.
- added some extra debug logging to help track down hold/resumes
- fixed some BAD logic in onCallMerged added in change ID
I94abbae37eb6773f1824c0e5c3a267d345610ada.  This code was swapping the
ImsPhoneCall references for foreground and background directly in order
to ensure that the right calls were passed in to ImsPhoneCall#merge.
The ImsPhoneCallTracker assumes the ImsPhoneCalls mForegroundCall and
mBackgroundCall will always stay the same; ImsPhoneConnections are attached
and detached from these ImsPhoneCalls, but the original references must
stay the same.  Fixed up that code to ensure it does what its supposed to
without messing up the original references.
- Added logState method which can be turned on via debug flag to periodically
dump verbose state of the calls tracked my ImsPhoneCallTracker.  I had
a hard time figuring out what was going on and this helped a lot.

ImsPhoneCall:
- Added enhanced logging when ImsPhoneConnections are moved between the
foreground, background, etc calls.  Also added knowledge of whether an
ImsPhoneCall is a foreground or background call so that logging can be made
more clear.

- After operations which change which calls are FG or BG, calling
ImsPhoneCallTracker.logState() which will log the full ImsPhoneCallTracker
state for even easier debugging (but only if the stop-ship flag is on).

Bug: 22173672
Change-Id: I704af9522a81ee036f290c7c723de4c3602229fd
parent c8582255

src/java/com/android/internal/telephony/imsphone/ImsPhoneCall.java

+64 −8
Original line number Diff line number Diff line
@@ -19,6 +19,7 @@ package com.android.internal.telephony.imsphone; 
import android.telecom.ConferenceParticipant;

import android.telephony.Rlog;

import android.telephony.DisconnectCause;

import android.util.Log;



import com.android.internal.annotations.VisibleForTesting;

import com.android.internal.telephony.Call;
@@ -35,22 +36,40 @@ import java.util.List; 
 * {@hide}

 */

public class ImsPhoneCall extends Call {

    /*************************** Instance Variables **************************/



    private static final String LOG_TAG = "ImsPhoneCall";



    // This flag is meant to be used as a debugging tool to quickly see all logs

    // regardless of the actual log level set on this component.

    private static final boolean FORCE_DEBUG = false; /* STOPSHIP if true */

    private static final boolean DBG = FORCE_DEBUG || Rlog.isLoggable(LOG_TAG, Log.DEBUG);

    private static final boolean VDBG = FORCE_DEBUG || Rlog.isLoggable(LOG_TAG, Log.VERBOSE);



    /*************************** Instance Variables **************************/

    public static final String CONTEXT_UNKNOWN = "UK";

    public static final String CONTEXT_RINGING = "RG";

    public static final String CONTEXT_FOREGROUND = "FG";

    public static final String CONTEXT_BACKGROUND = "BG";

    public static final String CONTEXT_HANDOVER = "HO";



    /*package*/ ImsPhoneCallTracker mOwner;



    private boolean mRingbackTonePlayed = false;



    // Determines what type of ImsPhoneCall this is.  ImsPhoneCallTracker uses instances of

    // ImsPhoneCall to for fg, bg, etc calls.  This is used as a convenience for logging so that it

    // can be made clear whether a call being logged is the foreground, background, etc.

    private final String mCallContext;



    /****************************** Constructors *****************************/

    /*package*/

    ImsPhoneCall() {

        mCallContext = CONTEXT_UNKNOWN;

    }



    /*package*/

    ImsPhoneCall(ImsPhoneCallTracker owner) {

    ImsPhoneCall(ImsPhoneCallTracker owner, String context) {

        mOwner = owner;

        mCallContext = context;

    }



    public void dispose() {
@@ -102,9 +121,23 @@ public class ImsPhoneCall extends Call { 
    }



    @Override

    public String

    toString() {

        return mState.toString();

    public String toString() {

        StringBuilder sb = new StringBuilder();

        sb.append("[ImsPhoneCall ");

        sb.append(mCallContext);

        sb.append(" state: ");

        sb.append(mState.toString());

        sb.append(" ");

        if (mConnections.size() > 1) {

            sb.append(" ERROR_MULTIPLE ");

        }

        for (Connection conn : mConnections) {

            sb.append(conn);

            sb.append(" ");

        }



        sb.append("]");

        return sb.toString();

    }



    @Override
@@ -120,12 +153,21 @@ public class ImsPhoneCall extends Call { 


    /*package*/ void

    attach(Connection conn) {

        if (VDBG) {

            Rlog.v(LOG_TAG, "attach : " + mCallContext + " conn = " + conn);

        }

        clearDisconnected();

        mConnections.add(conn);



        mOwner.logState();

    }



    /*package*/ void

    attach(Connection conn, State state) {

        if (VDBG) {

            Rlog.v(LOG_TAG, "attach : " + mCallContext + " state = " +

                    state.toString());

        }

        this.attach(conn);

        mState = state;

    }
@@ -163,8 +205,13 @@ public class ImsPhoneCall extends Call { 


    /*package*/ void

    detach(ImsPhoneConnection conn) {

        if (VDBG) {

            Rlog.v(LOG_TAG, "detach : " + mCallContext + " conn = " + conn);

        }

        mConnections.remove(conn);

        clearDisconnected();



        mOwner.logState();

    }



    /**
@@ -238,10 +285,15 @@ public class ImsPhoneCall extends Call { 
            if (conferenceConnectTime > 0) {

                imsPhoneConnection.setConnectTime(conferenceConnectTime);

            } else {

                if (DBG) {

                    Rlog.d(LOG_TAG, "merge: conference connect time is 0");

                }

            }

        Rlog.d(LOG_TAG, "merge: " + that + "state = " + state);

        }

        if (DBG) {

            Rlog.d(LOG_TAG, "merge(" + mCallContext + "): " + that + "state = "

                    + state);

        }

    }



    /**
@@ -309,12 +361,16 @@ public class ImsPhoneCall extends Call { 
    }



    void switchWith(ImsPhoneCall that) {

        if (VDBG) {

            Rlog.v(LOG_TAG, "switchWith : switchCall = " + this + " withCall = " + that);

        }

        synchronized (ImsPhoneCall.class) {

            ImsPhoneCall tmp = new ImsPhoneCall();

            tmp.takeOver(this);

            this.takeOver(that);

            that.takeOver(tmp);

        }

        mOwner.logState();

    }



    private void takeOver(ImsPhoneCall that) {

src/java/com/android/internal/telephony/imsphone/ImsPhoneCallTracker.java

+60 −21
Original line number Diff line number Diff line
@@ -75,6 +75,10 @@ public final class ImsPhoneCallTracker extends CallTracker { 


    private static final boolean DBG = true;



    // When true, dumps the state of ImsPhoneCallTracker after changes to foreground and background

    // calls.  This is helpful for debugging.

    private static final boolean VERBOSE_STATE_LOGGING = false; /* stopship if true */



    private boolean[] mImsFeatureEnabled = {false, false, false, false};



    private BroadcastReceiver mReceiver = new BroadcastReceiver() {
@@ -141,10 +145,10 @@ public final class ImsPhoneCallTracker extends CallTracker { 
    private RegistrantList mVoiceCallEndedRegistrants = new RegistrantList();

    private RegistrantList mVoiceCallStartedRegistrants = new RegistrantList();



    ImsPhoneCall mRingingCall = new ImsPhoneCall(this);

    ImsPhoneCall mForegroundCall = new ImsPhoneCall(this);

    ImsPhoneCall mBackgroundCall = new ImsPhoneCall(this);

    ImsPhoneCall mHandoverCall = new ImsPhoneCall(this);

    final ImsPhoneCall mRingingCall = new ImsPhoneCall(this, ImsPhoneCall.CONTEXT_RINGING);

    final ImsPhoneCall mForegroundCall = new ImsPhoneCall(this, ImsPhoneCall.CONTEXT_FOREGROUND);

    final ImsPhoneCall mBackgroundCall = new ImsPhoneCall(this, ImsPhoneCall.CONTEXT_BACKGROUND);

    final ImsPhoneCall mHandoverCall = new ImsPhoneCall(this, ImsPhoneCall.CONTEXT_HANDOVER);



    private ImsPhoneConnection mPendingMO;

    private int mClirMode = CommandsInterface.CLIR_DEFAULT;
@@ -506,6 +510,11 @@ public final class ImsPhoneCallTracker extends CallTracker { 
            // be resumed.

            try {

                imsCall.hold();



                // If there is no background call to resume, then don't expect there to be a switch.

                if (mCallExpectedToResume == null) {

                    mSwitchingFgAndBgCalls = false;

                }

            } catch (ImsException e) {

                mForegroundCall.switchWith(mBackgroundCall);

                throw new CallStateException(e.getMessage());
@@ -1081,7 +1090,13 @@ public final class ImsPhoneCallTracker extends CallTracker { 


        @Override

        public void onCallHeld(ImsCall imsCall) {

            if (DBG) log("onCallHeld");

            if (DBG) {

                if (mForegroundCall.getImsCall() == imsCall) {

                    log("onCallHeld (fg) " + imsCall);

                } else if (mBackgroundCall.getImsCall() == imsCall) {

                    log("onCallHeld (bg) " + imsCall);

                }

            }



            synchronized (mSyncHold) {

                ImsPhoneCall.State oldState = mBackgroundCall.getState();
@@ -1148,6 +1163,10 @@ public final class ImsPhoneCallTracker extends CallTracker { 
            // is not the one we expected, we likely had a resume failure and we need to swap the

            // FG and BG calls back.

            if (mSwitchingFgAndBgCalls && imsCall != mCallExpectedToResume) {

                if (DBG) {

                    log("onCallResumed : switching " + mForegroundCall + " with "

                            + mBackgroundCall);

                }

                mForegroundCall.switchWith(mBackgroundCall);

                mSwitchingFgAndBgCalls = false;

                mCallExpectedToResume = null;
@@ -1158,10 +1177,13 @@ public final class ImsPhoneCallTracker extends CallTracker { 


        @Override

        public void onCallResumeFailed(ImsCall imsCall, ImsReasonInfo reasonInfo) {

            // TODO : What should be done?

            // If we are in the midst of swapping the FG and BG calls and we got a resume fail, we

            // need to swap back the FG and BG calls.

            if (mSwitchingFgAndBgCalls && imsCall == mCallExpectedToResume) {

                if (DBG) {

                    log("onCallResumeFailed : switching " + mForegroundCall + " with "

                            + mBackgroundCall);

                }

                mForegroundCall.switchWith(mBackgroundCall);

                mCallExpectedToResume = null;

                mSwitchingFgAndBgCalls = false;
@@ -1196,25 +1218,15 @@ public final class ImsPhoneCallTracker extends CallTracker { 
        public void onCallMerged(final ImsCall call, final ImsCall peerCall, boolean swapCalls) {

            if (DBG) log("onCallMerged");



            ImsPhoneCall foregroundImsPhoneCall = findConnection(call).getCall();

            ImsPhoneConnection peerConnection = findConnection(peerCall);

            mForegroundCall = findConnection(call).getCall();

            if (peerConnection != null) {

                mBackgroundCall = peerConnection.getCall();

            } else {

                log("onCallMerged :: Null connection for background call.");

            }



            log("onCallMerged :: call.mSession=" + call.getSession());

            if (peerCall.getSession() != null) {

                log("onCallMerged :: b/g call session=" + peerCall.getSession());

            } else {

                log("onCallMerged :: b/g call session is null");

            }

            ImsPhoneCall peerImsPhoneCall = peerConnection == null ? null

                    : peerConnection.getCall();



            if (swapCalls) {

                switchAfterConferenceSuccess();

            }

            mForegroundCall.merge(mBackgroundCall, ImsPhoneCall.State.ACTIVE);

            foregroundImsPhoneCall.merge(peerImsPhoneCall, ImsPhoneCall.State.ACTIVE);



            // TODO Temporary code. Remove the try-catch block from the runnable once thread

            // synchronization is fixed.
@@ -1254,7 +1266,7 @@ public final class ImsPhoneCallTracker extends CallTracker { 
                // Reset the flag.

                call.resetIsMergeRequestedByConf(false);

            }



            logState();

        }



        @Override
@@ -1582,6 +1594,33 @@ public final class ImsPhoneCallTracker extends CallTracker { 
        Rlog.e(LOG_TAG, "[ImsPhoneCallTracker] " + msg);

    }



    /**

     * Logs the current state of the ImsPhoneCallTracker.  Useful for debugging issues with

     * call tracking.

     */

    /* package */

    void logState() {

        if (!VERBOSE_STATE_LOGGING) {

            return;

        }



        StringBuilder sb = new StringBuilder();

        sb.append("Current IMS PhoneCall State:\n");

        sb.append(" Foreground: ");

        sb.append(mForegroundCall);

        sb.append("\n");

        sb.append(" Background: ");

        sb.append(mBackgroundCall);

        sb.append("\n");

        sb.append(" Ringing: ");

        sb.append(mRingingCall);

        sb.append("\n");

        sb.append(" Handover: ");

        sb.append(mHandoverCall);

        sb.append("\n");

        Rlog.v(LOG_TAG, sb.toString());

    }



    @Override

    public void dump(FileDescriptor fd, PrintWriter pw, String[] args) {

        pw.println("ImsPhoneCallTracker extends:");

src/java/com/android/internal/telephony/imsphone/ImsPhoneConnection.java

+9 −0
Original line number Diff line number Diff line
@@ -575,6 +575,15 @@ public class ImsPhoneConnection extends Connection { 
     */

    /*package*/ boolean update(ImsCall imsCall, ImsPhoneCall.State state) {

        if (state == ImsPhoneCall.State.ACTIVE) {

            // If the state of the call is active, but there is a pending request to the RIL to hold

            // the call, we will skip this update.  This is really a signalling delay or failure

            // from the RIL, but we will prevent it from going through as we will end up erroneously

            // making this call active when really it should be on hold.

            if (imsCall.isPendingHold()) {

                Rlog.w(LOG_TAG, "update : state is ACTIVE, but call is pending hold, skipping");

                return false;

            }



            if (mParent.getState().isRinging() || mParent.getState().isDialing()) {

                onConnectedInOrOut();

            }