finamp icon indicating copy to clipboard operation
finamp copied to clipboard
verified publisher icon jmshrv

Duplicate AudioPlayback and AudioPlaybackStopped events

Open 9p4 opened this issue 8 months ago • 13 comments

The redesigned app seems to be sending an AudioPlayback event, immediately followed by an AudioPlaybackStopped event, then the real AudioPlayback event.

Image

This has a direct impact on the ListenBrainz integration, as the playbacks are double-reported.

The pattern and timing appears to be this:

  1. Song starts playing in Finamp
  2. Within a second, Jellyfin sees dual "AudioPlayback" and "AudioPlaybackStopped", then an "AudioPlayback"
  3. If there is a previous song that finished, its "AudioPlaybackStopped" appears here. Occasionally it appears before (2)
  4. Song plays
  5. Song finishes. The AudioPlaybackStopped appears as described in (2)
  6. Next song in queue is played (go back to (1)).

Note that this does not happen every time, just most times.

Another interesting thing that happens is that the back-to-back AudioPlayback and AudioPlaybackStopped events might be out of order: the AudioPlaybackStopped might come before the next two AudioPlayback events:

  1. Finished playing song X
  2. Finished playing previous song Y
  3. Started song X
  4. Started song X

Webserver logs show /Status/Playing and /Status/Playing/Stopped the INCORRECT # of times.

Versions:

  • Jellyfin Server: 10.10.7
  • Finamp: 0.9.15 (TestFlight build 115)
  • iOS 18.3.2
  • finamp-logs.txt

My guesses so far:

  • ~~Lyrics downloading could be causing it? I don't see the problem happen with instrumental songs or songs without lyrics available.~~ It sometimes doesn't happen on songs with lyrics
  • Race condition with onTrackChanged and onPlaybackStateChanged?

Webserver logs:

0.0.0.0 - - [15/Apr/2025:22:37:20 -0400] "GET /Items/cf1ec487e8a4b8d8da61a61daa47b519/Images/Primary?format=jpg&quality=90 HTTP/1.1" 200 44388 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:37:20 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/main.m3u8?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit HTTP/2.0" 200 30998 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:20 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/-1.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=0&actualSegmentLengthTicks=0 HTTP/2.0" 200 761 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:20 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/0.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=0&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 97462 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:20 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/1.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=30000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96480 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
[...]
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/22.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=660000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96546 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/23.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=690000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96561 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/24.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=720000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96579 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "POST /Sessions/Playing/Stopped HTTP/1.1" 204 0 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "POST /Sessions/Playing HTTP/1.1" 204 0 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/25.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=750000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 97331 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/26.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=780000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96596 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "POST /Sessions/Playing/Stopped HTTP/1.1" 204 0 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/27.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=810000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96504 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "POST /Sessions/Playing HTTP/1.1" 204 0 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:37:21 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/28.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=840000000&actualSegmentLengthTicks=30000000 HTTP/2.0" 200 96555 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
[...]
0.0.0.0 - - [15/Apr/2025:22:37:25 -0400] "GET /Audio/a14c4ee32eab1ac7208d90f471f5d6e7/hls1/main/107.mp4?ApiKey=&audioCodec=aac&audioSampleRate=44100&maxAudioBitDepth=16&audioBitRate=320000&segmentContainer=mp4&transcodeReasons=ContainerBitrateExceedsLimit&runtimeTicks=3210000000&actualSegmentLengthTicks=20666670 HTTP/2.0" 200 68444 "-" "AppleCoreMedia/1.0.0.22D82 (iPhone; U; CPU OS 18_3_2 like Mac OS X; en_us)"
0.0.0.0 - - [15/Apr/2025:22:39:47 -0400] "GET /Items/76421f585fe5e6d9d03cc7905b8a70ca/Images/Primary?format=jpg&quality=90 HTTP/1.1" 200 11132 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:39:47 -0400] "GET /Items/28ab5ec3913fe479a0d0b647113d9381/PlaybackInfo?userId=dff577728a934def948c8851cb56b869 HTTP/1.1" 200 764 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:39:47 -0400] "GET /Items/28ab5ec3913fe479a0d0b647113d9381/Images/Primary?format=jpg&quality=90 HTTP/1.1" 200 45768 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:39:47 -0400] "GET /Items/cf1ec487e8a4b8d8da61a61daa47b519/Images/Primary?format=jpg&quality=90 HTTP/1.1" 200 44388 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:39:47 -0400] "GET /Items/a14c4ee32eab1ac7208d90f471f5d6e7/Images/Primary?format=jpg&quality=90 HTTP/1.1" 200 31805 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:39:47 -0400] "GET /Users/dff577728a934def948c8851cb56b869/Items/db60f281b311e924bbb325a512629ae0 HTTP/1.1" 200 1249 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:39:51 -0400] "POST /Sessions/Playing/Progress HTTP/1.1" 204 0 "-" "Dart/3.7 (dart:io)"
0.0.0.0 - - [15/Apr/2025:22:42:21 -0400] "POST /Sessions/Playing/Progress HTTP/1.1" 204 0 "-" "Dart/3.7 (dart:io)"

