Skip to content

Commit

Permalink
ci: store logcat logs for test failures
Browse files Browse the repository at this point in the history
  • Loading branch information
fractalwrench committed Feb 13, 2024
1 parent c326cca commit e016c09
Show file tree
Hide file tree
Showing 8 changed files with 90 additions and 43 deletions.
5 changes: 3 additions & 2 deletions .github/workflows/functional-tests.yml
Original file line number Diff line number Diff line change
Expand Up @@ -82,7 +82,7 @@ jobs:
profile: Nexus 6
# Grab the failures from the device so we can include them in results.
# Exit with non-zero so GH checks still fail.
script: ./gradlew connectedCheck --stacktrace || (adb pull /storage/emulated/0/Android/data/io.embrace.android.embracesdk.test/cache/test_failure/ && exit 127)
script: ./gradlew connectedCheck --stacktrace || (adb logcat '[Embrace]:d' '*:S' -t 100000 > emulator_logcat.log && adb pull /storage/emulated/0/Android/data/io.embrace.android.embracesdk.test/cache/test_failure/ && exit 127)

- name: Retry Functional Tests
uses: embrace-io/android-emulator-runner@v2
Expand All @@ -95,7 +95,7 @@ jobs:
profile: Nexus 6
# Grab the failures from the device so we can include them in results.
# Exit with non-zero so GH checks still fail.
script: ./gradlew connectedCheck --stacktrace || (adb pull /storage/emulated/0/Android/data/io.embrace.android.embracesdk.test/cache/test_failure/ && exit 127)
script: ./gradlew connectedCheck --stacktrace || (adb logcat '[Embrace]:d' '*:S' -t 100000 > emulator_logcat.log && adb pull /storage/emulated/0/Android/data/io.embrace.android.embracesdk.test/cache/test_failure/ && exit 127)

- name: Archive Test Results
if: ${{ always() }}
Expand All @@ -105,6 +105,7 @@ jobs:
path: |
embrace-android-sdk/build/reports/androidTests/connected
test_failure
emulator_logcat.log
- name: Post workflow result
id: slack
Expand Down
8 changes: 8 additions & 0 deletions embrace-android-sdk/src/androidTest/java/TestLogger.kt
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
import android.util.Log

// use same tag value so that we can filter logs in logcat on CI job
private const val LOG_TAG = "[Embrace]"

internal fun logTestMessage(message: String) {
Log.w(LOG_TAG, message)
}
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,6 @@ package io.embrace.android.embracesdk

import android.os.Handler
import android.os.Looper
import android.util.Log
import io.embrace.android.embracesdk.payload.AnrInterval
import io.embrace.android.embracesdk.payload.AnrSample
import io.embrace.android.embracesdk.payload.SessionMessage
Expand All @@ -11,6 +10,7 @@ import java.util.concurrent.CountDownLatch
import java.util.concurrent.Executors
import java.util.concurrent.TimeUnit
import java.util.zip.GZIPInputStream
import logTestMessage
import okhttp3.mockwebserver.RecordedRequest
import org.junit.Assert.assertEquals
import org.junit.Assert.assertNotNull
Expand Down Expand Up @@ -152,7 +152,7 @@ internal class AnrIntegrationTest : BaseTest() {
}

