Spotify playlist not shown

yomao · February 25, 2017, 5:08pm

I installed volumio 2.041 in my pi2B, and it ran normally.

But when I tried to use spotify plugin, although I successfully signed in, it cannot fetch my playlists.

The situation is, I click Browser -> Spotify -> My playlists, and then it just showed nothing.

But other lists(Featured Playlists, What’s news, Genres & Moods) worked normally.

What should I do to fix it?

PropaGanja · February 25, 2017, 11:48pm

Hi,

Big Volumio fan. huge fan. Thanks so much. I have the same issue.

My playlists are accessible except for one playlist it will not load. That is i cannot click into it and see individual songs as i can with all the others & itwill not play

I thought perhaps it might be that one song became unavailable on the playlist as they do sometimes by your location but i chose in spotify not to show songs which are unavailable and this did not correct the situation.

Very frustrating, If i can help in any way with debugs or etc i can speak linux and follow instruction.

Sorry hope not to have hijacked thread just add to it that this is a bug ^^ Yomao with the plugin possibly.

Thanks !

PG

PropaGanja · March 3, 2017, 11:18pm

Bump**

Has no one else this problem or anyone any concept of how it might come about? a guess even - just something to work with…

can anyone advise on how to debug etc - does the plugin creator reside in these forums anywhere?

Many thanks,
regards.

PG

skikirkwood · March 4, 2017, 6:59am

Hi There, can you post the contents of your Volumio log file here - /var/log/volumio.log.

Volumio uses (the deprecated) libspotify to both access your personal playlists and play back all Spotify streams. Browsing Spotify’s Genre’s & Moods, Featured Playlists and What’s New along with Spotify search results uses the new Spotify Web API. We plan on replacing the use of libspotify to access your personal playlists with the new Spotify Web API but that will require users to authenticate with spotify.com versus plugging in their user name and password to the plugin.

If you can play the various Spotify streams such as Genre’s & Moods it indicates libspotify is partially working but somehow broken to access your personal playlists.

I didn’t create the original plugin, but I did add all of the additional browsing features for Volumio 2 with the new Spotify Web API. That said, I’ve been too busy at work to add any additional functionality in the last couple of months, and the last commit was on Dec. 18 of last year, so this is odd. Looking at your log file may help.

blackthroat · March 12, 2017, 10:20pm

Having the same problem. Was using Pi MusicBox and first noticed the custom Spotify playlists disappeared on 3/3/17. I’ve also tried RuneAudio but same problem. Seems like Spotify probably made a change. Posting logs in two posts due to character limit.

