Spotify plugin (SPOP) becomes unresponsive -> command error

Volumio Development Bug reports
1

Hi,

Not sure if it has already been said, or if I should just add it to the github. But I thought I’d try it here first, maybe there’s a configuration error on my part.

I’m having intermittent problems using the Spotify (SPOP) plugin on my PiB+ running 2.011, please note that I have had the same problems in previous versions, a little less in 1.55 and RC1. I know my way around some code, but this is beyond me I guess.

The problem is as follows, if I add Spotify tracks for the first time since a boot; no problems whatsoever. However if I want to add another playlist, or even want to view the contents of it, the GUI doesn’t seem to open the list. Adding + replacing to the current playlist gives me an empty playlist and a non-responsive playback UI for Spotify. If I add mpd tracks or a webradio it plays just fine. It seems that after the first add of a playlist from Spotify there’s something disconnected… the log shows the following:

2016-11-07T11:59:08.533Z - info: FIRST BRANCH 2016-11-07T11:59:08.540Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK 2016-11-07T11:59:08.555Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK 2016-11-07T11:59:08.597Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:13Ym1ywWPM8vdDxVFdKyRi","favourite":false} 2016-11-07T11:59:18.601Z - info: CoreCommandRouter::volumioAddQueueItems 2016-11-07T11:59:18.608Z - info: [1478519958603] CoreStateMachine::addQueueItems 2016-11-07T11:59:18.615Z - info: [1478519958610] CorePlayQueue::addQueueItems 2016-11-07T11:59:18.623Z - info: uri=spotify/playlists/12, title=Audiophile test music (Hifi High Quality), service=spop 2016-11-07T11:59:18.630Z - info: First index is 36 2016-11-07T11:59:18.636Z - info: ADDING THIS ITEM TO QUEUE: {"uri":"spotify/playlists/12","title":"Audiophile test music (Hifi High Quality)","service":"spop"} 2016-11-07T11:59:18.643Z - info: Exploding uri spotify/playlists/12 in service spop 2016-11-07T11:59:18.650Z - info: [1478519958645] ControllerSpop::sendSpopCommand 2016-11-07T11:59:18.657Z - info: ADDING DEFER FOR COMMAND ls 2016-11-07T11:59:18.673Z - info: SPOP command error: 2016-11-07T11:59:18.697Z - info: Error: This socket has been ended by the other party at Socket.writeAfterFIN [as write] (net.js:285: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:1201:16) at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28) at _combinedTickCallback (internal/process/next_tick.js:67:7) at process._tickCallback (internal/process/next_tick.js:98:9) volumio@volumio:~$

The ‘this socket has been ended by the other party’ does seem to imply a connection error. I’ve had this problem with the Pi2 and Pi3 too, however not that often. I’ve already tried the image as is and with the resized swapfile (volumio-stops-after-half-hour-gives-after-hours-t4640.html), to no avail. The log file had to be zipped, because log and txt are not allowed extensions for attachments.

Does anyone have any idea where I need to start looking, or is this too deep into code that I need to dig into the sources?

Update: I can reproduce this by adding a playlist, letting it play for a few seconds and then replacing the playlist with another one. Seems to be ‘crashing’ every time now.
volumio.zip (6.85 KB)

2

Just update to the latest version of the plugin, and I’m receiving new errors I hadn’t seen before:

2016-11-10T11:02:25.537Z - info: Spotify credentials grant failed with WebapiError: connect ETIMEDOUT 194.132.196.228:443

Right after the socket end message.

The strange thing is, my Pi2B seems to have trouble communicating to Spotify if I send too many commands in a short period of time, like switching playlists. If I continue down this path my playlists will not show anymore, with emphasis on my playlists, because ‘featured playlists’, ‘what’s new’ and ‘genres & moods’ do seem be working. Adding either one of those playlist to the queue works and volumio will start playback, still after playback has started browsing my playlists fails.

The PiB+ just jams and will not recover until I reboot the device.

Please also note that switching to my own music (SMB share) works flawlessly, on both the PiB+ and Pi2B (and Pi3B). All devices have been tested with DIGI DAC’s. (PiAudio and HifiBerry)

