logging: add breadcrumbs for common actions

Log sync start/finish/failure, star/unstar, scrobble now-playing/submission (and failures), download queue/start/complete/fail/remove, offline-mode toggles, network-mode and active-source changes, and pending-action queue/replay/drop. Enrich playback logs with title/artist/album, file-vs-http source and the transition reason, and render C.TIME_UNSET durations as 'unset'. Make console logging non-fatal so a logcat write never breaks the caller, and never prune the file being written.
2026-11-10 15:11:58 +01:00 · 2026-10-09 07:58:55 +00:00
parent b2b02e7c05
commit a2d89f28a6
10 changed files with 128 additions and 25 deletions
@@ -2,8 +2,8 @@ package com.subtracks.data.db

 import androidx.room3.Dao
 import androidx.room3.Insert
+import androidx.room3.OnConflictStrategy
 import androidx.room3.Query
-import androidx.room3.Upsert
 import com.subtracks.data.model.AlbumSongItem
 import com.subtracks.data.model.PlaybackCursor
 import com.subtracks.data.model.PlaylistSongItem
@@ -55,7 +55,7 @@ interface QueueDao {
    @Query("SELECT * FROM playback_cursor WHERE id = 1")
    suspend fun cursor(): PlaybackCursor?

-    @Upsert
+    @Insert(onConflict = OnConflictStrategy.REPLACE)
    suspend fun setCursor(cursor: PlaybackCursor)

    @Query(
@@ -19,6 +19,7 @@ import com.subtracks.data.model.DownloadedSong
 import com.subtracks.data.model.ListDownloadStatus
 import com.subtracks.data.model.SongDownload
 import com.subtracks.data.model.coverArtKey
+import com.subtracks.log.Log
 import kotlinx.coroutines.CancellationException
 import kotlinx.coroutines.CompletableDeferred
 import kotlinx.coroutines.CoroutineDispatcher
@@ -79,7 +80,10 @@ class DownloadRepository(
        }
        scope.launch {
            sourceRepository.offline.collect { offline ->
-                if (offline) cancelActive()
+                if (offline) {
+                    Log.i("download", "offline: cancelling active downloads")
+                    cancelActive()
+                }
            }
        }
    }
@@ -140,6 +144,7 @@ class DownloadRepository(
        dir(sourceId).mkdirs()
        file(sourceId, songId).delete()
        db.downloadDao().upsert(SongDownload(sourceId = sourceId, songId = songId, status = DownloadStatus.Queued))
+        Log.i("download", "queued song=$songId (source $sourceId)")
        ensurePolling()
        return true
    }
@@ -336,6 +341,7 @@ class DownloadRepository(

    private suspend fun removeRows(rows: List<SongDownload>) {
        if (rows.isEmpty()) return
+        Log.i("download", "removed ${rows.size} download(s)")
        val engineIds = rows.mapNotNull { it.engineId }
        if (engineIds.isNotEmpty()) engine.cancel(engineIds)
        rows.groupBy { it.sourceId }.forEach { (sourceId, group) ->
@@ -581,6 +587,14 @@ class DownloadRepository(
                    },
            )
        if (updated != row) db.downloadDao().upsert(updated)
+        if (updated.status != row.status) {
+            when (updated.status) {
+                DownloadStatus.Completed -> Log.i("download", "completed ${row.songId} (${updated.total} bytes)")
+                DownloadStatus.Failed -> Log.w("download", "failed ${row.songId}: ${updated.error}")
+                DownloadStatus.Running -> Log.i("download", "started ${row.songId}")
+                DownloadStatus.Queued -> Unit
+            }
+        }
    }

    private suspend fun markFailed(
@@ -590,6 +604,7 @@ class DownloadRepository(
        row.engineId?.let { engine.cancel(listOf(it)) }
        file(row.sourceId, row.songId).delete()
        db.downloadDao().upsert(row.copy(status = DownloadStatus.Failed, engineId = null, error = error))
+        Log.w("download", "failed ${row.songId}: $error")
    }

    private fun ensurePolling() {
@@ -24,6 +24,7 @@ import com.subtracks.data.prefs.PlaylistSort
 import com.subtracks.data.prefs.StarredFilter
 import com.subtracks.data.source.ServerActionSink
 import com.subtracks.data.source.StarType
+import com.subtracks.log.Log
 import kotlinx.coroutines.CancellationException
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Dispatchers
@@ -464,14 +465,17 @@ class LibraryRepository(
        }
        val previous = starredValue(sourceId, type, id)
        updateStarred(sourceId, type, id, if (starred) System.currentTimeMillis() else null)
+        val action = if (starred) "star" else "unstar"
        return try {
            serverActions.setStar(type, id, starred)
+            Log.i("star", "$action ${type.name.lowercase()} $id")
            Result.success(Unit)
        } catch (cancellation: CancellationException) {
            throw cancellation
        } catch (failure: Exception) {
            withContext(NonCancellable) { updateStarred(sourceId, type, id, previous) }
            showMessage(UiMessage(R.string.star_update_failed))
+            Log.w("star", "failed to $action ${type.name.lowercase()} $id", failure)
            Result.failure(failure)
        }
    }
@@ -6,6 +6,7 @@ import com.subtracks.data.model.PendingActionKind
 import com.subtracks.data.source.ServerActionSink
 import com.subtracks.data.source.StarType
 import com.subtracks.data.source.subsonic.SubsonicException
+import com.subtracks.log.Log
 import kotlinx.coroutines.CancellationException
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.flow.Flow
@@ -29,8 +30,13 @@ class PendingServerActionSink(

    init {
        scope.launch {
+            var lastReady: Boolean? = null
            combine(offlinePreferences, networkAvailable) { isOffline, online -> !isOffline && online }
                .collect { ready ->
+                    if (ready && lastReady == false) {
+                        Log.i("net", "connection available, replaying pending server actions")
+                    }
+                    lastReady = ready
                    // The persisted flag and connectivity are authoritative, unlike the process
                    // flag's default at cold start, so wait for that flag to agree before replaying.
                    if (ready) {
@@ -96,12 +102,14 @@ class PendingServerActionSink(
        for (action in dao.pending(sourceId)) {
            try {
                deliver(action)
+                Log.i("net", "replayed ${action.kind.name.lowercase()} ${action.targetId}")
            } catch (cancellation: CancellationException) {
                throw cancellation
            } catch (failure: Exception) {
                // Still unreachable: keep this and the remaining actions for the next attempt.
                if (isRetryable(failure)) return
                // The server answered and refused; drop the action rather than block the queue.
+                Log.w("net", "dropped ${action.kind.name.lowercase()} ${action.targetId}", failure)
            }
            dao.delete(action.id)
        }
@@ -139,6 +147,7 @@ class PendingServerActionSink(
        db.pendingActionDao().replace(
            PendingAction(sourceId = sourceId, kind = kind, targetId = targetId, starType = starType, time = time),
        )
+        Log.i("net", "queued ${kind.name.lowercase()} $targetId")
        return true
    }

@@ -17,6 +17,7 @@ import com.subtracks.data.source.MusicSource
 import com.subtracks.data.source.declaredStreamLength
 import com.subtracks.data.source.streamLengthSuffix
 import com.subtracks.data.source.subsonic.SubsonicClient
+import com.subtracks.log.Log
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Dispatchers
 import kotlinx.coroutines.SupervisorJob
@@ -46,6 +47,13 @@ class SourceRepository(
        val source: SubsonicMusicSource,
    )

+    private data class ResolvedSource(
+        val config: SubsonicConfig?,
+        val quality: StreamQuality,
+        val mode: NetworkMode,
+        val concurrency: Int,
+    )
+
    @Volatile
    private var active: ActiveSource? = null

@@ -64,6 +72,7 @@ class SourceRepository(
    fun downloadsAllowedOverMetered(): Boolean = allowMeteredDownloads

    fun setOfflineMode(enabled: Boolean) {
+        Log.i("net", "offline mode -> $enabled")
        scope.launch { prefs.setOfflineMode(enabled) }
    }

@@ -81,6 +90,7 @@ class SourceRepository(
            // Read the persisted flag before the source config can build a source or probe it, so a
            // cold start with offline on never touches the network.
            _offline.value = prefs.offlineMode().first()
+            var lastMode: NetworkMode? = null
            combine(
                db.sourcesDao().activeSubsonicConfig(),
                networkMode,
@@ -88,9 +98,16 @@ class SourceRepository(
                prefs.streamQuality(NetworkMode.Mobile),
                prefs.syncConcurrency(),
            ) { config, mode, wifi, mobile, concurrency ->
-                Triple(config, if (mode == NetworkMode.Wifi) wifi else mobile, concurrency)
-            }.collect { (config, quality, concurrency) ->
+                ResolvedSource(config, if (mode == NetworkMode.Wifi) wifi else mobile, mode, concurrency)
+            }.collect { (config, quality, mode, concurrency) ->
+                if (mode != lastMode) {
+                    Log.i("net", "network mode -> ${mode.key}")
+                    lastMode = mode
+                }
                val sourceChanged = config?.id != active?.id
+                if (sourceChanged) {
+                    Log.i("net", "active source -> ${config?.name ?: "none"}")
+                }
                active = config?.let { ActiveSource(it.id, it.toMusicSource(quality, concurrency)) }
                _quality.value = quality
                if (sourceChanged && config != null && config.useTokenAuth && !_offline.value) {
@@ -59,16 +59,19 @@ class SyncManager(
            return
        }
        _status.value = SyncStatus.Running
+        val startedAt = System.nanoTime()
        val result =
            try {
                val source = sourceRepository.activeMusicSource() ?: throw NoServerException()
+                Log.i("sync", "started (source ${source.id})")
                serverActions.flush()
                SyncService(db, source).sync()
+                Log.i("sync", "finished in ${elapsedMs(startedAt)}ms")
                SyncStatus.Success
            } catch (cancellation: CancellationException) {
                throw cancellation
            } catch (failure: Exception) {
-                Log.w("sync", "sync failed", failure)
+                Log.w("sync", "failed after ${elapsedMs(startedAt)}ms", failure)
                val message =
                    when (failure) {
                        is NoServerException -> {
@@ -86,6 +89,8 @@ class SyncManager(
        queueRepository.invalidateLibraryCache()
        _status.value = result
    }
+
+    private fun elapsedMs(startNanos: Long): Long = (System.nanoTime() - startNanos) / 1_000_000
 }

 private class NoServerException : IllegalStateException()
@@ -128,13 +128,16 @@ object Log {
    ) {
        val redacted = redactLogs(message)
        if (level.ordinal >= consoleLevel.ordinal) {
-            val text =
-                if (throwable != null) {
-                    "$redacted\n${redactLogs(AndroidLog.getStackTraceString(throwable))}"
-                } else {
-                    redacted
-                }
-            AndroidLog.println(priority(level), tag.take(23), text)
+            // Logging is best effort: a logcat write must never disturb the caller.
+            runCatching {
+                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)
    }
@@ -137,8 +137,9 @@ class LogFileStore(
    }

    private fun prune() {
-        val logs = files()
-        if (logs.size > maxFiles) logs.drop(maxFiles).forEach { it.delete() }
+        // Never prune the file we are writing to, and never keep fewer than one rolled file slot.
+        val rolled = files().filterNot { it == current }
+        if (rolled.size > maxFiles - 1) rolled.drop(maxFiles - 1).forEach { it.delete() }
    }

    private fun currentFile(): File = File(rootDir, dateFormat.format(Date()) + LOG_SUFFIX)
@@ -112,14 +112,19 @@ class Media3PlayerHandle(
    ) = controller.replaceMediaItem(index, toMediaItem(item))

    override fun seekToIndex(index: Int) {
-        Log.d("playback", "seekToIndex($index) playerDuration=${controller.duration} state=${controller.playbackState}")
+        Log.d(
+            "playback",
+            "seekToIndex($index) position=${controller.currentPosition} duration=${duration(
+                controller.duration,
+            )} state=${controller.playbackState}",
+        )
        controller.seekTo(index, 0)
    }

    override fun seekTo(positionMs: Long) {
        Log.d(
            "playback",
-            "seekTo(${positionMs}ms) from=${controller.currentPosition} playerDuration=${controller.duration} " +
+            "seekTo(${positionMs}ms) from=${controller.currentPosition} duration=${duration(controller.duration)} " +
                "itemDuration=${currentItem?.durationMs} state=${controller.playbackState}",
        )
        controller.seekTo(positionMs)
@@ -136,7 +141,7 @@ class Media3PlayerHandle(
                    mediaItem: MediaItem?,
                    reason: Int,
                ) {
-                    Log.d("playback", "item=${mediaItem?.mediaId}")
+                    Log.d("playback", "${describe(mediaItem)} transition=${transitionReason(reason)}")
                    listener.onTransition()
                }

@@ -148,7 +153,8 @@ class Media3PlayerHandle(
                override fun onPlayerError(error: PlaybackException) {
                    Log.w(
                        "playback",
-                        "Playback error ${error.errorCodeName} at ${controller.currentPosition}/${controller.duration}",
+                        "error ${error.errorCodeName} ${describe(controller.currentMediaItem)} " +
+                            "position=${controller.currentPosition} duration=${duration(controller.duration)}",
                        error,
                    )
                    listener.onError(playbackErrorMessage(error))
@@ -158,13 +164,49 @@ class Media3PlayerHandle(
                    Log.d(
                        "playback",
                        "state=$playbackState position=${controller.currentPosition} " +
-                            "playerDuration=${controller.duration} itemDuration=${currentItem?.durationMs}",
+                            "duration=${duration(controller.duration)} itemDuration=${currentItem?.durationMs}",
                    )
                }
            },
        )
    }

+    private fun describe(mediaItem: MediaItem?): String {
+        if (mediaItem == null) return "item=none"
+        val metadata = mediaItem.mediaMetadata
+        val artist =
+            metadata.artist
+                ?.toString()
+                ?.takeIf { it.isNotBlank() }
+                ?.let { " artist=\"$it\"" }
+                .orEmpty()
+        val album =
+            metadata.albumTitle
+                ?.toString()
+                ?.takeIf { it.isNotBlank() }
+                ?.let { " album=\"$it\"" }
+                .orEmpty()
+        val source =
+            when (mediaItem.localConfiguration?.uri?.scheme) {
+                "file", "content" -> "file"
+                "http", "https" -> "http"
+                null -> "none"
+                else -> "other"
+            }
+        return "item id=${mediaItem.mediaId} title=\"${metadata.title?.toString().orEmpty()}\"$artist$album source=$source"
+    }
+
+    private fun duration(value: Long): String = if (value == C.TIME_UNSET) "unset" else "${value}ms"
+
+    private fun transitionReason(reason: Int): String =
+        when (reason) {
+            Player.MEDIA_ITEM_TRANSITION_REASON_REPEAT -> "repeat"
+            Player.MEDIA_ITEM_TRANSITION_REASON_AUTO -> "auto"
+            Player.MEDIA_ITEM_TRANSITION_REASON_SEEK -> "seek"
+            Player.MEDIA_ITEM_TRANSITION_REASON_PLAYLIST_CHANGED -> "playlist"
+            else -> reason.toString()
+        }
+
    private fun toMediaItem(item: QueueItem): MediaItem {
        val quality = sourceRepository.quality.value
        return queueMediaItem(
@@ -1,6 +1,7 @@
 package com.subtracks.playback

 import com.subtracks.data.source.ServerActionSink
+import com.subtracks.log.Log
 import kotlinx.coroutines.CancellationException
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Dispatchers
@@ -128,22 +129,28 @@ class Scrobbler(
    private suspend fun submit(event: Scrobble) {
        when (event) {
            is Scrobble.NowPlaying -> {
-                attempt { sink.nowPlaying(event.songId) }
+                Log.i("scrobble", "now playing ${event.songId}")
+                attempt("now playing ${event.songId}") { sink.nowPlaying(event.songId) }
            }

            is Scrobble.Submission -> {
-                attempt { recordPlay(event.songId, event.time / 1000) }
-                attempt { sink.scrobble(event.songId, event.time) }
+                Log.i("scrobble", "submitted ${event.songId}")
+                attempt("record play ${event.songId}") { recordPlay(event.songId, event.time / 1000) }
+                attempt("scrobble ${event.songId}") { sink.scrobble(event.songId, event.time) }
            }
        }
    }

-    private suspend fun attempt(block: suspend () -> Unit) {
+    private suspend fun attempt(
+        label: String,
+        block: suspend () -> Unit,
+    ) {
        try {
            block()
        } catch (cancellation: CancellationException) {
            throw cancellation
-        } catch (_: Exception) {
+        } catch (failure: Exception) {
+            Log.w("scrobble", "$label failed", failure)
        }
    }
 }