search

librespot-org / librespot

Open Source Spotify client library
MIT License
4.7k stars 573 forks source link

First song is played twice when it should only be played once. #1097

Open LutzenH opened 1 year ago

LutzenH commented 1 year ago

Hello everyone,

When transferring playback to a single track (TRACK_A) using the web-api and adding a track (TRACK_B) to the queue whilst TRACK_A is playing, You will notice that TRACK_A is played twice:

Behavior: TRACK_A -> TRACK_B -> TRACK_A

Expected behavior: TRACK_A -> TRACK_B

Steps to reproduce the behavior:

  1. Launch librespot with librespot --backend pipe --device PIPE_NAME --bitrate 96 --name SPEAKER_NAME -c ./cache --username USERNAME --password PASSWORD
  2. Retrieve a valid Bearer token somehow YOUR_BEARER_TOKEN.
  3. Retrieve the device id associated with the created device: YOUR_DEVICE_ID
  4. Perform the following request (this transfers playback to the device and starts playing TRACK_A): 
    
PUT /v1/me/player/play?device_id=YOUR_DEVICE_ID HTTP/1.1
Content-Type: application/json
Authorization: Bearer YOUR_BEARER_TOKEN
Host: api.spotify.com
Content-Length: 49

{"uris":["spotify:track:2oLjhx7w8Hyd3gry9cCXr7"]}

