Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Decorate metadata with app exit trace data #150

Draft
wants to merge 1 commit into
base: main
Choose a base branch
from
+1,331 −3
Draft

Decorate metadata with app exit trace data #150

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
93 changes: 90 additions & 3 deletions platform/jvm/capture/src/main/kotlin/io/bitdrift/capture/events/lifecycle/AppExitLogger.kt
View file
Open in desktop
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
Open in desktop
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
Loading