New Volumio Spotify Plugin Open Beta-Testing

Hello, I am encountering an issue with the Spotify plugin on 3.0.9. Specifically, the playback frequently stops unexpectedly after a few songs.

Additionally, I have noticed that Volumio becomes unresponsive when I try to resume playback after manually stopping a Spotify song and returning a few hours later. To continue playing, I usually have to restart Volumio.

Here my log of a short session in which it stopped after one or two songs.

Here´s my logfile:
[http://logs.volumio.org/volumio/utWagzx.html]
All other things like internetradio and youtube work fine.
Pi4 with DAC, Spotify premium.
Problem: Can´t start playing song in spotify, browsing works fine.

1 Like

@Michael_Guth

Please remove the youtube plugin as your log is full with errors.

Mar 10 17:28:28 volumiobuero volumio[820]: Failed to parse renderer: TypeError: Cannot read property 'reduce' of undefined
Mar 10 17:28:28 volumiobuero volumio[820]:     at parseChannelRenderer (/data/plugins/music_service/youtube2/node_modules/youtube-scrape/scraper.js:208:79)
Mar 10 17:28:28 volumiobuero volumio[820]:     at /data/plugins/music_service/youtube2/node_modules/youtube-scrape/scraper.js:167:47
Mar 10 17:28:28 volumiobuero volumio[820]:     at Array.forEach ()
Mar 10 17:28:28 volumiobuero volumio[820]:     at /data/plugins/music_service/youtube2/node_modules/youtube-scrape/scraper.js:164:58

You start playing Spotify before the boot is ready,

Mar 10 17:28:42 volumiobuero volumio[820]: info: BOOT COMPLETED
1 Like

patrick has released a 1.01 version of the youtube plugin.

1 Like

@Wheaten
Deinstalled Youtube plugin, rebooted, test of spotify failed (browsing ok but doesn´t start playing a song)
[http://logs.volumio.org/volumio/QJjn1jM.html]

@volumio
I see in this and previous log shared by Michael, any suggestion?:

Mar 18 08:54:02 volumiobuero volumio[817]: error: Failed to Set Device Active: Error: Not Found Device ID: 63b7e959bee0958a5327a21fe9f334d1c6a1bfca

Hi all,
Still getting the refresh token timeout issue with the 3.0.9 version of the plugin.
Logs attached: http://logs.volumio.org/volumio/88QLwiA.html

Hello

I have the following issue with the spotify plugin since 3.0.6:
Spotify connect only works on mobile devices. Neither Pc nor Laptop will connect.
This is kinda fixed if I connect first via mobile. After that I’m able to connect via Pc aswell (with the same account). Unfortunately Spotify behaves a bit weird then and does not show the currently played track inside a playlist.

Here the logs:

Starting Live Log...

info: CoreCommandRouter::volumioGetState
info: CorePlayQueue::getTrack 0
info: CoreCommandRouter::volumioGetQueue
info: CoreStateMachine::getQueue
info: CorePlayQueue::getQueue
info: CoreCommandRouter::executeOnPlugin: system , getHwuuid
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
[Vollibrespot] : Connecting to AP "ap-gew4.spotify.com:443"
[Vollibrespot] : Authenticated as "xxx" !
[Vollibrespot] : Using alsa sink
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: "CH"
[Vollibrespot] : Event: Volume { volume_to_mixer: 17627 }
[SpotifyConnect] Volume Spotify: 26.897077897306783 Volumio: 27
[Vollibrespot] : Fetching autoplay context uri
[Vollibrespot] : Event: SessionActive { became_active_at: 1679151569686 }
[Vollibrespot] : SessionActive!
[Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 71453761429729184779793147365141245289, audio_type: Track } }
[Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 71453761429729184779793147365141245289, audio_type: Track } }
[SpotifyConnect]  A connect session has begun
info: Acquiring new spotify session
info: CoreCommandRouter::volumioStop
info: CoreStateMachine::stop
info: CoreStateMachine::setConsumeUpdateService undefined
info: Checking Spotify Web API
[SpotifyConnect] Vollibrespot Active
info: CoreStateMachine::setConsumeUpdateService undefined
info: [1679151569702] ControllerSpotify::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
[Vollibrespot] : error 403 for uri hm://keymaster/token/authenticated?client_id=xxx&scope=streaming,user-read-playback-state,user-modify-playback-state,user-read-currently-playing,user-read-private
[Vollibrespot] : Error: MercuryError
[Vollibrespot] : No autoplay_uri found
[Vollibrespot] : AutoplayError: MercuryError
thread 'main' panicked at 'cannot poll Map twice', /build/cache/registry/src/github.com-1ecc6299db9ec823/futures-0.1.31/src/future/map.rs:35:29
stack backtrace:
[SpotifyConnect]  Device palyback is active!
[SpotifyConnect]  Device palyback is loading
   0:   0xa58444 - std::backtrace_rs::backtrace::libunwind::trace::h40a4eff66330a36d
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:   0xa58444 - std::backtrace_rs::backtrace::trace_unsynchronized::hbce01963451b0cd5
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:   0xa58444 - std::sys_common::backtrace::_print_fmt::h95da650d09c7e00b
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:66:5
   3:   0xa58444 - ::fmt::h33b23b1d14f668ff
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:45:22
   4:   0xa810dc - core::fmt::write::h6320fb0e6ac90e58
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/fmt/mod.rs:1190:17
   5:   0xa504c4 - std::io::Write::write_fmt::h33b25d4810ca481f
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/io/mod.rs:1657:15
   6:   0xa5aef4 - std::sys_common::backtrace::_print::h7e61c5be69c715ef
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:48:5
   7:   0xa5aef4 - std::sys_common::backtrace::print::h3cee176d7c8dab8b
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:35:9
   8:   0xa5aef4 - std::panicking::default_hook::{{closure}}::h2d0211dd2e97dc43
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:295:22
   9:   0xa5ab14 - std::panicking::default_hook::hcbdb3b7c40dca30c
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:314:9
  10:   0xa5b694 - std::panicking::rust_panic_with_hook::h4ce49e7a343dc12b
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:698:17
  11:   0xa5b304 - std::panicking::begin_panic_handler::{{closure}}::h4961100fae529fe9
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:588:13
  12:   0xa589c4 - std::sys_common::backtrace::__rust_end_short_backtrace::hf2e68e62c7a80f1f
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/sys_common/backtrace.rs:138:18
  13:   0xa5b098 - rust_begin_unwind
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:584:5
  14:   0x53e6f4 - core::panicking::panic_fmt::h84c42730e4a50809
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:143:14
  15:   0xa7df88 - core::panicking::panic_display::he50fbe261a13d083
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:73:5
  16:   0xa7df38 - core::panicking::panic_str::h6e4cfb6a94cf14e8
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/panicking.rs:56:5
  17:   0x53e57c - core::option::expect_failed::h5f2b901fbc810215
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/option.rs:1852:5
  18:   0x7a0e18 -  as futures::future::Future>::poll::h794cc547cc6bc145
  19:   0x629d78 - ::poll::h2a7bff75029d3b82
  20:   0x5662ec - ::poll::h5fd9e3bcdeb25ad9
  21:   0x5833dc - futures::task_impl::std::set::h8f754e80bd562d0a
  22:   0x59a42c - std::thread::local::LocalKey::with::h71cfa1e374fcc0a0
  23:   0x57f99c - tokio_current_thread::Entered