volumio@Volumio:~$ cat /var/log/volumio.log
2017-03-12T21:51:08.411Z - info: -------------------------------------------
2017-03-12T21:51:08.500Z - info: -----            Volumio2              ----
2017-03-12T21:51:08.518Z - info: -------------------------------------------
2017-03-12T21:51:08.524Z - info: -----          System startup          ----
2017-03-12T21:51:08.530Z - info: -------------------------------------------
2017-03-12T21:51:10.423Z - info: File /data/configuration/plugins.json does not exist. Copying from Volumio
2017-03-12T21:51:11.092Z - info: Plugin folders cleanup
2017-03-12T21:51:11.099Z - info: Scanning into folder /volumio/app/plugins/
2017-03-12T21:51:11.113Z - info: Scanning category audio_interface
2017-03-12T21:51:11.133Z - info: Scanning category miscellanea
2017-03-12T21:51:11.153Z - info: Scanning category music_service
2017-03-12T21:51:11.179Z - info: Scanning category plugins.json
2017-03-12T21:51:11.193Z - info: Scanning category system_controller
2017-03-12T21:51:11.233Z - info: Scanning category user_interface
2017-03-12T21:51:11.244Z - info: Scanning into folder /data/plugins/
2017-03-12T21:51:11.250Z - info: Plugin folders cleanup completed
2017-03-12T21:51:11.273Z - info: Loading plugins from folder /volumio/app/plugins/
2017-03-12T21:51:11.393Z - info: Loading plugins from folder /data/plugins/
2017-03-12T21:51:11.433Z - info: Loading plugin "system"...
2017-03-12T21:51:12.233Z - info: Loading plugin "appearance"...
2017-03-12T21:51:15.743Z - info: Loading plugin "network"...
2017-03-12T21:51:16.768Z - info: Loading plugin "services"...
2017-03-12T21:51:16.829Z - info: Loading plugin "alsa_controller"...
2017-03-12T21:51:18.119Z - info: CoreCommandRouter::volumioUpdateVolumeSettings
2017-03-12T21:51:18.165Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
2017-03-12T21:51:18.185Z - info: Found match in Cards Database: setting mixer PCM for card Audio Jack
2017-03-12T21:51:18.210Z - info: CoreCommandRouter::volumioUpdateVolumeSettings
2017-03-12T21:51:18.232Z - info: CoreCommandRouter::volumioUpdateVolumeSettings
2017-03-12T21:51:18.253Z - info: CoreCommandRouter::volumioUpdateVolumeSettings
2017-03-12T21:51:18.477Z - info: Loading plugin "volumio_command_line_client"...
2017-03-12T21:51:18.573Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:18.603Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:18.611Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:18.895Z - info: Loading plugin "upnp"...
2017-03-12T21:51:18.993Z - info: [1489355478979] Starting Upmpd Daemon
2017-03-12T21:51:19.180Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback
2017-03-12T21:51:19.203Z - info: Loading plugin "mpd"...
2017-03-12T21:51:20.113Z - info: Loading plugin "networkfs"...
2017-03-12T21:51:20.533Z - info: Loading plugin "alarm-clock"...
2017-03-12T21:51:22.325Z - info: Loading plugin "airplay_emulation"...
2017-03-12T21:51:22.418Z - info: [1489355482407] Starting Shairport Sync
2017-03-12T21:51:22.459Z - info: Loading plugin "last_100"...
2017-03-12T21:51:22.543Z - info: Loading plugin "webradio"...
2017-03-12T21:51:35.913Z - info: Loading plugin "i2s_dacs"...
2017-03-12T21:51:36.169Z - info: I2S DAC not set, start Auto-detection
2017-03-12T21:51:36.471Z - info: Loading plugin "my_volumio"...
2017-03-12T21:51:36.650Z - info: Loading plugin "volumiodiscovery"...
2017-03-12T21:51:37.763Z - info: CoreCommandRouter::executeOnPlugin: system , registerCallback
2017-03-12T21:51:37.793Z - info: Loading plugin "albumart"...
2017-03-12T21:51:38.003Z - info: Plugin example_plugin is not enabled
2017-03-12T21:51:38.055Z - info: Loading plugin "updater_comm"...
2017-03-12T21:51:40.073Z - info: Plugin mpdemulation is not enabled
2017-03-12T21:51:40.081Z - info: Loading plugin "rest_api"...
2017-03-12T21:51:40.261Z - info: Loading plugin "websocket"...
2017-03-12T21:51:40.742Z - info: ___________ START PLUGINS ___________
2017-03-12T21:51:40.853Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
2017-03-12T21:51:40.873Z - info: [1489355500857] CoreMusicLibrary::Adding element Last_100
2017-03-12T21:51:40.998Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
2017-03-12T21:51:41.006Z - info: [1489355500999] CoreMusicLibrary::Adding element Webradio
2017-03-12T21:51:41.067Z - info: Loading i18n strings for locale en
2017-03-12T21:51:41.443Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:51:41.543Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:41.557Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getAlsaCards
2017-03-12T21:51:41.579Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:41.587Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:41.603Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:41.613Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:41.623Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:51:41.783Z - info: BOOT COMPLETED
2017-03-12T21:51:42.260Z - info: [1489355502232] CoreStateMachine::resetVolumioState
2017-03-12T21:51:42.294Z - info: [1489355502284] CoreStateMachine::getcurrentVolume
2017-03-12T21:51:42.313Z - info: CoreCommandRouter::volumioRetrievevolume
2017-03-12T21:51:42.484Z - info: [1489355502449] CoreStateMachine::updateTrackBlock
2017-03-12T21:51:42.532Z - info: [1489355502488] CorePlayQueue::getTrackBlock
2017-03-12T21:51:43.628Z - info: Cannot read play queue form file
2017-03-12T21:51:44.845Z - info: MPD running with PID538 ,establishing connection
2017-03-12T21:51:45.192Z - info: Setting Device type: Raspberry PI
2017-03-12T21:51:46.677Z - info: [1489355506665] VolumeController:: Volume=40 Mute =false
2017-03-12T21:51:46.713Z - info: [1489355506698] CoreStateMachine::pushState
2017-03-12T21:51:46.738Z - info: [1489355506721] CoreStateMachine::getState
2017-03-12T21:51:46.753Z - info: [1489355506741] CorePlayQueue::getTrack 0
2017-03-12T21:51:46.774Z - info: CoreCommandRouter::volumioPushState
2017-03-12T21:51:46.780Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T21:51:46.833Z - info: [1489355506818] interfaceApi::pushState
2017-03-12T21:51:46.853Z - info: [1489355506837] InterfaceWebUI::pushState
2017-03-12T21:51:47.285Z - info: Pushing Favourites {"service":"mpd","uri":"","favourite":false}
2017-03-12T21:51:48.457Z - info: Volumio called home
2017-03-12T21:51:49.998Z - info: 
2017-03-12T21:51:51.723Z - info: mDNS: Found device Volumio
2017-03-12T21:51:54.653Z - info: [1489355514636] Shairport-Sync Started
2017-03-12T21:51:54.673Z - info: Upmpdcli Daemon Started
2017-03-12T21:51:55.763Z - info: CoreCommandRouter::volumioGetState
2017-03-12T21:51:55.787Z - info: [1489355515772] CoreStateMachine::getState
2017-03-12T21:51:55.795Z - info: [1489355515789] CorePlayQueue::getTrack 0
2017-03-12T21:51:55.823Z - info: 
[1489355515799] ---------------------------- Client requests Volumio state
2017-03-12T21:51:55.850Z - info: [1489355515844] InterfaceWebUI::pushState
2017-03-12T21:51:55.993Z - info: [1489355515973] ------------------------------ 230ms
2017-03-12T21:54:46.504Z - info: CoreCommandRouter::volumioGetState
2017-03-12T21:54:46.509Z - info: [1489355686506] CoreStateMachine::getState
2017-03-12T21:54:46.512Z - info: [1489355686510] CorePlayQueue::getTrack 0
2017-03-12T21:54:46.530Z - info: 
[1489355686521] ---------------------------- Client requests Volumio state
2017-03-12T21:54:46.543Z - info: [1489355686537] InterfaceWebUI::pushState
2017-03-12T21:54:46.888Z - info: [1489355686879] ------------------------------ 388ms
2017-03-12T21:54:47.042Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2017-03-12T21:54:47.061Z - info: 
[1489355687051] ---------------------------- Client requests Menu Items
2017-03-12T21:54:47.072Z - info: [1489355687066] Listing playlists
2017-03-12T21:54:47.084Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
2017-03-12T21:54:47.456Z - info: [1489355687448] ------------------------------ 397ms
2017-03-12T21:55:01.278Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T21:55:01.423Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions
2017-03-12T21:55:01.455Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2017-03-12T21:55:01.466Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
2017-03-12T21:55:01.790Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:01.807Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:01.815Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:01.825Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:01.833Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:07.063Z - info: CALLMETHOD: audio_interface alsa_controller saveAlsaOptions [object Object]
2017-03-12T21:55:07.070Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , saveAlsaOptions
2017-03-12T21:55:07.086Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
2017-03-12T21:55:07.159Z - info: Output device has changed, restarting MPD
2017-03-12T21:55:07.500Z - info: Output device has changed, restarting Shairport Sync
2017-03-12T21:55:07.569Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
2017-03-12T21:55:07.578Z - info: Found match in Cards Database: setting mixer PCM for card Audio Jack
2017-03-12T21:55:07.640Z - info: CoreCommandRouter::volumioUpdateVolumeSettings
2017-03-12T21:55:07.701Z - info: Updating Volume Controller Parameters: Device: 0 Name: Audio Jack Mixer: PCM Max Vol: 100 Vol Curve; logarithmic Vol Steps: 10
2017-03-12T21:55:07.806Z - error: Raspberry PI HDMI Output Enabled 
2017-03-12T21:55:08.103Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:55:08.131Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:55:08.183Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:55:08.214Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:55:08.271Z - info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
2017-03-12T21:55:08.644Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions
2017-03-12T21:55:08.692Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2017-03-12T21:55:08.727Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
2017-03-12T21:55:09.195Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:09.227Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:09.253Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:09.281Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:09.323Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:55:09.867Z - error: Alsa Settings successfully stored
2017-03-12T21:55:09.880Z - info: MPD Permissions set
2017-03-12T21:55:11.563Z - info: [1489355711540] Shairport-Sync Started
2017-03-12T21:55:17.537Z - info: 
2017-03-12T21:55:23.940Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T21:55:24.100Z - info: CoreCommandRouter::executeOnPlugin: appearance , getBackgrounds
2017-03-12T21:55:33.882Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T21:55:34.281Z - info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork
2017-03-12T21:55:35.879Z - info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks
2017-03-12T21:55:48.149Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T21:55:48.278Z - info: Received Get System Version
2017-03-12T21:55:48.285Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
2017-03-12T21:55:54.849Z - info: Sending updateCheck to server
2017-03-12T21:55:59.300Z - info: Update Ready: [object Object]
2017-03-12T21:56:04.145Z - info: CALLMETHOD: system_controller system saveGeneralSettings [object Object]
2017-03-12T21:56:04.154Z - info: CoreCommandRouter::executeOnPlugin: system , saveGeneralSettings
2017-03-12T21:56:04.188Z - info: System name has changed, restarting Shairport Sync
2017-03-12T21:56:05.297Z - info: Permissions for /etc/hosts set
2017-03-12T21:56:05.634Z - info: Hostname now is volumio
2017-03-12T21:56:05.823Z - info: [1489355765782] Shairport-Sync Started
2017-03-12T21:56:06.040Z - info: New hostname set
2017-03-12T21:56:06.445Z - info: Upmpdcli Daemon Started
2017-03-12T21:56:09.064Z - info: mDNS Browse raised the following error Error: dns service error: unknown
2017-03-12T21:56:09.498Z - info: mDNS Advertisement raised the following error Error: dns service error: unknown
2017-03-12T21:56:09.570Z - info: Avahi Daemon Restarted
2017-03-12T21:56:10.550Z - info: []
2017-03-12T21:56:15.561Z - info: mDNS: Found device Volumio
2017-03-12T21:56:31.798Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T21:56:31.980Z - info: Received Get System Version
2017-03-12T21:56:31.988Z - info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
2017-03-12T21:56:36.013Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T21:56:36.083Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions
2017-03-12T21:56:36.095Z - info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
2017-03-12T21:56:36.104Z - info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
2017-03-12T21:56:36.208Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:56:36.217Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:56:36.230Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:56:36.239Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:56:36.247Z - info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
2017-03-12T21:56:48.227Z - info: []
2017-03-12T21:56:56.466Z - info: Downloading plugin at http://volumio.github.io/volumio-plugins/plugins/volumio/armhf/music_service/spotify/spotify.zip
2017-03-12T21:56:57.967Z - info: END DOWNLOAD: http://volumio.github.io/volumio-plugins/plugins/volumio/armhf/music_service/spotify/spotify.zip
2017-03-12T21:57:31.488Z - info: Checking if plugin already exists
2017-03-12T21:57:31.515Z - info: Rename folder
2017-03-12T21:57:40.875Z - info: Move to category
2017-03-12T21:57:50.551Z - info: Checking if install.sh is present
2017-03-12T21:57:50.569Z - info: Executing install.sh
2017-03-12T21:57:51.195Z - info: Installing Spop Dependencies
2017-03-12T21:57:53.693Z - info: Get:1 http://archive.raspberrypi.org jessie InRelease [22.9 kB]
2017-03-12T21:57:53.715Z - info: Get:2 http://archive.raspbian.org jessie InRelease [14.9 kB]
2017-03-12T21:57:54.182Z - info: Get:3 http://archive.raspbian.org jessie/main Sources [7746 kB]
2017-03-12T21:57:54.451Z - info: Get:4 http://archive.raspberrypi.org jessie/main Sources [58.1 kB]
2017-03-12T21:57:55.332Z - info: Get:5 http://archive.raspberrypi.org jessie/ui Sources [16.3 kB]
2017-03-12T21:57:55.709Z - info: Get:6 http://archive.raspberrypi.org jessie/main armhf Packages [147 kB]
2017-03-12T21:57:56.443Z - info: Get:7 http://archive.raspberrypi.org jessie/ui armhf Packages [57.6 kB]
2017-03-12T21:57:59.218Z - info: Ign http://archive.raspberrypi.org jessie/main Translation-en
2017-03-12T21:57:59.481Z - info: Ign http://archive.raspberrypi.org jessie/ui Translation-en
2017-03-12T21:58:00.131Z - info: Get:8 http://archive.raspbian.org jessie/contrib Sources [64.5 kB]
2017-03-12T21:58:00.453Z - info: Get:9 http://archive.raspbian.org jessie/non-free Sources [113 kB]
2017-03-12T21:58:00.680Z - info: Get:10 http://archive.raspbian.org jessie/rpi Sources [1132 B]
2017-03-12T21:58:00.883Z - info: Get:11 http://archive.raspbian.org jessie/main armhf Packages [8981 kB]
2017-03-12T21:58:09.570Z - info: Get:12 http://archive.raspbian.org jessie/contrib armhf Packages [37.5 kB]
2017-03-12T21:58:09.770Z - info: Get:13 http://archive.raspbian.org jessie/non-free armhf Packages [70.3 kB]
2017-03-12T21:58:10.010Z - info: Get:14 http://archive.raspbian.org jessie/rpi armhf Packages [1356 B]
2017-03-12T21:58:12.411Z - info: Ign http://archive.raspbian.org jessie/contrib Translation-en
2017-03-12T21:58:12.556Z - info: Ign http://archive.raspbian.org jessie/main Translation-en
2017-03-12T21:58:12.681Z - info: Ign http://archive.raspbian.org jessie/non-free Translation-en
2017-03-12T21:58:12.810Z - info: Ign http://archive.raspbian.org jessie/rpi Translation-en
2017-03-12T21:59:03.901Z - info: Fetched 17.3 MB in 1min 12s (241 kB/s)
2017-03-12T21:59:45.571Z - info: Reading package lists...
2017-03-12T21:59:45.963Z - info: Reading package lists...
2017-03-12T21:59:48.903Z - info: Building dependency tree...
2017-03-12T21:59:48.970Z - info: Reading state information...
2017-03-12T21:59:51.339Z - info: libao-common is already the newest version.
2017-03-12T21:59:51.370Z - info: The following extra packages will be installed:
2017-03-12T21:59:51.438Z - info:   dconf-gsettings-backend dconf-service gir1.2-gdkpixbuf-2.0 gir1.2-glib-2.0
2017-03-12T21:59:51.453Z - info:   gir1.2-json-1.0 gir1.2-notify-0.7 gir1.2-soup-2.4 glib-networking
2017-03-12T21:59:51.473Z - info:   glib-networking-common glib-networking-services gsettings-desktop-schemas
2017-03-12T21:59:51.513Z - info:   libasound2 libasound2-data libc-dev-bin libc6-dev libdconf1 libelfg0
2017-03-12T21:59:51.523Z - info:   libgdk-pixbuf2.0-dev libgirepository-1.0-1 libglib2.0-bin libglib2.0-data
2017-03-12T21:59:51.563Z - info:   libjson-glib-1.0-common libnotify4 libpcre3-dev libpcrecpp0 libpng12-dev
2017-03-12T21:59:51.603Z - info:   libproxy1 libpthread-stubs0-dev libreadline6-dev libsoup-gnome2.4-1
2017-03-12T21:59:51.613Z - info:   libsox-fmt-all libsox-fmt-ao libsox-fmt-mp3 libsox-fmt-oss libsox-fmt-pulse
2017-03-12T21:59:51.619Z - info:   libtinfo-dev libtwolame0 libx11-dev libxau-dev libxcb1-dev libxdmcp-dev
2017-03-12T21:59:51.660Z - info:   libxml2-dev linux-libc-dev x11proto-core-dev x11proto-input-dev
2017-03-12T21:59:51.683Z - info:   x11proto-kb-dev xorg-sgml-doctools xtrans-dev zlib1g-dev
2017-03-12T21:59:51.833Z - info: Suggested packages:
2017-03-12T21:59:51.854Z - info:   libasound2-plugins libasound2-doc glibc-doc libglib2.0-doc libjson-glib-doc
2017-03-12T21:59:51.886Z - info:   readline-doc libsoup2.4-doc libxcb-doc
2017-03-12T21:59:51.896Z - info: Recommended packages:
2017-03-12T21:59:51.913Z - info:   manpages-dev notification-daemon libx11-doc
2017-03-12T21:59:51.933Z - info: The following NEW packages will be installed:
2017-03-12T21:59:51.953Z - info:   dconf-gsettings-backend dconf-service gir1.2-gdkpixbuf-2.0 gir1.2-glib-2.0
2017-03-12T21:59:51.963Z - info:   gir1.2-json-1.0 gir1.2-notify-0.7 gir1.2-soup-2.4 glib-networking
2017-03-12T21:59:51.983Z - info:   glib-networking-common glib-networking-services gsettings-desktop-schemas
2017-03-12T21:59:51.993Z - info:   libao-dev libasound2-dev libc-dev-bin libc6-dev libdbus-glib-1-dev libdconf1
2017-03-12T21:59:52.013Z - info:   libelfg0 libgdk-pixbuf2.0-dev libgirepository-1.0-1 libglib2.0-bin
2017-03-12T21:59:52.030Z - info:   libglib2.0-data libglib2.0-dev libjson-glib-1.0-0 libjson-glib-1.0-common
2017-03-12T21:59:52.053Z - info:   libjson-glib-dev libnotify-dev libnotify4 libpcre3-dev libpcrecpp0
2017-03-12T21:59:52.063Z - info:   libpng12-dev libproxy1 libpthread-stubs0-dev libreadline-dev
2017-03-12T21:59:52.083Z - info:   libreadline6-dev libsoup-gnome2.4-1 libsoup2.4-1 libsoup2.4-dev libsox-dev
2017-03-12T21:59:52.093Z - info:   libsox-fmt-all libsox-fmt-ao libsox-fmt-mp3 libsox-fmt-oss libsox-fmt-pulse
2017-03-12T21:59:52.110Z - info:   libtinfo-dev libtwolame0 libx11-dev libxau-dev libxcb1-dev libxdmcp-dev
2017-03-12T21:59:52.130Z - info:   libxml2-dev linux-libc-dev x11proto-core-dev x11proto-input-dev
2017-03-12T21:59:52.153Z - info:   x11proto-kb-dev xorg-sgml-doctools xtrans-dev zlib1g-dev
2017-03-12T21:59:52.331Z - info: The following packages will be upgraded:
2017-03-12T21:59:52.353Z - info:   libasound2 libasound2-data
2017-03-12T21:59:55.448Z - info: 2 upgraded, 58 newly installed, 0 to remove and 22 not upgraded.
2017-03-12T21:59:55.470Z - info: Need to get 16.5 MB of archives.
2017-03-12T21:59:55.481Z - info: After this operation, 55.2 MB of additional disk space will be used.
2017-03-12T21:59:55.491Z - info: Get:1 http://archive.raspberrypi.org/debian/ jessie/main libasound2-data all 1.0.28-1+rpi2 [65.2 kB]
2017-03-12T21:59:55.533Z - info: Get:2 http://archive.raspbian.org/raspbian/ jessie/main libdconf1 armhf 0.22.0-1 [31.1 kB]
2017-03-12T21:59:55.772Z - info: Get:3 http://archive.raspbian.org/raspbian/ jessie/main libelfg0 armhf 0.8.13-5 [55.7 kB]
2017-03-12T21:59:56.031Z - info: Get:4 http://archive.raspberrypi.org/debian/ jessie/main libasound2 armhf 1.0.28-1+rpi2 [322 kB]
2017-03-12T21:59:56.062Z - info: Get:5 http://archive.raspbian.org/raspbian/ jessie/main libjson-glib-1.0-common all 1.0.2-1 [147 kB]
2017-03-12T21:59:56.383Z - info: Get:6 http://archive.raspbian.org/raspbian/ jessie/main libjson-glib-1.0-0 armhf 1.0.2-1 [151 kB]
2017-03-12T21:59:56.673Z - info: Get:7 http://archive.raspbian.org/raspbian/ jessie/main libnotify4 armhf 0.7.6-2 [26.4 kB]
2017-03-12T21:59:56.871Z - info: Get:8 http://archive.raspbian.org/raspbian/ jessie/main libpcrecpp0 armhf 2:8.35-3.3+deb8u4 [140 kB]
2017-03-12T21:59:57.149Z - info: Get:9 http://archive.raspbian.org/raspbian/ jessie/main libproxy1 armhf 0.4.11-4 [55.6 kB]
2017-03-12T21:59:57.299Z - info: Get:10 http://archive.raspberrypi.org/debian/ jessie/main libasound2-dev armhf 1.0.28-1+rpi2 [95.4 kB]
2017-03-12T21:59:57.379Z - info: Get:11 http://archive.raspbian.org/raspbian/ jessie/main glib-networking-common all 2.42.0-2 [52.1 kB]
2017-03-12T21:59:57.555Z - info: Get:12 http://archive.raspbian.org/raspbian/ jessie/main glib-networking-services armhf 2.42.0-2 [16.6 kB]
2017-03-12T21:59:57.713Z - info: Get:13 http://archive.raspbian.org/raspbian/ jessie/main dconf-service armhf 0.22.0-1 [38.0 kB]
2017-03-12T21:59:57.890Z - info: Get:14 http://archive.raspbian.org/raspbian/ jessie/main dconf-gsettings-backend armhf 0.22.0-1 [30.1 kB]
2017-03-12T21:59:58.103Z - info: Get:15 http://archive.raspberrypi.org/debian/ jessie/main x11proto-core-dev all 7.0.31-1 [728 kB]
2017-03-12T21:59:58.170Z - info: Get:16 http://archive.raspbian.org/raspbian/ jessie/main gsettings-desktop-schemas all 3.14.1-1 [391 kB]
2017-03-12T21:59:58.580Z - info: Get:17 http://archive.raspbian.org/raspbian/ jessie/main glib-networking armhf 2.42.0-2 [43.9 kB]
2017-03-12T21:59:58.820Z - info: Get:18 http://archive.raspbian.org/raspbian/ jessie/main libsoup2.4-1 armhf 2.48.0-1 [219 kB]
2017-03-12T21:59:59.130Z - info: Get:19 http://archive.raspbian.org/raspbian/ jessie/main libsoup-gnome2.4-1 armhf 2.48.0-1 [56.8 kB]
2017-03-12T21:59:59.360Z - info: Get:20 http://archive.raspbian.org/raspbian/ jessie/main libgirepository-1.0-1 armhf 1.42.0-2.2 [82.9 kB]
2017-03-12T21:59:59.590Z - info: Get:21 http://archive.raspbian.org/raspbian/ jessie/main gir1.2-glib-2.0 armhf 1.42.0-2.2 [141 kB]
2017-03-12T21:59:59.893Z - info: Get:22 http://archive.raspbian.org/raspbian/ jessie/main gir1.2-gdkpixbuf-2.0 armhf 2.31.1-2+deb8u5 [16.9 kB]
2017-03-12T22:00:00.063Z - info: Get:23 http://archive.raspbian.org/raspbian/ jessie/main gir1.2-json-1.0 armhf 1.0.2-1 [114 kB]
2017-03-12T22:00:00.333Z - info: Get:24 http://archive.raspbian.org/raspbian/ jessie/main gir1.2-notify-0.7 armhf 0.7.6-2 [19.8 kB]
2017-03-12T22:00:00.513Z - info: Get:25 http://archive.raspbian.org/raspbian/ jessie/main gir1.2-soup-2.4 armhf 2.48.0-1 [74.9 kB]
2017-03-12T22:00:00.594Z - info: Get:26 http://archive.raspberrypi.org/debian/ jessie/main xtrans-dev all 1.3.5-1 [100 kB]
2017-03-12T22:00:00.758Z - info: Get:27 http://archive.raspbian.org/raspbian/ jessie/main libc-dev-bin armhf 2.19-18+deb8u7 [231 kB]
2017-03-12T22:00:01.198Z - info: Get:28 http://archive.raspbian.org/raspbian/ jessie/main linux-libc-dev armhf 3.16.7-ckt11-1+deb8u4+rpi1 [977 kB]
2017-03-12T22:00:01.973Z - info: Get:29 http://archive.raspbian.org/raspbian/ jessie/main libc6-dev armhf 2.19-18+deb8u7 [1724 kB]
2017-03-12T22:00:02.970Z - info: Get:30 http://archive.raspbian.org/raspbian/ jessie/main libao-dev armhf 1.1.0-3 [49.5 kB]
2017-03-12T22:00:03.393Z - info: Get:31 http://archive.raspbian.org/raspbian/ jessie/main libglib2.0-data all 2.42.1-1 [2173 kB]
2017-03-12T22:00:04.811Z - info: Get:32 http://archive.raspbian.org/raspbian/ jessie/main libglib2.0-bin armhf 2.42.1-1 [1334 kB]
2017-03-12T22:00:05.991Z - info: Get:33 http://archive.raspbian.org/raspbian/ jessie/main libpcre3-dev armhf 2:8.35-3.3+deb8u4 [413 kB]
2017-03-12T22:00:06.412Z - info: Get:34 http://archive.raspbian.org/raspbian/ jessie/main zlib1g-dev armhf 1:1.2.8.dfsg-2 [199 kB]
2017-03-12T22:00:06.720Z - info: Get:35 http://archive.raspbian.org/raspbian/ jessie/main libglib2.0-dev armhf 2.42.1-1 [2472 kB]
2017-03-12T22:00:08.911Z - info: Get:36 http://archive.raspbian.org/raspbian/ jessie/main libdbus-glib-1-dev armhf 0.102-1 [222 kB]
2017-03-12T22:00:09.219Z - info: Get:37 http://archive.raspbian.org/raspbian/ jessie/main xorg-sgml-doctools all 1:1.11-1 [21.9 kB]
2017-03-12T22:00:09.410Z - info: Get:38 http://archive.raspbian.org/raspbian/ jessie/main libxau-dev armhf 1:1.0.8-1 [23.0 kB]
2017-03-12T22:00:09.603Z - info: Get:39 http://archive.raspbian.org/raspbian/ jessie/main libxdmcp-dev armhf 1:1.1.1-1 [40.8 kB]
2017-03-12T22:00:09.814Z - info: Get:40 http://archive.raspbian.org/raspbian/ jessie/main x11proto-input-dev all 2.3.1-1 [157 kB]
2017-03-12T22:00:10.113Z - info: Get:41 http://archive.raspbian.org/raspbian/ jessie/main x11proto-kb-dev all 1.0.6-2 [269 kB]
2017-03-12T22:00:10.431Z - info: Get:42 http://archive.raspbian.org/raspbian/ jessie/main libpthread-stubs0-dev armhf 0.3-4 [4042 B]
2017-03-12T22:00:10.601Z - info: Get:43 http://archive.raspbian.org/raspbian/ jessie/main libxcb1-dev armhf 1.10-3 [78.1 kB]
2017-03-12T22:00:10.859Z - info: Get:44 http://archive.raspbian.org/raspbian/ jessie/main libx11-dev armhf 2:1.6.2-3 [726 kB]
2017-03-12T22:00:11.403Z - info: Get:45 http://archive.raspbian.org/raspbian/ jessie/main libpng12-dev armhf 1.2.50-2+deb8u3 [237 kB]
2017-03-12T22:00:11.713Z - info: Get:46 http://archive.raspbian.org/raspbian/ jessie/main libgdk-pixbuf2.0-dev armhf 2.31.1-2+deb8u5 [52.4 kB]
2017-03-12T22:00:11.932Z - info: Get:47 http://archive.raspbian.org/raspbian/ jessie/main libjson-glib-dev armhf 1.0.2-1 [131 kB]
2017-03-12T22:00:12.190Z - info: Get:48 http://archive.raspbian.org/raspbian/ jessie/main libnotify-dev armhf 0.7.6-2 [31.3 kB]
2017-03-12T22:00:12.373Z - info: Get:49 http://archive.raspbian.org/raspbian/ jessie/main libtinfo-dev armhf 5.9+20140913-1 [65.4 kB]
2017-03-12T22:00:12.593Z - info: Get:50 http://archive.raspbian.org/raspbian/ jessie/main libreadline6-dev armhf 6.3-8 [105 kB]
2017-03-12T22:00:12.822Z - info: Get:51 http://archive.raspbian.org/raspbian/ jessie/main libreadline-dev armhf 6.3-8 [994 B]
2017-03-12T22:00:13.033Z - info: Get:52 http://archive.raspbian.org/raspbian/ jessie/main libxml2-dev armhf 2.9.1+dfsg1-5+deb8u4 [615 kB]
2017-03-12T22:00:13.542Z - info: Get:53 http://archive.raspbian.org/raspbian/ jessie/main libsoup2.4-dev armhf 2.48.0-1 [328 kB]
2017-03-12T22:00:13.911Z - info: Get:54 http://archive.raspbian.org/raspbian/ jessie/main libsox-fmt-ao armhf 14.4.1-5 [43.7 kB]
2017-03-12T22:00:14.092Z - info: Get:55 http://archive.raspbian.org/raspbian/ jessie/main libtwolame0 armhf 0.3.13-1.1 [47.3 kB]
2017-03-12T22:00:14.293Z - info: Get:56 http://archive.raspbian.org/raspbian/ jessie/main libsox-fmt-mp3 armhf 14.4.1-5 [52.1 kB]
2017-03-12T22:00:14.654Z - info: Get:57 http://archive.raspbian.org/raspbian/ jessie/main libsox-fmt-oss armhf 14.4.1-5 [44.0 kB]
2017-03-12T22:00:14.843Z - info: Get:58 http://archive.raspbian.org/raspbian/ jessie/main libsox-fmt-pulse armhf 14.4.1-5 [43.5 kB]
2017-03-12T22:00:15.043Z - info: Get:59 http://archive.raspbian.org/raspbian/ jessie/main libsox-fmt-all armhf 14.4.1-5 [41.2 kB]
2017-03-12T22:00:15.239Z - info: Get:60 http://archive.raspbian.org/raspbian/ jessie/main libsox-dev armhf 14.4.1-5 [308 kB]
2017-03-12T22:00:20.484Z - info: Fetched 16.5 MB in 22s (732 kB/s)
2017-03-12T22:00:21.145Z - info: Selecting previously unselected package libdconf1:armhf.
(Reading database ... 18792 files and directories currently installed.)
2017-03-12T22:00:25.148Z - info: Preparing to unpack .../libdconf1_0.22.0-1_armhf.deb ...
2017-03-12T22:00:25.251Z - info: Unpacking libdconf1:armhf (0.22.0-1) ...
2017-03-12T22:00:25.683Z - info: Selecting previously unselected package libelfg0:armhf.
2017-03-12T22:00:25.813Z - info: Preparing to unpack .../libelfg0_0.8.13-5_armhf.deb ...
2017-03-12T22:00:25.872Z - info: Unpacking libelfg0:armhf (0.8.13-5) ...
2017-03-12T22:00:26.327Z - info: Selecting previously unselected package libjson-glib-1.0-common.
2017-03-12T22:00:26.447Z - info: Preparing to unpack .../libjson-glib-1.0-common_1.0.2-1_all.deb ...
2017-03-12T22:00:26.520Z - info: Unpacking libjson-glib-1.0-common (1.0.2-1) ...
2017-03-12T22:00:27.951Z - info: Selecting previously unselected package libjson-glib-1.0-0:armhf.
2017-03-12T22:00:28.082Z - info: Preparing to unpack .../libjson-glib-1.0-0_1.0.2-1_armhf.deb ...
2017-03-12T22:00:28.155Z - info: Unpacking libjson-glib-1.0-0:armhf (1.0.2-1) ...
2017-03-12T22:00:28.722Z - info: Selecting previously unselected package libnotify4:armhf.
2017-03-12T22:00:28.859Z - info: Preparing to unpack .../libnotify4_0.7.6-2_armhf.deb ...
2017-03-12T22:00:28.934Z - info: Unpacking libnotify4:armhf (0.7.6-2) ...
2017-03-12T22:00:29.388Z - info: Selecting previously unselected package libpcrecpp0:armhf.
2017-03-12T22:00:29.502Z - info: Preparing to unpack .../libpcrecpp0_2%3a8.35-3.3+deb8u4_armhf.deb ...
2017-03-12T22:00:29.578Z - info: Unpacking libpcrecpp0:armhf (2:8.35-3.3+deb8u4) ...
2017-03-12T22:00:30.078Z - info: Selecting previously unselected package libproxy1:armhf.
2017-03-12T22:00:30.213Z - info: Preparing to unpack .../libproxy1_0.4.11-4_armhf.deb ...
2017-03-12T22:00:30.305Z - info: Unpacking libproxy1:armhf (0.4.11-4) ...
2017-03-12T22:00:30.641Z - info: Selecting previously unselected package glib-networking-common.
2017-03-12T22:00:30.710Z - info: Preparing to unpack .../glib-networking-common_2.42.0-2_all.deb ...
2017-03-12T22:00:30.883Z - info: Unpacking glib-networking-common (2.42.0-2) ...
2017-03-12T22:00:31.480Z - info: Selecting previously unselected package glib-networking-services.
2017-03-12T22:00:31.609Z - info: Preparing to unpack .../glib-networking-services_2.42.0-2_armhf.deb ...
2017-03-12T22:00:31.704Z - info: Unpacking glib-networking-services (2.42.0-2) ...
2017-03-12T22:00:32.078Z - info: Selecting previously unselected package dconf-service.
2017-03-12T22:00:32.179Z - info: Preparing to unpack .../dconf-service_0.22.0-1_armhf.deb ...
2017-03-12T22:00:32.322Z - info: Unpacking dconf-service (0.22.0-1) ...
2017-03-12T22:00:32.713Z - info: Selecting previously unselected package dconf-gsettings-backend:armhf.
2017-03-12T22:00:32.865Z - info: Preparing to unpack .../dconf-gsettings-backend_0.22.0-1_armhf.deb ...
2017-03-12T22:00:32.938Z - info: Unpacking dconf-gsettings-backend:armhf (0.22.0-1) ...
2017-03-12T22:00:33.318Z - info: Selecting previously unselected package gsettings-desktop-schemas.
2017-03-12T22:00:33.451Z - info: Preparing to unpack .../gsettings-desktop-schemas_3.14.1-1_all.deb ...
2017-03-12T22:00:33.494Z - info: Unpacking gsettings-desktop-schemas (3.14.1-1) ...
2017-03-12T22:00:35.100Z - info: Selecting previously unselected package glib-networking:armhf.
2017-03-12T22:00:35.233Z - info: Preparing to unpack .../glib-networking_2.42.0-2_armhf.deb ...
2017-03-12T22:00:35.323Z - info: Unpacking glib-networking:armhf (2.42.0-2) ...
2017-03-12T22:00:35.813Z - info: Selecting previously unselected package libsoup2.4-1:armhf.
2017-03-12T22:00:35.941Z - info: Preparing to unpack .../libsoup2.4-1_2.48.0-1_armhf.deb ...
2017-03-12T22:00:36.026Z - info: Unpacking libsoup2.4-1:armhf (2.48.0-1) ...
2017-03-12T22:00:36.850Z - info: Selecting previously unselected package libsoup-gnome2.4-1:armhf.
2017-03-12T22:00:36.984Z - info: Preparing to unpack .../libsoup-gnome2.4-1_2.48.0-1_armhf.deb ...
2017-03-12T22:00:37.083Z - info: Unpacking libsoup-gnome2.4-1:armhf (2.48.0-1) ...
2017-03-12T22:00:37.486Z - info: Selecting previously unselected package libgirepository-1.0-1:armhf.
2017-03-12T22:00:37.616Z - info: Preparing to unpack .../libgirepository-1.0-1_1.42.0-2.2_armhf.deb ...
2017-03-12T22:00:37.696Z - info: Unpacking libgirepository-1.0-1:armhf (1.42.0-2.2) ...
2017-03-12T22:00:38.199Z - info: Selecting previously unselected package gir1.2-glib-2.0:armhf.
2017-03-12T22:00:38.326Z - info: Preparing to unpack .../gir1.2-glib-2.0_1.42.0-2.2_armhf.deb ...
2017-03-12T22:00:38.427Z - info: Unpacking gir1.2-glib-2.0:armhf (1.42.0-2.2) ...
2017-03-12T22:00:39.146Z - info: Selecting previously unselected package gir1.2-gdkpixbuf-2.0.
2017-03-12T22:00:39.282Z - info: Preparing to unpack .../gir1.2-gdkpixbuf-2.0_2.31.1-2+deb8u5_armhf.deb ...
2017-03-12T22:00:39.377Z - info: Unpacking gir1.2-gdkpixbuf-2.0 (2.31.1-2+deb8u5) ...
2017-03-12T22:00:40.227Z - info: Selecting previously unselected package gir1.2-json-1.0.
2017-03-12T22:00:40.369Z - info: Preparing to unpack .../gir1.2-json-1.0_1.0.2-1_armhf.deb ...
2017-03-12T22:00:40.448Z - info: Unpacking gir1.2-json-1.0 (1.0.2-1) ...
2017-03-12T22:00:40.893Z - info: Selecting previously unselected package gir1.2-notify-0.7.
2017-03-12T22:00:41.031Z - info: Preparing to unpack .../gir1.2-notify-0.7_0.7.6-2_armhf.deb ...
2017-03-12T22:00:41.124Z - info: Unpacking gir1.2-notify-0.7 (0.7.6-2) ...
2017-03-12T22:00:41.451Z - info: Selecting previously unselected package gir1.2-soup-2.4.
2017-03-12T22:00:41.590Z - info: Preparing to unpack .../gir1.2-soup-2.4_2.48.0-1_armhf.deb ...
2017-03-12T22:00:41.687Z - info: Unpacking gir1.2-soup-2.4 (2.48.0-1) ...
2017-03-12T22:00:42.112Z - info: Selecting previously unselected package libc-dev-bin.
2017-03-12T22:00:42.314Z - info: Preparing to unpack .../libc-dev-bin_2.19-18+deb8u7_armhf.deb ...
2017-03-12T22:00:42.395Z - info: Unpacking libc-dev-bin (2.19-18+deb8u7) ...
2017-03-12T22:00:42.971Z - info: Selecting previously unselected package linux-libc-dev:armhf.
2017-03-12T22:00:43.110Z - info: Preparing to unpack .../linux-libc-dev_3.16.7-ckt11-1+deb8u4+rpi1_armhf.deb ...
2017-03-12T22:00:43.194Z - info: Unpacking linux-libc-dev:armhf (3.16.7-ckt11-1+deb8u4+rpi1) ...
2017-03-12T22:00:52.893Z - info: Selecting previously unselected package libc6-dev:armhf.
2017-03-12T22:00:53.027Z - info: Preparing to unpack .../libc6-dev_2.19-18+deb8u7_armhf.deb ...
2017-03-12T22:00:53.105Z - info: Unpacking libc6-dev:armhf (2.19-18+deb8u7) ...
2017-03-12T22:01:02.340Z - info: Selecting previously unselected package libao-dev.
2017-03-12T22:01:02.488Z - info: Preparing to unpack .../libao-dev_1.1.0-3_armhf.deb ...
2017-03-12T22:01:02.576Z - info: Unpacking libao-dev (1.1.0-3) ...
2017-03-12T22:01:03.342Z - info: Preparing to unpack .../libasound2-data_1.0.28-1+rpi2_all.deb ...
2017-03-12T22:01:03.474Z - info: Unpacking libasound2-data (1.0.28-1+rpi2) over (1.0.28-1) ...
2017-03-12T22:01:05.354Z - info: Preparing to unpack .../libasound2_1.0.28-1+rpi2_armhf.deb ...
2017-03-12T22:01:05.480Z - info: Unpacking libasound2:armhf (1.0.28-1+rpi2) over (1.0.28-1) ...
2017-03-12T22:01:07.760Z - info: Selecting previously unselected package libasound2-dev:armhf.
2017-03-12T22:01:07.949Z - info: Preparing to unpack .../libasound2-dev_1.0.28-1+rpi2_armhf.deb ...
2017-03-12T22:01:08.040Z - info: Unpacking libasound2-dev:armhf (1.0.28-1+rpi2) ...
2017-03-12T22:01:08.815Z - info: Selecting previously unselected package libglib2.0-data.
2017-03-12T22:01:08.969Z - info: Preparing to unpack .../libglib2.0-data_2.42.1-1_all.deb ...
2017-03-12T22:01:09.040Z - info: Unpacking libglib2.0-data (2.42.1-1) ...
2017-03-12T22:01:12.178Z - info: Selecting previously unselected package libglib2.0-bin.
2017-03-12T22:01:12.328Z - info: Preparing to unpack .../libglib2.0-bin_2.42.1-1_armhf.deb ...
2017-03-12T22:01:12.578Z - info: Unpacking libglib2.0-bin (2.42.1-1) ...
2017-03-12T22:01:13.481Z - info: Selecting previously unselected package libpcre3-dev:armhf.
2017-03-12T22:01:13.632Z - info: Preparing to unpack .../libpcre3-dev_2%3a8.35-3.3+deb8u4_armhf.deb ...
2017-03-12T22:01:13.727Z - info: Unpacking libpcre3-dev:armhf (2:8.35-3.3+deb8u4) ...
2017-03-12T22:01:16.718Z - info: Selecting previously unselected package zlib1g-dev:armhf.
2017-03-12T22:01:16.866Z - info: Preparing to unpack .../zlib1g-dev_1%3a1.2.8.dfsg-2_armhf.deb ...
2017-03-12T22:01:16.979Z - info: Unpacking zlib1g-dev:armhf (1:1.2.8.dfsg-2) ...
2017-03-12T22:01:17.801Z - info: Selecting previously unselected package libglib2.0-dev.
2017-03-12T22:01:17.938Z - info: Preparing to unpack .../libglib2.0-dev_2.42.1-1_armhf.deb ...
2017-03-12T22:01:18.033Z - info: Unpacking libglib2.0-dev (2.42.1-1) ...
2017-03-12T22:01:27.012Z - info: Selecting previously unselected package libdbus-glib-1-dev.
2017-03-12T22:01:27.190Z - info: Preparing to unpack .../libdbus-glib-1-dev_0.102-1_armhf.deb ...
2017-03-12T22:01:27.288Z - info: Unpacking libdbus-glib-1-dev (0.102-1) ...
2017-03-12T22:01:27.968Z - info: Selecting previously unselected package xorg-sgml-doctools.
2017-03-12T22:01:28.137Z - info: Preparing to unpack .../xorg-sgml-doctools_1%3a1.11-1_all.deb ...
2017-03-12T22:01:28.249Z - info: Unpacking xorg-sgml-doctools (1:1.11-1) ...
2017-03-12T22:01:28.622Z - info: Selecting previously unselected package x11proto-core-dev.
2017-03-12T22:01:28.874Z - info: Preparing to unpack .../x11proto-core-dev_7.0.31-1_all.deb ...
2017-03-12T22:01:28.998Z - info: Unpacking x11proto-core-dev (7.0.31-1) ...
2017-03-12T22:01:30.208Z - info: Selecting previously unselected package libxau-dev:armhf.
2017-03-12T22:01:30.389Z - info: Preparing to unpack .../libxau-dev_1%3a1.0.8-1_armhf.deb ...
2017-03-12T22:01:30.501Z - info: Unpacking libxau-dev:armhf (1:1.0.8-1) ...
2017-03-12T22:01:30.855Z - info: Selecting previously unselected package libxdmcp-dev:armhf.
2017-03-12T22:01:30.959Z - info: Preparing to unpack .../libxdmcp-dev_1%3a1.1.1-1_armhf.deb ...
2017-03-12T22:01:30.992Z - info: Unpacking libxdmcp-dev:armhf (1:1.1.1-1) ...
2017-03-12T22:01:31.483Z - info: Selecting previously unselected package x11proto-input-dev.
2017-03-12T22:01:31.580Z - info: Preparing to unpack .../x11proto-input-dev_2.3.1-1_all.deb ...
2017-03-12T22:01:31.609Z - info: Unpacking x11proto-input-dev (2.3.1-1) ...
2017-03-12T22:01:32.246Z - info: Selecting previously unselected package x11proto-kb-dev.
2017-03-12T22:01:32.343Z - info: Preparing to unpack .../x11proto-kb-dev_1.0.6-2_all.deb ...
2017-03-12T22:01:32.583Z - info: Unpacking x11proto-kb-dev (1.0.6-2) ...
2017-03-12T22:01:33.130Z - info: Selecting previously unselected package xtrans-dev.
2017-03-12T22:01:33.432Z - info: Preparing to unpack .../xtrans-dev_1.3.5-1_all.deb ...
2017-03-12T22:01:33.569Z - info: Unpacking xtrans-dev (1.3.5-1) ...
2017-03-12T22:01:35.284Z - info: Selecting previously unselected package libpthread-stubs0-dev:armhf.
2017-03-12T22:01:35.434Z - info: Preparing to unpack .../libpthread-stubs0-dev_0.3-4_armhf.deb ...
2017-03-12T22:01:35.544Z - info: Unpacking libpthread-stubs0-dev:armhf (0.3-4) ...
2017-03-12T22:01:35.864Z - info: Selecting previously unselected package libxcb1-dev:armhf.
2017-03-12T22:01:36.116Z - info: Preparing to unpack .../libxcb1-dev_1.10-3_armhf.deb ...
2017-03-12T22:01:36.269Z - info: Unpacking libxcb1-dev:armhf (1.10-3) ...
2017-03-12T22:01:36.809Z - info: Selecting previously unselected package libx11-dev:armhf.
2017-03-12T22:01:37.001Z - info: Preparing to unpack .../libx11-dev_2%3a1.6.2-3_armhf.deb ...
2017-03-12T22:01:37.106Z - info: Unpacking libx11-dev:armhf (2:1.6.2-3) ...
2017-03-12T22:01:38.665Z - info: Selecting previously unselected package libpng12-dev:armhf.
2017-03-12T22:01:38.841Z - info: Preparing to unpack .../libpng12-dev_1.2.50-2+deb8u3_armhf.deb ...
2017-03-12T22:01:38.957Z - info: Unpacking libpng12-dev:armhf (1.2.50-2+deb8u3) ...
2017-03-12T22:01:40.430Z - info: Selecting previously unselected package libgdk-pixbuf2.0-dev.
2017-03-12T22:01:40.536Z - info: Preparing to unpack .../libgdk-pixbuf2.0-dev_2.31.1-2+deb8u5_armhf.deb ...
2017-03-12T22:01:40.727Z - info: Unpacking libgdk-pixbuf2.0-dev (2.31.1-2+deb8u5) ...
2017-03-12T22:01:41.273Z - info: Selecting previously unselected package libjson-glib-dev.
2017-03-12T22:01:41.448Z - info: Preparing to unpack .../libjson-glib-dev_1.0.2-1_armhf.deb ...
2017-03-12T22:01:41.555Z - info: Unpacking libjson-glib-dev (1.0.2-1) ...
2017-03-12T22:01:42.894Z - info: Selecting previously unselected package libnotify-dev.
2017-03-12T22:01:43.079Z - info: Preparing to unpack .../libnotify-dev_0.7.6-2_armhf.deb ...
2017-03-12T22:01:43.210Z - info: Unpacking libnotify-dev (0.7.6-2) ...
2017-03-12T22:01:43.618Z - info: Selecting previously unselected package libtinfo-dev:armhf.
2017-03-12T22:01:43.806Z - info: Preparing to unpack .../libtinfo-dev_5.9+20140913-1_armhf.deb ...
2017-03-12T22:01:43.907Z - info: Unpacking libtinfo-dev:armhf (5.9+20140913-1) ...
2017-03-12T22:01:44.326Z - info: Selecting previously unselected package libreadline6-dev:armhf.
2017-03-12T22:01:44.577Z - info: Preparing to unpack .../libreadline6-dev_6.3-8_armhf.deb ...
2017-03-12T22:01:44.695Z - info: Unpacking libreadline6-dev:armhf (6.3-8) ...
2017-03-12T22:01:45.220Z - info: Selecting previously unselected package libreadline-dev:armhf.
2017-03-12T22:01:45.331Z - info: Preparing to unpack .../libreadline-dev_6.3-8_armhf.deb ...
2017-03-12T22:01:45.518Z - info: Unpacking libreadline-dev:armhf (6.3-8) ...
2017-03-12T22:01:45.922Z - info: Selecting previously unselected package libxml2-dev:armhf.
2017-03-12T22:01:45.959Z - info: Preparing to unpack .../libxml2-dev_2.9.1+dfsg1-5+deb8u4_armhf.deb ...
2017-03-12T22:01:45.992Z - info: Unpacking libxml2-dev:armhf (2.9.1+dfsg1-5+deb8u4) ...
2017-03-12T22:01:48.169Z - info: Selecting previously unselected package libsoup2.4-dev.
2017-03-12T22:01:48.331Z - info: Preparing to unpack .../libsoup2.4-dev_2.48.0-1_armhf.deb ...
2017-03-12T22:01:48.449Z - info: Unpacking libsoup2.4-dev (2.48.0-1) ...
2017-03-12T22:01:50.736Z - info: Selecting previously unselected package libsox-fmt-ao:armhf.
2017-03-12T22:01:50.851Z - info: Preparing to unpack .../libsox-fmt-ao_14.4.1-5_armhf.deb ...
2017-03-12T22:01:50.881Z - info: Unpacking libsox-fmt-ao:armhf (14.4.1-5) ...
2017-03-12T22:01:51.333Z - info: Selecting previously unselected package libtwolame0.
2017-03-12T22:01:51.450Z - info: Preparing to unpack .../libtwolame0_0.3.13-1.1_armhf.deb ...
2017-03-12T22:01:51.484Z - info: Unpacking libtwolame0 (0.3.13-1.1) ...
2017-03-12T22:01:52.083Z - info: Selecting previously unselected package libsox-fmt-mp3:armhf.
2017-03-12T22:01:52.220Z - info: Preparing to unpack .../libsox-fmt-mp3_14.4.1-5_armhf.deb ...
2017-03-12T22:01:52.423Z - info: Unpacking libsox-fmt-mp3:armhf (14.4.1-5) ...
2017-03-12T22:01:52.747Z - info: Selecting previously unselected package libsox-fmt-oss:armhf.
2017-03-12T22:01:52.848Z - info: Preparing to unpack .../libsox-fmt-oss_14.4.1-5_armhf.deb ...
2017-03-12T22:01:52.878Z - info: Unpacking libsox-fmt-oss:armhf (14.4.1-5) ...
2017-03-12T22:01:53.240Z - info: Selecting previously unselected package libsox-fmt-pulse:armhf.
2017-03-12T22:01:53.274Z - info: Preparing to unpack .../libsox-fmt-pulse_14.4.1-5_armhf.deb ...
2017-03-12T22:01:53.313Z - info: Unpacking libsox-fmt-pulse:armhf (14.4.1-5) ...
2017-03-12T22:01:53.894Z - info: Selecting previously unselected package libsox-fmt-all:armhf.
2017-03-12T22:01:53.927Z - info: Preparing to unpack .../libsox-fmt-all_14.4.1-5_armhf.deb ...
2017-03-12T22:01:53.960Z - info: Unpacking libsox-fmt-all:armhf (14.4.1-5) ...
2017-03-12T22:01:54.380Z - info: Selecting previously unselected package libsox-dev:armhf.
2017-03-12T22:01:55.016Z - info: Preparing to unpack .../libsox-dev_14.4.1-5_armhf.deb ...
2017-03-12T22:01:55.048Z - info: Unpacking libsox-dev:armhf (14.4.1-5) ...
2017-03-12T22:01:56.273Z - info: Processing triggers for libglib2.0-0:armhf (2.42.1-1) ...
2017-03-12T22:01:57.039Z - info: Processing triggers for libc-bin (2.19-18+deb8u7) ...
2017-03-12T22:02:02.338Z - info: Setting up libdconf1:armhf (0.22.0-1) ...
2017-03-12T22:02:02.579Z - info: Setting up libelfg0:armhf (0.8.13-5) ...
2017-03-12T22:02:02.737Z - info: Setting up libjson-glib-1.0-common (1.0.2-1) ...
2017-03-12T22:02:02.930Z - info: Setting up libjson-glib-1.0-0:armhf (1.0.2-1) ...
2017-03-12T22:02:03.013Z - info: Setting up libnotify4:armhf (0.7.6-2) ...
2017-03-12T22:02:03.323Z - info: Setting up libpcrecpp0:armhf (2:8.35-3.3+deb8u4) ...
2017-03-12T22:02:03.506Z - info: Setting up libproxy1:armhf (0.4.11-4) ...
2017-03-12T22:02:03.544Z - info: Setting up glib-networking-common (2.42.0-2) ...
2017-03-12T22:02:03.749Z - info: Setting up glib-networking-services (2.42.0-2) ...
2017-03-12T22:02:03.791Z - info: Setting up dconf-service (0.22.0-1) ...
2017-03-12T22:02:03.821Z - info: Setting up dconf-gsettings-backend:armhf (0.22.0-1) ...
2017-03-12T22:02:03.849Z - info: Setting up gsettings-desktop-schemas (3.14.1-1) ...
2017-03-12T22:02:04.041Z - info: Setting up glib-networking:armhf (2.42.0-2) ...
2017-03-12T22:02:04.073Z - info: Setting up libsoup2.4-1:armhf (2.48.0-1) ...
2017-03-12T22:02:04.098Z - info: Setting up libsoup-gnome2.4-1:armhf (2.48.0-1) ...
2017-03-12T22:02:04.396Z - info: Setting up libgirepository-1.0-1:armhf (1.42.0-2.2) ...
2017-03-12T22:02:04.419Z - info: Setting up gir1.2-glib-2.0:armhf (1.42.0-2.2) ...
2017-03-12T22:02:04.452Z - info: Setting up gir1.2-gdkpixbuf-2.0 (2.31.1-2+deb8u5) ...
2017-03-12T22:02:04.552Z - info: Setting up gir1.2-json-1.0 (1.0.2-1) ...
2017-03-12T22:02:04.566Z - info: Setting up gir1.2-notify-0.7 (0.7.6-2) ...
2017-03-12T22:02:04.581Z - info: Setting up gir1.2-soup-2.4 (2.48.0-1) ...
2017-03-12T22:02:04.595Z - info: Setting up libc-dev-bin (2.19-18+deb8u7) ...
2017-03-12T22:02:05.257Z - info: Setting up linux-libc-dev:armhf (3.16.7-ckt11-1+deb8u4+rpi1) ...
2017-03-12T22:02:05.282Z - info: Setting up libc6-dev:armhf (2.19-18+deb8u7) ...
2017-03-12T22:02:05.484Z - info: Setting up libao-dev (1.1.0-3) ...
2017-03-12T22:02:05.517Z - info: Setting up libasound2-data (1.0.28-1+rpi2) ...
2017-03-12T22:02:05.567Z - info: Setting up libasound2:armhf (1.0.28-1+rpi2) ...
2017-03-12T22:02:05.752Z - info: Setting up libasound2-dev:armhf (1.0.28-1+rpi2) ...
2017-03-12T22:02:05.780Z - info: Setting up libglib2.0-data (2.42.1-1) ...
2017-03-12T22:02:05.803Z - info: Setting up libglib2.0-bin (2.42.1-1) ...
2017-03-12T22:02:06.142Z - info: Setting up libpcre3-dev:armhf (2:8.35-3.3+deb8u4) ...
2017-03-12T22:02:06.180Z - info: Setting up zlib1g-dev:armhf (1:1.2.8.dfsg-2) ...
2017-03-12T22:02:06.199Z - info: Setting up libglib2.0-dev (2.42.1-1) ...
2017-03-12T22:02:11.414Z - info: Setting up libdbus-glib-1-dev (0.102-1) ...
2017-03-12T22:02:11.592Z - info: Setting up xorg-sgml-doctools (1:1.11-1) ...
2017-03-12T22:02:11.667Z - info: Setting up x11proto-core-dev (7.0.31-1) ...
2017-03-12T22:02:11.827Z - info: Setting up libxau-dev:armhf (1:1.0.8-1) ...
2017-03-12T22:02:11.856Z - info: Setting up libxdmcp-dev:armhf (1:1.1.1-1) ...
2017-03-12T22:02:11.879Z - info: Setting up x11proto-input-dev (2.3.1-1) ...
2017-03-12T22:02:12.173Z - info: Setting up x11proto-kb-dev (1.0.6-2) ...
2017-03-12T22:02:12.213Z - info: Setting up xtrans-dev (1.3.5-1) ...
2017-03-12T22:02:12.241Z - info: Setting up libpthread-stubs0-dev:armhf (0.3-4) ...
2017-03-12T22:02:12.257Z - info: Setting up libxcb1-dev:armhf (1.10-3) ...
2017-03-12T22:02:12.282Z - info: Setting up libx11-dev:armhf (2:1.6.2-3) ...
2017-03-12T22:02:12.493Z - info: Setting up libpng12-dev:armhf (1.2.50-2+deb8u3) ...
2017-03-12T22:02:12.521Z - info: Setting up libgdk-pixbuf2.0-dev (2.31.1-2+deb8u5) ...
2017-03-12T22:02:12.547Z - info: Setting up libjson-glib-dev (1.0.2-1) ...
2017-03-12T22:02:12.575Z - info: Setting up libnotify-dev (0.7.6-2) ...
2017-03-12T22:02:12.600Z - info: Setting up libtinfo-dev:armhf (5.9+20140913-1) ...
2017-03-12T22:02:12.839Z - info: Setting up libreadline6-dev:armhf (6.3-8) ...
2017-03-12T22:02:12.866Z - info: Setting up libreadline-dev:armhf (6.3-8) ...
2017-03-12T22:02:12.890Z - info: Setting up libxml2-dev:armhf (2.9.1+dfsg1-5+deb8u4) ...
2017-03-12T22:02:12.932Z - info: Setting up libsoup2.4-dev (2.48.0-1) ...
2017-03-12T22:02:12.951Z - info: Setting up libsox-fmt-ao:armhf (14.4.1-5) ...
2017-03-12T22:02:12.968Z - info: Setting up libtwolame0 (0.3.13-1.1) ...
2017-03-12T22:02:13.261Z - info: Setting up libsox-fmt-mp3:armhf (14.4.1-5) ...
2017-03-12T22:02:13.283Z - info: Setting up libsox-fmt-oss:armhf (14.4.1-5) ...
2017-03-12T22:02:13.313Z - info: Setting up libsox-fmt-pulse:armhf (14.4.1-5) ...
2017-03-12T22:02:13.337Z - info: Setting up libsox-fmt-all:armhf (14.4.1-5) ...
2017-03-12T22:02:13.361Z - info: Setting up libsox-dev:armhf (14.4.1-5) ...
2017-03-12T22:02:13.533Z - info: Processing triggers for libc-bin (2.19-18+deb8u7) ...
2017-03-12T22:02:20.515Z - info: Installing Spop and libspotify
2017-03-12T22:02:20.693Z - info: armhf
2017-03-12T22:02:26.207Z - info: etc/
2017-03-12T22:02:26.335Z - info: etc/spopd.conf
2017-03-12T22:02:26.403Z - info: lib/
2017-03-12T22:02:26.425Z - info: lib/systemd/
2017-03-12T22:02:26.447Z - info: lib/systemd/system/
2017-03-12T22:02:26.469Z - info: lib/systemd/system/spop.service
2017-03-12T22:02:26.509Z - info: usr/
2017-03-12T22:02:26.531Z - info: usr/local/
2017-03-12T22:02:26.558Z - info: usr/local/include/
2017-03-12T22:02:26.579Z - info: usr/local/include/libspotify/
2017-03-12T22:02:26.597Z - info: usr/local/include/libspotify/api.h
2017-03-12T22:02:26.620Z - info: usr/local/lib/
2017-03-12T22:02:26.644Z - info: usr/local/lib/pkgconfig/
2017-03-12T22:02:26.666Z - info: usr/local/lib/pkgconfig/libspotify.pc
2017-03-12T22:02:26.687Z - info: usr/local/lib/libspotify.so
2017-03-12T22:02:26.708Z - info: usr/local/lib/libspotify.so.12.1.103
2017-03-12T22:02:27.193Z - info: usr/local/lib/libspotify.so.12
2017-03-12T22:02:27.220Z - info: usr/share/
2017-03-12T22:02:27.243Z - info: usr/share/spop/
2017-03-12T22:02:27.260Z - info: usr/share/spop/awesome/
2017-03-12T22:02:27.282Z - info: usr/share/spop/awesome/spop.lua
2017-03-12T22:02:27.298Z - info: usr/lib/
2017-03-12T22:02:27.354Z - info: usr/lib/systemd/
2017-03-12T22:02:27.376Z - info: usr/lib/systemd/user/
2017-03-12T22:02:27.400Z - info: usr/lib/systemd/user/spopd.socket
2017-03-12T22:02:27.423Z - info: usr/lib/systemd/user/spopd.service
2017-03-12T22:02:27.437Z - info: usr/lib/libspop_plugin_savestate.so
2017-03-12T22:02:27.459Z - info: usr/lib/libspop_audio_ao.so
2017-03-12T22:02:27.483Z - info: usr/lib/libspop_plugin_awesome.so
2017-03-12T22:02:27.506Z - info: usr/lib/libspop_audio_sox.so
2017-03-12T22:02:27.533Z - info: usr/lib/libspop_plugin_mpris2.so
2017-03-12T22:02:27.545Z - info: usr/lib/libspop_plugin_scrobble.so
2017-03-12T22:02:27.567Z - info: usr/lib/libspop_audio_oss.so
2017-03-12T22:02:27.613Z - info: usr/bin/
2017-03-12T22:02:27.625Z - info: usr/bin/dspop
2017-03-12T22:02:27.637Z - info: usr/bin/spopd
2017-03-12T22:02:27.765Z - info: Install script completed
2017-03-12T22:02:27.785Z - info: Adding reference to registry
2017-03-12T22:02:27.825Z - info: Done installing plugin.
2017-03-12T22:02:28.060Z - info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"1.2.0","icon":"fa-spotify","enabled":false,"active":false}]
2017-03-12T22:02:28.189Z - info: Folder /tmp/downloaded_plugin removed
2017-03-12T22:02:28.199Z - info: Folder /tmp/downloaded_plugin.zip removed
2017-03-12T22:04:19.889Z - info: Following Redirect to: http://volumio.github.io/volumio-plugins/plugins/volumio/armhf/plugins.json
2017-03-12T22:04:34.299Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T22:04:34.519Z - info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
2017-03-12T22:04:34.541Z - info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
2017-03-12T22:04:34.633Z - info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
2017-03-12T22:04:34.719Z - info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
2017-03-12T22:04:38.633Z - info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
2017-03-12T22:04:39.189Z - info: CoreCommandRouter::volumioGetBrowseSources
2017-03-12T22:04:39.260Z - info: CoreCommandRouter::volumioGetQueue
2017-03-12T22:04:39.269Z - info: [1489356279263] CoreStateMachine::getQueue
2017-03-12T22:04:39.278Z - info: [1489356279271] CorePlayQueue::getQueue
2017-03-12T22:04:39.290Z - info: 
[1489356279280] ---------------------------- Client requests Volumio queue
2017-03-12T22:04:39.307Z - info: [1489356279301] InterfaceWebUI::pushQueue
2017-03-12T22:04:39.326Z - info: [1489356279319] ------------------------------ 67ms
2017-03-12T22:04:59.384Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T22:04:59.435Z - info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
2017-03-12T22:04:59.444Z - info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
2017-03-12T22:04:59.526Z - info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
2017-03-12T22:04:59.559Z - info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
2017-03-12T22:05:03.525Z - info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
2017-03-12T22:05:04.116Z - info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"1.2.0","icon":"fa-spotify","enabled":false,"active":false}]

