diff --git a/app/src/main/java/eu/darken/capod/App.kt b/app/src/main/java/eu/darken/capod/App.kt index ad817dff..06124c5e 100644 --- a/app/src/main/java/eu/darken/capod/App.kt +++ b/app/src/main/java/eu/darken/capod/App.kt @@ -1,17 +1,13 @@ package eu.darken.capod import android.app.Application -import android.os.Looper import dagger.hilt.android.HiltAndroidApp import eu.darken.capod.common.coroutine.AppScope -import eu.darken.capod.common.debug.Bugs import eu.darken.capod.common.debug.autoreport.AutomaticBugReporter import eu.darken.capod.common.debug.logging.LogCatLogger import eu.darken.capod.common.debug.logging.Logging import eu.darken.capod.common.debug.logging.asLog -import eu.darken.capod.common.debug.logging.Logging.Priority.ERROR import eu.darken.capod.common.debug.logging.Logging.Priority.VERBOSE -import eu.darken.capod.common.debug.logging.Logging.Priority.WARN import eu.darken.capod.common.debug.logging.log import eu.darken.capod.common.debug.logging.logTag import eu.darken.capod.common.flow.throttleLatest @@ -29,9 +25,7 @@ import kotlinx.coroutines.flow.map import kotlinx.coroutines.flow.onEach import kotlinx.coroutines.flow.distinctUntilChanged import kotlinx.coroutines.launch -import java.util.concurrent.atomic.AtomicBoolean import javax.inject.Inject -import kotlin.system.exitProcess @HiltAndroidApp open class App : Application() { @@ -46,22 +40,8 @@ open class App : Application() { super.onCreate() if (BuildConfig.DEBUG) Logging.install(LogCatLogger()) - val foregroundExceptionHandled = AtomicBoolean(false) val oldHandler = Thread.getDefaultUncaughtExceptionHandler() - Thread.setDefaultUncaughtExceptionHandler { thread, throwable -> - val isTimingExc = throwable.isForegroundServiceTimingException() - val isMain = thread === Looper.getMainLooper().thread - if (isTimingExc && isMain && foregroundExceptionHandled.compareAndSet(false, true)) { - runCatching { - log(TAG, WARN) { "Suppressed foreground service timing exception: ${throwable.asLog()}" } - Bugs.report(tag = TAG, "Foreground service timing exception suppressed", exception = throwable) - } - Looper.loop() - return@setDefaultUncaughtExceptionHandler - } - runCatching { log(TAG, ERROR) { "UNCAUGHT EXCEPTION: ${throwable.asLog()}" } } - if (oldHandler != null) oldHandler.uncaughtException(thread, throwable) else exitProcess(1) - } + Thread.setDefaultUncaughtExceptionHandler(CapodUncaughtExceptionHandler(oldHandler)) autoReporting.setup(this) @@ -90,14 +70,5 @@ open class App : Application() { companion object { internal val TAG = logTag("CAP") - - private fun Throwable.isForegroundServiceTimingException(): Boolean { - var current: Throwable? = this - while (current != null) { - if (current.javaClass.simpleName == "ForegroundServiceDidNotStartInTimeException") return true - current = current.cause - } - return false - } } } diff --git a/app/src/main/java/eu/darken/capod/CapodUncaughtExceptionHandler.kt b/app/src/main/java/eu/darken/capod/CapodUncaughtExceptionHandler.kt new file mode 100644 index 00000000..4bef99ec --- /dev/null +++ b/app/src/main/java/eu/darken/capod/CapodUncaughtExceptionHandler.kt @@ -0,0 +1,71 @@ +package eu.darken.capod + +import android.os.Looper +import eu.darken.capod.common.debug.Bugs +import eu.darken.capod.common.debug.logging.Logging.Priority.ERROR +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 java.util.concurrent.atomic.AtomicBoolean +import kotlin.system.exitProcess + +internal class CapodUncaughtExceptionHandler( + private val previousHandler: Thread.UncaughtExceptionHandler?, + private val mainThreadProvider: () -> Thread = { Looper.getMainLooper().thread }, + private val loopMainThread: () -> Unit = { Looper.loop() }, + private val reportForegroundServiceTimingException: (Throwable) -> Unit = { throwable -> + Bugs.report( + tag = App.TAG, + message = "Foreground service timing exception suppressed", + exception = throwable, + ) + }, + private val exit: (Int) -> Unit = { exitProcess(it) }, +) : Thread.UncaughtExceptionHandler { + + private val foregroundExceptionHandled = AtomicBoolean(false) + + override fun uncaughtException(thread: Thread, throwable: Throwable) { + if (shouldSuppress(thread, throwable)) { + runCatching { + log(App.TAG, WARN) { "Suppressed foreground service timing exception: ${throwable.asLog()}" } + reportForegroundServiceTimingException(throwable) + } + + val loopResult = runCatching { loopMainThread() } + if (loopResult.isSuccess) return + + val loopFailure = loopResult.exceptionOrNull()!! + runCatching { + log(App.TAG, ERROR) { + "Main loop failed after foreground service timing exception suppression: ${loopFailure.asLog()}" + } + } + delegate(thread, loopFailure) + return + } + + runCatching { log(App.TAG, ERROR) { "UNCAUGHT EXCEPTION: ${throwable.asLog()}" } } + delegate(thread, throwable) + } + + private fun shouldSuppress(thread: Thread, throwable: Throwable): Boolean { + val isMainThread = runCatching { thread === mainThreadProvider() }.getOrDefault(false) + return throwable.isForegroundServiceTimingException() && + isMainThread && + foregroundExceptionHandled.compareAndSet(false, true) + } + + private fun delegate(thread: Thread, throwable: Throwable) { + previousHandler?.uncaughtException(thread, throwable) ?: exit(1) + } +} + +internal fun Throwable.isForegroundServiceTimingException(): Boolean { + var current: Throwable? = this + while (current != null) { + if (current.javaClass.simpleName == "ForegroundServiceDidNotStartInTimeException") return true + current = current.cause + } + return false +} diff --git a/app/src/main/java/eu/darken/capod/common/debug/Bugs.kt b/app/src/main/java/eu/darken/capod/common/debug/Bugs.kt index 56ec2972..0b97ea3a 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/Bugs.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/Bugs.kt @@ -5,6 +5,7 @@ import eu.darken.capod.common.debug.logging.Logging.Priority.ERROR import eu.darken.capod.common.debug.logging.Logging.Priority.VERBOSE 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.asLogSummary import eu.darken.capod.common.debug.logging.log import eu.darken.capod.common.debug.logging.logTag @@ -15,13 +16,20 @@ object Bugs { message: String, exception: Throwable ) { - log(TAG, VERBOSE) { "Reporting $exception" } - log(tag, ERROR) { "$message\n${exception.asLog()}" } + runCatching { log(TAG, VERBOSE) { "Reporting ${exception.asLogSummary()}" } } + runCatching { log(tag, ERROR) { "$message\n${exception.asLog()}" } } - reporter?.notify(exception) ?: run { - log(TAG, WARN) { "Bug tracking not initialized yet." } + val bugReporter = reporter + if (bugReporter == null) { + runCatching { log(TAG, WARN) { "Bug tracking not initialized yet." } } + return } + + runCatching { bugReporter.notify(exception) } + .onFailure { failure -> + runCatching { log(TAG, WARN) { "Bug reporter failed: ${failure.asLog()}" } } + } } private val TAG = logTag("Bugs") -} \ No newline at end of file +} diff --git a/app/src/main/java/eu/darken/capod/common/debug/logging/Logging.kt b/app/src/main/java/eu/darken/capod/common/debug/logging/Logging.kt index 673f54d7..9ebedd7f 100644 --- a/app/src/main/java/eu/darken/capod/common/debug/logging/Logging.kt +++ b/app/src/main/java/eu/darken/capod/common/debug/logging/Logging.kt @@ -61,16 +61,19 @@ object Logging { message: String ) { val snapshot = synchronized(internalLoggers) { internalLoggers.toList() } - snapshot - .filter { it.isLoggable(priority) } - .forEach { - it.log( - priority = priority, - tag = tag, - metaData = metaData, - message = message - ) + snapshot.forEach { + val isLoggable = runCatching { it.isLoggable(priority) }.getOrDefault(false) + if (isLoggable) { + runCatching { + it.log( + priority = priority, + tag = tag, + metaData = metaData, + message = message + ) + } } + } } fun clearAll() { @@ -110,14 +113,28 @@ inline fun log( } } -fun Throwable.asLog(): String { +fun Throwable.asLog(): String = runCatching { val stringWriter = StringWriter(256) val printWriter = PrintWriter(stringWriter, false) printStackTrace(printWriter) printWriter.flush() - return stringWriter.toString() + stringWriter.toString() +}.getOrElse { renderFailure -> + "${asLogSummary()}\n" } +fun Throwable.asLogSummary(): String { + val throwableClass = javaClass.name + val throwableMessage = safeMessage() + return if (throwableMessage.isNullOrBlank()) { + throwableClass + } else { + "$throwableClass: $throwableMessage" + } +} + +private fun Throwable.safeMessage(): String? = runCatching { message }.getOrNull() + @PublishedApi internal fun Any.logTagViaCallSite(): String { val javaClass = this::class.java diff --git a/app/src/test/java/eu/darken/capod/CapodUncaughtExceptionHandlerTest.kt b/app/src/test/java/eu/darken/capod/CapodUncaughtExceptionHandlerTest.kt new file mode 100644 index 00000000..99c65fc3 --- /dev/null +++ b/app/src/test/java/eu/darken/capod/CapodUncaughtExceptionHandlerTest.kt @@ -0,0 +1,119 @@ +package eu.darken.capod + +import io.kotest.matchers.shouldBe +import org.junit.jupiter.api.Test +import testhelpers.BaseTest + +class CapodUncaughtExceptionHandlerTest : BaseTest() { + + @Test + fun `suppresses first main thread foreground service timing exception`() { + val mainThread = Thread.currentThread() + val previousHandler = RecordingHandler() + val reports = mutableListOf() + var loopCalls = 0 + val handler = CapodUncaughtExceptionHandler( + previousHandler = previousHandler, + mainThreadProvider = { mainThread }, + loopMainThread = { loopCalls++ }, + reportForegroundServiceTimingException = { reports += it }, + exit = { throw AssertionError("exitProcess($it)") }, + ) + val throwable = ForegroundServiceDidNotStartInTimeException() + + handler.uncaughtException(mainThread, throwable) + + loopCalls shouldBe 1 + reports shouldBe listOf(throwable) + previousHandler.throwables shouldBe emptyList() + } + + @Test + fun `delegates repeated main thread foreground service timing exception`() { + val mainThread = Thread.currentThread() + val previousHandler = RecordingHandler() + val reports = mutableListOf() + var loopCalls = 0 + val handler = CapodUncaughtExceptionHandler( + previousHandler = previousHandler, + mainThreadProvider = { mainThread }, + loopMainThread = { loopCalls++ }, + reportForegroundServiceTimingException = { reports += it }, + exit = { throw AssertionError("exitProcess($it)") }, + ) + val first = ForegroundServiceDidNotStartInTimeException() + val second = ForegroundServiceDidNotStartInTimeException() + + handler.uncaughtException(mainThread, first) + handler.uncaughtException(mainThread, second) + + loopCalls shouldBe 1 + reports shouldBe listOf(first) + previousHandler.throwables shouldBe listOf(second) + } + + @Test + fun `delegates foreground service timing exception from non-main thread`() { + val mainThread = Thread.currentThread() + val workerThread = Thread() + val previousHandler = RecordingHandler() + val handler = CapodUncaughtExceptionHandler( + previousHandler = previousHandler, + mainThreadProvider = { mainThread }, + loopMainThread = { throw AssertionError("loopMainThread should not run") }, + reportForegroundServiceTimingException = { throw AssertionError("report should not run") }, + exit = { throw AssertionError("exitProcess($it)") }, + ) + val throwable = ForegroundServiceDidNotStartInTimeException() + + handler.uncaughtException(workerThread, throwable) + + previousHandler.throwables shouldBe listOf(throwable) + } + + @Test + fun `delegates unrelated main thread exception`() { + val mainThread = Thread.currentThread() + val previousHandler = RecordingHandler() + val handler = CapodUncaughtExceptionHandler( + previousHandler = previousHandler, + mainThreadProvider = { mainThread }, + loopMainThread = { throw AssertionError("loopMainThread should not run") }, + reportForegroundServiceTimingException = { throw AssertionError("report should not run") }, + exit = { throw AssertionError("exitProcess($it)") }, + ) + val throwable = IllegalStateException("boom") + + handler.uncaughtException(mainThread, throwable) + + previousHandler.throwables shouldBe listOf(throwable) + } + + @Test + fun `delegates loop failure after suppression`() { + val mainThread = Thread.currentThread() + val previousHandler = RecordingHandler() + val loopFailure = IllegalStateException("loop failed") + val handler = CapodUncaughtExceptionHandler( + previousHandler = previousHandler, + mainThreadProvider = { mainThread }, + loopMainThread = { throw loopFailure }, + reportForegroundServiceTimingException = {}, + exit = { throw AssertionError("exitProcess($it)") }, + ) + + handler.uncaughtException(mainThread, ForegroundServiceDidNotStartInTimeException()) + + previousHandler.throwables shouldBe listOf(loopFailure) + } + + private class RecordingHandler : Thread.UncaughtExceptionHandler { + val throwables = mutableListOf() + + override fun uncaughtException(thread: Thread, throwable: Throwable) { + throwables += throwable + } + } + + private class ForegroundServiceDidNotStartInTimeException : RuntimeException("timed out") +} diff --git a/app/src/test/java/eu/darken/capod/common/debug/BugsTest.kt b/app/src/test/java/eu/darken/capod/common/debug/BugsTest.kt new file mode 100644 index 00000000..881ed3ae --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/debug/BugsTest.kt @@ -0,0 +1,71 @@ +package eu.darken.capod.common.debug + +import android.app.Application +import eu.darken.capod.common.debug.autoreport.AutomaticBugReporter +import eu.darken.capod.common.debug.logging.Logging +import io.kotest.assertions.throwables.shouldNotThrowAny +import io.kotest.matchers.shouldBe +import org.junit.jupiter.api.AfterEach +import org.junit.jupiter.api.Test +import testhelpers.BaseTest + +class BugsTest : BaseTest() { + + @AfterEach + fun cleanup() { + Bugs.reporter = null + Logging.clearAll() + } + + @Test + fun `report does not throw if logging fails`() { + Logging.clearAll() + Logging.install(ThrowingLogger()) + + shouldNotThrowAny { + Bugs.report(TAG, "Something failed", HostileThrowable()) + } + } + + @Test + fun `report does not throw if reporter fails`() { + var notified = false + Bugs.reporter = object : AutomaticBugReporter { + override fun setup(application: Application) = Unit + + override fun notify(throwable: Throwable) { + notified = true + throw IllegalStateException("reporter failed") + } + } + + shouldNotThrowAny { + Bugs.report(TAG, "Something failed", IllegalStateException("boom")) + } + notified shouldBe true + } + + private class HostileThrowable : Throwable() { + override val message: String? + get() = throw IllegalStateException("message failed") + + override fun toString(): String = throw IllegalStateException("toString failed") + } + + private class ThrowingLogger : Logging.Logger { + override fun isLoggable(priority: Logging.Priority): Boolean = true + + override fun log( + priority: Logging.Priority, + tag: String, + message: String, + metaData: Map? + ) { + throw IllegalStateException("log failed") + } + } + + companion object { + private const val TAG = "TEST" + } +} diff --git a/app/src/test/java/eu/darken/capod/common/debug/logging/LoggingTest.kt b/app/src/test/java/eu/darken/capod/common/debug/logging/LoggingTest.kt new file mode 100644 index 00000000..7e2e7520 --- /dev/null +++ b/app/src/test/java/eu/darken/capod/common/debug/logging/LoggingTest.kt @@ -0,0 +1,53 @@ +package eu.darken.capod.common.debug.logging + +import io.kotest.matchers.shouldBe +import org.junit.jupiter.api.Test +import testhelpers.BaseTest + +class LoggingTest : BaseTest() { + + @Test + fun `asLog renders normal throwable`() { + val log = IllegalStateException("boom").asLog() + + log.contains("java.lang.IllegalStateException: boom") shouldBe true + log.contains("LoggingTest") shouldBe true + } + + @Test + fun `asLog falls back when throwable rendering fails`() { + val log = HostileThrowable().asLog() + + log.contains("HostileThrowable") shouldBe true + log.contains("stacktrace unavailable") shouldBe true + } + + @Test + fun `logInternal ignores logger failures`() { + Logging.install(ThrowingLogger()) + + log("TEST") { "message" } + } + + private class HostileThrowable : Throwable() { + override val message: String? + get() = throw IllegalStateException("message failed") + + override fun toString(): String = throw IllegalStateException("toString failed") + } + + private class ThrowingLogger : Logging.Logger { + override fun isLoggable(priority: Logging.Priority): Boolean { + throw IllegalStateException("isLoggable failed") + } + + override fun log( + priority: Logging.Priority, + tag: String, + message: String, + metaData: Map? + ) { + throw IllegalStateException("log failed") + } + } +}