volspotconnect2: Stuck on 'Making connection'

[RealHayo]

Hi ,

On my samsung S9 spotify app I can see the Volumio device in the device list and I can chose it. But then nothing happens. It is just stuck. The volumio entry is green but it states the message 'making a connection...' . (translated from Dutch, so I don't know what the english message looks like.)

Also, I use the Allo USBridge on the sparky. I can't tell if that might be the problem.

I uses the instructions in the github to install the latest version of this plugin. and i use the settings for the plugin as follows: Multi-user device: ON When I use it in OFF-mode, the volumio device is not even shown in the list within the spotify app.

All the other spotify plug-ins are not working either. I was hoping this plug in is closer to the spotify-approved method.

BR Hayo

[ashthespy]

Could you share whats in the logs?

[RealHayo]

yes i can (NB. I can use the embedded spotify plug in, since i found the fix on the forum).

Here it is for the librespot version:

volumio_log.txt

[ashthespy]

@RealHayo your issue seems to be related to setting up the right Mixer.

Sep 04 13:53:55 volumio volumio[5262]: [Vollibrespot] : Setting up new mixer: card:hw:1 mixer:SMSL Clock Selector,1 index:0
Sep 04 13:53:55 volumio volumio[5262]: thread 'main' panicked at 'Couldn't find SelemId', src/libcore/option.rs:1036:5

Could you check if your startconnect.sh contains an input for --mixer-name ? There is a nagging issue with the mixer setup with these newer versions of Volumio. Have a look at https://github.com/balbuze/volumio-plugins/issues/212 for workarounds.

[RealHayo]

Hi

The mixer name, as pointed out by you, is set to: --mixer-name 'SMSL Clock Selector,1' --mixer-card 'hw:1' \

I experimented with the settings before (w/o using any volspotconnect plugins). Setting it to None gave music, but than i cannot change the volume w/ the app. When selecting software no music can be heard.

If you think the work around in #212 works, i can give it a try. But it sounds pretty weak.

the startconnect.sh content is:

volumio@volumio:/data/plugins/music_service/volspotconnect2$ more startconnect.sh

this file is generated by the plugin. You should not edit it unless you know what you do. It will be overwritten by the

plugin each time a change in config is detected cd /data/plugins/music_service/volspotconnect2 ./vollibrespot -b 320 -c /tmp \ --disable-audio-cache \ --name 'Volumio' --initial-volume 20\ --device plughw:1 \ --mixer alsa \ --mixer-name 'SMSL Clock Selector,1' --mixer-card 'hw:1' \ --verbose

[ashthespy]

I don't think 'SMSL Clock Selector,1' is the right mixer name. I would reckon --mixer-name should be SMSL Clock Selector and --mixer-card should be hw:1 What is the output of

#1 
aplay -l
#2.  
cat /data/configuration/audio_interface/alsa_controller/config.json

[RealHayo]

ok, I changed to the other mixer (as described). And it works!!! To be fair, on the other version of volumio , it would not play w/ that mixer at all! (it was a journey this weekend , to get things working) Other side note, spotify app doesn't respond when volumio is already playing some music. I just found out i first have to stop the playback, then turn to the spotify app and use it to play. Other side note, i have 2 entries in device list in the spotify app both named volumio. But at least they both work.

Thanx a bunch! A donation is in order, since volumio is a pretty neat solution.

[ashthespy]

Spotify Connect is a different beast as its not running through mpd - which is what Volumio uses for most of the other playback. Thus, the volspotconnect2 plugin basically interfaces the Spotify connect daemon into Volumio. So if you open the logs, you will see stuff like:

[Vollibrespot] : Using alsa sink
[Vollibrespot] : Current alsa volume: 36[i64] MilliBel(9999999)
[Vollibrespot] : Mapping (lin) volume [40.000%] 26214 [u16] ->> Alsa [39.394%] 39 [i64]
[Vollibrespot] : Metadata pipe established
[Vollibrespot] : Country: "NL"
[Vollibrespot] : SessionActive!
[Vollibrespot] : Loading track "Oerwoud" with Spotify URI "spotify:track:4oPGlZ9SwSCLevO6csdyR0"
[Vollibrespot] : Track "Oerwoud" loaded
[Vollibrespot] : Loading track "Oerwoud" with Spotify URI "spotify:track:4oPGlZ9SwSCLevO6csdyR0"
[Vollibrespot] : Track "Oerwoud" loaded
[Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
[Vollibrespot] : Could not start audio: Alsa error: PCM open failed
[Vollibrespot] : Alsa error PCM open ALSA function 'snd_pcm_open' failed with error 'EBUSY: Device or resource busy'
[Vollibrespot] : Could not start audio: Alsa error: PCM open failed
[Vollibrespot] : Current alsa volume: 39[i64] MilliBel(9999999)
[Vollibrespot] : Mapping (lin) volume [41.561%] 27237 [u16] ->> Alsa [41.414%] 41 [i64]

This is basically the daemon complaining a few times about a busy device while the plugin tells Volumio to stop the current playback and release the Alsa device..

So to make your solution more seamless, I would suggest editing the volspotconnect2.tmpl and replace ${mixeropts} \ with --mixer-name 'SMSL Clock Selector' --mixer-card 'hw:1' and restart the plugin from the webui..

[RealHayo]

Followed up on your recommendations. Not quit there yet. Now it says it couldn't open a slave

Sep 05 21:09:30 volumio volumio[2305]: info: STATE SERVICE {"status":"play","position":0,"seek":487,"duration":305,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"isStreaming":false,"title":"Knockin' On Heaven's Door","artist":"United Rhythms Of Brazil","album":"Chillout In Blue","uri":"NAS/DiskStation/EDM/V.A. - Chillout In Blue (2009)/CD2/14. United Rhythms Of Brazil - Knockin' On Heaven's Door.mp3","trackType":"mp3"} Sep 05 21:09:30 volumio volumio[2305]: info: CURRENT POSITION 1 Sep 05 21:09:30 volumio sudo[9970]: pam_unix(sudo:session): session closed for user root Sep 05 21:09:30 volumio volumio[2305]: info: CoreStateMachine::syncState stateService play Sep 05 21:09:30 volumio volumio[2305]: info: CoreStateMachine::syncState currentStatus play Sep 05 21:09:30 volumio volumio[2305]: info: Received an update from plugin. extracting info from payload Sep 05 21:09:30 volumio volumio[2305]: info: CoreStateMachine::pushState Sep 05 21:09:30 volumio volumio[2305]: info: CoreStateMachine::getState Sep 05 21:09:30 volumio volumio[2305]: info: CorePlayQueue::getTrack 1 Sep 05 21:09:30 volumio volumio[2305]: info: CoreCommandRouter::volumioPushState Sep 05 21:09:30 volumio volumio[2305]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 21:09:30 volumio volumio[2305]: info: CoreStateMachine::pushState Sep 05 21:09:30 volumio volumio[2305]: info: CoreStateMachine::getState Sep 05 21:09:30 volumio volumio[2305]: info: CorePlayQueue::getTrack 1 Sep 05 21:09:30 volumio volumio[2305]: info: CoreCommandRouter::volumioPushState Sep 05 21:09:30 volumio volumio[2305]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 21:09:30 volumio sudo[9978]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 05 21:09:30 volumio sudo[9978]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 21:09:30 volumio sudo[9978]: pam_unix(sudo:session): session closed for user root Sep 05 21:09:30 volumio volumio[2305]: info: ------------------------------ 294ms Sep 05 21:09:30 volumio sudo[9985]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 05 21:09:30 volumio sudo[9985]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 21:09:30 volumio sudo[9985]: pam_unix(sudo:session): session closed for user root Sep 05 21:10:25 volumio volumio[3787]: {'volume': 100, 'context_uri': 'spotify192.168.1.18 - - [2019-09-05 21:10:25] "GET /login/_zeroconf?action=getInfo HTTP/1.1" 200 599 0.021666 Sep 05 21:10:26 volumio volumio[3787]: ALSA lib pcm_dmix.c:1052:(snd_pcm_dmix_open) unable to open slave

[ashthespy]

Are you sure the plugin is enabled? I don't see any log messages from the plugin here. try filtering only the plugins messages with

 sudo journalctl -f | grep spot

[RealHayo]

it is all still shaky. plugin is enabled. Also getting the message [Vollibrespot] : Failed to register IPv6 receiver: Os code 19

what does the folowing mean?

Sep 10 20:14:24 volumio systemd[1]: volspotconnect2.service: main process exited, code=exited, status=127/n/a Sep 10 20:14:24 volumio systemd[1]: Unit volspotconnect2.service entered failed state. Sep 10 20:14:24 volumio volumio[22865]: /data/plugins/music_service/volspotconnect2/startconnect.sh: line 9: --mixer-name: command not found Sep 10 20:14:26 volumio systemd[1]: volspotconnect2.service holdoff time over, scheduling restart. Sep 10 20:14:26 volumio systemd[1]: Stopping Volspotconnect2 Daemon... Sep 10 20:14:26 volumio systemd[1]: Starting Volspotconnect2 Daemon... Sep 10 20:14:26 volumio systemd[1]: Started Volspotconnect2 Daemon. Sep 10 20:14:26 volumio volumio[24308]: vollibrespot v0.1.7 624ccec 2019-07-30 (librespot c9f83e7 2019-07-30) -- Built On 2019-07-30 Sep 10 20:14:26 volumio volumio[24308]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" } Sep 10 20:14:31 volumio volumio[3787]: 192.168.1.18 - - [2019-09-10 20:14:31] "GET /login/_zeroconf?action=getInfo HTTP/1.1" 200 599 0.021677

it complains about startconnect.sh: line 9: --mixer-name: command not found

but my startconnect .sh looks like this:

./vollibrespot -b 320 -c /tmp \ --disable-audio-cache \ --name 'Volumio' --initial-volume 20\ --device plughw:1 \ --mixer alsa \

--mixer-name 'SMSL Clock Selector' --mixer-card 'hw:1' \

              --mixer-name 'SMSL Clock Selector' --mixer-card 'hw:1'\
              --verbose

I also edited the commented line and deleted it. But (of course) it returns by itself when restarting player.

When switching around between the first and second volumio entry in the spotify devices list, it will work in the end. But i can't find a consistent approach or recognize a pattern of errors. Sometimes i get the code 19 error and other times the mixer name command not found.

I am not sure if we should continue on this thread.

[ashthespy]

[Vollibrespot] : Failed to register IPv6 receiver: Os code 19

That is a warning that there is no ipv6 interface, and can be ignored.

So to make your solution more seamless, I would suggest editing the volspotconnect2.tmpl and replace ${mixeropts} \ with --mixer-name 'SMSL Clock Selector' --mixer-card 'hw:1' and restart the plugin from the webui..

Try that - directly edit volspotconnect2.tmp as startconnect.sh gets overwritten on each boot like you have figured out..

[RealHayo]

ok i just did that. (actually it was sort of already like that) But now I also deleted the #-comment lines. And I think it had a positive effect.

Another issue i can see in the log is: volumio kernel: TX ERROR status: 0x007e0000 volumio kernel: TX ERROR status: 0x00760000

You know if that is bad?

I still have 2 Volumiio devices in my spotify app device list. But the bottom one seems to work more easily now.

[ashthespy]

Another issue i can see in the log is:

volumio kernel: TX ERROR status: 0x007e0000
volumio kernel: TX ERROR status: 0x00760000

That looks like a device specific kernel warning..

When switching around between the first and second volumio entry in the spotify devices list, it will work in the end. I still have 2 Volumiio devices in my spotify app device list.

Why do you have two enteritis? Are you also running volspotconnect?

[RealHayo]

no just the version 0.97 of connect2.

(and the spotify app from volumio team. But it is inactive).

[RealHayo]

I wish i knew why i have 2 entires. I have it since the beginning.

[RealHayo]

Darn. I had the feeling maybe i should have resetted my volumio box. So i did. Things are happening now. On the positive side , I now only see one volumio device in my spotify device list. But the negative side, is that it doesn't work at all. Again it is stuck on making a connection.

The connect settings look different i think.

I get a similar but slightly different message:

volumio volumio[4539]: [Vollibrespot] : Failed to register IPv6 receiver: Os { code: 19, kind: Other, message: "No such device" }

But sometimes also : volumio volumio[5274]: [Vollibrespot] : Login error for user "hayo_883": MAC mismatch

Do i need to do the refresh token stuff ? (i was thinking this is only for the spotify plugin which is inactive though)

[RealHayo]

again, darn. I made a mistake in the volspotconnect.sh , where i forgot a ''\'' (backslash) at the end of a line. So the log looks a lot better and i can see my phone mentioned in the log when I have Multi User Device --> Off. But then i can't see volumio in my spotify app. Multi user device --> On Now i can see my volumio device. But i still have the same old error that it doesn't connect.

thank you for your patience , still appreciating the help

[RealHayo]

Good news. After changing the settings back and forth it now works. Very happy to hear it working.

I am getting a lot of repeating messages in the journal. Is this normal?

Sep 10 21:59:47 volumio sudo[9126]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 10 21:59:47 volumio sudo[9126]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 10 21:59:47 volumio sudo[9126]: pam_unix(sudo:session): session closed for user root Sep 10 21:59:48 volumio kernel: TX ERROR status: 0x007e0000 Sep 10 21:59:48 volumio kernel: TX ERROR status: 0x00760000 Sep 10 21:59:49 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 21:59:50 volumio volumio[8099]: [Vollibrespot] librespot_core::session: Session[0] strong=7 weak=4 Sep 10 21:59:51 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 21:59:51 volumio kernel: TX ERROR status: 0x00760000 Sep 10 21:59:52 volumio volumio[8099]: [Vollibrespot] librespot_audio::fetch: File c526a31b0dad171530a3f08fb2fa3fb89a8b0be3 coete, saving to cache Sep 10 21:59:53 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 21:59:55 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 21:59:57 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 21:59:57 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _674A0243._sub._googlecast._tcp.local Sep 10 21:59:57 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _8E6C866D._sub._googlecast._tcp.local Sep 10 21:59:57 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local Sep 10 21:59:57 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _googlecast._tcp.local Sep 10 21:59:58 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _674A0243._sub._googlecast._tcp.local Sep 10 21:59:58 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _8E6C866D._sub._googlecast._tcp.local Sep 10 21:59:58 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local Sep 10 21:59:58 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _googlecast._tcp.local Sep 10 21:59:59 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 21:59:59 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _674A0243._sub._googlecast._tcp.local Sep 10 21:59:59 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _8E6C866D._sub._googlecast._tcp.local Sep 10 21:59:59 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _CC32E753._sub._googlecast._tcp.local Sep 10 21:59:59 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _googlecast._tcp.local Sep 10 22:00:01 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 22:00:02 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:02 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:02 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:02 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:03 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:03 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:03 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:03 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN Hayo.local Sep 10 22:00:03 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 22:00:05 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 22:00:07 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local Sep 10 22:00:09 volumio volumio[8099]: [Vollibrespot] mdns::fsm: received question: IN _spotify-connect._tcp.local

[ashthespy]

Great! disable the debug mode in the plugin settings to remove these messages (or remove the --verbose flag)