2016-11-10T11:00:52.928Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":177000,"samplerate":"320Kbps","bitdepth":null,"channels":null,"artist":"Zain Bhikha","title":"Nkosi Sikelel 'iAfrika","album":"Night Of Remembrance: Live At Royal Albert Hall"}
2016-11-10T11:00:52.952Z - info: CURRENT POSITION 0
2016-11-10T11:00:52.967Z - info: [1478775652954] CoreStateMachine::syncState   stateService play
2016-11-10T11:00:52.982Z - info: [1478775652969] CoreStateMachine::syncState   currentStatus stop
2016-11-10T11:00:53.017Z - info: [1478775652987] CoreStateMachine::pushState
2016-11-10T11:00:53.023Z - info: [1478775653018] CoreStateMachine::getState
2016-11-10T11:00:53.040Z - info: [1478775653024] CorePlayQueue::getTrack 0
2016-11-10T11:00:53.059Z - info: CoreCommandRouter::volumioPushState
2016-11-10T11:00:53.062Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2016-11-10T11:00:53.486Z - info: [1478775653462] InterfaceWebUI::pushState
2016-11-10T11:00:53.578Z - info: [1478775653571] ------------------------------ 1325ms
2016-11-10T11:00:53.640Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:2Gyt8gO9YoEIxyPnpHau7D","favourite":false}
2016-11-10T11:01:11.542Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2016-11-10T11:01:11.552Z - info: [1478775671547] ControllerSpop::sendSpopCommand
2016-11-10T11:01:11.564Z - info: ADDING DEFER FOR COMMAND ls
2016-11-10T11:01:11.573Z - info: SPOP command error:
2016-11-10T11:01:11.587Z - info:  Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:285: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:1201:16)
    at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28)
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)
2016-11-10T11:02:25.537Z - info: Spotify credentials grant failed with WebapiError: connect ETIMEDOUT 194.132.196.228:443
2016-11-10T11:02:45.903Z - info: Spotify credentials grant failed with WebapiError: connect ETIMEDOUT 194.132.196.228:443
2016-11-10T11:03:43.478Z - info: [1478775823472] CorePlayQueue::getTrack 0
2016-11-10T11:03:43.485Z - info: [1478775823479] CorePlayQueue::getTrack 1
2016-11-10T11:03:43.491Z - info: Prefetching next song
2016-11-10T11:04:18.867Z - info:
[1478775858860] ---------------------------- Client requests Volumio play at index 4
2016-11-10T11:04:18.871Z - info: CoreCommandRouter::volumioPlay
2016-11-10T11:04:18.876Z - info: [1478775858874] CoreStateMachine::play
2016-11-10T11:04:18.889Z - info: [1478775858887] CoreStateMachine::setConsumeUpdateService undefined
2016-11-10T11:04:18.894Z - info: [1478775858892] CoreStateMachine::stop
2016-11-10T11:04:18.907Z - info: [1478775858895] CoreStateMachine::setConsumeUpdateService undefined
2016-11-10T11:04:18.922Z - info: [1478775858916] CoreStateMachine::stPlaybackTimer
2016-11-10T11:04:18.932Z - info: [1478775858927] CoreStateMachine::updateTrackBlock
2016-11-10T11:04:18.939Z - info: [1478775858933] CorePlayQueue::getTrackBlock
2016-11-10T11:04:18.951Z - info: [1478775858946] CoreStateMachine::pushState
2016-11-10T11:04:18.958Z - info: [1478775858952] CoreStateMachine::getState
2016-11-10T11:04:18.964Z - info: [1478775858959] CorePlayQueue::getTrack 4
2016-11-10T11:04:18.967Z - info: CoreCommandRouter::volumioPushState
2016-11-10T11:04:18.969Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2016-11-10T11:04:18.975Z - info: [1478775858974] InterfaceWebUI::pushState
2016-11-10T11:04:19.094Z - info: [1478775859088] CoreStateMachine::serviceStop
2016-11-10T11:04:19.101Z - info: [1478775859095] CorePlayQueue::getTrack 4
2016-11-10T11:04:19.108Z - info: CoreCommandRouter::serviceStop
2016-11-10T11:04:19.120Z - info: [1478775859109] ControllerSpop::stop
2016-11-10T11:04:19.123Z - info: [1478775859121] ControllerSpop::sendSpopCommand
2016-11-10T11:04:19.126Z - info: ADDING DEFER FOR COMMAND stop
2016-11-10T11:04:19.160Z - info: SPOP command error:
2016-11-10T11:04:19.177Z - info:  Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:285: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:1201:16)
    at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28)
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)
2016-11-10T11:04:19.238Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7i86nU8E2Fpn0UgGbXU6l9","favourite":false}
2016-11-10T11:04:24.132Z - info:
[1478775864123] ---------------------------- Client requests Volumio play
2016-11-10T11:04:24.136Z - info: CoreCommandRouter::volumioPlay
2016-11-10T11:04:24.143Z - info: [1478775864141] CoreStateMachine::play
2016-11-10T11:04:24.145Z - info: [1478775864144] CoreStateMachine::setConsumeUpdateService undefined
2016-11-10T11:04:24.159Z - info: [1478775864158] CorePlayQueue::getTrack 4
2016-11-10T11:04:24.163Z - info: [1478775864161] CoreStateMachine::startPlaybackTimer
2016-11-10T11:04:24.166Z - info: [1478775864164] CorePlayQueue::getTrack 4
2016-11-10T11:04:24.181Z - info: [1478775864179] ControllerSpop::clearAddPlayTrack
2016-11-10T11:04:24.184Z - info: {"uri":"spotify:track:7i86nU8E2Fpn0UgGbXU6l9","service":"spop","type":"song","name":"Beatles' Medley","title":"Beatles' Medley","artist":"Tommy Emmanuel","album":"Center Stage","duration":371,"albumart":"/albumart?web=Tommy%20Emmanuel/Center%20Stage/large&path=","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}
2016-11-10T11:04:24.197Z - info: [1478775864185] ControllerSpop::sendSpopCommand
2016-11-10T11:04:24.206Z - info: ADDING DEFER FOR COMMAND uplay
2016-11-10T11:04:24.230Z - info: SPOP command error:
2016-11-10T11:04:24.247Z - info:  Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (net.js:285: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:1201:16)
    at nextTickCallback (/data/plugins/music_service/spop/node_modules/kew/kew.js:47:28)
    at _combinedTickCallback (internal/process/next_tick.js:67:7)
    at process._tickCallback (internal/process/next_tick.js:98:9)
2016-11-10T11:04:24.252Z - info: [1478775864250] ------------------------------ 128ms