Mar 27 14:24:05 volumio ntpd[1066]: CLOCK: time stepped by 23512.680136
Mar 27 14:24:05 volumio ntpd[1066]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes
Mar 27 14:24:06 volumio volumio[1256]: info: Loading plugin "soundcloud"...
Mar 27 14:24:07 volumio volumio[1256]: info: Loading plugin "spop"...
Mar 27 14:24:08 volumio volumio[1256]: info: Loading plugin "youtube2"...
Mar 27 14:24:09 volumio volumio[1256]: info: Loading plugin "ytcr"...
Mar 27 14:24:11 volumio volumio[1256]: info: Loading plugin "ytmusic"...
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "outputs"...
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "albumart"...
Mar 27 14:24:12 volumio volumio[1256]: info: Plugin example_plugin is not enabled
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "inputs"...
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "updater_comm"...
Mar 27 14:24:12 volumio volumio[1256]: info: Plugin mpdemulation is not enabled
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "rest_api"...
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "websocket"...
Mar 27 14:24:12 volumio volumio[1256]: info: Starting Socket.io Server version 1.7.4
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "motherearthradio"...
Mar 27 14:24:12 volumio volumio[1256]: info: Loading plugin "radio_browser"...
Mar 27 14:24:13 volumio volumio[1256]: info: Loading plugin "radio_paradise"...
Mar 27 14:24:13 volumio volumio[1447]: Forking 3 albumart workers
Mar 27 14:24:14 volumio volumio[1256]: info: Applying required configuration parameters for plugin radio_paradise
Mar 27 14:24:14 volumio volumio[1256]: info: [1774601654950] [RadioParadise] API delay: 5
Mar 27 14:24:14 volumio volumio[1256]: info: Loading plugin "music_services_shield"...
Mar 27 14:24:15 volumio volumio-remote-updater[819]: [2026-03-27 14:24:15] [connect] Successful connection
Mar 27 14:24:15 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully.
Mar 27 14:24:16 volumio volumio[1256]: info: Applying required configuration parameters for plugin music_services_shield
Mar 27 14:24:16 volumio volumio[1256]: info: Loading i18n strings for locale en
Mar 27 14:24:16 volumio volumio[1256]: Updating browse sources language
Mar 27 14:24:16 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::initPlayerControls
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Mar 27 14:24:17 volumio volumio[1256]: Express server listening on port 3000
Mar 27 14:24:17 volumio volumio[1256]: [Metrics] WebUI: 18s 641.10ms
Mar 27 14:24:17 volumio volumio[1256]: info: CoreStateMachine::resetVolumioState
Mar 27 14:24:17 volumio volumio[1256]: info: CoreStateMachine::getcurrentVolume
Mar 27 14:24:17 volumio volumio[1256]: info: CoreCommandRouter::volumioRetrievevolume
Mar 27 14:24:18 volumio sudo[1507]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Mar 27 14:24:18 volumio sudo[1507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:18 volumio sudo[1509]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Mar 27 14:24:18 volumio sudo[1507]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:18 volumio sudo[1509]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:18 volumio sudo[1509]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:18 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully.
Mar 27 14:24:18 volumio volumio[1256]: info: Volumio Network Manager: Network status updated: 1
Mar 27 14:24:18 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2.
Mar 27 14:24:18 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD.
Mar 27 14:24:18 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD.
Mar 27 14:24:18 volumio upmpdcli[1518]: :3:../libupnpp/upnpplib.cxx:273::LibUPnP: Using IPV4 192.168.1.3 port 49152 IPV6 port 49152
Mar 27 14:24:18 volumio upmpdcli[1518]: :3:../src/mediaserver/cdplugins/plgwithslave.cxx:248::PlgWithSlave: starting streaming proxy on port 49149
Mar 27 14:24:18 volumio upmpdcli[1518]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Cannot assign requested address
Mar 27 14:24:18 volumio upmpdcli[1518]: :2:../src/main.cxx:732::MPD connection failed
Mar 27 14:24:19 volumio volumio[1474]: Starting albumart workers
Mar 27 14:24:19 volumio volumio[1256]: info: VolumeController:: Volume=22 Mute =false
Mar 27 14:24:19 volumio volumio[1256]: info: CoreStateMachine::pushState
Mar 27 14:24:19 volumio volumio[1472]: Starting albumart workers
Mar 27 14:24:19 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::volumioPushState
Mar 27 14:24:19 volumio volumio[1256]: info: CoreStateMachine::updateTrackBlock
Mar 27 14:24:19 volumio volumio[1256]: info: CorePlayQueue::getTrackBlock
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::volumioRetrievevolume
Mar 27 14:24:19 volumio volumio[1473]: Starting albumart workers
Mar 27 14:24:19 volumio volumio-remote-updater[819]: [2026-03-27 14:24:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1774601655 101
Mar 27 14:24:19 volumio volumio[1256]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 1
Mar 27 14:24:19 volumio volumio[1256]: info: Reloading queue from file
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:19 volumio volumio[1256]: info: Executing start script for DAC IQaudIO DAC Plus
Mar 27 14:24:19 volumio volumio[1256]: info: Setting Device type: Raspberry PI
Mar 27 14:24:19 volumio volumio[1256]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb
Mar 27 14:24:19 volumio volumio[1256]: info: USB Boot Capable - System SBC Revision found in cpuinfo: c03115
Mar 27 14:24:19 volumio volumio[1256]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI
Mar 27 14:24:19 volumio volumio[1256]: info: CoreStateMachine::setRepeat true single undefined
Mar 27 14:24:19 volumio volumio[1256]: info: CoreStateMachine::pushState
Mar 27 14:24:19 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::volumioPushState
Mar 27 14:24:19 volumio volumio[1256]: info: CoreStateMachine::setRandom null
Mar 27 14:24:19 volumio volumio[1256]: info: CoreStateMachine::pushState
Mar 27 14:24:19 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:19 volumio volumio[1256]: info: CoreCommandRouter::volumioPushState
Mar 27 14:24:20 volumio volumio[1256]: info: VolumeController:: Volume=22 Mute =false
Mar 27 14:24:20 volumio volumio[1256]: info: CoreStateMachine::pushState
Mar 27 14:24:20 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:20 volumio volumio[1256]: info: CoreCommandRouter::volumioPushState
Mar 27 14:24:20 volumio volumio[1256]: info: DAC script executed
Mar 27 14:24:20 volumio volumio[1256]: info: Completed loading Core Plugins
Mar 27 14:24:20 volumio volumio[1256]: info: Preparing to generate the ALSA configuration file
Mar 27 14:24:20 volumio volumio[1256]: info: Discovery: A device disappeared from network
Mar 27 14:24:20 volumio sudo[1544]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Mar 27 14:24:20 volumio volumio[1256]: info: Discovery: adding ccd1327c-217f-41fd-87ea-83f2769b4eb8
Mar 27 14:24:20 volumio volumio[1256]: info: Discovery: Found device Volumio
Mar 27 14:24:20 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:20 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:20 volumio sudo[1544]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:20 volumio volumio[1256]: info: Discovery: this is already registered, ccd1327c-217f-41fd-87ea-83f2769b4eb8
Mar 27 14:24:20 volumio volumio[1256]: info: Discovery: Found device Volumio
Mar 27 14:24:20 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:20 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:20 volumio volumio[1256]: info: Discovery: A device disappeared from network
Mar 27 14:24:20 volumio sudo[1544]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:20 volumio volumio[1256]: info: Asound.conf file unchanged, so no further update is needed
Mar 27 14:24:20 volumio volumio[1256]: info: Output device has changed, restarting MPD
Mar 27 14:24:20 volumio volumio[1256]: info: Output device has changed, restarting Shairport Sync
Mar 27 14:24:20 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:20 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:20 volumio sudo[1548]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Mar 27 14:24:20 volumio sudo[1548]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:20 volumio sudo[1548]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:20 volumio volumio[1256]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Mar 27 14:24:20 volumio volumio[1256]: info: ___________ START PLUGINS ___________
Mar 27 14:24:20 volumio sudo[1550]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Mar 27 14:24:20 volumio sudo[1550]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:20 volumio volumio[1256]: info: ControllerMpd::onStart: Initializing MPD
Mar 27 14:24:20 volumio volumio[1256]: info: Creating MPD Configuration file
Mar 27 14:24:20 volumio upmpdcli[1518]: :2:../src/mpdcli.cxx:113::MPDCli::openconn: mpd_connection_new failed: Cannot assign requested address
Mar 27 14:24:20 volumio upmpdcli[1518]: :2:../src/main.cxx:732::MPD connection failed
Mar 27 14:24:21 volumio systemd[1]: musicservicesshield.service: Deactivated successfully.
Mar 27 14:24:21 volumio systemd[1]: Stopped musicservicesshield.service - Shield Volumio Music Services in the User CPU Set.
Mar 27 14:24:21 volumio systemd[1]: Stopping musicservicesshield.service - Shield Volumio Music Services in the User CPU Set...
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Mar 27 14:24:21 volumio sudo[1558]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio5-onboarding.service
Mar 27 14:24:21 volumio sudo[1558]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:21 volumio sudo[1560]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Mar 27 14:24:21 volumio sudo[1560]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:21 volumio volumio[1256]: info: [1774601661089] CoreMusicLibrary::Adding element Media Servers
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:21 volumio volumio[1256]: info: UPNP Browser: Client initialized successfully
Mar 27 14:24:21 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Mar 27 14:24:21 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:21 volumio sudo[1560]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:21 volumio sudo[1565]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:21 volumio sudo[1565]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:21 volumio sudo[1566]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Mar 27 14:24:21 volumio sudo[1566]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Mar 27 14:24:21 volumio sudo[1569]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory
Mar 27 14:24:21 volumio sudo[1566]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:21 volumio volumio[1256]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:21 volumio systemd[1]: Started volumio5-onboarding.service - Volumio5 Onboarding Server.
Mar 27 14:24:21 volumio systemd[1]: mpd.service: Deactivated successfully.
Mar 27 14:24:21 volumio systemd[1]: Stopped mpd.service - Music Player Daemon.
Mar 27 14:24:21 volumio systemd[1]: mpd.socket: Deactivated successfully.
Mar 27 14:24:21 volumio sudo[1558]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:21 volumio systemd[1]: Closed mpd.socket - Music Player Daemon Socket.
Mar 27 14:24:21 volumio systemd[1]: Stopping mpd.socket - Music Player Daemon Socket...
Mar 27 14:24:21 volumio systemd[1]: Listening on mpd.socket - Music Player Daemon Socket.
Mar 27 14:24:21 volumio systemd[1]: Starting mpd.service - Music Player Daemon...
Mar 27 14:24:21 volumio volumio[1256]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:21 volumio volumio[1256]: info: [1774601661609] CoreMusicLibrary::Adding element Last_100
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:21 volumio volumio[1256]: info: [1774601661611] CoreMusicLibrary::Adding element Webradio
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:21 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Mar 27 14:24:21 volumio volumio[1256]: info: Initializing BBC Radios
Mar 27 14:24:21 volumio sudo[1577]: root : PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Mar 27 14:24:21 volumio sudo[1577]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Mar 27 14:24:21 volumio sudo[1586]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory
Mar 27 14:24:21 volumio sudo[1577]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:21 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:21.856+05:30 level=INFO msg="running volumio5-device-gateway" version=10ca7e93+CHANGES buildDate=2026-03-06T14:30:20Z
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:22 volumio volumio[1256]: info: Adding Calm Radio to Browse Sources
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662024] CoreMusicLibrary::Adding element Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662043] CoreMusicLibrary::Adding element SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: info: Creating Spotify config file
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662128] CoreMusicLibrary::Adding element YouTube2
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube2
Mar 27 14:24:22 volumio volumio[1256]: info: [ytcr] Data store TTL expired - clearing it...
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662285] CoreMusicLibrary::Adding element YouTube Music
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube2
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube Music
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662300] CoreMusicLibrary::Adding element Mother Earth Radio
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube2
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube Music
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Mother Earth Radio
Mar 27 14:24:22 volumio volumio[1256]: info: [MER] Plugin started (SSE mode)
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662338] CoreMusicLibrary::Adding element Radio Browser
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube2
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube Music
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Mother Earth Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Radio Browser
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
Mar 27 14:24:22 volumio volumio[1256]: info: [1774601662365] CoreMusicLibrary::Adding element Radio Paradise
Mar 27 14:24:22 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Calm Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source SoundCloud
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube2
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source YouTube Music
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Mother Earth Radio
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Radio Browser
Mar 27 14:24:22 volumio volumio[1256]: Cannot find translation for source Radio Paradise
Mar 27 14:24:23 volumio volumio[1256]: info: Volumio Calling Home
Mar 27 14:24:23 volumio sudo[1667]: volumio : PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh
Mar 27 14:24:23 volumio sudo[1667]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:25 volumio volumio[1256]: info: Upmpdcli Daemon Started
Mar 27 14:24:25 volumio mpd[1587]: 2026-03-27T14:24:25 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Mar 27 14:24:25 volumio volumio[1256]: info: MPD Permissions set
Mar 27 14:24:25 volumio volumio[1256]: info: MPD Permissions set
Mar 27 14:24:26 volumio systemd[1]: Started mpd.service - Music Player Daemon.
Mar 27 14:24:26 volumio sudo[1565]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:26 volumio sudo[1550]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:26 volumio volumio[1256]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2
Mar 27 14:24:26 volumio systemd[1]: Starting musicservicesshield.service - Shield Volumio Music Services in the User CPU Set...
Mar 27 14:24:26 volumio upmpdcli[1691]: writing RSA key
Mar 27 14:24:26 volumio volumio[1256]: info: Volumio called home
Mar 27 14:24:26 volumio volumio[1256]: info: Spotify config file written
Mar 27 14:24:26 volumio sudo[1703]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Mar 27 14:24:26 volumio sudo[1703]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:26 volumio volumio[1256]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 2
Mar 27 14:24:26 volumio volumio[1256]: info: Received Get System Info
Mar 27 14:24:26 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Mar 27 14:24:26 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Mar 27 14:24:26 volumio volumio[1256]: info: Discovery: Getting this device information
Mar 27 14:24:26 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:26 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:26 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Mar 27 14:24:26 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:26.513+05:30 level=INFO msg="system info for e82adf1afcfe62ba62c7e923c8b02651" deviceName=Volumio deviceVariant=volumio deviceModel= softwareVersion=4.103
Mar 27 14:24:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Mar 27 14:24:26 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Mar 27 14:24:26 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:26.535+05:30 level=INFO msg="bootstrapping state" hasInternet=true
Mar 27 14:24:26 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon.
Mar 27 14:24:26 volumio go-librespot[1710]: go-librespot daemon starting...
Mar 27 14:24:26 volumio sudo[1703]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:27 volumio bash[1719]: cset: --> shielding system active with
Mar 27 14:24:27 volumio bash[1719]: cset: "system" cpuset of CPUSPEC(1-3) with 171 tasks running
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=info msg="running go-librespot 0.7.1"
Mar 27 14:24:27 volumio bash[1719]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=debug msg="app state loaded"
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=debug msg="stored credentials not found"
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=info msg="api server listening on 127.0.0.1:9879"
Mar 27 14:24:27 volumio systemd[1]: Finished musicservicesshield.service - Shield Volumio Music Services in the User CPU Set.
Mar 27 14:24:27 volumio volumio[1256]: info: Discovery: adding ccd1327c-217f-41fd-87ea-83f2769b4eb8
Mar 27 14:24:27 volumio volumio[1256]: info: Discovery: Found device Volumio
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:27 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:27 volumio volumio[1256]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=info msg="zeroconf server listening on port 37365"
Mar 27 14:24:27 volumio go-librespot[1711]: time="2026-03-27T14:24:27+05:30" level=info msg="using avahi-daemon avahi 0.8 for mDNS service registration"
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Mar 27 14:24:27 volumio volumio[1256]: info: No need to fix Spotify hosts
Mar 27 14:24:27 volumio volumio[1256]: info: Received Get System Info
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Mar 27 14:24:27 volumio volumio[1256]: info: Discovery: Getting this device information
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:27 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:27 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Mar 27 14:24:28 volumio volumio[1256]: info: Discovery: this is already registered, ccd1327c-217f-41fd-87ea-83f2769b4eb8
Mar 27 14:24:28 volumio volumio[1256]: info: Discovery: Found device Volumio
Mar 27 14:24:28 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:28 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:28 volumio volumio-remote-updater[819]: Test mode disabled
Mar 27 14:24:28 volumio volumio-remote-updater[819]: Alpha mode disabled
Mar 27 14:24:28 volumio volumio-remote-updater[819]: Alpha legacy test mode disabled
Mar 27 14:24:28 volumio volumio[1256]: error: MPD error: The expression evaluated to a falsy value:
Mar 27 14:24:28 volumio volumio[1256]: assert.ok(self.idling)
Mar 27 14:24:28 volumio volumio[1256]: error: The expression evaluated to a falsy value:
Mar 27 14:24:28 volumio volumio[1256]: assert.ok(self.idling)
Mar 27 14:24:28 volumio volumio[1256]: info: MPD running with PID1587
Mar 27 14:24:28 volumio volumio[1256]: ,establishing connection
Mar 27 14:24:28 volumio volumio[1256]: error: updateQueue error: null
Mar 27 14:24:28 volumio volumio[1256]: info: Starting Shairport Sync
Mar 27 14:24:28 volumio volumio[1256]: info: Starting Shairport Sync
Mar 27 14:24:28 volumio volumio[1256]: info: Starting Shairport Sync
Mar 27 14:24:28 volumio sudo[1741]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Mar 27 14:24:28 volumio sudo[1741]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:28 volumio sudo[1742]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Mar 27 14:24:28 volumio sudo[1742]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:28 volumio volumio[1256]: error: updateQueue error: null
Mar 27 14:24:28 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Mar 27 14:24:28 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Mar 27 14:24:28 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Mar 27 14:24:28 volumio systemd[1]: shairport-sync.service: Consumed 1.569s CPU time.
Mar 27 14:24:28 volumio sudo[1744]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Mar 27 14:24:28 volumio sudo[1744]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:28 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Mar 27 14:24:29 volumio sudo[1741]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:29 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver...
Mar 27 14:24:29 volumio systemd[1]: shairport-sync.service: Deactivated successfully.
Mar 27 14:24:29 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Mar 27 14:24:29 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver.
Mar 27 14:24:29 volumio sudo[1744]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:29 volumio sudo[1742]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:29 volumio volumio[1256]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"FIXES
\n\n- Fix for missing PWM backlight module
\n- Fix for crash loop on Onboarding plugin
\n
\nNEW ADDITIONS
\n\n- Bump RPi/CM4 kernel to 6.12.74
\n- Bump Vivaldi to 7.5 for Kiosk Mode
\n
\n","title":"Update v4.119","updateavailable":true}
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Mar 27 14:24:29 volumio sudo[1667]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Mar 27 14:24:29 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:29.452+05:30 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=tidal error="could not open plugin config file for \"tidal\": open /data/configuration/music_service/tidal/config.json: no such file or directory"
Mar 27 14:24:29 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:29.453+05:30 level=WARN msg="could not read OAuth data for music provider" component=volumio provider=qobuz error="could not open plugin config file for \"qobuz\": open /data/configuration/music_service/qobuz/config.json: no such file or directory"
Mar 27 14:24:29 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:29.453+05:30 level=WARN msg="could not read username/password data for music provider" component=volumio provider=hi_res_audio error="could not open plugin config file for \"hi_res_audio\": open /data/configuration/music_service/hi_res_audio/config.json: no such file or directory"
Mar 27 14:24:29 volumio volumio[1256]: info: Shairport-Sync Started
Mar 27 14:24:29 volumio volumio[1256]: Error adding Membership: Error: addMembership EINVAL
Mar 27 14:24:29 volumio volumio[1256]: info: Shairport-Sync Started
Mar 27 14:24:29 volumio volumio[1256]: info: Shairport-Sync Started
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:29 volumio sudo[1767]: volumio : PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh
Mar 27 14:24:29 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:29 volumio volumio[1256]: info: Received Get System Info
Mar 27 14:24:29 volumio sudo[1767]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Mar 27 14:24:29 volumio volumio[1256]: info: Discovery: Getting this device information
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:29 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
Mar 27 14:24:29 volumio volumio[1256]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
Mar 27 14:24:29 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:29.855+05:30 level=INFO msg="enabling local network discovery"
Mar 27 14:24:29 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:29.876+05:30 level=INFO msg="enabling BLE discovery"
Mar 27 14:24:30 volumio systemd[1]: Starting setdatetime-helper.service - Time Synchronization Helper Service...
Mar 27 14:24:30 volumio systemd[1]: Reloading.
Mar 27 14:24:30 volumio volumio5-onboarding[1575]: time=2026-03-27T14:24:30.783+05:30 level=INFO msg="service successfully established" component=discovery/localnet
Mar 27 14:24:31 volumio systemd[1]: /etc/systemd/system/musicservicesshield.service:14: Failed to parse output specifier, ignoring: jouurnal
Mar 27 14:24:31 volumio volumio[1256]: info: go-librespot daemon successfully initialized
Mar 27 14:24:31 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Mar 27 14:24:31 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether.
Mar 27 14:24:31 volumio sudo[1767]: pam_unix(sudo:session): session closed for user root
Mar 27 14:24:31 volumio volumio[1256]: info: succeeded
Mar 27 14:24:31 volumio volumio[1256]: info: [yt-cast-receiver] DIAL server listening on port 8098
Mar 27 14:24:31 volumio volumio[1256]: info: CoreCommandRouter::volumioRetrievevolume
Mar 27 14:24:32 volumio volumio[1256]: info: VolumeController:: Volume=22 Mute =false
Mar 27 14:24:32 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:32 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:32 volumio volumio[1256]: info: CoreStateMachine::pushState
Mar 27 14:24:32 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:32 volumio volumio[1256]: info: CoreCommandRouter::volumioPushState
Mar 27 14:24:32 volumio volumio[1256]: info: Completed starting Core Plugins
Mar 27 14:24:32 volumio volumio[1256]: info: -------------------------------------------
Mar 27 14:24:32 volumio volumio[1256]: info: ----- MyVolumio plugins startup ----
Mar 27 14:24:32 volumio volumio[1256]: info: -------------------------------------------
Mar 27 14:24:32 volumio volumio[1256]: info: [MyVolumio PluginManager] Fetching plans data....
Mar 27 14:24:34 volumio volumio[1256]: info: Initializing connection to go-librespot Websocket
Mar 27 14:24:34 volumio go-librespot[1711]: time="2026-03-27T14:24:34+05:30" level=debug msg="new websocket client"
Mar 27 14:24:35 volumio volumio[1256]: info: Connection to go-librespot Websocket established
Mar 27 14:24:38 volumio go-librespot[1711]: time="2026-03-27T14:24:38+05:30" level=debug msg="obtained new client token: AAA3LaW+ivS7VEw9+Bl98cyjy7Wb8lt29HqNUtfzIn0XeZYjws2vzTyZOHsdyRv8W1IZpgW5xm6jRTSjizC74399XafVzSCxRFGzPz4YQuxz7iMfPxzYF2e+JdqwRN7Wd4zNaBiuIPJ2nl1jnRA6h0frU3G8KqFf7z7JF3efNiBXHvu+hGmJbElLJMKWiirNpYNvFKOX+/SZfyTIQtUl3Hdwde8fsYro/oC6LyqYhdf+wN/jwYdDN2QFvBc="
Mar 27 14:24:38 volumio go-librespot[1711]: time="2026-03-27T14:24:38+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070"
Mar 27 14:24:38 volumio go-librespot[1711]: time="2026-03-27T14:24:38+05:30" level=debug msg="completed keyexchange"
Mar 27 14:24:38 volumio go-librespot[1711]: time="2026-03-27T14:24:38+05:30" level=debug msg="completed challenge"
Mar 27 14:24:38 volumio go-librespot[1711]: time="2026-03-27T14:24:38+05:30" level=info msg="authenticated AP" username="31************************jq"
Mar 27 14:24:38 volumio systemd[1]: setdatetime-helper.service: Deactivated successfully.
Mar 27 14:24:38 volumio systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service.
Mar 27 14:24:38 volumio volumio[1256]: info: Getting Spotify volume
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=info msg="authenticated Login5" username="31************************jq"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=info msg="accepted zeroconf from Redmi Note 9 Pro" username="31************************jq"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="dealer connection opened"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=trace msg="starting accesspoint recv loop"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=trace msg="starting dealer recv loop"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=trace msg="received accesspoint ping"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="received connection id: ZjhkMmIwOTUtMzFl...NkFCNzBCNEM1OQ=="
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=trace msg="received accesspoint pong ack"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="put connect state because NEW_DEVICE"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="handling transfer player command from 99944a6fe14ac5acccf2c6bbd992a460ea01e5d1"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="resolved context of track" uri="spotify:album:1VH5NvVxODTTjqsipqKLrH"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=trace msg="fetched new page 0 with 20 items (list: 20)" uri="spotify:album:1VH5NvVxODTTjqsipqKLrH"
Mar 27 14:24:39 volumio go-librespot[1711]: time="2026-03-27T14:24:39+05:30" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=trace msg="emitting websocket event: will_play"
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411"
Mar 27 14:24:40 volumio volumio[1256]: info: Spotify volume: 100
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1392"
Mar 27 14:24:40 volumio volumio[1256]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=debug msg="selected format OGG_VORBIS_320 (d31a2de351e4ce7bcd38b4f592cdb9097f26611c)" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=debug msg="requested aes key for file d31a2de351e4ce7bcd38b4f592cdb9097f26611c, gid: 1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1149"
Mar 27 14:24:40 volumio go-librespot[1711]: time="2026-03-27T14:24:40+05:30" level=trace msg="found 2 cdn urls" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:40 volumio volumio[1256]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:album:1VH5NvVxODTTjqsipqKLrH","uri":"spotify:track:1cv52T9Qx0AJdkfPxpuy86","play_origin":"album"}}
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="fetched first chunk of 28, total size is 14535073 bytes" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="created new output device"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=info msg="loaded track \"Devasabhathalam\" (paused: false, position: 1ms, duration: 532583ms, prefetched: false)" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=trace msg="scheduling prefetch in 502s"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=trace msg="emitting websocket event: metadata"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="fetched chunk 1/27, size: 524288" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=trace msg="emitting websocket event: active"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="sending successful reply for dealer request"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="fetched chunk 2/27, size: 524288" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Mar 27 14:24:42 volumio go-librespot[1711]: time="2026-03-27T14:24:42+05:30" level=trace msg="emitting websocket event: playing"
Mar 27 14:24:43 volumio go-librespot[1711]: time="2026-03-27T14:24:43+05:30" level=debug msg="fetched chunk 3/27, size: 524288" uri="spotify:track:1cv52T9Qx0AJdkfPxpuy86"
Mar 27 14:24:43 volumio volumio[1256]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1cv52T9Qx0AJdkfPxpuy86","name":"Devasabhathalam","artist_names":["K. J. Yesudas","Raveendran","M. G. Sreekumar"],"album_name":"Best of Raveendran Master","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b50821d4954b106268490509","position":1,"duration":532583,"release_date":"year:2016 month:7 day:30","track_number":19,"disc_number":1}}
Mar 27 14:24:43 volumio volumio[1256]: SPOTIFY: received: {"type":"active","data":null}
Mar 27 14:24:43 volumio volumio[1256]: info: Aligning Spotify Volume to Volumio Volume
Mar 27 14:24:43 volumio volumio[1256]: info: CoreCommandRouter::volumioGetState
Mar 27 14:24:43 volumio volumio[1256]: info: CorePlayQueue::getTrack 0
Mar 27 14:24:43 volumio volumio[1256]: info: Setting Spotify Volume from Volumio: 22
Mar 27 14:24:43 volumio volumio[1256]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:album:1VH5NvVxODTTjqsipqKLrH","uri":"spotify:track:1cv52T9Qx0AJdkfPxpuy86","resume":false,"play_origin":"album"}}
Mar 27 14:24:43 volumio volumio[1256]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Mar 27 14:24:43 volumio volumio[1256]: TypeError: Cannot read properties of undefined (reading 'service')
Mar 27 14:24:43 volumio volumio[1256]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50)
Mar 27 14:24:43 volumio volumio[1256]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18)
Mar 27 14:24:43 volumio volumio[1256]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14)
Mar 27 14:24:43 volumio volumio[1256]: at WebSocket.emit (node:events:514:28)
Mar 27 14:24:43 volumio volumio[1256]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20)
Mar 27 14:24:43 volumio volumio[1256]: at Receiver.emit (node:events:514:28)
Mar 27 14:24:43 volumio volumio[1256]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14)
Mar 27 14:24:43 volumio volumio[1256]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10)
Mar 27 14:24:43 volumio volumio[1256]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16)
Mar 27 14:24:43 volumio volumio[1256]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10)
Mar 27 14:24:43 volumio volumio[1256]: at writeOrBuffer (node:internal/streams/writable:399:12)
Mar 27 14:24:43 volumio volumio[1256]: at _write (node:internal/streams/writable:340:10)
Mar 27 14:24:43 volumio volumio[1256]: at Writable.write (node:internal/streams/writable:344:10)
Mar 27 14:24:43 volumio volumio[1256]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35)
Mar 27 14:24:43 volumio volumio[1256]: at Socket.emit (node:events:514:28)
Mar 27 14:24:43 volumio volumio[1256]: at addChunk (node:internal/streams/readable:343:12)
Mar 27 14:24:43 volumio volumio[1256]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Mar 27 14:24:46 volumio sudo[1861]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-27 14:23'
Mar 27 14:24:46 volumio sudo[1861]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000)
PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)"
NAME="Raspbian GNU/Linux"
VERSION_ID="12"
VERSION="12 (bookworm)"
VERSION_CODENAME=bookworm
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="dc61260dec5515dafd2b634881860b4c46c919ff"
VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd"
VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2"
VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Fri Mar 6 16:46:58 UTC 2026"
VOLUMIO_VERSION="4.103"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="aa741395b8bfc648ff5d04e312f53d2c"