-- Logs begin at Wed 2024-04-17 10:08:14 UTC, end at Wed 2024-04-17 12:06:42 UTC. -- Apr 17 12:05:02 volumio volumio[838]: info: ControllerAutoPlay - getting queue Apr 17 12:05:02 volumio volumio[838]: info: CoreCommandRouter::volumioGetQueue Apr 17 12:05:02 volumio volumio[838]: info: CoreStateMachine::getQueue Apr 17 12:05:02 volumio volumio[838]: info: CorePlayQueue::getQueue Apr 17 12:05:02 volumio volumio[838]: info: CoreCommandRouter::volumioGetState Apr 17 12:05:02 volumio volumio[838]: info: CoreStateMachine::getState Apr 17 12:05:02 volumio volumio[838]: info: CorePlayQueue::getTrack 0 Apr 17 12:05:03 volumio volumio[838]: info: CoreCommandRouter::volumioGetBrowseSources Apr 17 12:05:03 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 17 12:05:03 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 17 12:05:03 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 17 12:05:03 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 17 12:05:03 volumio volumio[838]: Plugin multiroom or method getMultiroom not found Apr 17 12:05:03 volumio volumio[838]: info: Listing playlists Apr 17 12:05:04 volumio volumio[838]: info: CoreCommandRouter::volumioPlay Apr 17 12:05:04 volumio volumio[838]: UNSET VOLATILE Apr 17 12:05:04 volumio volumio[838]: info: CoreStateMachine::play index undefined Apr 17 12:05:04 volumio volumio[838]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 17 12:05:04 volumio volumio[838]: info: CorePlayQueue::getTrack 0 Apr 17 12:05:05 volumio volumio[838]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=2.413&uuid=8a47768d7bd816bc76563e05eaf2e7d1" http://updates.volumio.org:7070/downloader-v1/track-device Apr 17 12:05:05 volumio volumio[838]: % Total % Received % Xferd Average Speed Time Time Time Current Apr 17 12:05:05 volumio volumio[838]: Dload Upload Total Spent Left Speed Apr 17 12:05:05 volumio volumio[838]: 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0curl: (7) Failed to connect to updates.volumio.org port 7070: Connection refused Apr 17 12:05:05 volumio volumio[838]: retrying in 5 seconds, trial 0 Apr 17 12:05:05 volumio volumio[838]: Volumio Calling Home Apr 17 12:05:08 volumio volumio[838]: info: CoreCommandRouter::volumioPlay Apr 17 12:05:08 volumio volumio[838]: UNSET VOLATILE Apr 17 12:05:08 volumio volumio[838]: info: CoreStateMachine::play index undefined Apr 17 12:05:08 volumio volumio[838]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 17 12:05:08 volumio volumio[838]: info: CorePlayQueue::getTrack 0 Apr 17 12:05:15 volumio volumio[838]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=2.413&uuid=8a47768d7bd816bc76563e05eaf2e7d1" http://updates.volumio.org:7070/downloader-v1/track-device Apr 17 12:05:15 volumio volumio[838]: % Total % Received % Xferd Average Speed Time Time Time Current Apr 17 12:05:15 volumio volumio[838]: Dload Upload Total Spent Left Speed Apr 17 12:05:15 volumio volumio[838]: 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0curl: (7) Failed to connect to updates.volumio.org port 7070: Connection refused Apr 17 12:05:15 volumio volumio[838]: retrying in 5 seconds, trial 1 Apr 17 12:05:15 volumio volumio[838]: Volumio Calling Home Apr 17 12:05:25 volumio volumio[838]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=2.413&uuid=8a47768d7bd816bc76563e05eaf2e7d1" http://updates.volumio.org:7070/downloader-v1/track-device Apr 17 12:05:25 volumio volumio[838]: % Total % Received % Xferd Average Speed Time Time Time Current Apr 17 12:05:25 volumio volumio[838]: Dload Upload Total Spent Left Speed Apr 17 12:05:25 volumio volumio[838]: 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0curl: (7) Failed to connect to updates.volumio.org port 7070: Connection refused Apr 17 12:05:25 volumio volumio[838]: retrying in 5 seconds, trial 2 Apr 17 12:05:25 volumio volumio[838]: Volumio Calling Home Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Event: SessionActive { became_active_at: 1713355594469 } Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : SessionActive! Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Fetching autoplay context uri Apr 17 12:06:34 volumio volumio[838]: [SpotifyConnect] A connect session has begun Apr 17 12:06:34 volumio volumio[838]: info: Acquiring new spotify session Apr 17 12:06:34 volumio volumio[838]: info: CoreCommandRouter::volumioStop Apr 17 12:06:34 volumio volumio[838]: info: CoreStateMachine::stop Apr 17 12:06:34 volumio volumio[838]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 17 12:06:34 volumio volumio[838]: UNSET VOLATILE Apr 17 12:06:34 volumio volumio[838]: info: Checking Spotify Web API Apr 17 12:06:34 volumio volumio[838]: [SpotifyConnect] Vollibrespot Active Apr 17 12:06:34 volumio volumio[838]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 17 12:06:34 volumio volumio[838]: info: [1713355594477] ControllerSpotify::pushState Apr 17 12:06:34 volumio volumio[838]: info: CoreCommandRouter::servicePushState Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 316676641317143611463521087878295550744, audio_type: Track } } Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 316676641317143611463521087878295550744, audio_type: Track } } Apr 17 12:06:34 volumio volumio[838]: info: CoreStateMachine::syncState Apr 17 12:06:34 volumio volumio[838]: info: CoreStateMachine::pushState Apr 17 12:06:34 volumio volumio[838]: info: CoreStateMachine::getState Apr 17 12:06:34 volumio volumio[838]: info: CoreCommandRouter::volumioPushState Apr 17 12:06:34 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 17 12:06:34 volumio volumio[838]: info: interfaceApi::pushState Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:playlist:37i9dQZF1EQpj7X7UK8OOF"> Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Resolving uri "spotify:station:playlist:37i9dQZF1EQpj7X7UK8OOF" Apr 17 12:06:34 volumio volumio[838]: [SpotifyConnect] Device palyback is active! Apr 17 12:06:34 volumio volumio[838]: info: Pushing Favourites {"service":"spop","uri":"","favourite":false} Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQAn4SKV8A0Y-tiFWPMxXHWvgUyLf6FwDHVfFeYO_UfBFSEtFewiZ9Lztz5c8nUc7KP3E0NBgdcVPr4sd4tcHV4Fy8qef3qTRLIG5myq7hVTQp1w6Ar3vIlq5bihZ2fIzyPCsG1WKYA-p0bGgw7yQ98PTVNBqJM3hnv49bEGqFIX-VRH0Drs1iza2wUDDF8CMOB6UbdqMH3QtUOq6UKgQqUHQIPAPA", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Apr 17 12:06:34 volumio volumio[838]: info: New Spotify Access Token Received Apr 17 12:06:34 volumio volumio[838]: info: Initializing Spotify Web API Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Loading with Spotify URI Apr 17 12:06:34 volumio volumio[838]: info: Initliazing Spotify Browsing Facility Apr 17 12:06:34 volumio volumio[838]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 17 12:06:34 volumio volumio[838]: info: [1713355594531] CoreMusicLibrary::Adding element Spotify Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : (216560 ms) loaded Apr 17 12:06:34 volumio volumio[963]: [Vollibrespot] : Event: SinkActive Apr 17 12:06:34 volumio volumio[838]: [SpotifyConnect] Sink acquired Apr 17 12:06:34 volumio volumio[838]: info: Continuing Spotify Session Apr 17 12:06:34 volumio volumio[838]: info: Checking Spotify Web API Apr 17 12:06:34 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Apr 17 12:06:35 volumio volumio[963]: [Vollibrespot] : Resolved 50 tracks from <"spotify:playlist:37i9dQZF1EQpj7X7UK8OOF"> Apr 17 12:06:40 volumio volumio[963]: [Vollibrespot] : Event: Next { track_id: SpotifyId { id: 262982330054999880914555074906473516601, audio_type: Track } } Apr 17 12:06:40 volumio volumio[963]: [Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 316676641317143611463521087878295550744, audio_type: Track }, track_id: SpotifyId { id: 262982330054999880914555074906473516601, audio_type: Track } } Apr 17 12:06:41 volumio volumio[838]: [SpotifyConnect] Streets Apr 17 12:06:41 volumio volumio[963]: [Vollibrespot] : Event: SinkInactive Apr 17 12:06:41 volumio volumio[963]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 262982330054999880914555074906473516601, audio_type: Track } } Apr 17 12:06:41 volumio volumio[838]: [SpotifyConnect] Sink released Apr 17 12:06:41 volumio volumio[838]: info: [1713355601444] ControllerSpotify::pushState Apr 17 12:06:41 volumio volumio[838]: info: CoreCommandRouter::servicePushState Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::syncState Apr 17 12:06:41 volumio volumio[838]: info: CorePlayQueue::getTrack 0 Apr 17 12:06:41 volumio volumio[838]: info: STATE SERVICE {"status":"stop","service":"spop","title":"Streets","artist":"Kensington","album":"Rivals","albumart":"https://i.scdn.co/image/ab67616d0000b27301a61d26510e1a444e48db61","uri":"spotify:track:61ks9qYaFaMxUGpYsl1BCF","trackType":"spotify","seek":0,"duration":186,"samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","channels":2,"stream":false} Apr 17 12:06:41 volumio volumio[838]: info: CURRENT POSITION 0 Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::syncState stateService stop Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::syncState currentStatus play Apr 17 12:06:41 volumio volumio[838]: info: CURRENT POSITION 0 Apr 17 12:06:41 volumio volumio[838]: info: CURRENT POSITION 0 Apr 17 12:06:41 volumio volumio[838]: info: END OF QUEUE Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::pushEmptyState Apr 17 12:06:41 volumio volumio[838]: info: CoreCommandRouter::volumioPushState Apr 17 12:06:41 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 17 12:06:41 volumio volumio[838]: info: interfaceApi::pushState Apr 17 12:06:41 volumio volumio[963]: [Vollibrespot] : Loading with Spotify URI Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::stPlaybackTimer Apr 17 12:06:41 volumio volumio[838]: info: Pushing Favourites {"service":"mpd","uri":"","favourite":false} Apr 17 12:06:41 volumio volumio[963]: [Vollibrespot] : (185358 ms) loaded Apr 17 12:06:41 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Apr 17 12:06:41 volumio volumio[963]: [Vollibrespot] : Event: SinkActive Apr 17 12:06:41 volumio volumio[838]: [SpotifyConnect] Sink acquired Apr 17 12:06:41 volumio volumio[838]: info: Acquiring new spotify session Apr 17 12:06:41 volumio volumio[838]: info: CoreCommandRouter::volumioStop Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::stop Apr 17 12:06:41 volumio volumio[838]: info: CoreStateMachine::serviceStop Apr 17 12:06:41 volumio volumio[838]: info: Received STOP, but no service to execute it Apr 17 12:06:41 volumio volumio[838]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 17 12:06:41 volumio volumio[838]: TypeError: Cannot read property 'then' of undefined Apr 17 12:06:41 volumio volumio[838]: at SpotConnEvents.SpotConn.on (/data/plugins/music_service/spop/index.js:2119:31) Apr 17 12:06:41 volumio volumio[838]: at emitNone (events.js:106:13) Apr 17 12:06:41 volumio volumio[838]: at SpotConnEvents.emit (events.js:208:7) Apr 17 12:06:41 volumio volumio[838]: at SpotConnEvents.parseData (/data/plugins/music_service/spop/SpotConnController.js:89:16) Apr 17 12:06:41 volumio volumio[838]: at Socket.SpotConnEvents._udpsource.on.msg (/data/plugins/music_service/spop/SpotConnController.js:15:12) Apr 17 12:06:41 volumio volumio[838]: at emitTwo (events.js:126:13) Apr 17 12:06:41 volumio volumio[838]: at Socket.emit (events.js:214:7) Apr 17 12:06:41 volumio volumio[838]: at UDP.onMessage [as onmessage] (dgram.js:659:8) Apr 17 12:06:41 volumio volumio[838]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 17 12:06:42 volumio sudo[1768]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-17 12:05 Apr 17 12:06:42 volumio sudo[1768]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 8 (jessie)" NAME="Raspbian GNU/Linux" VERSION_ID="8" VERSION="8 (jessie)" ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="d0d14b37ffe8e45861e4e0b9816241fbafb4eb91" VOLUMIO_FE_VERSION="81c7100e9c7342b16fc9e0ca5908a26771e08c4f" VOLUMIO_BE_VERSION="645f0e55945bdd625a662a1ee21ba0dfb11bd73e" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Jun 21 01:30:10 CEST 2018" VOLUMIO_VERSION="2.413" VOLUMIO_HARDWARE="pi"