mirror of
https://github.com/d4rken-org/capod.git
synced 2026-09-14 18:26:11 -04:00
feat(debug): Log the device power state while recording
A reception blackout in a capture is as easily the display going off as a broken scan, and nothing in a capture currently says which. The full snapshot is written on every screen, doze and power-save broadcast, plus once when the recording starts, so a single line format answers both "what is it now" and "what just changed". The receiver is registered before the first snapshot is taken: ACTION_SCREEN_OFF is not sticky, so a screen-off in between would appear as neither a transition nor a corrected state. The catch sits on the inner receiver flow rather than after flatMapLatest. Flow.catch completes the flow it is applied to, so a top-level catch would end the recording-flag collection on the first failure and every later recording in the process would carry no power state at all. Nothing here may throw: onReceive is an Android callback outside any flow, so a vendor PowerManager that throws would take the process down. Each field is guarded individually so a bad read costs one value rather than the line.
This commit is contained in:
darken
@@ -6,6 +6,7 @@ import androidx.work.Configuration
|
||||
import dagger.hilt.android.HiltAndroidApp
|
||||
import eu.darken.capod.common.BuildConfigWrap
|
||||
import eu.darken.capod.common.coroutine.AppScope
|
||||
import eu.darken.capod.common.debug.PowerStateLogger
|
||||
import eu.darken.capod.common.debug.autoreport.AutomaticBugReporter
|
||||
import eu.darken.capod.common.debug.logging.LogCatLogger
|
||||
import eu.darken.capod.common.debug.logging.Logging
|
||||
@@ -41,6 +42,7 @@ open class App : Application(), Configuration.Provider {
|
||||
|
||||
@Inject lateinit var workerFactory: HiltWorkerFactory
|
||||
@Inject lateinit var autoReporting: AutomaticBugReporter
|
||||
@Inject lateinit var powerStateLogger: PowerStateLogger
|
||||
@Inject lateinit var deviceMonitor: DeviceMonitor
|
||||
@Inject lateinit var widgetManager: WidgetManager
|
||||
@Inject lateinit var upgradeRepo: UpgradeRepo
|
||||
@@ -69,6 +71,7 @@ open class App : Application(), Configuration.Provider {
|
||||
)
|
||||
|
||||
autoReporting.setup(this)
|
||||
powerStateLogger.setup()
|
||||
|
||||
log(TAG) { "onCreate() done! ${Exception().asLog()}" }
|
||||
|
||||
|
||||
@@ -0,0 +1,117 @@
|
||||
package eu.darken.capod.common.debug
|
||||
|
||||
import android.content.BroadcastReceiver
|
||||
import android.content.Context
|
||||
import android.content.Intent
|
||||
import android.content.IntentFilter
|
||||
import android.os.PowerManager
|
||||
import dagger.hilt.android.qualifiers.ApplicationContext
|
||||
import eu.darken.capod.common.coroutine.AppScope
|
||||
import eu.darken.capod.common.debug.logging.Logging.Priority.ERROR
|
||||
import eu.darken.capod.common.debug.logging.Logging.Priority.INFO
|
||||
import eu.darken.capod.common.debug.logging.Logging.Priority.WARN
|
||||
import eu.darken.capod.common.debug.logging.asLog
|
||||
import eu.darken.capod.common.debug.logging.log
|
||||
import eu.darken.capod.common.debug.logging.logTag
|
||||
import kotlinx.coroutines.CoroutineScope
|
||||
import kotlinx.coroutines.channels.awaitClose
|
||||
import kotlinx.coroutines.flow.Flow
|
||||
import kotlinx.coroutines.flow.callbackFlow
|
||||
import kotlinx.coroutines.flow.catch
|
||||
import kotlinx.coroutines.flow.emptyFlow
|
||||
import kotlinx.coroutines.flow.flatMapLatest
|
||||
import kotlinx.coroutines.flow.launchIn
|
||||
import javax.inject.Inject
|
||||
import javax.inject.Singleton
|
||||
|
||||
/**
|
||||
* A BLE reception blackout can just as well be the display going off as the scan being wrong, and a
|
||||
* capture currently carries no evidence either way. Only active while a debug recording runs.
|
||||
*/
|
||||
@Singleton
|
||||
class PowerStateLogger @Inject constructor(
|
||||
@ApplicationContext private val context: Context,
|
||||
@AppScope private val appScope: CoroutineScope,
|
||||
) {
|
||||
|
||||
fun setup() {
|
||||
Bugs.isDebug
|
||||
.flatMapLatest { isRecording ->
|
||||
if (isRecording) {
|
||||
// The catch belongs to the episode, not to the flag: Flow.catch completes the
|
||||
// flow it is applied to, so catching after flatMapLatest would end the isDebug
|
||||
// collection on the first failure and every later recording in this process
|
||||
// would carry no power state at all.
|
||||
powerStateEvents().catch { log(TAG, ERROR) { "Power state logging failed: ${it.asLog()}" } }
|
||||
} else {
|
||||
emptyFlow()
|
||||
}
|
||||
}
|
||||
.launchIn(appScope)
|
||||
}
|
||||
|
||||
private fun powerStateEvents(): Flow<Unit> = callbackFlow {
|
||||
val receiver = object : BroadcastReceiver() {
|
||||
override fun onReceive(context: Context, intent: Intent) {
|
||||
// Android callback, outside any flow: a throw here takes the process with it.
|
||||
try {
|
||||
logPowerState(intent.action ?: "unknown")
|
||||
} catch (e: Exception) {
|
||||
log(TAG, ERROR) { "Failed to log power state: ${e.asLog()}" }
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
val filter = IntentFilter().apply {
|
||||
addAction(Intent.ACTION_SCREEN_ON)
|
||||
addAction(Intent.ACTION_SCREEN_OFF)
|
||||
addAction(PowerManager.ACTION_DEVICE_IDLE_MODE_CHANGED)
|
||||
addAction(PowerManager.ACTION_POWER_SAVE_MODE_CHANGED)
|
||||
}
|
||||
// Registered before the first snapshot is taken: ACTION_SCREEN_OFF is not sticky, so a
|
||||
// screen-off in between would show up as neither a transition nor a corrected state.
|
||||
context.registerReceiver(receiver, filter)
|
||||
|
||||
logPowerState("recording started")
|
||||
|
||||
awaitClose {
|
||||
try {
|
||||
context.unregisterReceiver(receiver)
|
||||
} catch (e: Exception) {
|
||||
log(TAG, WARN) { "Failed to unregister receiver: ${e.asLog()}" }
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
private fun logPowerState(trigger: String) {
|
||||
val powerManager = try {
|
||||
context.getSystemService(PowerManager::class.java)
|
||||
} catch (e: Exception) {
|
||||
null
|
||||
}
|
||||
val interactive = powerManager.read { isInteractive }
|
||||
val deviceIdle = powerManager.read { isDeviceIdleMode }
|
||||
val powerSave = powerManager.read { isPowerSaveMode }
|
||||
val ignoringBatteryOptimizations = powerManager.read { isIgnoringBatteryOptimizations(context.packageName) }
|
||||
|
||||
log(TAG, INFO) {
|
||||
"Power state ($trigger): interactive=$interactive, deviceIdle=$deviceIdle, " +
|
||||
"powerSave=$powerSave, ignoringBatteryOptimizations=$ignoringBatteryOptimizations"
|
||||
}
|
||||
}
|
||||
|
||||
// Per field, so an OEM PowerManager that throws costs one value instead of the whole line.
|
||||
private fun PowerManager?.read(value: PowerManager.() -> Any?): String {
|
||||
val powerManager = this ?: return UNAVAILABLE
|
||||
return try {
|
||||
powerManager.value()?.toString() ?: UNAVAILABLE
|
||||
} catch (e: Exception) {
|
||||
UNAVAILABLE
|
||||
}
|
||||
}
|
||||
|
||||
companion object {
|
||||
private const val UNAVAILABLE = "unavailable"
|
||||
private val TAG = logTag("Debug", "PowerStateLogger")
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,185 @@
|
||||
package eu.darken.capod.common.debug
|
||||
|
||||
import android.content.BroadcastReceiver
|
||||
import android.content.Context
|
||||
import android.content.ContextWrapper
|
||||
import android.content.Intent
|
||||
import android.content.IntentFilter
|
||||
import android.os.Looper
|
||||
import android.os.PowerManager
|
||||
import androidx.test.core.app.ApplicationProvider
|
||||
import eu.darken.capod.common.debug.logging.Logging
|
||||
import io.kotest.matchers.collections.shouldHaveSize
|
||||
import io.kotest.matchers.shouldBe
|
||||
import io.kotest.matchers.string.shouldContain
|
||||
import io.mockk.every
|
||||
import io.mockk.mockk
|
||||
import kotlinx.coroutines.test.runCurrent
|
||||
import kotlinx.coroutines.test.runTest
|
||||
import org.junit.After
|
||||
import org.junit.Before
|
||||
import org.junit.Test
|
||||
import org.junit.runner.RunWith
|
||||
import org.robolectric.RobolectricTestRunner
|
||||
import org.robolectric.Shadows.shadowOf
|
||||
import org.robolectric.annotation.Config
|
||||
import testhelpers.BaseTest
|
||||
import testhelpers.TestApplication
|
||||
import java.util.concurrent.CopyOnWriteArrayList
|
||||
|
||||
/**
|
||||
* Screen-off is one of the two explanations for a BLE reception blackout, and a debug capture
|
||||
* carries no evidence for it unless the state is written into the log while the recording runs.
|
||||
*/
|
||||
@RunWith(RobolectricTestRunner::class)
|
||||
@Config(application = TestApplication::class)
|
||||
class PowerStateLoggerTest : BaseTest() {
|
||||
|
||||
private val logLines = CopyOnWriteArrayList<String>()
|
||||
private val logCapture = object : Logging.Logger {
|
||||
override fun log(priority: Logging.Priority, tag: String, message: String, metaData: Map<String, Any>?) {
|
||||
logLines.add(message)
|
||||
}
|
||||
}
|
||||
|
||||
private val context: Context get() = ApplicationProvider.getApplicationContext()
|
||||
private val powerManager: PowerManager get() = context.getSystemService(PowerManager::class.java)
|
||||
|
||||
@Before
|
||||
fun setup() {
|
||||
Bugs.isDebug.value = false
|
||||
Logging.install(logCapture)
|
||||
}
|
||||
|
||||
@After
|
||||
fun teardown() {
|
||||
Logging.remove(logCapture)
|
||||
Bugs.isDebug.value = false
|
||||
}
|
||||
|
||||
private fun powerLines() = logLines.filter { it.startsWith("Power state") }
|
||||
|
||||
private fun broadcast(action: String) {
|
||||
context.sendBroadcast(Intent(action))
|
||||
shadowOf(Looper.getMainLooper()).idle()
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `a starting recording logs the current power state`() = runTest {
|
||||
shadowOf(powerManager).setIsInteractive(true)
|
||||
shadowOf(powerManager).setIgnoringBatteryOptimizations(context.packageName, true)
|
||||
|
||||
PowerStateLogger(context, backgroundScope).setup()
|
||||
runCurrent()
|
||||
|
||||
Bugs.isDebug.value = true
|
||||
runCurrent()
|
||||
|
||||
powerLines() shouldHaveSize 1
|
||||
powerLines().single() shouldBe "Power state (recording started): interactive=true, deviceIdle=false, " +
|
||||
"powerSave=false, ignoringBatteryOptimizations=true"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `a screen-off is logged with the state that came with it`() = runTest {
|
||||
PowerStateLogger(context, backgroundScope).setup()
|
||||
runCurrent()
|
||||
Bugs.isDebug.value = true
|
||||
runCurrent()
|
||||
|
||||
shadowOf(powerManager).setIsInteractive(false)
|
||||
broadcast(Intent.ACTION_SCREEN_OFF)
|
||||
|
||||
powerLines() shouldHaveSize 2
|
||||
powerLines().last() shouldContain "Power state (${Intent.ACTION_SCREEN_OFF})"
|
||||
powerLines().last() shouldContain "interactive=false"
|
||||
}
|
||||
|
||||
@Test
|
||||
fun `a stopped recording stops the logging`() = runTest {
|
||||
PowerStateLogger(context, backgroundScope).setup()
|
||||
runCurrent()
|
||||
Bugs.isDebug.value = true
|
||||
runCurrent()
|
||||
|
||||
Bugs.isDebug.value = false
|
||||
runCurrent()
|
||||
|
||||
broadcast(Intent.ACTION_SCREEN_OFF)
|
||||
|
||||
powerLines() shouldHaveSize 1
|
||||
}
|
||||
|
||||
/**
|
||||
* onReceive runs as an Android callback outside any flow, so a PowerManager that throws would
|
||||
* take the process down instead of costing a log line.
|
||||
*/
|
||||
@Test
|
||||
fun `an unreadable power manager degrades the line instead of the process`() = runTest {
|
||||
val throwing = mockk<PowerManager>().apply {
|
||||
every { isInteractive } throws RuntimeException("vendor power manager")
|
||||
every { isDeviceIdleMode } throws RuntimeException("vendor power manager")
|
||||
every { isPowerSaveMode } throws RuntimeException("vendor power manager")
|
||||
every { isIgnoringBatteryOptimizations(any()) } throws RuntimeException("vendor power manager")
|
||||
}
|
||||
|
||||
PowerStateLogger(ServiceOverrideContext(context, throwing), backgroundScope).setup()
|
||||
runCurrent()
|
||||
Bugs.isDebug.value = true
|
||||
runCurrent()
|
||||
|
||||
broadcast(Intent.ACTION_SCREEN_OFF)
|
||||
|
||||
powerLines() shouldHaveSize 2
|
||||
powerLines().last() shouldBe "Power state (${Intent.ACTION_SCREEN_OFF}): interactive=unavailable, " +
|
||||
"deviceIdle=unavailable, powerSave=unavailable, ignoringBatteryOptimizations=unavailable"
|
||||
}
|
||||
|
||||
/**
|
||||
* A failure inside one recording must not end the collection of the recording flag itself,
|
||||
* otherwise every later recording in the process silently carries no power state at all.
|
||||
*/
|
||||
@Test
|
||||
fun `a failed episode does not stop later recordings from logging`() = runTest {
|
||||
val flaky = FailFirstRegistrationContext(context)
|
||||
|
||||
PowerStateLogger(flaky, backgroundScope).setup()
|
||||
runCurrent()
|
||||
|
||||
Bugs.isDebug.value = true
|
||||
runCurrent()
|
||||
|
||||
powerLines() shouldHaveSize 0
|
||||
logLines.any { it.startsWith("Power state logging failed") } shouldBe true
|
||||
|
||||
Bugs.isDebug.value = false
|
||||
runCurrent()
|
||||
Bugs.isDebug.value = true
|
||||
runCurrent()
|
||||
|
||||
powerLines() shouldHaveSize 1
|
||||
powerLines().single() shouldContain "Power state (recording started)"
|
||||
}
|
||||
|
||||
private class ServiceOverrideContext(
|
||||
base: Context,
|
||||
private val powerManager: PowerManager,
|
||||
) : ContextWrapper(base) {
|
||||
override fun getSystemService(name: String): Any? = when (name) {
|
||||
Context.POWER_SERVICE -> powerManager
|
||||
else -> super.getSystemService(name)
|
||||
}
|
||||
}
|
||||
|
||||
private class FailFirstRegistrationContext(base: Context) : ContextWrapper(base) {
|
||||
private var failNext = true
|
||||
|
||||
override fun registerReceiver(receiver: BroadcastReceiver?, filter: IntentFilter?): Intent? {
|
||||
if (failNext) {
|
||||
failNext = false
|
||||
throw SecurityException("receiver registration denied")
|
||||
}
|
||||
return super.registerReceiver(receiver, filter)
|
||||
}
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user