5. This should start playing TRACK_A.
6. Whilst this track is playing perform the following request (This will add TRACK_B to the queue):
```http
POST /v1/me/player/queue?uri=spotify:track:2xizRhme7pYeITbH1NLLGt&device_id=YOUR_DEVICE_ID HTTP/1.1
Content-Type: application/json
Authorization: Bearer YOUR_BEARER_TOKEN
Host: api.spotify.com
  1. Wait until TRACK_A and TRACK_B are done playing, you will now hear TRACK_A again (unexpected behavior).

System Info

Potential Fix

I managed to fix this by swapping these two lines of code:

https://github.com/librespot-org/librespot/blob/8941495b80d5927b270a1a8dafcfae3b77abb5a9/connect/src/spirc.rs#L1281-L1282

In some situations consume_queued_track() might remove a track from the list meaning that the amount of tracks is from that point actually lower than what is stored in tracks_len.

If you swap the two lines of code the tracks_len will thus no longer in certain situations not be the same as the amount of tracks in the list. Which I think is more correct behavior than current behavior. (But I am not sure, as I am not that proficient in rust and this code base).

kingosticks commented 1 year ago

A debug log would be helpful

LutzenH commented 1 year ago

Ok here is a debug log, I tried to remove all sensitive information (maybe a little to aggressive), If you see anything else; or need something more specific feel free to ask.

  1. I started playing the track: 21 Hungarian Dances (spotify:track:2oLjhx7w8Hyd3gry9cCXr7) using the transfer playback api-call.
  2. Whilst 21 Hungarian Dances was playing I added Tchaikovsky: Swan Lake (spotify:track:2xizRhme7pYeITbH1NLLGt) using the add to queue api-call.
  3. As you can see in the log 21 Hungarian Dances (spotify:track:2oLjhx7w8Hyd3gry9cCXr7) starts playing again after Tchaikovsky: Swan Lake (spotify:track:2xizRhme7pYeITbH1NLLGt).
  4. After that I stopped librespot.
[2023-01-12T17:34:04Z DEBUG librespot_core::session] Session strong=4 weak=4
[2023-01-12T17:34:04Z INFO  librespot_core::session] Country: "NL"
[2023-01-12T17:34:04Z TRACE librespot_core::session] Received product info: {
...
    }
[2023-01-12T17:34:04Z DEBUG librespot_core::mercury] listening to uri=hm://remote/user/
[2023-01-12T17:34:04Z DEBUG librespot_core::mercury] listening to uri=spotify:user:attributes:update
[2023-01-12T17:34:04Z DEBUG librespot_core::mercury] listening to uri=spotify:user:attributes:mutated
[2023-01-12T17:34:04Z DEBUG librespot_core::mercury] listening to uri=hm://pusher/v1/connections/
[2023-01-12T17:34:04Z TRACE librespot_connect::spirc] Received update frame: version: 1
    ident: "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"
    protocol_version: "2.0.0"
    seq_nr: XXXXXXXXXX
    typ: kMessageTypeNotify
    device_state {
      sw_version: "X.X.X.XXXX.XXXXXXXX"
      is_active: false
      can_play: true
      volume: XXXXXXXXX
      name: "XXXXXXXXXXXXXXXXX"
      capabilities {
        typ: kCanBePlayer
        intValue: 1
      }
      capabilities {
        typ: kRestrictToLocal
        intValue: 0
      }
      capabilities {
        typ: kGaiaEqConnectId
        intValue: 1
      }
      capabilities {
        typ: kSupportsLogout
        intValue: 1
      }
      capabilities {
        typ: kIsObservable
        intValue: 1
      }
      capabilities {
        typ: kCommandAcks
        intValue: 1
      }
      capabilities {
        typ: kSupportsRename
        intValue: 1
      }
      capabilities {
        typ: kHidden
        intValue: 0
      }
      capabilities {
        typ: kDeviceType
        intValue: 1
      }
      capabilities {
        typ: kVolumeSteps
        intValue: 64
      }
      capabilities {
        typ: kSupportsPlaylistV2
        intValue: 1
      }
      capabilities {
        typ: kSupportsExternalEpisodes
        intValue: 1
      }
      capabilities {
        typ: kSupportedTypes
        stringValue: "audio/ad"
        stringValue: "audio/episode"
        stringValue: "audio/episode+track"
        stringValue: "audio/interruption"
        stringValue: "audio/local"
        stringValue: "audio/track"
        stringValue: "video/ad"
        stringValue: "video/episode"
      }
      metadata {
        type: "device_address_mask"
        metadata: "XXX.XXX.XXX.XXX/24"
      }
      metadata {
        type: "debug_level"
        metadata: "1"
      }
      metadata {
        type: "tier1_port"
        metadata: "0"
      }
      metadata {
        type: "client_id"
        metadata: "XXXXXXXXXXXXXXXXXXXXXXXXXXXX"
      }
      metadata {
        type: "brand_display_name"
        metadata: "spotify"
      }
      metadata {
        type: "model_display_name"
        metadata: "PC desktop"
      }
    }
    state_update_id: XXXXXXXXXXXXXXXXXXXXX

[2023-01-12T17:34:04Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusStop]
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] Received update frame: version: 1
    ident: "webapi-XXXXXXXXXXXXXXXXXXXXXXXXXXX"
    protocol_version: "2.0.0"
    seq_nr: XXXXXXXXXXXXXXXXX
    typ: kMessageTypeLoad
    device_state {
      sw_version: ""
      is_active: false
      can_play: false
      volume: 0
      name: ""
      capabilities {
        typ: kCanBePlayer
        intValue: 0
      }
      capabilities {
        typ: kRestrictToLocal
        intValue: 0
      }
      capabilities {
        typ: kGaiaEqConnectId
        intValue: 0
      }
      capabilities {
        typ: kSupportsLogout
        intValue: 0
      }
      capabilities {
        typ: kIsObservable
        intValue: 0
      }
      capabilities {
        typ: kCommandAcks
        intValue: 0
      }
      capabilities {
        typ: kSupportsRename
        intValue: 0
      }
      capabilities {
        typ: kHidden
        intValue: 1
      }
      capabilities {
        typ: kDeviceType
        intValue: 0
      }
      capabilities {
        typ: kVolumeSteps
        intValue: 0
      }
      capabilities {
        typ: kSupportsPlaylistV2
        intValue: 0
      }
      capabilities {
        typ: kSupportsExternalEpisodes
        intValue: 0
      }
    }
    state {
      index: 0
      position_ms: 0
      status: kPlayStatusPlay
      position_measured_at: XXXXXXXXXXXXXXXXX
      context_description: ""
      shuffle: false
      repeat: false
      playing_from_fallback: true
      row: 0
      playing_track_index: 0
      track {
        gid: "N\326>O\216II\334\236\244kKe\004\211\355"
      }
    }
    state_update_id: XXXXXXXXXXXXXXXX
    recipient: "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"

[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitSessionConnectedEvent("", "XXXXXXXXXXXXXXXXXXXXXXXX")
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] State: index: 0
    position_ms: 0
    status: kPlayStatusPlay
    position_measured_at: XXXXXXXXXXXXXXXXXXXXX
    context_description: ""
    shuffle: false
    repeat: false
    playing_from_fallback: true
    row: 0
    playing_track_index: 0
    track {
      gid: "N\326>O\216II\334\236\244kKe\004\211\355"
    }

[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] Frame has 1 tracks
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitSessionClientChangedEvent("XXXXXXXXXXXXXXXXXXXXXXXXXXX", "", "spotify", "PC desktop")
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitVolumeChangedEvent(49152)
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitAutoPlayChangedEvent(false)
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitFilterExplicitContentChangedEvent(false)
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitShuffleChangedEvent(false)
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=EmitRepeatChangedEvent(false)
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false)
[2023-01-12T17:34:12Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2oLjhx7w8Hyd3gry9cCXr7"), true, 0)
[2023-01-12T17:34:12Z DEBUG librespot::component] new SpClient
[2023-01-12T17:34:12Z INFO  librespot_core::spclient] Resolved "XXXXXXXXXX-XXXXXXXXXXX.spotify.com:443" as spclient access point
[2023-01-12T17:34:12Z TRACE librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token.
[2023-01-12T17:34:12Z TRACE librespot_core::token] Requested token in scopes "playlist-read" unavailable or expired, requesting new token.
[2023-01-12T17:34:12Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-01-12T17:34:12Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-01-12T17:34:12Z TRACE librespot_core::token] Got token: Token {
        access_token: "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX",
        expires_in: 3600s,
        token_type: "Bearer",
        scopes: [
            "playlist-read",
        ],
        timestamp: Instant {
            t: XXXXXXXXXXXX.XXXXXXXXXXXs,
        },
    }
[2023-01-12T17:34:12Z DEBUG librespot_core::spclient] Client token unavailable or expired, requesting new token.
[2023-01-12T17:34:12Z DEBUG librespot_core::http_client] Requesting https://clienttoken.spotify.com/v1/clienttoken
[2023-01-12T17:34:12Z DEBUG librespot_core::mercury] unknown subscription uri=social-connect/v2/session_update
[2023-01-12T17:34:12Z TRACE librespot_core::mercury] response pushed over Mercury: MercuryResponse { uri: "social-connect/v2/session_update", status_code: 200, payload: [[123, 34, 115, 101, 115, ....]] }
[2023-01-12T17:34:12Z DEBUG librespot_core::session] could not dispatch command: Service unavailable { error handling Mercury response: MercuryResponse { uri: "social-connect/v2/session_update", status_code: 200, payload: [[123, 34, 115, ....]] } }
[2023-01-12T17:34:12Z TRACE librespot_core::spclient] Got client token: token: "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" expires_after_seconds: 1216800 refresh_after_seconds: 1209600 domains {domain: "spotify.com"}
[2023-01-12T17:34:12Z TRACE librespot_core::spclient] Got client token: token: "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX" expires_after_seconds: 1216800 refresh_after_seconds: 1209600 domains {domain: "spotify.com"}
[2023-01-12T17:34:12Z DEBUG librespot_core::http_client] Requesting https://XXXXX-spclient.spotify.com:443/metadata/4/track/XXXXXXXXXXXXXXXXXXXXXXXXXXXX?product=0&country=NL&salt=XXXXXXXXXXXXX
[2023-01-12T17:34:12Z DEBUG librespot_core::http_client] Requesting https://XXXXX-spclient.spotify.com:443/radio-apollo/v3/tracks/?autoplay=false&product=0&country=NL&salt=XXXXXXXXXXXX
[2023-01-12T17:34:12Z ERROR librespot_connect::spirc] ContextError: Error { kind: NotFound, error: StatusCode(404) }
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:34:12Z TRACE librespot_metadata] Received metadata: gid: "N\326>O\216II\334\236\244kKe\004\211\355"
    name: "21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro"
    album {
      gid: "\232\376\242\305\261\213J\364\207}\350@Qx\307m"
      name: "Brahms: 21 Hungarian Dances"
      artist {
        gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
        name: "Johannes Brahms"
      }
      artist {
        gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
        name: "Wiener Philharmoniker"
      }
      artist {
        gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
        name: "Claudio Abbado"
      }
      label: "Deutsche Grammophon (DG)"
      date {
        year: 1984
        month: 1
        day: 1
      }
      cover_group {
        image {
          file_id: "\253gam\000\000\036\002\322\312SQU\350\202\316\202\336\037\353"
          size: DEFAULT
          width: 300
          height: 300
        }
        image {
          file_id: "\253gam\000\000HQ\322\312SQU\350\202\316\202\336\037\353"
          size: SMALL
          width: 64
          height: 64
        }
        image {
          file_id: "\253gam\000\000\262s\322\312SQU\350\202\316\202\336\037\353"
          size: LARGE
          width: 640
          height: 640
        }
      }
    }
    artist {
      gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
      name: "Johannes Brahms"
    }
    artist {
      gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
      name: "Wiener Philharmoniker"
    }
    artist {
      gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
      name: "Claudio Abbado"
    }
    number: 5
    disc_number: 1
    duration: 138706
    popularity: 63
    external_id {
      type: "isrc"
      id: "DEF058230904"
    }
    file {
      file_id: "\022%\035\347W\027`\211\324\212\232\342E}\345\245t\272\352\356"
      format: OGG_VORBIS_320
    }
    file {
      file_id: "U\2438J\022(\036\337\275\005f$\250\222S\364j\263.\022"
      format: OGG_VORBIS_160
    }
    file {
      file_id: "\0137\346t\363\242\005\000W\232\274\323*\354\030K\031\213\331;"
      format: OGG_VORBIS_96
    }
    file {
      file_id: "/\235E\2248\320\260\034w2\013\021\307\265U<\367\365d\376"
    }
    file {
      file_id: "\316\312\266q>f\2521VK\312\266\251\211\226n\230.\317\017"
    }
    file {
      file_id: "\027\216\350\240>v,:[\361~\307C\365\207.\037\250\343\343"
    }
    file {
      file_id: "\024\206\177H\323\262l:\'q\311\277+\235D\214\324?Sw"
    }
    file {
      file_id: "l\345o\310\020\247\350\273p\244\314\361f\226/\r\273\357a\014"
      format: AAC_24
    }
    preview {
      file_id: "\022\250u\224\265)\240W\365\243T\205\360\330g\303Po-\032"
      format: MP3_96
    }
    earliest_live_timestamp: 413146860
    licensor {
      uuid: "\3765\216\251\207\342BM\220!\302fZ\006g\267"
    }
    language_of_performance: "zxx"
    original_title: "21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro"
    artist_with_role {
      artist_gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
      artist_name: "Johannes Brahms"
      role: ARTIST_ROLE_COMPOSER
    }
    artist_with_role {
      artist_gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
      artist_name: "Wiener Philharmoniker"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
      artist_name: "Claudio Abbado"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
      artist_name: "Johannes Brahms"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
      artist_name: "Claudio Abbado"
      role: ARTIST_ROLE_CONDUCTOR
    }
    artist_with_role {
      artist_gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
      artist_name: "Wiener Philharmoniker"
      role: ARTIST_ROLE_ORCHESTRA
    }

