Add call event logging to telecom.
This code saves the last 5 calls and prints out all the call-related
events when doing a "dumpsys telecom". This includes dumping all
information about the last 5 calls so that bug reports always contain
information about the calls.
Bug: 18923652
Change-Id: I4dbdea32ba4eea3b3a4158fbae99649dc045cd62
diff --git a/src/com/android/server/telecom/Call.java b/src/com/android/server/telecom/Call.java
index 7edda41..8a13e01 100644
--- a/src/com/android/server/telecom/Call.java
+++ b/src/com/android/server/telecom/Call.java
@@ -367,6 +367,8 @@
mIsIncoming = isIncoming;
mIsConference = isConference;
maybeLoadCannedSmsResponses();
+
+ Log.event(this, Log.Events.CREATED);
}
/**
@@ -416,6 +418,10 @@
}
}
+ public void destroy() {
+ Log.event(this, Log.Events.DESTROYED);
+ }
+
/** {@inheritDoc} */
@Override
public String toString() {
@@ -526,6 +532,38 @@
setLocallyDisconnecting(false);
fixParentAfterDisconnect();
}
+
+ // Log the state transition event
+ String event = 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;
+ break;
+ case CallState.DISCONNECTING:
+ event = Log.Events.SET_DISCONNECTING;
+ break;
+ case CallState.ON_HOLD:
+ event = Log.Events.SET_HOLD;
+ break;
+ case CallState.PRE_DIAL_WAIT:
+ event = Log.Events.SET_PRE_DIAL_WAIT;
+ break;
+ case CallState.RINGING:
+ event = Log.Events.SET_RINGING;
+ break;
+ }
+ if (event != null) {
+ Log.event(this, event);
+ }
}
}
@@ -907,6 +945,7 @@
} else {
Log.i(this, "Send playDtmfTone to connection service for call %s", this);
mConnectionService.playDtmfTone(this, digit);
+ Log.event(this, Log.Events.START_DTMF, Log.pii(digit));
}
}
@@ -918,6 +957,7 @@
Log.w(this, "stopDtmfTone() request on a call without a connection service.");
} else {
Log.i(this, "Send stopDtmfTone to connection service for call %s", this);
+ Log.event(this, Log.Events.STOP_DTMF);
mConnectionService.stopDtmfTone(this);
}
}
@@ -930,6 +970,8 @@
* Attempts to disconnect the call through the connection service.
*/
void disconnect(boolean wasViaNewOutgoingCallBroadcaster) {
+ Log.event(this, Log.Events.REQUEST_DISCONNECT);
+
// Track that the call is now locally disconnecting.
setLocallyDisconnecting(true);
@@ -999,6 +1041,7 @@
// that the call is in a non-STATE_RINGING state before changing the UI. See
// {@link ConnectionServiceAdapter#setActive} and other set* methods.
mConnectionService.answer(this, videoState);
+ Log.event(this, Log.Events.REQUEST_ACCEPT);
}
}
@@ -1015,6 +1058,7 @@
// between the time the user hits 'reject' and Telecomm receives the command.
if (isRinging("reject")) {
mConnectionService.reject(this);
+ Log.event(this, Log.Events.REQUEST_REJECT);
}
}
@@ -1026,6 +1070,7 @@
if (mState == CallState.ACTIVE) {
mConnectionService.hold(this);
+ Log.event(this, Log.Events.REQUEST_HOLD);
}
}
@@ -1037,6 +1082,7 @@
if (mState == CallState.ON_HOLD) {
mConnectionService.unhold(this);
+ Log.event(this, Log.Events.REQUEST_UNHOLD);
}
}
diff --git a/src/com/android/server/telecom/CallsManager.java b/src/com/android/server/telecom/CallsManager.java
index 0d57c8a..cc1143a 100644
--- a/src/com/android/server/telecom/CallsManager.java
+++ b/src/com/android/server/telecom/CallsManager.java
@@ -1200,6 +1200,8 @@
shouldNotify = true;
}
+ call.destroy();
+
// Only broadcast changes for calls that are being tracked.
if (shouldNotify) {
for (CallsManagerListener listener : mListeners) {
diff --git a/src/com/android/server/telecom/Log.java b/src/com/android/server/telecom/Log.java
index b9ad73d..43dd181 100644
--- a/src/com/android/server/telecom/Log.java
+++ b/src/com/android/server/telecom/Log.java
@@ -20,12 +20,21 @@
import android.telecom.PhoneAccount;
import android.telephony.PhoneNumberUtils;
+import com.android.internal.annotations.VisibleForTesting;
+import com.android.internal.util.IndentingPrintWriter;
+
import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;
+import java.text.DateFormat;
+import java.text.SimpleDateFormat;
+import java.util.Date;
+import java.util.HashMap;
import java.util.IllegalFormatException;
+import java.util.LinkedList;
+import java.util.List;
import java.util.Locale;
-
-import com.android.internal.annotations.VisibleForTesting;
+import java.util.Map;
+import java.util.concurrent.LinkedBlockingQueue;
/**
* Manages logging for the entire module.
@@ -33,6 +42,130 @@
@VisibleForTesting
public class Log {
+ /**
+ * Stores the various events associated with {@link Call}s. Also stores all request-response
+ * pairs amongst the events.
+ */
+ public final static class Events {
+ public static final String CREATED = "CREATED";
+ public static final String DESTROYED = "DESTROYED";
+ public static final String SET_NEW = "SET_NEW";
+ public static final String SET_CONNECTING = "SET_CONNECTING";
+ public static final String SET_DIALING = "SET_DIALING";
+ public static final String SET_ACTIVE = "SET_ACTIVE";
+ public static final String SET_HOLD = "SET_HOLD";
+ public static final String SET_RINGING = "SET_RINGING";
+ public static final String SET_DISCONNECTED = "SET_DISCONNECTED";
+ public static final String SET_DISCONNECTING = "SET_DISCONNECTING";
+ public static final String SET_PRE_DIAL_WAIT = "SET_PRE_DIAL_WAIT";
+ public static final String REQUEST_HOLD = "REQUEST_HOLD";
+ public static final String REQUEST_UNHOLD = "REQUEST_UNHOLD";
+ public static final String REQUEST_DISCONNECT = "REQUEST_DISCONNECT";
+ public static final String REQUEST_ACCEPT = "REQUEST_ACCEPT";
+ public static final String REQUEST_REJECT = "REQUEST_REJECT";
+ public static final String START_DTMF = "START_DTMF";
+ public static final String STOP_DTMF = "STOP_DTMF";
+
+ /**
+ * Maps from a request to a response. The same event could be listed as the
+ * response for multiple requests (e.g. REQUEST_ACCEPT and REQUEST_UNHOLD both map to the
+ * SET_ACTIVE response). This map is used to print out the amount of time it takes between
+ * a request and a response.
+ */
+ public static final Map<String, String> requestResponsePairs =
+ new HashMap<String, String>() {{
+ put(REQUEST_ACCEPT, SET_ACTIVE);
+ put(REQUEST_REJECT, SET_DISCONNECTED);
+ put(REQUEST_DISCONNECT, SET_DISCONNECTED);
+ put(REQUEST_HOLD, SET_HOLD);
+ put(REQUEST_UNHOLD, SET_ACTIVE);
+ }};
+ }
+
+ public static class CallEvent {
+ public String eventId;
+ public long time;
+ public Object data;
+
+ public CallEvent(String eventId, long time, Object data) {
+ this.eventId = eventId;
+ this.time = time;
+ this.data = data;
+ }
+ }
+
+ public static class CallEventRecord {
+ private static final DateFormat sDateFormat = new SimpleDateFormat("HH:mm:ss.SSS");
+ private static int sNextId = 1;
+ private final List<CallEvent> mEvents = new LinkedList<>();
+ private final Call mCall;
+ private final int mId;
+
+ public CallEventRecord(Call call) {
+ mCall = call;
+ mId = ++sNextId;
+ }
+
+ public Call getCall() {
+ return mCall;
+ }
+
+ public void addEvent(String event, Object data) {
+ mEvents.add(new CallEvent(event, System.currentTimeMillis(), data));
+ Log.i("Event", "Call %d: %s, %s", mId, event, data);
+ }
+
+ public void dump(IndentingPrintWriter pw) {
+ Map<String, CallEvent> pendingResponses = new HashMap<>();
+
+ pw.print("Call [");
+ pw.print(sDateFormat.format(new Date(mCall.getCreationTimeMillis())));
+ pw.print("]");
+ pw.println(mCall.isIncoming() ? "(MT - incoming)" : "(MO - outgoing)");
+
+ pw.increaseIndent();
+ for (CallEvent event : mEvents) {
+
+ // We print out events in chronological order. During that process we look at each
+ // event and see if it maps to a request on the Request-Response pairs map. If it
+ // does, then we effectively start 'listening' for the response. We do that by
+ // storing the response event ID in {@code pendingResponses}. When we find the
+ // response in a later iteration of the loop, we grab the original request and
+ // calculate the time it took to get a response.
+ if (Events.requestResponsePairs.containsKey(event.eventId)) {
+ // This event expects a response, so add that response to the maps
+ // of pending events.
+ String pendingResponse = Events.requestResponsePairs.get(event.eventId);
+ pendingResponses.put(pendingResponse, event);
+ }
+
+ pw.print(sDateFormat.format(new Date(event.time)));
+ pw.print(" - ");
+ pw.print(event.eventId);
+ if (event.data != null) {
+ pw.print("(");
+ pw.print(event.data);
+ pw.print(")");
+ }
+
+ // If this event is a response event that we've been waiting for, calculate the time
+ // it took for the response to complete and print that out as well.
+ CallEvent requestEvent = pendingResponses.remove(event.eventId);
+ if (requestEvent != null) {
+ pw.print(", time since ");
+ pw.print(requestEvent.eventId);
+ pw.print(": ");
+ pw.print(event.time - requestEvent.time);
+ pw.print(" ms");
+ }
+ pw.println();
+ }
+ pw.decreaseIndent();
+ }
+ }
+
+ public static final int MAX_CALLS_TO_CACHE = 5; // Arbitrarily chosen.
+
// Generic tag for all In Call logging
@VisibleForTesting
public static String TAG = "Telecom";
@@ -45,6 +178,10 @@
public static final boolean WARN = isLoggable(android.util.Log.WARN);
public static final boolean ERROR = isLoggable(android.util.Log.ERROR);
+ private static final Map<Call, CallEventRecord> mCallEventRecordMap = new HashMap<>();
+ private static final LinkedBlockingQueue<CallEventRecord> mCallEventRecords =
+ new LinkedBlockingQueue<CallEventRecord>(MAX_CALLS_TO_CACHE);
+
private Log() {}
@VisibleForTesting
@@ -52,6 +189,32 @@
TAG = tag;
}
+ public static void event(Call call, String event) {
+ event(call, event, null);
+ }
+
+ public static void event(Call call, String event, Object data) {
+ synchronized (mCallEventRecords) {
+ if (!mCallEventRecordMap.containsKey(call)) {
+ // First remove the oldest entry if no new ones exist.
+ if (mCallEventRecords.remainingCapacity() == 0) {
+ CallEventRecord record = mCallEventRecords.poll();
+ if (record != null) {
+ mCallEventRecordMap.remove(record.getCall());
+ }
+ }
+
+ // Now add a new entry
+ CallEventRecord newRecord = new CallEventRecord(call);
+ mCallEventRecords.add(newRecord);
+ mCallEventRecordMap.put(call, newRecord);
+ }
+
+ CallEventRecord record = mCallEventRecordMap.get(call);
+ record.addEvent(event, data);
+ }
+ }
+
public static boolean isLoggable(int level) {
return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level);
}
@@ -176,6 +339,15 @@
return "[" + secureHash(String.valueOf(pii).getBytes()) + "]";
}
+ public static void dumpCallEvents(IndentingPrintWriter pw) {
+ pw.println("Historical Calls:");
+ pw.increaseIndent();
+ for (CallEventRecord callEventRecord : mCallEventRecords) {
+ callEventRecord.dump(pw);
+ }
+ pw.decreaseIndent();
+ }
+
private static String secureHash(byte[] input) {
MessageDigest messageDigest;
try {
diff --git a/src/com/android/server/telecom/TelecomServiceImpl.java b/src/com/android/server/telecom/TelecomServiceImpl.java
index 10aa782..7775a0c 100644
--- a/src/com/android/server/telecom/TelecomServiceImpl.java
+++ b/src/com/android/server/telecom/TelecomServiceImpl.java
@@ -692,6 +692,8 @@
mPhoneAccountRegistrar.dump(pw);
pw.decreaseIndent();
}
+
+ Log.dumpCallEvents(pw);
}
};