handler.post {
Log.i("Embrace", "Starting first ANR interval")
logTestMessage("Starting first ANR interval")
Thread.sleep(8000)
latch.countDown()
scheduleNextMainThreadWork { produceSecondAnrInterval() }
Expand All @@ -161,35 +161,35 @@ internal class AnrIntegrationTest : BaseTest() {
}

private fun produceSecondAnrInterval() {
Log.i("Embrace", "Starting second ANR interval")
logTestMessage("Starting second ANR interval")
Thread.sleep(2000)
latch.countDown()
scheduleNextMainThreadWork { produceThirdAnrInterval() }
}

private fun produceThirdAnrInterval() {
Log.i("Embrace", "Starting third ANR interval")
logTestMessage("Starting third ANR interval")
Thread.sleep(3000)
latch.countDown()
scheduleNextMainThreadWork { produceFourthAnrInterval() }
}

private fun produceFourthAnrInterval() {
Log.i("Embrace", "Starting fourth ANR interval")
logTestMessage("Starting fourth ANR interval")
Thread.sleep(3000)
latch.countDown()
scheduleNextMainThreadWork { produceFifthAnrInterval() }
}

private fun produceFifthAnrInterval() {
Log.i("Embrace", "Starting fifth ANR interval")
logTestMessage("Starting fifth ANR interval")
Thread.sleep(3000)
latch.countDown()
scheduleNextMainThreadWork { produceSixthAnrInterval() }
}

private fun produceSixthAnrInterval() {
Log.i("Embrace", "Starting sixth ANR interval")
logTestMessage("Starting sixth ANR interval")
Thread.sleep(3000)
latch.countDown()
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,6 @@ import android.os.FileObserver
import android.os.Handler
import android.os.Looper
import android.util.Base64
import android.util.Log
import androidx.lifecycle.ProcessLifecycleOwnerAccess
import androidx.test.platform.app.InstrumentationRegistry
import io.embrace.android.embracesdk.comms.api.ApiClient
Expand Down Expand Up @@ -34,6 +33,7 @@ import java.nio.charset.StandardCharsets
import java.util.concurrent.CountDownLatch
import java.util.concurrent.TimeUnit
import java.util.zip.GZIPInputStream
import logTestMessage

/**
* The default Base test class, which all tests using TestServer should inherit from. This
Expand All @@ -56,6 +56,7 @@ internal open class BaseTest {
@SuppressLint("VisibleForTests")
@Before
fun beforeEach() {
logTestMessage("Starting test server")
testServer.start(getDefaultNetworkResponses())

if (Looper.myLooper() == null) {
Expand All @@ -70,19 +71,24 @@ internal open class BaseTest {
// attach our mock context to the ProcessLifecycleOwner, this will give us control over the
// activity/application lifecycle for callbacks registered with the ProcessLifecycleOwner
Handler(Looper.getMainLooper()).post {
logTestMessage("Attaching mock context to ProcessLifecycleOwner")
ProcessLifecycleOwnerAccess.attach(mContext)
}

logTestMessage("Clearing cache folder")
clearCacheFolder()

logTestMessage("Setting new embrace instance")
Embrace.setImpl(EmbraceImpl())

logTestMessage("Setting local config")
setLocalConfig()
refreshScreenshotBitmap()
}

@After
fun afterEach() {
Log.e("TestServer", "Stop Embrace")
logTestMessage("Stop Embrace")
Embrace.getImpl().stop()
testServer.stop()
fileObserver?.stopWatching()
Expand Down Expand Up @@ -137,6 +143,7 @@ internal open class BaseTest {
* we will trigger ON_CREATE and then trigger ON_START when this method is invoked
*/
private fun sendForeground() {
logTestMessage("Sending application to the foreground")
mContext.sendForeground()
}

Expand All @@ -146,6 +153,7 @@ internal open class BaseTest {
* lifecycle state is ON_RESUME, we will trigger ON_PAUSE and then trigger ON_START when this method is invoked
*/
fun sendBackground() {
logTestMessage("Sending application to the background")
mContext.sendBackground()
}

Expand All @@ -158,11 +166,11 @@ internal open class BaseTest {
* starts a session).
*/
fun startEmbraceInForeground() {
Log.e("TestServer", "Start Embrace")
logTestMessage("Starting Embrace in the foreground")
Embrace.getInstance().start(mContext)
assertTrue(Embrace.getInstance().isStarted)
Log.e("TestServer", "initialize lifecycle to start session")
sendForeground()
logTestMessage("Adding some data to the session")
Embrace.getInstance().addBreadcrumb("a message")
Embrace.getInstance().setUserEmail("[email protected]")
Embrace.getInstance().setUserIdentifier("some id")
Expand All @@ -185,6 +193,7 @@ internal open class BaseTest {
* It needs to be done with a for because the order of the requests can be different between runs.
*/
private fun validateInitializationRequests() {
logTestMessage("Starting validation of initialization requests")
var isStartupStartEventValidated = false

(0 until TOTAL_REQUESTS_AT_INIT).forEach { _ ->
Expand Down Expand Up @@ -212,7 +221,7 @@ internal open class BaseTest {

else -> fail("Unexpected Request call. ${request.path}")
}
println("REQUEST: ${request.path}")
logTestMessage("Validated initialization request at ${request.path}")
}
}
}
Expand All @@ -227,6 +236,7 @@ internal open class BaseTest {
* fail the test.
*/
fun waitForRequest(action: (response: RecordedRequest) -> Unit = {}) {
logTestMessage("Waiting to assert that request was received by MockWebServer.")
val request = testServer.takeRequest()
request?.let(action) ?: fail(
"Expected request not sent after configured timeout. " +
Expand All @@ -236,10 +246,12 @@ internal open class BaseTest {

fun waitForFailedRequest(
endpoint: EmbraceEndpoint,
request: () -> Unit,
action: () -> Unit,
embraceOperation: () -> Unit,
assertion: () -> Unit,
validate: (file: File) -> Unit
) {
logTestMessage("Waiting to assert that failed request was written to disk.")

val startSignal = CountDownLatch(1)
val file = File(pendingApiCallsFilePath)

Expand All @@ -251,18 +263,26 @@ internal open class BaseTest {
TestServerResponse(ApiClient.NO_HTTP_RESPONSE)
)

request()
action()
startSignal.await(1000, TimeUnit.MILLISECONDS)
logTestMessage("Performing Embrace operation that will fail.")

embraceOperation()

logTestMessage("Performing assertion on Embrace action. that will fail.")

assertion()
startSignal.await(FAILED_REQUEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS)
validate(file)
}

fun validateMessageAgainstGoldenFile(
request: RecordedRequest,
goldenFileName: String
) {
logTestMessage("Validating request against golden file $goldenFileName.")

try {
val requestBody = readCompressedRequestBody(request)
logTestMessage("Read request body.")
val goldenFileIS = mContext.assets.open("golden-files/$goldenFileName")

val msg by lazy {
Expand All @@ -278,15 +298,21 @@ internal open class BaseTest {
"adb pull ${observedOutput.absolutePath}\n" +
"observed: $requestBody"
}
logTestMessage("Comparing expected versus observed JSON.")
assertTrue(msg, JsonValidator.areEquals(goldenFileIS, requestBody))
} catch (e: IOException) {
fail("Failed to validate request against golden file. ${e.stackTraceToString()}")
throw IllegalStateException("Failed to validate request against golden file.", e)
}
}

private fun readCompressedRequestBody(request: RecordedRequest): String {
return try {
val data = GZIPInputStream(request.body.inputStream())
val inputStream = request.body.inputStream()
logTestMessage("Opened input stream to request")

val data = GZIPInputStream(inputStream)
logTestMessage("Opened Gzip stream to request")

data.use { String(it.readBytes()) }
} catch (exc: IOException) {
throw IllegalStateException(
Expand All @@ -302,6 +328,7 @@ internal open class BaseTest {
goldenFilename: String,
suffix: String
): File {
logTestMessage("Writing expected/observed output to disk.")
val dir = File(mContext.externalCacheDir, "test_failure").apply { mkdir() }
return File(dir, "${goldenFilename}$suffix").apply {
writeText(requestBody)
Expand All @@ -317,7 +344,9 @@ internal open class BaseTest {
fun readFileContent(failedApiContent: String, failedCallFileName: String) {
val failedApiFilePath = storageDir.path + "/emb_" + failedCallFileName
val failedApiFile = File(failedApiFilePath)
logTestMessage("Reading failed API call at $failedApiFilePath")
GZIPInputStream(failedApiFile.inputStream()).use { stream ->
logTestMessage("Asserting failed API call contains expected content.")
val jsonString = String(stream.readBytes())
assertTrue(jsonString.contains(failedApiContent))
}
Expand All @@ -337,6 +366,7 @@ internal open class BaseTest {
}
}

public const val FAILED_REQUEST_WAIT_TIME_MS: Long = 10000
public const val TOTAL_REQUESTS_AT_INIT: Int = 3
public const val BITMAP_HEIGHT: Int = 100
public const val BITMAP_WIDTH: Int = 100
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@ import io.embrace.android.embracesdk.comms.delivery.PendingApiCalls
import io.embrace.android.embracesdk.internal.serialization.EmbraceSerializer
import java.io.File
import java.io.IOException
import logTestMessage
import org.junit.After
import org.junit.Assert.assertTrue
import org.junit.Assert.fail
Expand All @@ -25,6 +26,7 @@ internal class LogMessageTest : BaseTest() {

@Test
fun logInfoTest() {
logTestMessage("Adding info log to Embrace.")
Embrace.getInstance().logInfo("Test log info")

waitForRequest { request ->
Expand All @@ -34,9 +36,10 @@ internal class LogMessageTest : BaseTest() {

@Test
fun logInfoWithPropertyTest() {
logTestMessage("Adding info log to Embrace.")

val properties = HashMap<String, Any>()
properties["info"] = "test property"

Embrace.getInstance().logMessage("Test log info with property", Severity.INFO, properties)

waitForRequest { request ->
Expand All @@ -56,12 +59,13 @@ internal class LogMessageTest : BaseTest() {
assert(pendingApiCallFileName.isNotBlank())
readFileContent("Test log info fail", pendingApiCallFileName)
} catch (e: IOException) {
fail("IOException error: ${e.message}")
throw IllegalStateException("Failed to validate file context", e)
}
}

@Test
fun logErrorTest() {
logTestMessage("Adding error log to Embrace.")
Embrace.getInstance().logError("Test log error")

waitForRequest { request ->
Expand All @@ -71,6 +75,7 @@ internal class LogMessageTest : BaseTest() {

@Test
fun logErrorWithPropertyTest() {
logTestMessage("Adding error log to Embrace.")
val properties = HashMap<String, Any>()
properties["error"] = "test property"

Expand All @@ -83,6 +88,7 @@ internal class LogMessageTest : BaseTest() {

@Test
fun logExceptionTest() {
logTestMessage("Adding exception log to Embrace.")
Embrace.getInstance().logException(Exception("Another log error"))

waitForRequest { request ->
Expand All @@ -92,6 +98,7 @@ internal class LogMessageTest : BaseTest() {

@Test
fun logErrorWithExceptionAndMessageTest() {
logTestMessage("Adding exception log to Embrace.")
val exception = java.lang.NullPointerException("Exception message")
Embrace.getInstance().logException(exception, Severity.ERROR, mapOf(), "log message")

Expand All @@ -105,6 +112,7 @@ internal class LogMessageTest : BaseTest() {

@Test
fun logWarningTest() {
logTestMessage("Adding warning log to Embrace.")
Embrace.getInstance().logWarning("Test log warning")

waitForRequest { request ->
Expand Down
Loading

0 comments on commit e016c09

Please sign in to comment.