From 8fe26a36b1a91070d77723567cb23a5f405196ae Mon Sep 17 00:00:00 2001 From: austinried <4966622+austinried@users.noreply.github.com> Date: Thu, 8 Oct 2026 19:42:27 +0000 Subject: [PATCH] logging: make the writer total and harden export Never let a log-write or export failure reach the uncaught handler: wrap the async writer and crash path, synchronize export with rotation, and tolerate vanished files. Redact the Logcat stack-trace copy, stop leaking rows=0 on writes, shut down the previous writer on re-init, and drop unused API. Strengthen tests for the batched write path, rotation count and throwable redaction. --- .../kotlin/com/subtracks/data/db/DbLogging.kt | 3 ++ app/src/main/kotlin/com/subtracks/log/Log.kt | 21 ++++---- .../kotlin/com/subtracks/log/LogFileStore.kt | 48 +++++++++---------- .../subtracks/ui/settings/SettingsScreen.kt | 19 +++++--- app/src/main/res/values/strings.xml | 1 + .../com/subtracks/data/db/DbLoggingTest.kt | 28 ++++++++++- .../com/subtracks/log/LogFileStoreTest.kt | 25 +++++++++- 7 files changed, 102 insertions(+), 43 deletions(-) diff --git a/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt b/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt index b62cd807..558be462 100644 --- a/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt +++ b/app/src/main/kotlin/com/subtracks/data/db/DbLogging.kt @@ -6,6 +6,7 @@ import androidx.sqlite.SQLiteConnection import androidx.sqlite.SQLiteDriver import androidx.sqlite.SQLiteStatement import com.subtracks.log.Log +import kotlinx.coroutines.CancellationException data class SqlExecution( val sql: String, @@ -102,6 +103,8 @@ class LoggedMigration( val start = System.nanoTime() try { delegate.migrate(connection) + } catch (cancellation: CancellationException) { + throw cancellation } catch (failure: Throwable) { Log.e("sql", "migration $label failed after ${(System.nanoTime() - start) / 1_000_000}ms", failure) throw failure diff --git a/app/src/main/kotlin/com/subtracks/log/Log.kt b/app/src/main/kotlin/com/subtracks/log/Log.kt index 7134a58f..a63ab126 100644 --- a/app/src/main/kotlin/com/subtracks/log/Log.kt +++ b/app/src/main/kotlin/com/subtracks/log/Log.kt @@ -28,16 +28,12 @@ object Log { appContext = app consoleLevel = if (BuildConfig.DEBUG) LogLevel.VERBOSE else LogLevel.INFO val fileLevel = if (BuildConfig.DEBUG) LogLevel.DEBUG else LogLevel.INFO + fileStore?.shutdown() fileStore = LogFileStore(File(app.filesDir, "logs"), fileLevel) installCrashHandler() i("app", "started ${BuildConfig.VERSION_NAME} (${BuildConfig.VERSION_CODE}) on Android ${Build.VERSION.SDK_INT} ${Build.MODEL}") } - fun v( - tag: String, - message: String, - ) = log(LogLevel.VERBOSE, tag, message, null) - fun d( tag: String, message: String, @@ -60,8 +56,6 @@ object Log { throwable: Throwable? = null, ) = log(LogLevel.ERROR, tag, message, throwable) - fun files(): List = fileStore?.files().orEmpty() - fun exportZip(): File? { val store = fileStore ?: return null val context = appContext ?: return null @@ -109,7 +103,8 @@ object Log { return } if (!isSlowQuery(execution, SLOW_QUERY_MS)) return - w("sql", "slow ${execution.durationMillis.roundToLong()}ms rows=${execution.rows}: ${shortSql(execution.sql)}") + val rows = if (isReadStatement(execution.sql)) " rows=${execution.rows}" else "" + w("sql", "slow ${execution.durationMillis.roundToLong()}ms$rows: ${shortSql(execution.sql)}") } private fun log( @@ -120,7 +115,12 @@ object Log { ) { val redacted = redactLogs(message) if (level.ordinal >= consoleLevel.ordinal) { - val text = if (throwable != null) "$redacted\n${AndroidLog.getStackTraceString(throwable)}" else redacted + val text = + if (throwable != null) { + "$redacted\n${redactLogs(AndroidLog.getStackTraceString(throwable))}" + } else { + redacted + } AndroidLog.println(priority(level), tag.take(23), text) } fileStore?.write(level, tag, redacted, throwable) @@ -151,6 +151,7 @@ object Log { } private val DATA_KEYWORDS = setOf("SELECT", "INSERT", "UPDATE", "DELETE", "WITH", "REPLACE") +private val READ_KEYWORDS = setOf("SELECT", "WITH") private const val SQL_INTERNAL = "room_table_modification_log" internal fun isDataStatement(sql: String): Boolean { @@ -159,6 +160,8 @@ internal fun isDataStatement(sql: String): Boolean { return normalized.takeWhile { !it.isWhitespace() }.uppercase() in DATA_KEYWORDS } +internal fun isReadStatement(sql: String): Boolean = sql.trimStart().takeWhile { !it.isWhitespace() }.uppercase() in READ_KEYWORDS + internal fun isSlowQuery( execution: SqlExecution, thresholdMs: Double, diff --git a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt index cf671f9f..b7087671 100644 --- a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt +++ b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt @@ -10,15 +10,6 @@ import java.util.zip.ZipOutputStream enum class LogLevel { VERBOSE, DEBUG, INFO, WARN, ERROR } -fun interface LogSink { - fun log( - level: LogLevel, - tag: String, - message: String, - throwable: Throwable?, - ) -} - class LogFileStore( private val rootDir: File, private val minLevel: LogLevel, @@ -31,7 +22,6 @@ class LogFileStore( } private val lock = Any() private val dateFormat = SimpleDateFormat("yyyy-MM-dd", Locale.US) - private val stampFormat = SimpleDateFormat("yyyy-MM-dd-HHmmss-SSS", Locale.US) private val lineFormat = SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS", Locale.US) private var current = currentFile() @@ -42,7 +32,9 @@ class LogFileStore( throwable: Throwable?, ) { if (level.ordinal < minLevel.ordinal) return - executor.execute { synchronized(lock) { append(level, tag, message, throwable) } } + runCatching { + executor.execute { runCatching { synchronized(lock) { append(level, tag, message, throwable) } } } + } } fun writeImmediately( @@ -52,11 +44,15 @@ class LogFileStore( throwable: Throwable?, ) { if (level.ordinal < minLevel.ordinal) return - synchronized(lock) { append(level, tag, message, throwable) } + runCatching { synchronized(lock) { append(level, tag, message, throwable) } } } fun flush() { - executor.submit {}.get() + runCatching { executor.submit {}.get() } + } + + fun shutdown() { + executor.shutdownNow() } fun files(): List = @@ -65,20 +61,22 @@ class LogFileStore( ?.sortedByDescending { it.lastModified() } .orEmpty() - fun exportZip(destDir: File): File? { - val logs = files() - if (logs.isEmpty()) return null - destDir.mkdirs() - val zip = File(destDir, "subtracks-logs-${stampFormat.format(Date())}.zip") - ZipOutputStream(zip.outputStream().buffered()).use { out -> - logs.forEach { log -> - out.putNextEntry(ZipEntry(log.name)) - log.inputStream().use { it.copyTo(out) } - out.closeEntry() + fun exportZip(destDir: File): File? = + synchronized(lock) { + val logs = files() + if (logs.isEmpty()) return null + destDir.mkdirs() + val zip = File(destDir, "subtracks-logs-${System.currentTimeMillis()}.zip") + ZipOutputStream(zip.outputStream().buffered()).use { out -> + logs.forEach { log -> + if (!log.isFile) return@forEach + out.putNextEntry(ZipEntry(log.name)) + log.inputStream().use { it.copyTo(out) } + out.closeEntry() + } } + zip } - return zip - } private fun append( level: LogLevel, diff --git a/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt b/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt index 3423256f..81f98940 100644 --- a/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt +++ b/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt @@ -129,12 +129,19 @@ fun SettingsRoute( onOpenLicenses = onOpenLicenses, onShareLogs = { scope.launch { - val zip = withContext(Dispatchers.IO) { Log.exportZip() } - if (zip != null) { - Log.share(context, zip) - } else { - Toast.makeText(context, R.string.settings_about_share_logs_empty, Toast.LENGTH_SHORT).show() - } + val result = + runCatching { + val zip = withContext(Dispatchers.IO) { Log.exportZip() } + if (zip != null) Log.share(context, zip) + zip + } + val message = + when { + result.isFailure -> R.string.settings_about_share_logs_failed + result.getOrNull() == null -> R.string.settings_about_share_logs_empty + else -> null + } + message?.let { Toast.makeText(context, it, Toast.LENGTH_SHORT).show() } } }, onBack = onBack, diff --git a/app/src/main/res/values/strings.xml b/app/src/main/res/values/strings.xml index 3e441827..5a7c0916 100644 --- a/app/src/main/res/values/strings.xml +++ b/app/src/main/res/values/strings.xml @@ -60,6 +60,7 @@ Send logs Share the recent app logs with the developer No logs to send yet + Couldn\'t prepare the logs Subtracks logs Support the developer About diff --git a/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt b/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt index 1d494412..c6ea39f3 100644 --- a/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt +++ b/app/src/test/kotlin/com/subtracks/data/db/DbLoggingTest.kt @@ -2,11 +2,13 @@ package com.subtracks.data.db import androidx.room3.migration.Migration import androidx.sqlite.SQLiteConnection +import androidx.sqlite.SQLiteDriver import androidx.sqlite.driver.bundled.BundledSQLiteDriver import androidx.sqlite.execSQL import androidx.test.ext.junit.runners.AndroidJUnit4 import kotlinx.coroutines.test.runTest import org.junit.Assert.assertEquals +import org.junit.Assert.assertFalse import org.junit.Assert.assertNotNull import org.junit.Assert.assertNull import org.junit.Assert.assertTrue @@ -21,8 +23,24 @@ class DbLoggingTest { @Test fun forwardsConnectionPoolFlag() { - val delegate = BundledSQLiteDriver() - assertEquals(delegate.hasConnectionPool, LoggingSQLiteDriver(delegate) {}.hasConnectionPool) + assertTrue(LoggingSQLiteDriver(FakeDriver(hasConnectionPool = true)) {}.hasConnectionPool) + assertFalse(LoggingSQLiteDriver(FakeDriver(hasConnectionPool = false)) {}.hasConnectionPool) + } + + @Test + fun recordsOneExecutionPerBatchedWriteRow() { + driver().open(":memory:").use { connection -> + connection.prepare("CREATE TABLE t (id INTEGER PRIMARY KEY, name TEXT)").use { it.step() } + connection.prepare("INSERT INTO t (name) VALUES (?)").use { statement -> + repeat(3) { index -> + statement.bindText(1, "row$index") + statement.step() + statement.reset() + statement.clearBindings() + } + } + } + assertEquals(3, executions.count { it.sql.startsWith("INSERT") }) } @Test @@ -105,3 +123,9 @@ class DbLoggingTest { } } } + +private class FakeDriver( + override val hasConnectionPool: Boolean, +) : SQLiteDriver { + override fun open(fileName: String): SQLiteConnection = error("open should not be called") +} diff --git a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt index af8745e5..238466f8 100644 --- a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt +++ b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt @@ -59,6 +59,22 @@ class LogFileStoreTest { assertTrue(text, text.contains("IllegalStateException: kaboom")) } + @Test + fun redactsCredentialsInThrowable() { + val store = LogFileStore(root, LogLevel.VERBOSE) + store.write( + LogLevel.ERROR, + "http", + "failed", + IllegalStateException("GET http://alice:secret@host/x?u=bob&p=hunter2 failed"), + ) + store.flush() + val text = store.files().single().readText() + assertTrue(text, text.contains("REDACTED@host")) + assertFalse(text, text.contains("secret")) + assertFalse(text, text.contains("hunter2")) + } + @Test fun dropsBelowMinimumLevel() { val store = LogFileStore(root, LogLevel.WARN) @@ -75,7 +91,7 @@ class LogFileStoreTest { val store = LogFileStore(root, LogLevel.VERBOSE, maxFileBytes = 1) repeat(4) { store.write(LogLevel.INFO, "x", "line $it", null) } store.flush() - assertTrue(store.files().size >= 4) + assertEquals(4, store.files().size) } @Test @@ -127,6 +143,13 @@ class LogFileStoreTest { assertFalse(isDataStatement("END TRANSACTION")) } + @Test + fun classifiesReadStatements() { + assertTrue(isReadStatement("select * from songs")) + assertTrue(isReadStatement("WITH x AS (SELECT 1) SELECT * FROM x")) + assertFalse(isReadStatement("INSERT INTO t VALUES (1)")) + } + private fun execution( milliseconds: Double, sql: String,