9p4 avatar Apr 16 '25 02:04 9p4

Temporarily fixed with a debouncer in Nginx:

limit_req_zone $http_authorization zone=jfplayback:10m rate=1r/m;

# ...

        location /Sessions/Playing {
                access_log  /var/log/angie/fin_postdata.log  postdata;
                echo_read_request_body;
                limit_req zone=jfplayback burst=2 nodelay;
                limit_req_status 599;
                limit_conn_status 599;
                error_page 599 =204 'debounce';

                proxy_pass http://$jellyfin;
                include snippets.d/proxy.conf;

                add_header Cross-Origin-Resource-Policy cross-origin;
        }

9p4 avatar Apr 16 '25 03:04 9p4

Updating to iOS 18.4 may have caused the frequency of the duplicate entries to decrease significantly (but not stop completely)

9p4 avatar Apr 17 '25 15:04 9p4

I've been unable to replicate this on Android Studio, meaning it seems likely it's an iOS only issue - have still been having a lot of issues with this on the TestFlight app (iOS 18.5)

Coloradohusky avatar Jul 28 '25 20:07 Coloradohusky

Do you think this issue is related to https://github.com/jmshrv/finamp/issues/688 ?

Chaphasilor avatar Jul 29 '25 10:07 Chaphasilor

I believe so, these appear to be the same issue, where the audio gets immediately stopped and started again (the below logs show "I'm a Mess" being scrobbled twice)

