chore(flutter): drop success-path diagnostic prints

Cleanup pass on the noisy debugPrints we added during the recent
debugging sessions. Remaining prints are error-path only:
- AlbumCoverCache fetch failed
- album/playlist cold-cache fetch failed
- audio_handler playbackEventStream error
- audio_handler queue supersession (rare race)
- audio_handler forward/backward fill failed
- artist_detail play failed
- cacheFirst fetchAndPopulate failed (only when tag is set)

Removed per-event chatter:
- audio_handler player-state and processingState subscribers
- audio_handler timing measurements (built initial / setAudioSources
  / forward fill / backward fill)
- audio_handler cache hit/miss per-track (fired N times per play)
- audio_handler register stream cache (verifiable via Settings)
- audio_handler.configure log
- albumProvider step-by-step lines (drift miss / online / drift hit /
  album hit but no tracks)
- playlistDetailProvider step-by-step lines (calling get / drift
  write done / 404 evicted / drift hit / playlist hit but no tracks)
- playlistsListProvider wire returned + drift rows lines
- playTracks stage timings (serverUrl / token / configure / setQueue
  / play returned)
- metadataPrefetcher warming N artists
- artist_detail play tapped — N tracks success log
- cacheFirst step-by-step (drift hit / drift miss / online / done)