::block_on::hde55cdf28eabe6d5
  24:   0x59a6f0 - std::thread::local::LocalKey::with::hedba3cfe41326627
  25:   0x582880 - tokio::runtime::current_thread::runtime::Runtime::block_on::h6

0d5b89560100ed8
  26:   0x568eb0 - vollibrespot::main::h35555355ed947dd1
  27:   0x588c50 - std::sys_common::backtrace::__rust_begin_short_backtrace::hef626a10d324c12a
  28:   0x5ae52c - std::rt::lang_start::{{closure}}::hd80188e4bcac5072
  29:   0xa57b28 - core::ops::function::impls:: for &F>::call_once::h0567da839a080232
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/core/src/ops/function.rs:259:13
  30:   0xa57b28 - std::panicking::try::do_call::hdf194554a41aa3cc
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40
  31:   0xa57b28 - std::panicking::try::hbf4b7be9f9ffa5f8
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19
  32:   0xa57b28 - std::panic::catch_unwind::h45f392a39f2fe48c
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14
  33:   0xa57b28 - std::rt::lang_start_internal::{{closure}}::hd772cb03c2060671
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:48
  34:   0xa57b28 - std::panicking::try::do_call::hd126f715b519ff2a
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:492:40
  35:   0xa57b28 - std::panicking::try::h80b7148ce71893dc
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panicking.rs:456:19
  36:   0xa57b28 - std::panic::catch_unwind::h1562f0b2e8a9cb0d
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/panic.rs:137:14
  37:   0xa57b28 - std::rt::lang_start_internal::h3daa586a0b835507
                       at /rustc/7737e0b5c4103216d6fd8cf941b7ab9bdbaace7c/library/std/src/rt.rs:128:20
  38:   0x56ae80 - main
  39: 0x76c8f718 - __libc_start_main
