Hi community.
I just did setup a Volumio (Raspberry PI 3 + DAC + 7inches touch screen) and I love it.
Version is latest one 2.575 with Spotify 1.3.5 plugin (with index.js page with refresh token input).
The connection to Spotify is ok, and I can navigate among the different playlists.
However when I choose a title to play, nothing happen. I get the cover image but no sound.
In the logs I systematically have this error each time I try to play a track:
2019-05-11T16:54:55.183Z - info: SPOP command error:
2019-05-11T16:54:55.185Z - info: message=This socket has been ended by the other party, stack=Error: This socket has been ended by the other party
And the same error keeps repeating when I try to play a track.
Is this a known problem ?
I tried changing the DNS config (this was mentioned in an old post), but this did not change anything.
Thanks for your help.
Longer version of the volumio log file:
2019-05-11T16:54:39.241Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2019-05-11T16:54:39.242Z - info: In handleBrowseUri, curUri=spotify
2019-05-11T16:54:44.675Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2019-05-11T16:54:44.677Z - info: In handleBrowseUri, curUri=spotify/new
2019-05-11T16:54:50.009Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2019-05-11T16:54:50.010Z - info: In handleBrowseUri, curUri=spotify:album:1Q5yQIQXBLDWTSIYXF2oJc
2019-05-11T16:54:54.632Z - info: CoreCommandRouter::volumioAddQueueItems
2019-05-11T16:54:54.634Z - info: CoreStateMachine::addQueueItems
2019-05-11T16:54:54.635Z - info: CorePlayQueue::addQueueItems
2019-05-11T16:54:54.635Z - info: Adding Item to queue: spotify:track:5duCElafuovM4ZSmkQL4hn
2019-05-11T16:54:54.636Z - info: Exploding uri spotify:track:5duCElafuovM4ZSmkQL4hn in service spop
2019-05-11T16:54:54.824Z - info: CorePlayQueue::saveQueue
2019-05-11T16:54:54.828Z - info: CoreCommandRouter::volumioPushQueue
2019-05-11T16:54:54.845Z - info: CoreStateMachine::updateTrackBlock
2019-05-11T16:54:54.846Z - info: CorePlayQueue::getTrackBlock
2019-05-11T16:54:54.847Z - info: CoreCommandRouter::volumioPlay
2019-05-11T16:54:54.848Z - info: CoreStateMachine::play index 61
2019-05-11T16:54:54.848Z - info: CoreStateMachine::setConsumeUpdateService undefined
2019-05-11T16:54:54.849Z - info: CoreStateMachine::stop
2019-05-11T16:54:54.850Z - info: CoreStateMachine::setConsumeUpdateService undefined
2019-05-11T16:54:54.854Z - info: CoreStateMachine::updateTrackBlock
2019-05-11T16:54:54.855Z - info: CorePlayQueue::getTrackBlock
2019-05-11T16:54:54.855Z - info: CoreStateMachine::stPlaybackTimer
2019-05-11T16:54:54.856Z - info: CoreStateMachine::pushState
2019-05-11T16:54:54.856Z - info: CoreStateMachine::getState
2019-05-11T16:54:54.857Z - info: CorePlayQueue::getTrack 60
2019-05-11T16:54:54.857Z - info: CoreCommandRouter::volumioPushState
2019-05-11T16:54:54.858Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-05-11T16:54:54.895Z - info: CoreStateMachine::serviceStop
2019-05-11T16:54:54.896Z - info: CorePlayQueue::getTrack 60
2019-05-11T16:54:54.896Z - info: CoreCommandRouter::serviceStop
2019-05-11T16:54:54.898Z - info: ControllerMpd::stop
2019-05-11T16:54:54.899Z - info: ControllerMpd::sendMpdCommand stop
2019-05-11T16:54:54.904Z - info: sending command…
2019-05-11T16:54:54.944Z - info:
---------------------------- MPD announces state update: player
2019-05-11T16:54:54.947Z - info: parsing response…
2019-05-11T16:54:54.948Z - info: ControllerMpd::getState
2019-05-11T16:54:54.949Z - info: ControllerMpd::sendMpdCommand status
2019-05-11T16:54:54.950Z - info: CoreCommandRouter::servicePushState
2019-05-11T16:54:54.950Z - info: CoreStateMachine::syncState
2019-05-11T16:54:54.951Z - info: CoreStateMachine::pushState
2019-05-11T16:54:54.951Z - info: CoreStateMachine::getState
2019-05-11T16:54:54.952Z - info: CorePlayQueue::getTrack 60
2019-05-11T16:54:54.953Z - info: CoreCommandRouter::volumioPushState
2019-05-11T16:54:54.953Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-05-11T16:54:55.005Z - info: CorePlayQueue::getTrack 60
2019-05-11T16:54:55.009Z - info: STATE SERVICE {“status”:“stop”,“service”:“radio_paradise”,“type”:“track”,“trackType”:“flac”,“radioType”:“rparadise”,“albumart”:“https://img.radioparadise.com/covers/l/B0000005R2.jpg",“uri”:“https://audio-3.radioparadise.com/blocks/chan/0/4/1845122-1845128.flac”,“name”:"Chris Smither - I Am The Ride”,“title”:“I Am The Ride”,“artist”:“Radio Paradise Main”,“album”:“Up on the Lowdown”,“streaming”:true,“disableUiControls”:true,“duration”:225,“seek”:51945,“samplerate”:“44.1 KHz”,“bitdepth”:“16 bit”,“channels”:2}
2019-05-11T16:54:55.011Z - info: CURRENT POSITION 60
2019-05-11T16:54:55.013Z - info: CoreStateMachine::syncState stateService stop
2019-05-11T16:54:55.014Z - info: CoreStateMachine::syncState currentStatus stop
2019-05-11T16:54:55.033Z - info: CoreStateMachine::pushState
2019-05-11T16:54:55.034Z - info: CoreStateMachine::getState
2019-05-11T16:54:55.035Z - info: CorePlayQueue::getTrack 60
2019-05-11T16:54:55.036Z - info: CoreCommandRouter::volumioPushState
2019-05-11T16:54:55.036Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-05-11T16:54:55.081Z - info: No code
2019-05-11T16:54:55.082Z - info: CoreStateMachine::pushState
2019-05-11T16:54:55.083Z - info: CoreStateMachine::getState
2019-05-11T16:54:55.084Z - info: CorePlayQueue::getTrack 60
2019-05-11T16:54:55.085Z - info: CoreCommandRouter::volumioPushState
2019-05-11T16:54:55.086Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-05-11T16:54:55.131Z - info: sending command…
2019-05-11T16:54:55.160Z - info: CoreStateMachine::play index undefined
2019-05-11T16:54:55.161Z - info: CoreStateMachine::setConsumeUpdateService undefined
2019-05-11T16:54:55.167Z - info: CorePlayQueue::getTrack 61
2019-05-11T16:54:55.168Z - info: CoreStateMachine::startPlaybackTimer
2019-05-11T16:54:55.169Z - info: CorePlayQueue::getTrack 61
2019-05-11T16:54:55.171Z - info: [1557593695170] ControllerSpop::clearAddPlayTrack
2019-05-11T16:54:55.172Z - info: {“uri”:“spotify:track:5duCElafuovM4ZSmkQL4hn”,“service”:“spop”,“name”:“100 Bands (feat. Quavo, 21 Savage, YG & Meek Mill)”,“artist”:“Mustard”,“album”:“100 Bands (feat. Quavo, 21 Savage, YG & Meek Mill)”,“type”:“song”,“duration”:179,“tracknumber”:1,“albumart”:“https://i.scdn.co/image/c68e24e12e0cc83fc865357f5220aa217ad2c363",“samplerate”:“320Kbps”,“bitdepth”:"16 bit”,“trackType”:“spotify”}
2019-05-11T16:54:55.173Z - info: [1557593695172] ControllerSpop::sendSpopCommand
2019-05-11T16:54:55.174Z - info: ADDING DEFER FOR COMMAND uplay
2019-05-11T16:54:55.183Z - info: SPOP command error:
2019-05-11T16:54:55.185Z - info: message=This socket has been ended by the other party, stack=Error: This socket has been ended by the other party
at Socket.writeAfterFIN [as write] (net.js:364:12)
at applyWithContext (/data/plugins/music_service/spop/node_modules/fast.js/function/applyWithContext.js:15:22)
at /data/plugins/music_service/spop/node_modules/fast.js/function/bind.js:63:14
at onBoundPromise (/data/plugins/music_service/spop/node_modules/kew/kew.js:834:10)
at ncall (/data/plugins/music_service/spop/node_modules/kew/kew.js:816:44)
at Object.nfcall (/data/plugins/music_service/spop/node_modules/kew/kew.js:803:16)
at Promise._successFn (/data/plugins/music_service/spop/index.js:1424:25)
at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28)
at _combinedTickCallback (internal/process/next_tick.js:131:7)
at process._tickCallback (internal/process/next_tick.js:180:9), code=EPIPE
2019-05-11T16:54:55.198Z - info: parsing response…
2019-05-11T16:54:55.201Z - info: ControllerMpd::parseState
2019-05-11T16:54:55.202Z - info: ControllerMpd::sendMpdCommand playlistinfo
2019-05-11T16:54:55.203Z - info: sending command…
2019-05-11T16:54:55.220Z - info: parsing response…
2019-05-11T16:54:55.221Z - info: ControllerMpd::parseTrackInfo
2019-05-11T16:54:55.223Z - info: ControllerMpd::pushState
2019-05-11T16:54:55.224Z - info: CoreCommandRouter::servicePushState
2019-05-11T16:54:55.225Z - info: CoreStateMachine::syncState
2019-05-11T16:54:55.226Z - info: CoreStateMachine::pushState
2019-05-11T16:54:55.227Z - info: CoreStateMachine::getState
2019-05-11T16:54:55.228Z - info: CorePlayQueue::getTrack 61
2019-05-11T16:54:55.229Z - info: CoreCommandRouter::volumioPushState
2019-05-11T16:54:55.230Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2019-05-11T16:54:55.300Z - info: CorePlayQueue::getTrack 61
2019-05-11T16:54:55.301Z - info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd
2019-05-11T16:54:55.308Z - info: ------------------------------ 364ms
