Spotify Connect doesn't connect

zuli · December 18, 2020, 5:16pm

Hey,
I’m trying to use my Spotify Premium Family. I’m testing Volumio via USB 2.0 to a Benchmark DAC3.
Volumio is able to play to the DAC.
I can use Airplay from my Iphone to Volumio.
But SPotify doesn’t work. Usually I cannot see it as an available device. Sometimes it appears but you cannot connect

Any help?
This is the log:

at src/libstd/panicking.rs:325
30:   0x9c9404 - std::panic::catch_unwind::h8880a4c07cc66391
at src/libstd/panic.rs:394
31:   0x9c9404 - std::rt::lang_start_internal::hf4ae2140248bf16b
at src/libstd/rt.rs:51
32:   0x4e8d84 - main
33: 0x76cc8294 - __libc_start_main
info: CALLMETHOD: system_controller system enableLiveLog true
info: CoreCommandRouter::executeOnPlugin: system , enableLiveLog
info: Launching a new LiveLog session
volspotconnect2.service holdoff time over, scheduling restart.
Stopping Volspotconnect2 Daemon...
Starting Volspotconnect2 Daemon...
Started Volspotconnect2 Daemon.
vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07
Reading Config from "volspotify.toml"
[Vollibrespot] : Using Alsa backend with device: plughw:5
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-c19m.ap.spotify.com:443"
[Vollibrespot] : Authenticated as "11132001006" !
[Vollibrespot] : Setting up new mixer: card:hw:5 mixer:Benchmark DAC2 Audio 2.0 Output Playback Sw index:0
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(0)[dB]) -- max: 0 (MilliBel(0)[dB]) HW: false
[Vollibrespot] : Switching to linear volume mapping, control range: MilliBel(0)
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[Vollibrespot] : Using alsa sink
thread 'main' panicked at 'Couldn't get current volume: Error("snd_mixer_selem_get_playback_volume", Sys(EINVAL))', /build/cache/git/checkouts/librespot-6f197fd632ef9380/08d8bcc/playback/src/mixer/alsamixer.rs:94:14
stack backtrace:
0:   0xa0b33c - backtrace::backtrace::libunwind::trace::hae21a072c81e5842
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
1:   0xa0b33c - backtrace::backtrace::trace_unsynchronized::h0f9b260087e46e47
at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
2:   0xa0b33c - std::sys_common::backtrace::_print_fmt::hbf1a59173a7860c3
at src/libstd/sys_common/backtrace.rs:78
3:   0xa0b33c - ::fmt::he1a5d6f378e506c4
at src/libstd/sys_common/backtrace.rs:59
4:   0xa2bd5c - core::fmt::write::hb37ae5a5e0b70623
at src/libcore/fmt/mod.rs:1076
5:   0xa04c64 - std::io::Write::write_fmt::ha24bb3f5a858327b
at src/libstd/io/mod.rs:1537
6:   0xa0d974 - std::sys_common::backtrace::_print::h47b03aa1342833e3
at src/libstd/sys_common/backtrace.rs:62
7:   0xa0d974 - std::sys_common::backtrace::print::h2217cbc390250439
at src/libstd/sys_common/backtrace.rs:49
8:   0xa0d974 - std::panicking::default_hook::{{closure}}::h179f5229ea1c8e30
at src/libstd/panicking.rs:198
9:   0xa0d640 - std::panicking::default_hook::h46ab82039cbc65eb
at src/libstd/panicking.rs:217
10:   0xa0e054 - std::panicking::rust_panic_with_hook::h7326c48419bc7c33
at src/libstd/panicking.rs:526
11:   0xa0dc54 - rust_begin_unwind
at src/libstd/panicking.rs:437
12:   0xa29594 - core::panicking::panic_fmt::ha292e19d5ae716ed
at src/libcore/panicking.rs:85
13:   0xa293ec - core::option::expect_none_failed::h5afc8f3774fae01b
at src/libcore/option.rs:1269
14:   0x5f11f8 - librespot_playback::mixer::alsamixer::AlsaMixer::map_volume::h7d5c6cd4990de647
15:   0x5f1c74 - ::set_volume::h1824875d048eedd6
16:   0x5b97d8 - librespot_connect::spirc::SpircTask::set_volume::hbcc0ef22019a3745
17:   0x5b3b64 - librespot_connect::spirc::Spirc::new::hfd339f4dcad88e87
18:   0x52b890 - ::poll::hc5e7d2d1b7dbef13
19:   0x4f3844 - futures::task_impl::std::set::h8f081cf0436110c9
20:   0x50741c - std::thread::local::LocalKey::with::h711a13323aafc45a
21:   0x4e3a50 - tokio_current_thread::Entered
::block_on::h339073902a399eb7
22:   0x507e00 - std::thread::local::LocalKey::with::hff64c13ccfec5327

