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.
This commit is contained in:
austinried
2026-10-09 07:58:55 +00:00
parent 9695d83b1a
commit 779131c766
8 changed files with 54 additions and 13 deletions
@@ -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
@@ -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
+5 -2
View File
@@ -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 =
@@ -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')
}
@@ -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(
@@ -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) }
}
@@ -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()
}
}
@@ -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)