diff options
| -rw-r--r-- | telecomm/java/android/telecom/Log.java | 358 | ||||
| -rw-r--r-- | telecomm/java/android/telecom/Logging/EventManager.java | 365 | ||||
| -rw-r--r-- | telecomm/java/android/telecom/Logging/Session.java | 223 | ||||
| -rw-r--r-- | telecomm/java/android/telecom/Logging/SessionManager.java | 344 | ||||
| -rw-r--r-- | telecomm/java/android/telecom/Logging/TimedEvent.java | 50 |
5 files changed, 1261 insertions, 79 deletions
diff --git a/telecomm/java/android/telecom/Log.java b/telecomm/java/android/telecom/Log.java index a965342982f5..ecda3cd45f73 100644 --- a/telecomm/java/android/telecom/Log.java +++ b/telecomm/java/android/telecom/Log.java @@ -18,9 +18,15 @@ package android.telecom; import android.net.Uri; import android.os.AsyncTask; +import android.telecom.Logging.EventManager; +import android.telecom.Logging.Session; +import android.telecom.Logging.SessionManager; import android.telephony.PhoneNumberUtils; import android.text.TextUtils; +import com.android.internal.annotations.VisibleForTesting; +import com.android.internal.util.IndentingPrintWriter; + import java.security.MessageDigest; import java.security.NoSuchAlgorithmException; import java.util.IllegalFormatException; @@ -31,174 +37,364 @@ import java.util.Locale; * * @hide */ -final public class Log { +public class Log { + + private static final long EXTENDED_LOGGING_DURATION_MILLIS = 60000 * 30; // 30 minutes + + private static final int EVENTS_TO_CACHE = 10; + private static final int EVENTS_TO_CACHE_DEBUG = 20; - // Generic tag for all Telecom Framework logging - private static final String TAG = "TelecomFramework"; + // Generic tag for all Telecom logging + @VisibleForTesting + public static String TAG = "TelecomFramework"; - public static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */ + private static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */ public static final boolean DEBUG = isLoggable(android.util.Log.DEBUG); public static final boolean INFO = isLoggable(android.util.Log.INFO); public static final boolean VERBOSE = isLoggable(android.util.Log.VERBOSE); public static final boolean WARN = isLoggable(android.util.Log.WARN); public static final boolean ERROR = isLoggable(android.util.Log.ERROR); - private static MessageDigest sMessageDigest; - private static final Object sMessageDigestLock = new Object(); + // Used to synchronize singleton logging lazy initialization + private static final Object sSingletonSync = new Object(); + private static EventManager sEventManager; + private static SessionManager sSessionManager; - private Log() {} + /** + * Tracks whether user-activated extended logging is enabled. + */ + private static boolean sIsUserExtendedLoggingEnabled = false; - public static void initMd5Sum() { - new AsyncTask<Void, Void, Void>() { - @Override - public Void doInBackground(Void... args) { - MessageDigest md; - try { - md = MessageDigest.getInstance("SHA-1"); - } catch (NoSuchAlgorithmException e) { - md = null; - } - synchronized (sMessageDigestLock) { - sMessageDigest = md; - } - return null; - } - }.execute(); - } + /** + * The time when user-activated extended logging should be ended. Used to determine when + * extended logging should automatically be disabled. + */ + private static long sUserExtendedLoggingStopTime = 0; - public static boolean isLoggable(int level) { - return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level); + private Log() { } public static void d(String prefix, String format, Object... args) { - if (DEBUG) { - android.util.Log.d(TAG, buildMessage(prefix, format, args)); + if (sIsUserExtendedLoggingEnabled) { + maybeDisableLogging(); + android.util.Slog.i(TAG, buildMessage(prefix, format, args)); + } else if (DEBUG) { + android.util.Slog.d(TAG, buildMessage(prefix, format, args)); } } public static void d(Object objectPrefix, String format, Object... args) { - if (DEBUG) { - android.util.Log.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); + if (sIsUserExtendedLoggingEnabled) { + maybeDisableLogging(); + android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); + } else if (DEBUG) { + android.util.Slog.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void i(String prefix, String format, Object... args) { if (INFO) { - android.util.Log.i(TAG, buildMessage(prefix, format, args)); + android.util.Slog.i(TAG, buildMessage(prefix, format, args)); } } public static void i(Object objectPrefix, String format, Object... args) { if (INFO) { - android.util.Log.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); + android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void v(String prefix, String format, Object... args) { - if (VERBOSE) { - android.util.Log.v(TAG, buildMessage(prefix, format, args)); + if (sIsUserExtendedLoggingEnabled) { + maybeDisableLogging(); + android.util.Slog.i(TAG, buildMessage(prefix, format, args)); + } else if (VERBOSE) { + android.util.Slog.v(TAG, buildMessage(prefix, format, args)); } } public static void v(Object objectPrefix, String format, Object... args) { - if (VERBOSE) { - android.util.Log.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); + if (sIsUserExtendedLoggingEnabled) { + maybeDisableLogging(); + android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); + } else if (VERBOSE) { + android.util.Slog.v(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void w(String prefix, String format, Object... args) { if (WARN) { - android.util.Log.w(TAG, buildMessage(prefix, format, args)); + android.util.Slog.w(TAG, buildMessage(prefix, format, args)); } } public static void w(Object objectPrefix, String format, Object... args) { if (WARN) { - android.util.Log.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); + android.util.Slog.w(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args)); } } public static void e(String prefix, Throwable tr, String format, Object... args) { if (ERROR) { - android.util.Log.e(TAG, buildMessage(prefix, format, args), tr); + android.util.Slog.e(TAG, buildMessage(prefix, format, args), tr); } } public static void e(Object objectPrefix, Throwable tr, String format, Object... args) { if (ERROR) { - android.util.Log.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), + android.util.Slog.e(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), tr); } } public static void wtf(String prefix, Throwable tr, String format, Object... args) { - android.util.Log.wtf(TAG, buildMessage(prefix, format, args), tr); + android.util.Slog.wtf(TAG, buildMessage(prefix, format, args), tr); } public static void wtf(Object objectPrefix, Throwable tr, String format, Object... args) { - android.util.Log.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), + android.util.Slog.wtf(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args), tr); } public static void wtf(String prefix, String format, Object... args) { String msg = buildMessage(prefix, format, args); - android.util.Log.wtf(TAG, msg, new IllegalStateException(msg)); + android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg)); } public static void wtf(Object objectPrefix, String format, Object... args) { String msg = buildMessage(getPrefixFromObject(objectPrefix), format, args); - android.util.Log.wtf(TAG, msg, new IllegalStateException(msg)); + android.util.Slog.wtf(TAG, msg, new IllegalStateException(msg)); } /** - * Redact personally identifiable information for production users. - * If we are running in verbose mode, return the original string, otherwise - * return a SHA-1 hash of the input string. + * The ease of use methods below only act mostly as proxies to the Session and Event Loggers. + * They also control the lazy loaders of the singleton instances, which will never be loaded if + * the proxy methods aren't used. + * + * Please see each method's documentation inside of their respective implementations in the + * loggers. */ - public static String pii(Object pii) { + + public static void startSession(String shortMethodName) { + getSessionManager().startSession(shortMethodName, null); + } + + public static void startSession(String shortMethodName, String callerIdentification) { + getSessionManager().startSession(shortMethodName, callerIdentification); + } + + public static Session createSubsession() { + return getSessionManager().createSubsession(); + } + + public static void cancelSubsession(Session subsession) { + getSessionManager().cancelSubsession(subsession); + } + + public static void continueSession(Session subsession, String shortMethodName) { + getSessionManager().continueSession(subsession, shortMethodName); + } + + public static void endSession() { + getSessionManager().endSession(); + } + + public static String getSessionId() { + // If the Session logger has not been initialized, then there have been no sessions logged. + // Don't load it now! + synchronized (sSingletonSync) { + if (sSessionManager != null) { + return getSessionManager().getSessionId(); + } else { + return ""; + } + } + } + + public static void addEvent(EventManager.Loggable recordEntry, String event) { + getEventManager().event(recordEntry, event, null); + } + + public static void addEvent(EventManager.Loggable recordEntry, String event, Object data) { + getEventManager().event(recordEntry, event, data); + } + + public static void addEvent(EventManager.Loggable recordEntry, String event, String format, + Object... args) { + getEventManager().event(recordEntry, event, format, args); + } + + public static void registerEventListener(EventManager.EventListener e) { + getEventManager().registerEventListener(e); + } + + public static void addRequestResponsePair(EventManager.TimedEventPair p) { + getEventManager().addRequestResponsePair(p); + } + + public static void dumpEvents(IndentingPrintWriter pw) { + // If the Events logger has not been initialized, then there have been no events logged. + // Don't load it now! + synchronized (sSingletonSync) { + if (sEventManager != null) { + getEventManager().dumpEvents(pw); + } else { + pw.println("No Historical Events Logged."); + } + } + } + + /** + * Enable or disable extended telecom logging. + * + * @param isExtendedLoggingEnabled {@code true} if extended logging should be enabled, + * {@code false} if it should be disabled. + */ + public static void setIsExtendedLoggingEnabled(boolean isExtendedLoggingEnabled) { + // If the state hasn't changed, bail early. + if (sIsUserExtendedLoggingEnabled == isExtendedLoggingEnabled) { + return; + } + + if (sEventManager != null) { + sEventManager.changeEventCacheSize(isExtendedLoggingEnabled ? + EVENTS_TO_CACHE_DEBUG : EVENTS_TO_CACHE); + } + + sIsUserExtendedLoggingEnabled = isExtendedLoggingEnabled; + if (sIsUserExtendedLoggingEnabled) { + sUserExtendedLoggingStopTime = System.currentTimeMillis() + + EXTENDED_LOGGING_DURATION_MILLIS; + } else { + sUserExtendedLoggingStopTime = 0; + } + } + + private static EventManager getEventManager() { + // Checking for null again outside of synchronization because we only need to synchronize + // during the lazy loading of the events logger. We don't need to synchronize elsewhere. + if (sEventManager == null) { + synchronized (sSingletonSync) { + if (sEventManager == null) { + sEventManager = new EventManager(Log::getSessionId); + return sEventManager; + } + } + } + return sEventManager; + } + + private static SessionManager getSessionManager() { + // Checking for null again outside of synchronization because we only need to synchronize + // during the lazy loading of the session logger. We don't need to synchronize elsewhere. + if (sSessionManager == null) { + synchronized (sSingletonSync) { + if (sSessionManager == null) { + sSessionManager = new SessionManager(); + return sSessionManager; + } + } + } + return sSessionManager; + } + + private static MessageDigest sMessageDigest; + + static void initMd5Sum() { + new AsyncTask<Void, Void, Void>() { + @Override + public Void doInBackground(Void... args) { + MessageDigest md; + try { + md = MessageDigest.getInstance("SHA-1"); + } catch (NoSuchAlgorithmException e) { + md = null; + } + sMessageDigest = md; + return null; + } + }.execute(); + } + + public static void setTag(String tag) { + TAG = tag; + } + + /** + * If user enabled extended logging is enabled and the time limit has passed, disables the + * extended logging. + */ + private static void maybeDisableLogging() { + if (!sIsUserExtendedLoggingEnabled) { + return; + } + + if (sUserExtendedLoggingStopTime < System.currentTimeMillis()) { + sUserExtendedLoggingStopTime = 0; + sIsUserExtendedLoggingEnabled = false; + } + } + + public static boolean isLoggable(int level) { + return FORCE_LOGGING || android.util.Log.isLoggable(TAG, level); + } + + public static String piiHandle(Object pii) { if (pii == null || VERBOSE) { return String.valueOf(pii); - } if (pii instanceof Uri) { - return piiUri((Uri) pii); } - return "[" + secureHash(String.valueOf(pii).getBytes()) + "]"; - } - private static String piiUri(Uri handle) { StringBuilder sb = new StringBuilder(); - String scheme = handle.getScheme(); - if (!TextUtils.isEmpty(scheme)) { - sb.append(scheme).append(":"); - } - String value = handle.getSchemeSpecificPart(); - if (!TextUtils.isEmpty(value)) { - for (int i = 0; i < value.length(); i++) { - char c = value.charAt(i); - if (PhoneNumberUtils.isStartsPostDial(c)) { - sb.append(c); - } else if (PhoneNumberUtils.isDialable(c)) { - sb.append("*"); - } else if (('a' <= c && c <= 'z') || ('A' <= c && c <= 'Z')) { - sb.append("*"); - } else { + if (pii instanceof Uri) { + Uri uri = (Uri) pii; + String scheme = uri.getScheme(); + + if (!TextUtils.isEmpty(scheme)) { + sb.append(scheme).append(":"); + } + + String textToObfuscate = uri.getSchemeSpecificPart(); + if (PhoneAccount.SCHEME_TEL.equals(scheme)) { + for (int i = 0; i < textToObfuscate.length(); i++) { + char c = textToObfuscate.charAt(i); + sb.append(PhoneNumberUtils.isDialable(c) ? "*" : c); + } + } else if (PhoneAccount.SCHEME_SIP.equals(scheme)) { + for (int i = 0; i < textToObfuscate.length(); i++) { + char c = textToObfuscate.charAt(i); + if (c != '@' && c != '.') { + c = '*'; + } sb.append(c); } + } else { + sb.append(pii(pii)); } } + return sb.toString(); + } + /** + * Redact personally identifiable information for production users. + * If we are running in verbose mode, return the original string, otherwise + * return a SHA-1 hash of the input string. + */ + public static String pii(Object pii) { + if (pii == null || VERBOSE) { + return String.valueOf(pii); + } + return "[" + secureHash(String.valueOf(pii).getBytes()) + "]"; } private static String secureHash(byte[] input) { - synchronized (sMessageDigestLock) { - if (sMessageDigest != null) { - sMessageDigest.reset(); - sMessageDigest.update(input); - byte[] result = sMessageDigest.digest(); - return encodeHex(result); - } else { - return "Uninitialized SHA1"; - } + if (sMessageDigest != null) { + sMessageDigest.reset(); + sMessageDigest.update(input); + byte[] result = sMessageDigest.digest(); + return encodeHex(result); + } else { + return "Uninitialized SHA1"; } } @@ -221,15 +417,19 @@ final public class Log { } private static String buildMessage(String prefix, String format, Object... args) { + // Incorporate thread ID and calling method into prefix + String sessionName = getSessionId(); + String sessionPostfix = TextUtils.isEmpty(sessionName) ? "" : ": " + sessionName; + String msg; try { msg = (args == null || args.length == 0) ? format : String.format(Locale.US, format, args); } catch (IllegalFormatException ife) { - wtf("Log", ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, + e("Log", ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, args.length); msg = format + " (An error occurred while formatting the message.)"; } - return String.format(Locale.US, "%s: %s", prefix, msg); + return String.format(Locale.US, "%s: %s%s", prefix, msg, sessionPostfix); } } diff --git a/telecomm/java/android/telecom/Logging/EventManager.java b/telecomm/java/android/telecom/Logging/EventManager.java new file mode 100644 index 000000000000..8e7a393cb436 --- /dev/null +++ b/telecomm/java/android/telecom/Logging/EventManager.java @@ -0,0 +1,365 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License + */ + +package android.telecom.Logging; + +import android.annotation.NonNull; +import android.telecom.Log; +import android.text.TextUtils; + +import com.android.internal.util.IndentingPrintWriter; + +import java.text.DateFormat; +import java.text.SimpleDateFormat; +import java.util.ArrayList; +import java.util.Collections; +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 java.util.Map; +import java.util.concurrent.LinkedBlockingQueue; + +/** + * A utility class that provides the ability to define Events that a subsystem deems important, and + * then relate those events to other events so that information can be extracted. For example, a + * START and FINISH event can be defined and when a START and then FINISH occurs in a sequence, the + * time it took to complete that sequence can be saved to be retrieved later. + * @hide + */ + +public class EventManager { + + public static final String TAG = "Logging.Events"; + public static final int DEFAULT_EVENTS_TO_CACHE = 10; // Arbitrarily chosen. + + public interface Loggable { + /** + * @return a unique String ID that will allow the Event to be recognized later in the logs. + */ + String getId(); + + /** + * @return Formatted information about the state that will be printed out later in the logs. + */ + String getDescription(); + } + + private final Map<Loggable, EventRecord> mCallEventRecordMap = new HashMap<>(); + private LinkedBlockingQueue<EventRecord> mEventRecords = + new LinkedBlockingQueue<>(DEFAULT_EVENTS_TO_CACHE); + + private List<EventListener> mEventListeners = new ArrayList<>(); + + public interface EventListener { + /** + * Notifies the implementation of this method that a new event record has been added. + * @param eventRecord Reference to the recently added EventRecord + */ + void eventRecordAdded(EventRecord eventRecord); + } + + private SessionManager.ISessionIdQueryHandler mSessionIdHandler; + /** + * Maps from request events to a list of possible response events. Used to track + * end-to-end timing for critical user-facing operations in Telecom. + */ + public final Map<String, List<TimedEventPair>> requestResponsePairs = new HashMap<>(); + + private static final Object mSync = new Object(); + + /** + * Stores the various events. + * Also stores all request-response pairs amongst the events. + */ + public static class TimedEventPair { + private static final long DEFAULT_TIMEOUT = 3000L; + + String mRequest; + String mResponse; + String mName; + long mTimeoutMillis = DEFAULT_TIMEOUT; + + public TimedEventPair(String request, String response, String name) { + this.mRequest = request; + this.mResponse = response; + this.mName = name; + } + + public TimedEventPair(String request, String response, String name, long timeoutMillis) { + this.mRequest = request; + this.mResponse = response; + this.mName = name; + this.mTimeoutMillis = timeoutMillis; + } + } + + public void addRequestResponsePair(TimedEventPair p) { + if (requestResponsePairs.containsKey(p.mRequest)) { + requestResponsePairs.get(p.mRequest).add(p); + } else { + ArrayList<TimedEventPair> responses = new ArrayList<>(); + responses.add(p); + requestResponsePairs.put(p.mRequest, responses); + } + } + + public static class Event { + public String eventId; + public String sessionId; + public long time; + public Object data; + + public Event(String eventId, String sessionId, long time, Object data) { + this.eventId = eventId; + this.sessionId = sessionId; + this.time = time; + this.data = data; + } + } + + public class EventRecord { + public class EventTiming extends TimedEvent<String> { + public String name; + public long time; + + public EventTiming(String name, long time) { + this.name = name; + this.time = time; + } + + public String getKey() { + return name; + } + + public long getTime() { + return time; + } + } + + private class PendingResponse { + String requestEventId; + long requestEventTimeMillis; + long timeoutMillis; + String name; + + public PendingResponse(String requestEventId, long requestEventTimeMillis, + long timeoutMillis, String name) { + this.requestEventId = requestEventId; + this.requestEventTimeMillis = requestEventTimeMillis; + this.timeoutMillis = timeoutMillis; + this.name = name; + } + } + + private final DateFormat sDateFormat = new SimpleDateFormat("HH:mm:ss.SSS"); + private final List<Event> mEvents = new LinkedList<>(); + private final Loggable mRecordEntry; + + public EventRecord(Loggable recordEntry) { + mRecordEntry = recordEntry; + } + + public Loggable getRecordEntry() { + return mRecordEntry; + } + + public void addEvent(String event, String sessionId, Object data) { + mEvents.add(new Event(event, sessionId, System.currentTimeMillis(), data)); + Log.i("Event", "RecordEntry %s: %s, %s", mRecordEntry.getId(), event, data); + } + + public List<Event> getEvents() { + return mEvents; + } + + public List<EventTiming> extractEventTimings() { + if (mEvents == null) { + return Collections.emptyList(); + } + + LinkedList<EventTiming> result = new LinkedList<>(); + Map<String, PendingResponse> pendingResponses = new HashMap<>(); + for (Event event : mEvents) { + if (requestResponsePairs.containsKey(event.eventId)) { + // This event expects a response, so add that expected response to the maps + // of pending events. + for (EventManager.TimedEventPair p : requestResponsePairs.get(event.eventId)) { + pendingResponses.put(p.mResponse, new PendingResponse(event.eventId, + event.time, p.mTimeoutMillis, p.mName)); + } + } + + PendingResponse pendingResponse = pendingResponses.remove(event.eventId); + if (pendingResponse != null) { + long elapsedTime = event.time - pendingResponse.requestEventTimeMillis; + if (elapsedTime < pendingResponse.timeoutMillis) { + result.add(new EventTiming(pendingResponse.name, elapsedTime)); + } + } + } + + return result; + } + + public void dump(IndentingPrintWriter pw) { + pw.print(mRecordEntry.getDescription()); + + pw.increaseIndent(); + for (Event event : mEvents) { + pw.print(sDateFormat.format(new Date(event.time))); + pw.print(" - "); + pw.print(event.eventId); + if (event.data != null) { + pw.print(" ("); + Object data = event.data; + + if (data instanceof Loggable) { + // If the data is another Loggable, then change the data to the + // Entry's Event ID instead. + EventRecord record = mCallEventRecordMap.get(data); + if (record != null) { + data = "RecordEntry " + record.mRecordEntry.getId(); + } + } + + pw.print(data); + pw.print(")"); + } + if (!TextUtils.isEmpty(event.sessionId)) { + pw.print(":"); + pw.print(event.sessionId); + } + pw.println(); + } + + pw.println("Timings (average for this call, milliseconds):"); + pw.increaseIndent(); + Map<String, Double> avgEventTimings = EventTiming.averageTimings(extractEventTimings()); + List<String> eventNames = new ArrayList<>(avgEventTimings.keySet()); + Collections.sort(eventNames); + for (String eventName : eventNames) { + pw.printf("%s: %.2f\n", eventName, avgEventTimings.get(eventName)); + } + pw.decreaseIndent(); + pw.decreaseIndent(); + } + } + + public EventManager(@NonNull SessionManager.ISessionIdQueryHandler l) { + mSessionIdHandler = l; + } + + public void event(Loggable recordEntry, String event, Object data) { + String currentSessionID = mSessionIdHandler.getSessionId(); + + if (recordEntry == null) { + Log.i(TAG, "Non-call EVENT: %s, %s", event, data); + return; + } + synchronized (mEventRecords) { + if (!mCallEventRecordMap.containsKey(recordEntry)) { + EventRecord newRecord = new EventRecord(recordEntry); + addEventRecord(newRecord); + } + + EventRecord record = mCallEventRecordMap.get(recordEntry); + record.addEvent(event, currentSessionID, data); + } + } + + public void event(Loggable recordEntry, String event, String format, Object... args) { + String msg; + try { + msg = (args == null || args.length == 0) ? format + : String.format(Locale.US, format, args); + } catch (IllegalFormatException ife) { + Log.e("Log", ife, "IllegalFormatException: formatString='%s' numArgs=%d", format, + args.length); + msg = format + " (An error occurred while formatting the message.)"; + } + + event(recordEntry, event, msg); + } + + public void dumpEvents(IndentingPrintWriter pw) { + pw.println("Historical Events:"); + pw.increaseIndent(); + for (EventRecord eventRecord : mEventRecords) { + eventRecord.dump(pw); + } + pw.decreaseIndent(); + } + + public void changeEventCacheSize(int newSize) { + + // Resize the event queue. + LinkedBlockingQueue<EventRecord> oldEventLog = mEventRecords; + mEventRecords = new LinkedBlockingQueue<>(newSize); + mCallEventRecordMap.clear(); + + oldEventLog.forEach((newRecord -> { + Loggable recordEntry = newRecord.getRecordEntry(); + // Copy the existing queue into the new one. + // First remove the oldest entry if no new ones exist. + if (mEventRecords.remainingCapacity() == 0) { + EventRecord record = mEventRecords.poll(); + if (record != null) { + mCallEventRecordMap.remove(record.getRecordEntry()); + } + } + + // Now add a new entry + mEventRecords.add(newRecord); + mCallEventRecordMap.put(recordEntry, newRecord); + + // Don't worry about notifying mEventListeners, since we are just resizing the records. + })); + } + + public void registerEventListener(EventListener e) { + if (e != null) { + synchronized (mSync) { + mEventListeners.add(e); + } + } + } + + private void addEventRecord(EventRecord newRecord) { + Loggable recordEntry = newRecord.getRecordEntry(); + + // First remove the oldest entry if no new ones exist. + if (mEventRecords.remainingCapacity() == 0) { + EventRecord record = mEventRecords.poll(); + if (record != null) { + mCallEventRecordMap.remove(record.getRecordEntry()); + } + } + + // Now add a new entry + mEventRecords.add(newRecord); + mCallEventRecordMap.put(recordEntry, newRecord); + + // TODO: Add Implementation of this in Telecom for Analytics + synchronized (mSync) { + for (EventListener l : mEventListeners) { + l.eventRecordAdded(newRecord); + } + } + } +} diff --git a/telecomm/java/android/telecom/Logging/Session.java b/telecomm/java/android/telecom/Logging/Session.java new file mode 100644 index 000000000000..14f4a0f82f89 --- /dev/null +++ b/telecomm/java/android/telecom/Logging/Session.java @@ -0,0 +1,223 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License + */ + +package android.telecom.Logging; + +import android.annotation.NonNull; + +import java.util.ArrayList; + +/** + * The session that stores information about a thread's point of entry into the Telecom code that + * persists until the thread exits Telecom. + * @hide + */ +public class Session { + + public static final String START_SESSION = "START_SESSION"; + public static final String CREATE_SUBSESSION = "CREATE_SUBSESSION"; + public static final String CONTINUE_SUBSESSION = "CONTINUE_SUBSESSION"; + public static final String END_SUBSESSION = "END_SUBSESSION"; + public static final String END_SESSION = "END_SESSION"; + + public static final int UNDEFINED = -1; + + private String mSessionId; + private String mShortMethodName; + private long mExecutionStartTimeMs; + private long mExecutionEndTimeMs = UNDEFINED; + private Session mParentSession; + private ArrayList<Session> mChildSessions; + private boolean mIsCompleted = false; + private int mChildCounter = 0; + // True if this is a subsession that has been started from the same thread as the parent + // session. This can happen if Log.startSession(...) is called multiple times on the same + // thread in the case of one Telecom entry point method calling another entry point method. + // In this case, we can just make this subsession "invisible," but still keep track of it so + // that the Log.endSession() calls match up. + private boolean mIsStartedFromActiveSession = false; + // Optionally provided info about the method/class/component that started the session in order + // to make Logging easier. This info will be provided in parentheses along with the session. + private String mOwnerInfo; + + public Session(String sessionId, String shortMethodName, long startTimeMs, long threadID, + boolean isStartedFromActiveSession, String ownerInfo) { + setSessionId(sessionId); + setShortMethodName(shortMethodName); + mExecutionStartTimeMs = startTimeMs; + mParentSession = null; + mChildSessions = new ArrayList<>(5); + mIsStartedFromActiveSession = isStartedFromActiveSession; + mOwnerInfo = ownerInfo; + } + + public void setSessionId(@NonNull String sessionId) { + if (sessionId == null) { + mSessionId = "?"; + } + mSessionId = sessionId; + } + + public String getShortMethodName() { + return mShortMethodName; + } + + public void setShortMethodName(String shortMethodName) { + if (shortMethodName == null) { + shortMethodName = ""; + } + mShortMethodName = shortMethodName; + } + + public void setParentSession(Session parentSession) { + mParentSession = parentSession; + } + + public void addChild(Session childSession) { + if (childSession != null) { + mChildSessions.add(childSession); + } + } + + public void removeChild(Session child) { + if (child != null) { + mChildSessions.remove(child); + } + } + + public long getExecutionStartTimeMilliseconds() { + return mExecutionStartTimeMs; + } + + public void setExecutionStartTimeMs(long startTimeMs) { + mExecutionStartTimeMs = startTimeMs; + } + + public Session getParentSession() { + return mParentSession; + } + + public ArrayList<Session> getChildSessions() { + return mChildSessions; + } + + public boolean isSessionCompleted() { + return mIsCompleted; + } + + public boolean isStartedFromActiveSession() { + return mIsStartedFromActiveSession; + } + + // Mark this session complete. This will be deleted by Log when all subsessions are complete + // as well. + public void markSessionCompleted(long executionEndTimeMs) { + mExecutionEndTimeMs = executionEndTimeMs; + mIsCompleted = true; + } + + public long getLocalExecutionTime() { + if (mExecutionEndTimeMs == UNDEFINED) { + return UNDEFINED; + } + return mExecutionEndTimeMs - mExecutionStartTimeMs; + } + + public synchronized String getNextChildId() { + return String.valueOf(mChildCounter++); + } + + @Override + public boolean equals(Object obj) { + if (!(obj instanceof Session)) { + return false; + } + if (obj == this) { + return true; + } + Session otherSession = (Session) obj; + return (mSessionId.equals(otherSession.mSessionId)) && + (mShortMethodName.equals(otherSession.mShortMethodName)) && + mExecutionStartTimeMs == otherSession.mExecutionStartTimeMs && + mParentSession == otherSession.mParentSession && + mChildSessions.equals(otherSession.mChildSessions) && + mIsCompleted == otherSession.mIsCompleted && + mExecutionEndTimeMs == otherSession.mExecutionEndTimeMs && + mChildCounter == otherSession.mChildCounter && + mIsStartedFromActiveSession == otherSession.mIsStartedFromActiveSession && + mOwnerInfo == otherSession.mOwnerInfo; + } + + // Builds full session id recursively + private String getFullSessionId() { + // Cache mParentSession locally to prevent a concurrency problem where + // Log.endParentSessions() is called while a logging statement is running (Log.i, for + // example) and setting mParentSession to null in a different thread after the null check + // occurred. + Session parentSession = mParentSession; + if (parentSession == null) { + return mSessionId; + } else { + return parentSession.getFullSessionId() + "_" + mSessionId; + } + } + + // Print out the full Session tree from any subsession node + public String printFullSessionTree() { + // Get to the top of the tree + Session topNode = this; + while (topNode.getParentSession() != null) { + topNode = topNode.getParentSession(); + } + return topNode.printSessionTree(); + } + + // Recursively move down session tree using DFS, but print out each node when it is reached. + public String printSessionTree() { + StringBuilder sb = new StringBuilder(); + printSessionTree(0, sb); + return sb.toString(); + } + + private void printSessionTree(int tabI, StringBuilder sb) { + sb.append(toString()); + for (Session child : mChildSessions) { + sb.append("\n"); + for (int i = 0; i <= tabI; i++) { + sb.append("\t"); + } + child.printSessionTree(tabI + 1, sb); + } + } + + @Override + public String toString() { + if (mParentSession != null && mIsStartedFromActiveSession) { + // Log.startSession was called from within another active session. Use the parent's + // Id instead of the child to reduce confusion. + return mParentSession.toString(); + } else { + StringBuilder methodName = new StringBuilder(); + methodName.append(mShortMethodName); + if (mOwnerInfo != null && !mOwnerInfo.isEmpty()) { + methodName.append("(InCall package: "); + methodName.append(mOwnerInfo); + methodName.append(")"); + } + return methodName.toString() + "@" + getFullSessionId(); + } + } +} diff --git a/telecomm/java/android/telecom/Logging/SessionManager.java b/telecomm/java/android/telecom/Logging/SessionManager.java new file mode 100644 index 000000000000..a4e89778b59e --- /dev/null +++ b/telecomm/java/android/telecom/Logging/SessionManager.java @@ -0,0 +1,344 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License + */ + +package android.telecom.Logging; + +import android.content.Context; +import android.os.Handler; +import android.os.Looper; +import android.provider.Settings; +import android.util.Base64; + +import com.android.internal.annotations.VisibleForTesting; + +import java.nio.ByteBuffer; +import java.util.ArrayList; +import java.util.Arrays; +import java.util.Iterator; +import java.util.List; +import java.util.concurrent.ConcurrentHashMap; + +/** + * TODO: Create better Sessions Documentation + * @hide + */ + +public class SessionManager { + + // Currently using 3 letters, So don't exceed 64^3 + private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144; + + // This parameter can be overridden in Telecom's Timeouts class. + public static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds + + private static String LOGGING_TAG = "Logging"; + + private static final String TIMEOUTS_PREFIX = "telecom."; + + // Synchronized in all method calls + private int sCodeEntryCounter = 0; + private Context mContext; + + @VisibleForTesting + public ConcurrentHashMap<Integer, Session> sSessionMapper = new ConcurrentHashMap<>(100); + @VisibleForTesting + public Handler sSessionCleanupHandler = new Handler(Looper.getMainLooper()); + @VisibleForTesting + public java.lang.Runnable sCleanStaleSessions = () -> + cleanupStaleSessions(getSessionCleanupTimeoutMs()); + + // Overridden in LogTest to skip query to ContentProvider + private interface ISessionCleanupTimeoutMs { + long get(); + } + + @VisibleForTesting + public ISessionCleanupTimeoutMs sSessionCleanupTimeoutMs = () -> { + // mContext may be null in some cases, such as testing. For these cases, use the + // default value. + if (mContext == null) { + return DEFAULT_SESSION_TIMEOUT_MS; + } + return getCleanupTimeout(mContext); + }; + + // Usage is synchronized on this class. + private List<ISessionListener> mSessionListeners = new ArrayList<>(); + + public interface ISessionListener { + /** + * This method is run when a full Session has completed. + * @param sessionName The name of the Session that has completed. + * @param timeMs The time it took to complete in ms. + */ + void sessionComplete(String sessionName, long timeMs); + } + + public interface ISessionIdQueryHandler { + String getSessionId(); + } + + public void setContext(Context context) { + mContext = context; + } + + public SessionManager() { + } + + private long getSessionCleanupTimeoutMs() { + return sSessionCleanupTimeoutMs.get(); + } + + private synchronized void resetStaleSessionTimer() { + sSessionCleanupHandler.removeCallbacksAndMessages(null); + // Will be null in Log Testing + if (sCleanStaleSessions != null) { + sSessionCleanupHandler.postDelayed(sCleanStaleSessions, getSessionCleanupTimeoutMs()); + } + } + + /** + * Call at an entry point to the Telecom code to track the session. This code must be + * accompanied by a Log.endSession(). + */ + public synchronized void startSession(String shortMethodName, + String callerIdentification) { + resetStaleSessionTimer(); + int threadId = getCallingThreadId(); + Session activeSession = sSessionMapper.get(threadId); + // We have called startSession within an active session that has not ended... Register this + // session as a subsession. + if (activeSession != null) { + Session childSession = createSubsession(true); + continueSession(childSession, shortMethodName); + return; + } + Session newSession = new Session(getNextSessionID(), shortMethodName, + System.currentTimeMillis(), threadId, false, callerIdentification); + sSessionMapper.put(threadId, newSession); + + android.telecom.Log.v(LOGGING_TAG, Session.START_SESSION); + } + + + /** + * Notifies the logging system that a subsession will be run at a later point and + * allocates the resources. Returns a session object that must be used in + * Log.continueSession(...) to start the subsession. + */ + public Session createSubsession() { + return createSubsession(false); + } + + private synchronized Session createSubsession(boolean isStartedFromActiveSession) { + int threadId = getCallingThreadId(); + Session threadSession = sSessionMapper.get(threadId); + if (threadSession == null) { + android.telecom.Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " + + "active."); + return null; + } + // Start execution time of the session will be overwritten in continueSession(...). + Session newSubsession = new Session(threadSession.getNextChildId(), + threadSession.getShortMethodName(), System.currentTimeMillis(), threadId, + isStartedFromActiveSession, null); + threadSession.addChild(newSubsession); + newSubsession.setParentSession(threadSession); + + if (!isStartedFromActiveSession) { + android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " + + newSubsession.toString()); + } else { + android.telecom.Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + + " (Invisible subsession)"); + } + return newSubsession; + } + + /** + * Cancels a subsession that had Log.createSubsession() called on it, but will never have + * Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned + * gracefully instead of being removed by the sSessionCleanupHandler forcefully later. + */ + public synchronized void cancelSubsession(Session subsession) { + if (subsession == null) { + return; + } + + subsession.markSessionCompleted(0); + endParentSessions(subsession); + } + + /** + * Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method + * must be called at the end of this method. The full session will complete when all + * subsessions are completed. + */ + public synchronized void continueSession(Session subsession, String shortMethodName) { + if (subsession == null) { + return; + } + resetStaleSessionTimer(); + String callingMethodName = subsession.getShortMethodName(); + subsession.setShortMethodName(callingMethodName + "->" + shortMethodName); + subsession.setExecutionStartTimeMs(System.currentTimeMillis()); + Session parentSession = subsession.getParentSession(); + if (parentSession == null) { + android.telecom.Log.d(LOGGING_TAG, "Log.continueSession was called with no session " + + "active for method %s.", shortMethodName); + return; + } + + sSessionMapper.put(getCallingThreadId(), subsession); + if (!subsession.isStartedFromActiveSession()) { + android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION); + } else { + android.telecom.Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION + + " (Invisible Subsession) with Method " + shortMethodName); + } + } + + /** + * Ends the current session/subsession. Must be called after a Log.startSession(...) and + * Log.continueSession(...) call. + */ + public synchronized void endSession() { + int threadId = getCallingThreadId(); + Session completedSession = sSessionMapper.get(threadId); + if (completedSession == null) { + android.telecom.Log.w(LOGGING_TAG, "Log.endSession was called with no session active."); + return; + } + + completedSession.markSessionCompleted(System.currentTimeMillis()); + if (!completedSession.isStartedFromActiveSession()) { + android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " + + completedSession.getLocalExecutionTime() + " mS)"); + } else { + android.telecom.Log.v(LOGGING_TAG, Session.END_SUBSESSION + + " (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() + + " ms)"); + } + // Remove after completed so that reference still exists for logging the end events + Session parentSession = completedSession.getParentSession(); + sSessionMapper.remove(threadId); + endParentSessions(completedSession); + // If this subsession was started from a parent session using Log.startSession, return the + // ThreadID back to the parent after completion. + if (parentSession != null && !parentSession.isSessionCompleted() && + completedSession.isStartedFromActiveSession()) { + sSessionMapper.put(threadId, parentSession); + } + } + + // Recursively deletes all complete parent sessions of the current subsession if it is a leaf. + private void endParentSessions(Session subsession) { + // Session is not completed or not currently a leaf, so we can not remove because a child is + // still running + if (!subsession.isSessionCompleted() || subsession.getChildSessions().size() != 0) { + return; + } + + Session parentSession = subsession.getParentSession(); + if (parentSession != null) { + subsession.setParentSession(null); + parentSession.removeChild(subsession); + endParentSessions(parentSession); + } else { + // All of the subsessions have been completed and it is time to report on the full + // running time of the session. + long fullSessionTimeMs = + System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds(); + android.telecom.Log.v(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs + + " ms): " + subsession.toString()); + // TODO: Add analytics hook + for (ISessionListener l : mSessionListeners) { + l.sessionComplete(subsession.getShortMethodName(), fullSessionTimeMs); + } + } + } + + public String getSessionId() { + Session currentSession = sSessionMapper.get(getCallingThreadId()); + return currentSession != null ? currentSession.toString() : ""; + } + + public synchronized void registerSessionListener(ISessionListener l) { + if (l != null) { + mSessionListeners.add(l); + } + } + + private synchronized String getNextSessionID() { + Integer nextId = sCodeEntryCounter++; + if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) { + restartSessionCounter(); + nextId = sCodeEntryCounter++; + } + return getBase64Encoding(nextId); + } + + @VisibleForTesting + public synchronized void restartSessionCounter() { + sCodeEntryCounter = 0; + } + + @VisibleForTesting + public String getBase64Encoding(int number) { + byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array(); + idByteArray = Arrays.copyOfRange(idByteArray, 2, 4); + return Base64.encodeToString(idByteArray, Base64.NO_WRAP | Base64.NO_PADDING); + } + + public int getCallingThreadId() { + return android.os.Process.myTid(); + } + + @VisibleForTesting + private synchronized void cleanupStaleSessions(long timeoutMs) { + String logMessage = "Stale Sessions Cleaned:\n"; + boolean isSessionsStale = false; + long currentTimeMs = System.currentTimeMillis(); + // Remove references that are in the Session Mapper (causing GC to occur) on + // sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS. + // If this occurs, then there is most likely a Session active that never had + // Log.endSession called on it. + for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it = + sSessionMapper.entrySet().iterator(); it.hasNext(); ) { + ConcurrentHashMap.Entry<Integer, Session> entry = it.next(); + Session session = entry.getValue(); + if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) { + it.remove(); + logMessage += session.printFullSessionTree() + "\n"; + isSessionsStale = true; + } + } + if (isSessionsStale) { + android.telecom.Log.w(LOGGING_TAG, logMessage); + } else { + android.telecom.Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned..."); + } + } + + /** + * Returns the amount of time after a Logging session has been started that Telecom is set to + * perform a sweep to check and make sure that the session is still not incomplete (stale). + */ + private long getCleanupTimeout(Context context) { + return Settings.Secure.getLong(context.getContentResolver(), TIMEOUTS_PREFIX + + "stale_session_cleanup_timeout_millis", DEFAULT_SESSION_TIMEOUT_MS); + } +} diff --git a/telecomm/java/android/telecom/Logging/TimedEvent.java b/telecomm/java/android/telecom/Logging/TimedEvent.java new file mode 100644 index 000000000000..6785e92de6d8 --- /dev/null +++ b/telecomm/java/android/telecom/Logging/TimedEvent.java @@ -0,0 +1,50 @@ +/* + * Copyright (C) 2016 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License + */ + +package android.telecom.Logging; + +import java.util.Collection; +import java.util.HashMap; +import java.util.Map; + +/** + * @hide + */ +public abstract class TimedEvent<T> { + public abstract long getTime(); + public abstract T getKey(); + + public static <T> Map<T, Double> averageTimings(Collection<? extends TimedEvent<T>> events) { + HashMap<T, Integer> counts = new HashMap<>(); + HashMap<T, Double> result = new HashMap<>(); + + for (TimedEvent<T> entry : events) { + if (counts.containsKey(entry.getKey())) { + counts.put(entry.getKey(), counts.get(entry.getKey()) + 1); + result.put(entry.getKey(), result.get(entry.getKey()) + entry.getTime()); + } else { + counts.put(entry.getKey(), 1); + result.put(entry.getKey(), (double) entry.getTime()); + } + } + + for (Map.Entry<T, Double> entry : result.entrySet()) { + result.put(entry.getKey(), entry.getValue() / counts.get(entry.getKey())); + } + + return result; + } +} |