Skip to content

Commit

Permalink
Decorate metadata with app exit trace data
Browse files Browse the repository at this point in the history 
Enrich instrumentation data for App Terminations with ANR and CRASH_NATIVE reasons.
* adds new properties derived from data contained in traceInputStream
* adds/updates tests
  • Loading branch information
cs thomas authored and cs thomas committed Dec 10, 2024
1 parent abc207b commit 1190773
Show file tree
Hide file tree
Showing 4 changed files with 1,331 additions and 3 deletions.
93 changes: 90 additions & 3 deletions platform/jvm/capture/src/main/kotlin/io/bitdrift/capture/events/lifecycle/AppExitLogger.kt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

package io.bitdrift.capture.events.lifecycle

import android.annotation.SuppressLint
import android.annotation.TargetApi
import android.app.ActivityManager
import android.app.ActivityManager.RunningAppProcessInfo
Expand All @@ -21,10 +22,13 @@ import io.bitdrift.capture.LoggerImpl
import io.bitdrift.capture.common.ErrorHandler
import io.bitdrift.capture.common.Runtime
import io.bitdrift.capture.common.RuntimeFeature
import io.bitdrift.capture.providers.FieldValue
import io.bitdrift.capture.providers.toFields
import io.bitdrift.capture.utils.BuildVersionChecker
import java.lang.reflect.InvocationTargetException
import java.nio.charset.StandardCharsets
import java.util.regex.Matcher
import java.util.regex.Pattern

