-- Logs begin at Thu 2019-02-14 12:11:58 EET, end at Thu 2026-03-26 14:34:58 EET. -- Mar 26 14:34:32 streamer systemd-timedated[997]: Changed local time to Thu Mar 26 14:34:32 2026 Mar 26 14:34:32 streamer sudo[995]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:32 streamer volumio-time-update[609]: volumio-time-update-util: System time updated successfully. Mar 26 14:34:32 streamer systemd[1]: Starting Daily apt download activities... Mar 26 14:34:32 streamer systemd[1]: Started Volumio Time Update Utility. Mar 26 14:34:32 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:32 streamer volumio[973]: info: ----- Volumio3 ---- Mar 26 14:34:32 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:32 streamer volumio[973]: info: ----- System startup ---- Mar 26 14:34:32 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:32 streamer nmbd[722]: [2026/03/26 14:34:32.984866, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 26 14:34:32 streamer systemd[1]: Started Samba NMB Daemon. Mar 26 14:34:32 streamer nmbd[722]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Mar 26 14:34:33 streamer volumio[973]: info: MYVOLUMIO Environment detected Mar 26 14:34:33 streamer systemd[1]: Starting Samba Winbind Daemon... Mar 26 14:34:33 streamer volumio[973]: info: Plugin folders cleanup Mar 26 14:34:33 streamer volumio[973]: info: Scanning into folder /volumio/app/plugins/ Mar 26 14:34:33 streamer volumio[973]: info: Scanning category audio_interface Mar 26 14:34:33 streamer volumio[973]: info: Scanning category miscellanea Mar 26 14:34:33 streamer volumio[973]: info: Scanning category music_service Mar 26 14:34:33 streamer winbindd[1027]: [2026/03/26 14:34:33.373699, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Mar 26 14:34:33 streamer winbindd[1027]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Mar 26 14:34:33 streamer volumio[973]: info: Scanning category plugins.json Mar 26 14:34:33 streamer volumio[973]: info: Scanning category system_controller Mar 26 14:34:33 streamer volumio[973]: info: Scanning category user_interface Mar 26 14:34:33 streamer volumio[973]: info: Scanning into folder /data/plugins/ Mar 26 14:34:33 streamer volumio[973]: info: Scanning category music_service Mar 26 14:34:33 streamer volumio[973]: info: Plugin folders cleanup completed Mar 26 14:34:33 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:33 streamer volumio[973]: info: ----- Core plugins startup ---- Mar 26 14:34:33 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:33 streamer volumio[973]: info: Loading plugins from folder /volumio/app/plugins/ Mar 26 14:34:33 streamer volumio[973]: info: Adding plugin upnp to MyMusic Plugins Mar 26 14:34:33 streamer volumio[973]: info: Adding plugin airplay_emulation to MyMusic Plugins Mar 26 14:34:33 streamer volumio[973]: info: Adding plugin upnp_browser to MyMusic Plugins Mar 26 14:34:33 streamer volumio[973]: info: Loading plugins from folder /data/plugins/ Mar 26 14:34:33 streamer systemd[1]: Started Samba Winbind Daemon. Mar 26 14:34:33 streamer winbindd[1027]: [2026/03/26 14:34:33.390554, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 26 14:34:33 streamer winbindd[1027]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Mar 26 14:34:33 streamer volumio[973]: info: Loading plugin "system"... Mar 26 14:34:33 streamer volumio[973]: info: Loading plugin "appearance"... Mar 26 14:34:33 streamer systemd[1]: Starting Samba SMB Daemon... Mar 26 14:34:33 streamer smbd[1037]: [2026/03/26 14:34:33.811075, 0] ../lib/util/become_daemon.c:138(daemon_ready) Mar 26 14:34:33 streamer smbd[1037]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Mar 26 14:34:33 streamer systemd[1]: Started Samba SMB Daemon. Mar 26 14:34:33 streamer systemd[1]: Reached target Multi-User System. Mar 26 14:34:33 streamer systemd[1]: Reached target Graphical Interface. Mar 26 14:34:33 streamer systemd[1]: Starting Update UTMP about System Runlevel Changes... Mar 26 14:34:33 streamer systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Mar 26 14:34:33 streamer systemd[1]: Started Update UTMP about System Runlevel Changes. Mar 26 14:34:34 streamer volumio-remote-updater[627]: [2026-03-26 14:34:34] [connect] Successful connection Mar 26 14:34:34 streamer systemd[1]: apt-daily.service: Succeeded. Mar 26 14:34:34 streamer systemd[1]: Started Daily apt download activities. Mar 26 14:34:34 streamer systemd[1]: Starting Daily apt upgrade and clean activities... Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "network"... Mar 26 14:34:34 streamer volumio[973]: info: Refreshing Cached IP Addresses Mar 26 14:34:34 streamer sudo[1095]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 26 14:34:34 streamer sudo[1095]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:34 streamer sudo[1095]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:34 streamer sudo[1097]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 26 14:34:34 streamer sudo[1097]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:34 streamer sudo[1097]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "services"... Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "alsa_controller"... Mar 26 14:34:34 streamer sudo[1106]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Mar 26 14:34:34 streamer sudo[1106]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:34 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "wizard"... Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "networkfs"... Mar 26 14:34:34 streamer volumio[973]: info: Starting Udev Watcher for removable devices Mar 26 14:34:34 streamer sudo[1121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=jonttu,password=HVSdWH4DSzkEKRBiK6RSL,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //diskstation.local/media/music /mnt/NAS/Diskstation Mar 26 14:34:34 streamer sudo[1121]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:34 streamer volumio[973]: info: Ignoring mount for partition: boot Mar 26 14:34:34 streamer volumio[973]: info: Ignoring mount for partition: volumio Mar 26 14:34:34 streamer volumio[973]: info: Ignoring mount for partition: volumio_data Mar 26 14:34:34 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "volumio_command_line_client"... Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "upnp"... Mar 26 14:34:34 streamer volumio[973]: info: [1774528474833] Starting Upmpd Daemon Mar 26 14:34:34 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "my_music"... Mar 26 14:34:34 streamer volumio[973]: info: Loading plugin "mpd"... Mar 26 14:34:35 streamer kernel: Key type cifs.spnego registered Mar 26 14:34:35 streamer kernel: Key type cifs.idmap registered Mar 26 14:34:35 streamer 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 26 14:34:35 streamer kernel: CIFS: Attempting to mount //diskstation.local/media/music Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "upnp_browser"... Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "alarm-clock"... Mar 26 14:34:35 streamer systemd[1]: apt-daily-upgrade.service: Succeeded. Mar 26 14:34:35 streamer systemd[1]: Started Daily apt upgrade and clean activities. Mar 26 14:34:35 streamer systemd[1]: Startup finished in 12.048s (kernel) + 28.000s (userspace) = 40.049s. Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "airplay_emulation"... Mar 26 14:34:35 streamer volumio[973]: info: Starting Shairport Sync Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "last_100"... Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "webradio"... Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "i2s_dacs"... Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "volumiodiscovery"... Mar 26 14:34:35 streamer volumio[973]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 26 14:34:35 streamer volumio[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 26 14:34:35 streamer node[973]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Mar 26 14:34:35 streamer volumio[973]: *** WARNING *** For more information see Mar 26 14:34:35 streamer volumio[973]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 26 14:34:35 streamer volumio[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 26 14:34:35 streamer volumio[973]: *** WARNING *** For more information see Mar 26 14:34:35 streamer node[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 26 14:34:35 streamer node[973]: *** WARNING *** For more information see Mar 26 14:34:35 streamer node[973]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Mar 26 14:34:35 streamer node[973]: *** WARNING *** Please fix your application to use the native API of Avahi! Mar 26 14:34:35 streamer node[973]: *** WARNING *** For more information see Mar 26 14:34:35 streamer volumio[973]: info: Applying required configuration parameters for plugin volumiodiscovery Mar 26 14:34:35 streamer volumio[973]: info: Discovery: Started advertising with name: Streamer Mar 26 14:34:35 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Mar 26 14:34:35 streamer volumio[973]: info: Loading plugin "soundcloud"... Mar 26 14:34:36 streamer volumio[973]: info: Loading plugin "spop"... Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "outputs"... Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "albumart"... Mar 26 14:34:37 streamer volumio[973]: info: Plugin example_plugin is not enabled Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "inputs"... Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "updater_comm"... Mar 26 14:34:37 streamer volumio[973]: info: Plugin mpdemulation is not enabled Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "rest_api"... Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "websocket"... Mar 26 14:34:37 streamer volumio[973]: info: Starting Socket.io Server version 2.3.0 Mar 26 14:34:37 streamer volumio[973]: info: Loading plugin "radio_paradise"... Mar 26 14:34:37 streamer volumio[973]: Forking 3 albumart workers Mar 26 14:34:37 streamer volumio[973]: info: Applying required configuration parameters for plugin radio_paradise Mar 26 14:34:37 streamer volumio[973]: info: [1774528477748] [RadioParadise] API delay: 5 Mar 26 14:34:37 streamer volumio[973]: info: Loading i18n strings for locale en Mar 26 14:34:37 streamer volumio[973]: Updating browse sources language Mar 26 14:34:37 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:38 streamer volumio[973]: Starting albumart workers Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::initPlayerControls Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 14:34:38 streamer volumio[973]: Starting albumart workers Mar 26 14:34:38 streamer volumio[973]: Express server listening on port 3000 Mar 26 14:34:38 streamer volumio[973]: [Metrics] WebUI: 6s 601.07ms Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::resetVolumioState Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::getcurrentVolume Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::volumioRetrievevolume Mar 26 14:34:38 streamer volumio[973]: Starting albumart workers Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::pushState Mar 26 14:34:38 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::volumioPushState Mar 26 14:34:38 streamer volumio[973]: info: Volumio Network Manager: Network status updated: 2 Mar 26 14:34:38 streamer volumio-remote-updater[627]: [2026-03-26 14:34:38] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1774528474 101 Mar 26 14:34:38 streamer volumio[973]: 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 26 14:34:38 streamer volumio[973]: info: Reloading queue from file Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::setRepeat null single undefined Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::pushState Mar 26 14:34:38 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::volumioPushState Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::setRandom null Mar 26 14:34:38 streamer volumio[973]: info: CoreStateMachine::pushState Mar 26 14:34:38 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::volumioPushState Mar 26 14:34:38 streamer volumio[973]: info: Setting Device type: Raspberry PI Mar 26 14:34:38 streamer volumio[973]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Mar 26 14:34:38 streamer volumio[973]: info: USB Boot Capable - System SBC Revision found in cpuinfo: b03114 Mar 26 14:34:38 streamer volumio[973]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Mar 26 14:34:38 streamer volumio[973]: info: Discovery: adding 8eebf7db-761d-4600-aee5-6cdada14d4a0 Mar 26 14:34:38 streamer volumio[973]: info: Discovery: Found device Streamer Mar 26 14:34:38 streamer sudo[1106]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:38 streamer volumio[973]: info: CoreCommandRouter::volumioGetState Mar 26 14:34:38 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:40 streamer systemd[1]: systemd-fsckd.service: Succeeded. Mar 26 14:34:41 streamer sh[507]: timed out Mar 26 14:34:41 streamer dhcpcd[548]: timed out Mar 26 14:34:41 streamer sh[507]: dhcpcd exited Mar 26 14:34:41 streamer dhcpcd[548]: dhcpcd exited Mar 26 14:34:41 streamer sh[507]: ifup: failed to bring up eth0 Mar 26 14:34:41 streamer systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE Mar 26 14:34:41 streamer systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. Mar 26 14:34:42 streamer systemd[1]: systemd-hostnamed.service: Succeeded. Mar 26 14:34:44 streamer sudo[1258]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 26 14:34:44 streamer sudo[1258]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:44 streamer sudo[1258]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:44 streamer sudo[1260]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 26 14:34:44 streamer sudo[1260]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:44 streamer sudo[1260]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:44 streamer sudo[1264]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Mar 26 14:34:44 streamer sudo[1264]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:45 streamer systemd[1]: Started UPnP Renderer front-end to MPD. Mar 26 14:34:45 streamer sudo[1264]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:45 streamer volumio[973]: info: Upmpdcli Daemon Started Mar 26 14:34:45 streamer volumio[1266]: Generating RSA private key, 4096 bit long modulus (2 primes) Mar 26 14:34:45 streamer volumio[1266]: ....++++ Mar 26 14:34:46 streamer volumio[1266]: ......++++ Mar 26 14:34:46 streamer volumio[1266]: e is 65537 (0x010001) Mar 26 14:34:46 streamer volumio[1266]: writing RSA key Mar 26 14:34:48 streamer kernel: cryptd: max_cpu_qlen set to 1000 Mar 26 14:34:48 streamer sudo[1121]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:48 streamer volumio[973]: info: Completed loading Core Plugins Mar 26 14:34:48 streamer volumio[973]: info: Preparing to generate the ALSA configuration file Mar 26 14:34:49 streamer volumio[973]: info: Asound.conf file written Mar 26 14:34:49 streamer sudo[1319]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf Mar 26 14:34:49 streamer sudo[1319]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer sudo[1319]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:49 streamer volumio[973]: info: Output device has changed, restarting MPD Mar 26 14:34:49 streamer volumio[973]: info: Output device has changed, restarting Shairport Sync Mar 26 14:34:49 streamer sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:49 streamer sudo[1324]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:49 streamer sudo[1326]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 26 14:34:49 streamer sudo[1326]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer systemd[1]: Stopping Music Player Daemon... Mar 26 14:34:49 streamer volumio[973]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 26 14:34:49 streamer volumio[973]: info: ___________ START PLUGINS ___________ Mar 26 14:34:49 streamer volumio[973]: info: ControllerMpd::onStart: Initializing MPD Mar 26 14:34:49 streamer volumio[973]: info: Creating MPD Configuration file Mar 26 14:34:49 streamer sudo[1333]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 26 14:34:49 streamer sudo[1333]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 14:34:49 streamer volumio[973]: info: [1774528489206] CoreMusicLibrary::Adding element Media Servers Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:49 streamer sudo[1333]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:49 streamer sudo[1335]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 26 14:34:49 streamer sudo[1335]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:49 streamer systemd[1]: mpd.service: Succeeded. Mar 26 14:34:49 streamer systemd[1]: Stopped Music Player Daemon. Mar 26 14:34:49 streamer volumio[973]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 14:34:49 streamer volumio[973]: info: [1774528489299] CoreMusicLibrary::Adding element Last_100 Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 14:34:49 streamer volumio[973]: info: [1774528489301] CoreMusicLibrary::Adding element Webradio Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 14:34:49 streamer volumio[973]: info: Initializing BBC Radios Mar 26 14:34:49 streamer systemd[1]: Starting Music Player Daemon... Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 14:34:49 streamer volumio[973]: info: [1774528489360] CoreMusicLibrary::Adding element SoundCloud Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:49 streamer volumio[973]: Cannot find translation for source SoundCloud Mar 26 14:34:49 streamer volumio[973]: info: Creating Spotify config file Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer sudo[1342]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 26 14:34:49 streamer sudo[1342]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer sudo[1342]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 14:34:49 streamer volumio[973]: info: [1774528489438] CoreMusicLibrary::Adding element Radio Paradise Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:49 streamer volumio[973]: Cannot find translation for source SoundCloud Mar 26 14:34:49 streamer volumio[973]: Cannot find translation for source Radio Paradise Mar 26 14:34:49 streamer volumio[973]: info: Volumio Calling Home Mar 26 14:34:49 streamer volumio[973]: info: MPD Permissions set Mar 26 14:34:49 streamer volumio[973]: info: MPD Permissions set Mar 26 14:34:49 streamer volumio[973]: info: Spotify config file written Mar 26 14:34:49 streamer sudo[1362]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 26 14:34:49 streamer volumio[973]: 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 26 14:34:49 streamer sudo[1362]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: No need to fix Spotify hosts Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 26 14:34:49 streamer systemd[1]: Started go-librespot Daemon. Mar 26 14:34:49 streamer go-librespot[1368]: go-librespot daemon starting... Mar 26 14:34:49 streamer sudo[1362]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:49 streamer volumio[973]: info: Volumio called home Mar 26 14:34:49 streamer volumio[973]: info: Starting Shairport Sync Mar 26 14:34:49 streamer volumio[973]: info: Starting Shairport Sync Mar 26 14:34:49 streamer volumio[973]: info: Starting Shairport Sync Mar 26 14:34:49 streamer sudo[1380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 26 14:34:49 streamer sudo[1380]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer sudo[1382]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 26 14:34:49 streamer sudo[1382]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer sudo[1386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Mar 26 14:34:49 streamer volumio[973]: info: CoreCommandRouter::volumioGetState Mar 26 14:34:49 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:49 streamer sudo[1386]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:49 streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 26 14:34:49 streamer systemd[1]: shairport-sync.service: Succeeded. Mar 26 14:34:49 streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 26 14:34:49 streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 26 14:34:50 streamer sudo[1380]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:50 streamer sudo[1382]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:50 streamer volumio[973]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 26 14:34:50 streamer volumio[973]: SPOTIFY: BQAWmfW4etvIFJLcokt4b8YHfWdElO24JjM0C3S4bgfjm3B3Aj_pa9FSm-2DpGoYE6NsP3RRWOxz3UYIukZxmgJBU8jFTJv8Wz5NXgpOR5cJdaRXpe-vUCA-x7ftoG7f9bdWsESMVEDAngmSEx0xeP0leSoDLl4mnpYLKedkuUdPEWqkvV3pfWQR27G1UVUb96JSVyUK-eB7MYxggpiBQ9PohZfIi2l1-vl7bfTPowpWxqwui-58s2NXNNogYVC0w_mzYQEvKe2_MEZ5XEp2ejNtwKX6OOg1Bcm5 Mar 26 14:34:50 streamer volumio[973]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 26 14:34:50 streamer volumio[973]: info: New Spotify access token = BQAWmfW4etvIFJLcokt4b8YHfWdElO24JjM0C3S4bgfjm3B3Aj_pa9FSm-2DpGoYE6NsP3RRWOxz3UYIukZxmgJBU8jFTJv8Wz5NXgpOR5cJdaRXpe-vUCA-x7ftoG7f9bdWsESMVEDAngmSEx0xeP0leSoDLl4mnpYLKedkuUdPEWqkvV3pfWQR27G1UVUb96JSVyUK-eB7MYxggpiBQ9PohZfIi2l1-vl7bfTPowpWxqwui-58s2NXNNogYVC0w_mzYQEvKe2_MEZ5XEp2ejNtwKX6OOg1Bcm5 Mar 26 14:34:50 streamer volumio[973]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 26 14:34:50 streamer systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Mar 26 14:34:50 streamer systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Mar 26 14:34:50 streamer systemd[1]: shairport-sync.service: Succeeded. Mar 26 14:34:50 streamer systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Mar 26 14:34:50 streamer volumio[973]: info: Shairport-Sync Started Mar 26 14:34:50 streamer volumio[973]: Error adding Membership: Error: addMembership EINVAL Mar 26 14:34:50 streamer volumio[973]: info: Shairport-Sync Started Mar 26 14:34:50 streamer systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Mar 26 14:34:50 streamer sudo[1386]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:50 streamer volumio[973]: info: Shairport-Sync Started Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=info msg="running go-librespot 0.4.0" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="app state loaded" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 26 14:34:50 streamer volumio[973]: SPOTIFY: User informations: {"country":"FI","display_name":"aprilnine","email":"jonttuleskinen@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/aprilnine"},"followers":{"href":null,"total":19},"href":"https://api.spotify.com/v1/users/aprilnine","id":"aprilnine","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85b0c21597facdc19900fc60f8","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82b0c21597facdc19900fc60f8","width":64}],"product":"premium","type":"user","uri":"spotify:user:aprilnine"} Mar 26 14:34:50 streamer volumio[973]: info: Spotify Successfully logged in Mar 26 14:34:50 streamer volumio[973]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 26 14:34:50 streamer volumio[973]: info: [1774528490196] CoreMusicLibrary::Adding element Spotify Mar 26 14:34:50 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:50 streamer volumio[973]: Cannot find translation for source SoundCloud Mar 26 14:34:50 streamer volumio[973]: Cannot find translation for source Radio Paradise Mar 26 14:34:50 streamer volumio[973]: Cannot find translation for source Spotify Mar 26 14:34:50 streamer mpd[1357]: Mar 26 14:34 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+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]" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+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]" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+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]" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=info msg="zeroconf server listening on port 34593" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="obtained new client token: AAB6ELhiFbv+qrTWchFKSyoDbHM32wh4mMA5dl2WBaY1nHtfzMi16A6LJLT7OdQrqB1GYP9uHucuiYbTJbnBXAIX68pFM9cwVdj6OMzIqrCr7fAzbBWtOTbeftJMA/UwjYgd8tqjMzUf+L/hl6FCWCIwS878OA0qK1QwrGUci573sQD/q5pkvxe/M6u5a3iTgVFqGYxK90sUjdZhgRg2ZQZVlxbt6cUvZ7gF4w4naEDmO3NyXZORChxm56s=" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="completed keyexchange" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="completed challenge" Mar 26 14:34:50 streamer systemd[1]: Started Music Player Daemon. Mar 26 14:34:50 streamer sudo[1335]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:50 streamer sudo[1326]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:50 streamer volumio[973]: info: Completed starting Core Plugins Mar 26 14:34:50 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:50 streamer volumio[973]: info: ----- MyVolumio plugins startup ---- Mar 26 14:34:50 streamer volumio[973]: info: ------------------------------------------- Mar 26 14:34:50 streamer volumio[973]: info: [MyVolumio PluginManager] Fetching plans data.... Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=info msg="authenticated AP" username="ap*****ne" Mar 26 14:34:50 streamer volumio[973]: error: MPD error: The expression evaluated to a falsy value: Mar 26 14:34:50 streamer volumio[973]: assert.ok(self.idling) Mar 26 14:34:50 streamer volumio[973]: error: The expression evaluated to a falsy value: Mar 26 14:34:50 streamer volumio[973]: assert.ok(self.idling) Mar 26 14:34:50 streamer volumio[973]: info: MPD running with PID1357 Mar 26 14:34:50 streamer volumio[973]: ,establishing connection Mar 26 14:34:50 streamer volumio[973]: error: MPD error: The expression evaluated to a falsy value: Mar 26 14:34:50 streamer volumio[973]: assert.ok(self.idling) Mar 26 14:34:50 streamer volumio[973]: error: The expression evaluated to a falsy value: Mar 26 14:34:50 streamer volumio[973]: assert.ok(self.idling) Mar 26 14:34:50 streamer volumio[973]: error: updateQueue error: null Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=info msg="authenticated Login5" username="ap*****ne" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="initializing zeroconf session" username="ap*****ne" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="dealer connection opened" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=trace msg="starting accesspoint recv loop" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=trace msg="starting dealer recv loop" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=trace msg="received accesspoint ping" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=debug msg="received connection id: MGY2ZGZhNzEtYmIx...NTkzQzE5QTMzMg==" Mar 26 14:34:50 streamer go-librespot[1368]: time="2026-03-26T14:34:50+02:00" level=trace msg="received accesspoint pong ack" Mar 26 14:34:51 streamer go-librespot[1368]: time="2026-03-26T14:34:51+02:00" level=debug msg="put connect state because NEW_DEVICE" Mar 26 14:34:51 streamer go-librespot[1368]: time="2026-03-26T14:34:51+02:00" level=debug msg="update volume requested to 65535/65535" Mar 26 14:34:51 streamer go-librespot[1368]: time="2026-03-26T14:34:51+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Mar 26 14:34:51 streamer go-librespot[1368]: time="2026-03-26T14:34:51+02:00" level=trace msg="emitting websocket event: volume" Mar 26 14:34:52 streamer sudo[1400]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 26 14:34:52 streamer sudo[1400]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:52 streamer sudo[1400]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:52 streamer sudo[1402]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 26 14:34:52 streamer sudo[1402]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:52 streamer sudo[1402]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:52 streamer volumio[973]: verbose: New Socket.io Connection to 192.168.1.153 from 192.168.1.154 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) FxiOS/148.3 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 3 Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::volumioGetVisibleSources Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::volumioGetState Mar 26 14:34:52 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 14:34:52 streamer volumio[973]: info: go-librespot daemon successfully initialized Mar 26 14:34:52 streamer sudo[1406]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 26 14:34:52 streamer sudo[1406]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:52 streamer sudo[1406]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:52 streamer sudo[1408]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 26 14:34:52 streamer sudo[1408]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 26 14:34:52 streamer sudo[1408]: pam_unix(sudo:session): session closed for user root Mar 26 14:34:52 streamer volumio[973]: verbose: New Socket.io Connection to 192.168.1.153 from 192.168.1.154 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) FxiOS/148.3 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 4 Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::volumioGetState Mar 26 14:34:52 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 26 14:34:52 streamer volumio[973]: info: Listing playlists Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 26 14:34:52 streamer volumio[973]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 26 14:34:55 streamer volumio[973]: info: Initializing connection to go-librespot Websocket Mar 26 14:34:55 streamer go-librespot[1368]: time="2026-03-26T14:34:55+02:00" level=debug msg="new websocket client" Mar 26 14:34:55 streamer volumio[973]: info: Connection to go-librespot Websocket established Mar 26 14:34:56 streamer volumio[973]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="handling transfer player command from 656b438006f75313f5081b6e92b84d83d03d341c" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1E35mns579qbTR" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1E35mns579qbTR" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="loading track (paused: true, position: 189069ms)" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=trace msg="emitting websocket event: will_play" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="selected format OGG_VORBIS_320 (a0f5882f7251c512604182fc5081da4a1d236e49)" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="requested aes key for file a0f5882f7251c512604182fc5081da4a1d236e49, gid: 6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1683" Mar 26 14:34:56 streamer volumio[973]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:playlist:37i9dQZF1E35mns579qbTR","uri":"spotify:track:6avgLhlp3KdMhuvXQWwE4R","play_origin":"com.spotify.service.carplayv2"}} Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="fetched first chunk of 18, total size is 9089464 bytes" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1295" Mar 26 14:34:56 streamer go-librespot[1368]: time="2026-03-26T14:34:56+02:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="fetched chunk 15/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="fetched chunk 13/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=trace msg="seek to 189069ms (diff: 78ms, samples: 8337942, bytes: 7232100)" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="created new output device" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=info msg="loaded track \"Medicine\" (paused: true, position: 189069ms, duration: 235244ms, prefetched: false)" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="fetched chunk 14/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="fetched chunk 16/17, size: 524288" uri="spotify:track:6avgLhlp3KdMhuvXQWwE4R" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=trace msg="emitting websocket event: metadata" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=trace msg="emitting websocket event: active" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="sending successful reply for dealer request" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 26 14:34:57 streamer go-librespot[1368]: time="2026-03-26T14:34:57+02:00" level=trace msg="emitting websocket event: paused" Mar 26 14:34:58 streamer volumio[973]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6avgLhlp3KdMhuvXQWwE4R","name":"Medicine","artist_names":["Waldskin"],"album_name":"Wrong Party","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c4000db237523d22fe6db780","position":189069,"duration":235244,"release_date":"year:2024 month:10 day:25","track_number":1,"disc_number":1}} Mar 26 14:34:58 streamer volumio[973]: SPOTIFY: received: {"type":"active","data":null} Mar 26 14:34:58 streamer volumio[973]: info: Aligning Spotify Volume to Volumio Volume Mar 26 14:34:58 streamer volumio[973]: info: CoreCommandRouter::volumioGetState Mar 26 14:34:58 streamer volumio[973]: info: CorePlayQueue::getTrack 0 Mar 26 14:34:58 streamer volumio[973]: SPOTIFY: received: {"type":"paused","data":{"context_uri":"spotify:playlist:37i9dQZF1E35mns579qbTR","uri":"spotify:track:6avgLhlp3KdMhuvXQWwE4R","play_origin":"com.spotify.service.carplayv2"}} Mar 26 14:34:58 streamer volumio[973]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 14:34:58 streamer volumio[973]: TypeError: Cannot read property 'service' of undefined Mar 26 14:34:58 streamer volumio[973]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Mar 26 14:34:58 streamer volumio[973]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:280:18) Mar 26 14:34:58 streamer volumio[973]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Mar 26 14:34:58 streamer volumio[973]: at WebSocket.emit (events.js:315:20) Mar 26 14:34:58 streamer volumio[973]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 26 14:34:58 streamer volumio[973]: at Receiver.emit (events.js:315:20) Mar 26 14:34:58 streamer volumio[973]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 26 14:34:58 streamer volumio[973]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 26 14:34:58 streamer volumio[973]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 26 14:34:58 streamer volumio[973]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 26 14:34:58 streamer volumio[973]: at writeOrBuffer (internal/streams/writable.js:358:12) Mar 26 14:34:58 streamer volumio[973]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Mar 26 14:34:58 streamer volumio[973]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Mar 26 14:34:58 streamer volumio[973]: at Socket.emit (events.js:315:20) Mar 26 14:34:58 streamer volumio[973]: at addChunk (internal/streams/readable.js:309:12) Mar 26 14:34:58 streamer volumio[973]: at readableAddChunk (internal/streams/readable.js:284:9) Mar 26 14:34:58 streamer volumio[973]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 26 14:34:58 streamer sudo[1438]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2026-03-26 14:33 Mar 26 14:34:58 streamer sudo[1438]: 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"