-- Logs begin at Thu 2019-02-14 02:11:58 PST, end at Wed 2025-06-11 20:16:37 PDT. -- Jun 11 20:15:04 rpi5volumio volumio[1079]: info: Enabling plugin now_playing Jun 11 20:15:04 rpi5volumio volumio[1079]: info: Loading plugin "now_playing"... Jun 11 20:15:04 rpi5volumio volumio[1079]: error: !!!! WARNING !!!! Jun 11 20:15:04 rpi5volumio volumio[1079]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Jun 11 20:15:04 rpi5volumio volumio[1079]: Require stack: Jun 11 20:15:04 rpi5volumio volumio[1079]: - /volumio/app/pluginmanager.js Jun 11 20:15:04 rpi5volumio volumio[1079]: - /volumio/app/index.js Jun 11 20:15:04 rpi5volumio volumio[1079]: - /volumio/index.js Jun 11 20:15:04 rpi5volumio volumio[1079]: error: Stack trace: Error: Cannot find module '/data/plugins//user_interface/now_playing/./dist/index.js' Jun 11 20:15:04 rpi5volumio volumio[1079]: Require stack: Jun 11 20:15:04 rpi5volumio volumio[1079]: - /volumio/app/pluginmanager.js Jun 11 20:15:04 rpi5volumio volumio[1079]: - /volumio/app/index.js Jun 11 20:15:04 rpi5volumio volumio[1079]: - /volumio/index.js Jun 11 20:15:04 rpi5volumio volumio[1079]: at Function.Module._resolveFilename (internal/modules/cjs/loader.js:880:15) Jun 11 20:15:04 rpi5volumio volumio[1079]: at Function.Module._load (internal/modules/cjs/loader.js:725:27) Jun 11 20:15:04 rpi5volumio volumio[1079]: at Module.require (internal/modules/cjs/loader.js:952:19) Jun 11 20:15:04 rpi5volumio volumio[1079]: at require (internal/modules/cjs/helpers.js:88:18) Jun 11 20:15:04 rpi5volumio volumio[1079]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Jun 11 20:15:04 rpi5volumio volumio[1079]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jun 11 20:15:04 rpi5volumio volumio[1079]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jun 11 20:15:04 rpi5volumio volumio[1079]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Jun 11 20:15:04 rpi5volumio volumio[1079]: error: !!!! WARNING !!!! Jun 11 20:15:04 rpi5volumio volumio[1079]: info: Done. Jun 11 20:15:20 rpi5volumio volumio[1079]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 20:15:22 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to 192.168.1.150 from 192.168.1.229 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:139.0) Gecko/20100101 Firefox/139.0 Engine version: 3 Transport: polling Total Clients: 6 Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetVisibleSources Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 11 20:15:22 rpi5volumio volumio[1079]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jun 11 20:15:22 rpi5volumio volumio[1079]: info: Received Get System Info Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 20:15:22 rpi5volumio volumio[1079]: info: Discovery: Getting this device information Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:22 rpi5volumio volumio[1079]: info: Listing playlists Jun 11 20:15:22 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 11 20:15:44 rpi5volumio volumio[1079]: info: Received OAUTH Data Jun 11 20:15:44 rpi5volumio volumio[1079]: info: Executing Spotify Oauth Login Jun 11 20:15:44 rpi5volumio volumio[1079]: info: Saving Spotify Refresh Token Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: BQCD3otlQiu8nvN1px4sjUTAeOwm3OsUlE_zQnhc5EBJOSzBgbm0Ro98I0XMuVy3tHt0ixAZbmJBHzidfyUb8d0K3UrD9nQPmLejPmiCkvzsyrjtDXZGv9dJ8wwIG8dLaK9MpVFnUQwZOgfhEncxteyAs5MEUlWDWQ0WpCMv9lDo0uwGikIl43sMYbDiew-mRk0DM5RCZ0-hb_2eORSdkyU4hpqYxV6SWzPNkWx4Z-Scq9qFi8z5gIrWdmuo6lG0glZ0TewXeiOqcKGGlAcuUcc-Gyp7mj1o_kDjmMgmxvuoync Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 11 20:15:45 rpi5volumio volumio[1079]: info: New Spotify access token = BQCD3otlQiu8nvN1px4sjUTAeOwm3OsUlE_zQnhc5EBJOSzBgbm0Ro98I0XMuVy3tHt0ixAZbmJBHzidfyUb8d0K3UrD9nQPmLejPmiCkvzsyrjtDXZGv9dJ8wwIG8dLaK9MpVFnUQwZOgfhEncxteyAs5MEUlWDWQ0WpCMv9lDo0uwGikIl43sMYbDiew-mRk0DM5RCZ0-hb_2eORSdkyU4hpqYxV6SWzPNkWx4Z-Scq9qFi8z5gIrWdmuo6lG0glZ0TewXeiOqcKGGlAcuUcc-Gyp7mj1o_kDjmMgmxvuoync Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 11 20:15:45 rpi5volumio sudo[3828]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jun 11 20:15:45 rpi5volumio sudo[3828]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:15:45 rpi5volumio sudo[3828]: pam_unix(sudo:session): session closed for user root Jun 11 20:15:45 rpi5volumio sudo[3831]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jun 11 20:15:45 rpi5volumio sudo[3831]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:15:45 rpi5volumio sudo[3831]: pam_unix(sudo:session): session closed for user root Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: User informations: {"country":"US","display_name":"22wbf3d2bwtkml5jrta5crf2a","email":"sonnythaitran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/22wbf3d2bwtkml5jrta5crf2a"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/22wbf3d2bwtkml5jrta5crf2a","id":"22wbf3d2bwtkml5jrta5crf2a","images":[],"product":"premium","type":"user","uri":"spotify:user:22wbf3d2bwtkml5jrta5crf2a"} Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Creating Spotify config file Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Spotify config file written Jun 11 20:15:45 rpi5volumio sudo[3834]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 11 20:15:45 rpi5volumio sudo[3834]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:15:45 rpi5volumio systemd[1]: Stopping go-librespot Daemon... Jun 11 20:15:45 rpi5volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 11 20:15:45 rpi5volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jun 11 20:15:45 rpi5volumio systemd[1]: Stopped go-librespot Daemon. Jun 11 20:15:45 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 11 20:15:45 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket closed Jun 11 20:15:45 rpi5volumio systemd[1]: Started go-librespot Daemon. Jun 11 20:15:45 rpi5volumio go-librespot[3836]: go-librespot daemon starting... Jun 11 20:15:45 rpi5volumio sudo[3834]: pam_unix(sudo:session): session closed for user root Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=info msg="running go-librespot 0.2.0" Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=debug msg="app state loaded" Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=debug msg="stored credentials not found" Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 11 20:15:45 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to 192.168.1.150 from 192.168.1.229 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:139.0) Gecko/20100101 Firefox/139.0 Engine version: 3 Transport: polling Total Clients: 6 Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetVisibleSources Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Received Get System Info Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Discovery: Getting this device information Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Listing playlists Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gae2.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=info msg="zeroconf server listening on port 33155" Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: BQA2SxMFyHm74dOkVVaF8BsY8pdh03VsYpHMMNTkpELYZLjxRT11s7C_kuxDhELQFORAuCYcXm5TPDjT7qA4Tll_xRnt9HyglVK8fdUi971zxBMiv_7sbyqUqCuNZo5ZONtorvmjkMuVaM7dHHld39bm2LaLrvHLOYPkIkYkXp1rkwFEJMBvim_o4sEkkpkh5SecP8a9RxZsBg9q7C2hGoThwdTlHqBUhbB9TgN6m1Ee0jfkSRMpwsJQKP6aR5yCOVL26kSJtUDEe4MoCnVJRCld06e3ZYOV7K0V39jNssa3f9E Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jun 11 20:15:45 rpi5volumio volumio[1079]: info: New Spotify access token = BQA2SxMFyHm74dOkVVaF8BsY8pdh03VsYpHMMNTkpELYZLjxRT11s7C_kuxDhELQFORAuCYcXm5TPDjT7qA4Tll_xRnt9HyglVK8fdUi971zxBMiv_7sbyqUqCuNZo5ZONtorvmjkMuVaM7dHHld39bm2LaLrvHLOYPkIkYkXp1rkwFEJMBvim_o4sEkkpkh5SecP8a9RxZsBg9q7C2hGoThwdTlHqBUhbB9TgN6m1Ee0jfkSRMpwsJQKP6aR5yCOVL26kSJtUDEe4MoCnVJRCld06e3ZYOV7K0V39jNssa3f9E Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Spotify credentials grant success - running version from March 24, 2019 Jun 11 20:15:45 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:45-07:00" level=debug msg="obtained new client token: AAB3rbUw6dnGV70Bu1srAn12mqHyeRM3k2QT4tK8euvYOMbSr7HIwEF25Hhv3VYqrzVBNQYi9DkhiiQC7geWvkAed7VgTR+lRaeE07zUZkMJDP0eLZYWmCnDm0pm0gU7KbKEOTVj/3mUOByDmLt8NyPvUulpYvsw5Zd8vNh32fD7OguCISoRYLPE/zDsnc96xujjRX6ZfPxyTkaiw89X9GpiDl9xJUSjhxoea3wnC+bYab7jSZc3dQg5ow==" Jun 11 20:15:45 rpi5volumio volumio[1079]: SPOTIFY: User informations: {"country":"US","display_name":"22wbf3d2bwtkml5jrta5crf2a","email":"sonnythaitran@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/22wbf3d2bwtkml5jrta5crf2a"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/22wbf3d2bwtkml5jrta5crf2a","id":"22wbf3d2bwtkml5jrta5crf2a","images":[],"product":"premium","type":"user","uri":"spotify:user:22wbf3d2bwtkml5jrta5crf2a"} Jun 11 20:15:45 rpi5volumio volumio[1079]: info: Spotify Successfully logged in Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jun 11 20:15:45 rpi5volumio volumio[1079]: info: [1749698145944] CoreMusicLibrary::Adding element Spotify Jun 11 20:15:45 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jun 11 20:15:45 rpi5volumio volumio[1079]: Cannot find translation for source YouTube Music Jun 11 20:15:45 rpi5volumio volumio[1079]: Cannot find translation for source YouTube2 Jun 11 20:15:45 rpi5volumio volumio[1079]: Cannot find translation for source Spotify Jun 11 20:15:45 rpi5volumio volumio[1079]: info: An error occurred while initializing Spotify Browsing facility: TypeError: Cannot read property 'broadcastMessage' of null Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="completed keyexchange" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="completed challenge" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=info msg="authenticated AP as 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=info msg="authenticated Login5 as 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="stored credentials for 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="initializing zeroconf session, username: 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="dealer connection opened" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=trace msg="starting accesspoint recv loop" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=trace msg="starting dealer recv loop" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=trace msg="received accesspoint ping" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=debug msg="received connection id: YzJiYWFkOWEtYzUwOS00ZTkzLTk1NzYtNjNhNTY2YWRhNTBlK2RlYWxlcit0Y3A6Ly8wYWNiZDlhZi5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArRDFFNUQwQ0E3OEJCMTg5QkQ4RDVGREVGNDdDMjg0NzQ5QzM1NkZDRDFBQjVFRDg1NEFEM0E5NTg1RjhENDJDMw==" Jun 11 20:15:46 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:46-07:00" level=trace msg="received accesspoint pong ack" Jun 11 20:15:47 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:47-07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 11 20:15:47 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:47-07:00" level=debug msg="update volume to 65535/65535" Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 11 20:15:47 rpi5volumio volumio[1079]: info: Received Get System Info Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 20:15:47 rpi5volumio volumio[1079]: info: Discovery: Getting this device information Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:47 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 20:15:48 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jun 11 20:15:48 rpi5volumio volumio[1079]: info: Received Get System Info Jun 11 20:15:48 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 20:15:48 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 20:15:48 rpi5volumio volumio[1079]: info: Discovery: Getting this device information Jun 11 20:15:48 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:48 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:48 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 20:15:48 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:48-07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 11 20:15:48 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:48-07:00" level=trace msg="emitting websocket event: volume" Jun 11 20:15:48 rpi5volumio volumio[1079]: info: Initializing connection to go-librespot Websocket Jun 11 20:15:48 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:48-07:00" level=debug msg="new websocket client" Jun 11 20:15:48 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket established Jun 11 20:15:48 rpi5volumio volumio[1079]: info: go-librespot daemon successfully initialized Jun 11 20:15:51 rpi5volumio volumio[1079]: info: Getting Spotify volume Jun 11 20:15:51 rpi5volumio volumio[1079]: info: Spotify volume: 100 Jun 11 20:15:51 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 11 20:15:51 rpi5volumio volumio[1079]: info: Initializing connection to go-librespot Websocket Jun 11 20:15:51 rpi5volumio go-librespot[3836]: time="2025-06-11T20:15:51-07:00" level=debug msg="new websocket client" Jun 11 20:15:51 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:51 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:51 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket established Jun 11 20:15:54 rpi5volumio volumio[1079]: info: Getting Spotify volume Jun 11 20:15:54 rpi5volumio volumio[1079]: info: Spotify volume: 100 Jun 11 20:15:54 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 11 20:15:54 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:15:54 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:15:55 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Jun 11 20:15:59 rpi5volumio volumio[1079]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jun 11 20:15:59 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jun 11 20:15:59 rpi5volumio volumio[1079]: info: Creating Spotify config file Jun 11 20:15:59 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:15:59 rpi5volumio volumio[1079]: info: Spotify config file written Jun 11 20:15:59 rpi5volumio sudo[3864]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 11 20:15:59 rpi5volumio sudo[3864]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:15:59 rpi5volumio systemd[1]: Stopping go-librespot Daemon... Jun 11 20:15:59 rpi5volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 11 20:15:59 rpi5volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jun 11 20:15:59 rpi5volumio systemd[1]: Stopped go-librespot Daemon. Jun 11 20:15:59 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 11 20:15:59 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jun 11 20:15:59 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket closed Jun 11 20:15:59 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket closed Jun 11 20:15:59 rpi5volumio systemd[1]: Started go-librespot Daemon. Jun 11 20:15:59 rpi5volumio go-librespot[3866]: go-librespot daemon starting... Jun 11 20:15:59 rpi5volumio sudo[3864]: pam_unix(sudo:session): session closed for user root Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=info msg="running go-librespot 0.2.0" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="app state loaded" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=info msg="zeroconf server listening on port 40849" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="obtained new client token: AACIIMMzWUgemtH/Kp1ITb5qQ309TJyKhqxXVOPL789Gkd20r66zvsMFCwve+trwNxzPHamssC8/7BmV2Ls0PDMAP8D+trsfQ0++dLE2O4Ed7VYidtvuEDCc0rP870YgbMSgoxinA5IXjA+c5d8XSP3BANU+bgduSIWqHmR8kB8cbZqBBGyWXBdLWZvSDAc8mTrBzwdSthp4y6hhbYMVBkLWD7mQgQBzzyBIbO8/8QaqwYiU/k3IAuRoaA==" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="completed keyexchange" Jun 11 20:15:59 rpi5volumio go-librespot[3866]: time="2025-06-11T20:15:59-07:00" level=debug msg="completed challenge" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=info msg="authenticated AP as 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=info msg="authenticated Login5 as 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="initializing zeroconf session, username: 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="dealer connection opened" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=trace msg="starting accesspoint recv loop" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=trace msg="starting dealer recv loop" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=trace msg="received accesspoint ping" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="received connection id: NzRiMmYyNDktNWY0MC00MTkyLThkMTYtNDc0NmU5NjA1MDE0K2RlYWxlcit0Y3A6Ly8wYWNiZDg0YS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArMTAzMjMwNTYxMEZBQjUwOUI1RjdGMDUyOUU5MDRBNUJEOTkwNjBDNjk1MjA3ODg3RTY3MTQzRjAyN0RDNDE4MA==" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=trace msg="received accesspoint pong ack" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 11 20:16:00 rpi5volumio go-librespot[3866]: time="2025-06-11T20:16:00-07:00" level=debug msg="update volume to 65535/65535" Jun 11 20:16:01 rpi5volumio volumio[1079]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Jun 11 20:16:01 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Jun 11 20:16:01 rpi5volumio volumio[1079]: info: Creating Spotify config file Jun 11 20:16:01 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:01 rpi5volumio volumio[1079]: info: Spotify config file written Jun 11 20:16:01 rpi5volumio sudo[3875]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jun 11 20:16:01 rpi5volumio sudo[3875]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:16:01 rpi5volumio systemd[1]: Stopping go-librespot Daemon... Jun 11 20:16:01 rpi5volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Jun 11 20:16:01 rpi5volumio systemd[1]: go-librespot-daemon.service: Succeeded. Jun 11 20:16:01 rpi5volumio systemd[1]: Stopped go-librespot Daemon. Jun 11 20:16:01 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 11 20:16:01 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jun 11 20:16:01 rpi5volumio systemd[1]: Started go-librespot Daemon. Jun 11 20:16:01 rpi5volumio go-librespot[3877]: go-librespot daemon starting... Jun 11 20:16:01 rpi5volumio sudo[3875]: pam_unix(sudo:session): session closed for user root Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=info msg="running go-librespot 0.2.0" Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=debug msg="app state loaded" Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=info msg="api server listening on 127.0.0.1:9879" Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Jun 11 20:16:01 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:01-07:00" level=info msg="zeroconf server listening on port 34293" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="obtained new client token: AAAQOulGyp5abQZvGCtDc+DvyttCSvQKwCKX0JId0Ls+027t3YWfi20apgqeYPbB6nW/l2L3TFZWButXlmAe8Zc37VeEHOuXZsbThUtM+5VhzFMGuYrSM/5HotE42nF+Ni4NOqHjatTCYAuBA/LsTtPqvYP6cx+/DXtA1Orndsh4xWkwtnrSwqI6Hzn7Il59P0DwXaQrExSkHNmxaUgLmX9cLxhBZyR/FThOpTLehNcKa5mG2QTsEVg=" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="connected to ap-guc3.spotify.com:4070" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="completed keyexchange" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="completed challenge" Jun 11 20:16:02 rpi5volumio volumio[1079]: info: Initializing connection to go-librespot Websocket Jun 11 20:16:02 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket established Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="new websocket client" Jun 11 20:16:02 rpi5volumio volumio[1079]: info: go-librespot daemon successfully initialized Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=info msg="authenticated AP as 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=info msg="authenticated Login5 as 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="initializing zeroconf session, username: 22wbf3d2bwtkml5jrta5crf2a" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="dealer connection opened" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=trace msg="starting accesspoint recv loop" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=trace msg="starting dealer recv loop" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=trace msg="received accesspoint ping" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=debug msg="received connection id: ZWE4M2E1MTQtY2ExNi00ZDJjLWJhOWUtZWY2ZWEwMTI0MjA3K2RlYWxlcit0Y3A6Ly8wYWNiZDg0YS5pcC5ndWMzLnNwb3RpZnkubmV0OjU3MDArQTE3OENDQ0RFRjBCNUJCNUVENDlERTMxMUNEMTA3RDhCMUFEQ0Y2RjJFNTM2REQ4MzVCM0YzNzI5MTVFM0ZERA==" Jun 11 20:16:02 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:02-07:00" level=trace msg="received accesspoint pong ack" Jun 11 20:16:03 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:03-07:00" level=debug msg="put connect state because NEW_DEVICE" Jun 11 20:16:03 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:03-07:00" level=debug msg="update volume to 65535/65535" Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jun 11 20:16:04 rpi5volumio volumio[1079]: error: Failed callmethod call: TypeError: Cannot read property 'broadcastMessage' of null Jun 11 20:16:04 rpi5volumio volumio[1079]: info: Received Get System Version Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 11 20:16:04 rpi5volumio volumio[1079]: info: Received Get System Info Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jun 11 20:16:04 rpi5volumio volumio[1079]: info: Discovery: Getting this device information Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jun 11 20:16:04 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:04-07:00" level=debug msg="put connect state because VOLUME_CHANGED" Jun 11 20:16:04 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:04-07:00" level=trace msg="emitting websocket event: volume" Jun 11 20:16:04 rpi5volumio volumio[1079]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Jun 11 20:16:04 rpi5volumio volumio[1079]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Jun 11 20:16:04 rpi5volumio volumio[1079]: info: Setting Volumio Volume from Spotify: 100 Jun 11 20:16:04 rpi5volumio volumio[1079]: info: VolumeController::SetAlsaVolume100 Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreStateMachine::pushState Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:16:04 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioPushState Jun 11 20:16:04 rpi5volumio volumio[1079]: info: go-librespot daemon successfully initialized Jun 11 20:16:05 rpi5volumio volumio[1079]: info: Getting Spotify volume Jun 11 20:16:05 rpi5volumio volumio[1079]: info: Spotify volume: 100 Jun 11 20:16:05 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 11 20:16:05 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:16:05 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:16:05 rpi5volumio volumio[1079]: info: Initializing connection to go-librespot Websocket Jun 11 20:16:05 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:05-07:00" level=debug msg="new websocket client" Jun 11 20:16:05 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket established Jun 11 20:16:07 rpi5volumio volumio[1079]: info: Initializing connection to go-librespot Websocket Jun 11 20:16:07 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:07-07:00" level=debug msg="new websocket client" Jun 11 20:16:07 rpi5volumio volumio[1079]: info: Connection to go-librespot Websocket established Jun 11 20:16:07 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:16:07 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:16:08 rpi5volumio volumio[1079]: info: Getting Spotify volume Jun 11 20:16:08 rpi5volumio volumio[1079]: info: Spotify volume: 100 Jun 11 20:16:08 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 11 20:16:08 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:16:08 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::getUIConfigOnPlugin Jun 11 20:16:10 rpi5volumio volumio[1079]: xcb_connection_has_error() returned true Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 11 20:16:10 rpi5volumio volumio[1079]: xcb_connection_has_error() returned true Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jun 11 20:16:10 rpi5volumio volumio[1079]: info: Getting Spotify volume Jun 11 20:16:10 rpi5volumio volumio[1079]: info: Spotify volume: 100 Jun 11 20:16:10 rpi5volumio volumio[1079]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CoreCommandRouter::volumioGetState Jun 11 20:16:10 rpi5volumio volumio[1079]: info: CorePlayQueue::getTrack 0 Jun 11 20:16:32 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:32-07:00" level=trace msg="sent dealer ping" Jun 11 20:16:32 rpi5volumio go-librespot[3877]: time="2025-06-11T20:16:32-07:00" level=trace msg="received dealer pong" Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CALLMETHOD: music_service mpd savePlaybackOptions [object Object] Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: mpd , savePlaybackOptions Jun 11 20:16:37 rpi5volumio sudo[3995]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Jun 11 20:16:37 rpi5volumio sudo[3995]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:16:37 rpi5volumio sudo[3995]: pam_unix(sudo:session): session closed for user root Jun 11 20:16:37 rpi5volumio volumio[1079]: info: MPD Permissions set Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio sudo[3998]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Jun 11 20:16:37 rpi5volumio sudo[3998]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:16:37 rpi5volumio systemd[1]: Stopping Music Player Daemon... Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 11 20:16:37 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 11 20:16:37 rpi5volumio systemd[1]: mpd.service: Succeeded. Jun 11 20:16:37 rpi5volumio systemd[1]: Stopped Music Player Daemon. Jun 11 20:16:37 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jun 11 20:16:37 rpi5volumio systemd[1]: Starting Music Player Daemon... Jun 11 20:16:37 rpi5volumio volumio[1079]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 11 20:16:37 rpi5volumio sudo[4004]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Jun 11 20:16:37 rpi5volumio sudo[4004]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 11 20:16:37 rpi5volumio sudo[4004]: pam_unix(sudo:session): session closed for user root Jun 11 20:16:37 rpi5volumio mpd[4007]: Jun 11 20:16 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jun 11 20:16:37 rpi5volumio systemd[1]: Started Music Player Daemon. Jun 11 20:16:37 rpi5volumio sudo[3998]: pam_unix(sudo:session): session closed for user root Jun 11 20:16:37 rpi5volumio volumio[1079]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 20:16:37 rpi5volumio volumio[1079]: TypeError: Cannot read property 'printToastMessage' of null Jun 11 20:16:37 rpi5volumio volumio[1079]: at /volumio/app/index.js:1214:32 Jun 11 20:16:37 rpi5volumio volumio[1079]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Jun 11 20:16:37 rpi5volumio volumio[1079]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Jun 11 20:16:37 rpi5volumio volumio[1079]: at CoreCommandRouter.pushToastMessage (/volumio/app/index.js:1212:13) Jun 11 20:16:37 rpi5volumio volumio[1079]: at /volumio/app/plugins/music_service/mpd/index.js:898:30 Jun 11 20:16:37 rpi5volumio volumio[1079]: at /volumio/app/plugins/music_service/mpd/index.js:942:9 Jun 11 20:16:37 rpi5volumio volumio[1079]: at ChildProcess.exithandler (child_process.js:299:7) Jun 11 20:16:37 rpi5volumio volumio[1079]: at ChildProcess.emit (events.js:315:20) Jun 11 20:16:37 rpi5volumio volumio[1079]: at maybeClose (internal/child_process.js:1048:16) Jun 11 20:16:37 rpi5volumio volumio[1079]: at Process.ChildProcess._handle.onexit (internal/child_process.js:288:5) Jun 11 20:16:37 rpi5volumio volumio[1079]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 11 20:16:37 rpi5volumio sudo[4020]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-11 20:15 Jun 11 20:16:37 rpi5volumio sudo[4020]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"