logging: add file-based logging and a Send logs option

Capture logs to rotating app-private files with Subsonic credential and URL basic-auth redaction, mirror to Logcat, and capture uncaught crashes. Log slow SQL (>100ms), SQL errors, migrations and DB lifecycle via a decorating SQLiteDriver. Add a Send logs row in Settings that zips the logs and opens the share sheet through a FileProvider.
2026-11-10 23:21:59 +01:00 · 2026-10-09 07:58:54 +00:00
parent 4012cc0272
commit 7a890094fc
18 changed files with 1084 additions and 26 deletions
@@ -0,0 +1,107 @@
+package com.subtracks.data.db
+
+import androidx.room3.migration.Migration
+import androidx.sqlite.SQLiteConnection
+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.assertNotNull
+import org.junit.Assert.assertNull
+import org.junit.Assert.assertTrue
+import org.junit.Test
+import org.junit.runner.RunWith
+
+@RunWith(AndroidJUnit4::class)
+class DbLoggingTest {
+    private val executions = mutableListOf<SqlExecution>()
+
+    private fun driver() = LoggingSQLiteDriver(BundledSQLiteDriver()) { executions += it }
+
+    @Test
+    fun forwardsConnectionPoolFlag() {
+        val delegate = BundledSQLiteDriver()
+        assertEquals(delegate.hasConnectionPool, LoggingSQLiteDriver(delegate) {}.hasConnectionPool)
+    }
+
+    @Test
+    fun recordsSuccessfulSelect() {
+        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 {
+                it.bindText(1, "a")
+                it.step()
+            }
+            connection.prepare("SELECT * FROM t").use { statement ->
+                while (statement.step()) {
+                }
+            }
+        }
+        val select = executions.last { it.sql.startsWith("SELECT") }
+        assertNull(select.error)
+        assertEquals(1L, select.rows)
+        assertTrue(select.durationNanos > 0)
+    }
+
+    @Test
+    fun recordsPrepareError() {
+        driver().open(":memory:").use { connection ->
+            runCatching { connection.prepare("THIS IS NOT SQL") }
+        }
+        val failed = executions.single()
+        assertNotNull(failed.error)
+        assertEquals("THIS IS NOT SQL", failed.sql)
+    }
+
+    @Test
+    fun recordsStepError() {
+        driver().open(":memory:").use { connection ->
+            connection.prepare("CREATE TABLE t (id INTEGER PRIMARY KEY)").use { it.step() }
+            connection.prepare("INSERT INTO t (id) VALUES (1)").use { it.step() }
+            runCatching {
+                connection.prepare("INSERT INTO t (id) VALUES (1)").use { it.step() }
+            }
+        }
+        val failed = executions.last { it.error != null }
+        assertTrue(failed.sql.startsWith("INSERT"))
+    }
+
+    @Test
+    fun loggedMigrationRunsDelegate() =
+        runTest {
+            val driver = LoggingSQLiteDriver(BundledSQLiteDriver()) {}
+            val migration =
+                LoggedMigration(
+                    object : Migration(1, 2) {
+                        override suspend fun migrate(connection: SQLiteConnection) {
+                            connection.execSQL("CREATE TABLE m (id INTEGER)")
+                        }
+                    },
+                )
+            driver.open(":memory:").use { connection ->
+                migration.migrate(connection)
+                connection.prepare("SELECT count(*) FROM m").use { statement ->
+                    statement.step()
+                    assertEquals(0L, statement.getLong(0))
+                }
+            }
+        }
+
+    @Test
+    fun loggedMigrationRethrows() =
+        runTest {
+            val driver = LoggingSQLiteDriver(BundledSQLiteDriver()) {}
+            val migration =
+                LoggedMigration(
+                    object : Migration(1, 2) {
+                        override suspend fun migrate(connection: SQLiteConnection) {
+                            error("nope")
+                        }
+                    },
+                )
+            driver.open(":memory:").use { connection ->
+                assertTrue(runCatching { migration.migrate(connection) }.isFailure)
+            }
+        }
+}
@@ -0,0 +1,312 @@
+package com.subtracks.data.db
+
+import android.content.Context
+import androidx.paging.PagingSource
+import androidx.room3.Room
+import androidx.sqlite.driver.bundled.BundledSQLiteDriver
+import androidx.test.core.app.ApplicationProvider
+import androidx.test.ext.junit.runners.AndroidJUnit4
+import com.subtracks.data.model.Album
+import com.subtracks.data.model.Artist
+import com.subtracks.data.model.Playlist
+import com.subtracks.data.model.PlaylistSong
+import com.subtracks.data.model.Song
+import com.subtracks.data.model.Source
+import com.subtracks.data.source.MusicSource
+import com.subtracks.data.source.StarType
+import com.subtracks.data.sync.SyncService
+import kotlinx.coroutines.flow.Flow
+import kotlinx.coroutines.flow.first
+import kotlinx.coroutines.flow.flow
+import kotlinx.coroutines.test.runTest
+import org.junit.After
+import org.junit.Before
+import org.junit.Test
+import org.junit.runner.RunWith
+import java.io.File
+import java.util.Collections
+import kotlin.math.max
+
+@RunWith(AndroidJUnit4::class)
+class QueryTimingMeasurementTest {
+    private val executions: MutableList<SqlExecution> = Collections.synchronizedList(mutableListOf())
+    private val timings = linkedMapOf<String, MutableList<Double>>()
+    private lateinit var db: SubtracksDatabase
+
+    @Before
+    fun setUp() {
+        val context = ApplicationProvider.getApplicationContext<Context>()
+        val driver = LoggingSQLiteDriver(BundledSQLiteDriver()) { executions += it }
+        db = Room.inMemoryDatabaseBuilder(context, SubtracksDatabase::class.java).setDriver(driver).build()
+    }
+
+    @After
+    fun tearDown() = db.close()
+
+    @Test
+    fun measure() =
+        runTest {
+            val songCount = System.getProperty("measure.songs")?.toIntOrNull() ?: 20_000
+            val items = items(songCount)
+            db.sourcesDao().upsertSource(
+                Source(id = 1, name = "bench", address = "http://localhost", isActive = true, createdAt = 0),
+            )
+            val source = FakeSource(items)
+
+            executions.clear()
+            val firstSyncMs = wall { SyncService(db, source).sync() }
+            val firstSyncExecutions = executions.toList()
+
+            executions.clear()
+            val secondSyncMs = wall { SyncService(db, source).sync() }
+            val secondSyncExecutions = executions.toList()
+
+            executions.clear()
+            measureReads()
+            val readExecutions = executions.toList()
+
+            val report =
+                buildReport(
+                    songCount = songCount,
+                    firstSyncMs = firstSyncMs,
+                    secondSyncMs = secondSyncMs,
+                    firstSyncExecutions = firstSyncExecutions,
+                    secondSyncExecutions = secondSyncExecutions,
+                    readExecutions = readExecutions,
+                )
+            val out = File("build/query-timing.txt")
+            out.parentFile?.mkdirs()
+            out.writeText(report)
+            print(report)
+        }
+
+    private suspend fun measureReads() {
+        val dao = db.libraryDao()
+        timed("albums first page (name)") { dao.albumsByName(1, 0, "").firstPage() }
+        timed("albums first page (artist)") { dao.albumsByArtist(1, 0, "").firstPage() }
+        timed("albums first page (year)") { dao.albumsByYear(1, 0, "").firstPage() }
+        timed("albums first page (added)") { dao.albumsByRecentlyAdded(1, 0, "").firstPage() }
+        timed("albums first page (starred)") { dao.albumsByStarred(1, 0, "").firstPage() }
+        timed("albums first page (frequent)") { dao.albumsByFrequent(1, 0, "").firstPage() }
+        timed("albums first page (recent)") { dao.albumsByRecent(1, 0, "").firstPage() }
+        timed("artists first page (name)") { dao.artistsByName(1, 0, "").firstPage() }
+        timed("artists first page (frequent)") { dao.artistsByFrequent(1, 0, "").firstPage() }
+        timed("playlists first page (name)") { dao.playlistsByName(1, "").firstPage() }
+        timed("albums deep page") { dao.albumsByName(1, 0, "").deepPage(1000) }
+        timed("albums search FTS") { dao.albumsByName(1, 0, "Album 1").firstPage() }
+        timed("albums search short") { dao.albumsByName(1, 0, "al").firstPage() }
+        timed("songs search FTS") { dao.searchSongs(1, "Song", 50).first() }
+        timed("home recently played") { dao.recentlyPlayedAlbums(1, 20).first() }
+        timed("home most played") { dao.mostPlayedAlbums(1, 20).first() }
+        timed("home recently added") { dao.recentlyAddedAlbums(1, 20).first() }
+        timed("home recently starred") { dao.recentlyStarredSongs(1, 20).first() }
+        timed("home genres") { dao.genresByMostPlayed(1).first() }
+        timed("home decades") { dao.decades(1).first() }
+        timed("recompute play data") { dao.recomputePlayData(1) }
+    }
+
+    private suspend fun <T : Any> PagingSource<Int, T>.firstPage(): List<T> =
+        (
+            load(
+                PagingSource.LoadParams.Refresh(key = null, loadSize = 100, placeholdersEnabled = false),
+            ) as PagingSource.LoadResult.Page
+        ).data
+
+    private suspend fun <T : Any> PagingSource<Int, T>.deepPage(offset: Int): List<T> =
+        (
+            load(
+                PagingSource.LoadParams.Append(key = offset, loadSize = 100, placeholdersEnabled = false),
+            ) as PagingSource.LoadResult.Page
+        ).data
+
+    private suspend fun <T> timed(
+        name: String,
+        iterations: Int = 10,
+        block: suspend () -> T,
+    ) {
+        runCatching { block() }
+        val samples = timings.getOrPut(name) { mutableListOf() }
+        repeat(iterations) {
+            val start = System.nanoTime()
+            val result = runCatching { block() }
+            if (result.isSuccess) samples += (System.nanoTime() - start) / 1e6
+        }
+    }
+
+    private suspend fun wall(block: suspend () -> Unit): Double {
+        val start = System.nanoTime()
+        block()
+        return (System.nanoTime() - start) / 1e6
+    }
+
+    private fun buildReport(
+        songCount: Int,
+        firstSyncMs: Double,
+        secondSyncMs: Double,
+        firstSyncExecutions: List<SqlExecution>,
+        secondSyncExecutions: List<SqlExecution>,
+        readExecutions: List<SqlExecution>,
+    ): String =
+        buildString {
+            appendLine("SQL query timing measurement")
+            appendLine("songs=$songCount  albums=${songCount / 10}  artists=${max(1, songCount / 200)}")
+            appendLine()
+            appendLine("sync: first=%.1fms  second(no-op)=%.1fms".format(firstSyncMs, secondSyncMs))
+            appendLine()
+            appendLine("=== named measurements (ms) ===")
+            appendLine("%-32s %6s %8s %8s %8s %8s".format("measurement", "n", "p50", "p95", "p99", "max"))
+            timings.forEach { (name, samples) ->
+                if (samples.isEmpty()) return@forEach
+                val sorted = samples.sorted()
+                appendLine(
+                    "%-32s %6d %8.2f %8.2f %8.2f %8.2f".format(
+                        name,
+                        sorted.size,
+                        pct(sorted, 50),
+                        pct(sorted, 95),
+                        pct(sorted, 99),
+                        sorted.last(),
+                    ),
+                )
+            }
+            appendLine()
+            appendLine("=== driver executions ===")
+            appendLine(overThresholds("first sync", firstSyncExecutions))
+            appendLine(overThresholds("second sync", secondSyncExecutions))
+            appendLine(overThresholds("reads", readExecutions))
+            appendLine()
+            appendLine("=== slowest first-sync executions ===")
+            firstSyncExecutions.sortedByDescending { it.durationMillis }.take(15).forEach {
+                appendLine("  %8.2fms rows=%-6d %s".format(it.durationMillis, it.rows, it.sql.replace(Regex("\\s+"), " ").take(140)))
+            }
+            appendLine("=== slowest read executions ===")
+            readExecutions.sortedByDescending { it.durationMillis }.take(15).forEach {
+                appendLine("  %8.2fms rows=%-6d %s".format(it.durationMillis, it.rows, it.sql.replace(Regex("\\s+"), " ").take(140)))
+            }
+        }
+
+    private fun overThresholds(
+        label: String,
+        records: List<SqlExecution>,
+    ): String {
+        val thresholds = listOf(10, 25, 50, 100, 250, 500)
+        val counts = thresholds.joinToString { t -> ">${t}ms=${records.count { it.durationMillis > t }}" }
+        return "$label: n=${records.size} $counts"
+    }
+
+    private fun pct(
+        sorted: List<Double>,
+        percentile: Int,
+    ): Double = sorted[((percentile / 100.0) * (sorted.size - 1)).toInt()]
+
+    internal data class Items(
+        val artists: List<Artist>,
+        val albums: List<Album>,
+        val songs: List<Song>,
+        val playlists: List<Playlist>,
+        val playlistSongs: List<PlaylistSong>,
+    )
+
+    private fun items(songCount: Int): Items {
+        val words = listOf("Midnight", "Abbey", "Blue", "Golden", "Silent", "Rolling", "Purple", "Electric")
+        val artistCount = max(1, songCount / 200)
+        val albumCount = max(1, songCount / 10)
+        val artists =
+            (0 until artistCount).map { i ->
+                Artist(sourceId = 1, id = "ar$i", name = "Artist ${words[i % words.size]} $i", albumCount = 10, starred = null)
+            }
+        val albums =
+            (0 until albumCount).map { i ->
+                Album(
+                    sourceId = 1,
+                    id = "al$i",
+                    artistId = "ar${i / 20}",
+                    name = "${words[i % words.size]} Album $i",
+                    albumArtist = "Artist ${i / 20}",
+                    created = 1_000_000L + i,
+                    coverArt = null,
+                    genre = null,
+                    year = (1950 + i % 60).toLong(),
+                    starred = if (i % 11 == 0) 100L + i else null,
+                    songCount = 10,
+                )
+            }
+        val songs =
+            (0 until songCount).map { i ->
+                Song(
+                    sourceId = 1,
+                    id = "s$i",
+                    albumId = "al${i / 10}",
+                    artistId = "ar${i / 200}",
+                    title = "${words[i % words.size]} Song $i",
+                    album = "Album ${i / 10}",
+                    artist = "Artist ${i / 200}",
+                    duration = 200,
+                    track = (i % 10 + 1).toLong(),
+                    disc = 1,
+                    starred = if (i % 7 == 0) 1000L + i else null,
+                    genre = null,
+                    created = 1_000_000L + i,
+                    playCount = (i % 13).toLong(),
+                    played = if (i % 5 == 0) 1_700_000_000_000L + i else null,
+                    genres = listOf("genre${i % 50}"),
+                )
+            }
+        val playlistCount = max(1, songCount / 100)
+        val playlists =
+            (0 until playlistCount).map { i ->
+                Playlist(
+                    sourceId = 1,
+                    id = "pl$i",
+                    name = "Playlist $i",
+                    comment = null,
+                    coverArt = null,
+                    songCount = 20,
+                    created = 1_000_000L + i,
+                    changed = 2_000_000L + i,
+                    duration = 3600,
+                )
+            }
+        val playlistSongs =
+            (0 until playlistCount).flatMap { p ->
+                (0 until 20).map { s -> PlaylistSong(1, "pl$p", "s${(p * 20 + s) % songCount}", s.toLong()) }
+            }
+        return Items(artists, albums, songs, playlists, playlistSongs)
+    }
+}
+
+private class FakeSource(
+    private val items: QueryTimingMeasurementTest.Items,
+    private val batchSize: Int = 500,
+) : MusicSource {
+    override val id: Long = 1
+
+    override suspend fun ping() = Unit
+
+    override suspend fun setStar(
+        type: StarType,
+        id: String,
+        starred: Boolean,
+    ) = Unit
+
+    override suspend fun scrobble(
+        songId: String,
+        submission: Boolean,
+        time: Long?,
+    ) = Unit
+
+    override fun artists(): Flow<List<Artist>> = batches(items.artists)
+
+    override fun albums(): Flow<List<Album>> = batches(items.albums)
+
+    override fun songs(): Flow<List<Song>> = batches(items.songs)
+
+    override fun playlists(): Flow<List<Playlist>> = batches(items.playlists)
+
+    override fun playlistSongs(playlistIds: List<String>): Flow<List<PlaylistSong>> = batches(items.playlistSongs)
+
+    private fun <T> batches(list: List<T>): Flow<List<T>> =
+        flow {
+            list.chunked(batchSize).forEach { emit(it) }
+        }
+}
@@ -0,0 +1,134 @@
+package com.subtracks.log
+
+import com.subtracks.data.db.SqlExecution
+import org.junit.Assert.assertEquals
+import org.junit.Assert.assertFalse
+import org.junit.Assert.assertNull
+import org.junit.Assert.assertTrue
+import org.junit.Rule
+import org.junit.Test
+import org.junit.rules.TemporaryFolder
+import java.io.File
+import java.util.zip.ZipFile
+
+class LogFileStoreTest {
+    @get:Rule
+    val folder = TemporaryFolder()
+
+    private val root: File by lazy { folder.newFolder("logs") }
+
+    @Test
+    fun writesFormattedLine() {
+        val store = LogFileStore(root, LogLevel.VERBOSE)
+        store.write(LogLevel.INFO, "sync", "hello world", null)
+        store.flush()
+        val text = store.files().single().readText()
+        assertTrue(text, Regex("""\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{3} I sync hello world""").containsMatchIn(text))
+    }
+
+    @Test
+    fun redactsSubsonicParams() {
+        val store = LogFileStore(root, LogLevel.VERBOSE)
+        store.write(LogLevel.INFO, "http", "http://host/rest/stream?u=alice&p=hunter2&s=salt&t=tok&id=7", null)
+        store.flush()
+        val text = store.files().single().readText()
+        assertTrue(text, text.contains("u=REDACTED"))
+        assertTrue(text, text.contains("p=REDACTED"))
+        assertTrue(text, text.contains("&id=7"))
+        assertFalse(text, text.contains("hunter2"))
+        assertFalse(text, text.contains("salt"))
+        assertFalse(text, text.contains("tok"))
+    }
+
+    @Test
+    fun redactsBasicAuth() {
+        val store = LogFileStore(root, LogLevel.VERBOSE)
+        store.write(LogLevel.INFO, "http", "http://alice:hunter2@music.example.org/rest/ping", null)
+        store.flush()
+        val text = store.files().single().readText()
+        assertTrue(text, text.contains("http://REDACTED@music.example.org/rest/ping"))
+        assertFalse(text, text.contains("hunter2"))
+    }
+
+    @Test
+    fun includesStackTrace() {
+        val store = LogFileStore(root, LogLevel.VERBOSE)
+        store.write(LogLevel.ERROR, "sql", "boom", IllegalStateException("kaboom"))
+        store.flush()
+        val text = store.files().single().readText()
+        assertTrue(text, text.contains("IllegalStateException: kaboom"))
+    }
+
+    @Test
+    fun dropsBelowMinimumLevel() {
+        val store = LogFileStore(root, LogLevel.WARN)
+        store.write(LogLevel.INFO, "x", "quiet", null)
+        store.write(LogLevel.WARN, "x", "loud", null)
+        store.flush()
+        val text = store.files().single().readText()
+        assertFalse(text, text.contains("quiet"))
+        assertTrue(text, text.contains("loud"))
+    }
+
+    @Test
+    fun rotatesWhenFileExceedsCap() {
+        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)
+    }
+
+    @Test
+    fun prunesToMaxFiles() {
+        val store = LogFileStore(root, LogLevel.VERBOSE, maxFileBytes = 1, maxFiles = 3)
+        repeat(10) { store.write(LogLevel.INFO, "x", "line $it", null) }
+        store.flush()
+        assertEquals(3, store.files().size)
+    }
+
+    @Test
+    fun exportZipContainsLogs() {
+        val store = LogFileStore(root, LogLevel.VERBOSE)
+        store.write(LogLevel.INFO, "x", "one", null)
+        store.flush()
+        val zip = store.exportZip(folder.newFolder("out"))
+        assertTrue(zip != null)
+        ZipFile(zip!!).use { archive ->
+            assertEquals(1, archive.size())
+            assertTrue(
+                archive
+                    .entries()
+                    .nextElement()
+                    .name
+                    .endsWith(".log"),
+            )
+        }
+    }
+
+    @Test
+    fun exportZipIsNullWhenEmpty() {
+        val store = LogFileStore(root, LogLevel.VERBOSE)
+        assertNull(store.exportZip(folder.newFolder("out")))
+    }
+
+    @Test
+    fun slowQueryPredicateExcludesNonQueriesAndInternalSql() {
+        assertTrue(isSlowQuery(execution(150.0, "SELECT * FROM songs"), 100.0))
+        assertFalse(isSlowQuery(execution(50.0, "SELECT * FROM songs"), 100.0))
+        assertFalse(isSlowQuery(execution(150.0, "BEGIN IMMEDIATE TRANSACTION"), 100.0))
+        assertFalse(isSlowQuery(execution(150.0, "SELECT * FROM room_table_modification_log WHERE invalidated = 1"), 100.0))
+    }
+
+    @Test
+    fun classifiesDataStatements() {
+        assertTrue(isDataStatement("insert into t values (1)"))
+        assertTrue(isDataStatement("  SELECT 1"))
+        assertFalse(isDataStatement("PRAGMA user_version"))
+        assertFalse(isDataStatement("END TRANSACTION"))
+    }
+
+    private fun execution(
+        milliseconds: Double,
+        sql: String,
+    ) = SqlExecution(sql, (milliseconds * 1_000_000).toLong(), 0, null)
+}
@@ -362,6 +362,7 @@ class AppScreenshotTest {
                    onAddServer = {},
                    onOpenDownloads = {},
                    onOpenLicenses = {},
+                    onShareLogs = {},
                    onBack = {},
                )
            }
@@ -67,6 +67,7 @@ class LicensesScreenTest {
                    onAddServer = {},
                    onOpenDownloads = {},
                    onOpenLicenses = { opened = true },
+                    onShareLogs = {},
                    onBack = {},
                )
            }