From 714440fb25a52073251fa206995d19e4dca685cd Mon Sep 17 00:00:00 2001 From: austinried <4966622+austinried@users.noreply.github.com> Date: Fri, 9 Oct 2026 06:24:44 +0000 Subject: [PATCH] logging: add release-visible breadcrumbs and a verbose toggle Playback now logs each track transition and end at info (title/artist/album/source/reason), sync logs per-entity counts and pruned rows, and the Subsonic client logs server error codes and the token-auth fallback. Add a Verbose logging setting that drops the file level to debug at runtime (persisted) so a support session can capture full detail without flooding normal release logs. --- .../subtracks/data/prefs/UserPreferences.kt | 8 +++ .../subtracks/data/repo/SourceRepository.kt | 5 +- .../data/source/subsonic/SubsonicClient.kt | 7 ++- .../com/subtracks/data/sync/SyncManager.kt | 4 +- .../com/subtracks/data/sync/SyncService.kt | 55 ++++++++++++++----- .../main/kotlin/com/subtracks/di/AppModule.kt | 4 ++ app/src/main/kotlin/com/subtracks/log/Log.kt | 9 ++- .../kotlin/com/subtracks/log/LogFileStore.kt | 6 +- .../subtracks/playback/Media3PlayerHandle.kt | 5 +- .../subtracks/ui/settings/SettingsScreen.kt | 25 +++++++++ .../ui/settings/SettingsViewModel.kt | 9 +++ app/src/main/res/values/strings.xml | 2 + 12 files changed, 117 insertions(+), 22 deletions(-) diff --git a/app/src/main/kotlin/com/subtracks/data/prefs/UserPreferences.kt b/app/src/main/kotlin/com/subtracks/data/prefs/UserPreferences.kt index 5893064d..4caf84a0 100644 --- a/app/src/main/kotlin/com/subtracks/data/prefs/UserPreferences.kt +++ b/app/src/main/kotlin/com/subtracks/data/prefs/UserPreferences.kt @@ -121,6 +121,14 @@ class UserPreferences( private val offlineModeKey = booleanPreferencesKey("offline_mode") + fun verboseLogging(): Flow = store.data.map { prefs -> prefs[verboseLoggingKey] ?: false } + + suspend fun setVerboseLogging(enabled: Boolean) { + store.edit { prefs -> prefs[verboseLoggingKey] = enabled } + } + + private val verboseLoggingKey = booleanPreferencesKey("verbose_logging") + suspend fun lastSeed(): ArtworkSeedValue? { val prefs = store.data.first() val cacheKey = prefs[lastSeedKey] ?: return null 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 05b54a91..a5b14b9f 100644 --- a/app/src/main/kotlin/com/subtracks/data/repo/SourceRepository.kt +++ b/app/src/main/kotlin/com/subtracks/data/repo/SourceRepository.kt @@ -111,7 +111,10 @@ class SourceRepository( active = config?.let { ActiveSource(it.id, it.toMusicSource(quality, concurrency)) } _quality.value = quality if (sourceChanged && config != null && config.useTokenAuth && !_offline.value) { - scope.launch { runCatching { config.toClient().check("ping") } } + scope.launch { + runCatching { config.toClient().check("ping") } + .onSuccess { Log.i("net", "connected (ping ok)") } + } } } } diff --git a/app/src/main/kotlin/com/subtracks/data/source/subsonic/SubsonicClient.kt b/app/src/main/kotlin/com/subtracks/data/source/subsonic/SubsonicClient.kt index dc7bf2ce..d0bef7a9 100644 --- a/app/src/main/kotlin/com/subtracks/data/source/subsonic/SubsonicClient.kt +++ b/app/src/main/kotlin/com/subtracks/data/source/subsonic/SubsonicClient.kt @@ -2,6 +2,7 @@ package com.subtracks.data.source.subsonic import com.subtracks.R import com.subtracks.UiMessage +import com.subtracks.log.Log import okhttp3.HttpUrl import okhttp3.OkHttpClient import okhttp3.Request @@ -60,7 +61,11 @@ class SubsonicClient( return try { execute(method, params, body) } catch (failure: SubsonicException) { - if (failure.code !in TOKEN_AUTH_UNSUPPORTED_CODES || !usedTokenAuth) throw failure + if (failure.code !in TOKEN_AUTH_UNSUPPORTED_CODES || !usedTokenAuth) { + Log.w("http", "$method failed: server code ${failure.code} \"${failure.message}\"") + throw failure + } + Log.w("http", "$method: token auth unsupported (server code ${failure.code}), retrying with plaintext") disableTokenAuth() execute(method, params, body) } 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 c15a4853..5bef79fc 100644 --- a/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt +++ b/app/src/main/kotlin/com/subtracks/data/sync/SyncManager.kt @@ -65,8 +65,8 @@ class SyncManager( 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") + val summary = SyncService(db, source).sync() + Log.i("sync", "finished in ${elapsedMs(startedAt)}ms: $summary") SyncStatus.Success } catch (cancellation: CancellationException) { throw cancellation 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 d55ff6e3..f0c42687 100644 --- a/app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt +++ b/app/src/main/kotlin/com/subtracks/data/sync/SyncService.kt @@ -20,13 +20,21 @@ class SyncService( private val db: SubtracksDatabase, private val source: MusicSource, ) { - suspend fun sync() { + private var artistsSynced = 0 + private var albumsSynced = 0 + private var songsSynced = 0 + private var playlistsSynced = 0 + private var playlistSongsSynced = 0 + private var pruned = 0 + + suspend fun sync(): SyncSummary { syncArtists() syncAlbums() syncSongs() aggregatePlayData() syncPlaylists() syncPlaylistSongs() + return SyncSummary(artistsSynced, albumsSynced, songsSynced, playlistsSynced, playlistSongsSynced, pruned) } private suspend fun syncArtists() { @@ -36,8 +44,9 @@ class SyncService( if (batch.isEmpty()) return@collect write("artists", artistColumns, primaryKey, batch) { it.values() } batch.forEach { seen.add(idHash(it.id)) } + artistsSynced += batch.size } - pruneStaleIds(seen, { library.artistIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteArtists(source.id, it) }) + pruned += pruneStaleIds(seen, { library.artistIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteArtists(source.id, it) }) } private suspend fun syncAlbums() { @@ -53,11 +62,13 @@ class SyncService( writeAlbumsAndDiscs(batch, discs) batch.forEach { seenAlbums.add(idHash(it.id)) } discs.forEach { seenDiscs.add(discHash(it.albumId, it.disc)) } + albumsSynced += batch.size } - pruneStaleIds(seenAlbums, { library.albumIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteAlbums(source.id, it) }) - pruneStaleDiscs(seenDiscs, { albumId, disc -> library.discKeysAfter(source.id, albumId, disc, PRUNE_PAGE) }) { - deleteStaleDiscs(it) - } + pruned += pruneStaleIds(seenAlbums, { library.albumIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteAlbums(source.id, it) }) + pruned += + pruneStaleDiscs(seenDiscs, { albumId, disc -> library.discKeysAfter(source.id, albumId, disc, PRUNE_PAGE) }) { + deleteStaleDiscs(it) + } } private suspend fun syncSongs() { @@ -67,8 +78,9 @@ class SyncService( if (batch.isEmpty()) return@collect writeSongs(batch) batch.forEach { seen.add(idHash(it.id)) } + songsSynced += batch.size } - pruneStaleIds(seen, { library.songIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteSongs(source.id, it) }) + pruned += pruneStaleIds(seen, { library.songIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deleteSongs(source.id, it) }) } private suspend fun writeSongs(batch: List) { @@ -106,8 +118,9 @@ class SyncService( if (batch.isEmpty()) return@collect write("playlists", playlistColumns, primaryKey, batch) { it.values() } batch.forEach { seen.add(idHash(it.id)) } + playlistsSynced += batch.size } - pruneStaleIds(seen, { library.playlistIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deletePlaylists(source.id, it) }) + pruned += pruneStaleIds(seen, { library.playlistIdsAfter(source.id, it, PRUNE_PAGE) }, { library.deletePlaylists(source.id, it) }) } private suspend fun syncPlaylistSongs() { @@ -118,6 +131,7 @@ class SyncService( if (batch.isEmpty()) return@collect write("playlist_songs", playlistSongColumns, playlistSongKey, batch) { it.values() } batch.forEach { counts[it.playlistId] = (counts[it.playlistId] ?: 0L) + 1L } + playlistSongsSynced += batch.size } playlistIds.forEach { library.deletePlaylistSongsFrom(source.id, it, counts[it] ?: 0L) } library.deleteOrphanPlaylistSongs(source.id) @@ -173,15 +187,17 @@ class SyncService( seen: HashedIds, pageOf: suspend (afterId: String) -> List, delete: suspend (Collection) -> Unit, - ) { + ): Int { seen.freeze() var afterId = "" + var pruned = 0 while (true) { val ids = pageOf(afterId) - if (ids.isEmpty()) return + if (ids.isEmpty()) return pruned val stale = ids.filterNot { seen.contains(idHash(it)) } stale.chunked(DELETE_CHUNK).forEach { delete(it) } - if (ids.size < PRUNE_PAGE) return + pruned += stale.size + if (ids.size < PRUNE_PAGE) return pruned afterId = ids.last() } } @@ -190,22 +206,33 @@ class SyncService( seen: HashedIds, pageOf: suspend (afterAlbumId: String, afterDisc: Long) -> List, delete: suspend (Collection) -> Unit, - ) { + ): Int { seen.freeze() var afterAlbumId = "" var afterDisc = 0L + var pruned = 0 while (true) { val keys = pageOf(afterAlbumId, afterDisc) - if (keys.isEmpty()) return + if (keys.isEmpty()) return pruned val stale = keys.filterNot { seen.contains(discHash(it.albumId, it.disc)) } stale.chunked(DELETE_CHUNK).forEach { delete(it) } - if (keys.size < PRUNE_PAGE) return + pruned += stale.size + if (keys.size < PRUNE_PAGE) return pruned afterAlbumId = keys.last().albumId afterDisc = keys.last().disc } } } +data class SyncSummary( + val artists: Int, + val albums: Int, + val songs: Int, + val playlists: Int, + val playlistSongs: Int, + val pruned: Int, +) + private const val DELETE_CHUNK = 500 private const val PRUNE_PAGE = 500 private const val INITIAL_HASH_CAPACITY = 256 diff --git a/app/src/main/kotlin/com/subtracks/di/AppModule.kt b/app/src/main/kotlin/com/subtracks/di/AppModule.kt index 0e9fe92d..84856cb0 100644 --- a/app/src/main/kotlin/com/subtracks/di/AppModule.kt +++ b/app/src/main/kotlin/com/subtracks/di/AppModule.kt @@ -28,6 +28,7 @@ import com.subtracks.data.repo.QueueRepository import com.subtracks.data.repo.SourceRepository import com.subtracks.data.source.ServerActionSink import com.subtracks.data.sync.SyncManager +import com.subtracks.log.Log import com.subtracks.playback.MediaSessionConnection import com.subtracks.playback.PlaybackController import com.subtracks.playback.PlayerConnection @@ -48,6 +49,8 @@ import com.subtracks.ui.settings.SettingsViewModel import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.flow.launchIn +import kotlinx.coroutines.flow.onEach import okhttp3.OkHttpClient import org.koin.core.module.dsl.viewModel import org.koin.core.qualifier.named @@ -68,6 +71,7 @@ fun appModule( single { CoroutineScope(SupervisorJob() + Dispatchers.Default) } single(named("io")) { CoroutineScope(SupervisorJob() + Dispatchers.IO) } single(named("playback")) { CoroutineScope(SupervisorJob() + Dispatchers.Main.immediate) } + single(createdAtStart = true) { get().verboseLogging().onEach(Log::setVerbose).launchIn(get()) } single { SourceRepository( get(), diff --git a/app/src/main/kotlin/com/subtracks/log/Log.kt b/app/src/main/kotlin/com/subtracks/log/Log.kt index 495b59d6..1b7625c3 100644 --- a/app/src/main/kotlin/com/subtracks/log/Log.kt +++ b/app/src/main/kotlin/com/subtracks/log/Log.kt @@ -21,19 +21,24 @@ object Log { private var fileStore: LogFileStore? = null private var appContext: Context? = null private var consoleLevel = LogLevel.DEBUG + private var defaultFileLevel = LogLevel.INFO private var crashHandlerInstalled = false fun init(context: Context) { val app = context.applicationContext appContext = app consoleLevel = if (BuildConfig.DEBUG) LogLevel.VERBOSE else LogLevel.INFO - val fileLevel = if (BuildConfig.DEBUG) LogLevel.DEBUG else LogLevel.INFO + defaultFileLevel = if (BuildConfig.DEBUG) LogLevel.DEBUG else LogLevel.INFO fileStore?.shutdown() - fileStore = LogFileStore(File(app.filesDir, "logs"), fileLevel) + fileStore = LogFileStore(File(app.filesDir, "logs"), defaultFileLevel) installCrashHandler() i("app", "started ${BuildConfig.VERSION_NAME} (${BuildConfig.VERSION_CODE}) on Android ${Build.VERSION.SDK_INT} ${Build.MODEL}") } + fun setVerbose(enabled: Boolean) { + fileStore?.setMinLevel(if (enabled) LogLevel.DEBUG else defaultFileLevel) + } + fun v( tag: String, message: String, diff --git a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt index c6eff0ab..d85e86bd 100644 --- a/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt +++ b/app/src/main/kotlin/com/subtracks/log/LogFileStore.kt @@ -12,7 +12,7 @@ enum class LogLevel { VERBOSE, DEBUG, INFO, WARN, ERROR } class LogFileStore( private val rootDir: File, - private val minLevel: LogLevel, + @Volatile private var minLevel: LogLevel, private val maxFileBytes: Long = DEFAULT_MAX_FILE_BYTES, private val maxFiles: Int = DEFAULT_MAX_FILES, ) { @@ -55,6 +55,10 @@ class LogFileStore( runCatching { executor.submit {}.get() } } + fun setMinLevel(level: LogLevel) { + minLevel = level + } + fun shutdown() { executor.shutdownNow() } diff --git a/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt b/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt index 028a705f..0fe590f0 100644 --- a/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt +++ b/app/src/main/kotlin/com/subtracks/playback/Media3PlayerHandle.kt @@ -141,7 +141,7 @@ class Media3PlayerHandle( mediaItem: MediaItem?, reason: Int, ) { - Log.d("playback", "${describe(mediaItem)} transition=${transitionReason(reason)}") + Log.i("playback", "${describe(mediaItem)} transition=${transitionReason(reason)}") listener.onTransition() } @@ -166,6 +166,9 @@ class Media3PlayerHandle( "state=$playbackState position=${controller.currentPosition} " + "duration=${duration(controller.duration)} itemDuration=${currentItem?.durationMs}", ) + if (playbackState == Player.STATE_ENDED) { + Log.i("playback", "ended ${describe(controller.currentMediaItem)}") + } } }, ) diff --git a/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt b/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt index f7d1b78a..7d1f28aa 100644 --- a/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt +++ b/app/src/main/kotlin/com/subtracks/ui/settings/SettingsScreen.kt @@ -103,6 +103,7 @@ fun SettingsRoute( val downloadOverMetered by viewModel.downloadOverMetered.collectAsStateWithLifecycle() val scrobbling by viewModel.scrobbling.collectAsStateWithLifecycle() val offline by viewModel.offline.collectAsStateWithLifecycle() + val verboseLogging by viewModel.verboseLogging.collectAsStateWithLifecycle() val context = LocalContext.current val scope = rememberCoroutineScope() SettingsScreen( @@ -115,6 +116,7 @@ fun SettingsRoute( downloadOverMetered = downloadOverMetered, scrobbling = scrobbling, offline = offline, + verboseLogging = verboseLogging, onSelectSource = viewModel::selectSource, onEditServer = onEditServer, onWifiQualityChange = viewModel::setWifiQuality, @@ -124,6 +126,7 @@ fun SettingsRoute( onDownloadOverMeteredChange = viewModel::setDownloadOverMetered, onScrobblingChange = viewModel::setScrobbling, onOfflineChange = viewModel::setOfflineMode, + onVerboseLoggingChange = viewModel::setVerboseLogging, onAddServer = onAddServer, onOpenDownloads = onOpenDownloads, onOpenLicenses = onOpenLicenses, @@ -162,6 +165,7 @@ fun SettingsScreen( scrobbling: Boolean, modifier: Modifier = Modifier, offline: Boolean = false, + verboseLogging: Boolean = false, onSelectSource: (Long) -> Unit, onEditServer: (Long) -> Unit, onWifiQualityChange: (StreamQuality) -> Unit, @@ -171,6 +175,7 @@ fun SettingsScreen( onDownloadOverMeteredChange: (Boolean) -> Unit, onScrobblingChange: (Boolean) -> Unit, onOfflineChange: (Boolean) -> Unit = {}, + onVerboseLoggingChange: (Boolean) -> Unit = {}, onAddServer: () -> Unit, onOpenDownloads: () -> Unit, onOpenLicenses: () -> Unit, @@ -400,6 +405,26 @@ fun SettingsScreen( colors = ListItemDefaults.colors(containerColor = Color.Transparent), ) } + item { + ListItem( + headlineContent = { Text(stringResource(R.string.settings_about_verbose_logging)) }, + supportingContent = { Text(stringResource(R.string.settings_about_verbose_logging_description)) }, + trailingContent = { + Switch( + checked = verboseLogging, + onCheckedChange = onVerboseLoggingChange, + colors = + SwitchDefaults.colors( + uncheckedThumbColor = MaterialTheme.colorScheme.onSurfaceVariant, + uncheckedTrackColor = MaterialTheme.colorScheme.surfaceVariant, + uncheckedBorderColor = MaterialTheme.colorScheme.outline, + ), + ) + }, + modifier = Modifier.clickable { onVerboseLoggingChange(!verboseLogging) }, + colors = ListItemDefaults.colors(containerColor = Color.Transparent), + ) + } item { Spacer(Modifier.height(fill)) } } } diff --git a/app/src/main/kotlin/com/subtracks/ui/settings/SettingsViewModel.kt b/app/src/main/kotlin/com/subtracks/ui/settings/SettingsViewModel.kt index 7310ae07..401d7497 100644 --- a/app/src/main/kotlin/com/subtracks/ui/settings/SettingsViewModel.kt +++ b/app/src/main/kotlin/com/subtracks/ui/settings/SettingsViewModel.kt @@ -55,10 +55,19 @@ class SettingsViewModel( val offline: StateFlow = sourceRepository.offline + val verboseLogging: StateFlow = + userPreferences + .verboseLogging() + .stateIn(viewModelScope, SharingStarted.WhileSubscribed(5_000), false) + fun setOfflineMode(enabled: Boolean) { sourceRepository.setOfflineMode(enabled) } + fun setVerboseLogging(enabled: Boolean) { + viewModelScope.launch { userPreferences.setVerboseLogging(enabled) } + } + fun selectSource(id: Long) { viewModelScope.launch { sourceRepository.selectSource(id) } } diff --git a/app/src/main/res/values/strings.xml b/app/src/main/res/values/strings.xml index 33162c69..23a95a68 100644 --- a/app/src/main/res/values/strings.xml +++ b/app/src/main/res/values/strings.xml @@ -63,6 +63,8 @@ No logs to send yet Couldn\'t prepare the logs Subtracks logs + Verbose logging + Log extra detail for troubleshooting. Log files get larger. Version %1$s Playback Send now playing and play counts