[2023-01-12T17:34:12Z TRACE librespot_metadata::audio::file] Ignoring file <2f9d459438d0b01c77320b11c7b5553cf7f564fe> with unspecified format
[2023-01-12T17:34:12Z TRACE librespot_metadata::audio::file] Ignoring file <cecab6713e66aa31564bcab6a989966e982ecf0f> with unspecified format
[2023-01-12T17:34:12Z TRACE librespot_metadata::audio::file] Ignoring file <178ee8a03e762c3a5bf17ec743f5872e1fa8e3e3> with unspecified format
[2023-01-12T17:34:12Z TRACE librespot_metadata::audio::file] Ignoring file <14867f48d3b26c3a2771c9bf2b9d448cd43f5377> with unspecified format
[2023-01-12T17:34:12Z INFO  librespot_playback::player] Loading <21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro> with Spotify URI <spotify:track:2oLjhx7w8Hyd3gry9cCXr7>
[2023-01-12T17:34:12Z DEBUG librespot_audio::fetch] File 0b37e674f3a20500579abcd32aec184b198bd93b already in cache
[2023-01-12T17:34:12Z DEBUG librespot::component] new AudioKeyManager
[2023-01-12T17:34:12Z INFO  librespot_playback::player] <21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro> (138706 ms) loaded
[2023-01-12T17:34:12Z TRACE librespot_playback::player] == Starting sink ==
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-01-12T17:34:12Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:34:31Z TRACE librespot_connect::spirc] Received update frame: version: 1
    ident: "webapi-XXXXXXXXXXXXXXXXXXXXXXXXXXX"
    protocol_version: "2.0.0"
    seq_nr: 655108681
    typ: kMessageTypeReplace
    device_state {
      sw_version: ""
      is_active: false
      can_play: false
      volume: 0
      name: ""
      capabilities {
        typ: kCanBePlayer
        intValue: 0
      }
      capabilities {
        typ: kRestrictToLocal
        intValue: 0
      }
      capabilities {
        typ: kGaiaEqConnectId
        intValue: 0
      }
      capabilities {
        typ: kSupportsLogout
        intValue: 0
      }
      capabilities {
        typ: kIsObservable
        intValue: 0
      }
      capabilities {
        typ: kCommandAcks
        intValue: 0
      }
      capabilities {
        typ: kSupportsRename
        intValue: 0
      }
      capabilities {
        typ: kHidden
        intValue: 1
      }
      capabilities {
        typ: kDeviceType
        intValue: 0
      }
      capabilities {
        typ: kVolumeSteps
        intValue: 0
      }
      capabilities {
        typ: kSupportsPlaylistV2
        intValue: 0
      }
      capabilities {
        typ: kSupportsExternalEpisodes
        intValue: 0
      }
    }
    state {
      index: 0
      position_ms: XXXXXXXXXXXXXXX
      status: kPlayStatusPlay
      position_measured_at: XXXXXXXXXXXXXXXXX
      context_description: ""
      shuffle: false
      repeat: false
      playing_from_fallback: true
      row: 0
      playing_track_index: 0
      track {
        gid: "N\326>O\216II\334\236\244kKe\004\211\355"
      }
      track {
        gid: "S\\_\333B\215M\223\206\014Q)&\214\362\275"
        queued: true
      }
    }
    state_update_id: XXXXXXXXXXXXXXXXXXX
    recipient: "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX"

