Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 1 | /* |
| 2 | * Copyright (C) 2016 The Android Open Source Project |
| 3 | * |
| 4 | * Licensed under the Apache License, Version 2.0 (the "License"); |
| 5 | * you may not use this file except in compliance with the License. |
| 6 | * You may obtain a copy of the License at |
| 7 | * |
| 8 | * http://www.apache.org/licenses/LICENSE-2.0 |
| 9 | * |
| 10 | * Unless required by applicable law or agreed to in writing, software |
| 11 | * distributed under the License is distributed on an "AS IS" BASIS, |
| 12 | * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| 13 | * See the License for the specific language governing permissions and |
| 14 | * limitations under the License |
| 15 | */ |
| 16 | |
| 17 | package android.telecom.Logging; |
| 18 | |
| 19 | import android.content.Context; |
| 20 | import android.os.Handler; |
| 21 | import android.os.Looper; |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 22 | import android.os.Process; |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 23 | import android.provider.Settings; |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 24 | import android.telecom.Log; |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 25 | import android.util.Base64; |
| 26 | |
| 27 | import com.android.internal.annotations.VisibleForTesting; |
| 28 | |
| 29 | import java.nio.ByteBuffer; |
| 30 | import java.util.ArrayList; |
| 31 | import java.util.Arrays; |
| 32 | import java.util.Iterator; |
| 33 | import java.util.List; |
| 34 | import java.util.concurrent.ConcurrentHashMap; |
| 35 | |
| 36 | /** |
| 37 | * TODO: Create better Sessions Documentation |
| 38 | * @hide |
| 39 | */ |
| 40 | |
| 41 | public class SessionManager { |
| 42 | |
| 43 | // Currently using 3 letters, So don't exceed 64^3 |
| 44 | private static final long SESSION_ID_ROLLOVER_THRESHOLD = 262144; |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 45 | // This parameter can be overridden in Telecom's Timeouts class. |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 46 | private static final long DEFAULT_SESSION_TIMEOUT_MS = 30000L; // 30 seconds |
| 47 | private static final String LOGGING_TAG = "Logging"; |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 48 | private static final String TIMEOUTS_PREFIX = "telecom."; |
| 49 | |
| 50 | // Synchronized in all method calls |
| 51 | private int sCodeEntryCounter = 0; |
| 52 | private Context mContext; |
| 53 | |
| 54 | @VisibleForTesting |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 55 | public ConcurrentHashMap<Integer, Session> mSessionMapper = new ConcurrentHashMap<>(100); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 56 | @VisibleForTesting |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 57 | public java.lang.Runnable mCleanStaleSessions = () -> |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 58 | cleanupStaleSessions(getSessionCleanupTimeoutMs()); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 59 | private Handler mSessionCleanupHandler = new Handler(Looper.getMainLooper()); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 60 | |
| 61 | // Overridden in LogTest to skip query to ContentProvider |
| 62 | private interface ISessionCleanupTimeoutMs { |
| 63 | long get(); |
| 64 | } |
| 65 | |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 66 | // Overridden in tests to provide test Thread IDs |
| 67 | public interface ICurrentThreadId { |
| 68 | int get(); |
| 69 | } |
| 70 | |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 71 | @VisibleForTesting |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 72 | public ICurrentThreadId mCurrentThreadId = Process::myTid; |
| 73 | |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 74 | private ISessionCleanupTimeoutMs mSessionCleanupTimeoutMs = () -> { |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 75 | // mContext may be null in some cases, such as testing. For these cases, use the |
| 76 | // default value. |
| 77 | if (mContext == null) { |
| 78 | return DEFAULT_SESSION_TIMEOUT_MS; |
| 79 | } |
| 80 | return getCleanupTimeout(mContext); |
| 81 | }; |
| 82 | |
| 83 | // Usage is synchronized on this class. |
| 84 | private List<ISessionListener> mSessionListeners = new ArrayList<>(); |
| 85 | |
| 86 | public interface ISessionListener { |
| 87 | /** |
| 88 | * This method is run when a full Session has completed. |
| 89 | * @param sessionName The name of the Session that has completed. |
| 90 | * @param timeMs The time it took to complete in ms. |
| 91 | */ |
| 92 | void sessionComplete(String sessionName, long timeMs); |
| 93 | } |
| 94 | |
| 95 | public interface ISessionIdQueryHandler { |
| 96 | String getSessionId(); |
| 97 | } |
| 98 | |
| 99 | public void setContext(Context context) { |
| 100 | mContext = context; |
| 101 | } |
| 102 | |
| 103 | public SessionManager() { |
| 104 | } |
| 105 | |
| 106 | private long getSessionCleanupTimeoutMs() { |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 107 | return mSessionCleanupTimeoutMs.get(); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 108 | } |
| 109 | |
| 110 | private synchronized void resetStaleSessionTimer() { |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 111 | mSessionCleanupHandler.removeCallbacksAndMessages(null); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 112 | // Will be null in Log Testing |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 113 | if (mCleanStaleSessions != null) { |
| 114 | mSessionCleanupHandler.postDelayed(mCleanStaleSessions, getSessionCleanupTimeoutMs()); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 115 | } |
| 116 | } |
| 117 | |
| 118 | /** |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 119 | * Determines whether or not to start a new session or continue an existing session based on |
| 120 | * the {@link Session.Info} info passed into startSession. If info is null, a new Session is |
| 121 | * created. This code must be accompanied by endSession() at the end of the Session. |
| 122 | */ |
| 123 | public synchronized void startSession(Session.Info info, String shortMethodName, |
| 124 | String callerIdentification) { |
| 125 | // Start a new session normally if the |
| 126 | if(info == null) { |
| 127 | startSession(shortMethodName, callerIdentification); |
| 128 | } else { |
| 129 | startExternalSession(info, shortMethodName); |
| 130 | } |
| 131 | } |
| 132 | |
| 133 | /** |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 134 | * Call at an entry point to the Telecom code to track the session. This code must be |
| 135 | * accompanied by a Log.endSession(). |
| 136 | */ |
| 137 | public synchronized void startSession(String shortMethodName, |
| 138 | String callerIdentification) { |
| 139 | resetStaleSessionTimer(); |
| 140 | int threadId = getCallingThreadId(); |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 141 | Session activeSession = mSessionMapper.get(threadId); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 142 | // We have called startSession within an active session that has not ended... Register this |
| 143 | // session as a subsession. |
| 144 | if (activeSession != null) { |
| 145 | Session childSession = createSubsession(true); |
| 146 | continueSession(childSession, shortMethodName); |
| 147 | return; |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 148 | } else { |
| 149 | // Only Log that we are starting the parent session. |
| 150 | Log.d(LOGGING_TAG, Session.START_SESSION); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 151 | } |
| 152 | Session newSession = new Session(getNextSessionID(), shortMethodName, |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 153 | System.currentTimeMillis(), false, callerIdentification); |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 154 | mSessionMapper.put(threadId, newSession); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 155 | } |
| 156 | |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 157 | /** |
| 158 | * Registers an external Session with the Manager using that external Session's sessionInfo. |
| 159 | * Log.endSession will still need to be called at the end of the session. |
| 160 | * @param sessionInfo Describes the external Session's information. |
| 161 | * @param shortMethodName The method name of the new session that is being started. |
| 162 | */ |
| 163 | public synchronized void startExternalSession(Session.Info sessionInfo, |
| 164 | String shortMethodName) { |
| 165 | if(sessionInfo == null) { |
| 166 | return; |
| 167 | } |
| 168 | |
| 169 | int threadId = getCallingThreadId(); |
| 170 | Session threadSession = mSessionMapper.get(threadId); |
| 171 | if (threadSession != null) { |
| 172 | // We should never get into a situation where there is already an active session AND |
| 173 | // an external session is added. We are just using that active session. |
| 174 | Log.w(LOGGING_TAG, "trying to start an external session with a session " + |
| 175 | "already active."); |
| 176 | return; |
| 177 | } |
| 178 | |
| 179 | // Create Session from Info and add to the sessionMapper under this ID. |
Brad Ebinger | 0c3541b | 2016-11-01 14:11:38 -0700 | [diff] [blame] | 180 | Log.d(LOGGING_TAG, Session.START_EXTERNAL_SESSION); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 181 | Session externalSession = new Session(Session.EXTERNAL_INDICATOR + sessionInfo.sessionId, |
Brad Ebinger | 0c3541b | 2016-11-01 14:11:38 -0700 | [diff] [blame] | 182 | sessionInfo.methodPath, System.currentTimeMillis(), |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 183 | false /*isStartedFromActiveSession*/, null); |
| 184 | externalSession.setIsExternal(true); |
| 185 | // Mark the external session as already completed, since we have no way of knowing when |
| 186 | // the external session actually has completed. |
| 187 | externalSession.markSessionCompleted(Session.UNDEFINED); |
| 188 | // Track the external session with the SessionMapper so that we can create and continue |
| 189 | // an active subsession based on it. |
| 190 | mSessionMapper.put(threadId, externalSession); |
| 191 | // Create a subsession from this external Session parent node |
| 192 | Session childSession = createSubsession(); |
| 193 | continueSession(childSession, shortMethodName); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 194 | } |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 195 | |
| 196 | /** |
| 197 | * Notifies the logging system that a subsession will be run at a later point and |
| 198 | * allocates the resources. Returns a session object that must be used in |
| 199 | * Log.continueSession(...) to start the subsession. |
| 200 | */ |
| 201 | public Session createSubsession() { |
| 202 | return createSubsession(false); |
| 203 | } |
| 204 | |
| 205 | private synchronized Session createSubsession(boolean isStartedFromActiveSession) { |
| 206 | int threadId = getCallingThreadId(); |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 207 | Session threadSession = mSessionMapper.get(threadId); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 208 | if (threadSession == null) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 209 | Log.d(LOGGING_TAG, "Log.createSubsession was called with no session " + |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 210 | "active."); |
| 211 | return null; |
| 212 | } |
| 213 | // Start execution time of the session will be overwritten in continueSession(...). |
| 214 | Session newSubsession = new Session(threadSession.getNextChildId(), |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 215 | threadSession.getShortMethodName(), System.currentTimeMillis(), |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 216 | isStartedFromActiveSession, null); |
| 217 | threadSession.addChild(newSubsession); |
| 218 | newSubsession.setParentSession(threadSession); |
| 219 | |
| 220 | if (!isStartedFromActiveSession) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 221 | Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + " " + |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 222 | newSubsession.toString()); |
| 223 | } else { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 224 | Log.v(LOGGING_TAG, Session.CREATE_SUBSESSION + |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 225 | " (Invisible subsession)"); |
| 226 | } |
| 227 | return newSubsession; |
| 228 | } |
| 229 | |
| 230 | /** |
Brad Ebinger | 3445f82 | 2016-10-24 16:40:49 -0700 | [diff] [blame] | 231 | * Retrieve the information of the currently active Session. This information is parcelable and |
| 232 | * is used to create an external Session ({@link #startExternalSession(Session.Info, String)}). |
| 233 | * If there is no Session active, this method will return null. |
| 234 | */ |
| 235 | public synchronized Session.Info getExternalSession() { |
| 236 | int threadId = getCallingThreadId(); |
| 237 | Session threadSession = mSessionMapper.get(threadId); |
| 238 | if (threadSession == null) { |
| 239 | Log.d(LOGGING_TAG, "Log.getExternalSession was called with no session " + |
| 240 | "active."); |
| 241 | return null; |
| 242 | } |
| 243 | |
| 244 | return threadSession.getInfo(); |
| 245 | } |
| 246 | |
| 247 | /** |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 248 | * Cancels a subsession that had Log.createSubsession() called on it, but will never have |
| 249 | * Log.continueSession(...) called on it due to an error. Allows the subsession to be cleaned |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 250 | * gracefully instead of being removed by the mSessionCleanupHandler forcefully later. |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 251 | */ |
| 252 | public synchronized void cancelSubsession(Session subsession) { |
| 253 | if (subsession == null) { |
| 254 | return; |
| 255 | } |
| 256 | |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 257 | subsession.markSessionCompleted(Session.UNDEFINED); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 258 | endParentSessions(subsession); |
| 259 | } |
| 260 | |
| 261 | /** |
| 262 | * Starts the subsession that was created in Log.CreateSubsession. The Log.endSession() method |
| 263 | * must be called at the end of this method. The full session will complete when all |
| 264 | * subsessions are completed. |
| 265 | */ |
| 266 | public synchronized void continueSession(Session subsession, String shortMethodName) { |
| 267 | if (subsession == null) { |
| 268 | return; |
| 269 | } |
| 270 | resetStaleSessionTimer(); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 271 | subsession.setShortMethodName(shortMethodName); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 272 | subsession.setExecutionStartTimeMs(System.currentTimeMillis()); |
| 273 | Session parentSession = subsession.getParentSession(); |
| 274 | if (parentSession == null) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 275 | Log.i(LOGGING_TAG, "Log.continueSession was called with no session " + |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 276 | "active for method " + shortMethodName); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 277 | return; |
| 278 | } |
| 279 | |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 280 | mSessionMapper.put(getCallingThreadId(), subsession); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 281 | if (!subsession.isStartedFromActiveSession()) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 282 | Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 283 | } else { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 284 | Log.v(LOGGING_TAG, Session.CONTINUE_SUBSESSION + |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 285 | " (Invisible Subsession) with Method " + shortMethodName); |
| 286 | } |
| 287 | } |
| 288 | |
| 289 | /** |
| 290 | * Ends the current session/subsession. Must be called after a Log.startSession(...) and |
| 291 | * Log.continueSession(...) call. |
| 292 | */ |
| 293 | public synchronized void endSession() { |
| 294 | int threadId = getCallingThreadId(); |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 295 | Session completedSession = mSessionMapper.get(threadId); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 296 | if (completedSession == null) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 297 | Log.w(LOGGING_TAG, "Log.endSession was called with no session active."); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 298 | return; |
| 299 | } |
| 300 | |
| 301 | completedSession.markSessionCompleted(System.currentTimeMillis()); |
| 302 | if (!completedSession.isStartedFromActiveSession()) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 303 | Log.v(LOGGING_TAG, Session.END_SUBSESSION + " (dur: " + |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 304 | completedSession.getLocalExecutionTime() + " mS)"); |
| 305 | } else { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 306 | Log.v(LOGGING_TAG, Session.END_SUBSESSION + |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 307 | " (Invisible Subsession) (dur: " + completedSession.getLocalExecutionTime() + |
| 308 | " ms)"); |
| 309 | } |
| 310 | // Remove after completed so that reference still exists for logging the end events |
| 311 | Session parentSession = completedSession.getParentSession(); |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 312 | mSessionMapper.remove(threadId); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 313 | endParentSessions(completedSession); |
| 314 | // If this subsession was started from a parent session using Log.startSession, return the |
| 315 | // ThreadID back to the parent after completion. |
| 316 | if (parentSession != null && !parentSession.isSessionCompleted() && |
| 317 | completedSession.isStartedFromActiveSession()) { |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 318 | mSessionMapper.put(threadId, parentSession); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 319 | } |
| 320 | } |
| 321 | |
| 322 | // Recursively deletes all complete parent sessions of the current subsession if it is a leaf. |
| 323 | private void endParentSessions(Session subsession) { |
| 324 | // Session is not completed or not currently a leaf, so we can not remove because a child is |
| 325 | // still running |
| 326 | if (!subsession.isSessionCompleted() || subsession.getChildSessions().size() != 0) { |
| 327 | return; |
| 328 | } |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 329 | Session parentSession = subsession.getParentSession(); |
| 330 | if (parentSession != null) { |
| 331 | subsession.setParentSession(null); |
| 332 | parentSession.removeChild(subsession); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 333 | // Report the child session of the external session as being complete to the listeners, |
| 334 | // not the external session itself. |
| 335 | if (parentSession.isExternal()) { |
| 336 | long fullSessionTimeMs = |
| 337 | System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds(); |
| 338 | notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs); |
| 339 | } |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 340 | endParentSessions(parentSession); |
| 341 | } else { |
| 342 | // All of the subsessions have been completed and it is time to report on the full |
| 343 | // running time of the session. |
| 344 | long fullSessionTimeMs = |
| 345 | System.currentTimeMillis() - subsession.getExecutionStartTimeMilliseconds(); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 346 | Log.d(LOGGING_TAG, Session.END_SESSION + " (dur: " + fullSessionTimeMs |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 347 | + " ms): " + subsession.toString()); |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 348 | if (!subsession.isExternal()) { |
| 349 | notifySessionCompleteListeners(subsession.getShortMethodName(), fullSessionTimeMs); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 350 | } |
| 351 | } |
| 352 | } |
| 353 | |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 354 | private void notifySessionCompleteListeners(String methodName, long sessionTimeMs) { |
| 355 | for (ISessionListener l : mSessionListeners) { |
| 356 | l.sessionComplete(methodName, sessionTimeMs); |
| 357 | } |
| 358 | } |
| 359 | |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 360 | public String getSessionId() { |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 361 | Session currentSession = mSessionMapper.get(getCallingThreadId()); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 362 | return currentSession != null ? currentSession.toString() : ""; |
| 363 | } |
| 364 | |
| 365 | public synchronized void registerSessionListener(ISessionListener l) { |
| 366 | if (l != null) { |
| 367 | mSessionListeners.add(l); |
| 368 | } |
| 369 | } |
| 370 | |
| 371 | private synchronized String getNextSessionID() { |
| 372 | Integer nextId = sCodeEntryCounter++; |
| 373 | if (nextId >= SESSION_ID_ROLLOVER_THRESHOLD) { |
| 374 | restartSessionCounter(); |
| 375 | nextId = sCodeEntryCounter++; |
| 376 | } |
| 377 | return getBase64Encoding(nextId); |
| 378 | } |
| 379 | |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 380 | private synchronized void restartSessionCounter() { |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 381 | sCodeEntryCounter = 0; |
| 382 | } |
| 383 | |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 384 | private String getBase64Encoding(int number) { |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 385 | byte[] idByteArray = ByteBuffer.allocate(4).putInt(number).array(); |
| 386 | idByteArray = Arrays.copyOfRange(idByteArray, 2, 4); |
| 387 | return Base64.encodeToString(idByteArray, Base64.NO_WRAP | Base64.NO_PADDING); |
| 388 | } |
| 389 | |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 390 | private int getCallingThreadId() { |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 391 | return mCurrentThreadId.get(); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 392 | } |
| 393 | |
| 394 | @VisibleForTesting |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 395 | public synchronized void cleanupStaleSessions(long timeoutMs) { |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 396 | String logMessage = "Stale Sessions Cleaned:\n"; |
| 397 | boolean isSessionsStale = false; |
| 398 | long currentTimeMs = System.currentTimeMillis(); |
| 399 | // Remove references that are in the Session Mapper (causing GC to occur) on |
| 400 | // sessions that are lasting longer than LOGGING_SESSION_TIMEOUT_MS. |
| 401 | // If this occurs, then there is most likely a Session active that never had |
| 402 | // Log.endSession called on it. |
| 403 | for (Iterator<ConcurrentHashMap.Entry<Integer, Session>> it = |
Brad Ebinger | 096d282 | 2016-10-13 15:26:58 -0700 | [diff] [blame] | 404 | mSessionMapper.entrySet().iterator(); it.hasNext(); ) { |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 405 | ConcurrentHashMap.Entry<Integer, Session> entry = it.next(); |
| 406 | Session session = entry.getValue(); |
| 407 | if (currentTimeMs - session.getExecutionStartTimeMilliseconds() > timeoutMs) { |
| 408 | it.remove(); |
| 409 | logMessage += session.printFullSessionTree() + "\n"; |
| 410 | isSessionsStale = true; |
| 411 | } |
| 412 | } |
| 413 | if (isSessionsStale) { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 414 | Log.w(LOGGING_TAG, logMessage); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 415 | } else { |
Brad Ebinger | a0dc976 | 2016-10-21 09:41:29 -0700 | [diff] [blame] | 416 | Log.v(LOGGING_TAG, "No stale logging sessions needed to be cleaned..."); |
Brad Ebinger | 51b9834 | 2016-09-22 16:30:46 -0700 | [diff] [blame] | 417 | } |
| 418 | } |
| 419 | |
| 420 | /** |
| 421 | * Returns the amount of time after a Logging session has been started that Telecom is set to |
| 422 | * perform a sweep to check and make sure that the session is still not incomplete (stale). |
| 423 | */ |
| 424 | private long getCleanupTimeout(Context context) { |
| 425 | return Settings.Secure.getLong(context.getContentResolver(), TIMEOUTS_PREFIX + |
| 426 | "stale_session_cleanup_timeout_millis", DEFAULT_SESSION_TIMEOUT_MS); |
| 427 | } |
| 428 | } |