diff --git a/app/src/main/kotlin/com/subtracks/data/db/QueueDao.kt b/app/src/main/kotlin/com/subtracks/data/db/QueueDao.kt index 8954f4b4..d44ec921 100644 --- a/app/src/main/kotlin/com/subtracks/data/db/QueueDao.kt +++ b/app/src/main/kotlin/com/subtracks/data/db/QueueDao.kt @@ -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( diff --git a/app/src/main/kotlin/com/subtracks/data/repo/DownloadRepository.kt b/app/src/main/kotlin/com/subtracks/data/repo/DownloadRepository.kt index de10ebda..437fca2b 100644 --- a/app/src/main/kotlin/com/subtracks/data/repo/DownloadRepository.kt +++ b/app/src/main/kotlin/com/subtracks/data/repo/DownloadRepository.kt @@ -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) { 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() { diff --git a/app/src/main/kotlin/com/subtracks/data/repo/LibraryRepository.kt b/app/src/main/kotlin/com/subtracks/data/repo/LibraryRepository.kt index 9d1fca58..d5a52237 100644 --- a/app/src/main/kotlin/com/subtracks/data/repo/LibraryRepository.kt +++ b/app/src/main/kotlin/com/subtracks/data/repo/LibraryRepository.kt @@ -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) } } diff --git a/app/src/main/kotlin/com/subtracks/data/repo/PendingServerActionSink.kt b/app/src/main/kotlin/com/subtracks/data/repo/PendingServerActionSink.kt index 49636bf3..0ffbf7b8 100644 --- a/app/src/main/kotlin/com/subtracks/data/repo/PendingServerActionSink.kt +++ b/app/src/main/kotlin/com/subtracks/data/repo/PendingServerActionSink.kt @@ -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 } diff --git a/app/src/main/kotlin/com/subtracks/data/repo/SourceRepository.kt b/app/src/main/kotlin/com/subtracks/data/repo/SourceRepository.kt index 4fab802b..05b54a91 100644 --- a/app/src/main/kotlin/com/subtracks/data/repo/SourceRepository.kt +++ b/app/src/main/kotlin/com/subtracks/data/repo/SourceRepository.kt @@ -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) { 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 11ef7d79..c15a4853 100644 --- a/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt +++ b/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt @@ -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() diff --git a/app/src/main/kotlin/com/subtracks/log/Log.kt b/app/src/main/kotlin/com/subtracks/log/Log.kt index e580c779..495b59d6 100644 --- a/app/src/main/kotlin/com/subtracks/log/Log.kt +++ b/app/src/main/kotlin/com/subtracks/log/Log.kt @@ -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) } diff --git a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt index b27d193b..c6eff0ab 100644 --- a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt +++ b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt @@ -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) diff --git a/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt b/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt index c172d2e9..028a705f 100644 --- a/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt +++ b/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt @@ -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( diff --git a/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt b/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt index 878d9fd9..8d0b263c 100644 --- a/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt +++ b/app/src/main/kotlin/com/subtracks/playback/Scrobbler.kt @@ -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) } } }