From 6ed0bf8257a3da42f42332d8bf0b495a7c363b86 Mon Sep 17 00:00:00 2001 From: darken Date: Mon, 31 Aug 2026 18:47:52 +0200 Subject: [PATCH] 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. --- app/src/main/java/eu/darken/capod/App.kt | 3 + .../capod/common/debug/PowerStateLogger.kt | 117 +++++++++++ .../common/debug/PowerStateLoggerTest.kt | 185 ++++++++++++++++++ 3 files changed, 305 insertions(+) create mode 100644 app/src/main/java/eu/darken/capod/common/debug/PowerStateLogger.kt create mode 100644 app/src/test/java/eu/darken/capod/common/debug/PowerStateLoggerTest.kt diff --git a/app/src/main/java/eu/darken/capod/App.kt b/app/src/main/java/eu/darken/capod/App.kt index 28790f85..0f60f0c1 100644 --- a/app/src/main/java/eu/darken/capod/App.kt +++ b/app/src/main/java/eu/darken/capod/App.kt @@ -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()}" } diff --git a/app/src/main/java/eu/darken/capod/common/debug/PowerStateLogger.kt b/app/src/main/java/eu/darken/capod/common/debug/PowerStateLogger.kt new file mode 100644 index 00000000..b58b7fe3 --- /dev/null +++ b/app/src/main/java/eu/darken/capod/common/debug/PowerStateLogger.kt @@ -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 = 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") + } +} diff --git a/app/src/test/java/eu/darken/capod/common/debug/PowerStateLoggerTest.kt b/app/src/test/java/eu/darken/capod/common/debug/PowerStateLoggerTest.kt new file mode 100644 index 00000000..8e797d0e --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/debug/PowerStateLoggerTest.kt @@ -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() + private val logCapture = object : Logging.Logger { + override fun log(priority: Logging.Priority, tag: String, message: String, metaData: Map?) { + 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().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) + } + } +}