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