blackthroat · March 12, 2017, 10:25pm

Part 2/2 of logs. As mentioned earlier in this thread, the other Spotify streams play fine.

2017-03-12T22:05:06.864Z - info: Enabling plugin spop
2017-03-12T22:05:06.901Z - info: Loading plugin "spop"...
2017-03-12T22:05:11.543Z - info: CoreCommandRouter::getUIConfigOnPlugin
2017-03-12T22:05:11.883Z - info: SpopD Daemon Started
2017-03-12T22:05:16.898Z - info: Connecting to daemon
2017-03-12T22:05:17.653Z - info: SPOP command error:
2017-03-12T22:05:17.673Z - info:  Error: connect ECONNREFUSED 127.0.0.1:6602
    at Object.exports._errnoException (util.js:1026:11)
    at exports._exceptionWithHostPort (util.js:1049:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1085:14)
2017-03-12T22:05:17.695Z - info: SPOP status error:
2017-03-12T22:05:17.713Z - info:  Error: connect ECONNREFUSED 127.0.0.1:6602
    at Object.exports._errnoException (util.js:1026:11)
    at exports._exceptionWithHostPort (util.js:1049:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1085:14)
2017-03-12T22:05:18.372Z - info: Spotify access token expires at 1489359916929
2017-03-12T22:05:18.380Z - info: Spotify access token is BQB0oyIG1bCTtamoXrgcif8Ssx2r13Vhrx5RUhmGHJy7lkoTF1Zx5ZIXoLg_Bdc8Kvo562cHmXJ7PTiU_R6CcQ
2017-03-12T22:05:18.389Z - info: Spotify credentials grant success
2017-03-12T22:05:40.124Z - info: CALLMETHOD: music_service spop saveSpotifyAccount [object Object]
2017-03-12T22:05:40.132Z - info: CoreCommandRouter::executeOnPlugin: spop , saveSpotifyAccount
2017-03-12T22:05:40.673Z - info: SpopD Daemon Started
2017-03-12T22:05:45.685Z - info: Connecting to daemon
2017-03-12T22:05:45.785Z - info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
2017-03-12T22:05:45.796Z - info: [1489356345790] CoreMusicLibrary::Adding element Spotify
2017-03-12T22:05:45.840Z - info: FIRST BRANCH
2017-03-12T22:05:46.371Z - info: Spotify access token expires at 1489359945696
2017-03-12T22:05:46.378Z - info: Spotify access token is BQAbpYMUIMTumxFnMt7rjKXZjpuFWiZI_Vk-nAEewfC1x9ayHH72fX8KCyZwJ591WCVovXmfOxGfD8nXPralEQ
2017-03-12T22:05:46.386Z - info: Spotify credentials grant success
2017-03-12T22:05:49.824Z - info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"1.2.0","icon":"fa-spotify","enabled":true,"active":false}]
2017-03-12T22:05:56.502Z - info: CoreCommandRouter::volumioGetState
2017-03-12T22:05:56.516Z - info: [1489356356509] CoreStateMachine::getState
2017-03-12T22:05:56.526Z - info: [1489356356520] CorePlayQueue::getTrack 0
2017-03-12T22:05:56.537Z - info: 
[1489356356528] ---------------------------- Client requests Volumio state
2017-03-12T22:05:56.549Z - info: [1489356356544] InterfaceWebUI::pushState
2017-03-12T22:05:56.683Z - info: [1489356356677] ------------------------------ 185ms
2017-03-12T22:05:56.820Z - info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
2017-03-12T22:05:56.833Z - info: 
[1489356356826] ---------------------------- Client requests Menu Items
2017-03-12T22:05:56.846Z - info: [1489356356837] Listing playlists
2017-03-12T22:05:56.861Z - info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
2017-03-12T22:05:56.987Z - info: [1489356356981] ------------------------------ 155ms
2017-03-12T22:05:59.512Z - info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"1.2.0","icon":"fa-spotify","enabled":true,"active":false}]
2017-03-12T22:06:08.547Z - info: CoreCommandRouter::volumioGetBrowseSources
2017-03-12T22:06:08.578Z - info: CoreCommandRouter::volumioGetQueue
2017-03-12T22:06:08.587Z - info: [1489356368581] CoreStateMachine::getQueue
2017-03-12T22:06:08.594Z - info: [1489356368588] CorePlayQueue::getQueue
2017-03-12T22:06:08.601Z - info: 
[1489356368595] ---------------------------- Client requests Volumio queue
2017-03-12T22:06:08.606Z - info: [1489356368604] InterfaceWebUI::pushQueue
2017-03-12T22:06:08.625Z - info: [1489356368612] ------------------------------ 40ms
2017-03-12T22:06:09.583Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:06:11.029Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:06:11.043Z - info: [1489356371037] ControllerSpop::sendSpopCommand
2017-03-12T22:06:11.051Z - info: ADDING DEFER FOR COMMAND ls
2017-03-12T22:06:11.092Z - info: FIRST BRANCH
2017-03-12T22:06:11.099Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:06:11.107Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK
2017-03-12T22:06:51.659Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:06:53.401Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:04.620Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:06.876Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:09.800Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:17.379Z - info: [{"prettyName":"Spotify","name":"spop","category":"music_service","version":"1.2.0","icon":"fa-spotify","enabled":true,"active":false}]
2017-03-12T22:07:23.521Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:27.472Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:30.766Z - info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri
2017-03-12T22:07:35.831Z - info: CoreCommandRouter::volumioAddQueueItems
2017-03-12T22:07:35.840Z - info: [1489356455834] CoreStateMachine::addQueueItems
2017-03-12T22:07:35.854Z - info: [1489356455848] CorePlayQueue::addQueueItems
2017-03-12T22:07:35.872Z - info:  uri=spotify:track:7BHPGtpuuWWsvE7cCaMuEU, title=Naive, service=spop
2017-03-12T22:07:35.880Z - info: First index is 0
2017-03-12T22:07:35.888Z - info: ADDING THIS ITEM TO QUEUE: {"uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","title":"Naive","service":"spop"}
2017-03-12T22:07:35.897Z - info: Exploding uri spotify:track:7BHPGtpuuWWsvE7cCaMuEU in service spop
2017-03-12T22:07:36.496Z - info: [1489356456489] CorePlayQueue::saveQueue
2017-03-12T22:07:36.510Z - info: Adding item to queue: [{"uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","service":"spop","name":"Naive","artist":"The Kooks","album":"Inside In / Inside Out","type":"song","duration":203,"tracknumber":9,"albumart":"https://i.scdn.co/image/2091e88d1ddde2be64e429ae880930cd53f35272","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}]
2017-03-12T22:07:36.520Z - info: CoreCommandRouter::volumioPushQueue
2017-03-12T22:07:36.531Z - info: [1489356456524] interfaceApi::pushQueue
2017-03-12T22:07:36.538Z - info: [1489356456532] InterfaceWebUI::pushQueue
2017-03-12T22:07:36.558Z - info: [1489356456551] CoreStateMachine::updateTrackBlock
2017-03-12T22:07:36.568Z - info: [1489356456562] CorePlayQueue::getTrackBlock
2017-03-12T22:07:36.582Z - info: CoreCommandRouter::volumioPlay
2017-03-12T22:07:36.598Z - info: [1489356456592] CoreStateMachine::play index 0
2017-03-12T22:07:36.607Z - info: [1489356456601] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:07:36.623Z - info: [1489356456617] CoreStateMachine::stop
2017-03-12T22:07:36.627Z - info: [1489356456624] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:07:36.645Z - info: [1489356456631] CoreStateMachine::play index undefined
2017-03-12T22:07:36.651Z - info: [1489356456646] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:07:36.659Z - info: [1489356456654] CorePlayQueue::getTrack 0
2017-03-12T22:07:36.670Z - info: [1489356456663] CoreStateMachine::startPlaybackTimer
2017-03-12T22:07:36.677Z - info: [1489356456671] CorePlayQueue::getTrack 0
2017-03-12T22:07:36.693Z - info: [1489356456687] ControllerSpop::clearAddPlayTrack
2017-03-12T22:07:36.696Z - info: {"uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","service":"spop","name":"Naive","artist":"The Kooks","album":"Inside In / Inside Out","type":"song","duration":203,"tracknumber":9,"albumart":"https://i.scdn.co/image/2091e88d1ddde2be64e429ae880930cd53f35272","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}
2017-03-12T22:07:36.700Z - info: [1489356456698] ControllerSpop::sendSpopCommand
2017-03-12T22:07:36.715Z - info: ADDING DEFER FOR COMMAND uplay
2017-03-12T22:07:36.957Z - info: STATUS
2017-03-12T22:07:36.973Z - info: {
  "status" : "playing",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1,
  "current_track" : 1,
  "artist" : "The Kooks",
  "title" : "Naive",
  "album" : "Inside In / Inside Out",
  "duration" : 204000,
  "position" : 0,
  "uri" : "spotify:track:7BHPGtpuuWWsvE7cCaMuEU",
  "popularity" : 71
}

2017-03-12T22:07:36.978Z - info: 
[1489356456976] ---------------------------- Spop announces state update
2017-03-12T22:07:37.051Z - info: [1489356457048] ControllerSpop::parseState
2017-03-12T22:07:37.091Z - info: [1489356457088] ControllerSpop::pushState
2017-03-12T22:07:37.105Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:07:37.191Z - info: [1489356457166] CoreStateMachine::syncState
2017-03-12T22:07:37.199Z - info: [1489356457193] CorePlayQueue::getTrack 0
2017-03-12T22:07:37.210Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":204000,"samplerate":"320Kbps","bitdepth":null,"channels":null,"artist":"The Kooks","title":"Naive","album":"Inside In / Inside Out"}
2017-03-12T22:07:37.227Z - info: CURRENT POSITION 0
2017-03-12T22:07:37.243Z - info: [1489356457229] CoreStateMachine::syncState   stateService play
2017-03-12T22:07:37.252Z - info: [1489356457244] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:07:37.281Z - info: [1489356457275] CoreStateMachine::pushState
2017-03-12T22:07:37.293Z - info: [1489356457282] CoreStateMachine::getState
2017-03-12T22:07:37.303Z - info: [1489356457294] CorePlayQueue::getTrack 0
2017-03-12T22:07:37.333Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:07:37.340Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:07:37.370Z - info: [1489356457363] interfaceApi::pushState
2017-03-12T22:07:37.387Z - info: [1489356457371] InterfaceWebUI::pushState
2017-03-12T22:07:37.589Z - info: [1489356457571] ------------------------------ 624ms
2017-03-12T22:07:37.633Z - info: FIRST BRANCH
2017-03-12T22:07:37.644Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:07:37.657Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK
2017-03-12T22:07:37.699Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:09.560Z - info: 
[1489356489549] ---------------------------- Client requests Volume +
2017-03-12T22:08:09.580Z - info: [1489356489572] VolumeController::SetAlsaVolume+
2017-03-12T22:08:09.671Z - info: [1489356489665] ------------------------------ 117ms
2017-03-12T22:08:09.948Z - info: Mpd Status Update: mixer
2017-03-12T22:08:09.961Z - info: 
[1489356489951] ---------------------------- MPD announces state update
2017-03-12T22:08:09.978Z - info: [1489356489971] ControllerMpd::getState
2017-03-12T22:08:09.988Z - info: [1489356489982] ControllerMpd::sendMpdCommand status
2017-03-12T22:08:10.004Z - info: [1489356489993] sending command...
2017-03-12T22:08:10.034Z - info: [1489356490022] parsing response...
2017-03-12T22:08:10.060Z - info: [1489356490054] ControllerMpd::parseState
2017-03-12T22:08:10.071Z - info: [1489356490065] ControllerMpd::pushState
2017-03-12T22:08:10.078Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:10.087Z - info: [1489356490080] CoreStateMachine::syncState
2017-03-12T22:08:10.094Z - info: [1489356490088] CorePlayQueue::getTrack 0
2017-03-12T22:08:10.102Z - info: [1489356490095] Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd
2017-03-12T22:08:10.113Z - info: [1489356490107] ------------------------------ 169ms
2017-03-12T22:08:10.131Z - info: [1489356490124] VolumeController::Volume 40
2017-03-12T22:08:10.142Z - info: [1489356490137] CoreStateMachine::pushState
2017-03-12T22:08:10.150Z - info: [1489356490144] CoreStateMachine::getState
2017-03-12T22:08:10.157Z - info: [1489356490150] CorePlayQueue::getTrack 0
2017-03-12T22:08:10.165Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:10.172Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:10.185Z - info: [1489356490179] interfaceApi::pushState
2017-03-12T22:08:10.188Z - info: [1489356490186] InterfaceWebUI::pushState
2017-03-12T22:08:10.311Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:20.640Z - info: 
[1489356500630] ---------------------------- Client requests Volumio next
2017-03-12T22:08:20.650Z - info: CoreCommandRouter::volumioNext
2017-03-12T22:08:20.660Z - info: [1489356500653] CoreStateMachine::next
2017-03-12T22:08:20.667Z - info: [1489356500661] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:20.675Z - info: [1489356500669] CoreStateMachine::stop
2017-03-12T22:08:20.678Z - info: [1489356500676] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:20.692Z - info: [1489356500690] CoreStateMachine::stPlaybackTimer
2017-03-12T22:08:20.700Z - info: [1489356500697] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:20.707Z - info: [1489356500701] CorePlayQueue::getTrackBlock
2017-03-12T22:08:20.711Z - info: [1489356500709] CoreStateMachine::pushState
2017-03-12T22:08:20.725Z - info: [1489356500712] CoreStateMachine::getState
2017-03-12T22:08:20.728Z - info: [1489356500726] CorePlayQueue::getTrack 0
2017-03-12T22:08:20.731Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:20.742Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:20.757Z - info: [1489356500751] interfaceApi::pushState
2017-03-12T22:08:20.764Z - info: [1489356500758] InterfaceWebUI::pushState
2017-03-12T22:08:20.863Z - info: [1489356500857] CoreStateMachine::serviceStop
2017-03-12T22:08:20.871Z - info: [1489356500865] CorePlayQueue::getTrack 0
2017-03-12T22:08:20.880Z - info: CoreCommandRouter::serviceStop
2017-03-12T22:08:20.890Z - info: [1489356500883] ControllerSpop::stop
2017-03-12T22:08:20.897Z - info: [1489356500891] ControllerSpop::sendSpopCommand
2017-03-12T22:08:20.905Z - info: ADDING DEFER FOR COMMAND stop
2017-03-12T22:08:20.930Z - info: [1489356500924] ------------------------------ 294ms
2017-03-12T22:08:20.963Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:21.350Z - info: STATUS
2017-03-12T22:08:21.354Z - info: {
  "status" : "stopped",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1
}

2017-03-12T22:08:21.357Z - info: 
[1489356501355] ---------------------------- Spop announces state update
2017-03-12T22:08:21.373Z - info: [1489356501361] ControllerSpop::parseState
2017-03-12T22:08:21.378Z - info: [1489356501376] ControllerSpop::pushState
2017-03-12T22:08:21.382Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:21.405Z - info: [1489356501382] CoreStateMachine::syncState
2017-03-12T22:08:21.408Z - info: [1489356501406] CorePlayQueue::getTrack 0
2017-03-12T22:08:21.423Z - info: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":"320Kbps","bitdepth":null,"channels":null}
2017-03-12T22:08:21.426Z - info: CURRENT POSITION 0
2017-03-12T22:08:21.431Z - info: [1489356501429] CoreStateMachine::syncState   stateService stop
2017-03-12T22:08:21.444Z - info: [1489356501432] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:08:21.448Z - info: [1489356501446] CoreStateMachine::pushState
2017-03-12T22:08:21.451Z - info: [1489356501449] CoreStateMachine::getState
2017-03-12T22:08:21.464Z - info: [1489356501452] CorePlayQueue::getTrack 0
2017-03-12T22:08:21.467Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:21.470Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:21.486Z - info: [1489356501484] interfaceApi::pushState
2017-03-12T22:08:21.490Z - info: [1489356501488] InterfaceWebUI::pushState
2017-03-12T22:08:21.581Z - info: [1489356501566] No code
2017-03-12T22:08:21.588Z - info: [1489356501582] CoreStateMachine::pushState
2017-03-12T22:08:21.595Z - info: [1489356501589] CoreStateMachine::getState
2017-03-12T22:08:21.602Z - info: [1489356501596] CorePlayQueue::getTrack 0
2017-03-12T22:08:21.609Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:21.612Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:21.626Z - info: [1489356501620] interfaceApi::pushState
2017-03-12T22:08:21.633Z - info: [1489356501627] InterfaceWebUI::pushState
2017-03-12T22:08:21.721Z - info: [1489356501714] ------------------------------ 375ms
2017-03-12T22:08:21.745Z - info: FIRST BRANCH
2017-03-12T22:08:21.751Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:08:21.759Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK
2017-03-12T22:08:21.769Z - info: NEXT POSITION 0
2017-03-12T22:08:21.777Z - info: [1489356501771] CoreStateMachine::play index undefined
2017-03-12T22:08:21.784Z - info: [1489356501778] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:21.793Z - info: [1489356501787] CorePlayQueue::getTrack 0
2017-03-12T22:08:21.800Z - info: [1489356501795] CoreStateMachine::startPlaybackTimer
2017-03-12T22:08:21.807Z - info: [1489356501802] CorePlayQueue::getTrack 0
2017-03-12T22:08:21.817Z - info: [1489356501811] ControllerSpop::clearAddPlayTrack
2017-03-12T22:08:21.824Z - info: {"uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","service":"spop","name":"Naive","artist":"The Kooks","album":"Inside In / Inside Out","type":"song","duration":203,"tracknumber":9,"albumart":"https://i.scdn.co/image/2091e88d1ddde2be64e429ae880930cd53f35272","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}
2017-03-12T22:08:21.831Z - info: [1489356501825] ControllerSpop::sendSpopCommand
2017-03-12T22:08:21.838Z - info: ADDING DEFER FOR COMMAND uplay
2017-03-12T22:08:21.869Z - info: [1489356501863] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:21.876Z - info: [1489356501870] CorePlayQueue::getTrackBlock
2017-03-12T22:08:21.903Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:21.929Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:22.131Z - info: STATUS
2017-03-12T22:08:22.143Z - info: {
  "status" : "playing",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1,
  "current_track" : 1,
  "artist" : "The Kooks",
  "title" : "Naive",
  "album" : "Inside In / Inside Out",
  "duration" : 204000,
  "position" : 0,
  "uri" : "spotify:track:7BHPGtpuuWWsvE7cCaMuEU",
  "popularity" : 71
}

2017-03-12T22:08:22.146Z - info: 
[1489356502144] ---------------------------- Spop announces state update
2017-03-12T22:08:22.150Z - info: [1489356502148] ControllerSpop::parseState
2017-03-12T22:08:22.185Z - info: [1489356502183] ControllerSpop::pushState
2017-03-12T22:08:22.188Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:22.191Z - info: [1489356502189] CoreStateMachine::syncState
2017-03-12T22:08:22.225Z - info: [1489356502192] CorePlayQueue::getTrack 0
2017-03-12T22:08:22.228Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":204000,"samplerate":"320Kbps","bitdepth":null,"channels":null,"artist":"The Kooks","title":"Naive","album":"Inside In / Inside Out"}
2017-03-12T22:08:22.230Z - info: CURRENT POSITION 0
2017-03-12T22:08:22.264Z - info: [1489356502231] CoreStateMachine::syncState   stateService play
2017-03-12T22:08:22.275Z - info: [1489356502273] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:08:22.279Z - info: [1489356502277] CoreStateMachine::pushState
2017-03-12T22:08:22.282Z - info: [1489356502279] CoreStateMachine::getState
2017-03-12T22:08:22.315Z - info: [1489356502312] CorePlayQueue::getTrack 0
2017-03-12T22:08:22.318Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:22.321Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:22.352Z - info: [1489356502345] interfaceApi::pushState
2017-03-12T22:08:22.356Z - info: [1489356502354] InterfaceWebUI::pushState
2017-03-12T22:08:22.543Z - info: [1489356502520] ------------------------------ 395ms
2017-03-12T22:08:22.553Z - info: FIRST BRANCH
2017-03-12T22:08:22.556Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:08:22.559Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK
2017-03-12T22:08:22.598Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:32.522Z - info: CoreCommandRouter::volumioAddQueueItems
2017-03-12T22:08:32.536Z - info: [1489356512530] CoreStateMachine::addQueueItems
2017-03-12T22:08:32.554Z - info: [1489356512538] CorePlayQueue::addQueueItems
2017-03-12T22:08:32.562Z - info:  uri=spotify:track:7kcyCnpHm1BZGB9Wc7MCZH, title=Golden Skans, service=spop
2017-03-12T22:08:32.573Z - info: First index is 1
2017-03-12T22:08:32.583Z - info: ADDING THIS ITEM TO QUEUE: {"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","title":"Golden Skans","service":"spop"}
2017-03-12T22:08:32.592Z - info: Exploding uri spotify:track:7kcyCnpHm1BZGB9Wc7MCZH in service spop
2017-03-12T22:08:33.236Z - info: [1489356513230] CorePlayQueue::saveQueue
2017-03-12T22:08:33.246Z - info: Adding item to queue: [{"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","service":"spop","name":"Golden Skans","artist":"Klaxons","album":"Myths Of The Near Future","type":"song","duration":165,"tracknumber":3,"albumart":"https://i.scdn.co/image/0994008cdfca44356c7249678db6430688eefb9c","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}]
2017-03-12T22:08:33.253Z - info: CoreCommandRouter::volumioPushQueue
2017-03-12T22:08:33.257Z - info: [1489356513255] interfaceApi::pushQueue
2017-03-12T22:08:33.261Z - info: [1489356513259] InterfaceWebUI::pushQueue
2017-03-12T22:08:33.288Z - info: [1489356513282] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:33.296Z - info: [1489356513289] CorePlayQueue::getTrackBlock
2017-03-12T22:08:33.306Z - info: CoreCommandRouter::volumioPlay
2017-03-12T22:08:33.317Z - info: [1489356513315] CoreStateMachine::play index 1
2017-03-12T22:08:33.320Z - info: [1489356513318] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:33.342Z - info: [1489356513340] CoreStateMachine::stop
2017-03-12T22:08:33.349Z - info: [1489356513347] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:33.360Z - info: [1489356513351] CoreStateMachine::stPlaybackTimer
2017-03-12T22:08:33.369Z - info: [1489356513362] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:33.372Z - info: [1489356513370] CorePlayQueue::getTrackBlock
2017-03-12T22:08:33.381Z - info: [1489356513379] CoreStateMachine::pushState
2017-03-12T22:08:33.390Z - info: [1489356513388] CoreStateMachine::getState
2017-03-12T22:08:33.393Z - info: [1489356513391] CorePlayQueue::getTrack 0
2017-03-12T22:08:33.396Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:33.399Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:33.421Z - info: [1489356513418] interfaceApi::pushState
2017-03-12T22:08:33.429Z - info: [1489356513422] InterfaceWebUI::pushState
2017-03-12T22:08:33.516Z - info: [1489356513510] CoreStateMachine::serviceStop
2017-03-12T22:08:33.560Z - info: [1489356513518] CorePlayQueue::getTrack 0
2017-03-12T22:08:33.571Z - info: CoreCommandRouter::serviceStop
2017-03-12T22:08:33.578Z - info: [1489356513572] ControllerSpop::stop
2017-03-12T22:08:33.586Z - info: [1489356513579] ControllerSpop::sendSpopCommand
2017-03-12T22:08:33.592Z - info: ADDING DEFER FOR COMMAND stop
2017-03-12T22:08:33.623Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:33.930Z - info: CoreCommandRouter::volumioAddQueueItems
2017-03-12T22:08:33.938Z - info: [1489356513932] CoreStateMachine::addQueueItems
2017-03-12T22:08:33.945Z - info: [1489356513939] CorePlayQueue::addQueueItems
2017-03-12T22:08:33.952Z - info:  uri=spotify:track:7kcyCnpHm1BZGB9Wc7MCZH, title=Golden Skans, service=spop
2017-03-12T22:08:33.959Z - info: First index is 2
2017-03-12T22:08:33.966Z - info: ADDING THIS ITEM TO QUEUE: {"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","title":"Golden Skans","service":"spop"}
2017-03-12T22:08:33.973Z - info: Exploding uri spotify:track:7kcyCnpHm1BZGB9Wc7MCZH in service spop
2017-03-12T22:08:34.016Z - info: STATUS
2017-03-12T22:08:34.027Z - info: {
  "status" : "stopped",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1
}

2017-03-12T22:08:34.030Z - info: 
[1489356514027] ---------------------------- Spop announces state update
2017-03-12T22:08:34.043Z - info: [1489356514032] ControllerSpop::parseState
2017-03-12T22:08:34.047Z - info: [1489356514045] ControllerSpop::pushState
2017-03-12T22:08:34.050Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:34.063Z - info: [1489356514051] CoreStateMachine::syncState
2017-03-12T22:08:34.067Z - info: [1489356514064] CorePlayQueue::getTrack 0
2017-03-12T22:08:34.070Z - info: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":"320Kbps","bitdepth":null,"channels":null}
2017-03-12T22:08:34.072Z - info: CURRENT POSITION 0
2017-03-12T22:08:34.086Z - info: [1489356514083] CoreStateMachine::syncState   stateService stop
2017-03-12T22:08:34.088Z - info: [1489356514086] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:08:34.092Z - info: [1489356514090] CoreStateMachine::pushState
2017-03-12T22:08:34.105Z - info: [1489356514103] CoreStateMachine::getState
2017-03-12T22:08:34.108Z - info: [1489356514106] CorePlayQueue::getTrack 0
2017-03-12T22:08:34.111Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:34.124Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:34.130Z - info: [1489356514128] interfaceApi::pushState
2017-03-12T22:08:34.144Z - info: [1489356514131] InterfaceWebUI::pushState
2017-03-12T22:08:34.240Z - info: [1489356514234] No code
2017-03-12T22:08:34.250Z - info: [1489356514241] CoreStateMachine::pushState
2017-03-12T22:08:34.257Z - info: [1489356514251] CoreStateMachine::getState
2017-03-12T22:08:34.263Z - info: [1489356514258] CorePlayQueue::getTrack 0
2017-03-12T22:08:34.266Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:34.269Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:34.287Z - info: [1489356514280] interfaceApi::pushState
2017-03-12T22:08:34.294Z - info: [1489356514288] InterfaceWebUI::pushState
2017-03-12T22:08:34.381Z - info: [1489356514375] ------------------------------ 365ms
2017-03-12T22:08:34.406Z - info: FIRST BRANCH
2017-03-12T22:08:34.413Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:08:34.420Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK
2017-03-12T22:08:34.427Z - info: [1489356514421] CoreStateMachine::play index undefined
2017-03-12T22:08:34.437Z - info: [1489356514431] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:34.446Z - info: [1489356514440] CorePlayQueue::getTrack 1
2017-03-12T22:08:34.453Z - info: [1489356514447] CoreStateMachine::startPlaybackTimer
2017-03-12T22:08:34.456Z - info: [1489356514454] CorePlayQueue::getTrack 1
2017-03-12T22:08:34.460Z - info: [1489356514458] ControllerSpop::clearAddPlayTrack
2017-03-12T22:08:34.474Z - info: {"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","service":"spop","name":"Golden Skans","artist":"Klaxons","album":"Myths Of The Near Future","type":"song","duration":165,"tracknumber":3,"albumart":"https://i.scdn.co/image/0994008cdfca44356c7249678db6430688eefb9c","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}
2017-03-12T22:08:34.481Z - info: [1489356514475] ControllerSpop::sendSpopCommand
2017-03-12T22:08:34.488Z - info: ADDING DEFER FOR COMMAND uplay
2017-03-12T22:08:34.533Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:34.560Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7BHPGtpuuWWsvE7cCaMuEU","favourite":false}
2017-03-12T22:08:34.699Z - info: CoreCommandRouter::volumioAddQueueItems
2017-03-12T22:08:34.706Z - info: [1489356514700] CoreStateMachine::addQueueItems
2017-03-12T22:08:34.719Z - info: [1489356514707] CorePlayQueue::addQueueItems
2017-03-12T22:08:34.726Z - info:  uri=spotify:track:7kcyCnpHm1BZGB9Wc7MCZH, title=Golden Skans, service=spop
2017-03-12T22:08:34.733Z - info: First index is 2
2017-03-12T22:08:34.736Z - info: ADDING THIS ITEM TO QUEUE: {"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","title":"Golden Skans","service":"spop"}
2017-03-12T22:08:34.741Z - info: Exploding uri spotify:track:7kcyCnpHm1BZGB9Wc7MCZH in service spop
2017-03-12T22:08:34.783Z - info: STATUS
2017-03-12T22:08:34.793Z - info: {
  "status" : "playing",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1,
  "current_track" : 1,
  "artist" : "Klaxons",
  "title" : "Golden Skans",
  "album" : "Myths Of The Near Future",
  "duration" : 165000,
  "position" : 0,
  "uri" : "spotify:track:7kcyCnpHm1BZGB9Wc7MCZH",
  "popularity" : 61
}

2017-03-12T22:08:34.796Z - info: 
[1489356514794] ---------------------------- Spop announces state update
2017-03-12T22:08:34.800Z - info: [1489356514798] ControllerSpop::parseState
2017-03-12T22:08:34.835Z - info: [1489356514802] ControllerSpop::pushState
2017-03-12T22:08:34.838Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:34.841Z - info: [1489356514839] CoreStateMachine::syncState
2017-03-12T22:08:34.864Z - info: [1489356514842] CorePlayQueue::getTrack 1
2017-03-12T22:08:34.904Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":165000,"samplerate":"320Kbps","bitdepth":null,"channels":null,"artist":"Klaxons","title":"Golden Skans","album":"Myths Of The Near Future"}
2017-03-12T22:08:34.907Z - info: CURRENT POSITION 1
2017-03-12T22:08:34.910Z - info: [1489356514908] CoreStateMachine::syncState   stateService play
2017-03-12T22:08:34.933Z - info: [1489356514911] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:08:34.936Z - info: [1489356514934] CoreStateMachine::pushState
2017-03-12T22:08:34.940Z - info: [1489356514937] CoreStateMachine::getState
2017-03-12T22:08:34.963Z - info: [1489356514940] CorePlayQueue::getTrack 1
2017-03-12T22:08:34.966Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:34.968Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:35.003Z - info: [1489356514990] interfaceApi::pushState
2017-03-12T22:08:35.007Z - info: [1489356515004] InterfaceWebUI::pushState
2017-03-12T22:08:35.288Z - info: [1489356515282] ------------------------------ 504ms
2017-03-12T22:08:35.310Z - info: FIRST BRANCH
2017-03-12T22:08:35.317Z - info: BEFORE: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:08:35.333Z - info: AFTER: SPOP HAS 0 PROMISE IN STACK
2017-03-12T22:08:35.459Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","favourite":false}
2017-03-12T22:08:35.833Z - info: [1489356515818] CorePlayQueue::saveQueue
2017-03-12T22:08:35.849Z - info: Adding item to queue: [{"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","service":"spop","name":"Golden Skans","artist":"Klaxons","album":"Myths Of The Near Future","type":"song","duration":165,"tracknumber":3,"albumart":"https://i.scdn.co/image/0994008cdfca44356c7249678db6430688eefb9c","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}]
2017-03-12T22:08:35.863Z - info: CoreCommandRouter::volumioPushQueue
2017-03-12T22:08:35.870Z - info: [1489356515865] interfaceApi::pushQueue
2017-03-12T22:08:35.888Z - info: [1489356515872] InterfaceWebUI::pushQueue
2017-03-12T22:08:35.922Z - info: [1489356515900] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:35.929Z - info: [1489356515923] CorePlayQueue::getTrackBlock
2017-03-12T22:08:35.943Z - info: CoreCommandRouter::volumioPlay
2017-03-12T22:08:35.950Z - info: [1489356515948] CoreStateMachine::play index 2
2017-03-12T22:08:35.964Z - info: [1489356515951] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:35.968Z - info: [1489356515966] CoreStateMachine::stop
2017-03-12T22:08:35.971Z - info: [1489356515969] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:35.996Z - info: [1489356515993] CoreStateMachine::stPlaybackTimer
2017-03-12T22:08:35.998Z - info: [1489356515996] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:36.001Z - info: [1489356515999] CorePlayQueue::getTrackBlock
2017-03-12T22:08:36.063Z - info: [1489356516023] CoreStateMachine::pushState
2017-03-12T22:08:36.070Z - info: [1489356516064] CoreStateMachine::getState
2017-03-12T22:08:36.077Z - info: [1489356516070] CorePlayQueue::getTrack 1
2017-03-12T22:08:36.087Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:36.090Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:36.114Z - info: [1489356516108] interfaceApi::pushState
2017-03-12T22:08:36.124Z - info: [1489356516116] InterfaceWebUI::pushState
2017-03-12T22:08:36.253Z - info: [1489356516239] CoreStateMachine::serviceStop
2017-03-12T22:08:36.260Z - info: [1489356516254] CorePlayQueue::getTrack 1
2017-03-12T22:08:36.293Z - info: CoreCommandRouter::serviceStop
2017-03-12T22:08:36.296Z - info: [1489356516294] ControllerSpop::stop
2017-03-12T22:08:36.299Z - info: [1489356516297] ControllerSpop::sendSpopCommand
2017-03-12T22:08:36.323Z - info: ADDING DEFER FOR COMMAND stop
2017-03-12T22:08:36.423Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","favourite":false}
2017-03-12T22:08:36.670Z - info: [1489356516664] CorePlayQueue::saveQueue
2017-03-12T22:08:36.683Z - info: Adding item to queue: [{"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","service":"spop","name":"Golden Skans","artist":"Klaxons","album":"Myths Of The Near Future","type":"song","duration":165,"tracknumber":3,"albumart":"https://i.scdn.co/image/0994008cdfca44356c7249678db6430688eefb9c","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}]
2017-03-12T22:08:36.693Z - info: CoreCommandRouter::volumioPushQueue
2017-03-12T22:08:36.713Z - info: [1489356516695] interfaceApi::pushQueue
2017-03-12T22:08:36.720Z - info: [1489356516714] InterfaceWebUI::pushQueue
2017-03-12T22:08:36.755Z - info: [1489356516744] CoreStateMachine::updateTrackBlock
2017-03-12T22:08:36.758Z - info: [1489356516756] CorePlayQueue::getTrackBlock
2017-03-12T22:08:36.762Z - info: CoreCommandRouter::volumioPlay
2017-03-12T22:08:36.778Z - info: [1489356516775] CoreStateMachine::play index 2
2017-03-12T22:08:36.781Z - info: [1489356516779] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:36.793Z - info: [1489356516790] CoreStateMachine::stop
2017-03-12T22:08:36.796Z - info: [1489356516794] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:36.800Z - info: [1489356516798] CoreStateMachine::play index undefined
2017-03-12T22:08:36.817Z - info: [1489356516801] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:36.821Z - info: [1489356516819] CorePlayQueue::getTrack 2
2017-03-12T22:08:36.831Z - info: [1489356516822] CoreStateMachine::startPlaybackTimer
2017-03-12T22:08:36.838Z - info: [1489356516832] CorePlayQueue::getTrack 2
2017-03-12T22:08:36.849Z - info: [1489356516839] ControllerSpop::clearAddPlayTrack
2017-03-12T22:08:36.852Z - info: {"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","service":"spop","name":"Golden Skans","artist":"Klaxons","album":"Myths Of The Near Future","type":"song","duration":165,"tracknumber":3,"albumart":"https://i.scdn.co/image/0994008cdfca44356c7249678db6430688eefb9c","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}
2017-03-12T22:08:36.860Z - info: [1489356516857] ControllerSpop::sendSpopCommand
2017-03-12T22:08:36.868Z - info: ADDING DEFER FOR COMMAND uplay
2017-03-12T22:08:36.910Z - info: STATUS
2017-03-12T22:08:36.923Z - info: {
  "status" : "stopped",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1
}

2017-03-12T22:08:36.926Z - info: 
[1489356516924] ---------------------------- Spop announces state update
2017-03-12T22:08:36.944Z - info: [1489356516928] ControllerSpop::parseState
2017-03-12T22:08:36.948Z - info: [1489356516945] ControllerSpop::pushState
2017-03-12T22:08:36.951Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:36.974Z - info: [1489356516951] CoreStateMachine::syncState
2017-03-12T22:08:36.977Z - info: [1489356516975] CorePlayQueue::getTrack 2
2017-03-12T22:08:36.980Z - info: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":"320Kbps","bitdepth":null,"channels":null}
2017-03-12T22:08:37.003Z - info: CURRENT POSITION 2
2017-03-12T22:08:37.006Z - info: [1489356517004] CoreStateMachine::syncState   stateService stop
2017-03-12T22:08:37.009Z - info: [1489356517007] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:08:37.025Z - info: [1489356517010] CoreStateMachine::pushState
2017-03-12T22:08:37.028Z - info: [1489356517026] CoreStateMachine::getState
2017-03-12T22:08:37.031Z - info: [1489356517029] CorePlayQueue::getTrack 2
2017-03-12T22:08:37.054Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:37.057Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:37.083Z - info: [1489356517061] interfaceApi::pushState
2017-03-12T22:08:37.086Z - info: [1489356517084] InterfaceWebUI::pushState
2017-03-12T22:08:37.253Z - info: [1489356517202] No code
2017-03-12T22:08:37.273Z - info: [1489356517255] CoreStateMachine::pushState
2017-03-12T22:08:37.282Z - info: [1489356517274] CoreStateMachine::getState
2017-03-12T22:08:37.289Z - info: [1489356517283] CorePlayQueue::getTrack 2
2017-03-12T22:08:37.299Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:37.313Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:37.337Z - info: [1489356517317] interfaceApi::pushState
2017-03-12T22:08:37.345Z - info: [1489356517338] InterfaceWebUI::pushState
2017-03-12T22:08:37.459Z - info: [1489356517437] ------------------------------ 533ms
2017-03-12T22:08:37.483Z - info: FIRST BRANCH
2017-03-12T22:08:37.489Z - info: BEFORE: SPOP HAS 2 PROMISE IN STACK
2017-03-12T22:08:37.496Z - info: AFTER: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:08:37.504Z - info: [1489356517498] CoreStateMachine::play index undefined
2017-03-12T22:08:37.519Z - info: [1489356517505] CoreStateMachine::setConsumeUpdateService undefined
2017-03-12T22:08:37.533Z - info: [1489356517520] CorePlayQueue::getTrack 2
2017-03-12T22:08:37.541Z - info: [1489356517534] CoreStateMachine::startPlaybackTimer
2017-03-12T22:08:37.553Z - info: [1489356517542] CorePlayQueue::getTrack 2
2017-03-12T22:08:37.560Z - info: [1489356517554] ControllerSpop::clearAddPlayTrack
2017-03-12T22:08:37.573Z - info: {"uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","service":"spop","name":"Golden Skans","artist":"Klaxons","album":"Myths Of The Near Future","type":"song","duration":165,"tracknumber":3,"albumart":"https://i.scdn.co/image/0994008cdfca44356c7249678db6430688eefb9c","samplerate":"320Kbps","bitdepth":"16 bit","trackType":"spotify"}
2017-03-12T22:08:37.580Z - info: [1489356517574] ControllerSpop::sendSpopCommand
2017-03-12T22:08:37.597Z - info: ADDING DEFER FOR COMMAND uplay
2017-03-12T22:08:37.769Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","favourite":false}
2017-03-12T22:08:37.803Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","favourite":false}
2017-03-12T22:08:37.928Z - info: STATUS
2017-03-12T22:08:37.943Z - info: {
  "status" : "playing",
  "repeat" : false,
  "shuffle" : false,
  "total_tracks" : 1,
  "current_track" : 1,
  "artist" : "Klaxons",
  "title" : "Golden Skans",
  "album" : "Myths Of The Near Future",
  "duration" : 165000,
  "position" : 0,
  "uri" : "spotify:track:7kcyCnpHm1BZGB9Wc7MCZH",
  "popularity" : 61
}

2017-03-12T22:08:37.946Z - info: 
[1489356517944] ---------------------------- Spop announces state update
2017-03-12T22:08:37.950Z - info: [1489356517948] ControllerSpop::parseState
2017-03-12T22:08:37.975Z - info: [1489356517952] ControllerSpop::pushState
2017-03-12T22:08:37.977Z - info: CoreCommandRouter::servicePushState
2017-03-12T22:08:37.981Z - info: [1489356517978] CoreStateMachine::syncState
2017-03-12T22:08:38.004Z - info: [1489356517981] CorePlayQueue::getTrack 2
2017-03-12T22:08:38.007Z - info: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":165000,"samplerate":"320Kbps","bitdepth":null,"channels":null,"artist":"Klaxons","title":"Golden Skans","album":"Myths Of The Near Future"}
2017-03-12T22:08:38.010Z - info: CURRENT POSITION 2
2017-03-12T22:08:38.033Z - info: [1489356518011] CoreStateMachine::syncState   stateService play
2017-03-12T22:08:38.036Z - info: [1489356518034] CoreStateMachine::syncState   currentStatus stop
2017-03-12T22:08:38.039Z - info: [1489356518037] CoreStateMachine::pushState
2017-03-12T22:08:38.042Z - info: [1489356518040] CoreStateMachine::getState
2017-03-12T22:08:38.066Z - info: [1489356518064] CorePlayQueue::getTrack 2
2017-03-12T22:08:38.069Z - info: CoreCommandRouter::volumioPushState
2017-03-12T22:08:38.072Z - info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
2017-03-12T22:08:38.098Z - info: [1489356518096] interfaceApi::pushState
2017-03-12T22:08:38.101Z - info: [1489356518099] InterfaceWebUI::pushState
2017-03-12T22:08:38.329Z - info: [1489356518322] ------------------------------ 400ms
2017-03-12T22:08:38.340Z - info: FIRST BRANCH
2017-03-12T22:08:38.346Z - info: BEFORE: SPOP HAS 2 PROMISE IN STACK
2017-03-12T22:08:38.353Z - info: AFTER: SPOP HAS 1 PROMISE IN STACK
2017-03-12T22:08:38.377Z - info: Pushing Favourites {"service":"spop","uri":"spotify:track:7kcyCnpHm1BZGB9Wc7MCZH","favourite":false}
volumio@Volumio:~$

freuz · April 5, 2017, 10:35am

hi,
i had som problems with my current installation of Volumio2 on my RPI 3 so i thought i’d start fresh and reinstall.

When reinstalling, the “Spotify My playlist” comes up empty. non of my own playlists are shown

everything else works with Spotify plugin, i see the other playlist like recommendations and they play fine.
i tried different versions of Volumio ranging from latest to versions back in october-december last year. NO GO
i tried different users of spotify. NO GO
i had a backup copy of previous installations, and they show My playlists, but it’s some sort of cache and it’s not reflecting the current playlists i have on my spotify account.

any ideas?

volumio · April 5, 2017, 11:25am

Yes, this has nothing to do with Volumio itself, but rather with Spotify gradually dropping libspotify support (its the official spotify library used by spop, the daemon that Volumio uses to provide spotify functionality).

This means that spotify is most likely to stop working completely in the next few months. We are aware of this and we’re actively working to provide a solution. This will involve creating a cloud infrastructure to use the 0auth authentication method provided by Spotify web API. This means that there is a lot of work involved and this new feature will not see daylight until mid summer. We would have avoided building a cloud infrastructure just for it, but it seems to be the only way to have reliable access to Spotity.

The good news is that we’ll be including all major other streaming services in this cloud service.

freuz · April 5, 2017, 11:48am

thank you very much for a quick and clear respons!

atleast I know can stop troubleshooting and install volumio over and over on different SD cards

thanks for all your hard work

santanacorreia · April 5, 2017, 6:34pm

Can we use spotify app to control the volumio?

freuz · April 6, 2017, 2:58pm

update: by chance I noticed one thing that might be of use for others at this point. Right after I installed the plugin it didn’t show the “My Playlist” in Spotify plugin.

BUT, when I left the RPI 3 running for some time, all of a sudden they appeared. Tried it with two different versions and same result.

danielfelix · April 7, 2017, 8:26pm

michelangelo:

Yes, this has nothing to do with Volumio itself, but rather with Spotify gradually dropping libspotify support (its the official spotify library used by spop, the daemon that Volumio uses to provide spotify functionality).

This means that spotify is most likely to stop working completely in the next few months. We are aware of this and we’re actively working to provide a solution. This will involve creating a cloud infrastructure to use the 0auth authentication method provided by Spotify web API. This means that there is a lot of work involved and this new feature will not see daylight until mid summer. We would have avoided building a cloud infrastructure just for it, but it seems to be the only way to have reliable access to Spotity.

The good news is that we’ll be including all major other streaming services in this cloud service.

Of this subject I know very little, but I have a lot of practice in discovering errors, I am a manager of digital map drawer, there are always some strange things to solve.
I can not understand why if I install version 2.041 everything referred to Spotify works correctly, and from there on does not. Did something change in the code? While the fixes are being implemented, you can not go back to the 2.041 code referred to Spotify?
You know how to apologize for the audacity, but I’m worried I will not have a logical answer. Needless to say, this is a contribution and not a criticism.
Regards

Daniel