From 779131c766977e833ea797078f8236820111c395 Mon Sep 17 00:00:00 2001 From: austinried <4966622+austinried@users.noreply.github.com> Date: Fri, 9 Oct 2026 07:58:51 +0000 Subject: [PATCH] logging: address review of the breadcrumbs Drop the non-distinct song comparison (sum of album song counts double-counts compilations), skip redaction for dropped lines via a level check, defer the startup prune off the main thread and cap the writer queue, and only warn about a stall against the still-current player. Reward the scrobble info line and cover the new preferences/level toggles with tests. --- .../com/subtracks/data/sync/SyncManager.kt | 3 +-- .../com/subtracks/data/sync/SyncService.kt | 4 ---- app/src/main/kotlin/com/subtracks/log/Log.kt | 7 +++++-- .../kotlin/com/subtracks/log/LogFileStore.kt | 21 ++++++++++++++++--- .../subtracks/playback/PlaybackController.kt | 2 +- .../com/subtracks/playback/Scrobbler.kt | 2 +- .../data/prefs/UserPreferencesTest.kt | 15 +++++++++++++ .../com/subtracks/log/LogFileStoreTest.kt | 13 ++++++++++++ 8 files changed, 54 insertions(+), 13 deletions(-) diff --git a/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt b/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt index 4520dcac..a0f19b57 100644 --- a/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt +++ b/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt @@ -69,8 +69,7 @@ class SyncManager( Log.i( "sync", "finished in ${elapsedMs(startedAt)}ms: " + - "${summary.artists} artists, ${summary.albums} albums, " + - "${summary.songs} songs (server reported ${summary.reportedSongs}), " + + "${summary.artists} artists, ${summary.albums} albums, ${summary.songs} songs, " + "${summary.playlists} playlists, ${summary.playlistSongs} playlist tracks, ${summary.pruned} pruned", ) SyncStatus.Success diff --git a/app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt b/app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt index 2965426f..5e4b8ac7 100644 --- a/app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt +++ b/app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt @@ -26,7 +26,6 @@ class SyncService( private var playlistsSynced = 0 private var playlistSongsSynced = 0 private var pruned = 0 - private var reportedSongs = 0L suspend fun sync(): SyncSummary { syncArtists() @@ -42,7 +41,6 @@ class SyncService( playlists = playlistsSynced, playlistSongs = playlistSongsSynced, pruned = pruned, - reportedSongs = reportedSongs, ) } @@ -72,7 +70,6 @@ class SyncService( batch.forEach { seenAlbums.add(idHash(it.id)) } discs.forEach { seenDiscs.add(discHash(it.albumId, it.disc)) } albumsSynced += batch.size - reportedSongs += batch.sumOf { it.songCount } } pruned += pruneStaleIds(seenAlbums, { library.albumIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteAlbums(source.id, it) }) pruned += @@ -241,7 +238,6 @@ data class SyncSummary( val playlists: Int, val playlistSongs: Int, val pruned: Int, - val reportedSongs: Long, ) private const val DELETE_CHUNK = 500 diff --git a/app/src/main/kotlin/com/subtracks/log/Log.kt b/app/src/main/kotlin/com/subtracks/log/Log.kt index 975ba273..9afcc2b1 100644 --- a/app/src/main/kotlin/com/subtracks/log/Log.kt +++ b/app/src/main/kotlin/com/subtracks/log/Log.kt @@ -131,8 +131,11 @@ object Log { message: String, throwable: Throwable?, ) { + val toConsole = level.ordinal >= consoleLevel.ordinal + val store = fileStore + if (!toConsole && store?.willLog(level) != true) return val redacted = redactLogs(message) - if (level.ordinal >= consoleLevel.ordinal) { + if (toConsole) { // Logging is best effort: a logcat write must never disturb the caller. runCatching { val text = @@ -144,7 +147,7 @@ object Log { AndroidLog.println(priority(level), tag.take(23), text) } } - fileStore?.write(level, tag, redacted, throwable) + store?.write(level, tag, redacted, throwable) } private fun priority(level: LogLevel): Int = diff --git a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt index d85e86bd..5d91aac2 100644 --- a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt +++ b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt @@ -5,6 +5,7 @@ import java.text.SimpleDateFormat import java.util.Date import java.util.Locale import java.util.concurrent.Executors +import java.util.concurrent.atomic.AtomicInteger import java.util.zip.ZipEntry import java.util.zip.ZipOutputStream @@ -21,14 +22,18 @@ class LogFileStore( Thread(runnable, "log-writer").apply { isDaemon = true } } private val lock = Any() + private val pending = AtomicInteger() private val dateFormat = SimpleDateFormat("yyyy-MM-dd", Locale.US) private val lineFormat = SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS", Locale.US) private var current = currentFile() init { - prune() + // Log.init runs in Application.onCreate, so clean up leftovers on the writer thread. + runCatching { executor.execute { synchronized(lock) { prune() } } } } + fun willLog(level: LogLevel): Boolean = level.ordinal >= minLevel.ordinal + fun write( level: LogLevel, tag: String, @@ -36,9 +41,18 @@ class LogFileStore( throwable: Throwable?, ) { if (level.ordinal < minLevel.ordinal) return + // Drop under pressure rather than grow the queue without bound (verbose logs every request). + if (pending.get() >= MAX_PENDING) return + pending.incrementAndGet() runCatching { - executor.execute { runCatching { synchronized(lock) { append(level, tag, message, throwable) } } } - } + executor.execute { + try { + synchronized(lock) { append(level, tag, message, throwable) } + } finally { + pending.decrementAndGet() + } + } + }.onFailure { pending.decrementAndGet() } } fun writeImmediately( @@ -151,6 +165,7 @@ class LogFileStore( companion object { const val DEFAULT_MAX_FILE_BYTES = 1L * 1024 * 1024 const val DEFAULT_MAX_FILES = 7 + private const val MAX_PENDING = 4096 private const val LOG_SUFFIX = ".log" private val LEVEL_CHARS = charArrayOf('V', 'D', 'I', 'W', 'E') } diff --git a/app/src/main/kotlin/com/subtracks/playback/PlaybackController.kt b/app/src/main/kotlin/com/subtracks/playback/PlaybackController.kt index 0c0b1186..7e33a0cc 100644 --- a/app/src/main/kotlin/com/subtracks/playback/PlaybackController.kt +++ b/app/src/main/kotlin/com/subtracks/playback/PlaybackController.kt @@ -1491,7 +1491,7 @@ class PlaybackController( stallJob = scope.launch { delay(STALL_WATCHDOG_MS) - if (player.isBuffering && player.playWhenReady) { + if (player === this@PlaybackController.player && player.isBuffering && player.playWhenReady) { stalled = true val item = player.currentItem Log.w( diff --git a/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt b/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt index 8d0b263c..f8dbd97d 100644 --- a/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt +++ b/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt @@ -134,7 +134,7 @@ class Scrobbler( } is Scrobble.Submission -> { - Log.i("scrobble", "submitted ${event.songId}") + Log.i("scrobble", "submitting ${event.songId}") attempt("record play ${event.songId}") { recordPlay(event.songId, event.time / 1000) } attempt("scrobble ${event.songId}") { sink.scrobble(event.songId, event.time) } } diff --git a/app/src/test/kotlin/com/subtracks/data/prefs/UserPreferencesTest.kt b/app/src/test/kotlin/com/subtracks/data/prefs/UserPreferencesTest.kt index 4a584a09..941163ee 100644 --- a/app/src/test/kotlin/com/subtracks/data/prefs/UserPreferencesTest.kt +++ b/app/src/test/kotlin/com/subtracks/data/prefs/UserPreferencesTest.kt @@ -173,6 +173,21 @@ class UserPreferencesTest { prefs.setLastSeed(ArtworkSeedValue("art:2", 0xFF778899.toInt(), null)) assertEquals(ArtworkSeedValue("art:2", 0xFF778899.toInt(), null), prefs.lastSeed()) + file.delete() + } + + @Test + fun verboseLoggingDefaultsOffAndRoundTrips() = + runTest { + val file = File.createTempFile("user-prefs", ".preferences_pb").apply { delete() } + val store = PreferenceDataStoreFactory.create(scope = backgroundScope) { file } + val prefs = UserPreferences(store) + + assertEquals(false, prefs.verboseLogging().first()) + + prefs.setVerboseLogging(true) + assertEquals(true, prefs.verboseLogging().first()) + file.delete() } } diff --git a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt index 0f70a53c..bd04e1e1 100644 --- a/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt +++ b/app/src/test/kotlin/com/subtracks/log/LogFileStoreTest.kt @@ -86,6 +86,19 @@ class LogFileStoreTest { assertTrue(text, text.contains("loud")) } + @Test + fun setMinLevelChangesWhatIsWritten() { + val store = LogFileStore(root, LogLevel.WARN) + store.setMinLevel(LogLevel.VERBOSE) + store.write(LogLevel.VERBOSE, "x", "verbose-line", null) + store.setMinLevel(LogLevel.ERROR) + store.write(LogLevel.INFO, "x", "info-line", null) + store.flush() + val text = store.files().single().readText() + assertTrue(text, text.contains("verbose-line")) + assertFalse(text, text.contains("info-line")) + } + @Test fun rotatesWhenFileExceedsCap() { val store = LogFileStore(root, LogLevel.VERBOSE, maxFileBytes = 1)