Skip to content

Commit dfc31a3

Browse files
ChaseMotormanChaseMotorman
committed
Decorate metadata with app exit trace data
Enrich instrumentation data for App Terminations with ANR and CRASH_NATIVE reasons. * adds new properties derived from data contained in traceInputStream * adds/updates tests
1 parent abc207b commit dfc31a3

File tree

4 files changed

+1331
-3
lines changed

4 files changed

+1331
-3
lines changed

‎platform/jvm/capture/src/main/kotlin/io/bitdrift/capture/events/lifecycle/AppExitLogger.kt

+90-3
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77

88
package io.bitdrift.capture.events.lifecycle
99

10+
import android.annotation.SuppressLint
1011
import android.annotation.TargetApi
1112
import android.app.ActivityManager
1213
import android.app.ActivityManager.RunningAppProcessInfo
@@ -21,10 +22,13 @@ import io.bitdrift.capture.LoggerImpl
2122
import io.bitdrift.capture.common.ErrorHandler
2223
import io.bitdrift.capture.common.Runtime
2324
import io.bitdrift.capture.common.RuntimeFeature
25+
import io.bitdrift.capture.providers.FieldValue
2426
import io.bitdrift.capture.providers.toFields
2527
import io.bitdrift.capture.utils.BuildVersionChecker
2628
import java.lang.reflect.InvocationTargetException
2729
import java.nio.charset.StandardCharsets
30+
import java.util.regex.Matcher
31+
import java.util.regex.Pattern
2832

