java.io.FileNotFoundException: http://localhost:9001/status - PerfettoHttpServer [329145808]

Fixed

Bug

Status Update

No update yet.

Description

en...@meta.com

created issue #1

Mar 12, 2024 09:25AM

Component used: Version used: Benchmark-Macro v1.2.3 Devices/Android versions reproduced on: Android emulator (API 30)

If this is a bug in the library, we would appreciate if you could attach:

Sample project to trigger the issue.
A screenrecord or screenshots showing the issue (if UI related).

Using v1.2.3 of the benchmark-macro library on an emulator is yielding the below error which hangs my test.

I have attempted to add android:usesCleartextTraffic="true" to my instrumentation apk and confirmed that it was present in the merged manifest for the instrumentation apk. I also did a get request to the same url via adb shell which yielded a http status code 200 via "nc localhost 9001" with a "GET /status HTTP/1.1" request which yielded the following response for the perfetto server:

HTTP/1.1 200 OK
Cache-Control: no-cache
Content-Type: application/x-protobuf
Transfer-Encoding: identity
Content-Length: 73
Connection: keep-alive

I do notice that the perfetto log for starting the server successfully happens after the failure so I'm wondering if there's a race between the 2 processes.

Error stack trace:

03-11 23:23:12.827  6794  6816 E TestRunner: java.io.FileNotFoundException: http://localhost:9001/status
03-11 23:23:12.827  6794  6816 E TestRunner:    at com.android.okhttp.internal.huc.HttpURLConnectionImpl.getInputStream(HttpURLConnectionImpl.java:255)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.perfetto.server.PerfettoHttpServer.httpRequest(PerfettoHttpServer.kt:289)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.perfetto.server.PerfettoHttpServer.httpRequest$default(PerfettoHttpServer.kt:270)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.perfetto.server.PerfettoHttpServer.status(PerfettoHttpServer.kt:263)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.perfetto.server.PerfettoHttpServer.isRunning(PerfettoHttpServer.kt:185)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.perfetto.server.PerfettoHttpServer.startServer(PerfettoHttpServer.kt:135)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.perfetto.PerfettoTraceProcessor.startServer(PerfettoTraceProcessor.kt:289)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.perfetto.PerfettoTraceProcessor.access$startServer(PerfettoTraceProcessor.kt:74)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.perfetto.PerfettoTraceProcessor$Companion.runServer(PerfettoTraceProcessor.kt:101)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmark(Macrobenchmark.kt:241)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmarkWithStartupMode(Macrobenchmark.kt:422)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.junit4.MacrobenchmarkRule.measureRepeated(MacrobenchmarkRule.kt:107)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.junit4.MacrobenchmarkRule.measureRepeated$default(MacrobenchmarkRule.kt:97)
03-11 23:23:12.827  6794  6816 E TestRunner:    at XXXXXXX.ColdStartNoneTest.coldStart(ColdStartNoneTest.kt:23)
03-11 23:23:12.827  6794  6816 E TestRunner:    at java.lang.reflect.Method.invoke(Native Method)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
03-11 23:23:12.827  6794  6816 E TestRunner:    at com.facebook.testing.jetpackbenchmark.JetpackBenchmarkRunner$2.evaluate(JetpackBenchmarkRunner.java:82)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.benchmark.macro.junit4.MacrobenchmarkRule$applyInternal$1.evaluate(MacrobenchmarkRule.kt:133)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.test.rule.GrantPermissionRule$RequestPermissionStatement.evaluate(GrantPermissionRule.java:136)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.rules.RunRules.evaluate(RunRules.java:20)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:128)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:27)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
03-11 23:23:12.827  6794  6816 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:67)
03-11 23:23:12.827  6794  6816 E TestRunner:    at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:58)
03-11 23:23:12.827  6794  6816 E TestRunner:    at com.facebook.testing.instrumentation.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:497)
03-11 23:23:12.827  6794  6816 E TestRunner:    at com.facebook.testing.instrumentation.FbInstrumentationTestRunner.onStart(FbInstrumentationTestRunner.java:198)
03-11 23:23:12.827  6794  6816 E TestRunner:    at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2211)
03-11 23:23:12.830  6953  6953 W perfetto:             httpd.cc:99 [HTTP] Starting RPC server on localhost:9001
03-11 23:23:12.831  6953  6953 I perfetto:            httpd.cc:104 [HTTP] This server can be used by reloading https://ui.perfetto.dev and clicking on YES on the "Trace Processor native acceleration" dialog or through the Python API (see https://perfetto.dev/docs/analysis/trace-processor#python-api).

Comments

cc...@google.com <cc...@google.com> Apr 1, 2024 05:40PM

Reassigned to ma...@google.com.

