Add more logging.
1) Call state logging was lost in a merge conflict, adding that back.
2) Adding better ringing state logging. Fixes problems:
- No more superfluous "STOP_RINGER" logging
- Adding call-waiting logging
- More accurate call attribution for start and stop ringing
Change-Id: Ie41340ab6790a6c5f87f5592836b29bf6799708d
diff --git a/src/com/android/server/telecom/Call.java b/src/com/android/server/telecom/Call.java
index da9da22..cf123e7 100644
--- a/src/com/android/server/telecom/Call.java
+++ b/src/com/android/server/telecom/Call.java
@@ -505,7 +505,7 @@
* misbehave and they do this very often. The result is that we do not enforce state transitions
* and instead keep the code resilient to unexpected state changes.
*/
- public void setState(int newState) {
+ public void setState(int newState, String tag) {
if (mState != newState) {
Log.v(this, "setState %s -> %s", mState, newState);
@@ -544,6 +544,46 @@
// Ensure when an incoming call is missed that the video state history is updated.
mVideoStateHistory |= mVideoState;
}
+
+ // Log the state transition event
+ String event = null;
+ Object data = null;
+ switch (newState) {
+ case CallState.ACTIVE:
+ event = Log.Events.SET_ACTIVE;
+ break;
+ case CallState.CONNECTING:
+ event = Log.Events.SET_CONNECTING;
+ break;
+ case CallState.DIALING:
+ event = Log.Events.SET_DIALING;
+ break;
+ case CallState.DISCONNECTED:
+ event = Log.Events.SET_DISCONNECTED;
+ data = getDisconnectCause();
+ break;
+ case CallState.DISCONNECTING:
+ event = Log.Events.SET_DISCONNECTING;
+ break;
+ case CallState.ON_HOLD:
+ event = Log.Events.SET_HOLD;
+ break;
+ case CallState.SELECT_PHONE_ACCOUNT:
+ event = Log.Events.SET_SELECT_PHONE_ACCOUNT;
+ break;
+ case CallState.RINGING:
+ event = Log.Events.SET_RINGING;
+ break;
+ }
+ if (event != null) {
+ // The string data should be just the tag.
+ String stringData = tag;
+ if (data != null) {
+ // If data exists, add it to tag. If no tag, just use data.toString().
+ stringData = stringData == null ? data.toString() : stringData + "> " + data;
+ }
+ Log.event(this, event, stringData);
+ }
}
}
@@ -821,7 +861,7 @@
Log.i(this, "Directing call to voicemail: %s.", this);
// TODO: Once we move State handling from CallsManager to Call, we
// will not need to set STATE_RINGING state prior to calling reject.
- setState(CallState.RINGING);
+ setState(CallState.RINGING, "directing to voicemail");
reject(false, null);
} else {
// TODO: Make this class (not CallsManager) responsible for changing
diff --git a/src/com/android/server/telecom/CallsManager.java b/src/com/android/server/telecom/CallsManager.java
index 7283648..636f721 100644
--- a/src/com/android/server/telecom/CallsManager.java
+++ b/src/com/android/server/telecom/CallsManager.java
@@ -215,7 +215,7 @@
public void onSuccessfulOutgoingCall(Call call, int callState) {
Log.v(this, "onSuccessfulOutgoingCall, %s", call);
- setCallState(call, callState);
+ setCallState(call, callState, "successful outgoing call");
if (!mCalls.contains(call)) {
// Call was not added previously in startOutgoingCall due to it being a potential MMI
// code, so add it now.
@@ -240,7 +240,7 @@
@Override
public void onSuccessfulIncomingCall(Call incomingCall) {
Log.d(this, "onSuccessfulIncomingCall");
- setCallState(incomingCall, CallState.RINGING);
+ setCallState(incomingCall, CallState.RINGING, "successful incoming call");
if (hasMaximumRingingCalls()) {
incomingCall.reject(false, null);
@@ -255,13 +255,13 @@
@Override
public void onFailedIncomingCall(Call call) {
- setCallState(call, CallState.DISCONNECTED);
+ setCallState(call, CallState.DISCONNECTED, "failed incoming call");
call.removeListener(this);
}
@Override
public void onSuccessfulUnknownCall(Call call, int callState) {
- setCallState(call, callState);
+ setCallState(call, callState, "successful unknown call");
Log.i(this, "onSuccessfulUnknownCall for call %s", call);
addCall(call);
}
@@ -269,7 +269,7 @@
@Override
public void onFailedUnknownCall(Call call) {
Log.i(this, "onFailedUnknownCall for call %s", call);
- setCallState(call, CallState.DISCONNECTED);
+ setCallState(call, CallState.DISCONNECTED, "failed unknown call");
call.removeListener(this);
}
@@ -579,12 +579,12 @@
if (needsAccountSelection) {
// This is the state where the user is expected to select an account
- call.setState(CallState.SELECT_PHONE_ACCOUNT);
+ call.setState(CallState.SELECT_PHONE_ACCOUNT, "needs account selection");
// Create our own instance to modify (since extras may be Bundle.EMPTY)
extras = new Bundle(extras);
extras.putParcelableList(android.telecom.Call.AVAILABLE_PHONE_ACCOUNTS, accounts);
} else {
- call.setState(CallState.CONNECTING);
+ call.setState(CallState.CONNECTING, phoneAccountHandle.toString());
}
call.setIntentExtras(extras);
@@ -903,21 +903,21 @@
}
void markCallAsRinging(Call call) {
- setCallState(call, CallState.RINGING);
+ setCallState(call, CallState.RINGING, "ringing set explicitly");
}
void markCallAsDialing(Call call) {
- setCallState(call, CallState.DIALING);
+ setCallState(call, CallState.DIALING, "dialing set explicitly");
maybeMoveToSpeakerPhone(call);
}
void markCallAsActive(Call call) {
- setCallState(call, CallState.ACTIVE);
+ setCallState(call, CallState.ACTIVE, "active set explicitly");
maybeMoveToSpeakerPhone(call);
}
void markCallAsOnHold(Call call) {
- setCallState(call, CallState.ON_HOLD);
+ setCallState(call, CallState.ON_HOLD, "on-hold set explicitly");
}
/**
@@ -928,7 +928,7 @@
*/
void markCallAsDisconnected(Call call, DisconnectCause disconnectCause) {
call.setDisconnectCause(disconnectCause);
- setCallState(call, CallState.DISCONNECTED);
+ setCallState(call, CallState.DISCONNECTED, "disconnected set explicitly");
}
/**
@@ -1117,7 +1117,8 @@
true /* isConference */,
connectTime);
- setCallState(call, Call.getStateFromConnectionState(parcelableConference.getState()));
+ setCallState(call, Call.getStateFromConnectionState(parcelableConference.getState()),
+ "new conference call");
call.setConnectionCapabilities(parcelableConference.getConnectionCapabilities());
call.setVideoState(parcelableConference.getVideoState());
call.setVideoProvider(parcelableConference.getVideoProvider());
@@ -1218,7 +1219,7 @@
* @param call The call.
* @param newState The new state of the call.
*/
- private void setCallState(Call call, int newState) {
+ private void setCallState(Call call, int newState, String tag) {
if (call == null) {
return;
}
@@ -1233,7 +1234,7 @@
// into a well-defined state machine.
// TODO: Define expected state transitions here, and log when an
// unexpected transition occurs.
- call.setState(newState);
+ call.setState(newState, tag);
Trace.beginSection("onCallStateChanged");
// Only broadcast state change for calls that are being tracked.
@@ -1486,7 +1487,8 @@
false /* isIncoming */,
false /* isConference */);
- setCallState(call, Call.getStateFromConnectionState(connection.getState()));
+ setCallState(call, Call.getStateFromConnectionState(connection.getState()),
+ "existing connection");
call.setConnectionCapabilities(connection.getConnectionCapabilities());
call.setCallerDisplayName(connection.getCallerDisplayName(),
connection.getCallerDisplayNamePresentation());
diff --git a/src/com/android/server/telecom/Log.java b/src/com/android/server/telecom/Log.java
index c10f8ce..b9bb780 100644
--- a/src/com/android/server/telecom/Log.java
+++ b/src/com/android/server/telecom/Log.java
@@ -68,6 +68,8 @@
public static final String STOP_DTMF = "STOP_DTMF";
public static final String START_RINGER = "START_RINGER";
public static final String STOP_RINGER = "STOP_RINGER";
+ public static final String START_CALL_WAITING_TONE = "START_CALL_WAITING_TONE";
+ public static final String STOP_CALL_WAITING_TONE = "STOP_CALL_WAITING_TONE";
/**
* Maps from a request to a response. The same event could be listed as the
diff --git a/src/com/android/server/telecom/PhoneAccountRegistrar.java b/src/com/android/server/telecom/PhoneAccountRegistrar.java
index 83f1207..f511c89 100644
--- a/src/com/android/server/telecom/PhoneAccountRegistrar.java
+++ b/src/com/android/server/telecom/PhoneAccountRegistrar.java
@@ -529,6 +529,9 @@
if (oldAccount != null) {
mState.accounts.remove(oldAccount);
isEnabled = oldAccount.isEnabled();
+ Log.i(this, getAccountDiffString(account, oldAccount));
+ } else {
+ Log.i(this, "New phone account registered: " + account);
}
mState.accounts.add(account);
@@ -610,6 +613,39 @@
}
}
+ private String getAccountDiffString(PhoneAccount account1, PhoneAccount account2) {
+ if (account1 == null || account2 == null) {
+ return "Diff: " + account1 + ", " + account2;
+ }
+
+ StringBuffer sb = new StringBuffer();
+ sb.append("[").append(account1.getAccountHandle());
+ appendDiff(sb, "addr", account1.getAddress(), account2.getAddress());
+ appendDiff(sb, "cap", account1.getCapabilities(), account2.getCapabilities());
+ appendDiff(sb, "hl", account1.getHighlightColor(), account2.getHighlightColor());
+ appendDiff(sb, "icon", account1.getIcon(), account2.getIcon());
+ appendDiff(sb, "lbl", account1.getLabel(), account2.getLabel());
+ appendDiff(sb, "desc", account1.getShortDescription(), account2.getShortDescription());
+ appendDiff(sb, "subAddr", account1.getSubscriptionAddress(),
+ account2.getSubscriptionAddress());
+ appendDiff(sb, "uris", account1.getSupportedUriSchemes(),
+ account2.getSupportedUriSchemes());
+ sb.append("]");
+ return sb.toString();
+ }
+
+ private void appendDiff(StringBuffer sb, String attrName, Object obj1, Object obj2) {
+ if (!Objects.equals(obj1, obj2)) {
+ sb.append("(")
+ .append(attrName)
+ .append(": ")
+ .append(obj1)
+ .append(" -> ")
+ .append(obj2)
+ .append(")");
+ }
+ }
+
/**
* Determines if the connection service specified by a {@link PhoneAccountHandle} requires the
* {@link Manifest.permission#BIND_TELECOM_CONNECTION_SERVICE} permission.
diff --git a/src/com/android/server/telecom/Ringer.java b/src/com/android/server/telecom/Ringer.java
index eef8494..dcdd21c 100644
--- a/src/com/android/server/telecom/Ringer.java
+++ b/src/com/android/server/telecom/Ringer.java
@@ -32,6 +32,7 @@
/**
* Controls the ringtone player.
+ * TODO: Turn this into a proper state machine: Ringing, CallWaiting, Stopped.
*/
final class Ringer extends CallsManagerListenerBase {
private static final long[] VIBRATION_PATTERN = new long[] {
@@ -40,6 +41,10 @@
1000, // How long to wait before vibrating again
};
+ private static final int STATE_RINGING = 1;
+ private static final int STATE_CALL_WAITING = 2;
+ private static final int STATE_STOPPED = 3;
+
private static final AudioAttributes VIBRATION_ATTRIBUTES = new AudioAttributes.Builder()
.setContentType(AudioAttributes.CONTENT_TYPE_SONIFICATION)
.setUsage(AudioAttributes.USAGE_NOTIFICATION_RINGTONE)
@@ -62,6 +67,7 @@
private final Context mContext;
private final Vibrator mVibrator;
+ private int mState = STATE_STOPPED;
private InCallTonePlayer mCallWaitingPlayer;
/**
@@ -93,7 +99,7 @@
Log.wtf(this, "New ringing call is already in list of unanswered calls");
}
mRingingCalls.add(call);
- updateRinging();
+ updateRinging(call);
}
}
@@ -121,9 +127,14 @@
@Override
public void onForegroundCallChanged(Call oldForegroundCall, Call newForegroundCall) {
- if (mRingingCalls.contains(oldForegroundCall) ||
- mRingingCalls.contains(newForegroundCall)) {
- updateRinging();
+ Call ringingCall = null;
+ if (mRingingCalls.contains(newForegroundCall)) {
+ ringingCall = newForegroundCall;
+ } else if (mRingingCalls.contains(oldForegroundCall)) {
+ ringingCall = oldForegroundCall;
+ }
+ if (ringingCall != null) {
+ updateRinging(ringingCall);
}
}
@@ -153,25 +164,25 @@
*/
private void removeFromUnansweredCall(Call call) {
mRingingCalls.remove(call);
- updateRinging();
+ updateRinging(call);
}
- private void updateRinging() {
+ private void updateRinging(Call call) {
if (mRingingCalls.isEmpty()) {
- stopRinging("No more ringing calls found");
- stopCallWaiting();
+ stopRinging(call, "No more ringing calls found");
+ stopCallWaiting(call);
} else {
- startRingingOrCallWaiting();
+ startRingingOrCallWaiting(call);
}
}
- private void startRingingOrCallWaiting() {
+ private void startRingingOrCallWaiting(Call call) {
Call foregroundCall = mCallsManager.getForegroundCall();
Log.v(this, "startRingingOrCallWaiting, foregroundCall: %s.", foregroundCall);
if (mRingingCalls.contains(foregroundCall)) {
// The foreground call is one of incoming calls so play the ringer out loud.
- stopCallWaiting();
+ stopCallWaiting(call);
if (!shouldRingForContact(foregroundCall.getContactUri())) {
return;
@@ -180,7 +191,10 @@
AudioManager audioManager =
(AudioManager) mContext.getSystemService(Context.AUDIO_SERVICE);
if (audioManager.getStreamVolume(AudioManager.STREAM_RING) > 0) {
- Log.event(foregroundCall, Log.Events.START_RINGER);
+ if (mState != STATE_RINGING) {
+ Log.event(call, Log.Events.START_RINGER);
+ mState = STATE_RINGING;
+ }
mCallAudioManager.setIsRinging(true);
// Because we wait until a contact info query to complete before processing a
@@ -205,7 +219,13 @@
Log.v(this, "Playing call-waiting tone.");
// All incoming calls are in background so play call waiting.
- stopRinging("Stop for call-waiting");
+ stopRinging(call, "Stop for call-waiting");
+
+
+ if (mState != STATE_CALL_WAITING) {
+ Log.event(call, Log.Events.START_CALL_WAITING_TONE);
+ mState = STATE_CALL_WAITING;
+ }
if (mCallWaitingPlayer == null) {
mCallWaitingPlayer =
@@ -225,8 +245,11 @@
return manager.matchesCallFilter(extras);
}
- private void stopRinging(String reasonTag) {
- Log.event(mCallsManager.getForegroundCall(), Log.Events.STOP_RINGER, reasonTag);
+ private void stopRinging(Call call, String reasonTag) {
+ if (mState == STATE_RINGING) {
+ Log.event(call, Log.Events.STOP_RINGER, reasonTag);
+ mState = STATE_STOPPED;
+ }
mRingtonePlayer.stop();
@@ -240,12 +263,17 @@
mCallAudioManager.setIsRinging(false);
}
- private void stopCallWaiting() {
+ private void stopCallWaiting(Call call) {
Log.v(this, "stop call waiting.");
if (mCallWaitingPlayer != null) {
mCallWaitingPlayer.stopTone();
mCallWaitingPlayer = null;
}
+
+ if (mState == STATE_CALL_WAITING) {
+ Log.event(call, Log.Events.STOP_CALL_WAITING_TONE);
+ mState = STATE_STOPPED;
+ }
}
private boolean shouldVibrate(Context context) {
diff --git a/src/com/android/server/telecom/ui/MissedCallNotifierImpl.java b/src/com/android/server/telecom/ui/MissedCallNotifierImpl.java
index 36dd892..99621d9 100644
--- a/src/com/android/server/telecom/ui/MissedCallNotifierImpl.java
+++ b/src/com/android/server/telecom/ui/MissedCallNotifierImpl.java
@@ -349,7 +349,7 @@
null, null, null, null, true, false);
call.setDisconnectCause(
new DisconnectCause(DisconnectCause.MISSED));
- call.setState(CallState.DISCONNECTED);
+ call.setState(CallState.DISCONNECTED, "throw away call");
call.setCreationTimeMillis(date);
// Listen for the update to the caller information before posting