volspotconnect2: Stuck on 'Making connection'

Question

volspotconnect2: Stuck on 'Making connection'

RealHayo opened this issue 5 years ago · 19 comments

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

Answer 1 · 2019-09-03T09:05:09.000Z

Could you share whats in the logs?

Answer 2 · 2019-09-04T13:57:09.000Z

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

Answer 3 · 2019-09-05T08:04:18.000Z

@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 #212 for workarounds.

Answer 4 · 2019-09-05T19:25:14.000Z

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

Answer 5 · 2019-09-05T19:32:24.000Z

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

Answer 6 · 2019-09-05T19:51:53.000Z

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.

Answer 7 · 2019-09-05T20:12:21.000Z

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..

Answer 8 · 2019-09-05T21:12:07.000Z

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

Answer 9 · 2019-09-05T21:23:12.000Z

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

Answer 10 · 2019-09-10T20:31:28.000Z

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.

Answer 11 · 2019-09-10T20:44:37.000Z

[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..

Answer 12 · 2019-09-10T21:02:41.000Z

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.

Answer 13 · 2019-09-10T21:06:06.000Z

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?

Answer 14 · 2019-09-10T21:12:29.000Z

no just the version 0.97 of connect2.

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

Answer 15 · 2019-09-10T21:13:40.000Z

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

Answer 16 · 2019-09-10T21:32:56.000Z

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)

Answer 17 · 2019-09-10T21:51:28.000Z

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

Answer 18 · 2019-09-10T22:02:11.000Z

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

Answer 19 · 2019-09-10T22:05:22.000Z

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