en...@meta.com <en...@meta.com> #2Apr 8, 2024 03:21AM

Yigit, do you have time to fix it?

reemission of the same liveData is racy

ma...@google.com <ma...@google.com> #3Apr 22, 2024 11:16PM

Accepted by ma...@google.com.

yea i'll take it.

Message last modified on Apr 22, 2024 11:26PM

ap...@google.com <ap...@google.com> #4Apr 23, 2024 12:17AM

Thanks for the detailed analysis. This may not be an issue anymore since we've started using Main.immediate there but I' not sure; I'll try to create a test case.

ma...@google.com <ma...@google.com> Apr 23, 2024 03:32PM

Marked as fixed.

en...@meta.com <en...@meta.com> #5Apr 28, 2024 09:30PM

just emitting same live data reproduces the issue.

@Test
fun raceTest() {
val subLiveData = MutableLiveData(1)
val subject = liveData(testScope.coroutineContext) {
emitSource(subLiveData)
emitSource(subLiveData) //crashes
}
subject.addObserver().apply {
testScope.advanceUntilIdle()
}
}

ma...@google.com <ma...@google.com> #6Apr 29, 2024 04:03PM

With 2.2.0-alpha04 (that use Main.immediate), the issue seems to be still there (I tested it by calling emitSource() twice, like your test case)

en...@meta.com <en...@meta.com> #7Apr 30, 2024 03:04AM

yea sorry immediate does not fix it.
I actually have a WIP fix for it:

https://android-review.googlesource.com/c/platform/frameworks/support/+/1112186

if your case is the one i found (emitting same LiveData multiple times, as shown in #5) you can work around it by adding a dummy transformation.

val subLiveData = MutableLiveData(1)
val subject = liveData(testScope.coroutineContext) {
emitSource(subLiveData.map {it })
emitSource(subLiveData.map {it} )
}

ma...@google.com <ma...@google.com> #8Apr 30, 2024 04:41PM

Project: platform/frameworks/support
Branch: androidx-master-dev

commit af12e75e6b4110f48e44ca121466943909de8f06
Author: Yigit Boyar <yboyar@google.com>
Date: Tue Sep 03 12:58:11 2019

Fix coroutine livedata race condition

This CL fixes a bug in liveData builder where emitting same
LiveData source twice would make it crash because the second
emission registry could possibly happen before first one is
removed as source.

We fix it by using a suspending dispose function. It does feel
a bit hacky but we cannot make DisposableHandle.dispose async
and we do not want to block there. This does not mean that there
is a problem if developer disposes it manually since our emit
functions take care of making sure it disposes (and there is
no other way to add source to the underlying MediatorLiveData)

Bug: 140249349
Test: BuildLiveDataTest#raceTest_*

Change-Id: I0b464c242a583da4669af195cf2504e2adc4de40

M lifecycle/lifecycle-livedata-ktx/api/2.2.0-alpha05.txt
M lifecycle/lifecycle-livedata-ktx/api/current.txt
M lifecycle/lifecycle-livedata-ktx/api/public_plus_experimental_2.2.0-alpha05.txt
M lifecycle/lifecycle-livedata-ktx/api/public_plus_experimental_current.txt
M lifecycle/lifecycle-livedata-ktx/api/restricted_2.2.0-alpha05.txt
M lifecycle/lifecycle-livedata-ktx/api/restricted_current.txt
M lifecycle/lifecycle-livedata-ktx/src/main/java/androidx/lifecycle/CoroutineLiveData.kt
M lifecycle/lifecycle-livedata-ktx/src/test/java/androidx/lifecycle/BuildLiveDataTest.kt

https://android-review.googlesource.com/1112186

https://goto.google.com/android-sha1/af12e75e6b4110f48e44ca121466943909de8f06

ap...@google.com <ap...@google.com> #9Apr 30, 2024 05:28PM

Project: platform/frameworks/support
Branch: androidx-main

commit 8c32f5e6f64a40fc30c85da98646f814ef2fdb0e
Author: Marcello Albano <maralb@google.com>
Date: Tue Apr 30 09:46:58 2024

Increased default start timeout for perfetto trace processor

Test: n/a
Bug: 329145808
Change-Id: I87e8c9ec3472db0aafb908b590a9a91f6e9e5ed8

M benchmark/benchmark-macro/src/main/java/androidx/benchmark/perfetto/PerfettoTraceProcessor.kt

https://android-review.googlesource.com/3066627

en...@meta.com <en...@meta.com> #10Apr 30, 2024 07:15PM

Thank you!

pr...@google.com <pr...@google.com> #11May 14, 2024 05:21PM

The following release(s) address this bug.It is possible this bug has only been partially addressed:

androidx.benchmark:benchmark-macro:1.3.0-alpha05