internal class AppExitLogger(
private val logger: LoggerImpl,
Expand All @@ -37,6 +41,15 @@ internal class AppExitLogger(

companion object {
const val APP_EXIT_EVENT_NAME = "AppExit"

// TODO Refactor to trace parser class
val THREAD_HEADER_PATTERN =
Pattern.compile(".*----- pid (?<pid>.\\d+) at (?<timeCreated>\\d{4}-\\d{2}-\\d{2}[T ]{0,}[0-9:.-]+) -----(?<body>.*$)")
val TRACE_THREADS_PATTERN = Pattern.compile(
".*DALVIK THREADS \\((?<threadCnt>\\d+)\\):\\s(.*)----- end (\\d+) -----",
Pattern.MULTILINE
)
val THREAD_ID_PATTERN = Pattern.compile("^\"(?<threadName>.*)\" (.*)prio=(\\d+).*$")
}

fun installAppExitLogger() {
Expand Down Expand Up @@ -98,6 +111,13 @@ internal class AppExitLogger(
lastExitInfo.toFields(),
attributesOverrides = LogAttributesOverrides(sessionId, timestampMs),
) { APP_EXIT_EVENT_NAME }

/** FIXME
* AEI records are maintained in a ring buffer that is updated when ART sees fit,
* So the _last_ AEI record for this PID may appear over several launches.
* To avoid over reporting of exit reasons, we need to maintain a history of
* AEI records visited
*/
}

fun logCrash(thread: Thread, throwable: Throwable) {
Expand Down Expand Up @@ -141,7 +161,8 @@ internal class AppExitLogger(
@TargetApi(Build.VERSION_CODES.R)
private fun ApplicationExitInfo.toFields(): InternalFieldsMap {
// https://developer.android.com/reference/kotlin/android/app/ApplicationExitInfo
return mapOf(

val appExitProps = mapOf(
"_app_exit_source" to "ApplicationExitInfo",
"_app_exit_process_name" to this.processName,
"_app_exit_reason" to this.reason.toReasonText(),
Expand All @@ -150,8 +171,11 @@ internal class AppExitLogger(
"_app_exit_pss" to this.pss.toString(),
"_app_exit_rss" to this.rss.toString(),
"_app_exit_description" to this.description.orEmpty(),
// TODO(murki): Extract getTraceInputStream() for REASON_ANR or REASON_CRASH_NATIVE
).toFields()
)

appExitProps.plus(decomposeSystemTraceToFieldValues(this))

return appExitProps.toFields()
}

private fun Int.toReasonText(): String {
Expand Down Expand Up @@ -202,4 +226,67 @@ internal class AppExitLogger(
else -> LogLevel.INFO
}
}

/**
* For AEI reason types that support it (ANR and NATIVE_CRASH), read the options trace file provided through
* the getTraceInputStream() method. Parse out the interesting bits from the sys trace
*
* @param appExitInfo ApplicationExitInfo record provided by ART
* @return InternalFieldsMap containing any harvested data
*/
@SuppressLint("SwitchIntDef")
@TargetApi(Build.VERSION_CODES.R)
@VisibleForTesting
fun decomposeSystemTraceToFieldValues(appExitInfo: ApplicationExitInfo): InternalFieldsMap {
val traceFields = buildMap<String, FieldValue> { }.toMutableMap()

when (appExitInfo.reason) {
ApplicationExitInfo.REASON_CRASH_NATIVE,
ApplicationExitInfo.REASON_ANR -> {
var sysTrace =
appExitInfo.traceInputStream?.bufferedReader().use { it?.readText() ?: "" }

if (sysTrace.isNotBlank()) {
// replace newlines with tabs to parse the entire trace as a tab delimited string
sysTrace = sysTrace.trim().replace('\n', '\t')

// ----- pid 4473 at 2024-02-15 23:37:45.593138790-0800 -----
val headerMatcher: Matcher =
THREAD_HEADER_PATTERN.matcher(sysTrace)
if (headerMatcher.matches()) {
traceFields["_app_pid"] =
FieldValue.StringField(headerMatcher.group(1)!!.trim())
traceFields["_app_timestamp"] =
FieldValue.StringField(headerMatcher.group(2)!!.trim())
}

// DALVIK THREADS (<nThreads>):\n<thread 0>\n<thread 1>...\n<thread n>\n----- end (<pid>) -----
val threadsMatcher: Matcher = TRACE_THREADS_PATTERN.matcher(sysTrace)
if (threadsMatcher.matches()) {
val threadData = threadsMatcher.group(2)!!.trim()
traceFields["_app_threads"] =
FieldValue.StringField(parseThreadData(threadData).toString())
}

// TODO Look for additional context info: GC, JNI/JIT, ART internal metrics?
}
}
}

return traceFields
}

@VisibleForTesting
fun parseThreadData(threadData: String?): List<String> {
if (!threadData.isNullOrBlank()) {
val threads = threadData.split("\t\t")
.filter { THREAD_ID_PATTERN.matcher(it).matches() }
.map { it.replace("\t", "\n").plus("\n\n") }

return threads
}

return arrayListOf()
}

}
70 changes: 70 additions & 0 deletions platform/jvm/capture/src/test/kotlin/io/bitdrift/capture/AppExitLoggerTest.kt
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,7 @@ import io.bitdrift.capture.events.lifecycle.AppExitLogger
import io.bitdrift.capture.events.lifecycle.CaptureUncaughtExceptionHandler
import io.bitdrift.capture.providers.toFields
import io.bitdrift.capture.utils.BuildVersionChecker
import org.junit.Assert
import org.junit.Before
import org.junit.Test
import org.mockito.ArgumentMatchers.anyInt
Expand Down Expand Up @@ -141,6 +142,7 @@ class AppExitLoggerTest {
whenever(mockExitInfo.pss).thenReturn(1)
whenever(mockExitInfo.rss).thenReturn(2)
whenever(mockExitInfo.description).thenReturn("test-description")
whenever(mockExitInfo.traceInputStream).thenReturn(null)
whenever(activityManager.getHistoricalProcessExitReasons(anyOrNull(), any(), any())).thenReturn(listOf(mockExitInfo))

// ACT
Expand Down Expand Up @@ -209,4 +211,72 @@ class AppExitLoggerTest {
)
verify(logger).flush(true)
}

@Test
fun decomposeSysTraceToANRProperties() {
val sessionId = "test-session-id"
val timestamp = 123L
val mockExitInfo = mock<ApplicationExitInfo>(defaultAnswer = RETURNS_DEEP_STUBS)
val sysTraceStream = AppExitLogger::class.java.getResource("/applicationExitInfo/systrace")?.openStream()

whenever(mockExitInfo.processStateSummary).thenReturn(sessionId.toByteArray(StandardCharsets.UTF_8))
whenever(mockExitInfo.timestamp).thenReturn(timestamp)
whenever(mockExitInfo.processName).thenReturn("test-process-name")
whenever(mockExitInfo.reason).thenReturn(ApplicationExitInfo.REASON_ANR)
whenever(mockExitInfo.importance).thenReturn(RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
whenever(mockExitInfo.status).thenReturn(0)
whenever(mockExitInfo.pss).thenReturn(1)
whenever(mockExitInfo.rss).thenReturn(2)
whenever(mockExitInfo.description).thenReturn("systrace-anr-description")
whenever(mockExitInfo.traceInputStream).thenReturn(sysTraceStream)
whenever(activityManager.getHistoricalProcessExitReasons(anyOrNull(), any(), any())).thenReturn(listOf(mockExitInfo))

val fieldsMaps = appExitLogger.decomposeSystemTraceToFieldValues(mockExitInfo)
Assert.assertTrue(fieldsMaps.containsKey("_app_pid"))
Assert.assertTrue(fieldsMaps.containsKey("_app_timestamp"))
Assert.assertTrue(fieldsMaps.containsKey("_app_threads"))

val threads = fieldsMaps.get("_app_threads").toString().split("\n\n")
Assert.assertEquals(30, threads.size)
}

@Test
fun decomposeSysTraceToNativeCrashProperties() {
val sessionId = "test-session-id"
val timestamp = 123L
val mockExitInfo = mock<ApplicationExitInfo>(defaultAnswer = RETURNS_DEEP_STUBS)
val sysTraceStream = AppExitLogger::class.java.getResource("/applicationExitInfo/systrace")?.openStream()

whenever(mockExitInfo.processStateSummary).thenReturn(sessionId.toByteArray(StandardCharsets.UTF_8))
whenever(mockExitInfo.timestamp).thenReturn(timestamp)
whenever(mockExitInfo.processName).thenReturn("test-process-name")
whenever(mockExitInfo.reason).thenReturn(ApplicationExitInfo.REASON_CRASH_NATIVE)
whenever(mockExitInfo.importance).thenReturn(RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
whenever(mockExitInfo.status).thenReturn(0)
whenever(mockExitInfo.pss).thenReturn(1)
whenever(mockExitInfo.rss).thenReturn(2)
whenever(mockExitInfo.description).thenReturn("systrace-native-crash-description")
whenever(mockExitInfo.traceInputStream).thenReturn(sysTraceStream)
whenever(activityManager.getHistoricalProcessExitReasons(anyOrNull(), any(), any())).thenReturn(listOf(mockExitInfo))

val fieldsMaps = appExitLogger.decomposeSystemTraceToFieldValues(mockExitInfo)
Assert.assertTrue(fieldsMaps.containsKey("_app_pid"))
Assert.assertTrue(fieldsMaps.containsKey("_app_timestamp"))
Assert.assertTrue(fieldsMaps.containsKey("_app_threads"))

val threads = fieldsMaps.get("_app_threads").toString().split("\n\n")
Assert.assertEquals(30, threads.size)
}

@Test
fun decomposeSysTraceToThreadList() {
val sysTraceAsString = AppExitLogger::class.java.getResource("/applicationExitInfo/tracethreads")
?.openStream()
?.bufferedReader()
?.readText().orEmpty()

// replace newlines with tabs to parse the entire trace as a tab delimited string
val threads = appExitLogger.parseThreadData(sysTraceAsString.trim().replace('\n', '\t'))
Assert.assertEquals("trace contains 27 threads", 27, threads.size)
}
}
Loading

0 comments on commit 1190773

Please sign in to comment.