-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Sat 2026-02-07 13:17:52 GMT. -- Feb 07 13:16:15 volumio autossh[2632]: starting ssh (count 10) Feb 07 13:16:15 volumio autossh[2632]: ssh child pid is 2983 Feb 07 13:16:15 volumio volumiossh-tunnel[2630]: ssh: connect to host eu7.myvolumio.org port 2222: Connection refused Feb 07 13:16:15 volumio autossh[2632]: ssh exited with error status 255; restarting ssh Feb 07 13:16:47 volumio autossh[2632]: starting ssh (count 11) Feb 07 13:16:47 volumio autossh[2632]: ssh child pid is 3072 Feb 07 13:17:06 volumio volumio[1012]: info: Tunnel connection is inactive, restarting it Feb 07 13:17:06 volumio volumio[1012]: info: Starting Tunnel 1 Feb 07 13:17:06 volumio volumio[1012]: info: Starting Tunnel Connection Checker Feb 07 13:17:06 volumio sudo[3112]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart sshtunnel.service Feb 07 13:17:06 volumio sudo[3112]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 07 13:17:06 volumio autossh[2632]: received signal to exit (15) Feb 07 13:17:06 volumio systemd[1]: Stopping MyVolumio SSH Tunnel... Feb 07 13:17:06 volumio systemd[1]: sshtunnel.service: Main process exited, code=killed, status=15/TERM Feb 07 13:17:06 volumio systemd[1]: sshtunnel.service: Succeeded. Feb 07 13:17:06 volumio volumio[1012]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 07 13:17:06 volumio systemd[1]: Stopped MyVolumio SSH Tunnel. Feb 07 13:17:06 volumio volumio[1012]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Feb 07 13:17:06 volumio systemd[1]: Started MyVolumio SSH Tunnel. Feb 07 13:17:06 volumio sudo[3112]: pam_unix(sudo:session): session closed for user root Feb 07 13:17:06 volumio volumio[1012]: info: Remote SSH Started Feb 07 13:17:06 volumio autossh[3116]: port set to 0, monitoring disabled Feb 07 13:17:06 volumio autossh[3116]: starting ssh (count 1) Feb 07 13:17:06 volumio autossh[3116]: ssh child pid is 3119 Feb 07 13:17:06 volumio volumio[1012]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Feb 07 13:17:06 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:06 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:08 volumio volumiossh-tunnel[3114]: Warning: Permanently added '[eu7.myvolumio.org]:2222,[167.71.43.69]:2222' (RSA) to the list of known hosts. Feb 07 13:17:23 volumio volumio[1619]: [Vollibrespot] : Connecting to AP "ap-gew1.spotify.com:443" Feb 07 13:17:23 volumio volumio[1619]: [Vollibrespot] : Could not connect to server: early eof Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:33 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:33 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:33 volumio volumio[1012]: info: Currently active: mpd Feb 07 13:17:33 volumio volumio[1012]: info: Stopping currently active service Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioStop Feb 07 13:17:33 volumio volumio[1012]: info: CoreStateMachine::stop Feb 07 13:17:33 volumio volumio[1012]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 07 13:17:33 volumio volumio[1012]: info: TidalConnect Active Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:33 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:33 volumio volumio[1012]: info: Currently active: mpd Feb 07 13:17:33 volumio volumio[1012]: info: Setting Volatile state to tidalconnect Feb 07 13:17:33 volumio volumio[1012]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:33 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:33 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:33 volumio volumio[1012]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:33 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:33 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:33 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:33 volumio volumio[1012]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Feb 07 13:17:33 volumio volumio[1012]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.QRarN9k5cxQLq1ZX4VUFbNcMGcT2.a04c93f4434beaf68c97b9e464454633.state.status' Feb 07 13:17:34 volumio vtcs[1643]: [2026-02-07 13:17:34.053] [tisoc] [warning] [PlaybackControllerImpl.cpp:520] Illegal state:1 Feb 07 13:17:34 volumio volumio[1012]: info: Pushing metadata Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:34 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:34 volumio volumio[1012]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:34 volumio volumio[1012]: info: CorePlayQueue::getTrack 0 Feb 07 13:17:34 volumio volumio[1012]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:34 volumio volumio[1012]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.QRarN9k5cxQLq1ZX4VUFbNcMGcT2.a04c93f4434beaf68c97b9e464454633.state.status' Feb 07 13:17:34 volumio volumio[1012]: error: Cannot update RT Device info: Error: Reference.set failed: First argument contains undefined in property 'user_devices.QRarN9k5cxQLq1ZX4VUFbNcMGcT2.a04c93f4434beaf68c97b9e464454633.state.status' Feb 07 13:17:34 volumio volumio[1012]: info: Pushing metadata Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:34 volumio vtcs[1643]: [close:85] Entering Feb 07 13:17:34 volumio vtcs[1643]: [close:100] Exiting Feb 07 13:17:34 volumio vtcs[1643]: [open:50] Opening with sample rate: 44100, type: 3 Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::servicePushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreStateMachine::pushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioPushState Feb 07 13:17:34 volumio volumio[1012]: info: CoreCommandRouter::volumioGetState Feb 07 13:17:36 volumio vtcs[1643]: [2026-02-07 13:17:36] [info] asio async_shutdown error: asio.misc:2 (End of file) Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Connecting to AP "ap-gew1.spotify.com:443" Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Authenticated as "31if4kh24j6xh2zc77hmdfvjr3ri" ! Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Using alsa sink Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Metadata pipe established Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Country: "GB" Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Event: Volume { volume_to_mixer: 7167 } Feb 07 13:17:51 volumio volumio[1012]: [SpotifyConnect] Volume Spotify: 10.936140993362326 Volumio: 11 Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Fetching autoplay context uri Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Event: SessionActive { became_active_at: 1770470271725 } Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : SessionActive! Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Event: PlaybackStarted { track_id: SpotifyId { id: 295440647491204031057295741924957154062, audio_type: Track } } Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Event: PlaybackLoading { track_id: SpotifyId { id: 295440647491204031057295741924957154062, audio_type: Track } } Feb 07 13:17:51 volumio volumio[1012]: [SpotifyConnect] A connect session has begun Feb 07 13:17:51 volumio volumio[1012]: info: Acquiring new spotify session Feb 07 13:17:51 volumio volumio[1012]: info: CoreCommandRouter::volumioStop Feb 07 13:17:51 volumio volumio[1012]: info: CoreStateMachine::stop Feb 07 13:17:51 volumio volumio[1012]: info: CoreStateMachine::serviceStop Feb 07 13:17:51 volumio volumio[1012]: info: CoreCommandRouter::serviceStop Feb 07 13:17:51 volumio vtcs[1643]: [close:85] Entering Feb 07 13:17:51 volumio vtcs[1643]: [close:100] Exiting Feb 07 13:17:51 volumio volumio[1012]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 07 13:17:51 volumio volumio[1012]: TypeError: Cannot read property 'then' of undefined Feb 07 13:17:51 volumio volumio[1012]: at SpotConnEvents. (/data/plugins/music_service/spop/index.js:2132:31) Feb 07 13:17:51 volumio volumio[1012]: at SpotConnEvents.emit (events.js:315:20) Feb 07 13:17:51 volumio volumio[1012]: at SpotConnEvents.parseData (/data/plugins/music_service/spop/SpotConnController.js:92:16) Feb 07 13:17:51 volumio volumio[1012]: at Socket. (/data/plugins/music_service/spop/SpotConnController.js:15:12) Feb 07 13:17:51 volumio volumio[1012]: at Socket.emit (events.js:315:20) Feb 07 13:17:51 volumio volumio[1012]: at UDP.onMessage [as onmessage] (dgram.js:919:8) Feb 07 13:17:51 volumio volumio[1012]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Autoplay uri resolved to <"spotify:station:track:6Lphpr9Z6H282Sguw0dUWa"> Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Resolving uri "spotify:station:track:6Lphpr9Z6H282Sguw0dUWa" Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Event: GotToken { token: Token { access_token: "BQCzaCNz0bnMUpTO-MpH5pTyLDixWGUm9F7BPuPW84hZGQZdJCCZOUJpgUG0optwvUCK75_JgwU6GR_Xrrxc8q1JYmsQ_Kv3oCbs2Bold0iKGGLUyItugxkEZbMoUhPnwtMnSTIjPMxpaK-UObUPWNjF7tUcbhokRnnrkB_6DQkOt1MM_moA69-HB4NqDn226A6k3JsuqprqsA-Jhtj64CEOAXwWebB812Q9X9EKKRt5r-sKwcCwP2Sq1ckrMdSY3JF46GSNyA", expires_in: 3600, token_type: "Bearer", scope: ["streaming", "user-modify-playback-state", "user-read-playback-state", "user-read-currently-playing", "user-read-private"] } } Feb 07 13:17:51 volumio volumio[1619]: [Vollibrespot] : Loading with Spotify URI Feb 07 13:17:52 volumio sudo[3279]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-02-07 13:16 Feb 07 13:17:52 volumio sudo[3279]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 07 13:17:52 volumio volumio[1619]: [Vollibrespot] : Resolved 50 tracks from <"spotify:track:6Lphpr9Z6H282Sguw0dUWa"> 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="b43c85cc0006d3f1efecba101311ec96e334d1fd" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu 11 Dec 2025 05:43:24 PM CET" VOLUMIO_VERSION="3.886" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="15d0241b0cd805792809f3ddf4a0fc4e"