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.
This commit is contained in:
austinried
2026-10-09 07:58:55 +00:00
parent 7a890094fc
commit 8fe26a36b1
7 changed files with 102 additions and 43 deletions
@@ -6,6 +6,7 @@ import androidx.sqlite.SQLiteConnection
import androidx.sqlite.SQLiteDriver import androidx.sqlite.SQLiteDriver
import androidx.sqlite.SQLiteStatement import androidx.sqlite.SQLiteStatement
import com.subtracks.log.Log import com.subtracks.log.Log
import kotlinx.coroutines.CancellationException
data class SqlExecution( data class SqlExecution(
val sql: String, val sql: String,
@@ -102,6 +103,8 @@ class LoggedMigration(
val start = System.nanoTime() val start = System.nanoTime()
try { try {
delegate.migrate(connection) delegate.migrate(connection)
} catch (cancellation: CancellationException) {
throw cancellation
} catch (failure: Throwable) { } catch (failure: Throwable) {
Log.e("sql", "migration $label failed after ${(System.nanoTime() - start) / 1_000_000}ms", failure) Log.e("sql", "migration $label failed after ${(System.nanoTime() - start) / 1_000_000}ms", failure)
throw failure throw failure
+12 -9
View File
@@ -28,16 +28,12 @@ object Log {
appContext = app appContext = app
consoleLevel = if (BuildConfig.DEBUG) LogLevel.VERBOSE else LogLevel.INFO consoleLevel = if (BuildConfig.DEBUG) LogLevel.VERBOSE else LogLevel.INFO
val fileLevel = if (BuildConfig.DEBUG) LogLevel.DEBUG else LogLevel.INFO val fileLevel = if (BuildConfig.DEBUG) LogLevel.DEBUG else LogLevel.INFO
fileStore?.shutdown()
fileStore = LogFileStore(File(app.filesDir, "logs"), fileLevel) fileStore = LogFileStore(File(app.filesDir, "logs"), fileLevel)
installCrashHandler() installCrashHandler()
i("app", "started ${BuildConfig.VERSION_NAME} (${BuildConfig.VERSION_CODE}) on Android ${Build.VERSION.SDK_INT} ${Build.MODEL}") 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( fun d(
tag: String, tag: String,
message: String, message: String,
@@ -60,8 +56,6 @@ object Log {
throwable: Throwable? = null, throwable: Throwable? = null,
) = log(LogLevel.ERROR, tag, message, throwable) ) = log(LogLevel.ERROR, tag, message, throwable)
fun files(): List<File> = fileStore?.files().orEmpty()
fun exportZip(): File? { fun exportZip(): File? {
val store = fileStore ?: return null val store = fileStore ?: return null
val context = appContext ?: return null val context = appContext ?: return null
@@ -109,7 +103,8 @@ object Log {
return return
} }
if (!isSlowQuery(execution, SLOW_QUERY_MS)) 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( private fun log(
@@ -120,7 +115,12 @@ object Log {
) { ) {
val redacted = redactLogs(message) val redacted = redactLogs(message)
if (level.ordinal >= consoleLevel.ordinal) { 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) AndroidLog.println(priority(level), tag.take(23), text)
} }
fileStore?.write(level, tag, redacted, throwable) 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 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" private const val SQL_INTERNAL = "room_table_modification_log"
internal fun isDataStatement(sql: String): Boolean { 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 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( internal fun isSlowQuery(
execution: SqlExecution, execution: SqlExecution,
thresholdMs: Double, thresholdMs: Double,
@@ -10,15 +10,6 @@ import java.util.zip.ZipOutputStream
enum class LogLevel { VERBOSE, DEBUG, INFO, WARN, ERROR } enum class LogLevel { VERBOSE, DEBUG, INFO, WARN, ERROR }
fun interface LogSink {
fun log(
level: LogLevel,
tag: String,
message: String,
throwable: Throwable?,
)
}
class LogFileStore( class LogFileStore(
private val rootDir: File, private val rootDir: File,
private val minLevel: LogLevel, private val minLevel: LogLevel,
@@ -31,7 +22,6 @@ class LogFileStore(
} }
private val lock = Any() private val lock = Any()
private val dateFormat = SimpleDateFormat("yyyy-MM-dd", Locale.US) 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 val lineFormat = SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS", Locale.US)
private var current = currentFile() private var current = currentFile()
@@ -42,7 +32,9 @@ class LogFileStore(
throwable: Throwable?, throwable: Throwable?,
) { ) {
if (level.ordinal < minLevel.ordinal) return 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( fun writeImmediately(
@@ -52,11 +44,15 @@ class LogFileStore(
throwable: Throwable?, throwable: Throwable?,
) { ) {
if (level.ordinal < minLevel.ordinal) return if (level.ordinal < minLevel.ordinal) return
synchronized(lock) { append(level, tag, message, throwable) } runCatching { synchronized(lock) { append(level, tag, message, throwable) } }
} }
fun flush() { fun flush() {
executor.submit {}.get() runCatching { executor.submit {}.get() }
}
fun shutdown() {
executor.shutdownNow()
} }
fun files(): List<File> = fun files(): List<File> =
@@ -65,19 +61,21 @@ class LogFileStore(
?.sortedByDescending { it.lastModified() } ?.sortedByDescending { it.lastModified() }
.orEmpty() .orEmpty()
fun exportZip(destDir: File): File? { fun exportZip(destDir: File): File? =
synchronized(lock) {
val logs = files() val logs = files()
if (logs.isEmpty()) return null if (logs.isEmpty()) return null
destDir.mkdirs() destDir.mkdirs()
val zip = File(destDir, "subtracks-logs-${stampFormat.format(Date())}.zip") val zip = File(destDir, "subtracks-logs-${System.currentTimeMillis()}.zip")
ZipOutputStream(zip.outputStream().buffered()).use { out -> ZipOutputStream(zip.outputStream().buffered()).use { out ->
logs.forEach { log -> logs.forEach { log ->
if (!log.isFile) return@forEach
out.putNextEntry(ZipEntry(log.name)) out.putNextEntry(ZipEntry(log.name))
log.inputStream().use { it.copyTo(out) } log.inputStream().use { it.copyTo(out) }
out.closeEntry() out.closeEntry()
} }
} }
return zip zip
} }
private fun append( private fun append(
@@ -129,12 +129,19 @@ fun SettingsRoute(
onOpenLicenses = onOpenLicenses, onOpenLicenses = onOpenLicenses,
onShareLogs = { onShareLogs = {
scope.launch { scope.launch {
val result =
runCatching {
val zip = withContext(Dispatchers.IO) { Log.exportZip() } val zip = withContext(Dispatchers.IO) { Log.exportZip() }
if (zip != null) { if (zip != null) Log.share(context, zip)
Log.share(context, zip) zip
} else {
Toast.makeText(context, R.string.settings_about_share_logs_empty, Toast.LENGTH_SHORT).show()
} }
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, onBack = onBack,
+1
View File
@@ -60,6 +60,7 @@
<string name="settings_about_actions_share_logs">Send logs</string> <string name="settings_about_actions_share_logs">Send logs</string>
<string name="settings_about_actions_share_logs_description">Share the recent app logs with the developer</string> <string name="settings_about_actions_share_logs_description">Share the recent app logs with the developer</string>
<string name="settings_about_share_logs_empty">No logs to send yet</string> <string name="settings_about_share_logs_empty">No logs to send yet</string>
<string name="settings_about_share_logs_failed">Couldn\'t prepare the logs</string>
<string name="settings_about_share_logs_subject">Subtracks logs</string> <string name="settings_about_share_logs_subject">Subtracks logs</string>
<string name="settings_about_actions_support">Support the developer</string> <string name="settings_about_actions_support">Support the developer</string>
<string name="settings_about_name">About</string> <string name="settings_about_name">About</string>
@@ -2,11 +2,13 @@ package com.subtracks.data.db
import androidx.room3.migration.Migration import androidx.room3.migration.Migration
import androidx.sqlite.SQLiteConnection import androidx.sqlite.SQLiteConnection
import androidx.sqlite.SQLiteDriver
import androidx.sqlite.driver.bundled.BundledSQLiteDriver import androidx.sqlite.driver.bundled.BundledSQLiteDriver
import androidx.sqlite.execSQL import androidx.sqlite.execSQL
import androidx.test.ext.junit.runners.AndroidJUnit4 import androidx.test.ext.junit.runners.AndroidJUnit4
import kotlinx.coroutines.test.runTest import kotlinx.coroutines.test.runTest
import org.junit.Assert.assertEquals import org.junit.Assert.assertEquals
import org.junit.Assert.assertFalse
import org.junit.Assert.assertNotNull import org.junit.Assert.assertNotNull
import org.junit.Assert.assertNull import org.junit.Assert.assertNull
import org.junit.Assert.assertTrue import org.junit.Assert.assertTrue
@@ -21,8 +23,24 @@ class DbLoggingTest {
@Test @Test
fun forwardsConnectionPoolFlag() { fun forwardsConnectionPoolFlag() {
val delegate = BundledSQLiteDriver() assertTrue(LoggingSQLiteDriver(FakeDriver(hasConnectionPool = true)) {}.hasConnectionPool)
assertEquals(delegate.hasConnectionPool, LoggingSQLiteDriver(delegate) {}.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 @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")
}
@@ -59,6 +59,22 @@ class LogFileStoreTest {
assertTrue(text, text.contains("IllegalStateException: kaboom")) 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 @Test
fun dropsBelowMinimumLevel() { fun dropsBelowMinimumLevel() {
val store = LogFileStore(root, LogLevel.WARN) val store = LogFileStore(root, LogLevel.WARN)
@@ -75,7 +91,7 @@ class LogFileStoreTest {
val store = LogFileStore(root, LogLevel.VERBOSE, maxFileBytes = 1) val store = LogFileStore(root, LogLevel.VERBOSE, maxFileBytes = 1)
repeat(4) { store.write(LogLevel.INFO, "x", "line $it", null) } repeat(4) { store.write(LogLevel.INFO, "x", "line $it", null) }
store.flush() store.flush()
assertTrue(store.files().size >= 4) assertEquals(4, store.files().size)
} }
@Test @Test
@@ -127,6 +143,13 @@ class LogFileStoreTest {
assertFalse(isDataStatement("END TRANSACTION")) 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( private fun execution(
milliseconds: Double, milliseconds: Double,
sql: String, sql: String,