2933
internal class AppExitLogger(
3034
private val logger: LoggerImpl,
@@ -37,6 +41,15 @@ internal class AppExitLogger(
3741

3842
companion object {
3943
const val APP_EXIT_EVENT_NAME = "AppExit"
44+
45+
// TODO Refactor to trace parser class
46+
val THREAD_HEADER_PATTERN =
47+
Pattern.compile(".*----- pid (?<pid>.\\d+) at (?<timeCreated>\\d{4}-\\d{2}-\\d{2}[T ]{0,}[0-9:.-]+) -----(?<body>.*$)")
48+
val TRACE_THREADS_PATTERN = Pattern.compile(
49+
".*DALVIK THREADS \\((?<threadCnt>\\d+)\\):\\s(.*)----- end (\\d+) -----",
50+
Pattern.MULTILINE
51+
)
52+
val THREAD_ID_PATTERN = Pattern.compile("^\"(?<threadName>.*)\" (.*)prio=(\\d+).*$")
4053
}
4154

4255
fun installAppExitLogger() {
@@ -98,6 +111,13 @@ internal class AppExitLogger(
98111
lastExitInfo.toFields(),
99112
attributesOverrides = LogAttributesOverrides(sessionId, timestampMs),
100113
) { APP_EXIT_EVENT_NAME }
114+
115+
/** FIXME
116+
* AEI records are maintained in a ring buffer that is updated when ART sees fit,
117+
* So the _last_ AEI record for this PID may appear over several launches.
118+
* To avoid over reporting of exit reasons, we need to maintain a history of
119+
* AEI records visited
120+
*/
101121
}
102122

103123
fun logCrash(thread: Thread, throwable: Throwable) {
@@ -141,7 +161,8 @@ internal class AppExitLogger(
141161
@TargetApi(Build.VERSION_CODES.R)
142162
private fun ApplicationExitInfo.toFields(): InternalFieldsMap {
143163
// https://developer.android.com/reference/kotlin/android/app/ApplicationExitInfo
144-
return mapOf(
164+
165+
val appExitProps = mapOf(
145166
"_app_exit_source" to "ApplicationExitInfo",
146167
"_app_exit_process_name" to this.processName,
147168
"_app_exit_reason" to this.reason.toReasonText(),
@@ -150,8 +171,11 @@ internal class AppExitLogger(
150171
"_app_exit_pss" to this.pss.toString(),
151172
"_app_exit_rss" to this.rss.toString(),
152173
"_app_exit_description" to this.description.orEmpty(),
153-
// TODO(murki): Extract getTraceInputStream() for REASON_ANR or REASON_CRASH_NATIVE
154-
).toFields()
174+
)
175+
176+
appExitProps.plus(decomposeSystemTraceToFieldValues(this))
177+
178+
return appExitProps.toFields()
155179
}
156180

157181
private fun Int.toReasonText(): String {
@@ -202,4 +226,67 @@ internal class AppExitLogger(
202226
else -> LogLevel.INFO
203227
}
204228
}
229+
230+
/**
231+
* For AEI reason types that support it (ANR and NATIVE_CRASH), read the options trace file provided through
232+
* the getTraceInputStream() method. Parse out the interesting bits from the sys trace
233+
*
234+
* @param appExitInfo ApplicationExitInfo record provided by ART
235+
* @return InternalFieldsMap containing any harvested data
236+
*/
237+
@SuppressLint("SwitchIntDef")
238+
@TargetApi(Build.VERSION_CODES.R)
239+
@VisibleForTesting
240+
fun decomposeSystemTraceToFieldValues(appExitInfo: ApplicationExitInfo): InternalFieldsMap {
241+
val traceFields = buildMap<String, FieldValue> { }.toMutableMap()
242+
243+
when (appExitInfo.reason) {
244+
ApplicationExitInfo.REASON_CRASH_NATIVE,
245+
ApplicationExitInfo.REASON_ANR -> {
246+
var sysTrace =
247+
appExitInfo.traceInputStream?.bufferedReader().use { it?.readText() ?: "" }
248+
249+
if (sysTrace.isNotBlank()) {
250+
// replace newlines with tabs to parse the entire trace as a tab delimited string
251+
sysTrace = sysTrace.trim().replace('\n', '\t')
252+
253+
// ----- pid 4473 at 2024-02-15 23:37:45.593138790-0800 -----
254+
val headerMatcher: Matcher =
255+
THREAD_HEADER_PATTERN.matcher(sysTrace)
256+
if (headerMatcher.matches()) {
257+
traceFields["_app_pid"] =
258+
FieldValue.StringField(headerMatcher.group(1)!!.trim())
259+
traceFields["_app_timestamp"] =
260+
FieldValue.StringField(headerMatcher.group(2)!!.trim())
261+
}
262+
263+
// DALVIK THREADS (<nThreads>):\n<thread 0>\n<thread 1>...\n<thread n>\n----- end (<pid>) -----
264+
val threadsMatcher: Matcher = TRACE_THREADS_PATTERN.matcher(sysTrace)
265+
if (threadsMatcher.matches()) {
266+
val threadData = threadsMatcher.group(2)!!.trim()
267+
traceFields["_app_threads"] =
268+
FieldValue.StringField(parseThreadData(threadData).toString())
269+
}
270+
271+
// TODO Look for additional context info: GC, JNI/JIT, ART internal metrics?
272+
}
273+
}
274+
}
275+
276+
return traceFields
277+
}
278+
279+
@VisibleForTesting
280+
fun parseThreadData(threadData: String?): List<String> {
281+
if (!threadData.isNullOrBlank()) {
282+
val threads = threadData.split("\t\t")
283+
.filter { THREAD_ID_PATTERN.matcher(it).matches() }
284+
.map { it.replace("\t", "\n").plus("\n\n") }
285+
286+
return threads
287+
}
288+
289+
return arrayListOf()
290+
}
291+
205292
}

‎platform/jvm/capture/src/test/kotlin/io/bitdrift/capture/AppExitLoggerTest.kt

+70
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ import io.bitdrift.capture.events.lifecycle.AppExitLogger
2424
import io.bitdrift.capture.events.lifecycle.CaptureUncaughtExceptionHandler
2525
import io.bitdrift.capture.providers.toFields
2626
import io.bitdrift.capture.utils.BuildVersionChecker
27+
import org.junit.Assert
2728
import org.junit.Before
2829
import org.junit.Test
2930
import org.mockito.ArgumentMatchers.anyInt
@@ -141,6 +142,7 @@ class AppExitLoggerTest {
141142
whenever(mockExitInfo.pss).thenReturn(1)
142143
whenever(mockExitInfo.rss).thenReturn(2)
143144
whenever(mockExitInfo.description).thenReturn("test-description")
145+
whenever(mockExitInfo.traceInputStream).thenReturn(null)
144146
whenever(activityManager.getHistoricalProcessExitReasons(anyOrNull(), any(), any())).thenReturn(listOf(mockExitInfo))
145147

146148
// ACT
@@ -209,4 +211,72 @@ class AppExitLoggerTest {
209211
)
210212
verify(logger).flush(true)
211213
}
214+
215+
@Test
216+
fun decomposeSysTraceToANRProperties() {
217+
val sessionId = "test-session-id"
218+
val timestamp = 123L
219+
val mockExitInfo = mock<ApplicationExitInfo>(defaultAnswer = RETURNS_DEEP_STUBS)
220+
val sysTraceStream = AppExitLogger::class.java.getResource("/applicationExitInfo/systrace")?.openStream()
221+
222+
whenever(mockExitInfo.processStateSummary).thenReturn(sessionId.toByteArray(StandardCharsets.UTF_8))
223+
whenever(mockExitInfo.timestamp).thenReturn(timestamp)
224+
whenever(mockExitInfo.processName).thenReturn("test-process-name")
225+
whenever(mockExitInfo.reason).thenReturn(ApplicationExitInfo.REASON_ANR)
226+
whenever(mockExitInfo.importance).thenReturn(RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
227+
whenever(mockExitInfo.status).thenReturn(0)
228+
whenever(mockExitInfo.pss).thenReturn(1)
229+
whenever(mockExitInfo.rss).thenReturn(2)
230+
whenever(mockExitInfo.description).thenReturn("systrace-anr-description")
231+
whenever(mockExitInfo.traceInputStream).thenReturn(sysTraceStream)
232+
whenever(activityManager.getHistoricalProcessExitReasons(anyOrNull(), any(), any())).thenReturn(listOf(mockExitInfo))
233+
234+
val fieldsMaps = appExitLogger.decomposeSystemTraceToFieldValues(mockExitInfo)
235+
Assert.assertTrue(fieldsMaps.containsKey("_app_pid"))
236+
Assert.assertTrue(fieldsMaps.containsKey("_app_timestamp"))
237+
Assert.assertTrue(fieldsMaps.containsKey("_app_threads"))
238+
239+
val threads = fieldsMaps.get("_app_threads").toString().split("\n\n")
240+
Assert.assertEquals(30, threads.size)
241+
}
242+
243+
@Test
244+
fun decomposeSysTraceToNativeCrashProperties() {
245+
val sessionId = "test-session-id"
246+
val timestamp = 123L
247+
val mockExitInfo = mock<ApplicationExitInfo>(defaultAnswer = RETURNS_DEEP_STUBS)
248+
val sysTraceStream = AppExitLogger::class.java.getResource("/applicationExitInfo/systrace")?.openStream()
249+
250+
whenever(mockExitInfo.processStateSummary).thenReturn(sessionId.toByteArray(StandardCharsets.UTF_8))
251+
whenever(mockExitInfo.timestamp).thenReturn(timestamp)
252+
whenever(mockExitInfo.processName).thenReturn("test-process-name")
253+
whenever(mockExitInfo.reason).thenReturn(ApplicationExitInfo.REASON_CRASH_NATIVE)
254+
whenever(mockExitInfo.importance).thenReturn(RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
255+
whenever(mockExitInfo.status).thenReturn(0)
256+
whenever(mockExitInfo.pss).thenReturn(1)
257+
whenever(mockExitInfo.rss).thenReturn(2)
258+
whenever(mockExitInfo.description).thenReturn("systrace-native-crash-description")
259+
whenever(mockExitInfo.traceInputStream).thenReturn(sysTraceStream)
260+
whenever(activityManager.getHistoricalProcessExitReasons(anyOrNull(), any(), any())).thenReturn(listOf(mockExitInfo))
261+
262+
val fieldsMaps = appExitLogger.decomposeSystemTraceToFieldValues(mockExitInfo)
263+
Assert.assertTrue(fieldsMaps.containsKey("_app_pid"))
264+
Assert.assertTrue(fieldsMaps.containsKey("_app_timestamp"))
265+
Assert.assertTrue(fieldsMaps.containsKey("_app_threads"))
266+
267+
val threads = fieldsMaps.get("_app_threads").toString().split("\n\n")
268+
Assert.assertEquals(30, threads.size)
269+
}
270+
271+
@Test
272+
fun decomposeSysTraceToThreadList() {
273+
val sysTraceAsString = AppExitLogger::class.java.getResource("/applicationExitInfo/tracethreads")
274+
?.openStream()
275+
?.bufferedReader()
276+
?.readText().orEmpty()
277+
278+
// replace newlines with tabs to parse the entire trace as a tab delimited string
279+
val threads = appExitLogger.parseThreadData(sysTraceAsString.trim().replace('\n', '\t'))
280+
Assert.assertEquals("trace contains 27 threads", 27, threads.size)
281+
}
212282
}

0 commit comments

Comments
 (0)