logging: add a stall watchdog and server-vs-synced counts

Warn when playback stays buffering for 15s while play-wanted, and log what the server reports for album/song totals next to what was synced and pruned.

app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt

@@ -66,7 +66,13 @@ class SyncManager(
                 Log.i("sync", "started (source ${source.id})")
                 serverActions.flush()
                 val summary = SyncService(db, source).sync()
-                Log.i("sync", "finished in ${elapsedMs(startedAt)}ms: $summary")
+                Log.i(
+                    "sync",
+                    "finished in ${elapsedMs(startedAt)}ms: " +
+                        "${summary.artists} artists, ${summary.albums} albums (server reported ${summary.reportedAlbums}), " +
+                        "${summary.songs} songs (server reported ${summary.reportedSongs}), " +
+                        "${summary.playlists} playlists, ${summary.playlistSongs} playlist tracks, ${summary.pruned} pruned",
+                )
                 SyncStatus.Success
             } catch (cancellation: CancellationException) {
                 throw cancellation

app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt

@@ -26,6 +26,8 @@ class SyncService(
     private var playlistsSynced = 0
     private var playlistSongsSynced = 0
     private var pruned = 0
+    private var reportedAlbums = 0L
+    private var reportedSongs = 0L
 
     suspend fun sync(): SyncSummary {
         syncArtists()
@@ -34,7 +36,16 @@ class SyncService(
         aggregatePlayData()
         syncPlaylists()
         syncPlaylistSongs()
-        return SyncSummary(artistsSynced, albumsSynced, songsSynced, playlistsSynced, playlistSongsSynced, pruned)
+        return SyncSummary(
+            artists = artistsSynced,
+            albums = albumsSynced,
+            songs = songsSynced,
+            playlists = playlistsSynced,
+            playlistSongs = playlistSongsSynced,
+            pruned = pruned,
+            reportedAlbums = reportedAlbums,
+            reportedSongs = reportedSongs,
+        )
     }
 
     private suspend fun syncArtists() {
@@ -45,6 +56,7 @@ class SyncService(
             write("artists", artistColumns, primaryKey, batch) { it.values() }
             batch.forEach { seen.add(idHash(it.id)) }
             artistsSynced += batch.size
+            reportedAlbums += batch.sumOf { it.albumCount }
         }
         pruned += pruneStaleIds(seen, { library.artistIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteArtists(source.id, it) })
     }
@@ -63,6 +75,7 @@ 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 +=
@@ -231,6 +244,8 @@ data class SyncSummary(
     val playlists: Int,
     val playlistSongs: Int,
     val pruned: Int,
+    val reportedAlbums: Long,
+    val reportedSongs: Long,
 )
 
 private const val DELETE_CHUNK = 500

app/src/main/kotlin/com/subtracks/playback/PlaybackController.kt

@@ -11,6 +11,7 @@ import com.subtracks.data.repo.QueueSnapshot
 import com.subtracks.data.repo.QueueWindowItem
 import com.subtracks.data.repo.Shuffle
 import com.subtracks.data.repo.SourceRepository
+import com.subtracks.log.Log
 import kotlinx.coroutines.CancellationException
 import kotlinx.coroutines.CoroutineScope
 import kotlinx.coroutines.Dispatchers
@@ -127,7 +128,9 @@ class PlaybackController(
     private var positionJob: Job? = null
     private var windowJob: Job? = null
     private var bufferingJob: Job? = null
+    private var stallJob: Job? = null
     private var showBuffering = false
+    private var stalled = false
     private val startLock = Mutex()
 
     private var snapshot: QueueSnapshot? = null
@@ -1047,6 +1050,9 @@ class PlaybackController(
         windowJob?.cancel()
         bufferingJob?.cancel()
         bufferingJob = null
+        stallJob?.cancel()
+        stallJob = null
+        stalled = false
         showBuffering = false
         snapshot = null
         queueSourceId = null
@@ -1460,21 +1466,42 @@ class PlaybackController(
     suspend fun sourceTitle(context: QueueContext?): String? = context?.let { queueRepository.sourceName(it.kind, it.sourceId, it.refId) }
 
     private fun updateBuffering() {
+        val player = player
         if (player?.isBuffering != true) {
             bufferingJob?.cancel()
             bufferingJob = null
+            stallJob?.cancel()
+            stallJob = null
+            stalled = false
             showBuffering = false
             return
         }
-        if (showBuffering || bufferingJob?.isActive == true) return
-        bufferingJob =
-            scope.launch {
-                delay(BUFFERING_INDICATOR_DELAY_MS)
-                if (player?.isBuffering == true) {
-                    showBuffering = true
-                    refresh()
+        if (!showBuffering && bufferingJob?.isActive != true) {
+            bufferingJob =
+                scope.launch {
+                    delay(BUFFERING_INDICATOR_DELAY_MS)
+                    if (player.isBuffering) {
+                        showBuffering = true
+                        refresh()
+                    }
                 }
-            }
+        }
+        // A stall is buffering that persists long enough to be a real problem, not a track change.
+        if (stallJob?.isActive != true && !stalled) {
+            stallJob =
+                scope.launch {
+                    delay(STALL_WATCHDOG_MS)
+                    if (player.isBuffering && player.playWhenReady) {
+                        stalled = true
+                        val item = player.currentItem
+                        Log.w(
+                            "playback",
+                            "stalled: buffering for ${STALL_WATCHDOG_MS / 1000}s at ${player.currentPositionMs}ms " +
+                                "item id=${item?.id} title=\"${item?.title}\"",
+                        )
+                    }
+                }
+        }
     }
 
     private fun refresh(position: Long? = currentPosition()) {
@@ -1541,6 +1568,7 @@ class PlaybackController(
         const val POSITION_TICK_MS = 500L
         const val POSITION_SAVE_INTERVAL_MS = 15_000L
         const val BUFFERING_INDICATOR_DELAY_MS = 1_000L
+        const val STALL_WATCHDOG_MS = 15_000L
         const val QUEUE_WINDOW_RADIUS = 25L
         const val WINDOW_SHIFT_DELAY_MS = 400L
         const val RESTART_THRESHOLD_MS = 3_000L