New Volumio Spotify Plugin Open Beta-Testing

Wheaten · March 16, 2023, 7:00am

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

dvo · March 16, 2023, 8:30am

patrick has released a 1.01 version of the youtube plugin.

Michael_Guth · March 18, 2023, 8:59am

@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]

Wheaten · March 18, 2023, 10:48am

@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

lordvader · March 18, 2023, 1:45pm

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

XENONFFM · March 18, 2023, 3:15pm

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

forte89 · March 23, 2023, 5:49pm

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

pjorgenunes · March 24, 2023, 9:43am

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

Gjutarn · March 31, 2023, 9:52am

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

Wheaten · March 31, 2023, 10:53am

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
  },

Wheaten · March 31, 2023, 4:21pm

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
  },

Gjutarn · March 31, 2023, 7:18pm

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

Wheaten · March 31, 2023, 7:21pm

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.

starfly · March 31, 2023, 9:31pm

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?

Gjutarn · April 1, 2023, 2:50pm

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

Wheaten · April 1, 2023, 3:09pm

@volumio

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

TheToneCapone · April 1, 2023, 6:03pm

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

starfly · April 7, 2023, 10:24pm

Is there a way to have Spotify control Volumio’s volume? As it is, I need to go into Volumio to change volume, which is a hassle, especially when controlling from a phone.

The old Spotify Connect plugin supported this (along with every other Spotify Connect compatible device in the house that allows the Spotify app to control volume).

hankberry · April 8, 2023, 7:35pm

http://logs.volumio.org/volumio/6gpmjLQ.html

I am experiencing the same issues as @TheToneCapone with my RPi4 + Spotify Connect, running the latest versions of Volumio OS and Spotify Plugin.

The initial selection of songs works fine, but once I select any song outside that original playlist/album/radio, it pauses the song immediately, and rebooting the device is the only temporary fix.

I have no other plugins installed on the device. Thanks for the help!

Josh2000 · April 11, 2023, 1:09pm

Hi,

what could be tested if fixed in 3.0.10 beta version ?

br

Josef

Edit: Yes i know it’s beta. Since i upgraded to v3.0.10 the connect dropped 3 times during this work day - after just reconnecting in Spotify App it starts to play again. That did not happen with 3.0.9 stable