Spotify pipe seem to be broken

[jappish84]

• steps to reproduce and/or logging of the error
  • stream from the spotify app to the pipe
• version of owntone
  • 28.4
• platform
  • docker container running on a VM I've had this working for quite some time but recently noticed that this must have gotten broken. No audio is plying when playing to the spotify pipe. The spotify app quickly changes a few songs and after it settles it gives the impression that it's playing a song on forked-daapd speaker (pipe) but no audio is playing and WebUI shows no songs playing.

Simply choosing a spotify playlist from the webUI works as expected though.

Here are the logs I've managed to capture:

[2022-07-30T14:45:36Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 166058163510854302058009012321170738111, audio_type: Track }>: ()
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <I Feel Like I'm Drowning> with Spotify URI <spotify:track:3aauaXWRgwCMoykMbI0Jq1>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 230355740659092191195643390269684858994, audio_type: Track }>: ()
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2022-07-30 16:45:37] [DEBUG]   player: Player status: stopped
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=32'
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2022-07-30 16:45:37] [DEBUG]   player: Player status: stopped
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=32'
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2022-07-30 16:45:37] [DEBUG]   player: Player status: stopped
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
[2022-07-30 16:45:37] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=32'
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <Feel the Love (feat. John Newman)> with Spotify URI <spotify:track:0BomfsUcw03fQPKK668Etn>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 26340424053977082570291133824133571229, audio_type: Track }>: ()
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <High - Don Diablo Remix> with Spotify URI <spotify:track:6c2NgGHj1PxDhpkbx4d5nO>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 270530347455813581057373684321701317456, audio_type: Track }>: ()
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <Permanence> with Spotify URI <spotify:track:05IbhAKODbXn8og9uaUgpc>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 4024098305259685389224001944127129530, audio_type: Track }>: ()
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <The Unknown> with Spotify URI <spotify:track:3j5udcJCWrQK51O6wahLyf>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 144469147190377836445704883036494704799, audio_type: Track }>: ()
[2022-07-30 16:45:37] [DEBUG]     dacp: Update request: client closed connection
[2022-07-30 16:45:37] [DEBUG]     dacp: Update request: client closed connection
[2022-07-30 16:45:37] [DEBUG]     dacp: Update request: client closed connection
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <20:25> with Spotify URI <spotify:track:3zwR7O61Dl7hsf5nwENrvy>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 156050885898634735843939459439788262216, audio_type: Track }>: ()
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <Think I'm Crazy> with Spotify URI <spotify:track:271bNJw8s9aL0EqxBZY56P>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 92292993193368913420333119174155946315, audio_type: Track }>: ()
[2022-07-30T14:45:37Z INFO  librespot_playback::player] Loading <Barely Breathing> with Spotify URI <spotify:track:4iJ5m4KWZpgDBUnl1EfA3K>
[2022-07-30T14:45:37Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:37Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:37Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 187888887777938519269337250337990595616, audio_type: Track }>: ()
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <First Breath> with Spotify URI <spotify:track:75nBbBcSc6unGATTuhB8Ig>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 309510016819379578975482016768533146688, audio_type: Track }>: ()
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <Ride Wit Me> with Spotify URI <spotify:track:3Gf5nttwcX9aaSQXRWidEZ>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 160779951696628424634038267245240216145, audio_type: Track }>: ()
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <L*** Is a Bad Word> with Spotify URI <spotify:track:3Kvce9qtIAmR4Axtq7mdGl>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 163780687301279491813280213518938231477, audio_type: Track }>: ()
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <Do It Again> with Spotify URI <spotify:track:3SoxkXbPiVU8Pw5JoxCJAN>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 169340411442020553120933124491315406653, audio_type: Track }>: ()
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2022-07-30 16:45:38] [DEBUG]   player: Player status: stopped
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=32'
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2022-07-30 16:45:38] [DEBUG]   player: Player status: stopped
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=32'
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getproperty?properties=dmcp.volume'
[2022-07-30 16:45:38] [DEBUG]   player: Player status: stopped
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/getspeakers'
[2022-07-30 16:45:38] [DEBUG]     dacp: DACP request: '/ctrl-int/1/playstatusupdate?revision-number=32'
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <LSD> with Spotify URI <spotify:track:0jHWM2GRtH258HIsmBlznw>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 13883367474689331211138554078837858598, audio_type: Track }>: ()
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <Where Are You?> with Spotify URI <spotify:track:0kVbqPkUBwEMcUmXw4ZuMX>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 14738178670835048666487844732883080043, audio_type: Track }>: ()
[2022-07-30T14:45:38Z INFO  librespot_playback::player] Loading <Crack A Bottle> with Spotify URI <spotify:track:4dK00wCxlqWEeN8BoM1BHT>
[2022-07-30T14:45:38Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:38Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:38Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 184377152357998709924323488667599991661, audio_type: Track }>: ()
[2022-07-30T14:45:39Z INFO  librespot_playback::player] Loading <Chocolate (feat. Trozé)> with Spotify URI <spotify:track:6EC5JMW0hwIRawSOVJfVQn>
[2022-07-30T14:45:39Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:39Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:39Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 290655246317651689408464538760593640011, audio_type: Track }>: ()
[2022-07-30 16:45:39] [DEBUG]     dacp: Update request: client closed connection
[2022-07-30 16:45:39] [DEBUG]     dacp: Update request: client closed connection
[2022-07-30 16:45:39] [DEBUG]     dacp: Update request: client closed connection
[2022-07-30T14:45:39Z INFO  librespot_playback::player] Loading <Yeah! (feat. Lil Jon & Ludacris)> with Spotify URI <spotify:track:5rb9QrpfcKFHM1EUbSIurX>
[2022-07-30T14:45:39Z ERROR librespot_core::channel] channel error: 2 1
[2022-07-30T14:45:39Z ERROR librespot_playback::player] Unable to load encrypted file: ChannelError
[2022-07-30T14:45:39Z WARN  librespot_playback::player] Skipping to next track, unable to load track <SpotifyId { id: 237517477035830874206699596520797739229, audio_type: Track }>: ()
[2022-07-30T14:45:39Z INFO  librespot_playback::player] Loading <We Are Love> with Spotify URI <spotify:track:2MEkDq4Rl17FXDWK5JKsVX>

[ejurgensen]

Those errors seem to come from librespot, so I think you have to report it there. I expect you see the same when you use librespot standalone.

[ejurgensen]

Maybe it is this issue: https://github.com/librespot-org/librespot/issues/972

[jappish84]

Thank you, I have been able to confirm that the issues is the one you posted here above. I have a few speakers using librespot but only the owntone build was the one causing the issue that's why I wrongly assumed this was an owntone issue. Thanks for pointing me in the right direction