23:   0x51420c - tokio_reactor::with_default::h7ef12e65cb103d2f
volspotconnect2.service: main process exited, code=exited, status=101/n/a
Unit volspotconnect2.service entered failed state.
24:   0x4e79f8 - tokio::runtime::current_thread::runtime::Runtime::block_on::h043f136d6b8cf48f
25:   0x52d2c8 - vollibrespot::main::h02a0d49d4cc5eaa6
26:   0x514f18 - std::rt::lang_start::{{closure}}::h279cd2b7929fdba7
27:   0xa0e404 - std::rt::lang_start_internal::{{closure}}::he93bfc404849b78a
at src/libstd/rt.rs:52
28:   0xa0e404 - std::panicking::try::do_call::h6e9e98f4078affb0
at src/libstd/panicking.rs:348
29:   0xa0e404 - std::panicking::try::h2e68d4f7f799a6df
at src/libstd/panicking.rs:325
30:   0xa0e404 - std::panic::catch_unwind::h8880a4c07cc66391
at src/libstd/panic.rs:394
31:   0xa0e404 - std::rt::lang_start_internal::hf4ae2140248bf16b
at src/libstd/rt.rs:51
32:   0x52dd84 - main
33: 0x76d20294 - __libc_start_main
volspotconnect2.service holdoff time over, scheduling restart.
Stopping Volspotconnect2 Daemon...
Starting Volspotconnect2 Daemon...
Started Volspotconnect2 Daemon.
vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07
Reading Config from "volspotify.toml"```

zuli · December 18, 2020, 5:27pm

I’ve found a workaround changing the Mixer type in the Settings/Volume options to “None” or “Software”.
I’m not really sure how does this affects the quality of the reproduction.

ashthespy · December 18, 2020, 6:34pm

Yep, this seems to be a recurrent issue with some USB dacs. You should find quite a few posts about me trying to figure out why is happens already, but I haven’t had the time to fully investigate

[Vollibrespot] : Setting up new mixer: card:hw:5 
 mixer:Benchmark DAC2 Audio 2.0 Output Playback Sw index:0

Anyway, looks like that mixer doesn’t exist. Can you send me a log so I can dig deeper?

zuli · December 19, 2020, 8:00am

@ashthespy thank you for helping out!
this is the log http://logs.volumio.org/volumio/zaO0XeG.html

ashthespy · December 19, 2020, 11:26am

Thanks for that, as guessed, the Volumio API doesn’t figure out what mixer your DAC has and hence as VLS blindly uses what it gives, we crash when we can’t find it.

Dec 18 16:58:50 volumio volumio[1191]: Unable to parse:
Dec 18 16:58:50 volumio volumio[1191]: Simple mixer control 'Benchmark DAC2 Audio 2.0 Output Playback Sw',0
Dec 18 16:58:50 volumio volumio[1191]: Capabilities: pswitch
Dec 18 16:58:50 volumio volumio[1191]: Playback channels: Front Left - Front Right
Dec 18 16:58:50 volumio volumio[1191]: Mono:
Dec 18 16:58:50 volumio volumio[1191]: Front Left: Playback [on]
Dec 18 16:58:50 volumio volumio[1191]: Front Right: Playback [on]
Dec 18 16:58:50 volumio volumio[1191]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output

Does your DAC actually have a hardware mixer? Simply way to check is to launch alsamixer, hit F6 switch to your DAC (Card 5) and play with the sliders and see which one actually changes volume while playing something.

PS: If you can share, it should also be clearer

amixer -c5 scontrols

zuli · December 19, 2020, 7:42pm

This is what I’m getting from alsamixer

When I change the volume nothing changes.
PS: I’m not understanding what I should share to help you, sorry

ashthespy · December 19, 2020, 9:14pm

Sorry for the rather vague prose - I was a bit preoccupied…

Basically, if you go to these sliders (Benchmark DAC2) and then move them around with your arrow keys, you should hopefully hear volume changes?

The following command dumps some information about each of those mixers so we can try and figure out which one is the right mixer

amixer -c5 scontrols

zuli · December 20, 2020, 12:52pm

amixer -c5 scontrols

Simple mixer control 'Benchmark DAC2 Audio 2.0 Output Playback Sw',0
Simple mixer control 'Benchmark DAC2 Audio 2.0 Output Playback Sw',1
Simple mixer control 'Benchmark DAC2 Audio 2.0 Output Playback Vo',0
Simple mixer control 'Benchmark DAC2 Audio 2.0 Output Playback Vo',1
Simple mixer control 'SoftMaster',0

Scenario 1: Mixer Hardware - Playback from volumio
Volumio is not discoverable from Spotify

I can move Benchmark DAC2 Audio 2.0 Output Playback Vo and Benchmark DAC2 Audio 2.0 Output Playback Vo 1, and this changes the volume
I can also move Softmaster, but it doesn’t change the volume
In the volume UI I can change the volume but this doesn’t effect the playback volume

Scenario 2: Mixer None - Playback from Spotify from IPhone
Volumio is discoverable from Spotify

I can move Benchmark DAC2 Audio 2.0 Output Playback Vo and Benchmark DAC2 Audio 2.0 Output Playback Vo 1, and this changes the volume.
I can also move Softmaster, but it doesn’t change the volume.
Basically same as scenario1
In the volume UI I cannot change the volume which is fixed to 100

Thank you for your help!
Best
R

ashthespy · December 20, 2020, 1:42pm

So basically Volumio’s parsing logic fails for your DAC. You can hardcode it into the Vls’s config.toml file.

You should find it file at /data/plugins/music_service/volspotconnect2/volspotify.tmpl
And then remove these template values with the correct ones for your mixer, so that it doesn’t get overwritten by the wrong ones from the API.

mixer-name = 'Benchmark DAC2 Audio 2.0 Output Playback Vo'
mixer-card = '${mixdev}'
mixer-index = ${mixidx}

After that is done, restart the daemon with

journalctl restart volspotconnect2

Let me know if that works for your Spotify connect issues

PS: Scenario 2: Mixer None – this is as expected, as the UI just defaults to a preset constant value.

zuli · December 22, 2020, 5:07pm

I wasn’t able to connect to Spotify before to modify the config file
http://logs.volumio.org/volumio/LRTp5rh.html

And also after the modification it’s not working
http://logs.volumio.org/volumio/V8bqjOB.html

Volumio is discoverable, but it disconnects when selected

ashthespy · December 22, 2020, 5:16pm

The errors aren’t anything to do with the mixer config, looks you there some issues server side currently!

volumio[1955]: thread 'main' panicked at 'Spotify servers returned an error. Restart librespot.'
 /build/cache/git/checkouts/librespot-6f197fd632ef9380/08d8bcc/core/src/mercury/mod.rs:200:13

But in other news, your mixer setup is now correct

vollibrespot v0.2.2 cd96399 2020-10-07 (librespot 08d8bcc 2020-10-07) -- Built On 2020-10-07
Reading Config from "volspotify.toml"
[Vollibrespot] : Using Alsa backend with device: plughw:5
[Vollibrespot] : Connecting to AP "gew1-accesspoint-b-wg0s.ap.spotify.com:443"
[Vollibrespot] : Authenticated as "xxxxxxx" !
[Vollibrespot] : Setting up new mixer: card:hw:5 mixer:Benchmark DAC2 Audio 2.0 Output Playback Vo index:0
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[Vollibrespot] : Alsa Mixer info min: 0 (MilliBel(0)[dB]) -- max: 127 (MilliBel(0)[dB]) HW: false
[Vollibrespot] : Switching to linear volume mapping, control range: MilliBel(0)
[Vollibrespot] : Alsa min-db is not SND_CTL_TLV_DB_GAIN_MUTE!!
[SpotifyConnect]  0
[SpotifyConnect] Volume: Spotify:0 Volumio: 0

So try again (probably with a different track) in a while, hopefully Spotify finishes their server tuning by then?

zuli · December 22, 2020, 5:33pm

Well,
I think I’ve also other problems. I’m actually unable to get anything out of Volumio, even from a NAS (and this was working until this afternoon

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

zuli · December 22, 2020, 5:39pm

I’ve found the issue. In the mixer the third and the fifth as at 0. I don’t know why. I’ve manully moved them to 100 and I’m getting sound now

zuli · December 24, 2020, 5:23pm

@ashthespy I’m still getting some erratic behaviour. From time to time volumio disappears and spotify doesn’t work anymore. The last log should show the error at the very bottom, if you have can have a look at it.
Thanks
R
http://logs.volumio.org/volumio/mLJKafr.html

ashthespy · December 24, 2020, 5:56pm

Can you try disabling the “autoplay” in the plugin settings? It looks like it’s trying to autoplay your search query and fails. It normally should only query this endpoint for albums/playlists/tracks. I need to investigate if Spotify changed their API again.

[Vollibrespot] : Fetching autoplay context uri
[Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 192139317667023484952115033566058387572, audio_type: Track }, track_id: SpotifyId { id: 227132190234318368334859918200733443347, audio_type: Track } }
[Vollibrespot] : error 400 for uri hm://autoplay-enabled/query?uri=spotify:search:walking%20irr
[Vollibrespot] : AutoplayError: MercuryError
[SpotifyConnect]  Walking Irrevocable

zuli · December 24, 2020, 7:17pm

I’ve disabled the “autoplay”. Volumio was discoverable but still unable to play that song, from the suggested list. But it wasn’t disappearing.
I’ve tried another song from my library and it worked fine.
This is the last log, if you will have a chance to have a look at it http://logs.volumio.org/volumio/2Ov8vR9.html
In the meantime, have a wonderful holiday season ahead!

ashthespy · December 29, 2020, 6:00pm

I don’t see why it is failing the error unfortunately comes from a very generic error Spotify returns sometimes – what is this song? I could test to see if it’s song specific.

Spotify servers returned an error. Restart librespot.