flutter: [QueueService/FINER] 2025-08-07 18:23:42.242817: Queue (current) [1-1-0-10]: One, [[I’m a Mess]], {} Sing, Don’t, Nina, Photograph, Bloodstream, Tenerife Sea, Runaway, The Man, Thinking Out Loud, Afire Love,
flutter: [PlaybackHistoryService/FINE] 2025-08-07 18:23:42.243696: Handling track change event from One to I’m a Mess
flutter: [PlaybackHistoryService/INFO] 2025-08-07 18:23:42.245238: Stopping playback progress for One
flutter: [VolumeNormalization/INFO] 2025-08-07 18:23:42.250835: normalization gain for 'I’m a Mess': null (track gain change: null)
flutter: [PlaybackHistoryService/INFO] 2025-08-07 18:23:42.268421: Stopping playback progress for I’m a Mess
flutter: [MetadataProvider/FINE] 2025-08-07 18:23:42.280650: Fetching metadata for 'Nina' (5069eef9104edd5c92145afd75ee18da)
flutter: [MetadataProvider/FINE] 2025-08-07 18:23:42.625192: Fetching metadata for 'Nina' (5069eef9104edd5c92145afd75ee18da) from server due to missing attributes
flutter: [Chopper/INFO] 2025-08-07 18:23:42.676690: --> POST http://server:8096/Sessions/Playing/Stopped
flutter: Content-Type: application/json; charset=utf-8
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 547
flutter: {"CanSeek":true,"Item":null,"ItemId":"ed0115fe6a45708bf53483e1819a6268","SessionId":null,"MediaSourceId":null,"AudioStreamIndex":null,"SubtitleStreamIndex":null,"IsPaused":false,"IsMuted":false,"PositionTicks":2446080000,"PlaybackStartTimeTicks":17546162222680000,"VolumeLevel":100,"Brightness":null,"AspectRatio":null,"PlayMethod":"DirectPlay","PlaybackOrder":"Default","LiveStreamId":null,"PlaySessionId":"5db14006-f042-4ba8-a7fd-2157cb82510a","RepeatMode":"RepeatNone","NowPlayingQueue":null,"PlaylistItemId":"0c235da963992a6ccf9aa29fbdc15747"}
flutter: --> END POST
flutter: [Chopper/INFO] 2025-08-07 18:23:42.679422: <-- 204 No Content POST http://server:8096/Sessions/Playing/Stopped (405ms)
flutter: x-response-time-ms: 31.0812
flutter: date: Fri, 08 Aug 2025 01:23:40 GMT
flutter: server: Kestrel
flutter: content-length: 0
flutter: <-- END HTTP
flutter: [PlaybackHistoryService/INFO] 2025-08-07 18:23:42.682568: Starting playback progress for I’m a Mess
flutter: [Chopper/INFO] 2025-08-07 18:23:42.815567: --> GET http://server:8096/Items/5069eef9104edd5c92145afd75ee18da/PlaybackInfo?userId=d78481eb238b4672a63c46ae47a693f6
flutter: Content-Type: application/json
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 0
flutter: --> END GET
flutter: [Chopper/INFO] 2025-08-07 18:23:42.824161: <-- 200 OK GET http://server:8096/Items/5069eef9104edd5c92145afd75ee18da/PlaybackInfo?userId=d78481eb238b4672a63c46ae47a693f6 (179ms)
flutter: date: Fri, 08 Aug 2025 01:23:40 GMT
flutter: transfer-encoding: chunked
flutter: content-encoding: gzip
flutter: vary: Accept-Encoding
flutter: x-response-time-ms: 121.2668
flutter: content-type: application/json; charset=utf-8
flutter: server: Kestrel
flutter: content-length: 2346
flutter: {"MediaSources":[{"Protocol":"File","Id":"5069eef9104edd5c92145afd75ee18da","Path":"E:\\Music\\Ed Sheeran\\\u00D7 (multiply) (c9351441)\\05 - Nina (017830c1).mp3","Type":"Default","Container":"mp3","Size":3673746,"Name":"05 - Nina (017830c1)","IsRemote":false,"ETag":"1267ee252ff2343172dba5545a322224","RunTimeTicks":2255760000,"ReadAtNativeFramerate":false,"IgnoreDts":false,"IgnoreIndex":false,"GenPtsInput":false,"SupportsTranscoding":true,"SupportsDirectStream":true,"SupportsDirectPlay":true,"IsInfiniteStream":false,"UseMostCompatibleTranscodingProfile":false,"RequiresOpening":false,"RequiresClosing":false,"RequiresLooping":false,"SupportsProbing":true,"MediaStreams":[{"Codec":"mp3","TimeBase":"1/14112000","VideoRange":"Unknown","VideoRangeType":"Unknown","AudioSpatialFormat":"None","LocalizedDefault":"Default","LocalizedExternal":"External","DisplayTitle":"MP3 - Stereo","IsInterlaced":false,"IsAVC":false,"ChannelLayout":"stereo","BitRate":128000,"Channels":2,"SampleRate":48000,"IsDefa<…>
flutter: <-- END HTTP
flutter: [MetadataProvider/FINE] 2025-08-07 18:23:42.839801: Fetching lyrics for 'Nina' (5069eef9104edd5c92145afd75ee18da)
flutter: [Chopper/INFO] 2025-08-07 18:23:42.846554: --> POST http://server:8096/Sessions/Playing/Stopped
flutter: Content-Type: application/json; charset=utf-8
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 547
flutter: {"CanSeek":true,"Item":null,"ItemId":"83ed6301fb1a25a5a85318f0e5dba158","SessionId":null,"MediaSourceId":null,"AudioStreamIndex":null,"SubtitleStreamIndex":null,"IsPaused":false,"IsMuted":false,"PositionTicks":2528160000,"PlaybackStartTimeTicks":17546159689470000,"VolumeLevel":100,"Brightness":null,"AspectRatio":null,"PlayMethod":"DirectPlay","PlaybackOrder":"Default","LiveStreamId":null,"PlaySessionId":"5db14006-f042-4ba8-a7fd-2157cb82510a","RepeatMode":"RepeatNone","NowPlayingQueue":null,"PlaylistItemId":"0c235da963992a6ccf9aa29fbdc15747"}
flutter: --> END POST
flutter: [Chopper/INFO] 2025-08-07 18:23:42.852663: <-- 204 No Content POST http://server:8096/Sessions/Playing/Stopped (590ms)
flutter: x-response-time-ms: 185.8016
flutter: date: Fri, 08 Aug 2025 01:23:40 GMT
flutter: server: Kestrel
flutter: content-length: 0
flutter: <-- END HTTP
flutter: [PlaybackHistoryService/INFO] 2025-08-07 18:23:42.862201: Starting playback progress for I’m a Mess
flutter: [Chopper/INFO] 2025-08-07 18:23:42.866729: --> POST http://server:8096/Sessions/Playing
flutter: Content-Type: application/json; charset=utf-8
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 543
flutter: {"CanSeek":true,"Item":null,"ItemId":"ed0115fe6a45708bf53483e1819a6268","SessionId":null,"MediaSourceId":null,"AudioStreamIndex":null,"SubtitleStreamIndex":null,"IsPaused":false,"IsMuted":false,"PositionTicks":910000,"PlaybackStartTimeTicks":17546162222680000,"VolumeLevel":100,"Brightness":null,"AspectRatio":null,"PlayMethod":"DirectPlay","PlaybackOrder":"Default","LiveStreamId":null,"PlaySessionId":"5db14006-f042-4ba8-a7fd-2157cb82510a","RepeatMode":"RepeatNone","NowPlayingQueue":null,"PlaylistItemId":"0c235da963992a6ccf9aa29fbdc15747"}
flutter: --> END POST
flutter: [Chopper/INFO] 2025-08-07 18:23:42.871128: <-- 204 No Content POST http://server:8096/Sessions/Playing (181ms)
flutter: x-response-time-ms: 124.3759
flutter: date: Fri, 08 Aug 2025 01:23:40 GMT
flutter: server: Kestrel
flutter: content-length: 0
flutter: <-- END HTTP
flutter: [Chopper/INFO] 2025-08-07 18:23:42.899468: --> GET http://server:8096/Audio/5069eef9104edd5c92145afd75ee18da/Lyrics
flutter: Content-Type: application/json
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 0
flutter: --> END GET
flutter: [Chopper/INFO] 2025-08-07 18:23:42.920717: <-- 200 OK GET http://server:8096/Audio/5069eef9104edd5c92145afd75ee18da/Lyrics (42ms)
flutter: date: Fri, 08 Aug 2025 01:23:40 GMT
flutter: transfer-encoding: chunked
flutter: content-encoding: gzip
flutter: vary: Accept-Encoding
flutter: x-response-time-ms: 19.7595
flutter: content-type: application/json; charset=utf-8
flutter: server: Kestrel
flutter: content-length: 5999
flutter: {"Metadata":{},"Lyrics":[{"Text":"I met you when I was a teen, but then you were one as well","Start":97900000},{"Text":"And I could play a guitar just like ringing a bell","Start":126500000},{"Text":"Sometimes I wonder, in any other summer","Start":151200000},{"Text":"Could you have been my part-time lover to me listening to Stevie Wonder?","Start":176200000},{"Text":"Under the covers where we used to lay","Start":210400000},{"Text":"And \u0022re: Stacks\u0022 is what the speakers played","Start":237800000},{"Text":"I\u0027d be on tour almost every day","Start":263400000},{"Text":"When I was home, up in my flat is where we used to stay","Start":284800000},{"Text":"Just watching a DVD, smoking illegal weed","Start":311400000},{"Text":"Getting high as two kites when we needed to breathe","Start":343400000},{"Text":"We\u0027d use each other\u0027s air just for the people to see","Start":367900000},{"Text":"And stay up all night like when we needed to sleep","Start":394900000},{"Text":"We<…>
flutter: <-- END HTTP
flutter: [MetadataProvider/FINE] 2025-08-07 18:23:42.942060: Fetched metadata for 'Nina' (5069eef9104edd5c92145afd75ee18da): Instance of 'LyricDto' true
flutter: [Chopper/INFO] 2025-08-07 18:23:42.944701: --> POST http://server:8096/Sessions/Playing
flutter: Content-Type: application/json; charset=utf-8
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 547
flutter: {"CanSeek":true,"Item":null,"ItemId":"ed0115fe6a45708bf53483e1819a6268","SessionId":null,"MediaSourceId":null,"AudioStreamIndex":null,"SubtitleStreamIndex":null,"IsPaused":false,"IsMuted":false,"PositionTicks":2446080000,"PlaybackStartTimeTicks":17546159689470000,"VolumeLevel":100,"Brightness":null,"AspectRatio":null,"PlayMethod":"DirectPlay","PlaybackOrder":"Default","LiveStreamId":null,"PlaySessionId":"5db14006-f042-4ba8-a7fd-2157cb82510a","RepeatMode":"RepeatNone","NowPlayingQueue":null,"PlaylistItemId":"0c235da963992a6ccf9aa29fbdc15747"}
flutter: --> END POST
flutter: [Chopper/INFO] 2025-08-07 18:23:42.945116: <-- 204 No Content POST http://server:8096/Sessions/Playing (79ms)
flutter: x-response-time-ms: 6.8742
flutter: date: Fri, 08 Aug 2025 01:23:40 GMT
flutter: server: Kestrel
flutter: content-length: 0
flutter: <-- END HTTP
flutter: [QueueService/FINEST] 2025-08-07 18:23:51.133804: Saved new periodic queue previous:[83ed6301fb1a25a5a85318f0e5dba158] current:ed0115fe6a45708bf53483e1819a6268 seek:8955 next:[] queue:[cfa2ed3ed9563b5a4606507d4c19c070, 8972982f886b213e26348e1945b81073, 5069eef9104edd5c92145afd75ee18da, 66482cfda332c0d9bc8d1d3ab02ea2cb, 060e740205e98f130988f53b9e0d3cf5, 26c27d957de3b444be450c43055bf376, 5ef3bd886144fb5469798e1e79df5ca7, 0f807abcbbf7cfe9545dca03b74569f4, 419c17a14bb7d9ba7b222c215e29019b, 39439cff922408b1f29b517af325f9d1] order:FinampPlaybackOrder.linear
flutter: [QueueService/FINEST] 2025-08-07 18:24:51.133923: Saved new periodic queue previous:[83ed6301fb1a25a5a85318f0e5dba158] current:ed0115fe6a45708bf53483e1819a6268 seek:68956 next:[] queue:[cfa2ed3ed9563b5a4606507d4c19c070, 8972982f886b213e26348e1945b81073, 5069eef9104edd5c92145afd75ee18da, 66482cfda332c0d9bc8d1d3ab02ea2cb, 060e740205e98f130988f53b9e0d3cf5, 26c27d957de3b444be450c43055bf376, 5ef3bd886144fb5469798e1e79df5ca7, 0f807abcbbf7cfe9545dca03b74569f4, 419c17a14bb7d9ba7b222c215e29019b, 39439cff922408b1f29b517af325f9d1] order:FinampPlaybackOrder.linear
flutter: [QueueService/FINEST] 2025-08-07 18:25:51.134230: Saved new periodic queue previous:[83ed6301fb1a25a5a85318f0e5dba158] current:ed0115fe6a45708bf53483e1819a6268 seek:128957 next:[] queue:[cfa2ed3ed9563b5a4606507d4c19c070, 8972982f886b213e26348e1945b81073, 5069eef9104edd5c92145afd75ee18da, 66482cfda332c0d9bc8d1d3ab02ea2cb, 060e740205e98f130988f53b9e0d3cf5, 26c27d957de3b444be450c43055bf376, 5ef3bd886144fb5469798e1e79df5ca7, 0f807abcbbf7cfe9545dca03b74569f4, 419c17a14bb7d9ba7b222c215e29019b, 39439cff922408b1f29b517af325f9d1] order:FinampPlaybackOrder.linear
flutter: [Chopper/INFO] 2025-08-07 18:26:12.928326: --> POST http://server:8096/Sessions/Playing/Progress
flutter: Content-Type: application/json; charset=utf-8
flutter: Authorization: MediaBrowser UserId="d78481eb238b4672a63c46ae47a693f6", Token="0dca795963b74954890446fb29207f9b", Client="Finamp", Device="iPhone 16 Plus",DeviceId="E0BD2728-66E3-40AC-954E-827CDAF3E746-debug", Version="0.9.19"
flutter: content-length: 547
flutter: {"CanSeek":true,"Item":null,"ItemId":"ed0115fe6a45708bf53483e1819a6268","SessionId":null,"MediaSourceId":null,"AudioStreamIndex":null,"SubtitleStreamIndex":null,"IsPaused":false,"IsMuted":false,"PositionTicks":1506934580,"PlaybackStartTimeTicks":17546162222680000,"VolumeLevel":100,"Brightness":null,"AspectRatio":null,"PlayMethod":"DirectPlay","PlaybackOrder":"Default","LiveStreamId":null,"PlaySessionId":"5db14006-f042-4ba8-a7fd-2157cb82510a","RepeatMode":"RepeatNone","NowPlayingQueue":null,"PlaylistItemId":"0c235da963992a6ccf9aa29fbdc15747"}
flutter: --> END POST
flutter: [Chopper/INFO] 2025-08-07 18:26:12.930480: <-- 204 No Content POST http://server:8096/Sessions/Playing/Progress (54ms)
flutter: x-response-time-ms: 28.5315
flutter: date: Fri, 08 Aug 2025 01:26:11 GMT
flutter: server: Kestrel
flutter: content-length: 0
flutter: <-- END HTTP
flutter: [QueueService/FINEST] 2025-08-07 18:26:51.136798: Saved new periodic queue previous:[83ed6301fb1a25a5a85318f0e5dba158] current:ed0115fe6a45708bf53483e1819a6268 seek:188959 next:[] queue:[cfa2ed3ed9563b5a4606507d4c19c070, 8972982f886b213e26348e1945b81073, 5069eef9104edd5c92145afd75ee18da, 66482cfda332c0d9bc8d1d3ab02ea2cb, 060e740205e98f130988f53b9e0d3cf5, 26c27d957de3b444be450c43055bf376, 5ef3bd886144fb5469798e1e79df5ca7, 0f807abcbbf7cfe9545dca03b74569f4, 419c17a14bb7d9ba7b222c215e29019b, 39439cff922408b1f29b517af325f9d1] order:FinampPlaybackOrder.linear
flutter: [VolumeNormalization/INFO] 2025-08-07 18:27:46.787246: normalization gain for 'Sing': null (track gain change: null)
flutter: [QueueService/FINER] 2025-08-07 18:27:46.789346: Play queue index changed, new index: 2
flutter: [QueueService/FINEST] 2025-08-07 18:27:46.790301: Saved new rebuilt queue
flutter: [QueueService/FINER] 2025-08-07 18:27:46.791016: Queue (current) [2-1-0-9]: One, I’m a Mess, [[Sing]], {} Don’t, Nina, Photograph, Bloodstream, Tenerife Sea, Runaway, The Man, Thinking Out Loud, Afire Love,
flutter: [PlaybackHistoryService/FINE] 2025-08-07 18:27:46.798651: Handling track change event from I’m a Mess to Sing
flutter: [PlaybackHistoryService/INFO] 2025-08-07 18:27:46.799613: Stopping playback progress for I’m a Mess
flutter: [VolumeNormalization/INFO] 2025-08-07 18:27:46.802945: normalization gain for 'Sing': null (track gain change: null)
flutter: [PlaybackHistoryService/INFO] 2025-08-07 18:27:46.821261: Stopping playback progress for Sing

Coloradohusky avatar Aug 08 '25 01:08 Coloradohusky

As far as I can tell, the "bad reports" come from playback_history_service.dart:139, while the "good reports" come from playback_history_service.dart:105, although that wouldn't explain why this is an iOS-exclusive issue

Bad: onTrackChanged(currentItem, currentState, prevItem, prevState, true); Good: onTrackChanged(currentItem, currentState, prevItem, prevState, currentIndex > (prevState?.queueIndex ?? 0),);

Coloradohusky avatar Aug 08 '25 04:08 Coloradohusky

@Coloradohusky thanks for taking a look. If you say playback_history_service.dart:139 is causing the issues, then that might be a clue to the problem. Because that line should only be called if we are looping a single track (previous track ID is current track ID, new position is towards the start of the tracks while old position is towards the end).

If you're not looping the same track, but this line is getting called for you, then the conditions are probably unsuited for iOS's behavior.
Would you mind taking a look at the currentItem, currentState, prevItem, prevStat variables in a breakpoint when this line is called?

Chaphasilor avatar Aug 08 '25 13:08 Chaphasilor

In playback_history_service.dart:139, currentItem==prevItem, however the states are different - prevState.updatePosition is set to the end of the song, while currentState.updatePosition is set to near the beginning of the song - usually between 0.1 and 0.5 sec off from the beginning of the track (instead of being right at 0). Other than that, the states are the same.

Stack: 
	new PlaybackHistoryService.<anonymous closure> (playback_history_service.dart:139)
	_RootZone.runUnaryGuarded (zone.dart:1778)
	_BufferingStreamSubscription._sendData (stream_impl.dart:381)
	_BufferingStreamSubscription._add (stream_impl.dart:312)
	_MultiStreamController.addSync (stream_impl.dart:1197)
	_MultiControllerSink.add (forwarding_stream.dart:135)
	_StartWithStreamSink.onData (start_with.dart:12)
	_RootZone.runUnaryGuarded (zone.dart:1778)
	_BufferingStreamSubscription._sendData (stream_impl.dart:381)
	_DelayedData.perform (stream_impl.dart:573)
	_PendingEvents.handleNext (stream_impl.dart:678)
	_PendingEvents.schedule.<anonymous closure> (stream_impl.dart:649)
	_microtaskLoop (schedule_microtask.dart:40)
	_startMicrotaskLoop (schedule_microtask.dart:49)
flutter: [PlaybackHistoryService/INFO] 2025-08-08 18:05:31.505888: Stopping playback progress for Song
flutter: [PlaybackHistoryService/FINE] 2025-08-08 18:05:31.507217: previousItem update: Instance of 'FinampQueueItem'
flutter: [PlaybackHistoryService/FINE] 2025-08-08 18:05:31.508225: currentItem update: Instance of 'FinampQueueItem'
flutter: [PlaybackHistoryService/FINE] 2025-08-08 18:05:31.511839: prevState update: {processingState: 3, playing: true, controls: [{androidIcon: drawable/audio_service_skip_previous, label: Previous, action: 4}, {androidIcon: drawable/audio_service_pause, label: Pause, action: 1}, {androidIcon: drawable/audio_service_skip_next, label: Next, action: 5}, {androidIcon: drawable/baseline_heart_24, label: Add Favorite, action: 25, customAction: {name: toggleFavorite, extras: null}}, {androidIcon: drawable/baseline_shuffle_24, label: Playing in order, action: 25, customAction: {name: shuffle, extras: null}}], androidCompactActionIndices: [0, 1, 2], systemActions: [8, 23, 22], updatePosition: 221160, bufferedPosition: 221160, speed: 1.0, updateTime: 1754701530959, errorCode: null, errorMessage: null, repeatMode: 0, shuffleMode: 0, captioningEnabled: false, queueIndex: 11}
flutter: [PlaybackHistoryService/FINE] 2025-08-08 18:05:31.512922: currentState update: {processingState: 3, playing: true, controls: [{androidIcon: drawable/audio_service_skip_previous, label: Previous, action: 4}, {androidIcon: drawable/audio_service_pause, label: Pause, action: 1}, {androidIcon: drawable/audio_service_skip_next, label: Next, action: 5}, {androidIcon: drawable/baseline_heart_24, label: Add Favorite, action: 25, customAction: {name: toggleFavorite, extras: null}}, {androidIcon: drawable/baseline_shuffle_24, label: Playing in order, action: 25, customAction: {name: shuffle, extras: null}}], androidCompactActionIndices: [0, 1, 2], systemActions: [8, 23, 22], updatePosition: 161, bufferedPosition: 221160, speed: 1.0, updateTime: 1754701531069, errorCode: null, errorMessage: null, repeatMode: 0, shuffleMode: 0, captioningEnabled: false, queueIndex: 11}
flutter: [PlaybackHistoryService/FINE] 2025-08-08 18:05:31.513852: #0      new PlaybackHistoryService.<anonymous closure> (package:finamp/services/playback_history_service.dart:144:63)
flutter: #1      _RootZone.runUnaryGuarded (dart:async/zone.dart:1778:10)
flutter: #2      _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:381:11)
flutter: #3      _BufferingStreamSubscription._add (dart:async/stream_impl.dart:312:7)
flutter: #4      _MultiStreamController.addSync (dart:async/stream_impl.dart:1197:36)
flutter: #5      _MultiControllerSink.add (package:rxdart/src/utils/forwarding_stream.dart:135:35)
flutter: #6      _StartWithStreamSink.onData (package:rxdart/src/transformers/start_with.dart:12:31)
flutter: #7      _RootZone.runUnaryGuarded (dart:async/zone.dart:1778:10)
flutter: #8      _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:381:11)
flutter: #9      _DelayedData.perform (dart:async/stream_impl.dart:573:14)
flutter: #10     _PendingEvents.handleNext (dart:async/stream_impl.dart:678:11)
flutter: #11     _PendingEvents.schedule.<anonymous closure> (dart:async/stream_impl.dart:649:7)
flutter: #12     _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
flutter: #13     _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)
flutter:

Coloradohusky avatar Aug 09 '25 01:08 Coloradohusky

Okay, but are you actually looping the track? Or does the player just randomly report the wrong position? 😅

Chaphasilor avatar Aug 09 '25 18:08 Chaphasilor

No, no looping is occurring - this behavior happens when I finish listening to one track in an album and it transitions to the next track in the album (or playlist)

Coloradohusky avatar Aug 09 '25 18:08 Coloradohusky

Okay, thanks for confirming.
I'll check if there are any similar issue reported for just_audio, our music player plugin...

Is this occuring for every track, or only occaisonally?

Chaphasilor avatar Aug 09 '25 21:08 Chaphasilor

Sorry for the delay - it seems to be every track (except for the very first song played), I checked playing from Albums, Playlists, and Genres and they all exhibited this behavior

Coloradohusky avatar Aug 12 '25 16:08 Coloradohusky

Currently on 0.9.20. On my Linux dev environment it seems to occur for every track but the very first played. On IOS 26.0 with downloaded tracks it's a bit inconsistent but still occurs on the vast majority of tracks.

I think I found a potential fix. When investigating the conditions for the playback_history_service.dart:139 call, I added a check for loopMode to line 134:

if (((prevState.position.inMilliseconds) >= ((prevItem?.item.duration?.inMilliseconds ?? 0) - 1000 * 10)) &&(_queueService.loopMode == FinampLoopMode.one))

With this change, playback on Linux dev environment is appearing as expected with no duplicate stops or starts. This still recognized loop mode with looping over a single track. I also tested with playing through the queue normally (full playing with no skipping), and filling queue with the same song over and over.

jagarwa1 avatar Oct 23 '25 02:10 jagarwa1