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.annotation.Nullable; 20 import android.os.Parcel; 21 import android.os.Parcelable; 22 import android.telecom.Log; 23 import android.text.TextUtils; 24 25 import com.android.internal.annotations.VisibleForTesting; 26 import com.android.server.telecom.flags.Flags; 27 28 import java.util.ArrayDeque; 29 import java.util.ArrayList; 30 import java.util.List; 31 import java.util.Objects; 32 import java.util.concurrent.atomic.AtomicInteger; 33 34 /** 35 * Stores information about a thread's point of entry into that should persist until that thread 36 * exits. 37 * @hide 38 */ 39 public class Session { 40 41 public static final String LOG_TAG = "Session"; 42 43 public static final String START_SESSION = "START_SESSION"; 44 public static final String START_EXTERNAL_SESSION = "START_EXTERNAL_SESSION"; 45 public static final String CREATE_SUBSESSION = "CREATE_SUBSESSION"; 46 public static final String CONTINUE_SUBSESSION = "CONTINUE_SUBSESSION"; 47 public static final String END_SUBSESSION = "END_SUBSESSION"; 48 public static final String END_SESSION = "END_SESSION"; 49 50 public static final String SUBSESSION_SEPARATION_CHAR = "->"; 51 public static final String SESSION_SEPARATION_CHAR_CHILD = "_"; 52 public static final String EXTERNAL_INDICATOR = "E-"; 53 public static final String TRUNCATE_STRING = "..."; 54 55 // Prevent infinite recursion by setting a reasonable limit. 56 private static final int SESSION_RECURSION_LIMIT = 25; 57 58 /** 59 * Initial value of mExecutionEndTimeMs and the final value of {@link #getLocalExecutionTime()} 60 * if the Session is canceled. 61 */ 62 public static final long UNDEFINED = -1; 63 64 public static class Info implements Parcelable { 65 public final String sessionId; 66 public final String methodPath; 67 public final String ownerInfo; 68 Info(String id, String path, String owner)69 private Info(String id, String path, String owner) { 70 sessionId = id; 71 methodPath = path; 72 ownerInfo = owner; 73 } 74 getInfo(Session s)75 public static Info getInfo (Session s) { 76 // Create Info based on the truncated method path if the session is external, so we do 77 // not get multiple stacking external sessions (unless we have DEBUG level logging or 78 // lower). 79 return new Info(s.getFullSessionId(), s.getFullMethodPath( 80 !Log.DEBUG && s.isSessionExternal()), s.getOwnerInfo()); 81 } 82 getExternalInfo(Session s, @Nullable String ownerInfo)83 public static Info getExternalInfo(Session s, @Nullable String ownerInfo) { 84 // When creating session information for an existing session, the caller may pass in a 85 // context to be passed along to the recipient of the external session info. 86 // So, for example, if telecom has an active session with owner 'cad', and Telecom is 87 // calling into Telephony and providing external session info, it would pass in 'cast' 88 // as the owner info. This would result in Telephony seeing owner info 'cad/cast', 89 // which would make it very clear in the Telephony logs the chain of package calls which 90 // ultimately resulted in the logs. 91 String newInfo = ownerInfo != null && s.getOwnerInfo() != null 92 // If we've got both, concatenate them. 93 ? s.getOwnerInfo() + "/" + ownerInfo 94 // Otherwise use whichever is present. 95 : ownerInfo != null ? ownerInfo : s.getOwnerInfo(); 96 97 // Create Info based on the truncated method path if the session is external, so we do 98 // not get multiple stacking external sessions (unless we have DEBUG level logging or 99 // lower). 100 return new Info(s.getFullSessionId(), s.getFullMethodPath( 101 !Log.DEBUG && s.isSessionExternal()), newInfo); 102 } 103 104 /** Responsible for creating Info objects for deserialized Parcels. */ 105 public static final @android.annotation.NonNull Parcelable.Creator<Info> CREATOR = 106 new Parcelable.Creator<Info> () { 107 @Override 108 public Info createFromParcel(Parcel source) { 109 String id = source.readString(); 110 String methodName = source.readString(); 111 String ownerInfo = source.readString(); 112 return new Info(id, methodName, ownerInfo); 113 } 114 115 @Override 116 public Info[] newArray(int size) { 117 return new Info[size]; 118 } 119 }; 120 121 /** {@inheritDoc} */ 122 @Override describeContents()123 public int describeContents() { 124 return 0; 125 } 126 127 /** Writes Info object into a Parcel. */ 128 @Override writeToParcel(Parcel destination, int flags)129 public void writeToParcel(Parcel destination, int flags) { 130 destination.writeString(sessionId); 131 destination.writeString(methodPath); 132 destination.writeString(ownerInfo); 133 } 134 } 135 136 private final String mSessionId; 137 private volatile String mShortMethodName; 138 private long mExecutionStartTimeMs; 139 private long mExecutionEndTimeMs = UNDEFINED; 140 private volatile Session mParentSession; 141 private final ArrayList<Session> mChildSessions = new ArrayList<>(5); 142 private boolean mIsCompleted = false; 143 private final boolean mIsExternal; 144 private final AtomicInteger mChildCounter = new AtomicInteger(0); 145 // True if this is a subsession that has been started from the same thread as the parent 146 // session. This can happen if Log.startSession(...) is called multiple times on the same 147 // thread in the case of one Telecom entry point method calling another entry point method. 148 // In this case, we can just make this subsession "invisible," but still keep track of it so 149 // that the Log.endSession() calls match up. 150 private final boolean mIsStartedFromActiveSession; 151 // Optionally provided info about the method/class/component that started the session in order 152 // to make Logging easier. This info will be provided in parentheses along with the session. 153 private final String mOwnerInfo; 154 // Cache Full Method path so that recursive population of the full method path only needs to 155 // be calculated once. 156 private volatile String mFullMethodPathCache; 157 Session(String sessionId, String shortMethodName, long startTimeMs, boolean isStartedFromActiveSession, boolean isExternal, String ownerInfo)158 public Session(String sessionId, String shortMethodName, long startTimeMs, 159 boolean isStartedFromActiveSession, boolean isExternal, String ownerInfo) { 160 mSessionId = (sessionId != null) ? sessionId : "???"; 161 setShortMethodName(shortMethodName); 162 mExecutionStartTimeMs = startTimeMs; 163 mParentSession = null; 164 mIsStartedFromActiveSession = isStartedFromActiveSession; 165 mIsExternal = isExternal; 166 mOwnerInfo = ownerInfo; 167 } 168 getShortMethodName()169 public String getShortMethodName() { 170 return mShortMethodName; 171 } 172 setShortMethodName(String shortMethodName)173 public void setShortMethodName(String shortMethodName) { 174 if (shortMethodName == null) { 175 shortMethodName = ""; 176 } 177 mShortMethodName = shortMethodName; 178 } 179 isExternal()180 public boolean isExternal() { 181 return mIsExternal; 182 } 183 setParentSession(Session parentSession)184 public void setParentSession(Session parentSession) { 185 mParentSession = parentSession; 186 } 187 addChild(Session childSession)188 public void addChild(Session childSession) { 189 if (childSession == null) return; 190 synchronized (mChildSessions) { 191 mChildSessions.add(childSession); 192 } 193 } 194 removeChild(Session child)195 public void removeChild(Session child) { 196 if (child == null) return; 197 synchronized (mChildSessions) { 198 mChildSessions.remove(child); 199 } 200 } 201 getExecutionStartTimeMilliseconds()202 public long getExecutionStartTimeMilliseconds() { 203 return mExecutionStartTimeMs; 204 } 205 setExecutionStartTimeMs(long startTimeMs)206 public void setExecutionStartTimeMs(long startTimeMs) { 207 mExecutionStartTimeMs = startTimeMs; 208 } 209 getParentSession()210 public Session getParentSession() { 211 return mParentSession; 212 } 213 getChildSessions()214 public ArrayList<Session> getChildSessions() { 215 synchronized (mChildSessions) { 216 return new ArrayList<>(mChildSessions); 217 } 218 } 219 isSessionCompleted()220 public boolean isSessionCompleted() { 221 return mIsCompleted; 222 } 223 isStartedFromActiveSession()224 public boolean isStartedFromActiveSession() { 225 return mIsStartedFromActiveSession; 226 } 227 getInfo()228 public Info getInfo() { 229 return Info.getInfo(this); 230 } 231 getExternalInfo(@ullable String ownerInfo)232 public Info getExternalInfo(@Nullable String ownerInfo) { 233 return Info.getExternalInfo(this, ownerInfo); 234 } 235 getOwnerInfo()236 public String getOwnerInfo() { 237 return mOwnerInfo; 238 } 239 240 @VisibleForTesting getSessionId()241 public String getSessionId() { 242 return mSessionId; 243 } 244 245 // Mark this session complete. This will be deleted by Log when all subsessions are complete 246 // as well. markSessionCompleted(long executionEndTimeMs)247 public void markSessionCompleted(long executionEndTimeMs) { 248 mExecutionEndTimeMs = executionEndTimeMs; 249 mIsCompleted = true; 250 } 251 getLocalExecutionTime()252 public long getLocalExecutionTime() { 253 if (mExecutionEndTimeMs == UNDEFINED) { 254 return UNDEFINED; 255 } 256 return mExecutionEndTimeMs - mExecutionStartTimeMs; 257 } 258 getNextChildId()259 public String getNextChildId() { 260 return String.valueOf(mChildCounter.getAndIncrement()); 261 } 262 263 // Builds full session ID, which incliudes the optional external indicators (E), 264 // base session ID, and the optional sub-session IDs (_X): @[E-]...[ID][_X][_Y]... getFullSessionId()265 private String getFullSessionId() { 266 if (!Flags.endSessionImprovements()) return getFullSessionIdRecursive(0); 267 int currParentCount = 0; 268 StringBuilder id = new StringBuilder(); 269 Session currSession = this; 270 while (currSession != null) { 271 Session parentSession = currSession.getParentSession(); 272 if (parentSession != null) { 273 if (currParentCount >= SESSION_RECURSION_LIMIT) { 274 id.insert(0, getSessionId()); 275 id.insert(0, TRUNCATE_STRING); 276 android.util.Slog.w(LOG_TAG, "getFullSessionId: Hit iteration limit!"); 277 return id.toString(); 278 } 279 if (Log.VERBOSE) { 280 id.insert(0, currSession.getSessionId()); 281 id.insert(0, SESSION_SEPARATION_CHAR_CHILD); 282 } 283 } else { 284 id.insert(0, currSession.getSessionId()); 285 } 286 currSession = parentSession; 287 currParentCount++; 288 } 289 return id.toString(); 290 } 291 292 // keep track of calls and bail if we hit the recursion limit getFullSessionIdRecursive(int parentCount)293 private String getFullSessionIdRecursive(int parentCount) { 294 if (parentCount >= SESSION_RECURSION_LIMIT) { 295 // Don't use Telecom's Log.w here or it will cause infinite recursion because it will 296 // try to add session information to this logging statement, which will cause it to hit 297 // this condition again and so on... 298 android.util.Slog.w(LOG_TAG, "getFullSessionId: Hit recursion limit!"); 299 return TRUNCATE_STRING + mSessionId; 300 } 301 // Cache mParentSession locally to prevent a concurrency problem where 302 // Log.endParentSessions() is called while a logging statement is running (Log.i, for 303 // example) and setting mParentSession to null in a different thread after the null check 304 // occurred. 305 Session parentSession = mParentSession; 306 if (parentSession == null) { 307 return mSessionId; 308 } else { 309 if (Log.VERBOSE) { 310 return parentSession.getFullSessionIdRecursive(parentCount + 1) 311 // Append "_X" to subsession to show subsession designation. 312 + SESSION_SEPARATION_CHAR_CHILD + mSessionId; 313 } else { 314 // Only worry about the base ID at the top of the tree. 315 return parentSession.getFullSessionIdRecursive(parentCount + 1); 316 } 317 318 } 319 } 320 getRootSession(String callingMethod)321 private Session getRootSession(String callingMethod) { 322 int currParentCount = 0; 323 Session topNode = this; 324 Session parentNode = topNode.getParentSession(); 325 while (parentNode != null) { 326 if (currParentCount >= SESSION_RECURSION_LIMIT) { 327 // Don't use Telecom's Log.w here or it will cause infinite recursion because it 328 // will try to add session information to this logging statement, which will cause 329 // it to hit this condition again and so on... 330 android.util.Slog.w(LOG_TAG, "getRootSession: Hit iteration limit from " 331 + callingMethod); 332 break; 333 } 334 topNode = parentNode; 335 parentNode = topNode.getParentSession(); 336 currParentCount++; 337 } 338 return topNode; 339 } 340 341 // Print out the full Session tree from any subsession node printFullSessionTree()342 public String printFullSessionTree() { 343 return getRootSession("printFullSessionTree").printSessionTree(); 344 } 345 printSessionTree()346 private String printSessionTree() { 347 StringBuilder sb = new StringBuilder(); 348 if (!Flags.endSessionImprovements()) { 349 printSessionTreeRecursive(0, sb, 0); 350 return sb.toString(); 351 } 352 int depth = 0; 353 ArrayDeque<Session> deque = new ArrayDeque<>(); 354 deque.add(this); 355 while (!deque.isEmpty()) { 356 Session node = deque.pollFirst(); 357 sb.append("\t".repeat(depth)); 358 sb.append(node.toString()); 359 sb.append("\n"); 360 if (depth >= SESSION_RECURSION_LIMIT) { 361 sb.append(TRUNCATE_STRING); 362 depth -= 1; 363 continue; 364 } 365 List<Session> childSessions = node.getChildSessions().reversed(); 366 if (!childSessions.isEmpty()) { 367 depth += 1; 368 for (Session child : childSessions) { 369 deque.addFirst(child); 370 } 371 } else { 372 depth -= 1; 373 } 374 } 375 return sb.toString(); 376 } 377 378 // Recursively move down session tree using DFS, but print out each node when it is reached. printSessionTreeRecursive(int tabI, StringBuilder sb, int currChildCount)379 private void printSessionTreeRecursive(int tabI, StringBuilder sb, int currChildCount) { 380 // Prevent infinite recursion. 381 if (currChildCount >= SESSION_RECURSION_LIMIT) { 382 // Don't use Telecom's Log.w here or it will cause infinite recursion because it will 383 // try to add session information to this logging statement, which will cause it to hit 384 // this condition again and so on... 385 android.util.Slog.w(LOG_TAG, "printSessionTree: Hit recursion limit!"); 386 sb.append(TRUNCATE_STRING); 387 return; 388 } 389 sb.append(toString()); 390 for (Session child : mChildSessions) { 391 sb.append("\n"); 392 for (int i = 0; i <= tabI; i++) { 393 sb.append("\t"); 394 } 395 child.printSessionTreeRecursive(tabI + 1, sb, currChildCount + 1); 396 } 397 } 398 399 // 400 401 /** 402 * Concatenate the short method name with the parent Sessions to create full method path. 403 * @param truncatePath if truncatePath is set to true, all other external sessions (except for 404 * the most recent) will be truncated to "..." 405 * @return The full method path associated with this Session. 406 */ 407 @VisibleForTesting getFullMethodPath(boolean truncatePath)408 public String getFullMethodPath(boolean truncatePath) { 409 StringBuilder sb = new StringBuilder(); 410 if (!Flags.endSessionImprovements()) { 411 getFullMethodPathRecursive(sb, truncatePath, 0); 412 return sb.toString(); 413 } 414 // Check to see if the session has been renamed yet. If it has not, then the session 415 // has not been continued. 416 Session parentSession = getParentSession(); 417 boolean isSessionStarted = parentSession == null 418 || !getShortMethodName().equals(parentSession.getShortMethodName()); 419 int depth = 0; 420 Session currSession = this; 421 while (currSession != null) { 422 String cache = currSession.mFullMethodPathCache; 423 // Return cached value for method path. When returning the truncated path, recalculate 424 // the full path without using the cached value. 425 if (!TextUtils.isEmpty(cache) && !truncatePath) { 426 sb.insert(0, cache); 427 return sb.toString(); 428 } 429 430 parentSession = currSession.getParentSession(); 431 // Encapsulate the external session's method name so it is obvious what part of the 432 // session is external or truncate it if we do not want the entire history. 433 if (currSession.isExternal()) { 434 if (truncatePath) { 435 sb.insert(0, TRUNCATE_STRING); 436 } else { 437 sb.insert(0, ")"); 438 sb.insert(0, currSession.getShortMethodName()); 439 sb.insert(0, "("); 440 } 441 } else { 442 sb.insert(0, currSession.getShortMethodName()); 443 } 444 if (parentSession != null) { 445 sb.insert(0, SUBSESSION_SEPARATION_CHAR); 446 } 447 448 if (depth >= SESSION_RECURSION_LIMIT) { 449 // Don't use Telecom's Log.w here or it will cause infinite recursion because it 450 // will try to add session information to this logging statement, which will cause 451 // it to hit this condition again and so on... 452 android.util.Slog.w(LOG_TAG, "getFullMethodPath: Hit iteration limit!"); 453 sb.insert(0, TRUNCATE_STRING); 454 return sb.toString(); 455 } 456 currSession = parentSession; 457 depth++; 458 } 459 if (isSessionStarted && !truncatePath) { 460 // Cache the full method path for this node so that we do not need to calculate it 461 // again in the future. 462 mFullMethodPathCache = sb.toString(); 463 } 464 return sb.toString(); 465 } 466 getFullMethodPathRecursive(StringBuilder sb, boolean truncatePath, int parentCount)467 private synchronized void getFullMethodPathRecursive(StringBuilder sb, boolean truncatePath, 468 int parentCount) { 469 if (parentCount >= SESSION_RECURSION_LIMIT) { 470 // Don't use Telecom's Log.w here or it will cause infinite recursion because it will 471 // try to add session information to this logging statement, which will cause it to hit 472 // this condition again and so on... 473 android.util.Slog.w(LOG_TAG, "getFullMethodPathRecursive: Hit recursion limit!"); 474 sb.append(TRUNCATE_STRING); 475 return; 476 } 477 // Return cached value for method path. When returning the truncated path, recalculate the 478 // full path without using the cached value. 479 if (!TextUtils.isEmpty(mFullMethodPathCache) && !truncatePath) { 480 sb.append(mFullMethodPathCache); 481 return; 482 } 483 Session parentSession = getParentSession(); 484 boolean isSessionStarted = false; 485 if (parentSession != null) { 486 // Check to see if the session has been renamed yet. If it has not, then the session 487 // has not been continued. 488 isSessionStarted = !mShortMethodName.equals(parentSession.mShortMethodName); 489 parentSession.getFullMethodPathRecursive(sb, truncatePath, parentCount + 1); 490 sb.append(SUBSESSION_SEPARATION_CHAR); 491 } 492 // Encapsulate the external session's method name so it is obvious what part of the session 493 // is external or truncate it if we do not want the entire history. 494 if (isExternal()) { 495 if (truncatePath) { 496 sb.append(TRUNCATE_STRING); 497 } else { 498 sb.append("("); 499 sb.append(mShortMethodName); 500 sb.append(")"); 501 } 502 } else { 503 sb.append(mShortMethodName); 504 } 505 // If we are returning the truncated path, do not save that path as the full path. 506 if (isSessionStarted && !truncatePath) { 507 // Cache this value so that we do not have to do this work next time! 508 // We do not cache the value if the session being evaluated hasn't been continued yet. 509 mFullMethodPathCache = sb.toString(); 510 } 511 } 512 513 // Recursively move to the top of the tree to see if the parent session is external. isSessionExternal()514 private boolean isSessionExternal() { 515 return getRootSession("isSessionExternal").isExternal(); 516 } 517 518 @Override hashCode()519 public int hashCode() { 520 int result = mSessionId.hashCode(); 521 result = 31 * result + mShortMethodName.hashCode(); 522 result = 31 * result + Long.hashCode(mExecutionStartTimeMs); 523 result = 31 * result + Long.hashCode(mExecutionEndTimeMs); 524 result = 31 * result + (mParentSession != null ? mParentSession.hashCode() : 0); 525 result = 31 * result + mChildSessions.hashCode(); 526 result = 31 * result + (mIsCompleted ? 1 : 0); 527 result = 31 * result + mChildCounter.hashCode(); 528 result = 31 * result + (mIsStartedFromActiveSession ? 1 : 0); 529 result = 31 * result + (mOwnerInfo != null ? mOwnerInfo.hashCode() : 0); 530 return result; 531 } 532 533 @Override equals(Object o)534 public boolean equals(Object o) { 535 if (this == o) return true; 536 if (o == null || getClass() != o.getClass()) return false; 537 538 Session session = (Session) o; 539 540 if (mExecutionStartTimeMs != session.mExecutionStartTimeMs) return false; 541 if (mExecutionEndTimeMs != session.mExecutionEndTimeMs) return false; 542 if (mIsCompleted != session.mIsCompleted) return false; 543 if (!(mChildCounter.get() == session.mChildCounter.get())) return false; 544 if (mIsStartedFromActiveSession != session.mIsStartedFromActiveSession) return false; 545 if (!Objects.equals(mSessionId, session.mSessionId)) return false; 546 if (!Objects.equals(mShortMethodName, session.mShortMethodName)) return false; 547 if (!Objects.equals(mParentSession, session.mParentSession)) return false; 548 if (!Objects.equals(mChildSessions, session.mChildSessions)) return false; 549 return Objects.equals(mOwnerInfo, session.mOwnerInfo); 550 } 551 552 @Override toString()553 public String toString() { 554 Session sessionToPrint = this; 555 if (getParentSession() != null && isStartedFromActiveSession()) { 556 // Log.startSession was called from within another active session. Use the parent's 557 // Id instead of the child to reduce confusion. 558 sessionToPrint = getRootSession("toString"); 559 } 560 StringBuilder methodName = new StringBuilder(); 561 methodName.append(sessionToPrint.getFullMethodPath(false /*truncatePath*/)); 562 if (sessionToPrint.getOwnerInfo() != null && !sessionToPrint.getOwnerInfo().isEmpty()) { 563 methodName.append("("); 564 methodName.append(sessionToPrint.getOwnerInfo()); 565 methodName.append(")"); 566 } 567 return methodName.toString() + "@" + sessionToPrint.getFullSessionId(); 568 } 569 } 570