Android/frameworks_base
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge "Transplant the Logging system from Telecom"

Browse Source 
am: cbb03d1ad3

Change-Id: I216ed7c9ab32a8a21fc58ec1ee3972d5f881084a
This commit is contained in:
Brad Ebinger
2016-10-11 22:30:31 +00:00
committed by android-build-merger
parent eedd2b529d cbb03d1ad3
commit 951dca8209
5 changed files with 1305 additions and 123 deletions
Download Patch File Download Diff File Expand all files Collapse all files

446
telecomm/java/android/telecom/Log.java
View File

@@ -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,24 +37,270 @@ import java.util.Locale;
*
* @hide
*/
final public class Log {
public class Log {
// Generic tag for all Telecom Framework logging
private static final String TAG = "TelecomFramework";
private static final long EXTENDED_LOGGING_DURATION_MILLIS = 60000 * 30; // 30 minutes
public static final boolean FORCE_LOGGING = false; /* STOP SHIP if true */
private static final int EVENTS_TO_CACHE = 10;
private static final int EVENTS_TO_CACHE_DEBUG = 20;
// Generic tag for all Telecom logging
@VisibleForTesting
public static String TAG = "TelecomFramework";
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);
// Used to synchronize singleton logging lazy initialization
private static final Object sSingletonSync = new Object();
private static EventManager sEventManager;
private static SessionManager sSessionManager;
/**
* Tracks whether user-activated extended logging is enabled.
*/
private static boolean sIsUserExtendedLoggingEnabled = false;
/**
* 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;
private Log() {
}
public static void d(String prefix, String format, Object... 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 (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.Slog.i(TAG, buildMessage(prefix, format, args));
}
}
public static void i(Object objectPrefix, String format, Object... args) {
if (INFO) {
android.util.Slog.i(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
}
}
public static void v(String prefix, String format, Object... 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 (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.Slog.w(TAG, buildMessage(prefix, format, args));
}
}
public static void w(Object objectPrefix, String format, Object... args) {
if (WARN) {
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.Slog.e(TAG, buildMessage(prefix, format, args), tr);
}
}
public static void e(Object objectPrefix, Throwable tr, String format, Object... args) {
if (ERROR) {
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.Slog.wtf(TAG, buildMessage(prefix, format, args), tr);
}
public static void wtf(Object objectPrefix, Throwable tr, String format, Object... 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.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.Slog.wtf(TAG, msg, new IllegalStateException(msg));
}
/**
* 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 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;
private static final Object sMessageDigestLock = new Object();
private Log() {}
public static void initMd5Sum() {
static void initMd5Sum() {
new AsyncTask<Void, Void, Void>() {
@Override
public Void doInBackground(Void... args) {
@@ -58,96 +310,69 @@ final public class Log {
} catch (NoSuchAlgorithmException e) {
md = null;
}
synchronized (sMessageDigestLock) {
sMessageDigest = md;
}
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 void d(String prefix, String format, Object... args) {
if (DEBUG) {
android.util.Log.d(TAG, buildMessage(prefix, format, args));
public static String piiHandle(Object pii) {
if (pii == null || VERBOSE) {
return String.valueOf(pii);
}
}
public static void d(Object objectPrefix, String format, Object... args) {
if (DEBUG) {
android.util.Log.d(TAG, buildMessage(getPrefixFromObject(objectPrefix), format, args));
StringBuilder sb = new StringBuilder();
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));
}
}
}
public static void i(String prefix, String format, Object... args) {
if (INFO) {
android.util.Log.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));
}
}
public static void v(String prefix, String format, Object... args) {
if (VERBOSE) {
android.util.Log.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));
}
}
public static void w(String prefix, String format, Object... args) {
if (WARN) {
android.util.Log.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));
}
}
public static void e(String prefix, Throwable tr, String format, Object... args) {
if (ERROR) {
android.util.Log.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),
tr);
}
}
public static void wtf(String prefix, Throwable tr, String format, Object... args) {
android.util.Log.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),
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));
}
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));
return sb.toString();
}
/**
@@ -158,47 +383,18 @@ final public class Log {
public static String pii(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 {
sb.append(c);
}
}
}
return sb.toString();
}
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);
}
}

365
telecomm/java/android/telecom/Logging/EventManager.java Normal file
View File

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

223
telecomm/java/android/telecom/Logging/Session.java Normal file
View File

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

344
telecomm/java/android/telecom/Logging/SessionManager.java Normal file
View File

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

50
telecomm/java/android/telecom/Logging/TimedEvent.java Normal file
View File

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