-- Logs begin at Sun 2024-04-07 00:15:19 -03, end at Sun 2024-04-07 21:00:52 -03. -- Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "outputs"... Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "albumart"... Apr 07 20:59:00 volumio volumio[16104]: info: Plugin example_plugin is not enabled Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "inputs"... Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "updater_comm"... Apr 07 20:59:00 volumio volumio[16104]: info: Plugin mpdemulation is not enabled Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "rest_api"... Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "websocket"... Apr 07 20:59:00 volumio volumio[16104]: info: Loading plugin "radio_paradise"... Apr 07 20:59:01 volumio volumio[16104]: Forking 3 albumart workers Apr 07 20:59:01 volumio volumio[16104]: info: Applying required configuration parameters for plugin radio_paradise Apr 07 20:59:01 volumio volumio[16104]: info: [1712534341474] [RadioParadise] API delay: 5 Apr 07 20:59:01 volumio volumio[16104]: info: Loading plugin "gpio_control"... Apr 07 20:59:02 volumio volumio[16104]: info: Applying required configuration parameters for plugin gpio_control Apr 07 20:59:02 volumio volumio[16104]: info: [GPIO_Control] Detected Raspberry Pi 3 Model B Plus Rev 1.3 Apr 07 20:59:02 volumio volumio[16104]: info: [GPIO_Control] 40 GPIOs: true Apr 07 20:59:02 volumio volumio[16104]: info: [GPIO_Control] Initialized Apr 07 20:59:02 volumio volumio[16104]: info: Loading plugin "music_services_shield"... Apr 07 20:59:03 volumio volumio[16104]: Starting albumart workers Apr 07 20:59:03 volumio volumio[16104]: info: Applying required configuration parameters for plugin music_services_shield Apr 07 20:59:03 volumio volumio[16104]: info: Loading i18n strings for locale en Apr 07 20:59:03 volumio volumio[16104]: Updating browse sources language Apr 07 20:59:03 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:03 volumio volumio[16104]: Starting albumart workers Apr 07 20:59:03 volumio volumio[16104]: Starting albumart workers Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::initPlayerControls Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 20:59:04 volumio volumio[16104]: Express server listening on port 3000 Apr 07 20:59:04 volumio volumio[16104]: [Metrics] WebUI: 27s 160.71ms Apr 07 20:59:04 volumio volumio[16104]: info: CoreStateMachine::resetVolumioState Apr 07 20:59:04 volumio volumio[16104]: info: CoreStateMachine::getcurrentVolume Apr 07 20:59:04 volumio volumio[16104]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 20:59:04 volumio sudo[16237]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:04 volumio sudo[16237]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:04 volumio sudo[16237]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:04 volumio sudo[16240]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:04 volumio sudo[16240]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:04 volumio sudo[16240]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:05 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 2 Apr 07 20:59:05 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 3 Apr 07 20:59:05 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 4 Apr 07 20:59:05 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 5 Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:05 volumio volumio[16104]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 07 20:59:05 volumio volumio[16104]: info: VolumeController:: Volume=43 Mute =true Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::pushState Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::updateTrackBlock Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrackBlock Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 20:59:05 volumio volumio[16104]: info: Reloading queue from file Apr 07 20:59:05 volumio volumio[16104]: info: Setting Device type: Raspberry PI Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::setRepeat null single undefined Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::pushState Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::setRandom null Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::pushState Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:05 volumio volumio[16104]: info: Listing playlists Apr 07 20:59:05 volumio volumio[16104]: info: Listing playlists Apr 07 20:59:05 volumio sudo[16275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 07 20:59:05 volumio sudo[16275]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:05 volumio sudo[16275]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:05 volumio volumio[16104]: info: VolumeController:: Volume=43 Mute =true Apr 07 20:59:05 volumio volumio[16104]: info: CoreStateMachine::pushState Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:05 volumio volumio[16104]: info: Discovery: adding 770e9769-1c51-4f90-9488-b2b12d804989 Apr 07 20:59:05 volumio volumio[16104]: info: Discovery: Found device Volumio Apr 07 20:59:05 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:05 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:05 volumio volumio[16104]: info: Upmpdcli Daemon Started Apr 07 20:59:06 volumio volumio-remote-updater[524]: [2024-04-07 20:59:06] [connect] Successful connection Apr 07 20:59:06 volumio volumio-remote-updater[524]: [2024-04-07 20:59:06] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1712534346 101 Apr 07 20:59:06 volumio volumio[16104]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 7 Apr 07 20:59:07 volumio sudo[16278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:07 volumio sudo[16278]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:07 volumio sudo[16278]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:07 volumio sudo[16281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:07 volumio sudo[16281]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:07 volumio sudo[16281]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:07 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 8 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 07 20:59:07 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 9 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetVisibleSources Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 07 20:59:07 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:07 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: Listing playlists Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 07 20:59:07 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:07 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 07 20:59:07 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:07 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 07 20:59:07 volumio volumio[16104]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Apr 07 20:59:07 volumio volumio[16104]: info: Received Get System Version Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 07 20:59:07 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:07 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetVisibleSources Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 07 20:59:07 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:07 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:07 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:07 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:07 volumio volumio[16104]: info: Listing playlists Apr 07 20:59:08 volumio sudo[16285]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:08 volumio sudo[16285]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:08 volumio sudo[16285]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:08 volumio sudo[16286]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:08 volumio sudo[16286]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:08 volumio sudo[16286]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:08 volumio volumio[16104]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 10 Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::volumioGetVisibleSources Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:08 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 07 20:59:08 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:08 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:08 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:08 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:08 volumio volumio[16104]: info: Listing playlists Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 07 20:59:08 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 07 20:59:09 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:09 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:09 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 07 20:59:09 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 07 20:59:10 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:10 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:10 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 07 20:59:10 volumio volumio[16104]: info: CoreCommandRouter::volumioGetQueue Apr 07 20:59:10 volumio volumio[16104]: info: CoreStateMachine::getQueue Apr 07 20:59:10 volumio volumio[16104]: info: CorePlayQueue::getQueue Apr 07 20:59:11 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 07 20:59:11 volumio volumio[16104]: info: Received Get System Info Apr 07 20:59:11 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:11 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:11 volumio volumio[16104]: info: Discovery: Getting this device information Apr 07 20:59:11 volumio volumio[16104]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:11 volumio volumio[16104]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:11 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:11 volumio volumio[16104]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 07 20:59:12 volumio volumio[16104]: info: Preload queue cleared Apr 07 20:59:12 volumio volumio[16104]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 07 20:59:12 volumio volumio[16104]: info: CoreStateMachine::ClearQueue Apr 07 20:59:12 volumio volumio[16104]: info: CoreStateMachine::stop Apr 07 20:59:12 volumio volumio[16104]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 07 20:59:12 volumio volumio[16104]: info: CorePlayQueue::clearPlayQueue Apr 07 20:59:12 volumio volumio[16104]: info: CorePlayQueue::saveQueue Apr 07 20:59:12 volumio volumio[16104]: info: CoreCommandRouter::volumioPushQueue Apr 07 20:59:12 volumio volumio[16104]: info: CoreStateMachine::addQueueItems Apr 07 20:59:12 volumio volumio[16104]: info: CorePlayQueue::addQueueItems Apr 07 20:59:12 volumio volumio[16104]: info: Preload queue cleared Apr 07 20:59:12 volumio volumio[16104]: info: Adding Item to queue: artists://Herbie%20Hancock/Man-Child Apr 07 20:59:12 volumio volumio[16104]: info: Exploding uri artists://Herbie%20Hancock/Man-Child in service mpd Apr 07 20:59:12 volumio volumio[16104]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 07 20:59:12 volumio volumio[16104]: TypeError: Cannot read property 'sendCommand' of undefined Apr 07 20:59:12 volumio volumio[16104]: at ControllerMpd.explodeUri (/volumio/app/plugins/music_service/mpd/index.js:2120:20) Apr 07 20:59:12 volumio volumio[16104]: at ControllerMpd.explodeUri (/volumio/app/plugins/music_service/mpd/index.js:2180:19) Apr 07 20:59:12 volumio volumio[16104]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1359:16) Apr 07 20:59:12 volumio volumio[16104]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Apr 07 20:59:12 volumio volumio[16104]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Apr 07 20:59:12 volumio volumio[16104]: at CorePlayQueue.addQueueItems (/volumio/app/playqueue.js:223:30) Apr 07 20:59:12 volumio volumio[16104]: at CoreStateMachine.addQueueItems (/volumio/app/statemachine.js:247:25) Apr 07 20:59:12 volumio volumio[16104]: at CoreCommandRouter.replaceAndPlay (/volumio/app/index.js:507:23) Apr 07 20:59:12 volumio volumio[16104]: at CoreCommandRouter.playItemsList (/volumio/app/index.js:477:17) Apr 07 20:59:12 volumio volumio[16104]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:118:33) Apr 07 20:59:12 volumio volumio[16104]: at Socket.emit (events.js:315:20) Apr 07 20:59:12 volumio volumio[16104]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Apr 07 20:59:12 volumio volumio[16104]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Apr 07 20:59:12 volumio volumio[16104]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 07 20:59:13 volumio sudo[16299]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-07 20:58 Apr 07 20:59:13 volumio sudo[16299]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:13 volumio sudo[16299]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:15 volumio volumio-remote-updater[524]: [2024-04-07 20:59:15] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Apr 07 20:59:15 volumio volumio-remote-updater[524]: [2024-04-07 20:59:15] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Apr 07 20:59:15 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Apr 07 20:59:15 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Apr 07 20:59:15 volumio systemd[1]: Started dynamicswap service. Apr 07 20:59:15 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 07 20:59:15 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Apr 07 20:59:15 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 2. Apr 07 20:59:15 volumio systemd[1]: Stopped Volumio Backend Module. Apr 07 20:59:15 volumio systemd[1]: Started Volumio Backend Module. Apr 07 20:59:15 volumio systemd[1]: Started dynamicswap service. Apr 07 20:59:15 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 07 20:59:18 volumio volumio[16314]: info: ------------------------------------------- Apr 07 20:59:18 volumio volumio[16314]: info: ----- Volumio3 ---- Apr 07 20:59:18 volumio volumio[16314]: info: ------------------------------------------- Apr 07 20:59:18 volumio volumio[16314]: info: ----- System startup ---- Apr 07 20:59:18 volumio volumio[16314]: info: ------------------------------------------- Apr 07 20:59:20 volumio volumio-remote-updater[524]: [2024-04-07 20:59:20] [connect] Successful connection Apr 07 20:59:20 volumio volumio[16314]: info: MYVOLUMIO Environment detected Apr 07 20:59:20 volumio volumio[16314]: info: Plugin folders cleanup Apr 07 20:59:20 volumio volumio[16314]: info: Scanning into folder /volumio/app/plugins/ Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category audio_interface Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category miscellanea Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category music_service Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category plugins.json Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category system_controller Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category user_interface Apr 07 20:59:20 volumio volumio[16314]: info: Scanning into folder /data/plugins/ Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category music_service Apr 07 20:59:20 volumio volumio[16314]: info: Scanning category system_hardware Apr 07 20:59:20 volumio volumio[16314]: info: Plugin folders cleanup completed Apr 07 20:59:20 volumio volumio[16314]: info: ------------------------------------------- Apr 07 20:59:20 volumio volumio[16314]: info: ----- Core plugins startup ---- Apr 07 20:59:20 volumio volumio[16314]: info: ------------------------------------------- Apr 07 20:59:20 volumio volumio[16314]: info: Loading plugins from folder /volumio/app/plugins/ Apr 07 20:59:20 volumio volumio[16314]: info: Adding plugin upnp to MyMusic Plugins Apr 07 20:59:20 volumio volumio[16314]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 07 20:59:20 volumio volumio[16314]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 07 20:59:20 volumio volumio[16314]: info: Loading plugins from folder /data/plugins/ Apr 07 20:59:20 volumio volumio[16314]: info: Loading plugin "system"... Apr 07 20:59:20 volumio volumio[16314]: info: Loading plugin "appearance"... Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "network"... Apr 07 20:59:22 volumio volumio[16314]: info: Refreshing Cached IP Addresses Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "services"... Apr 07 20:59:22 volumio sudo[16341]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:22 volumio sudo[16341]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "alsa_controller"... Apr 07 20:59:22 volumio sudo[16341]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:22 volumio sudo[16343]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:22 volumio sudo[16343]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:22 volumio sudo[16343]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:22 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "wizard"... Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "networkfs"... Apr 07 20:59:22 volumio volumio[16314]: info: Starting Udev Watcher for removable devices Apr 07 20:59:22 volumio volumio[16314]: info: Ignoring mount for partition: boot Apr 07 20:59:22 volumio volumio[16314]: info: Ignoring mount for partition: volumio Apr 07 20:59:22 volumio volumio[16314]: info: Ignoring mount for partition: volumio_data Apr 07 20:59:22 volumio volumio[16314]: error: Cannot associate FS Label, not mounting Apr 07 20:59:22 volumio volumio[16314]: info: Mounting Device IPOD_DE_PEJ Apr 07 20:59:22 volumio sudo[16354]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda2 /mnt/USB/IPOD_DE_PEJ -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 07 20:59:22 volumio sudo[16354]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:22 volumio sudo[16354]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:22 volumio volumio[16314]: mount: /media/IPOD_DE_PEJ: /dev/sda2 already mounted on /media/IPOD_DE_PEJ. Apr 07 20:59:22 volumio volumio[16314]: error: Failed to mount IPOD_DE_PEJ: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda2" "/mnt/USB/IPOD_DE_PEJ" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 07 20:59:22 volumio volumio[16314]: mount: /media/IPOD_DE_PEJ: /dev/sda2 already mounted on /media/IPOD_DE_PEJ. Apr 07 20:59:22 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "volumio_command_line_client"... Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "upnp"... Apr 07 20:59:22 volumio volumio[16314]: info: [1712534362844] Starting Upmpd Daemon Apr 07 20:59:22 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "my_music"... Apr 07 20:59:22 volumio volumio[16314]: info: Loading plugin "mpd"... Apr 07 20:59:23 volumio volumio[16314]: info: Loading plugin "upnp_browser"... Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "alarm-clock"... Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "airplay_emulation"... Apr 07 20:59:24 volumio volumio[16314]: info: Starting Shairport Sync Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "last_100"... Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "webradio"... Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "i2s_dacs"... Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "volumiodiscovery"... Apr 07 20:59:24 volumio volumio[16314]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:24 volumio volumio[16314]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:24 volumio volumio[16314]: *** WARNING *** For more information see Apr 07 20:59:24 volumio volumio[16314]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:24 volumio node[16314]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:24 volumio volumio[16314]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:24 volumio volumio[16314]: *** WARNING *** For more information see Apr 07 20:59:24 volumio node[16314]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:24 volumio node[16314]: *** WARNING *** For more information see Apr 07 20:59:24 volumio node[16314]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:24 volumio node[16314]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:24 volumio node[16314]: *** WARNING *** For more information see Apr 07 20:59:24 volumio volumio[16314]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 07 20:59:24 volumio volumio[16314]: info: Discovery: Started advertising with name: Volumio Apr 07 20:59:24 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 07 20:59:24 volumio volumio[16314]: info: Loading plugin "soundcloud"... Apr 07 20:59:25 volumio volumio[16314]: info: Loading plugin "spop"... Apr 07 20:59:27 volumio volumio[16314]: info: Loading plugin "youtube2"... Apr 07 20:59:29 volumio volumio[16314]: info: Loading plugin "ytcr"... Apr 07 20:59:32 volumio volumio-remote-updater[524]: [2024-04-07 20:59:32] [connect] Successful connection Apr 07 20:59:33 volumio volumio[16314]: info: Loading plugin "outputs"... Apr 07 20:59:33 volumio volumio[16314]: info: Loading plugin "albumart"... Apr 07 20:59:33 volumio volumio[16314]: info: Plugin example_plugin is not enabled Apr 07 20:59:33 volumio volumio[16314]: info: Loading plugin "inputs"... Apr 07 20:59:33 volumio volumio[16314]: info: Loading plugin "updater_comm"... Apr 07 20:59:34 volumio volumio[16314]: info: Plugin mpdemulation is not enabled Apr 07 20:59:34 volumio volumio[16314]: info: Loading plugin "rest_api"... Apr 07 20:59:34 volumio volumio[16314]: info: Loading plugin "websocket"... Apr 07 20:59:34 volumio volumio[16314]: info: Loading plugin "radio_paradise"... Apr 07 20:59:34 volumio volumio[16314]: info: Applying required configuration parameters for plugin radio_paradise Apr 07 20:59:34 volumio volumio[16314]: info: [1712534374674] [RadioParadise] API delay: 5 Apr 07 20:59:34 volumio volumio[16314]: Forking 3 albumart workers Apr 07 20:59:34 volumio volumio[16314]: info: Loading plugin "gpio_control"... Apr 07 20:59:35 volumio volumio[16314]: info: Applying required configuration parameters for plugin gpio_control Apr 07 20:59:35 volumio volumio[16314]: info: [GPIO_Control] Detected Raspberry Pi 3 Model B Plus Rev 1.3 Apr 07 20:59:35 volumio volumio[16314]: info: [GPIO_Control] 40 GPIOs: true Apr 07 20:59:35 volumio volumio[16314]: info: [GPIO_Control] Initialized Apr 07 20:59:35 volumio volumio[16314]: info: Loading plugin "music_services_shield"... Apr 07 20:59:36 volumio volumio[16314]: info: Applying required configuration parameters for plugin music_services_shield Apr 07 20:59:36 volumio volumio[16314]: info: Loading i18n strings for locale en Apr 07 20:59:36 volumio volumio[16314]: Updating browse sources language Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:36 volumio volumio[16314]: Starting albumart workers Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::initPlayerControls Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 20:59:36 volumio volumio[16314]: Express server listening on port 3000 Apr 07 20:59:36 volumio volumio[16314]: [Metrics] WebUI: 18s 716.44ms Apr 07 20:59:36 volumio volumio[16314]: info: CoreStateMachine::resetVolumioState Apr 07 20:59:36 volumio volumio[16314]: info: CoreStateMachine::getcurrentVolume Apr 07 20:59:36 volumio volumio[16314]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 20:59:36 volumio sudo[16397]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:36 volumio sudo[16397]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:36 volumio sudo[16397]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:36 volumio sudo[16399]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:36 volumio sudo[16399]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:37 volumio sudo[16399]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 1 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 2 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 3 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 4 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 5 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 6 Apr 07 20:59:37 volumio volumio-remote-updater[524]: [2024-04-07 20:59:37] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1712534372 101 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 7 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 8 Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 9 Apr 07 20:59:37 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:37 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:37 volumio volumio[16314]: Starting albumart workers Apr 07 20:59:37 volumio volumio[16314]: Starting albumart workers Apr 07 20:59:37 volumio volumio[16314]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 07 20:59:37 volumio volumio[16314]: info: VolumeController:: Volume=43 Mute =true Apr 07 20:59:37 volumio volumio[16314]: info: CoreStateMachine::pushState Apr 07 20:59:37 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:37 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 07 20:59:37 volumio volumio[16314]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:37 volumio volumio[16314]: info: CoreStateMachine::updateTrackBlock Apr 07 20:59:37 volumio volumio[16314]: info: CorePlayQueue::getTrackBlock Apr 07 20:59:37 volumio volumio[16314]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 20:59:38 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 20:59:38 volumio volumio[16314]: info: Reloading queue from file Apr 07 20:59:38 volumio volumio[16314]: info: CoreStateMachine::setRepeat null single undefined Apr 07 20:59:38 volumio volumio[16314]: info: CoreStateMachine::pushState Apr 07 20:59:38 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:38 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 07 20:59:38 volumio volumio[16314]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:38 volumio volumio[16314]: info: CoreStateMachine::setRandom null Apr 07 20:59:38 volumio volumio[16314]: info: CoreStateMachine::pushState Apr 07 20:59:38 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:38 volumio volumio[16314]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:38 volumio volumio[16314]: info: Setting Device type: Raspberry PI Apr 07 20:59:38 volumio volumio[16314]: info: Listing playlists Apr 07 20:59:38 volumio volumio[16314]: info: Listing playlists Apr 07 20:59:38 volumio sudo[16420]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 07 20:59:38 volumio sudo[16420]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:38 volumio sudo[16420]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:38 volumio volumio[16314]: info: VolumeController:: Volume=43 Mute =true Apr 07 20:59:38 volumio volumio[16314]: info: CoreStateMachine::pushState Apr 07 20:59:38 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:38 volumio volumio[16314]: info: CoreCommandRouter::volumioPushState Apr 07 20:59:38 volumio volumio[16314]: info: Discovery: adding 770e9769-1c51-4f90-9488-b2b12d804989 Apr 07 20:59:38 volumio volumio[16314]: info: Discovery: Found device Volumio Apr 07 20:59:38 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:38 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:38 volumio volumio[16314]: info: Upmpdcli Daemon Started Apr 07 20:59:39 volumio sudo[16431]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:39 volumio sudo[16431]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:39 volumio sudo[16431]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:39 volumio sudo[16437]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:39 volumio sudo[16437]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:39 volumio sudo[16437]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:39 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 11 Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::volumioGetVisibleSources Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:39 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::volumioGetQueue Apr 07 20:59:39 volumio volumio[16314]: info: CoreStateMachine::getQueue Apr 07 20:59:39 volumio volumio[16314]: info: CorePlayQueue::getQueue Apr 07 20:59:39 volumio volumio[16314]: info: Listing playlists Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 07 20:59:39 volumio volumio[16314]: info: Received Get System Info Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:39 volumio volumio[16314]: info: Discovery: Getting this device information Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:39 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:39 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 07 20:59:39 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:40 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:40 volumio volumio[16314]: verbose: New Socket.io Connection to 192.168.0.4 from 192.168.0.5 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 16_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.3 Mobile/15E148 Safari/604.1 Total Clients: 12 Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::volumioGetVisibleSources Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:40 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 07 20:59:40 volumio volumio[16314]: info: Received Get System Info Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:40 volumio volumio[16314]: info: Discovery: Getting this device information Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:40 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:40 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:40 volumio volumio[16314]: info: Listing playlists Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 07 20:59:40 volumio volumio[16314]: info: Received Get System Info Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:40 volumio volumio[16314]: info: Discovery: Getting this device information Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:40 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:40 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 07 20:59:42 volumio volumio[16314]: info: Received Get System Info Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 07 20:59:42 volumio volumio[16314]: info: Discovery: Getting this device information Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::volumioGetState Apr 07 20:59:42 volumio volumio[16314]: info: CorePlayQueue::getTrack 0 Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::executeOnPlugin: my_volumio , setMyVolumioToken Apr 07 20:59:42 volumio volumio[16314]: info: Preload queue cleared Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 07 20:59:42 volumio volumio[16314]: info: CoreStateMachine::ClearQueue Apr 07 20:59:42 volumio volumio[16314]: info: CoreStateMachine::stop Apr 07 20:59:42 volumio volumio[16314]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 07 20:59:42 volumio volumio[16314]: info: CorePlayQueue::clearPlayQueue Apr 07 20:59:42 volumio volumio[16314]: info: CorePlayQueue::saveQueue Apr 07 20:59:42 volumio volumio[16314]: info: CoreCommandRouter::volumioPushQueue Apr 07 20:59:42 volumio volumio[16314]: info: CoreStateMachine::addQueueItems Apr 07 20:59:42 volumio volumio[16314]: info: CorePlayQueue::addQueueItems Apr 07 20:59:42 volumio volumio[16314]: info: Preload queue cleared Apr 07 20:59:42 volumio volumio[16314]: info: Adding Item to queue: music-library/USB/IPOD_DE_PEJ/iPod_Control/Music/F09/NYYT.mp3 Apr 07 20:59:42 volumio volumio[16314]: info: Exploding uri music-library/USB/IPOD_DE_PEJ/iPod_Control/Music/F09/NYYT.mp3 in service mpd Apr 07 20:59:42 volumio volumio[16314]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 07 20:59:42 volumio volumio[16314]: TypeError: Cannot read property 'then' of undefined Apr 07 20:59:42 volumio volumio[16314]: at ControllerMpd.scanFolder (/volumio/app/plugins/music_service/mpd/index.js:2527:19) Apr 07 20:59:42 volumio volumio[16314]: at ControllerMpd.explodeUri (/volumio/app/plugins/music_service/mpd/index.js:2325:21) Apr 07 20:59:42 volumio volumio[16314]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1359:16) Apr 07 20:59:42 volumio volumio[16314]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Apr 07 20:59:42 volumio volumio[16314]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Apr 07 20:59:42 volumio volumio[16314]: at CorePlayQueue.addQueueItems (/volumio/app/playqueue.js:223:30) Apr 07 20:59:42 volumio volumio[16314]: at CoreStateMachine.addQueueItems (/volumio/app/statemachine.js:247:25) Apr 07 20:59:42 volumio volumio[16314]: at CoreCommandRouter.replaceAndPlay (/volumio/app/index.js:501:23) Apr 07 20:59:42 volumio volumio[16314]: at CoreCommandRouter.playItemsList (/volumio/app/index.js:477:17) Apr 07 20:59:42 volumio volumio[16314]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:118:33) Apr 07 20:59:42 volumio volumio[16314]: at Socket.emit (events.js:315:20) Apr 07 20:59:42 volumio volumio[16314]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Apr 07 20:59:42 volumio volumio[16314]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Apr 07 20:59:42 volumio volumio[16314]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 07 20:59:43 volumio sudo[16453]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-07 20:58 Apr 07 20:59:43 volumio sudo[16453]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:44 volumio sudo[16453]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:45 volumio volumio-remote-updater[524]: [2024-04-07 20:59:45] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Apr 07 20:59:45 volumio volumio-remote-updater[524]: [2024-04-07 20:59:45] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Apr 07 20:59:45 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Apr 07 20:59:45 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Apr 07 20:59:45 volumio systemd[1]: Started dynamicswap service. Apr 07 20:59:45 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Apr 07 20:59:45 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 3. Apr 07 20:59:45 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 07 20:59:45 volumio systemd[1]: Stopped Volumio Backend Module. Apr 07 20:59:45 volumio systemd[1]: Started Volumio Backend Module. Apr 07 20:59:49 volumio volumio[16467]: info: ------------------------------------------- Apr 07 20:59:49 volumio volumio[16467]: info: ----- Volumio3 ---- Apr 07 20:59:49 volumio volumio[16467]: info: ------------------------------------------- Apr 07 20:59:49 volumio volumio[16467]: info: ----- System startup ---- Apr 07 20:59:49 volumio volumio[16467]: info: ------------------------------------------- Apr 07 20:59:50 volumio volumio[16467]: info: MYVOLUMIO Environment detected Apr 07 20:59:50 volumio volumio-remote-updater[524]: [2024-04-07 20:59:50] [connect] Successful connection Apr 07 20:59:50 volumio volumio[16467]: info: Plugin folders cleanup Apr 07 20:59:50 volumio volumio[16467]: info: Scanning into folder /volumio/app/plugins/ Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category audio_interface Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category miscellanea Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category music_service Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category plugins.json Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category system_controller Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category user_interface Apr 07 20:59:50 volumio volumio[16467]: info: Scanning into folder /data/plugins/ Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category music_service Apr 07 20:59:50 volumio volumio[16467]: info: Scanning category system_hardware Apr 07 20:59:50 volumio volumio[16467]: info: Plugin folders cleanup completed Apr 07 20:59:50 volumio volumio[16467]: info: ------------------------------------------- Apr 07 20:59:50 volumio volumio[16467]: info: ----- Core plugins startup ---- Apr 07 20:59:50 volumio volumio[16467]: info: ------------------------------------------- Apr 07 20:59:50 volumio volumio[16467]: info: Loading plugins from folder /volumio/app/plugins/ Apr 07 20:59:50 volumio volumio[16467]: info: Adding plugin upnp to MyMusic Plugins Apr 07 20:59:50 volumio volumio[16467]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 07 20:59:50 volumio volumio[16467]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 07 20:59:50 volumio volumio[16467]: info: Loading plugins from folder /data/plugins/ Apr 07 20:59:50 volumio volumio[16467]: info: Loading plugin "system"... Apr 07 20:59:50 volumio volumio[16467]: info: Loading plugin "appearance"... Apr 07 20:59:52 volumio volumio[16467]: info: Loading plugin "network"... Apr 07 20:59:52 volumio volumio[16467]: info: Refreshing Cached IP Addresses Apr 07 20:59:52 volumio volumio[16467]: info: Loading plugin "services"... Apr 07 20:59:52 volumio sudo[16529]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 20:59:52 volumio volumio[16467]: info: Loading plugin "alsa_controller"... Apr 07 20:59:52 volumio sudo[16529]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:52 volumio sudo[16529]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:52 volumio sudo[16531]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 20:59:52 volumio sudo[16531]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:52 volumio sudo[16531]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:52 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 07 20:59:52 volumio volumio[16467]: info: Loading plugin "wizard"... Apr 07 20:59:52 volumio volumio[16467]: info: Loading plugin "networkfs"... Apr 07 20:59:52 volumio volumio[16467]: info: Starting Udev Watcher for removable devices Apr 07 20:59:52 volumio volumio[16467]: info: Ignoring mount for partition: boot Apr 07 20:59:52 volumio volumio[16467]: info: Ignoring mount for partition: volumio Apr 07 20:59:52 volumio volumio[16467]: info: Ignoring mount for partition: volumio_data Apr 07 20:59:52 volumio volumio[16467]: error: Cannot associate FS Label, not mounting Apr 07 20:59:52 volumio volumio[16467]: info: Mounting Device IPOD_DE_PEJ Apr 07 20:59:53 volumio sudo[16542]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda2 /mnt/USB/IPOD_DE_PEJ -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 07 20:59:53 volumio sudo[16542]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 20:59:53 volumio sudo[16542]: pam_unix(sudo:session): session closed for user root Apr 07 20:59:53 volumio volumio[16467]: mount: /media/IPOD_DE_PEJ: /dev/sda2 already mounted on /media/IPOD_DE_PEJ. Apr 07 20:59:53 volumio volumio[16467]: error: Failed to mount IPOD_DE_PEJ: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda2" "/mnt/USB/IPOD_DE_PEJ" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 07 20:59:53 volumio volumio[16467]: mount: /media/IPOD_DE_PEJ: /dev/sda2 already mounted on /media/IPOD_DE_PEJ. Apr 07 20:59:53 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 07 20:59:53 volumio volumio[16467]: info: Loading plugin "volumio_command_line_client"... Apr 07 20:59:53 volumio volumio[16467]: info: Loading plugin "upnp"... Apr 07 20:59:53 volumio volumio[16467]: info: [1712534393096] Starting Upmpd Daemon Apr 07 20:59:53 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 07 20:59:53 volumio volumio[16467]: info: Loading plugin "my_music"... Apr 07 20:59:53 volumio volumio[16467]: info: Loading plugin "mpd"... Apr 07 20:59:53 volumio volumio[16467]: info: Loading plugin "upnp_browser"... Apr 07 20:59:54 volumio volumio[16467]: info: Loading plugin "alarm-clock"... Apr 07 20:59:54 volumio volumio[16467]: info: Loading plugin "airplay_emulation"... Apr 07 20:59:54 volumio volumio[16467]: info: Starting Shairport Sync Apr 07 20:59:54 volumio volumio[16467]: info: Loading plugin "last_100"... Apr 07 20:59:54 volumio volumio[16467]: info: Loading plugin "webradio"... Apr 07 20:59:54 volumio volumio[16467]: info: Loading plugin "i2s_dacs"... Apr 07 20:59:54 volumio volumio[16467]: info: Loading plugin "volumiodiscovery"... Apr 07 20:59:54 volumio volumio[16467]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:54 volumio node[16467]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:54 volumio volumio[16467]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:54 volumio node[16467]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:54 volumio volumio[16467]: *** WARNING *** For more information see Apr 07 20:59:54 volumio node[16467]: *** WARNING *** For more information see Apr 07 20:59:54 volumio volumio[16467]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:54 volumio node[16467]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 07 20:59:54 volumio volumio[16467]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:54 volumio node[16467]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 07 20:59:54 volumio volumio[16467]: *** WARNING *** For more information see Apr 07 20:59:54 volumio node[16467]: *** WARNING *** For more information see Apr 07 20:59:54 volumio volumio[16467]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 07 20:59:55 volumio volumio[16467]: info: Discovery: Started advertising with name: Volumio Apr 07 20:59:55 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 07 20:59:55 volumio volumio[16467]: info: Loading plugin "soundcloud"... Apr 07 20:59:56 volumio volumio[16467]: info: Loading plugin "spop"... Apr 07 20:59:57 volumio volumio[16467]: info: Loading plugin "youtube2"... Apr 07 21:00:00 volumio volumio[16467]: info: Loading plugin "ytcr"... Apr 07 21:00:00 volumio go-librespot[5507]: time="2024-04-07T21:00:00-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1548" Apr 07 21:00:02 volumio go-librespot[5507]: time="2024-04-07T21:00:02-03:00" level=debug msg="handling transfer player command from 1d6fb2b16919f3255f569961c6a2287ece272136" Apr 07 21:00:02 volumio go-librespot[5507]: time="2024-04-07T21:00:02-03:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" Apr 07 21:00:02 volumio go-librespot[5507]: time="2024-04-07T21:00:02-03:00" level=debug msg="loading track spotify:track:5FVd6KXrgO9B3JPmC8OPst (paused: false, position: 2012ms)" Apr 07 21:00:02 volumio volumio-remote-updater[524]: [2024-04-07 21:00:02] [connect] Successful connection Apr 07 21:00:03 volumio go-librespot[5507]: time="2024-04-07T21:00:03-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1544" Apr 07 21:00:03 volumio go-librespot[5507]: time="2024-04-07T21:00:03-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:03 volumio go-librespot[5507]: time="2024-04-07T21:00:03-03:00" level=trace msg="emitting websocket event: will_play" Apr 07 21:00:03 volumio go-librespot[5507]: time="2024-04-07T21:00:03-03:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5FVd6KXrgO9B3JPmC8OPst" Apr 07 21:00:03 volumio go-librespot[5507]: time="2024-04-07T21:00:03-03:00" level=debug msg="requested aes key for file 5c143ef6a0dae7b6bce4e338af080a6a6b1756e8, gid: 5FVd6KXrgO9B3JPmC8OPst" Apr 07 21:00:03 volumio go-librespot[5507]: time="2024-04-07T21:00:03-03:00" level=debug msg="fetched first chunk of 22, total size is 11197628 bytes" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=trace msg="seek to 2012ms (diff: 271ms, samples: 88729, bytes: 53562)" Apr 07 21:00:04 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Apr 07 21:00:04 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=info msg="loaded track \"Do I Wanna Know?\" (uri: spotify:track:5FVd6KXrgO9B3JPmC8OPst, paused: false, position: 2012ms, duration: 272394ms)" Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "outputs"... Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "albumart"... Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=debug msg="fetched chunk 2/21, size: 524288" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=trace msg="emitting websocket event: metadata" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=trace msg="emitting websocket event: active" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=debug msg="sending successful reply for delaer request" Apr 07 21:00:04 volumio volumio[16467]: info: Plugin example_plugin is not enabled Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "inputs"... Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "updater_comm"... Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=debug msg="fetched chunk 3/21, size: 524288" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=debug msg="fetched chunk 1/21, size: 524288" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:04 volumio go-librespot[5507]: time="2024-04-07T21:00:04-03:00" level=trace msg="emitting websocket event: playing" Apr 07 21:00:04 volumio volumio[16467]: info: Plugin mpdemulation is not enabled Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "rest_api"... Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "websocket"... Apr 07 21:00:04 volumio volumio[16467]: info: Loading plugin "radio_paradise"... Apr 07 21:00:05 volumio go-librespot[5507]: time="2024-04-07T21:00:05-03:00" level=debug msg="put connect state inactive" Apr 07 21:00:05 volumio go-librespot[5507]: time="2024-04-07T21:00:05-03:00" level=trace msg="emitting websocket event: inactive" Apr 07 21:00:05 volumio volumio[16467]: info: Applying required configuration parameters for plugin radio_paradise Apr 07 21:00:05 volumio volumio[16467]: info: [1712534405220] [RadioParadise] API delay: 5 Apr 07 21:00:05 volumio volumio[16467]: info: Loading plugin "gpio_control"... Apr 07 21:00:05 volumio volumio[16467]: Forking 3 albumart workers Apr 07 21:00:06 volumio volumio[16467]: info: Applying required configuration parameters for plugin gpio_control Apr 07 21:00:06 volumio volumio[16467]: Starting albumart workers Apr 07 21:00:07 volumio volumio[16467]: info: [GPIO_Control] Detected Raspberry Pi 3 Model B Plus Rev 1.3 Apr 07 21:00:07 volumio volumio[16467]: info: [GPIO_Control] 40 GPIOs: true Apr 07 21:00:07 volumio volumio[16467]: info: [GPIO_Control] Initialized Apr 07 21:00:07 volumio volumio[16467]: info: Loading plugin "music_services_shield"... Apr 07 21:00:07 volumio volumio[16467]: Starting albumart workers Apr 07 21:00:07 volumio volumio[16467]: info: Applying required configuration parameters for plugin music_services_shield Apr 07 21:00:07 volumio volumio[16467]: info: Loading i18n strings for locale en Apr 07 21:00:07 volumio volumio[16467]: Updating browse sources language Apr 07 21:00:07 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::initPlayerControls Apr 07 21:00:08 volumio volumio[16467]: Starting albumart workers Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 21:00:08 volumio volumio[16467]: Express server listening on port 3000 Apr 07 21:00:08 volumio volumio[16467]: [Metrics] WebUI: 20s 393.39ms Apr 07 21:00:08 volumio volumio[16467]: info: CoreStateMachine::resetVolumioState Apr 07 21:00:08 volumio volumio[16467]: info: CoreStateMachine::getcurrentVolume Apr 07 21:00:08 volumio volumio[16467]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 21:00:08 volumio sudo[16601]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 07 21:00:08 volumio sudo[16601]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:08 volumio sudo[16601]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:08 volumio sudo[16604]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 07 21:00:08 volumio sudo[16604]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:08 volumio sudo[16604]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:09 volumio volumio[16467]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Apr 07 21:00:09 volumio volumio[16467]: info: VolumeController:: Volume=43 Mute =true Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::pushState Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioPushState Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::updateTrackBlock Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrackBlock Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 21:00:09 volumio volumio[16467]: info: Reloading queue from file Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::setRepeat null single undefined Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::pushState Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioPushState Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::setRandom null Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::pushState Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioPushState Apr 07 21:00:09 volumio volumio[16467]: info: Setting Device type: Raspberry PI Apr 07 21:00:09 volumio volumio[16467]: info: Listing playlists Apr 07 21:00:09 volumio volumio[16467]: info: Listing playlists Apr 07 21:00:09 volumio sudo[16623]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 07 21:00:09 volumio sudo[16623]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:09 volumio sudo[16623]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:09 volumio volumio[16467]: info: VolumeController:: Volume=43 Mute =true Apr 07 21:00:09 volumio volumio[16467]: info: CoreStateMachine::pushState Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioPushState Apr 07 21:00:09 volumio volumio[16467]: info: Discovery: adding 770e9769-1c51-4f90-9488-b2b12d804989 Apr 07 21:00:09 volumio volumio[16467]: info: Discovery: Found device Volumio Apr 07 21:00:09 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:09 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:09 volumio volumio[16467]: info: Upmpdcli Daemon Started Apr 07 21:00:10 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:10 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:17 volumio volumio-remote-updater[524]: [2024-04-07 21:00:17] [connect] Successful connection Apr 07 21:00:17 volumio volumio-remote-updater[524]: [2024-04-07 21:00:17] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1712534417 101 Apr 07 21:00:17 volumio volumio[16467]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 6 Apr 07 21:00:20 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:20 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=debug msg="handling transfer player command from 1d6fb2b16919f3255f569961c6a2287ece272136" Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=debug msg="loading track spotify:track:5FVd6KXrgO9B3JPmC8OPst (paused: false, position: 25548ms)" Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=trace msg="emitting websocket event: will_play" Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5FVd6KXrgO9B3JPmC8OPst" Apr 07 21:00:26 volumio go-librespot[5507]: time="2024-04-07T21:00:26-03:00" level=debug msg="requested aes key for file 5c143ef6a0dae7b6bce4e338af080a6a6b1756e8, gid: 5FVd6KXrgO9B3JPmC8OPst" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=debug msg="fetched first chunk of 22, total size is 11197628 bytes" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=debug msg="fetched chunk 3/21, size: 524288" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=debug msg="fetched chunk 1/21, size: 524288" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=debug msg="fetched chunk 4/21, size: 524288" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=debug msg="fetched chunk 5/21, size: 524288" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=debug msg="fetched chunk 2/21, size: 524288" Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=trace msg="seek to 25548ms (diff: 276ms, samples: 1126666, bytes: 1100448)" Apr 07 21:00:27 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Apr 07 21:00:27 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Apr 07 21:00:27 volumio go-librespot[5507]: time="2024-04-07T21:00:27-03:00" level=info msg="loaded track \"Do I Wanna Know?\" (uri: spotify:track:5FVd6KXrgO9B3JPmC8OPst, paused: false, position: 25548ms, duration: 272394ms)" Apr 07 21:00:28 volumio go-librespot[5507]: time="2024-04-07T21:00:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:28 volumio go-librespot[5507]: time="2024-04-07T21:00:28-03:00" level=trace msg="emitting websocket event: metadata" Apr 07 21:00:28 volumio go-librespot[5507]: time="2024-04-07T21:00:28-03:00" level=trace msg="emitting websocket event: active" Apr 07 21:00:28 volumio go-librespot[5507]: time="2024-04-07T21:00:28-03:00" level=debug msg="sending successful reply for delaer request" Apr 07 21:00:28 volumio go-librespot[5507]: time="2024-04-07T21:00:28-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:28 volumio go-librespot[5507]: time="2024-04-07T21:00:28-03:00" level=trace msg="emitting websocket event: playing" Apr 07 21:00:30 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:30 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:30 volumio volumio[16467]: info: Listing playlists Apr 07 21:00:30 volumio volumio[16467]: info: Listing playlists Apr 07 21:00:36 volumio go-librespot[5507]: time="2024-04-07T21:00:36-03:00" level=debug msg="fetched chunk 6/21, size: 524288" Apr 07 21:00:37 volumio volumio[16467]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion Apr 07 21:00:37 volumio volumio[16467]: info: Preparing to generate the ALSA configuration file Apr 07 21:00:37 volumio volumio[16467]: info: Asound.conf file unchanged, so no further update is needed Apr 07 21:00:37 volumio volumio[16467]: info: Output device has changed, restarting MPD Apr 07 21:00:37 volumio sudo[16651]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 07 21:00:37 volumio sudo[16651]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:37 volumio volumio[16467]: info: Output device has changed, restarting Shairport Sync Apr 07 21:00:37 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:37 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 21:00:37 volumio sudo[16651]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:38 volumio sudo[16654]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 07 21:00:38 volumio sudo[16654]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:38 volumio systemd[1]: musicservicesshield.service: Succeeded. Apr 07 21:00:38 volumio systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Apr 07 21:00:38 volumio systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Apr 07 21:00:38 volumio systemd[1]: Stopping Music Player Daemon... Apr 07 21:00:38 volumio volumio[16467]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 07 21:00:38 volumio volumio[16467]: info: ___________ START PLUGINS ___________ Apr 07 21:00:38 volumio volumio[16467]: info: ControllerMpd::onStart: Initializing MPD Apr 07 21:00:38 volumio volumio[16467]: info: Creating MPD Configuration file Apr 07 21:00:38 volumio sudo[16660]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 07 21:00:38 volumio sudo[16660]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 07 21:00:38 volumio volumio[16467]: info: [1712534438235] CoreMusicLibrary::Adding element Media Servers Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:38 volumio sudo[16660]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:38 volumio sudo[16662]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 07 21:00:38 volumio sudo[16662]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 21:00:38 volumio volumio[16467]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 21:00:38 volumio volumio[16467]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 07 21:00:38 volumio volumio[16467]: info: [1712534438517] CoreMusicLibrary::Adding element Last_100 Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 07 21:00:38 volumio volumio[16467]: info: [1712534438525] CoreMusicLibrary::Adding element Webradio Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 07 21:00:38 volumio systemd[1]: mpd.service: Succeeded. Apr 07 21:00:38 volumio systemd[1]: Stopped Music Player Daemon. Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 07 21:00:38 volumio volumio[16467]: info: [1712534438593] CoreMusicLibrary::Adding element SoundCloud Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:38 volumio volumio[16467]: Cannot find translation for source SoundCloud Apr 07 21:00:38 volumio systemd[1]: Starting Music Player Daemon... Apr 07 21:00:38 volumio volumio[16467]: info: Creating Spotify config file Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 07 21:00:38 volumio volumio[16467]: info: [1712534438661] CoreMusicLibrary::Adding element YouTube2 Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:38 volumio volumio[16467]: Cannot find translation for source SoundCloud Apr 07 21:00:38 volumio volumio[16467]: Cannot find translation for source YouTube2 Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 07 21:00:38 volumio volumio[16467]: info: [1712534438767] CoreMusicLibrary::Adding element Radio Paradise Apr 07 21:00:38 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 07 21:00:38 volumio volumio[16467]: Cannot find translation for source SoundCloud Apr 07 21:00:38 volumio volumio[16467]: Cannot find translation for source YouTube2 Apr 07 21:00:38 volumio volumio[16467]: Cannot find translation for source Radio Paradise Apr 07 21:00:38 volumio volumio[16467]: info: [GPIO_Control] Reading config and creating GPIOs Apr 07 21:00:38 volumio volumio[16467]: info: [GPIO_Control] Will set GPIO 24 Off when musicPlay Apr 07 21:00:38 volumio volumio[16467]: info: [GPIO_Control] Will set GPIO 24 On when musicPause Apr 07 21:00:38 volumio volumio[16467]: info: [GPIO_Control] Will set GPIO 24 On when musicStop Apr 07 21:00:39 volumio volumio[16467]: info: Volumio Calling Home Apr 07 21:00:39 volumio volumio[16467]: info: [GPIO_Control] GPIOs created Apr 07 21:00:39 volumio volumio[16467]: info: [GPIO_Control] GPIOs Yea! Apr 07 21:00:39 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:39 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:39 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:39 volumio sudo[16699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Apr 07 21:00:39 volumio sudo[16699]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:39 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:39 volumio volumio[16467]: info: MPD Permissions set Apr 07 21:00:39 volumio volumio[16467]: info: MPD Permissions set Apr 07 21:00:39 volumio volumio[16467]: info: Spotify config file written Apr 07 21:00:39 volumio volumio[16467]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:39 volumio sudo[16713]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 07 21:00:39 volumio sudo[16713]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:39 volumio systemd[1]: Stopping go-librespot Daemon... Apr 07 21:00:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Apr 07 21:00:39 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Apr 07 21:00:39 volumio systemd[1]: Stopped go-librespot Daemon. Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 21:00:40 volumio systemd[1]: Started go-librespot Daemon. Apr 07 21:00:40 volumio go-librespot[16719]: Librespot-go daemon starting... Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio sudo[16713]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 07 21:00:40 volumio go-librespot[16719]: time="2024-04-07T21:00:40-03:00" level=info msg="generated new device id: e25158c899e7f39ec09c50481ffa118872e4cb26" Apr 07 21:00:40 volumio volumio[16467]: info: Volumio called home Apr 07 21:00:40 volumio volumio[16467]: info: Starting Shairport Sync Apr 07 21:00:40 volumio volumio[16467]: info: Starting Shairport Sync Apr 07 21:00:40 volumio volumio[16467]: info: Starting Shairport Sync Apr 07 21:00:40 volumio sudo[16738]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 07 21:00:40 volumio sudo[16738]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:40 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:40 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 07 21:00:40 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:40 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 07 21:00:40 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 07 21:00:40 volumio sudo[16743]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 07 21:00:40 volumio sudo[16740]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 07 21:00:40 volumio sudo[16740]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:40 volumio sudo[16743]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:40 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 07 21:00:40 volumio sudo[16738]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:40 volumio go-librespot[16719]: time="2024-04-07T21:00:40-03: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]" Apr 07 21:00:40 volumio go-librespot[16719]: time="2024-04-07T21:00:40-03: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]" Apr 07 21:00:40 volumio go-librespot[16719]: time="2024-04-07T21:00:40-03: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]" Apr 07 21:00:41 volumio go-librespot[16719]: time="2024-04-07T21:00:41-03:00" level=debug msg="zeroconf server listening on port 34061" Apr 07 21:00:41 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 07 21:00:41 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:41 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:41 volumio volumio[16467]: info: Shairport-Sync Started Apr 07 21:00:41 volumio volumio[16467]: Error adding Membership: Error: addMembership EINVAL Apr 07 21:00:41 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 07 21:00:41 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 07 21:00:41 volumio sudo[16699]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:41 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 07 21:00:41 volumio sudo[16743]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:41 volumio sudo[16740]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:41 volumio volumio[16467]: info: Shairport-Sync Started Apr 07 21:00:41 volumio volumio[16467]: info: Shairport-Sync Started Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] *** musicStop *** Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Delaying: 10000ms Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] *** musicStop *** Apr 07 21:00:41 volumio volumio[16467]: info: [GPIO_Control] Delaying: 10000ms Apr 07 21:00:41 volumio sudo[16753]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Apr 07 21:00:41 volumio sudo[16753]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 07 21:00:41 volumio mpd[16671]: Apr 07 21:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 07 21:00:42 volumio systemd[1]: Started Music Player Daemon. Apr 07 21:00:42 volumio sudo[16654]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:42 volumio sudo[16662]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:42 volumio systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Apr 07 21:00:42 volumio volumio[16467]: info: [yt-cast-receiver] DIAL server listening on port 8098 Apr 07 21:00:42 volumio volumio[16467]: info: CoreCommandRouter::volumioRetrievevolume Apr 07 21:00:42 volumio volumio[16467]: error: MPD error: The expression evaluated to a falsy value: Apr 07 21:00:42 volumio volumio[16467]: assert.ok(self.idling) Apr 07 21:00:42 volumio volumio[16467]: error: The expression evaluated to a falsy value: Apr 07 21:00:42 volumio volumio[16467]: assert.ok(self.idling) Apr 07 21:00:42 volumio volumio[16467]: info: MPD running with PID16671 Apr 07 21:00:42 volumio volumio[16467]: ,establishing connection Apr 07 21:00:42 volumio volumio[16467]: error: MPD error: The expression evaluated to a falsy value: Apr 07 21:00:42 volumio volumio[16467]: assert.ok(self.idling) Apr 07 21:00:42 volumio volumio[16467]: error: The expression evaluated to a falsy value: Apr 07 21:00:42 volumio volumio[16467]: assert.ok(self.idling) Apr 07 21:00:42 volumio volumio[16467]: error: updateQueue error: null Apr 07 21:00:42 volumio volumio[16467]: info: VolumeController:: Volume=43 Mute =true Apr 07 21:00:42 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:42 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:42 volumio volumio[16467]: info: CoreStateMachine::pushState Apr 07 21:00:42 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:42 volumio volumio[16467]: info: CoreCommandRouter::volumioPushState Apr 07 21:00:42 volumio volumio[16467]: info: Completed starting Core Plugins Apr 07 21:00:42 volumio volumio[16467]: info: ------------------------------------------- Apr 07 21:00:42 volumio volumio[16467]: info: ----- MyVolumio plugins startup ---- Apr 07 21:00:42 volumio volumio[16467]: info: ------------------------------------------- Apr 07 21:00:42 volumio volumio[16467]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 07 21:00:42 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:42 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:42 volumio volumio[16467]: info: [GPIO_Control] Clearing timeouts for: [object Object] Apr 07 21:00:42 volumio volumio[16467]: info: [GPIO_Control] *** musicStop *** Apr 07 21:00:42 volumio volumio[16467]: info: [GPIO_Control] Delaying: 10000ms Apr 07 21:00:43 volumio volumio[16759]: cset: --> shielding system active with Apr 07 21:00:43 volumio volumio[16759]: cset: "system" cpuset of CPUSPEC(1-3) with 115 tasks running Apr 07 21:00:43 volumio volumio[16759]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Apr 07 21:00:43 volumio systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Apr 07 21:00:43 volumio systemd[1]: Reloading. Apr 07 21:00:43 volumio volumio[16467]: info: go-librespot daemon successfully initialized Apr 07 21:00:44 volumio go-librespot[16719]: time="2024-04-07T21:00:44-03:00" level=debug msg="obtained new client token: AADQF1ObT4ArdxOgvNuNCmI9WSYm2mVQ4t//JaufuA4/E8ceV1swkHe4UebKe5rhDwp718pozzbfYbkhvEYOUZKsoydoqs38SHLVF9HusjXzS784Hi4M7xMhoaPcoUDJuUT03AeercPY0pWJVUI9L9EqsiU/U1H28slnI0jPDQQpKRV0gNBOt1IR61uTiqC6bJ48uzOazvfwgeZJEDSUb/w+1hZupUkZ3crdIZcnEPEY0HSSCrNJOWPQ/nwkJdU=" Apr 07 21:00:44 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Apr 07 21:00:44 volumio go-librespot[16719]: time="2024-04-07T21:00:44-03:00" level=debug msg="completed keyexchange" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="completed challenge" Apr 07 21:00:45 volumio sudo[16753]: pam_unix(sudo:session): session closed for user root Apr 07 21:00:45 volumio volumio[16467]: info: succeeded Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="authenticated as bobrow-us" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="authenticated as bobrow-us" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="dealer connection opened" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=info msg="accepted zeroconf user bobrow-us from iPhone" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" Apr 07 21:00:45 volumio go-librespot[16719]: time="2024-04-07T21:00:45-03:00" level=debug msg="received connection id: Y2U5NzA0YjUtMGI4Yi00MWNmLTgwMTUtMmU5MGQ0ODg3NDM1K2RlYWxlcit0Y3A6Ly9ndWMzLWRlYWxlci1hLXJoeGYuZ3VjMy5zcG90aWZ5Lm5ldDo1NzAwK0ZCREMxQUNFQTE3QjExOTFBNkZENTRGMEEyNjMwQUU5NEQ5NjIyNzUwNjU0QkFBRkI0NzAyMTg0RkJGMUQ3MEY=" Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=debug msg="put connect state because NEW_DEVICE" Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=debug msg="handling transfer player command from 1d6fb2b16919f3255f569961c6a2287ece272136" Apr 07 21:00:46 volumio volumio[16467]: info: Initializing connection to go-librespot Websocket Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=debug msg="new websocket client" Apr 07 21:00:46 volumio volumio[16467]: info: Connection to go-librespot Websocket established Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=debug msg="loading track spotify:track:5FVd6KXrgO9B3JPmC8OPst (paused: false, position: 41309ms)" Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:46 volumio go-librespot[16719]: time="2024-04-07T21:00:46-03:00" level=trace msg="emitting websocket event: will_play" Apr 07 21:00:46 volumio volumio[16467]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5FVd6KXrgO9B3JPmC8OPst","play_origin":"com.spotify.service.freetieralbum"}} Apr 07 21:00:47 volumio go-librespot[16719]: time="2024-04-07T21:00:47-03:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5FVd6KXrgO9B3JPmC8OPst" Apr 07 21:00:47 volumio go-librespot[16719]: time="2024-04-07T21:00:47-03:00" level=debug msg="requested aes key for file 5c143ef6a0dae7b6bce4e338af080a6a6b1756e8, gid: 5FVd6KXrgO9B3JPmC8OPst" Apr 07 21:00:47 volumio go-librespot[16719]: time="2024-04-07T21:00:47-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1544" Apr 07 21:00:48 volumio go-librespot[16719]: time="2024-04-07T21:00:48-03:00" level=debug msg="fetched first chunk of 22, total size is 11197628 bytes" Apr 07 21:00:49 volumio go-librespot[16719]: time="2024-04-07T21:00:49-03:00" level=debug msg="fetched chunk 2/21, size: 524288" Apr 07 21:00:49 volumio go-librespot[16719]: time="2024-04-07T21:00:49-03:00" level=debug msg="fetched chunk 4/21, size: 524288" Apr 07 21:00:49 volumio go-librespot[16719]: time="2024-04-07T21:00:49-03:00" level=debug msg="fetched chunk 1/21, size: 524288" Apr 07 21:00:49 volumio go-librespot[16719]: time="2024-04-07T21:00:49-03:00" level=debug msg="fetched chunk 6/21, size: 524288" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=debug msg="fetched chunk 3/21, size: 524288" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=debug msg="fetched chunk 5/21, size: 524288" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=trace msg="seek to 41309ms (diff: 206ms, samples: 1821726, bytes: 1798761)" Apr 07 21:00:50 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Apr 07 21:00:50 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=info msg="loaded track \"Do I Wanna Know?\" (uri: spotify:track:5FVd6KXrgO9B3JPmC8OPst, paused: false, position: 41309ms, duration: 272394ms)" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=trace msg="emitting websocket event: metadata" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=trace msg="emitting websocket event: active" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=debug msg="sending successful reply for delaer request" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 07 21:00:50 volumio go-librespot[16719]: time="2024-04-07T21:00:50-03:00" level=trace msg="emitting websocket event: playing" Apr 07 21:00:50 volumio volumio[16467]: info: Getting Spotify volume Apr 07 21:00:50 volumio volumio[16467]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:5FVd6KXrgO9B3JPmC8OPst","name":"Do I Wanna Know?","artist_names":["Arctic Monkeys"],"album_name":"AM","album_cover_url":"https://i.scdn.co/image/ab67616d00001e024ae1c4c5c45aabe565499163","position":41309,"duration":272394,"release_date":"year:2013 month:9 day:9","track_number":1,"disc_number":1}} Apr 07 21:00:50 volumio volumio[16467]: SPOTIFY: received: {"type":"active","data":null} Apr 07 21:00:50 volumio volumio[16467]: info: Aligning Spotify Volume to Volumio Volume Apr 07 21:00:50 volumio volumio[16467]: info: CoreCommandRouter::volumioGetState Apr 07 21:00:50 volumio volumio[16467]: info: CorePlayQueue::getTrack 0 Apr 07 21:00:50 volumio volumio[16467]: info: Setting Spotify Volume from Volumio: 0 Apr 07 21:00:50 volumio volumio[16467]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5FVd6KXrgO9B3JPmC8OPst","play_origin":"com.spotify.service.freetieralbum"}} Apr 07 21:00:51 volumio volumio[16467]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 07 21:00:51 volumio volumio[16467]: TypeError: Cannot read property 'service' of undefined Apr 07 21:00:51 volumio volumio[16467]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Apr 07 21:00:51 volumio volumio[16467]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Apr 07 21:00:51 volumio volumio[16467]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Apr 07 21:00:51 volumio volumio[16467]: at WebSocket.emit (events.js:315:20) Apr 07 21:00:51 volumio volumio[16467]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Apr 07 21:00:51 volumio volumio[16467]: at Receiver.emit (events.js:315:20) Apr 07 21:00:51 volumio volumio[16467]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Apr 07 21:00:51 volumio volumio[16467]: at internal/process/task_queues.js:149:7 Apr 07 21:00:51 volumio volumio[16467]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Apr 07 21:00:51 volumio volumio[16467]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) Apr 07 21:00:51 volumio volumio[16467]: at processTicksAndRejections (internal/process/task_queues.js:93:5) Apr 07 21:00:51 volumio volumio[16467]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 07 21:00:51 volumio go-librespot[16719]: time="2024-04-07T21:00:51-03:00" level=debug msg="put connect state inactive" Apr 07 21:00:51 volumio go-librespot[16719]: time="2024-04-07T21:00:51-03:00" level=trace msg="emitting websocket event: inactive" Apr 07 21:00:52 volumio sudo[16801]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-07 20:59 Apr 07 21:00:52 volumio sudo[16801]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"