-- Logs begin at Wed 2024-09-04 19:40:26 UTC, end at Thu 2024-09-05 15:54:06 UTC. -- Sep 05 15:53:04 volumio vtcs[1463]: [2024-09-05 15:53:04.595] [tisoc] [warning] [PlaybackControllerImpl.cpp:214] Ignore play request because playback state is not STARTED. state_=2, playstate_=1, player_state_=0 Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: Pushing metadata Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: Pushing metadata Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:04 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::servicePushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:05 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:53:19 volumio volumio[1084]: info: CorePlayQueue::getTrack 3 Sep 05 15:53:19 volumio volumio[1084]: info: CorePlayQueue::getTrack 4 Sep 05 15:53:19 volumio volumio[1084]: info: Prefetching next song Sep 05 15:53:19 volumio volumio[1084]: info: [1725551599778] ControllerTidal::prefetch Sep 05 15:53:19 volumio volumio[1084]: info: Getting stream with soundQuality HI_RES Sep 05 15:53:19 volumio volumio[1084]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/3268248&soundQuality=HI_RES" Sep 05 15:53:19 volumio volumio[1084]: info: Sep 05 15:53:19 volumio volumio[1084]: ---------------------------- MPD announces system playlist update Sep 05 15:53:19 volumio volumio[1084]: info: Ignoring MPD Status Update Sep 05 15:53:19 volumio volumio[1084]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/3268248&soundQuality=HI_RES" took 2 milliseconds Sep 05 15:53:19 volumio volumio[1084]: info: CoreStateMachine::setConsumeUpdateService mpd Sep 05 15:53:19 volumio volumio[1084]: verbose: ControllerMpd::sendMpdCommand consume 1 Sep 05 15:53:19 volumio volumio[1084]: info: ------------------------------ 3ms Sep 05 15:53:19 volumio volumio[1084]: info: sendMpdCommand consume 1 took 2 milliseconds Sep 05 15:53:24 volumio volumio[1084]: info: CoreStateMachine::startPlaybackTimer Sep 05 15:53:24 volumio volumio[1084]: info: CorePlayQueue::getTrack 4 Sep 05 15:53:24 volumio volumio[1084]: info: CoreStateMachine::pushState Sep 05 15:53:24 volumio volumio[1084]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 05 15:53:24 volumio volumio[1084]: info: CoreCommandRouter::volumioPushState Sep 05 15:54:05 volumio volumio[1416]: [Vollibrespot] : Connecting to AP "ap2-gew4.spotify.com:443" Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Authenticated as "21ojxt7mi4wwjjo6r6ecu2rgq" ! Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Using alsa sink Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Metadata pipe established Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Country: "PL" Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Event: Volume { volume_to_mixer: 65535 } Sep 05 15:54:06 volumio volumio[1084]: [SpotifyConnect] Volume Spotify: 100 Volumio: 100 Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Fetching autoplay context uri Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Event: SessionActive { became_active_at: 1725551645239 } Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : SessionActive! Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 139562546789365919944646864065301812558, audio_type: Track } } Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 139562546789365919944646864065301812558, audio_type: Track } } Sep 05 15:54:06 volumio volumio[1084]: [SpotifyConnect] A connect session has begun Sep 05 15:54:06 volumio volumio[1084]: info: Acquiring new spotify session Sep 05 15:54:06 volumio volumio[1084]: info: CoreCommandRouter::volumioStop Sep 05 15:54:06 volumio volumio[1084]: info: CoreStateMachine::stop Sep 05 15:54:06 volumio volumio[1084]: info: CoreStateMachine::serviceStop Sep 05 15:54:06 volumio volumio[1084]: info: CoreCommandRouter::serviceStop Sep 05 15:54:06 volumio volumio[1084]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 05 15:54:06 volumio volumio[1084]: TypeError: Cannot read property 'then' of undefined Sep 05 15:54:06 volumio volumio[1084]: at SpotConnEvents. (/data/plugins/music_service/spop/index.js:2132:31) Sep 05 15:54:06 volumio volumio[1084]: at SpotConnEvents.emit (events.js:315:20) Sep 05 15:54:06 volumio volumio[1084]: at SpotConnEvents.parseData (/data/plugins/music_service/spop/SpotConnController.js:92:16) Sep 05 15:54:06 volumio volumio[1084]: at Socket. (/data/plugins/music_service/spop/SpotConnController.js:15:12) Sep 05 15:54:06 volumio volumio[1084]: at Socket.emit (events.js:315:20) Sep 05 15:54:06 volumio volumio[1084]: at UDP.onMessage [as onmessage] (dgram.js:919:8) Sep 05 15:54:06 volumio volumio[1084]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 05 15:54:06 volumio vtcs[1463]: [2024-09-05 15:54:06] [info] asio async_shutdown error: asio.misc:2 (End of file) Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:2M9E6uD6mYqRFTjqcaVzzC"> Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Resolving uri "spotify:station:album:2M9E6uD6mYqRFTjqcaVzzC" Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQAVFCNCWTiHta4gurEIHQRbqhhNs2BL84ObGU4KYI5E1xMIpJBaflFZMPSZyRlsqNNVw7qcTQcyZyfJXfzb3EbwO1CFzFb4PvqY9a5PFU-VE14CZguc5U_Zznv-KIiQ0FYGq67YveBE1mb3Aya62iHe_wdDwFuWLO2dI1sgu4YZ86kvRXrPvMiEtQ-1SoyHurZgVwM1ZsseEgsHTMoQ9RFa2WzZ7wHWqA", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Sep 05 15:54:06 volumio volumio[1416]: [Vollibrespot] : Loading with Spotify URI Sep 05 15:54:06 volumio sudo[2500]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-05 15:53 Sep 05 15:54:06 volumio sudo[2500]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"