-- Logs begin at Thu 2019-02-14 10:11:59 GMT, end at Tue 2024-09-03 08:59:33 BST. -- Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioGetState Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrack 0 Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioGetState Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrack 0 Sep 03 08:59:22 volumio volumio[928]: info: Currently active: mpd Sep 03 08:59:22 volumio volumio[928]: info: Stopping currently active service Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioStop Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::stop Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::updateTrackBlock Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrackBlock Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::stPlaybackTimer Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrack 0 Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::serviceStop Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrack 0 Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::serviceStop Sep 03 08:59:22 volumio volumio[928]: info: ControllerMpd::stop Sep 03 08:59:22 volumio volumio[928]: verbose: ControllerMpd::sendMpdCommand stop Sep 03 08:59:22 volumio volumio[928]: info: Sep 03 08:59:22 volumio volumio[928]: ---------------------------- MPD announces state update: player Sep 03 08:59:22 volumio volumio[928]: info: sendMpdCommand stop took 22 milliseconds Sep 03 08:59:22 volumio volumio[928]: info: ControllerMpd::getState Sep 03 08:59:22 volumio volumio[928]: verbose: ControllerMpd::sendMpdCommand status Sep 03 08:59:22 volumio volumio[928]: info: TidalConnect Active Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioGetState Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrack 0 Sep 03 08:59:22 volumio volumio[928]: info: Currently active: mpd Sep 03 08:59:22 volumio volumio[928]: info: Setting Volatile state to tidalconnect Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::setConsumeUpdateService undefined Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:22 volumio volumio[928]: info: sendMpdCommand status took 17 milliseconds Sep 03 08:59:22 volumio volumio[928]: verbose: ControllerMpd::parseState Sep 03 08:59:22 volumio volumio[928]: verbose: ControllerMpd::sendMpdCommand playlistinfo Sep 03 08:59:22 volumio volumio[928]: error: Upnp client error: Error: This socket has been ended by the other party Sep 03 08:59:22 volumio volumio[928]: info: sendMpdCommand playlistinfo took 2 milliseconds Sep 03 08:59:22 volumio volumio[928]: verbose: ControllerMpd::parseTrackInfo Sep 03 08:59:22 volumio volumio[928]: info: ControllerMpd::pushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:22 volumio volumio[928]: info: CorePlayQueue::getTrack 0 Sep 03 08:59:22 volumio volumio[928]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"水の星へ愛をこめて / with 寺井尚子","artist":"森口博子","album":"GUNDAM SONG COVERS (Digital Edition)","uri":"USB/4323-1EC2/ANIME/森口博子/GUNDAM SONG COVERS (Digital Edition)/01-水の星へ愛をこめて _ with 寺井尚子.flac","trackType":"flac"} Sep 03 08:59:22 volumio volumio[928]: verbose: CURRENT POSITION 0 Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::syncState stateService stop Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::syncState currentStatus pause Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:22 volumio volumio[928]: info: ------------------------------ 31ms Sep 03 08:59:22 volumio vtcs[2378]: [2024-09-03 08:59:22.997] [tisoc] [warning] [PlaybackControllerImpl.cpp:472] Illegal state:1 Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:22 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 03 08:59:22 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:23 volumio volumio[928]: info: Pushing metadata Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:23 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:23 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:23 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:23 volumio volumio[928]: info: Pushing metadata Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:23 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::servicePushState Sep 03 08:59:23 volumio volumio[928]: info: CoreStateMachine::pushState Sep 03 08:59:23 volumio volumio[928]: info: CoreCommandRouter::volumioPushState Sep 03 08:59:26 volumio vtcs[2378]: [2024-09-03 08:59:26] [info] asio async_shutdown error: asio.misc:2 (End of file) Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Connecting to AP "ap2-gew1.spotify.com:443" Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Authenticated as "314i5t62yg5g6u76mjmh6mv5uota" ! Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Using alsa sink Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Metadata pipe established Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Country: "HK" Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: Volume { volume_to_mixer: 50175 } Sep 03 08:59:32 volumio volumio[928]: [SpotifyConnect] Volume Spotify: 76.5621423666743 Volumio: 77 Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Fetching autoplay context uri Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: SessionActive { became_active_at: 1725350372696 } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : SessionActive! Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 22419726958383474722450040677537556705, audio_type: Track } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 22419726958383474722450040677537556705, audio_type: Track } } Sep 03 08:59:32 volumio volumio[928]: [SpotifyConnect] A connect session has begun Sep 03 08:59:32 volumio volumio[928]: info: Acquiring new spotify session Sep 03 08:59:32 volumio volumio[928]: info: CoreCommandRouter::volumioStop Sep 03 08:59:32 volumio volumio[928]: info: CoreStateMachine::stop Sep 03 08:59:32 volumio volumio[928]: info: CoreStateMachine::serviceStop Sep 03 08:59:32 volumio volumio[928]: info: CoreCommandRouter::serviceStop Sep 03 08:59:32 volumio volumio[928]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 03 08:59:32 volumio volumio[928]: TypeError: Cannot read property 'then' of undefined Sep 03 08:59:32 volumio volumio[928]: at SpotConnEvents. (/data/plugins/music_service/spop/index.js:2132:31) Sep 03 08:59:32 volumio volumio[928]: at SpotConnEvents.emit (events.js:315:20) Sep 03 08:59:32 volumio volumio[928]: at SpotConnEvents.parseData (/data/plugins/music_service/spop/SpotConnController.js:92:16) Sep 03 08:59:32 volumio volumio[928]: at Socket. (/data/plugins/music_service/spop/SpotConnController.js:15:12) Sep 03 08:59:32 volumio volumio[928]: at Socket.emit (events.js:315:20) Sep 03 08:59:32 volumio volumio[928]: at UDP.onMessage [as onmessage] (dgram.js:919:8) Sep 03 08:59:32 volumio volumio[928]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 03 08:59:32 volumio vtcs[2378]: [2024-09-03 08:59:32.704] [tisoc] [warning] [PlaybackControllerImpl.cpp:472] Illegal state:0 Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:album:2YzyG2hSiQq3xnZVeNgieb"> Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Resolving uri "spotify:station:album:2YzyG2hSiQq3xnZVeNgieb" Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQCLJuwlD0xI1obRsoKzzoXGQbys9SyjMiaRcc6J6Umr6eth0khphpai4LVlWnkTA-pVt-xKzy_STEGtwW7ExkS_bfR940px4ZP04gGJoMbTFvjURSJJ_GwiCLdbuh1x7YdZvpkKZbxjbbhiwf2uxe85TdCF1a9CQ5WHXUEc7TgdkDzeFjTlyPX2Ixt1EhrK15Z6wcfF_50U4AzX1vfVYM7ZkYskB355n5qzSQ", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-read-playback-state", "user-modify-playback-state", "user-read-currently-playing", "user-read-private"] } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Loading with Spotify URI Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : channel error: 2 0 Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Unable to load encrypted file. Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Unable to load Sep 03 08:59:32 volumio volumio[6823]: Skipping to next track Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: Next { track_id: SpotifyId { id: 263481029306916327784171964214737238019, audio_type: Track } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 22419726958383474722450040677537556705, audio_type: Track }, track_id: SpotifyId { id: 263481029306916327784171964214737238019, audio_type: Track } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Loading with Spotify URI Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : channel error: 2 0 Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Unable to load encrypted file. Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Unable to load Sep 03 08:59:32 volumio volumio[6823]: Skipping to next track Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 263481029306916327784171964214737238019, audio_type: Track } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: Next { track_id: SpotifyId { id: 314434772290051122787484859088378498372, audio_type: Track } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Event: TrackChanged { old_track_id: SpotifyId { id: 263481029306916327784171964214737238019, audio_type: Track }, track_id: SpotifyId { id: 314434772290051122787484859088378498372, audio_type: Track } } Sep 03 08:59:32 volumio volumio[6823]: [Vollibrespot] : Loading with Spotify URI Sep 03 08:59:33 volumio sudo[9670]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-03 08:58 Sep 03 08:59:33 volumio sudo[9670]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 03 08:59:33 volumio volumio[6823]: [Vollibrespot] : channel error: 2 0 Sep 03 08:59:33 volumio volumio[6823]: [Vollibrespot] : Unable to load encrypted file. Sep 03 08:59:33 volumio volumio[6823]: [Vollibrespot] : Unable to load Sep 03 08:59:33 volumio volumio[6823]: Skipping to next track 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="b1c3cf61c2a0027c66bab1eb0a3795f80c1f2e95" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="e3eb3ee5b16063502f3a1735e11a28cfe54a0f46" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sun 25 Jun 2023 07:20:58 PM CEST" VOLUMIO_VERSION="3.512" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="946a42b62509f37b5e7e2d86a2932a62"