-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Thu 2025-05-29 18:47:20 CEST. -- May 29 18:47:00 volumio systemd-timedated[991]: Changed local time to Thu May 29 18:47:00 2025 May 29 18:47:00 volumio sudo[989]: pam_unix(sudo:session): session closed for user root May 29 18:47:00 volumio volumio-time-update[533]: volumio-time-update-util: System time updated successfully. May 29 18:47:00 volumio systemd[1]: Starting Daily apt download activities... May 29 18:47:00 volumio systemd[1]: Started Volumio Time Update Utility. May 29 18:47:00 volumio systemd[1]: Reached target Multi-User System. May 29 18:47:00 volumio systemd[1]: Reached target Graphical Interface. May 29 18:47:00 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... May 29 18:47:00 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 29 18:47:00 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. May 29 18:47:01 volumio volumio[896]: info: MYVOLUMIO Environment detected May 29 18:47:01 volumio volumio[896]: info: Plugin folders cleanup May 29 18:47:01 volumio volumio[896]: info: Scanning into folder /volumio/app/plugins/ May 29 18:47:01 volumio volumio[896]: info: Scanning category audio_interface May 29 18:47:01 volumio volumio[896]: info: Scanning category miscellanea May 29 18:47:01 volumio volumio[896]: info: Scanning category music_service May 29 18:47:01 volumio volumio[896]: info: Scanning category plugins.json May 29 18:47:01 volumio volumio[896]: info: Scanning category system_controller May 29 18:47:01 volumio volumio[896]: info: Scanning category user_interface May 29 18:47:01 volumio volumio[896]: info: Scanning into folder /data/plugins/ May 29 18:47:01 volumio volumio[896]: info: Scanning category audio_interface May 29 18:47:01 volumio volumio[896]: info: Scanning category music_service May 29 18:47:01 volumio volumio[896]: info: Plugin folders cleanup completed May 29 18:47:01 volumio volumio[896]: info: ------------------------------------------- May 29 18:47:01 volumio volumio[896]: info: ----- Core plugins startup ---- May 29 18:47:01 volumio volumio[896]: info: ------------------------------------------- May 29 18:47:01 volumio volumio[896]: info: Loading plugins from folder /volumio/app/plugins/ May 29 18:47:01 volumio volumio[896]: info: Adding plugin upnp to MyMusic Plugins May 29 18:47:01 volumio volumio[896]: info: Adding plugin airplay_emulation to MyMusic Plugins May 29 18:47:01 volumio volumio[896]: info: Adding plugin upnp_browser to MyMusic Plugins May 29 18:47:01 volumio volumio[896]: info: Loading plugins from folder /data/plugins/ May 29 18:47:01 volumio volumio-remote-updater[541]: [2025-05-29 18:47:01] [connect] Successful connection May 29 18:47:01 volumio volumio[896]: info: Loading plugin "system"... May 29 18:47:01 volumio volumio[896]: info: Loading plugin "appearance"... May 29 18:47:03 volumio volumio[896]: info: Loading plugin "network"... May 29 18:47:03 volumio volumio[896]: info: Refreshing Cached IP Addresses May 29 18:47:03 volumio sudo[1030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 18:47:03 volumio sudo[1030]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:03 volumio sudo[1033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 18:47:03 volumio sudo[1033]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:03 volumio sudo[1030]: pam_unix(sudo:session): session closed for user root May 29 18:47:03 volumio sudo[1033]: pam_unix(sudo:session): session closed for user root May 29 18:47:03 volumio volumio[896]: info: Loading plugin "services"... May 29 18:47:03 volumio volumio[896]: info: Loading plugin "alsa_controller"... May 29 18:47:03 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 18:47:03 volumio volumio[896]: info: Loading plugin "wizard"... May 29 18:47:03 volumio volumio[896]: info: Loading plugin "networkfs"... May 29 18:47:03 volumio volumio[896]: info: Starting Udev Watcher for removable devices May 29 18:47:03 volumio sudo[1073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=sdubg^@sdgm6awdHz,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.100/Pobrane/Muzyka/muzyka /mnt/NAS/Muzyka May 29 18:47:03 volumio sudo[1073]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:03 volumio sudo[1076]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Volumio,password=sdubg^@sdgm6awdHz,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.2.100/Pobrane/Muzyka/muzyka jazz /mnt/NAS/Muzyka_jazz May 29 18:47:03 volumio sudo[1076]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:04 volumio systemd[1]: apt-daily.service: Succeeded. May 29 18:47:04 volumio systemd[1]: Started Daily apt download activities. May 29 18:47:04 volumio volumio[896]: info: Ignoring mount for partition: boot May 29 18:47:04 volumio volumio[896]: info: Ignoring mount for partition: volumio May 29 18:47:04 volumio volumio[896]: info: Ignoring mount for partition: volumio_data May 29 18:47:04 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 29 18:47:04 volumio volumio[896]: info: Loading plugin "volumio_command_line_client"... May 29 18:47:04 volumio volumio[896]: info: Loading plugin "upnp"... May 29 18:47:04 volumio systemd[1]: Starting Daily apt upgrade and clean activities... May 29 18:47:04 volumio volumio[896]: info: [1748537224073] Starting Upmpd Daemon May 29 18:47:04 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 29 18:47:04 volumio volumio[896]: info: Loading plugin "my_music"... May 29 18:47:04 volumio volumio[896]: info: Loading plugin "mpd"... May 29 18:47:04 volumio kernel: Key type cifs.spnego registered May 29 18:47:04 volumio kernel: Key type cifs.idmap registered May 29 18:47:04 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. May 29 18:47:04 volumio kernel: CIFS: Attempting to mount //192.168.2.100/Pobrane/Muzyka/muzyka May 29 18:47:04 volumio kernel: cryptd: max_cpu_qlen set to 1000 May 29 18:47:04 volumio sudo[1073]: pam_unix(sudo:session): session closed for user root May 29 18:47:04 volumio kernel: CIFS: Attempting to mount //192.168.2.100/Pobrane/Muzyka/muzyka jazz May 29 18:47:04 volumio volumio[896]: info: Loading plugin "upnp_browser"... May 29 18:47:04 volumio sudo[1076]: pam_unix(sudo:session): session closed for user root May 29 18:47:05 volumio volumio[896]: info: Loading plugin "alarm-clock"... May 29 18:47:05 volumio volumio[896]: info: Loading plugin "airplay_emulation"... May 29 18:47:05 volumio volumio[896]: info: Starting Shairport Sync May 29 18:47:05 volumio volumio[896]: info: Loading plugin "last_100"... May 29 18:47:05 volumio volumio[896]: info: Loading plugin "webradio"... May 29 18:47:05 volumio volumio[896]: info: Loading plugin "i2s_dacs"... May 29 18:47:05 volumio volumio[896]: info: I2S DAC not set, start Auto-detection May 29 18:47:05 volumio volumio[896]: info: Loading plugin "volumiodiscovery"... May 29 18:47:05 volumio volumio[896]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 29 18:47:05 volumio volumio[896]: *** WARNING *** Please fix your application to use the native API of Avahi! May 29 18:47:05 volumio volumio[896]: *** WARNING *** For more information see May 29 18:47:05 volumio volumio[896]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 29 18:47:05 volumio volumio[896]: *** WARNING *** Please fix your application to use the native API of Avahi! May 29 18:47:05 volumio node[896]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 29 18:47:05 volumio volumio[896]: *** WARNING *** For more information see May 29 18:47:05 volumio node[896]: *** WARNING *** Please fix your application to use the native API of Avahi! May 29 18:47:05 volumio node[896]: *** WARNING *** For more information see May 29 18:47:05 volumio node[896]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 29 18:47:05 volumio node[896]: *** WARNING *** Please fix your application to use the native API of Avahi! May 29 18:47:05 volumio node[896]: *** WARNING *** For more information see May 29 18:47:05 volumio volumio[896]: info: Applying required configuration parameters for plugin volumiodiscovery May 29 18:47:05 volumio volumio[896]: info: Discovery: Started advertising with name: Volumio May 29 18:47:05 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 29 18:47:05 volumio volumio[896]: info: Loading plugin "spop"... May 29 18:47:06 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. May 29 18:47:06 volumio systemd[1]: Started Daily apt upgrade and clean activities. May 29 18:47:06 volumio systemd[1]: Startup finished in 14.851s (kernel) + 22.663s (userspace) = 37.514s. May 29 18:47:08 volumio volumio[896]: info: Loading plugin "outputs"... May 29 18:47:08 volumio volumio[896]: info: Loading plugin "albumart"... May 29 18:47:08 volumio volumio[896]: info: Plugin example_plugin is not enabled May 29 18:47:08 volumio volumio[896]: info: Loading plugin "inputs"... May 29 18:47:08 volumio volumio[896]: info: Loading plugin "updater_comm"... May 29 18:47:08 volumio volumio[896]: info: Plugin mpdemulation is not enabled May 29 18:47:08 volumio volumio[896]: info: Loading plugin "rest_api"... May 29 18:47:08 volumio volumio[896]: info: Loading plugin "websocket"... May 29 18:47:08 volumio volumio[896]: info: Starting Socket.io Server version 2.3.0 May 29 18:47:08 volumio volumio[896]: info: Loading plugin "fusiondsp"... May 29 18:47:08 volumio volumio[896]: Forking 3 albumart workers May 29 18:47:08 volumio volumio[896]: info: Applying required configuration parameters for plugin fusiondsp May 29 18:47:09 volumio volumio[896]: info: Loading plugin "rad357pl"... May 29 18:47:09 volumio volumio[896]: Starting albumart workers May 29 18:47:09 volumio volumio[896]: Starting albumart workers May 29 18:47:09 volumio volumio[896]: Starting albumart workers May 29 18:47:09 volumio volumio[896]: info: Applying required configuration parameters for plugin rad357pl May 29 18:47:09 volumio volumio[896]: info: [1748537229765] [rad357pl] API delay: 5 May 29 18:47:09 volumio volumio[896]: info: Loading i18n strings for locale pl May 29 18:47:09 volumio volumio[896]: Updating browse sources language May 29 18:47:09 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::initPlayerControls May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 29 18:47:10 volumio volumio[896]: Express server listening on port 3000 May 29 18:47:10 volumio volumio[896]: [Metrics] WebUI: 12s 651.94ms May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::resetVolumioState May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::getcurrentVolume May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioRetrievevolume May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:10 volumio volumio[896]: info: Volumio Network Manager: Network status updated: 1 May 29 18:47:10 volumio volumio[896]: info: Reloading queue from file May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::setRepeat null single undefined May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::pushState May 29 18:47:10 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioPushState May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::setRandom null May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::pushState May 29 18:47:10 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioPushState May 29 18:47:10 volumio volumio[896]: info: VolumeController:: Volume=17 Mute =false May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::pushState May 29 18:47:10 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioPushState May 29 18:47:10 volumio volumio[896]: info: CoreStateMachine::updateTrackBlock May 29 18:47:10 volumio volumio[896]: info: CorePlayQueue::getTrackBlock May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioRetrievevolume May 29 18:47:10 volumio volumio[896]: info: Setting Device type: Raspberry PI May 29 18:47:10 volumio volumio[896]: info: Completed loading Core Plugins May 29 18:47:10 volumio volumio[896]: info: Preparing to generate the ALSA configuration file May 29 18:47:10 volumio volumio[896]: info: Discovery: adding 3fe515ff-8757-49e8-874b-1b6dcea823f3 May 29 18:47:10 volumio volumio[896]: info: Discovery: Found device Volumio May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioGetState May 29 18:47:10 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:10 volumio volumio[896]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 29 18:47:10 volumio volumio[896]: info: Reading ALSA contributions from plugins. May 29 18:47:10 volumio volumio[896]: info: Asound.conf file unchanged, so no further update is needed May 29 18:47:10 volumio volumio[896]: info: Output device has changed, restarting MPD May 29 18:47:10 volumio volumio[896]: info: Output device has changed, restarting Shairport Sync May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:10 volumio sudo[1237]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 29 18:47:10 volumio sudo[1237]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:10 volumio sudo[1237]: pam_unix(sudo:session): session closed for user root May 29 18:47:10 volumio sudo[1239]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 29 18:47:10 volumio sudo[1239]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:10 volumio systemd[1]: Stopping Music Player Daemon... May 29 18:47:10 volumio volumio[896]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 29 18:47:10 volumio volumio[896]: info: ___________ START PLUGINS ___________ May 29 18:47:10 volumio volumio[896]: info: ControllerMpd::onStart: Initializing MPD May 29 18:47:10 volumio volumio[896]: info: Creating MPD Configuration file May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 18:47:10 volumio volumio[896]: info: [1748537230880] CoreMusicLibrary::Adding element Serwery Mediów May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 18:47:10 volumio sudo[1246]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 29 18:47:10 volumio sudo[1246]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:10 volumio sudo[1248]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 29 18:47:10 volumio sudo[1248]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:10 volumio sudo[1246]: pam_unix(sudo:session): session closed for user root May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:10 volumio volumio[896]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:10 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:11 volumio volumio[896]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 18:47:11 volumio volumio[896]: info: [1748537231028] CoreMusicLibrary::Adding element Last_100 May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 18:47:11 volumio volumio[896]: info: [1748537231032] CoreMusicLibrary::Adding element Webradio May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 18:47:11 volumio volumio[896]: info: Initializing BBC Radios May 29 18:47:11 volumio systemd[1]: mpd.service: Succeeded. May 29 18:47:11 volumio systemd[1]: Stopped Music Player Daemon. May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:11 volumio systemd[1]: Starting Music Player Daemon... May 29 18:47:11 volumio volumio[896]: info: Creating Spotify config file May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio sudo[1259]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 29 18:47:11 volumio sudo[1259]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:11 volumio volumio[896]: info: Loading i18n strings for locale pl May 29 18:47:11 volumio sudo[1259]: pam_unix(sudo:session): session closed for user root May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: FusionDsp - mixtype--------------------- Hardware May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 18:47:11 volumio volumio[896]: info: [1748537231288] CoreMusicLibrary::Adding element RADIO 357 May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 18:47:11 volumio volumio[896]: Cannot find translation for source RADIO 357 May 29 18:47:11 volumio volumio[896]: info: Volumio Calling Home May 29 18:47:11 volumio volumio[896]: info: Preparing to generate the ALSA configuration file May 29 18:47:11 volumio volumio[896]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 29 18:47:11 volumio volumio[896]: info: Reading ALSA contributions from plugins. May 29 18:47:11 volumio volumio[896]: info: MPD Permissions set May 29 18:47:11 volumio volumio[896]: info: MPD Permissions set May 29 18:47:11 volumio volumio[896]: info: VolumeController:: Volume=17 Mute =false May 29 18:47:11 volumio volumio[896]: info: CoreStateMachine::pushState May 29 18:47:11 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::volumioPushState May 29 18:47:11 volumio volumio[896]: info: Spotify config file written May 29 18:47:11 volumio sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 29 18:47:11 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:11 volumio volumio[896]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:11 volumio volumio[896]: info: No need to fix Spotify hosts May 29 18:47:11 volumio systemd[1]: Started go-librespot Daemon. May 29 18:47:11 volumio go-librespot[1277]: go-librespot daemon starting... May 29 18:47:11 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root May 29 18:47:11 volumio volumio[896]: info: Volumio called home May 29 18:47:11 volumio volumio[896]: info: Starting Shairport Sync May 29 18:47:11 volumio volumio[896]: info: Starting Shairport Sync May 29 18:47:11 volumio volumio[896]: info: Starting Shairport Sync May 29 18:47:11 volumio sudo[1287]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 29 18:47:11 volumio sudo[1287]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:11 volumio sudo[1289]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 29 18:47:11 volumio sudo[1289]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:11 volumio volumio[896]: info: CoreCommandRouter::volumioGetState May 29 18:47:11 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:11 volumio sudo[1292]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 29 18:47:11 volumio sudo[1292]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:11 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 29 18:47:11 volumio systemd[1]: shairport-sync.service: Succeeded. May 29 18:47:11 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 29 18:47:11 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 29 18:47:11 volumio sudo[1289]: pam_unix(sudo:session): session closed for user root May 29 18:47:11 volumio sudo[1287]: pam_unix(sudo:session): session closed for user root May 29 18:47:11 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 29 18:47:11 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 29 18:47:11 volumio systemd[1]: shairport-sync.service: Succeeded. May 29 18:47:11 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 29 18:47:11 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 29 18:47:12 volumio sudo[1292]: pam_unix(sudo:session): session closed for user root May 29 18:47:12 volumio volumio[896]: info: Asound.conf file unchanged, so no further update is needed May 29 18:47:12 volumio volumio[896]: info: Output device has changed, restarting MPD May 29 18:47:12 volumio volumio[896]: info: Output device has changed, restarting Shairport Sync May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:12 volumio sudo[1305]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 29 18:47:12 volumio sudo[1305]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:12 volumio sudo[1305]: pam_unix(sudo:session): session closed for user root May 29 18:47:12 volumio sudo[1307]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 29 18:47:12 volumio sudo[1307]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:12 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 29 18:47:12 volumio systemd[1]: mpd.service: Succeeded. May 29 18:47:12 volumio systemd[1]: Stopped Music Player Daemon. May 29 18:47:12 volumio volumio[896]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 29 18:47:12 volumio volumio[896]: info: Shairport-Sync Started May 29 18:47:12 volumio volumio[896]: Error adding Membership: Error: addMembership EINVAL May 29 18:47:12 volumio volumio[896]: info: Shairport-Sync Started May 29 18:47:12 volumio volumio[896]: info: Shairport-Sync Started May 29 18:47:12 volumio volumio[896]: info: MPD Permissions set May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio systemd[1]: Starting Music Player Daemon... May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:12 volumio volumio[896]: info: Starting Shairport Sync May 29 18:47:12 volumio sudo[1319]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 29 18:47:12 volumio sudo[1319]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:12 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 29 18:47:12 volumio systemd[1]: shairport-sync.service: Succeeded. May 29 18:47:12 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 29 18:47:12 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 29 18:47:12 volumio sudo[1319]: pam_unix(sudo:session): session closed for user root May 29 18:47:12 volumio volumio[896]: info: Shairport-Sync Started May 29 18:47:12 volumio sudo[1313]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 29 18:47:12 volumio sudo[1313]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:12 volumio sudo[1313]: pam_unix(sudo:session): session closed for user root May 29 18:47:12 volumio volumio[896]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 18:47:12 volumio volumio[896]: SPOTIFY: BQBVloK2pmocRRnZxhv0P0yuTk9oohcSfJSyIvgZhQxLnziCd5sAnavNC-49fy3bto28bWw3bekcZi8b_IO-pbrTV9g97tLN0eAXAyOs2AoO6aBLuNXhzh82LsZdApdKPiQggJs-x0MF0Ib-NLRZjD3sPU4D1Uz6KYVYR0lOcPRn32BhUhUtSD0jKYO-ASl7gKcOjKG7IXH-yD3P4fArUFNWSxyUxlrlkD8GHNXTdtGu_AiwqfrcCdi-G1Vca-mMpo6Fl81_f-HJjlFhm4hDNJrbyQ May 29 18:47:12 volumio volumio[896]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 29 18:47:12 volumio volumio[896]: info: New Spotify access token = BQBVloK2pmocRRnZxhv0P0yuTk9oohcSfJSyIvgZhQxLnziCd5sAnavNC-49fy3bto28bWw3bekcZi8b_IO-pbrTV9g97tLN0eAXAyOs2AoO6aBLuNXhzh82LsZdApdKPiQggJs-x0MF0Ib-NLRZjD3sPU4D1Uz6KYVYR0lOcPRn32BhUhUtSD0jKYO-ASl7gKcOjKG7IXH-yD3P4fArUFNWSxyUxlrlkD8GHNXTdtGu_AiwqfrcCdi-G1Vca-mMpo6Fl81_f-HJjlFhm4hDNJrbyQ May 29 18:47:12 volumio volumio[896]: info: Spotify credentials grant success - running version from March 24, 2019 May 29 18:47:12 volumio volumio[896]: SPOTIFY: User informations: {"country":"PL","display_name":"wavelet26","email":"wojciech.binek@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/wavelet26"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/wavelet26","id":"wavelet26","images":[],"product":"premium","type":"user","uri":"spotify:user:wavelet26"} May 29 18:47:12 volumio volumio[896]: info: Spotify Successfully logged in May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 29 18:47:12 volumio volumio[896]: info: [1748537232644] CoreMusicLibrary::Adding element Spotify May 29 18:47:12 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 29 18:47:12 volumio volumio[896]: Cannot find translation for source RADIO 357 May 29 18:47:12 volumio volumio[896]: Cannot find translation for source Spotify May 29 18:47:13 volumio mpd[1323]: May 29 18:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 29 18:47:13 volumio volumio[896]: info: camilladsp spawned new process with pid 1347, instance 1, run: true May 29 18:47:13 volumio volumio[896]: info: camilladsp service started and running in background, instance 1 May 29 18:47:13 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 29 18:47:13 volumio volumio[896]: info: FusionDsp - AAAAAAAAAAAAAA-> 44100 48000 88200 96000 <-AAAAAAAAAAAAA May 29 18:47:13 volumio volumio[896]: info: FusionDsp loaded May 29 18:47:13 volumio volumio[896]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 29 18:47:13 volumio sudo[1351]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service May 29 18:47:13 volumio sudo[1351]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:13 volumio volumio[896]: info: FusionDsp - Reporting Fusion DSP Enabled May 29 18:47:13 volumio volumio[896]: info: Adding Signal Path Element [object Object] May 29 18:47:13 volumio volumio[896]: info: Adding fusiondspeq DSP Signal Path Element May 29 18:47:13 volumio volumio[896]: info: FusionDsp - ---- installed callbackRead May 29 18:47:13 volumio volumio[896]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 29 18:47:13 volumio volumio[896]: info: FusionDsp - Effects disabled May 29 18:47:15 volumio systemd[1]: Started Music Player Daemon. May 29 18:47:15 volumio sudo[1307]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio sudo[1248]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio sudo[1239]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio volumio[896]: info: go-librespot daemon successfully initialized May 29 18:47:15 volumio volumio[896]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 May 29 18:47:15 volumio systemd[1]: Started FusionDsp Daemon. May 29 18:47:15 volumio sudo[1357]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 29 18:47:15 volumio sudo[1357]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:15 volumio sudo[1357]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio sudo[1359]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 29 18:47:15 volumio sudo[1359]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:15 volumio sudo[1359]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio sudo[1351]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio volumio[896]: info: Completed starting Core Plugins May 29 18:47:15 volumio volumio[896]: info: ------------------------------------------- May 29 18:47:15 volumio volumio[896]: info: ----- MyVolumio plugins startup ---- May 29 18:47:15 volumio volumio[896]: info: ------------------------------------------- May 29 18:47:15 volumio volumio[896]: info: [MyVolumio PluginManager] Fetching plans data.... May 29 18:47:15 volumio go-librespot[1277]: time="2025-05-29T18:47:15+02:00" level=info msg="running go-librespot 0.2.0" May 29 18:47:15 volumio go-librespot[1277]: time="2025-05-29T18:47:15+02:00" level=debug msg="app state loaded" May 29 18:47:15 volumio go-librespot[1277]: time="2025-05-29T18:47:15+02:00" level=info msg="api server listening on 127.0.0.1:9879" May 29 18:47:15 volumio volumio[896]: error: MPD error: The expression evaluated to a falsy value: May 29 18:47:15 volumio volumio[896]: assert.ok(self.idling) May 29 18:47:15 volumio volumio[896]: error: The expression evaluated to a falsy value: May 29 18:47:15 volumio volumio[896]: assert.ok(self.idling) May 29 18:47:15 volumio volumio[896]: error: FusionDsp - WebSocket error: [object Object] May 29 18:47:15 volumio volumio[896]: info: MPD running with PID1323 May 29 18:47:15 volumio volumio[896]: ,establishing connection May 29 18:47:15 volumio volumio[896]: error: MPD error: The expression evaluated to a falsy value: May 29 18:47:15 volumio volumio[896]: assert.ok(self.idling) May 29 18:47:15 volumio volumio[896]: error: The expression evaluated to a falsy value: May 29 18:47:15 volumio volumio[896]: assert.ok(self.idling) May 29 18:47:15 volumio volumio[896]: error: MPD error: The expression evaluated to a falsy value: May 29 18:47:15 volumio volumio[896]: assert.ok(self.idling) May 29 18:47:15 volumio volumio[896]: error: The expression evaluated to a falsy value: May 29 18:47:15 volumio volumio[896]: assert.ok(self.idling) May 29 18:47:15 volumio volumio[896]: error: updateQueue error: null May 29 18:47:15 volumio kernel: usb 1-1.3: 2:1: cannot get freq at ep 0x1 May 29 18:47:15 volumio kernel: usb 1-1.3: 2:1: cannot get freq at ep 0x1 May 29 18:47:15 volumio sudo[1371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 29 18:47:15 volumio sudo[1371]: pam_unix(sudo:session): session opened for user root by (uid=0) May 29 18:47:15 volumio systemd[1]: Started UPnP Renderer front-end to MPD. May 29 18:47:15 volumio sudo[1371]: pam_unix(sudo:session): session closed for user root May 29 18:47:15 volumio volumio[896]: info: Upmpdcli Daemon Started May 29 18:47:16 volumio volumio[1373]: Generating RSA private key, 4096 bit long modulus (2 primes) May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=info msg="zeroconf server listening on port 45849" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="obtained new client token: AABXVznWILf2x6arqW3IstHJH41X4AGRUcP5CxXHwcTF3kNpudMGwYkGsL5z2fvwz+Gb20tjHYQCfrCXbXeWvcBcYnW1R9XMbZVl3FoOHlnqmmsiN5AyDpgjjO0PxWrwsn+eTqtZGPCBVQ/aQWsAMQS1mmhbBW+gdX5hJ9ZPiZafFrHswoUV9kE4l5fKTE9m/Tf3b73UAG+H1LSpI3Ntz0sZhklkxf0oNR+mSij81b3k1b6Basho7Hiyxg==" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070" May 29 18:47:16 volumio systemd[1]: systemd-fsckd.service: Succeeded. May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="completed keyexchange" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="completed challenge" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=info msg="authenticated AP as wavelet26" May 29 18:47:16 volumio volumio[1373]: ..++++ May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=info msg="authenticated Login5 as wavelet26" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="initializing zeroconf session, username: wavelet26" May 29 18:47:16 volumio volumio-remote-updater[541]: [2025-05-29 18:47:16] [connect] Successful connection May 29 18:47:16 volumio volumio-remote-updater[541]: [2025-05-29 18:47:16] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748537236 101 May 29 18:47:16 volumio volumio[896]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 3 May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="dealer connection opened" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=trace msg="starting accesspoint recv loop" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=trace msg="starting dealer recv loop" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=trace msg="received accesspoint ping" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=debug msg="received connection id: MzBlMjY4NDEtOTcwMC00YzY1LTlmOTAtMGJmYzdmOGEyNGFmK2RlYWxlcit0Y3A6Ly8wYWNhNTk3OS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQURERkU2MEM5Q0FFNTk4MTYwRkQ3NkQxQUM4N0YzN0U2MzQzQkJGQkM0NTRDMkI4OUYxMENGOTU1OUZENkFBNQ==" May 29 18:47:16 volumio go-librespot[1277]: time="2025-05-29T18:47:16+02:00" level=trace msg="received accesspoint pong ack" May 29 18:47:17 volumio go-librespot[1277]: time="2025-05-29T18:47:17+02:00" level=debug msg="put connect state because NEW_DEVICE" May 29 18:47:17 volumio volumio[1373]: ....++++ May 29 18:47:17 volumio volumio[1373]: e is 65537 (0x010001) May 29 18:47:17 volumio volumio[1373]: writing RSA key May 29 18:47:18 volumio volumio[896]: info: Initializing connection to go-librespot Websocket May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="handling transfer player command from 6ff58d252da2f677b6634f94d90c9dd022c25e8f" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="resolved context of track" uri="spotify:artist:2ApaG60P4r0yhBoDCGD8YG" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:2ApaG60P4r0yhBoDCGD8YG" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=trace msg="fetched new page 1 with 38 items (list: 48)" uri="spotify:artist:2ApaG60P4r0yhBoDCGD8YG" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="shuffled context with seed 9398763497700016272 (len: 48, keep: 13)" uri="spotify:artist:2ApaG60P4r0yhBoDCGD8YG" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="loading track (paused: false, position: 3525ms)" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="new websocket client" May 29 18:47:18 volumio volumio[896]: info: Connection to go-librespot Websocket established May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=trace msg="emitting websocket event: will_play" May 29 18:47:18 volumio volumio[896]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:52Bg6oaos7twR7IUtEpqcE","play_origin":"free-tier-artist"}} May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="selected format OGG_VORBIS_320 (50d72d60da0fb6ac41f9c31e36319664e514d316)" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="requested aes key for file 50d72d60da0fb6ac41f9c31e36319664e514d316, gid: 52Bg6oaos7twR7IUtEpqcE" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1336" May 29 18:47:18 volumio go-librespot[1277]: time="2025-05-29T18:47:18+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1112" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="fetched first chunk of 12, total size is 5791124 bytes" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=trace msg="seek to 3525ms (diff: 99ms, samples: 155452, bytes: 140676)" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="created new output device" May 29 18:47:19 volumio volumio[896]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 29 18:47:19 volumio volumio[896]: info: FusionDsp - ---- read samplerate from file: 44100 May 29 18:47:19 volumio volumio[896]: info: camilladsp stopping service pid 1347... May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=info msg="loaded track \"Between The Bars\" (paused: false, position: 3525ms, duration: 141280ms, prefetched: false)" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:19 volumio volumio[896]: info: camilladsp service terminated, instance 1 May 29 18:47:19 volumio volumio[896]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 29 18:47:19 volumio volumio[896]: info: FusionDsp - Effects disabled May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=trace msg="scheduling prefetch in 108s" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=trace msg="emitting websocket event: metadata" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=trace msg="emitting websocket event: active" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="sending successful reply for dealer request" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=trace msg="emitting websocket event: playing" May 29 18:47:19 volumio go-librespot[1277]: time="2025-05-29T18:47:19+02:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:52Bg6oaos7twR7IUtEpqcE" May 29 18:47:19 volumio volumio[896]: info: camilladsp service started and running in background, instance 1 May 29 18:47:19 volumio volumio[896]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 29 18:47:19 volumio volumio[896]: info: FusionDsp - ---- read samplerate from file: 44100 May 29 18:47:19 volumio volumio[896]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 29 18:47:19 volumio volumio[896]: info: FusionDsp - Effects disabled May 29 18:47:19 volumio volumio[896]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:52Bg6oaos7twR7IUtEpqcE","name":"Between The Bars","artist_names":["Elliott Smith"],"album_name":"Either/Or","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ea7ac80765aa4549d18a27b9","position":3525,"duration":141280,"release_date":"year:1997 month:2 day:25","track_number":4,"disc_number":1}} May 29 18:47:19 volumio volumio[896]: SPOTIFY: received: {"type":"active","data":null} May 29 18:47:19 volumio volumio[896]: info: Aligning Spotify Volume to Volumio Volume May 29 18:47:19 volumio volumio[896]: info: CoreCommandRouter::volumioGetState May 29 18:47:19 volumio volumio[896]: info: CorePlayQueue::getTrack 0 May 29 18:47:19 volumio volumio[896]: info: Setting Spotify Volume from Volumio: 17 May 29 18:47:19 volumio volumio[896]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:52Bg6oaos7twR7IUtEpqcE","play_origin":"free-tier-artist"}} May 29 18:47:19 volumio volumio[896]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 18:47:19 volumio volumio[896]: TypeError: Cannot read property 'service' of undefined May 29 18:47:19 volumio volumio[896]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) May 29 18:47:19 volumio volumio[896]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) May 29 18:47:19 volumio volumio[896]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) May 29 18:47:19 volumio volumio[896]: at WebSocket.emit (events.js:315:20) May 29 18:47:19 volumio volumio[896]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 29 18:47:19 volumio volumio[896]: at Receiver.emit (events.js:315:20) May 29 18:47:19 volumio volumio[896]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 29 18:47:19 volumio volumio[896]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 29 18:47:19 volumio volumio[896]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 29 18:47:19 volumio volumio[896]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 29 18:47:19 volumio volumio[896]: at writeOrBuffer (internal/streams/writable.js:358:12) May 29 18:47:19 volumio volumio[896]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 29 18:47:19 volumio volumio[896]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 29 18:47:19 volumio volumio[896]: at Socket.emit (events.js:315:20) May 29 18:47:19 volumio volumio[896]: at addChunk (internal/streams/readable.js:309:12) May 29 18:47:19 volumio volumio[896]: at readableAddChunk (internal/streams/readable.js:284:9) May 29 18:47:19 volumio volumio[896]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 29 18:47:20 volumio sudo[1421]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-29 18:46 May 29 18:47:20 volumio sudo[1421]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"