[Vollibrespot] : EventSender disconnected
[SpotifyConnect]  PlaybackInactive
info: [1679151570095] ControllerSpotify::pushState
info: CoreCommandRouter::servicePushState
info: CoreStateMachine::pushState
info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
info: CoreCommandRouter::volumioPushState
info: CorePlayQueue::getTrack 0


info: CoreStateMachine::syncState   stateService stop
info: CoreStateMachine::syncState   currentStatus play
info: CoreCommandRouter::volumioPushState
info: CoreStateMachine::stPlaybackTimer
volspotconnect.service: Main process exited, code=exited, status=101/n/a
volspotconnect.service: Failed with result 'exit-code'.
volspotconnect.service: Service RestartSec=2s expired, scheduling restart.
volspotconnect.service: Scheduled restart job, restart counter is at 1.
Stopped Volspotconnect2 Daemon.
Started Volspotconnect2 Daemon.
vollibrespot v0.2.5 8922128 2022-05-31 (librespot 08d8bcc 2020-10-07) -- Built On 2022-05-31
Reading Config from "/tmp/volspotify.toml"
[Vollibrespot] : Using Alsa backend with device: volumio
[Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Uncategorized, message: "No such device" }
[Vollibrespot] : dropping truncated packet from 192.168.1.1:5353
[Vollibrespot] : dropping truncated packet from 192.168.1.1:5353

Full logs: http://logs.volumio.org/volumio/ajV6rRW.html

I just wanna say the plugin has been working amazingly well since the update. Thanks a lot for the great work!!

4 Likes

Also to say that, since last update of plugin, it´s working like a charm in my Volumio Primo.

4 Likes

Running RPI 4b Volumio 3 with Spotify plugin. Music always stops at the end of a song after 2-8 tracks been played. Sometime it’s possible to restart the song after a couple of minutes, sometimes a restart is required. Had this problem with Volumio 2 as well. Network through cable. Any ideas? Not very well versed in reading the log unfortunately.

Logs:
http://logs.volumio.org/volumio/Yj3SI9K.html

Please run the same test on a cabled network cnnection and upgrade the Spotify plugin to the latest V3.0.8 As you still running an older version.

 {
    prettyName: 'Spotify',
    name: 'spop',
    category: 'music_service',
    version: '3.0.6',
    icon: 'fa-spotify',
    isManuallyInstalled: false,
    enabled: true,
    active: true
  },

Where is the plugin SpotifyConnect coming from?

  {
    prettyName: 'Volumio Spotify Connect2',
    name: 'volspotconnect2',
    category: 'music_service',
    version: '3.0.8',
    icon: 'fa-spotify',
    isManuallyInstalled: false,
    enabled: false,
    active: true
  },
1 Like

I have removed the Spotify Connect plug in. Only Spotify running. The same result, music halts after7-8 tracks. The iOS app shows the song, as normal but the progressbar and seconds are standing still. Thanks for your support, I appreciate it.

http://logs.volumio.org/volumio/mwtrIb2.html

Please reflash your SD card and start over. Only install spotify plugin from the plugin store.

No clue what has been broken by installing unsupported plugins, I will not debug this.

http://logs.volumio.org/volumio/RlUDsAU.html

I have issues when I try to stream through Spotify Connect. It starts to play whatever the last song was that I played through my local/NAS music library. And when I try to do it again, I get static mixed with the song that’s playing from the local library. Really weird.

I also only recently upgraded to the latest version of Volumio, coming from whatever version was available around Feb of last year and using the other Spotify Connect plugin initially (which is now uninstalled).

Already tried uninstalling Spotify pluging, and re-installed it, but I get the same results.

Any thoughts on how to debug this?

Still problem with music stopping a couple of tracks in. Flashed SD with fresh reinstall yesterday, latest Volumio, running Spotify, RPI4b. Network connected through cable (network working fine).

http://logs.volumio.org/volumio/e1rRjcq.html

@volumio

Any siggestion, can’t find anything in the logs besides/;/
AutoplayError: MercuryError

I am continuing to have issues with Spotify Connect after the latest update (3.09).

After a fresh reboot of my RPi 4 with the latest version of Volumio installed, Spotify Connect will work on whatever album or Playlist is originally selected. I can choose tracks in that specific album/playlist and have them work as intended. Whenever any track is selected outside of that original album/playlist, one second of the song plays and the track pauses. This is on ANY track, no matter using Spotify Connect on a computer or my mobile phone.

The only way to get it out of this loop is to reboot he pi.

I would really like to just be able to use Spotify Connect without any hiccups in the near future. Hope this helps