`tag` parameter on cacheFirst preserved for ad-hoc instrumentation.
This commit is contained in:
2026-05-11 23:16:42 -04:00
parent ab62a3d118
commit e856172d60
7 changed files with 10 additions and 109 deletions
+7 -9
View File
@@ -19,6 +19,10 @@ import 'dart:async';
import 'package:flutter/foundation.dart' show debugPrint; import 'package:flutter/foundation.dart' show debugPrint;
// `tag` parameter is preserved for future ad-hoc instrumentation.
// Normal operation only logs failure paths so the per-screen log
// noise stays low.
/// Wraps the watch + cold-cache fallback pattern. Generic over: /// Wraps the watch + cold-cache fallback pattern. Generic over:
/// D — the drift row type (or TypedResult for joins) /// D — the drift row type (or TypedResult for joins)
/// T — the result type the caller wants (e.g. `List<ArtistRef>`) /// T — the result type the caller wants (e.g. `List<ArtistRef>`)
@@ -43,13 +47,9 @@ Stream<T> cacheFirst<D, T>({
// refresh for this stream subscription, so we don't fire one on every // refresh for this stream subscription, so we don't fire one on every
// drift re-emission (otherwise the populate cycles forever). // drift re-emission (otherwise the populate cycles forever).
var revalidated = false; var revalidated = false;
void log(String msg) {
if (tag != null) debugPrint('cacheFirst[$tag]: $msg');
}
await for (final rows in driftStream) { await for (final rows in driftStream) {
if (rows.isNotEmpty) { if (rows.isNotEmpty) {
log('drift hit (${rows.length} rows)');
yield toResult(rows); yield toResult(rows);
// Stale-while-revalidate: yield cache immediately, then kick off // Stale-while-revalidate: yield cache immediately, then kick off
// a REST refresh in the background. Drift watch() picks up the // a REST refresh in the background. Drift watch() picks up the
@@ -62,20 +62,18 @@ Stream<T> cacheFirst<D, T>({
} }
continue; continue;
} }
log('drift miss; checking connectivity');
if (await isOnline()) { if (await isOnline()) {
log('online; calling fetchAndPopulate');
try { try {
await fetchAndPopulate(); await fetchAndPopulate();
log('fetchAndPopulate done; awaiting drift re-emit');
// The drift watch() stream re-emits with the populated rows on // The drift watch() stream re-emits with the populated rows on
// the next loop iteration. Don't yield here. // the next loop iteration. Don't yield here.
} catch (e, st) { } catch (e, st) {
log('fetchAndPopulate failed: $e\n$st'); if (tag != null) {
debugPrint('cacheFirst[$tag]: fetchAndPopulate failed: $e\n$st');
}
yield toResult(rows); // empty result; caller surfaces error yield toResult(rows); // empty result; caller surfaces error
} }
} else { } else {
log('offline; yielding empty');
yield toResult(rows); // empty result; offline yield toResult(rows); // empty result; offline
} }
} }
-2
View File
@@ -1,4 +1,3 @@
import 'package:flutter/foundation.dart' show debugPrint;
import 'package:flutter_riverpod/flutter_riverpod.dart'; import 'package:flutter_riverpod/flutter_riverpod.dart';
import '../library/library_providers.dart'; import '../library/library_providers.dart';
@@ -38,7 +37,6 @@ class MetadataPrefetcher {
if (n++ >= _topN) break; if (n++ >= _topN) break;
_swallow(_ref.read(artistProvider(id).future)); _swallow(_ref.read(artistProvider(id).future));
} }
if (n > 0) debugPrint('metadataPrefetcher: warming $n artists');
} }
void _warmHome(HomeData h) { void _warmHome(HomeData h) {
@@ -95,8 +95,6 @@ class ArtistDetailScreen extends ConsumerWidget {
try { try {
final tracks = final tracks =
await ref.read(artistTracksProvider(id).future); await ref.read(artistTracksProvider(id).future);
debugPrint(
'artist_detail: play tapped — ${tracks.length} tracks for $id');
if (tracks.isEmpty) { if (tracks.isEmpty) {
if (context.mounted) { if (context.mounted) {
ScaffoldMessenger.of(context).showSnackBar( ScaffoldMessenger.of(context).showSnackBar(
@@ -187,11 +187,9 @@ final albumProvider = StreamProvider.family<
Future<bool> fetchAndPopulate() async { Future<bool> fetchAndPopulate() async {
try { try {
final api = await ref.read(libraryApiProvider.future); final api = await ref.read(libraryApiProvider.future);
debugPrint('albumProvider($albumId): calling getAlbum');
final fresh = await api final fresh = await api
.getAlbum(albumId) .getAlbum(albumId)
.timeout(const Duration(seconds: 10)); .timeout(const Duration(seconds: 10));
debugPrint('albumProvider($albumId): got ${fresh.tracks.length} tracks, writing to drift');
// Collect every artist mentioned by the album + its tracks so // Collect every artist mentioned by the album + its tracks so
// the JOINs that drive both the album header and the track rows // the JOINs that drive both the album header and the track rows
// have something to bind to. Without this, drift returns null // have something to bind to. Without this, drift returns null
@@ -224,7 +222,6 @@ final albumProvider = StreamProvider.family<
b.insertAllOnConflictUpdate(db.cachedTracks, b.insertAllOnConflictUpdate(db.cachedTracks,
fresh.tracks.map((t) => t.toDrift()).toList()); fresh.tracks.map((t) => t.toDrift()).toList());
}); });
debugPrint('albumProvider($albumId): drift write done; awaiting watch re-emit');
return true; return true;
} catch (e, st) { } catch (e, st) {
debugPrint('albumProvider($albumId): cold-cache fetch failed: $e\n$st'); debugPrint('albumProvider($albumId): cold-cache fetch failed: $e\n$st');
@@ -235,7 +232,6 @@ final albumProvider = StreamProvider.family<
await for (final albumRows in albumQuery.watch()) { await for (final albumRows in albumQuery.watch()) {
// Case 1: no album row at all → cold-fetch. // Case 1: no album row at all → cold-fetch.
if (albumRows.isEmpty) { if (albumRows.isEmpty) {
debugPrint('albumProvider($albumId): drift miss, attempting cold-cache fetch');
if (fetchAttempted) { if (fetchAttempted) {
// Already tried and got nothing back. // Already tried and got nothing back.
yield ( yield (
@@ -245,10 +241,7 @@ final albumProvider = StreamProvider.family<
continue; continue;
} }
fetchAttempted = true; fetchAttempted = true;
final online = await isOnline(); if (!await isOnline()) {
debugPrint('albumProvider($albumId): online=$online');
if (!online) {
debugPrint('albumProvider($albumId): offline, yielding empty');
yield ( yield (
album: const AlbumRef(id: '', title: '', artistId: ''), album: const AlbumRef(id: '', title: '', artistId: ''),
tracks: const <TrackRef>[], tracks: const <TrackRef>[],
@@ -265,7 +258,6 @@ final albumProvider = StreamProvider.family<
// On success, drift watch re-emits with rows; loop continues. // On success, drift watch re-emits with rows; loop continues.
continue; continue;
} }
debugPrint('albumProvider($albumId): drift hit (${albumRows.length} rows)');
final albumRow = albumRows.first; final albumRow = albumRows.first;
final album = albumRow.readTable(db.cachedAlbums).toRef( final album = albumRow.readTable(db.cachedAlbums).toRef(
@@ -280,7 +272,6 @@ final albumProvider = StreamProvider.family<
// fetchAndPopulate so the album becomes complete; drift watch // fetchAndPopulate so the album becomes complete; drift watch
// re-emits and we land in the populated branch on the next pass. // re-emits and we land in the populated branch on the next pass.
if (trackRows.isEmpty && !fetchAttempted) { if (trackRows.isEmpty && !fetchAttempted) {
debugPrint('albumProvider($albumId): album hit but no tracks; fetching');
fetchAttempted = true; fetchAttempted = true;
if (await isOnline()) { if (await isOnline()) {
final ok = await fetchAndPopulate(); final ok = await fetchAndPopulate();
+2 -43
View File
@@ -33,15 +33,6 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
// the index and the eviction loop can't reclaim them. // the index and the eviction loop can't reclaim them.
_player.bufferedPositionStream _player.bufferedPositionStream
.listen((_) => unawaited(_maybeRegisterStreamCache())); .listen((_) => unawaited(_maybeRegisterStreamCache()));
// Diagnostic: log every player-state transition so silent stops
// surface as something we can read in the log.
_player.playerStateStream.listen((s) {
debugPrint(
'audio_handler: state playing=${s.playing} processing=${s.processingState}');
});
_player.processingStateStream.listen((ps) {
debugPrint('audio_handler: processingState=$ps');
});
} }
final AudioPlayer _player = AudioPlayer(); final AudioPlayer _player = AudioPlayer();
@@ -100,10 +91,6 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
_token = token; _token = token;
if (coverCache != null) _coverCache = coverCache; if (coverCache != null) _coverCache = coverCache;
if (audioCacheManager != null) _audioCacheManager = audioCacheManager; if (audioCacheManager != null) _audioCacheManager = audioCacheManager;
debugPrint('audio_handler.configure: baseUrl="$baseUrl" '
'tokenPresent=${token != null && token.isNotEmpty} '
'coverCachePresent=${_coverCache != null} '
'audioCachePresent=${_audioCacheManager != null}');
} }
Future<void> setQueueFromTracks(List<TrackRef> tracks, {int initialIndex = 0}) async { Future<void> setQueueFromTracks(List<TrackRef> tracks, {int initialIndex = 0}) async {
@@ -127,10 +114,6 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
queue.add(items); queue.add(items);
mediaItem.add(items[clampedInitial]); mediaItem.add(items[clampedInitial]);
debugPrint('audio_handler.setQueueFromTracks: '
'_baseUrl="$_baseUrl" trackCount=${tracks.length} gen=$myGen');
final sw = Stopwatch()..start();
// Fast path: build only the initial source so the player can // Fast path: build only the initial source so the player can
// start. Remaining sources stream in via _fillRemainingSources() // start. Remaining sources stream in via _fillRemainingSources()
// in the background — addAudioSource for next/auto-advance // in the background — addAudioSource for next/auto-advance
@@ -140,13 +123,8 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
debugPrint('audio_handler: superseded before setAudioSources (gen=$myGen)'); debugPrint('audio_handler: superseded before setAudioSources (gen=$myGen)');
return; return;
} }
debugPrint('audio_handler: built initial source in '
'${sw.elapsedMilliseconds}ms');
sw.reset();
sw.start();
await _player.setAudioSources([initial], initialIndex: 0); await _player.setAudioSources([initial], initialIndex: 0);
debugPrint('audio_handler: setAudioSources(1) ${sw.elapsedMilliseconds}ms');
unawaited(_loadArtForCurrentItem()); unawaited(_loadArtForCurrentItem());
unawaited(_fillRemainingSources(tracks, clampedInitial, myGen)); unawaited(_fillRemainingSources(tracks, clampedInitial, myGen));
@@ -166,12 +144,8 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
/// addAudioSource calls from this stale fill. /// addAudioSource calls from this stale fill.
Future<void> _fillRemainingSources( Future<void> _fillRemainingSources(
List<TrackRef> tracks, int initialIndex, int gen) async { List<TrackRef> tracks, int initialIndex, int gen) async {
final sw = Stopwatch()..start();
for (var i = initialIndex + 1; i < tracks.length; i++) { for (var i = initialIndex + 1; i < tracks.length; i++) {
if (gen != _queueGeneration) { if (gen != _queueGeneration) return;
debugPrint('audio_handler: forward fill aborted (gen=$gen, current=$_queueGeneration)');
return;
}
try { try {
final src = await _buildAudioSource(tracks[i]); final src = await _buildAudioSource(tracks[i]);
if (gen != _queueGeneration) return; if (gen != _queueGeneration) return;
@@ -180,18 +154,11 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
debugPrint('audio_handler: forward fill failed for ${tracks[i].id}: $e'); debugPrint('audio_handler: forward fill failed for ${tracks[i].id}: $e');
} }
} }
debugPrint('audio_handler: forward fill (${tracks.length - initialIndex - 1}) '
'${sw.elapsedMilliseconds}ms');
if (initialIndex > 0) { if (initialIndex > 0) {
sw.reset();
sw.start();
_suppressIndexUpdates = true; _suppressIndexUpdates = true;
try { try {
for (var i = 0; i < initialIndex; i++) { for (var i = 0; i < initialIndex; i++) {
if (gen != _queueGeneration) { if (gen != _queueGeneration) return;
debugPrint('audio_handler: backward fill aborted (gen=$gen, current=$_queueGeneration)');
return;
}
final src = await _buildAudioSource(tracks[i]); final src = await _buildAudioSource(tracks[i]);
if (gen != _queueGeneration) return; if (gen != _queueGeneration) return;
await _player.insertAudioSource(i, src); await _player.insertAudioSource(i, src);
@@ -203,8 +170,6 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
// newer setQueueFromTracks already reset it for itself. // newer setQueueFromTracks already reset it for itself.
if (gen == _queueGeneration) _suppressIndexUpdates = false; if (gen == _queueGeneration) _suppressIndexUpdates = false;
} }
debugPrint('audio_handler: backward fill ($initialIndex) '
'${sw.elapsedMilliseconds}ms');
} }
} }
@@ -234,7 +199,6 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
if (mgr != null) { if (mgr != null) {
final path = await mgr.pathFor(t.id); final path = await mgr.pathFor(t.id);
if (path != null) { if (path != null) {
debugPrint('audio_handler: cache hit for track.id=${t.id} → file://$path');
return AudioSource.uri(Uri.file(path)); return AudioSource.uri(Uri.file(path));
} }
} }
@@ -260,15 +224,12 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
if (mgr != null) { if (mgr != null) {
_cacheDirPath ??= (await getApplicationCacheDirectory()).path; _cacheDirPath ??= (await getApplicationCacheDirectory()).path;
final cacheFile = File('${_cacheDirPath!}/audio_cache/${t.id}.mp3'); final cacheFile = File('${_cacheDirPath!}/audio_cache/${t.id}.mp3');
debugPrint('audio_handler: cache miss for track.id=${t.id}, '
'using LockCachingAudioSource → ${cacheFile.path}');
// ignore: experimental_member_use // ignore: experimental_member_use
return LockCachingAudioSource(parsed, return LockCachingAudioSource(parsed,
headers: headers, cacheFile: cacheFile); headers: headers, cacheFile: cacheFile);
} }
// 3. No manager configured: plain network source (legacy path). // 3. No manager configured: plain network source (legacy path).
debugPrint('audio_handler: no cache manager; track.id=${t.id} → "$url"');
return AudioSource.uri(parsed, headers: headers); return AudioSource.uri(parsed, headers: headers);
} }
@@ -344,8 +305,6 @@ class MinstrelAudioHandler extends BaseAudioHandler with QueueHandler, SeekHandl
_streamCacheRegistered.add(trackId); _streamCacheRegistered.add(trackId);
await mgr.registerStreamCache(trackId, path, size); await mgr.registerStreamCache(trackId, path, size);
debugPrint(
'audio_handler: registered stream cache for $trackId ($size bytes)');
} }
void _onCurrentIndexChanged(int? idx) { void _onCurrentIndexChanged(int? idx) {
@@ -1,5 +1,4 @@
import 'package:audio_service/audio_service.dart'; import 'package:audio_service/audio_service.dart';
import 'package:flutter/foundation.dart' show debugPrint;
import 'package:flutter_riverpod/flutter_riverpod.dart'; import 'package:flutter_riverpod/flutter_riverpod.dart';
import '../api/endpoints/radio.dart'; import '../api/endpoints/radio.dart';
@@ -54,22 +53,8 @@ class PlayerActions {
final Ref _ref; final Ref _ref;
Future<void> playTracks(List<TrackRef> tracks, {int initialIndex = 0}) async { Future<void> playTracks(List<TrackRef> tracks, {int initialIndex = 0}) async {
// Stage-by-stage timing so we can see exactly where the
// "tap → audio" delay lives. Look for "playTracks: ..." lines
// in the next log capture; each stage label is followed by its
// elapsed millis since the previous stage.
final sw = Stopwatch()..start();
int lap() {
final ms = sw.elapsedMilliseconds;
sw.reset();
sw.start();
return ms;
}
final url = await _ref.read(serverUrlProvider.future); final url = await _ref.read(serverUrlProvider.future);
debugPrint('playTracks: serverUrl ${lap()}ms');
final token = await _ref.read(secureStorageProvider).read(key: 'session_token'); final token = await _ref.read(secureStorageProvider).read(key: 'session_token');
debugPrint('playTracks: token ${lap()}ms');
final cache = _ref.read(albumCoverCacheProvider); final cache = _ref.read(albumCoverCacheProvider);
final audioCache = _ref.read(audioCacheManagerProvider); final audioCache = _ref.read(audioCacheManagerProvider);
final h = _ref.read(audioHandlerProvider) final h = _ref.read(audioHandlerProvider)
@@ -79,11 +64,8 @@ class PlayerActions {
coverCache: cache, coverCache: cache,
audioCacheManager: audioCache, audioCacheManager: audioCache,
); );
debugPrint('playTracks: configure ${lap()}ms');
await h.setQueueFromTracks(tracks, initialIndex: initialIndex); await h.setQueueFromTracks(tracks, initialIndex: initialIndex);
debugPrint('playTracks: setQueue (${tracks.length} tracks) ${lap()}ms');
await h.play(); await h.play();
debugPrint('playTracks: play() returned ${lap()}ms');
} }
Future<void> playNext(TrackRef track) async { Future<void> playNext(TrackRef track) async {
@@ -40,11 +40,6 @@ final playlistsListProvider =
fetchAndPopulate: () async { fetchAndPopulate: () async {
final api = await ref.read(playlistsApiProvider.future); final api = await ref.read(playlistsApiProvider.future);
final fresh = await api.list(kind: kind); final fresh = await api.list(kind: kind);
final ownedSysCount =
fresh.owned.where((p) => p.systemVariant != null).length;
debugPrint(
'playlistsListProvider($kind): wire returned owned=${fresh.owned.length} '
'(system=$ownedSysCount) public=${fresh.public.length}');
// Reconcile: BuildSystemPlaylists rotates system-playlist UUIDs // Reconcile: BuildSystemPlaylists rotates system-playlist UUIDs
// every rebuild, so insertOrReplace alone leaves stale rows in // every rebuild, so insertOrReplace alone leaves stale rows in
@@ -81,13 +76,6 @@ final playlistsListProvider =
.where((r) => r.userId != user.id && r.isPublic) .where((r) => r.userId != user.id && r.isPublic)
.map((r) => r.toRef()) .map((r) => r.toRef())
.toList(); .toList();
final ownedSys = owned.where((p) => p.isSystem).length;
final driftSys = filtered.where((r) => r.systemVariant != null).length;
debugPrint(
'playlistsListProvider($kind): drift rows=${rows.length} '
'filtered=${filtered.length} (system=$driftSys) '
'owned=${owned.length} (system=$ownedSys) pub=${pub.length} '
'userId=${user.id}');
return PlaylistsList(owned: owned, public: pub); return PlaylistsList(owned: owned, public: pub);
}, },
isOnline: () async => (await ref isOnline: () async => (await ref
@@ -153,10 +141,7 @@ final playlistDetailProvider =
Future<bool> fetchAndPopulate() async { Future<bool> fetchAndPopulate() async {
try { try {
final api = await ref.read(playlistsApiProvider.future); final api = await ref.read(playlistsApiProvider.future);
debugPrint('playlistDetailProvider($id): calling get');
final fresh = await api.get(id).timeout(const Duration(seconds: 10)); final fresh = await api.get(id).timeout(const Duration(seconds: 10));
debugPrint(
'playlistDetailProvider($id): got ${fresh.tracks.length} tracks, writing');
// Collect the track + artist + album rows referenced by these // Collect the track + artist + album rows referenced by these
// playlist entries. Without writing the cachedTracks rows // playlist entries. Without writing the cachedTracks rows
@@ -262,8 +247,6 @@ final playlistDetailProvider =
); );
} }
}); });
debugPrint(
'playlistDetailProvider($id): drift write done; awaiting watch re-emit');
return true; return true;
} catch (e, st) { } catch (e, st) {
// 404 = the playlist row in drift is stale (BuildSystemPlaylists // 404 = the playlist row in drift is stale (BuildSystemPlaylists
@@ -272,8 +255,6 @@ final playlistDetailProvider =
// stale row + its track positions so the home tile disappears // stale row + its track positions so the home tile disappears
// on next render and we don't keep trying. // on next render and we don't keep trying.
if (e is DioException && e.response?.statusCode == 404) { if (e is DioException && e.response?.statusCode == 404) {
debugPrint(
'playlistDetailProvider($id): server says 404, evicting stale drift rows');
await db.batch((b) { await db.batch((b) {
b.deleteWhere( b.deleteWhere(
db.cachedPlaylistTracks, (t) => t.playlistId.equals(id)); db.cachedPlaylistTracks, (t) => t.playlistId.equals(id));
@@ -292,7 +273,6 @@ final playlistDetailProvider =
await for (final playlistRows in playlistQuery.watch()) { await for (final playlistRows in playlistQuery.watch()) {
if (playlistRows.isEmpty) { if (playlistRows.isEmpty) {
debugPrint('playlistDetailProvider($id): drift miss, cold-fetching');
if (fetchAttempted) { if (fetchAttempted) {
yield emptyDetail(); yield emptyDetail();
continue; continue;
@@ -307,9 +287,6 @@ final playlistDetailProvider =
continue; continue;
} }
debugPrint(
'playlistDetailProvider($id): drift hit (${playlistRows.length} rows)');
final playlist = playlistRows.first.toRef(); final playlist = playlistRows.first.toRef();
final trackRows = await tracksQuery.get(); final trackRows = await tracksQuery.get();
@@ -318,8 +295,6 @@ final playlistDetailProvider =
// tracks for system playlists). Trigger the same fetch, drift // tracks for system playlists). Trigger the same fetch, drift
// watch re-emits with populated tracks. // watch re-emits with populated tracks.
if (trackRows.isEmpty && !fetchAttempted) { if (trackRows.isEmpty && !fetchAttempted) {
debugPrint(
'playlistDetailProvider($id): playlist hit but no tracks; fetching');
fetchAttempted = true; fetchAttempted = true;
if (await isOnline()) { if (await isOnline()) {
final ok = await fetchAndPopulate(); final ok = await fetchAndPopulate();