[2023-01-12T17:34:31Z TRACE librespot_connect::spirc] State: index: 0
    position_ms: XXXXXXXXXXXXXX
    status: kPlayStatusPlay
    position_measured_at: XXXXXXXXXXXXXXXX
    context_description: ""
    shuffle: false
    repeat: false
    playing_from_fallback: true
    row: 0
    playing_track_index: 0
    track {
      gid: "N\326>O\216II\334\236\244kKe\004\211\355"
    }
    track {
      gid: "S\\_\333B\215M\223\206\014Q)&\214\362\275"
      queued: true
    }

[2023-01-12T17:34:31Z TRACE librespot_connect::spirc] Frame has 2 tracks
[2023-01-12T17:34:31Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:34:31Z DEBUG librespot_core::http_client] Requesting https://XXXX-spclient.spotify.com:443/radio-apollo/v3/tracks/?autoplay=false&product=0&country=NL&salt=1837300344
[2023-01-12T17:34:31Z ERROR librespot_connect::spirc] ContextError: Error { kind: NotFound, error: StatusCode(404) }
[2023-01-12T17:34:32Z DEBUG librespot_playback::player] command=SetAutoNormaliseAsAlbum(false)
[2023-01-12T17:35:57Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2xizRhme7pYeITbH1NLLGt"))
[2023-01-12T17:35:57Z DEBUG librespot_playback::player] Preloading track
[2023-01-12T17:35:57Z DEBUG librespot_core::http_client] Requesting https://XXXX-spclient.spotify.com:443/metadata/4/track/535c5fdb428d4d93860c5129268cf2bd?product=0&country=NL&salt=2274839568
[2023-01-12T17:35:57Z TRACE librespot_metadata] Received metadata: gid: "S\\_\333B\215M\223\206\014Q)&\214\362\275"
    name: "Tchaikovsky: Swan Lake, Op. 20, Act II: No. 10, Scene. Moderato"
    album {
      gid: "\355a\'=\364QA$\251\347,\'\360\350e\330"
      name: "Tchaikovsky: Swan Lake"
      artist {
        gid: "|h\031{}\246Ob\200\331I\306\360\315\340\212"
        name: "Pyotr Ilyich Tchaikovsky"
      }
      artist {
        gid: "\347j\300(\010\331L\277\251\002\022\350\307\225I\205"
        name: "Alfredo Kraus"
      }
      artist {
        gid: "Q7\356\301\251\345F\223\2167ZW\227\177T\220"
        name: "Andr\303\251 Previn"
      }
      artist {
        gid: "\266\226\343\267o\270K\326\262eo,\245\t\240\024"
        name: "London Symphony Orchestra"
      }
      label: "Warner Classics"
      date {
        year: 1976
      }
      cover_group {
        image {
          file_id: "\253gam\000\000\036\002\035\234f\002\252\225\253\330\305\261F\332"
          size: DEFAULT
          width: 300
          height: 300
        }
        image {
          file_id: "\253gam\000\000HQ\035\234f\002\252\225\253\330\305\261F\332"
          size: SMALL
          width: 64
          height: 64
        }
        image {
          file_id: "\253gam\000\000\262s\035\234f\002\252\225\253\330\305\261F\332"
          size: LARGE
          width: 640
          height: 640
        }
      }
    }
    artist {
      gid: "|h\031{}\246Ob\200\331I\306\360\315\340\212"
      name: "Pyotr Ilyich Tchaikovsky"
    }
    artist {
      gid: "Q7\356\301\251\345F\223\2167ZW\227\177T\220"
      name: "Andr\303\251 Previn"
    }
    artist {
      gid: "\266\226\343\267o\270K\326\262eo,\245\t\240\024"
      name: "London Symphony Orchestra"
    }
    number: 10
    disc_number: 1
    duration: 166866
    popularity: 68
    external_id {
      type: "isrc"
      id: "GBAYC0702145"
    }
    file {
      file_id: "\274\006\365\020\243\332P@\257\364Ak\252\351\263\250\316.f\356"
      format: OGG_VORBIS_320
    }
    file {
      file_id: "\376;\001%6\375\032O\324o\300\245\002a>8\265W\216\367"
      format: OGG_VORBIS_160
    }
    file {
      file_id: "^\370]n\322l\300\201\266\255\217\213\\\231E\230u\372\353\262"
      format: OGG_VORBIS_96
    }
    file {
      file_id: "S}\221\203r\220\254nZ\244\372=I\206\013\362e\262\305w"
    }
    file {
      file_id: "\212\374wC\253)\036U\330\020\207=\310\030\322)\330\314~\342"
    }
    file {
      file_id: "\355>(v\363\037\"\306\007\270\023\203\222\212\206\206\251\007\026y"
    }
    file {
      file_id: "G\327\237Uu\311\362\311Zj\342\345\272@\242\275\202\302\374m"
    }
    file {
      file_id: "\353\315\316\370\314\351<\206b\223RR\014\355\262\263\272{\214l"
      format: AAC_24
    }
    preview {
      file_id: "\203As_{Sj\266(;\356\035R\317\006\261\374\003i\321"
      format: MP3_96
    }
    earliest_live_timestamp: 413146860
    licensor {
      uuid: "\2037\246\256\254\247D\247\263 P\360\306n\023\217"
    }
    language_of_performance: "zxx"
    original_title: "Tchaikovsky: Swan Lake, Op. 20, Act II: No. 10, Scene. Moderato"
    artist_with_role {
      artist_gid: "|h\031{}\246Ob\200\331I\306\360\315\340\212"
      artist_name: "Pyotr Ilyich Tchaikovsky"
      role: ARTIST_ROLE_COMPOSER
    }
    artist_with_role {
      artist_gid: "Q7\356\301\251\345F\223\2167ZW\227\177T\220"
      artist_name: "Andr\303\251 Previn"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\266\226\343\267o\270K\326\262eo,\245\t\240\024"
      artist_name: "London Symphony Orchestra"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "Q7\356\301\251\345F\223\2167ZW\227\177T\220"
      artist_name: "Andr\303\251 Previn"
      role: ARTIST_ROLE_CONDUCTOR
    }
    artist_with_role {
      artist_gid: "\266\226\343\267o\270K\326\262eo,\245\t\240\024"
      artist_name: "London Symphony Orchestra"
      role: ARTIST_ROLE_ORCHESTRA
    }

[2023-01-12T17:35:57Z TRACE librespot_metadata::audio::file] Ignoring file <537d91837290ac6e5aa4fa3d49860bf265b2c577> with unspecified format
[2023-01-12T17:35:57Z TRACE librespot_metadata::audio::file] Ignoring file <8afc7743ab291e55d810873dc818d229d8cc7ee2> with unspecified format
[2023-01-12T17:35:57Z TRACE librespot_metadata::audio::file] Ignoring file <ed3e2876f31f22c607b81383928a8686a9071679> with unspecified format
[2023-01-12T17:35:57Z TRACE librespot_metadata::audio::file] Ignoring file <47d79f5575c9f2c95a6ae2e5ba40a2bd82c2fc6d> with unspecified format
[2023-01-12T17:35:57Z INFO  librespot_playback::player] Loading <Tchaikovsky: Swan Lake, Op. 20, Act II: No. 10, Scene. Moderato> with Spotify URI <spotify:track:2xizRhme7pYeITbH1NLLGt>
[2023-01-12T17:35:57Z DEBUG librespot_audio::fetch] File 5ef85d6ed26cc081b6ad8f8b5c99459875faebb2 already in cache
[2023-01-12T17:35:57Z INFO  librespot_playback::player] <Tchaikovsky: Swan Lake, Op. 20, Act II: No. 10, Scene. Moderato> (166866 ms) loaded
[2023-01-12T17:36:04Z DEBUG librespot_core::session] Session strong=4 weak=6
[2023-01-12T17:36:26Z DEBUG librespot_connect::spirc] At track 2 of 2 <""> update [false]
[2023-01-12T17:36:26Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:36:26Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2xizRhme7pYeITbH1NLLGt"), true, 0)
[2023-01-12T17:36:26Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-01-12T17:36:26Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:38:04Z DEBUG librespot_core::session] Session strong=4 weak=6
[2023-01-12T17:38:41Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2oLjhx7w8Hyd3gry9cCXr7"))
[2023-01-12T17:38:41Z DEBUG librespot_playback::player] Preloading track
[2023-01-12T17:38:41Z DEBUG librespot_core::http_client] Requesting https://XXXX-spclient.spotify.com:443/metadata/4/track/4ed63e4f8e4949dc9ea46b4b650489ed?product=0&country=NL&salt=2092844859
[2023-01-12T17:38:41Z TRACE librespot_metadata] Received metadata: gid: "N\326>O\216II\334\236\244kKe\004\211\355"
    name: "21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro"
    album {
      gid: "\232\376\242\305\261\213J\364\207}\350@Qx\307m"
      name: "Brahms: 21 Hungarian Dances"
      artist {
        gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
        name: "Johannes Brahms"
      }
      artist {
        gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
        name: "Wiener Philharmoniker"
      }
      artist {
        gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
        name: "Claudio Abbado"
      }
      label: "Deutsche Grammophon (DG)"
      date {
        year: 1984
        month: 1
        day: 1
      }
      cover_group {
        image {
          file_id: "\253gam\000\000\036\002\322\312SQU\350\202\316\202\336\037\353"
          size: DEFAULT
          width: 300
          height: 300
        }
        image {
          file_id: "\253gam\000\000HQ\322\312SQU\350\202\316\202\336\037\353"
          size: SMALL
          width: 64
          height: 64
        }
        image {
          file_id: "\253gam\000\000\262s\322\312SQU\350\202\316\202\336\037\353"
          size: LARGE
          width: 640
          height: 640
        }
      }
    }
    artist {
      gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
      name: "Johannes Brahms"
    }
    artist {
      gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
      name: "Wiener Philharmoniker"
    }
    artist {
      gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
      name: "Claudio Abbado"
    }
    number: 5
    disc_number: 1
    duration: 138706
    popularity: 63
    external_id {
      type: "isrc"
      id: "DEF058230904"
    }
    file {
      file_id: "\022%\035\347W\027`\211\324\212\232\342E}\345\245t\272\352\356"
      format: OGG_VORBIS_320
    }
    file {
      file_id: "U\2438J\022(\036\337\275\005f$\250\222S\364j\263.\022"
      format: OGG_VORBIS_160
    }
    file {
      file_id: "\0137\346t\363\242\005\000W\232\274\323*\354\030K\031\213\331;"
      format: OGG_VORBIS_96
    }
    file {
      file_id: "/\235E\2248\320\260\034w2\013\021\307\265U<\367\365d\376"
    }
    file {
      file_id: "\316\312\266q>f\2521VK\312\266\251\211\226n\230.\317\017"
    }
    file {
      file_id: "\027\216\350\240>v,:[\361~\307C\365\207.\037\250\343\343"
    }
    file {
      file_id: "\024\206\177H\323\262l:\'q\311\277+\235D\214\324?Sw"
    }
    file {
      file_id: "l\345o\310\020\247\350\273p\244\314\361f\226/\r\273\357a\014"
      format: AAC_24
    }
    preview {
      file_id: "\022\250u\224\265)\240W\365\243T\205\360\330g\303Po-\032"
      format: MP3_96
    }
    earliest_live_timestamp: 413146860
    licensor {
      uuid: "\3765\216\251\207\342BM\220!\302fZ\006g\267"
    }
    language_of_performance: "zxx"
    original_title: "21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro"
    artist_with_role {
      artist_gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
      artist_name: "Johannes Brahms"
      role: ARTIST_ROLE_COMPOSER
    }
    artist_with_role {
      artist_gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
      artist_name: "Wiener Philharmoniker"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
      artist_name: "Claudio Abbado"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\265\267\300\033r\324G\021\234\010Ks\377\251\"r"
      artist_name: "Johannes Brahms"
      role: ARTIST_ROLE_MAIN_ARTIST
    }
    artist_with_role {
      artist_gid: "\334\010\327\327x\251I\216\271\002\271n\350\306\240\237"
      artist_name: "Claudio Abbado"
      role: ARTIST_ROLE_CONDUCTOR
    }
    artist_with_role {
      artist_gid: "\000\007\030\247\344\226Ju\271\251\366]\320I\246\345"
      artist_name: "Wiener Philharmoniker"
      role: ARTIST_ROLE_ORCHESTRA
    }

[2023-01-12T17:38:41Z TRACE librespot_metadata::audio::file] Ignoring file <2f9d459438d0b01c77320b11c7b5553cf7f564fe> with unspecified format
[2023-01-12T17:38:41Z TRACE librespot_metadata::audio::file] Ignoring file <cecab6713e66aa31564bcab6a989966e982ecf0f> with unspecified format
[2023-01-12T17:38:41Z TRACE librespot_metadata::audio::file] Ignoring file <178ee8a03e762c3a5bf17ec743f5872e1fa8e3e3> with unspecified format
[2023-01-12T17:38:41Z TRACE librespot_metadata::audio::file] Ignoring file <14867f48d3b26c3a2771c9bf2b9d448cd43f5377> with unspecified format
[2023-01-12T17:38:41Z INFO  librespot_playback::player] Loading <21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro> with Spotify URI <spotify:track:2oLjhx7w8Hyd3gry9cCXr7>
[2023-01-12T17:38:41Z DEBUG librespot_audio::fetch] File 0b37e674f3a20500579abcd32aec184b198bd93b already in cache
[2023-01-12T17:38:41Z INFO  librespot_playback::player] <21 Hungarian Dances, WoO 1: No. 5 in G Minor: Allegro> (138706 ms) loaded
[2023-01-12T17:39:10Z DEBUG librespot_connect::spirc] At track 2 of 2 <""> update [false]
[2023-01-12T17:39:10Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:39:10Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2oLjhx7w8Hyd3gry9cCXr7"), true, 0)
[2023-01-12T17:39:10Z TRACE librespot_connect::spirc] ==> kPlayStatusPlay
[2023-01-12T17:39:10Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPlay]
[2023-01-12T17:40:04Z DEBUG librespot_core::session] Session strong=4 weak=6
[2023-01-12T17:40:57Z DEBUG librespot_playback::player] command=Preload(SpotifyId("spotify:track:2oLjhx7w8Hyd3gry9cCXr7"))
[2023-01-12T17:40:57Z DEBUG librespot_playback::player] Preloading track
[2023-01-12T17:41:27Z DEBUG librespot_connect::spirc] At track 2 of 1 <""> update [false]
[2023-01-12T17:41:27Z DEBUG librespot_connect::spirc] Looping back to start, repeat is false
[2023-01-12T17:41:27Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-01-12T17:41:27Z DEBUG librespot_playback::player] command=Load(SpotifyId("spotify:track:2oLjhx7w8Hyd3gry9cCXr7"), false, 0)
[2023-01-12T17:41:27Z TRACE librespot_playback::player] == Stopping sink ==
[2023-01-12T17:41:27Z TRACE librespot_connect::spirc] ==> kPlayStatusPause
[2023-01-12T17:41:27Z TRACE librespot_connect::spirc] Sending status to server: [kPlayStatusPause]
[2023-01-12T17:41:36Z INFO  librespot] Gracefully shutting down
[2023-01-12T17:41:36Z TRACE librespot_connect::spirc] Received SpircCommand::Shutdown
[2023-01-12T17:41:36Z DEBUG librespot_playback::player] command=Stop
[2023-01-12T17:41:36Z DEBUG librespot_playback::player] command=EmitSessionDisconnectedEvent("", "XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX")
[2023-01-12T17:41:36Z DEBUG librespot_connect::spirc] drop Spirc[0]
[2023-01-12T17:41:36Z DEBUG librespot_playback::player] Shutting down player thread ...
[2023-01-12T17:41:36Z DEBUG librespot_playback::player] drop PlayerInternal[0]
[2023-01-12T17:41:36Z DEBUG librespot_playback::player] PlayerInternal thread finished.
[2023-01-12T17:41:36Z DEBUG librespot_core::session] drop Session
[2023-01-12T17:41:36Z DEBUG librespot::component] drop ApResolver
[2023-01-12T17:41:36Z DEBUG librespot::component] drop AudioKeyManager
[2023-01-12T17:41:36Z DEBUG librespot::component] drop MercuryManager
[2023-01-12T17:41:36Z DEBUG librespot::component] drop SpClient
[2023-01-12T17:41:36Z DEBUG librespot::component] drop TokenProvider
[2023-01-12T17:41:36Z DEBUG librespot_core::session] drop Dispatch
roderickvd commented 1 year ago

I think your proposed fix may be correct, but it must be tested in multiple variants. The code there is rather crufty. I admit that I spent some time there before, trying to fix some cases on the short-term, without doing the refactoring I suspect it might deserve on the long term.

Can you try your fix in varying combinations of repeat on/off, shuffle on/off, playlists with single/two/more tracks, and so on? There are quite a number of cases to cover here.