-- Logs begin at Sun 2025-03-02 15:56:16 CET, end at Wed 2025-03-05 14:28:17 CET. -- Mar 05 14:27:59 volumio systemd-timedated[1008]: Changed local time to Wed Mar 5 14:27:59 2025 Mar 05 14:27:59 volumio sudo[1006]: pam_unix(sudo:session): session closed for user root Mar 05 14:27:59 volumio volumio-time-update[584]: volumio-time-update-util: System time updated successfully. Mar 05 14:27:59 volumio systemd[1]: Started Volumio Time Update Utility. Mar 05 14:27:59 volumio systemd[1]: Reached target Multi-User System. Mar 05 14:27:59 volumio systemd[1]: Reached target Graphical Interface. Mar 05 14:27:59 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 05 14:27:59 volumio systemd[1]: Starting Daily apt download activities... Mar 05 14:27:59 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 05 14:27:59 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 05 14:28:00 volumio systemd[1]: apt-daily.service: Succeeded. Mar 05 14:28:00 volumio systemd[1]: Started Daily apt download activities. Mar 05 14:28:00 volumio volumio[963]: info: MYVOLUMIO Environment detected Mar 05 14:28:00 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Mar 05 14:28:00 volumio volumio[963]: info: Plugin folders cleanup Mar 05 14:28:00 volumio volumio[963]: info: Scanning into folder /volumio/app/plugins/ Mar 05 14:28:00 volumio volumio[963]: info: Scanning category audio_interface Mar 05 14:28:00 volumio volumio[963]: info: Scanning category miscellanea Mar 05 14:28:00 volumio volumio[963]: info: Scanning category music_service Mar 05 14:28:00 volumio volumio[963]: info: Scanning category plugins.json Mar 05 14:28:00 volumio volumio[963]: info: Scanning category system_controller Mar 05 14:28:00 volumio volumio[963]: info: Scanning category user_interface Mar 05 14:28:00 volumio volumio[963]: info: Scanning into folder /data/plugins/ Mar 05 14:28:00 volumio volumio[963]: info: Scanning category music_service Mar 05 14:28:00 volumio volumio[963]: info: Plugin folders cleanup completed Mar 05 14:28:00 volumio volumio[963]: info: ------------------------------------------- Mar 05 14:28:00 volumio volumio[963]: info: ----- Core plugins startup ---- Mar 05 14:28:00 volumio volumio[963]: info: ------------------------------------------- Mar 05 14:28:00 volumio volumio[963]: info: Loading plugins from folder /volumio/app/plugins/ Mar 05 14:28:00 volumio volumio[963]: info: Adding plugin upnp to MyMusic Plugins Mar 05 14:28:00 volumio volumio[963]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 05 14:28:00 volumio volumio[963]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 05 14:28:00 volumio volumio[963]: info: Loading plugins from folder /data/plugins/ Mar 05 14:28:00 volumio volumio[963]: info: Loading plugin "system"... Mar 05 14:28:00 volumio volumio[963]: info: Loading plugin "appearance"... Mar 05 14:28:01 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Mar 05 14:28:01 volumio systemd[1]: Started Daily apt upgrade and clean activities. Mar 05 14:28:01 volumio systemd[1]: Startup finished in 13.529s (kernel) + 23.017s (userspace) = 36.547s. Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "network"... Mar 05 14:28:02 volumio volumio[963]: info: Refreshing Cached IP Addresses Mar 05 14:28:02 volumio sudo[1119]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 14:28:02 volumio sudo[1119]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:02 volumio sudo[1119]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:02 volumio sudo[1121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 14:28:02 volumio sudo[1121]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:02 volumio sudo[1121]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "services"... Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "alsa_controller"... Mar 05 14:28:02 volumio sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 05 14:28:02 volumio sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:02 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "wizard"... Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "networkfs"... Mar 05 14:28:02 volumio volumio[963]: info: Starting Udev Watcher for removable devices Mar 05 14:28:02 volumio sudo[1147]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=buster,password=Dummheit13,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.5/Multimedia/Musik /mnt/NAS/TrueNAS Mar 05 14:28:02 volumio sudo[1147]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:02 volumio volumio[963]: info: Ignoring mount for partition: boot Mar 05 14:28:02 volumio volumio[963]: info: Ignoring mount for partition: volumio Mar 05 14:28:02 volumio volumio[963]: info: Ignoring mount for partition: volumio_data Mar 05 14:28:02 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "volumio_command_line_client"... Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "upnp"... Mar 05 14:28:02 volumio volumio[963]: info: [1741181282560] Starting Upmpd Daemon Mar 05 14:28:02 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "my_music"... Mar 05 14:28:02 volumio volumio[963]: info: Loading plugin "mpd"... Mar 05 14:28:02 volumio kernel: Key type cifs.spnego registered Mar 05 14:28:02 volumio kernel: Key type cifs.idmap registered Mar 05 14:28:02 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. Mar 05 14:28:02 volumio kernel: CIFS: Attempting to mount //192.168.1.5/Multimedia/Musik Mar 05 14:28:02 volumio kernel: cryptd: max_cpu_qlen set to 1000 Mar 05 14:28:03 volumio sudo[1130]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:03 volumio volumio[963]: info: Loading plugin "upnp_browser"... Mar 05 14:28:03 volumio sudo[1147]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:03 volumio volumio[963]: info: Loading plugin "alarm-clock"... Mar 05 14:28:03 volumio volumio[963]: info: Loading plugin "airplay_emulation"... Mar 05 14:28:03 volumio volumio[963]: info: Starting Shairport Sync Mar 05 14:28:03 volumio volumio[963]: info: Loading plugin "last_100"... Mar 05 14:28:03 volumio volumio[963]: info: Loading plugin "webradio"... Mar 05 14:28:04 volumio volumio[963]: info: Loading plugin "i2s_dacs"... Mar 05 14:28:04 volumio volumio[963]: info: I2S DAC not set, start Auto-detection Mar 05 14:28:04 volumio volumio[963]: info: Loading plugin "volumiodiscovery"... Mar 05 14:28:04 volumio volumio[963]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 14:28:04 volumio volumio[963]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 14:28:04 volumio volumio[963]: *** WARNING *** For more information see Mar 05 14:28:04 volumio volumio[963]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 14:28:04 volumio volumio[963]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 14:28:04 volumio volumio[963]: *** WARNING *** For more information see Mar 05 14:28:04 volumio node[963]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 05 14:28:04 volumio node[963]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 14:28:04 volumio node[963]: *** WARNING *** For more information see Mar 05 14:28:04 volumio node[963]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 05 14:28:04 volumio node[963]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 05 14:28:04 volumio node[963]: *** WARNING *** For more information see Mar 05 14:28:04 volumio volumio[963]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 05 14:28:04 volumio volumio[963]: info: Discovery: Started advertising with name: Volumio Mar 05 14:28:04 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 05 14:28:04 volumio volumio[963]: info: Loading plugin "spop"... Mar 05 14:28:05 volumio volumio-remote-updater[591]: [2025-03-05 14:28:05] [connect] Successful connection Mar 05 14:28:06 volumio volumio[963]: info: Loading plugin "outputs"... Mar 05 14:28:06 volumio volumio[963]: info: Loading plugin "albumart"... Mar 05 14:28:06 volumio volumio[963]: info: Plugin example_plugin is not enabled Mar 05 14:28:06 volumio volumio[963]: info: Loading plugin "inputs"... Mar 05 14:28:06 volumio volumio[963]: info: Loading plugin "updater_comm"... Mar 05 14:28:06 volumio volumio[963]: info: Plugin mpdemulation is not enabled Mar 05 14:28:06 volumio volumio[963]: info: Loading plugin "rest_api"... Mar 05 14:28:06 volumio volumio[963]: info: Loading plugin "websocket"... Mar 05 14:28:06 volumio volumio[963]: info: Starting Socket.io Server version 2.3.0 Mar 05 14:28:06 volumio volumio[963]: info: Loading i18n strings for locale de Mar 05 14:28:06 volumio volumio[963]: Updating browse sources language Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:28:06 volumio volumio[963]: Forking 3 albumart workers Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::initPlayerControls Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 14:28:06 volumio volumio[963]: Express server listening on port 3000 Mar 05 14:28:06 volumio volumio[963]: [Metrics] WebUI: 9s 214.07ms Mar 05 14:28:06 volumio volumio[963]: info: CoreStateMachine::resetVolumioState Mar 05 14:28:06 volumio volumio[963]: info: CoreStateMachine::getcurrentVolume Mar 05 14:28:06 volumio volumio[963]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:07 volumio volumio[963]: info: Volumio Network Manager: Network status updated: 2 Mar 05 14:28:07 volumio volumio-remote-updater[591]: [2025-03-05 14:28:07] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741181285 101 Mar 05 14:28:07 volumio volumio[963]: 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: 1 Mar 05 14:28:07 volumio volumio[963]: Unable to parse: Mar 05 14:28:07 volumio volumio[963]: Simple mixer control 'PCM',0 Mar 05 14:28:07 volumio volumio[963]: Capabilities: pswitch pswitch-joined Mar 05 14:28:07 volumio volumio[963]: Playback channels: Mono Mar 05 14:28:07 volumio volumio[963]: Mono: Playback [on] Mar 05 14:28:07 volumio volumio[963]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Mar 05 14:28:07 volumio volumio[963]: info: Reloading queue from file Mar 05 14:28:07 volumio volumio[963]: info: Setting Device type: Raspberry PI Mar 05 14:28:07 volumio volumio[963]: info: CoreStateMachine::setRepeat false single undefined Mar 05 14:28:07 volumio volumio[963]: info: CoreStateMachine::pushState Mar 05 14:28:07 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::volumioPushState Mar 05 14:28:07 volumio volumio[963]: info: CoreStateMachine::setRandom null Mar 05 14:28:07 volumio volumio[963]: info: CoreStateMachine::pushState Mar 05 14:28:07 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::volumioPushState Mar 05 14:28:07 volumio volumio[963]: Unable to parse: Mar 05 14:28:07 volumio volumio[963]: Simple mixer control 'PCM',0 Mar 05 14:28:07 volumio volumio[963]: Capabilities: pswitch pswitch-joined Mar 05 14:28:07 volumio volumio[963]: Playback channels: Mono Mar 05 14:28:07 volumio volumio[963]: Mono: Playback [on] Mar 05 14:28:07 volumio volumio[963]: info: VolumeController:: Volume=undefined Mute =false Mar 05 14:28:07 volumio volumio[963]: info: CoreStateMachine::pushState Mar 05 14:28:07 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::volumioPushState Mar 05 14:28:07 volumio volumio[963]: info: CoreStateMachine::updateTrackBlock Mar 05 14:28:07 volumio volumio[963]: info: CorePlayQueue::getTrackBlock Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 14:28:07 volumio volumio[963]: info: Completed loading Core Plugins Mar 05 14:28:07 volumio volumio[963]: info: Preparing to generate the ALSA configuration file Mar 05 14:28:07 volumio volumio[963]: info: Discovery: adding aef04afc-e7ed-4364-b33d-9933941394c0 Mar 05 14:28:07 volumio volumio[963]: info: Discovery: Found device Volumio Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::volumioGetState Mar 05 14:28:07 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:07 volumio volumio[963]: Unable to parse: Mar 05 14:28:07 volumio volumio[963]: Simple mixer control 'PCM',0 Mar 05 14:28:07 volumio volumio[963]: Capabilities: pswitch pswitch-joined Mar 05 14:28:07 volumio volumio[963]: Playback channels: Mono Mar 05 14:28:07 volumio volumio[963]: Mono: Playback [on] Mar 05 14:28:07 volumio volumio[963]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Mar 05 14:28:07 volumio volumio[963]: info: Asound.conf file unchanged, so no further update is needed Mar 05 14:28:07 volumio volumio[963]: info: Output device has changed, restarting MPD Mar 05 14:28:07 volumio volumio[963]: info: Output device has changed, restarting Shairport Sync Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:07 volumio sudo[1234]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 14:28:07 volumio sudo[1234]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:07 volumio sudo[1236]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 14:28:07 volumio sudo[1236]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:07 volumio sudo[1234]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:07 volumio systemd[1]: Stopping Music Player Daemon... Mar 05 14:28:07 volumio volumio[963]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 14:28:07 volumio volumio[963]: info: ___________ START PLUGINS ___________ Mar 05 14:28:07 volumio volumio[963]: info: ControllerMpd::onStart: Initializing MPD Mar 05 14:28:07 volumio volumio[963]: info: Creating MPD Configuration file Mar 05 14:28:07 volumio volumio[963]: Starting albumart workers Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:28:07 volumio volumio[963]: info: [1741181287818] CoreMusicLibrary::Adding element Medienserver Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:28:07 volumio sudo[1245]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 14:28:07 volumio sudo[1245]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:07 volumio sudo[1243]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 14:28:07 volumio sudo[1243]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:07 volumio systemd[1]: mpd.service: Succeeded. Mar 05 14:28:07 volumio sudo[1243]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:07 volumio systemd[1]: Stopped Music Player Daemon. Mar 05 14:28:07 volumio volumio[963]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:07 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:07 volumio systemd[1]: Starting Music Player Daemon... Mar 05 14:28:08 volumio volumio[963]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:28:08 volumio volumio[963]: info: [1741181288038] CoreMusicLibrary::Adding element Last_100 Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:28:08 volumio volumio[963]: info: [1741181288044] CoreMusicLibrary::Adding element Webradio Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:28:08 volumio volumio[963]: Starting albumart workers Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 14:28:08 volumio volumio[963]: info: Initializing BBC Radios Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 14:28:08 volumio sudo[1251]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:08 volumio sudo[1251]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:08 volumio sudo[1251]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:08 volumio volumio[963]: info: Creating Spotify config file Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:08 volumio volumio[963]: Starting albumart workers Mar 05 14:28:08 volumio volumio[963]: info: Volumio Calling Home Mar 05 14:28:08 volumio volumio[963]: info: MPD Permissions set Mar 05 14:28:08 volumio volumio[963]: info: MPD Permissions set Mar 05 14:28:08 volumio volumio[963]: Unable to parse: Mar 05 14:28:08 volumio volumio[963]: Simple mixer control 'PCM',0 Mar 05 14:28:08 volumio volumio[963]: Capabilities: pswitch pswitch-joined Mar 05 14:28:08 volumio volumio[963]: Playback channels: Mono Mar 05 14:28:08 volumio volumio[963]: Mono: Playback [on] Mar 05 14:28:08 volumio volumio[963]: info: VolumeController:: Volume=undefined Mute =false Mar 05 14:28:08 volumio volumio[963]: info: CoreStateMachine::pushState Mar 05 14:28:08 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:08 volumio volumio[963]: info: CoreCommandRouter::volumioPushState Mar 05 14:28:09 volumio volumio[963]: info: Volumio called home Mar 05 14:28:09 volumio volumio[963]: info: Spotify config file written Mar 05 14:28:09 volumio sudo[1279]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 14:28:09 volumio sudo[1279]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:09 volumio volumio[963]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio systemd[1]: Started go-librespot Daemon. Mar 05 14:28:09 volumio go-librespot[1283]: go-librespot daemon starting... Mar 05 14:28:09 volumio sudo[1279]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:28:09 volumio volumio[963]: info: No need to fix Spotify hosts Mar 05 14:28:09 volumio volumio[963]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 05 14:28:09 volumio volumio[963]: SPOTIFY: BQCuxU-uyp5ICGUpLI3Xwnme8gm7LhX44vbEffVXqHJxmZOLuH7DOFW-4DS9no7FoZvOr6YbpGcPFchmV1vrp9SukPPw9iXFOpNiORnKk1jEhLWVY2kKQxMRVhKZIe6NQp5FP3ELaB4izEHHLiPI73cHMYER6uu8npkGBXavqa27UZgO9HnzPCVRaGEwCX3U_J3akLhd_9U1H7VEfCqxgRyX6lY3tskEImG3GWCDHMntfXX62NdkrblsnCdNVTPnyhU4OA84TBRqkRnSdEHg1A Mar 05 14:28:09 volumio volumio[963]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 05 14:28:09 volumio volumio[963]: info: New Spotify access token = BQCuxU-uyp5ICGUpLI3Xwnme8gm7LhX44vbEffVXqHJxmZOLuH7DOFW-4DS9no7FoZvOr6YbpGcPFchmV1vrp9SukPPw9iXFOpNiORnKk1jEhLWVY2kKQxMRVhKZIe6NQp5FP3ELaB4izEHHLiPI73cHMYER6uu8npkGBXavqa27UZgO9HnzPCVRaGEwCX3U_J3akLhd_9U1H7VEfCqxgRyX6lY3tskEImG3GWCDHMntfXX62NdkrblsnCdNVTPnyhU4OA84TBRqkRnSdEHg1A Mar 05 14:28:09 volumio volumio[963]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 05 14:28:09 volumio volumio[963]: info: Starting Shairport Sync Mar 05 14:28:09 volumio volumio[963]: info: Starting Shairport Sync Mar 05 14:28:09 volumio volumio[963]: info: Starting Shairport Sync Mar 05 14:28:09 volumio sudo[1315]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 14:28:09 volumio sudo[1315]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::volumioGetState Mar 05 14:28:09 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:09 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 05 14:28:09 volumio sudo[1320]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 14:28:09 volumio sudo[1320]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:09 volumio systemd[1]: shairport-sync.service: Succeeded. Mar 05 14:28:09 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 05 14:28:09 volumio sudo[1317]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 05 14:28:09 volumio sudo[1317]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:09 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 05 14:28:09 volumio sudo[1315]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:09 volumio go-librespot[1283]: time="2025-03-05T14:28:09+01:00" level=info msg="running go-librespot 0.1.3" Mar 05 14:28:09 volumio go-librespot[1283]: time="2025-03-05T14:28:09+01:00" level=debug msg="app state loaded" Mar 05 14:28:09 volumio sudo[1317]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:09 volumio go-librespot[1283]: time="2025-03-05T14:28:09+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 05 14:28:09 volumio sudo[1320]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:09 volumio volumio[963]: info: Shairport-Sync Started Mar 05 14:28:09 volumio volumio[963]: Error adding Membership: Error: addMembership EINVAL Mar 05 14:28:09 volumio volumio[963]: info: Shairport-Sync Started Mar 05 14:28:09 volumio volumio[963]: info: Shairport-Sync Started Mar 05 14:28:09 volumio volumio[963]: SPOTIFY: User informations: {"country":"DE","display_name":"bustertrumpf","email":"nico@raecher-der-enterbten.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/bustertrumpf"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/bustertrumpf","id":"bustertrumpf","images":[],"product":"premium","type":"user","uri":"spotify:user:bustertrumpf"} Mar 05 14:28:09 volumio volumio[963]: info: Spotify Successfully logged in Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:28:09 volumio volumio[963]: info: [1741181289976] CoreMusicLibrary::Adding element Spotify Mar 05 14:28:09 volumio volumio[963]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:28:09 volumio volumio[963]: Cannot find translation for source Spotify Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01: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]" Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01: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]" Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01: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]" Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01:00" level=info msg="zeroconf server listening on port 44735" Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01:00" level=debug msg="obtained new client token: AABQghffSBNht3tcHzpRGDqcZ3iMELL6sWg2ZfDrqw+xdmtggX/hFRCIUt7EmCRC7YBnCm31EcEpzz65i2vf77eYdiYGiyhbZajIETu0HSBpO+FaL3x6T9LmrbpApXJcejpvxXIw8YycDJrqb5MrMtMH1lUbVlGOChIL4jXamd7vKPS3GbIYcB+PxJ4hx4WlZ7Z3K8ospoNRFFPJamTe3xbtst+cVIjfS9o8Uuy4qLa8JlzZhrt5fdx6mA==" Mar 05 14:28:10 volumio mpd[1266]: Mar 05 14:28 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01:00" level=debug msg="completed keyexchange" Mar 05 14:28:10 volumio systemd[1]: Started Music Player Daemon. Mar 05 14:28:10 volumio sudo[1236]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:10 volumio sudo[1245]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:10 volumio go-librespot[1283]: time="2025-03-05T14:28:10+01:00" level=debug msg="completed challenge" Mar 05 14:28:10 volumio volumio[963]: info: Completed starting Core Plugins Mar 05 14:28:10 volumio volumio[963]: info: ------------------------------------------- Mar 05 14:28:10 volumio volumio[963]: info: ----- MyVolumio plugins startup ---- Mar 05 14:28:10 volumio volumio[963]: info: ------------------------------------------- Mar 05 14:28:10 volumio volumio[963]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=info msg="authenticated AP as bustertrumpf" Mar 05 14:28:11 volumio volumio[963]: error: MPD error: The expression evaluated to a falsy value: Mar 05 14:28:11 volumio volumio[963]: assert.ok(self.idling) Mar 05 14:28:11 volumio volumio[963]: error: The expression evaluated to a falsy value: Mar 05 14:28:11 volumio volumio[963]: assert.ok(self.idling) Mar 05 14:28:11 volumio volumio[963]: error: updateQueue error: null Mar 05 14:28:11 volumio volumio[963]: info: MPD running with PID1266 Mar 05 14:28:11 volumio volumio[963]: ,establishing connection Mar 05 14:28:11 volumio volumio[963]: error: updateQueue error: null Mar 05 14:28:11 volumio systemd[1]: systemd-fsckd.service: Succeeded. Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=info msg="authenticated Login5 as bustertrumpf" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="initializing zeroconf session, username: bustertrumpf" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="dealer connection opened" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=trace msg="starting accesspoint recv loop" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=trace msg="starting dealer recv loop" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=trace msg="received accesspoint ping" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="received connection id: MDA2NWU3NjgtYmRlMi00ZWNmLTg5N2EtNjM2ZTIxNmQxMzJiK2RlYWxlcit0Y3A6Ly8wYWNhNTk4Ni5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDU2RDFEOTRGQkI0MDlBM0QxQzBBRjAxNTg1RUM4NEZBQzFBQjdFRDYzNDkzMDI0Njg5NUMxQUVBNDVGMUQzRA==" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 05 14:28:11 volumio go-librespot[1283]: time="2025-03-05T14:28:11+01:00" level=trace msg="received accesspoint pong ack" Mar 05 14:28:12 volumio volumio[963]: info: go-librespot daemon successfully initialized Mar 05 14:28:12 volumio sudo[1348]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 05 14:28:12 volumio sudo[1348]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:12 volumio sudo[1348]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:12 volumio sudo[1350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 05 14:28:12 volumio sudo[1350]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:12 volumio sudo[1350]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:12 volumio sudo[1354]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 05 14:28:12 volumio sudo[1354]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:28:12 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Mar 05 14:28:12 volumio sudo[1354]: pam_unix(sudo:session): session closed for user root Mar 05 14:28:12 volumio volumio[963]: info: Upmpdcli Daemon Started Mar 05 14:28:12 volumio volumio[1356]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 05 14:28:13 volumio sh[515]: timed out Mar 05 14:28:13 volumio dhcpcd[561]: timed out Mar 05 14:28:13 volumio sh[515]: dhcpcd exited Mar 05 14:28:13 volumio dhcpcd[561]: dhcpcd exited Mar 05 14:28:13 volumio sh[515]: ifup: failed to bring up eth0 Mar 05 14:28:13 volumio systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Mar 05 14:28:13 volumio systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Mar 05 14:28:14 volumio go-librespot[1283]: time="2025-03-05T14:28:14+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 05 14:28:14 volumio go-librespot[1283]: time="2025-03-05T14:28:14+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 336" Mar 05 14:28:14 volumio go-librespot[1283]: time="2025-03-05T14:28:14+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:28:14 volumio go-librespot[1283]: time="2025-03-05T14:28:14+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1407" Mar 05 14:28:15 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="handling transfer player command from d1cf43652a49f0f8fec67d9d7e436f7133671fa0" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="resolved context of track" uri="spotify:artist:78BKeGuQw5avYdV8kzK0Nh" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:artist:78BKeGuQw5avYdV8kzK0Nh" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=trace msg="fetched new page 1 with 22 items (list: 32)" uri="spotify:artist:78BKeGuQw5avYdV8kzK0Nh" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="loading track (paused: true, position: 172880ms)" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:15 volumio volumio[963]: info: Initializing connection to go-librespot Websocket Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="new websocket client" Mar 05 14:28:15 volumio volumio[963]: info: Connection to go-librespot Websocket established Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=trace msg="emitting websocket event: will_play" Mar 05 14:28:15 volumio volumio[963]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:2K6wCGdWJQcLXhmSZXQ16e","play_origin":"com.spotify.service.freetierartist"}} Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="selected format OGG_VORBIS_320 (fa4d8a60e0085248bd5f5f6e2bb5cd6d95597a0b)" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="requested aes key for file fa4d8a60e0085248bd5f5f6e2bb5cd6d95597a0b, gid: 2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:15 volumio go-librespot[1283]: time="2025-03-05T14:28:15+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1348" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1118" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched first chunk of 30, total size is 15321516 bytes" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched chunk 1/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio volumio[1356]: ........................++++ Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched chunk 12/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=trace msg="seek to 172880ms (diff: 137ms, samples: 7624008, bytes: 6427491)" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="created new output device" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=info msg="loaded track \"Fahnen im Wind\" (paused: true, position: 172880ms, duration: 380893ms, prefetched: false)" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=trace msg="emitting websocket event: metadata" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=trace msg="emitting websocket event: active" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:28:16 volumio volumio[963]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:2K6wCGdWJQcLXhmSZXQ16e","name":"Fahnen im Wind","artist_names":["Berliner Weisse"],"album_name":"Steelcap Love Affair","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02203ee30ea725475120df7dad","position":172880,"duration":380893,"release_date":"year:2013 month:3 day:29","track_number":1,"disc_number":1}} Mar 05 14:28:16 volumio volumio[963]: SPOTIFY: received: {"type":"active","data":null} Mar 05 14:28:16 volumio volumio[963]: info: Aligning Spotify Volume to Volumio Volume Mar 05 14:28:16 volumio volumio[963]: info: CoreCommandRouter::volumioGetState Mar 05 14:28:16 volumio volumio[963]: info: CorePlayQueue::getTrack 0 Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched chunk 3/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched chunk 15/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched chunk 13/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:16 volumio volumio[963]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 05 14:28:16 volumio go-librespot[1283]: time="2025-03-05T14:28:16+01:00" level=debug msg="fetched chunk 2/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="fetched chunk 14/29, size: 524288" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=trace msg="emitting websocket event: paused" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="handling resume player command from d1cf43652a49f0f8fec67d9d7e436f7133671fa0" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=trace msg="seek to 172880ms (diff: 137ms, samples: 7624008, bytes: 6427491)" uri="spotify:track:2K6wCGdWJQcLXhmSZXQ16e" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01: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" Mar 05 14:28:17 volumio volumio[963]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:2K6wCGdWJQcLXhmSZXQ16e","play_origin":"com.spotify.service.freetierartist"}} Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="resume track at 172553ms" Mar 05 14:28:17 volumio volumio[963]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 14:28:17 volumio volumio[963]: TypeError: Cannot read property 'service' of undefined Mar 05 14:28:17 volumio volumio[963]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Mar 05 14:28:17 volumio volumio[963]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) Mar 05 14:28:17 volumio volumio[963]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Mar 05 14:28:17 volumio volumio[963]: at WebSocket.emit (events.js:315:20) Mar 05 14:28:17 volumio volumio[963]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 05 14:28:17 volumio volumio[963]: at Receiver.emit (events.js:315:20) Mar 05 14:28:17 volumio volumio[963]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 05 14:28:17 volumio volumio[963]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 05 14:28:17 volumio volumio[963]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 05 14:28:17 volumio volumio[963]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 05 14:28:17 volumio volumio[963]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 05 14:28:17 volumio volumio[963]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 05 14:28:17 volumio volumio[963]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 05 14:28:17 volumio volumio[963]: at Socket.emit (events.js:315:20) Mar 05 14:28:17 volumio volumio[963]: at addChunk (internal/streams/readable.js:309:12) Mar 05 14:28:17 volumio volumio[963]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 05 14:28:17 volumio volumio[963]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=trace msg="scheduling prefetch in 178s" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:28:17 volumio go-librespot[1283]: time="2025-03-05T14:28:17+01:00" level=trace msg="emitting websocket event: playing" Mar 05 14:28:17 volumio sudo[1386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-05 14:27 Mar 05 14:28:17 volumio sudo[1386]: 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"