-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Thu 2025-05-15 16:32:02 CEST. -- May 15 16:31:45 stuehjttalere systemd-timedated[1050]: Changed local time to Thu May 15 16:31:45 2025 May 15 16:31:45 stuehjttalere sudo[1048]: pam_unix(sudo:session): session closed for user root May 15 16:31:45 stuehjttalere volumio-time-update[680]: volumio-time-update-util: System time updated successfully. May 15 16:31:45 stuehjttalere systemd[1]: Starting Daily apt download activities... May 15 16:31:45 stuehjttalere systemd[1]: Started Volumio Time Update Utility. May 15 16:31:45 stuehjttalere nmbd[759]: [2025/05/15 16:31:45.620954, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 15 16:31:45 stuehjttalere nmbd[759]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 15 16:31:45 stuehjttalere systemd[1]: Started Samba NMB Daemon. May 15 16:31:45 stuehjttalere systemd[1]: Starting Samba Winbind Daemon... May 15 16:31:45 stuehjttalere volumio[1013]: info: Loading plugin "network"... May 15 16:31:45 stuehjttalere volumio[1013]: info: Refreshing Cached IP Addresses May 15 16:31:45 stuehjttalere sudo[1074]: volumio : unable to resolve host stuehjttalere May 15 16:31:45 stuehjttalere sudo[1074]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:45 stuehjttalere volumio[1013]: info: Loading plugin "services"... May 15 16:31:45 stuehjttalere sudo[1076]: volumio : unable to resolve host stuehjttalere May 15 16:31:45 stuehjttalere sudo[1076]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:45 stuehjttalere volumio[1013]: info: Loading plugin "alsa_controller"... May 15 16:31:45 stuehjttalere sudo[1076]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 15 16:31:45 stuehjttalere sudo[1074]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 15 16:31:45 stuehjttalere sudo[1076]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:45 stuehjttalere sudo[1074]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:45 stuehjttalere sudo[1074]: pam_unix(sudo:session): session closed for user root May 15 16:31:45 stuehjttalere sudo[1076]: pam_unix(sudo:session): session closed for user root May 15 16:31:45 stuehjttalere sudo[1083]: volumio : unable to resolve host stuehjttalere May 15 16:31:45 stuehjttalere sudo[1083]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:45 stuehjttalere sudo[1083]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 15 16:31:45 stuehjttalere sudo[1083]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:45 stuehjttalere winbindd[1071]: [2025/05/15 16:31:45.995531, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 15 16:31:45 stuehjttalere winbindd[1071]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 15 16:31:46 stuehjttalere winbindd[1071]: [2025/05/15 16:31:46.059268, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 15 16:31:46 stuehjttalere systemd[1]: Started Samba Winbind Daemon. May 15 16:31:46 stuehjttalere winbindd[1071]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 15 16:31:46 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "wizard"... May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "networkfs"... May 15 16:31:46 stuehjttalere systemd[1]: Starting Samba SMB Daemon... May 15 16:31:46 stuehjttalere volumio[1013]: info: Starting Udev Watcher for removable devices May 15 16:31:46 stuehjttalere volumio[1013]: info: Ignoring mount for partition: boot May 15 16:31:46 stuehjttalere volumio[1013]: info: Ignoring mount for partition: volumio May 15 16:31:46 stuehjttalere volumio[1013]: info: Ignoring mount for partition: volumio_data May 15 16:31:46 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "volumio_command_line_client"... May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "upnp"... May 15 16:31:46 stuehjttalere volumio[1013]: info: [1747319506380] Starting Upmpd Daemon May 15 16:31:46 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "my_music"... May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "mpd"... May 15 16:31:46 stuehjttalere sudo[1106]: volumio : unable to resolve host stuehjttalere May 15 16:31:46 stuehjttalere sudo[1106]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:46 stuehjttalere sudo[1106]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Sebastian,password=A6er?+0599til,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.2/Media/musik /mnt/NAS/Enghave May 15 16:31:46 stuehjttalere sudo[1106]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:46 stuehjttalere smbd[1104]: [2025/05/15 16:31:46.623222, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 15 16:31:46 stuehjttalere smbd[1104]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 15 16:31:46 stuehjttalere systemd[1]: Started Samba SMB Daemon. May 15 16:31:46 stuehjttalere systemd[1]: Reached target Multi-User System. May 15 16:31:46 stuehjttalere systemd[1]: Reached target Graphical Interface. May 15 16:31:46 stuehjttalere kernel: Key type cifs.spnego registered May 15 16:31:46 stuehjttalere kernel: Key type cifs.idmap registered May 15 16:31:46 stuehjttalere kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. May 15 16:31:46 stuehjttalere kernel: CIFS: Attempting to mount //192.168.0.2/Media/musik May 15 16:31:46 stuehjttalere systemd[1]: Starting Update UTMP about System Runlevel Changes... May 15 16:31:46 stuehjttalere systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 15 16:31:46 stuehjttalere systemd[1]: Started Update UTMP about System Runlevel Changes. May 15 16:31:46 stuehjttalere kernel: cryptd: max_cpu_qlen set to 1000 May 15 16:31:46 stuehjttalere volumio[1013]: info: Loading plugin "upnp_browser"... May 15 16:31:46 stuehjttalere volumio-remote-updater[672]: [2025-05-15 16:31:46] [connect] Successful connection May 15 16:31:47 stuehjttalere sudo[1106]: pam_unix(sudo:session): session closed for user root May 15 16:31:47 stuehjttalere kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE May 15 16:31:47 stuehjttalere kernel: CIFS: VFS: \\192.168.0.2 Send error in SessSetup = -13 May 15 16:31:47 stuehjttalere kernel: CIFS: VFS: cifs_mount failed w/return code = -13 May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "alarm-clock"... May 15 16:31:47 stuehjttalere systemd[1]: apt-daily.service: Succeeded. May 15 16:31:47 stuehjttalere systemd[1]: Started Daily apt download activities. May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "airplay_emulation"... May 15 16:31:47 stuehjttalere volumio[1013]: info: Starting Shairport Sync May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "last_100"... May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "webradio"... May 15 16:31:47 stuehjttalere systemd[1]: Starting Daily apt upgrade and clean activities... May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "i2s_dacs"... May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "volumiodiscovery"... May 15 16:31:47 stuehjttalere volumio[1013]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 15 16:31:47 stuehjttalere volumio[1013]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 16:31:47 stuehjttalere volumio[1013]: *** WARNING *** For more information see May 15 16:31:47 stuehjttalere node[1013]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 15 16:31:47 stuehjttalere volumio[1013]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 15 16:31:47 stuehjttalere volumio[1013]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 16:31:47 stuehjttalere volumio[1013]: *** WARNING *** For more information see May 15 16:31:47 stuehjttalere node[1013]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 16:31:47 stuehjttalere node[1013]: *** WARNING *** For more information see May 15 16:31:47 stuehjttalere node[1013]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 15 16:31:47 stuehjttalere node[1013]: *** WARNING *** Please fix your application to use the native API of Avahi! May 15 16:31:47 stuehjttalere node[1013]: *** WARNING *** For more information see May 15 16:31:47 stuehjttalere volumio[1013]: info: Applying required configuration parameters for plugin volumiodiscovery May 15 16:31:47 stuehjttalere volumio[1013]: info: Discovery: Started advertising with name: Stuehøjttalere May 15 16:31:47 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 15 16:31:47 stuehjttalere volumio[1013]: info: Loading plugin "spop"... May 15 16:31:48 stuehjttalere systemd[1]: apt-daily-upgrade.service: Succeeded. May 15 16:31:48 stuehjttalere systemd[1]: Started Daily apt upgrade and clean activities. May 15 16:31:48 stuehjttalere systemd[1]: Startup finished in 12.031s (kernel) + 28.315s (userspace) = 40.347s. May 15 16:31:48 stuehjttalere volumio[1013]: info: Loading plugin "ytcr"... May 15 16:31:49 stuehjttalere sudo[1083]: pam_unix(sudo:session): session closed for user root May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading plugin "outputs"... May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading plugin "albumart"... May 15 16:31:52 stuehjttalere volumio[1013]: info: Plugin example_plugin is not enabled May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading plugin "inputs"... May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading plugin "updater_comm"... May 15 16:31:52 stuehjttalere volumio[1013]: info: Plugin mpdemulation is not enabled May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading plugin "rest_api"... May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading plugin "websocket"... May 15 16:31:52 stuehjttalere volumio[1013]: info: Starting Socket.io Server version 2.3.0 May 15 16:31:52 stuehjttalere volumio[1013]: info: Loading i18n strings for locale en May 15 16:31:52 stuehjttalere volumio[1013]: Updating browse sources language May 15 16:31:52 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 16:31:52 stuehjttalere volumio[1013]: Forking 3 albumart workers May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::initPlayerControls May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: Express server listening on port 3000 May 15 16:31:53 stuehjttalere volumio[1013]: [Metrics] WebUI: 9s 919.09ms May 15 16:31:53 stuehjttalere systemd[1]: systemd-fsckd.service: Succeeded. May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::resetVolumioState May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::getcurrentVolume May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioRetrievevolume May 15 16:31:53 stuehjttalere volumio[1013]: info: Volumio Network Manager: Network status updated: 2 May 15 16:31:53 stuehjttalere volumio[1013]: info: Cannot mount NAS Enghave at system boot, trial number 1 ,retrying in 5 seconds May 15 16:31:53 stuehjttalere volumio[1013]: info: Reloading queue from file May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: Setting Device type: Raspberry PI May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::setRepeat null single undefined May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::pushState May 15 16:31:53 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioPushState May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::setRandom null May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::pushState May 15 16:31:53 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioPushState May 15 16:31:53 stuehjttalere volumio[1013]: info: VolumeController:: Volume=27 Mute =false May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::pushState May 15 16:31:53 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioPushState May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::updateTrackBlock May 15 16:31:53 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrackBlock May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioRetrievevolume May 15 16:31:53 stuehjttalere volumio[1013]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb May 15 16:31:53 stuehjttalere volumio[1013]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 May 15 16:31:53 stuehjttalere volumio[1013]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI May 15 16:31:53 stuehjttalere volumio[1013]: info: Completed loading Core Plugins May 15 16:31:53 stuehjttalere volumio[1013]: info: Preparing to generate the ALSA configuration file May 15 16:31:53 stuehjttalere volumio[1013]: Starting albumart workers May 15 16:31:53 stuehjttalere volumio[1013]: info: Discovery: adding b87ed83c-f963-44f9-844e-82083049c93f May 15 16:31:53 stuehjttalere volumio[1013]: Starting albumart workers May 15 16:31:53 stuehjttalere volumio[1013]: info: Discovery: Found device Stuehøjttalere May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioGetState May 15 16:31:53 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:53 stuehjttalere volumio[1013]: Starting albumart workers May 15 16:31:53 stuehjttalere volumio[1013]: info: VolumeController:: Volume=27 Mute =false May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreStateMachine::pushState May 15 16:31:53 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioPushState May 15 16:31:53 stuehjttalere volumio[1013]: info: Asound.conf file unchanged, so no further update is needed May 15 16:31:53 stuehjttalere volumio[1013]: info: Output device has changed, restarting MPD May 15 16:31:53 stuehjttalere volumio[1013]: info: Output device has changed, restarting Shairport Sync May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:53 stuehjttalere sudo[1275]: volumio : unable to resolve host stuehjttalere May 15 16:31:53 stuehjttalere sudo[1275]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:53 stuehjttalere sudo[1277]: volumio : unable to resolve host stuehjttalere May 15 16:31:53 stuehjttalere sudo[1277]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:53 stuehjttalere sudo[1275]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 15 16:31:53 stuehjttalere sudo[1277]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 15 16:31:53 stuehjttalere sudo[1275]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:53 stuehjttalere sudo[1277]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:53 stuehjttalere sudo[1275]: pam_unix(sudo:session): session closed for user root May 15 16:31:53 stuehjttalere volumio[1013]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 15 16:31:53 stuehjttalere systemd[1]: Stopping Music Player Daemon... May 15 16:31:53 stuehjttalere volumio[1013]: info: ___________ START PLUGINS ___________ May 15 16:31:53 stuehjttalere volumio[1013]: info: ControllerMpd::onStart: Initializing MPD May 15 16:31:53 stuehjttalere volumio[1013]: info: Creating MPD Configuration file May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 16:31:53 stuehjttalere volumio[1013]: info: [1747319513711] CoreMusicLibrary::Adding element Media Servers May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 16:31:53 stuehjttalere sudo[1284]: volumio : unable to resolve host stuehjttalere May 15 16:31:53 stuehjttalere sudo[1284]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:53 stuehjttalere sudo[1284]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 15 16:31:53 stuehjttalere sudo[1284]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:53 stuehjttalere sudo[1284]: pam_unix(sudo:session): session closed for user root May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:53 stuehjttalere systemd[1]: mpd.service: Succeeded. May 15 16:31:53 stuehjttalere systemd[1]: Stopped Music Player Daemon. May 15 16:31:53 stuehjttalere sudo[1286]: volumio : unable to resolve host stuehjttalere May 15 16:31:53 stuehjttalere sudo[1286]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:53 stuehjttalere sudo[1286]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 15 16:31:53 stuehjttalere systemd[1]: Starting Music Player Daemon... May 15 16:31:53 stuehjttalere sudo[1286]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:53 stuehjttalere systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM May 15 16:31:53 stuehjttalere systemd[1]: mpd.service: Succeeded. May 15 16:31:53 stuehjttalere systemd[1]: Stopped Music Player Daemon. May 15 16:31:53 stuehjttalere systemd[1]: Starting Music Player Daemon... May 15 16:31:53 stuehjttalere volumio[1013]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:53 stuehjttalere sudo[1293]: root : unable to resolve host stuehjttalere May 15 16:31:53 stuehjttalere sudo[1293]: root : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:53 stuehjttalere sudo[1293]: sudo: unable to resolve host stuehjttalere: System error May 15 16:31:53 stuehjttalere sudo[1293]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 15 16:31:53 stuehjttalere sudo[1293]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:53 stuehjttalere volumio[1013]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 16:31:53 stuehjttalere volumio[1013]: info: [1747319513925] CoreMusicLibrary::Adding element Last_100 May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 15 16:31:53 stuehjttalere volumio[1013]: info: [1747319513928] CoreMusicLibrary::Adding element Webradio May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 15 16:31:53 stuehjttalere sudo[1293]: pam_unix(sudo:session): session closed for user root May 15 16:31:53 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 16:31:53 stuehjttalere volumio[1013]: info: Initializing BBC Radios May 15 16:31:54 stuehjttalere sh[555]: timed out May 15 16:31:54 stuehjttalere dhcpcd[592]: timed out May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:54 stuehjttalere sh[555]: dhcpcd exited May 15 16:31:54 stuehjttalere dhcpcd[592]: dhcpcd exited May 15 16:31:54 stuehjttalere sh[555]: ifup: failed to bring up eth0 May 15 16:31:54 stuehjttalere systemd[1]: ifup@eth0.service: Main process exited, code=exited, status=1/FAILURE May 15 16:31:54 stuehjttalere systemd[1]: ifup@eth0.service: Failed with result 'exit-code'. May 15 16:31:54 stuehjttalere volumio[1013]: info: Creating Spotify config file May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: Volumio Calling Home May 15 16:31:54 stuehjttalere volumio[1013]: info: MPD Permissions set May 15 16:31:54 stuehjttalere volumio[1013]: info: MPD Permissions set May 15 16:31:54 stuehjttalere volumio[1013]: info: Spotify config file written May 15 16:31:54 stuehjttalere sudo[1338]: volumio : unable to resolve host stuehjttalere May 15 16:31:54 stuehjttalere volumio[1013]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 15 16:31:54 stuehjttalere sudo[1338]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:54 stuehjttalere sudo[1338]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere sudo[1338]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 15 16:31:54 stuehjttalere volumio[1013]: info: No need to fix Spotify hosts May 15 16:31:54 stuehjttalere systemd[1]: Started go-librespot Daemon. May 15 16:31:54 stuehjttalere go-librespot[1344]: Librespot-go daemon starting... May 15 16:31:54 stuehjttalere sudo[1338]: pam_unix(sudo:session): session closed for user root May 15 16:31:54 stuehjttalere volumio[1013]: info: Volumio called home May 15 16:31:54 stuehjttalere volumio[1013]: info: Starting Shairport Sync May 15 16:31:54 stuehjttalere volumio[1013]: info: Starting Shairport Sync May 15 16:31:54 stuehjttalere volumio[1013]: info: Starting Shairport Sync May 15 16:31:54 stuehjttalere sudo[1352]: volumio : unable to resolve host stuehjttalere May 15 16:31:54 stuehjttalere sudo[1352]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:54 stuehjttalere sudo[1352]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 15 16:31:54 stuehjttalere sudo[1352]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:54 stuehjttalere sudo[1357]: volumio : unable to resolve host stuehjttalere May 15 16:31:54 stuehjttalere sudo[1357]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:54 stuehjttalere sudo[1357]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 15 16:31:54 stuehjttalere sudo[1357]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:54 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioGetState May 15 16:31:54 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:54 stuehjttalere sudo[1360]: volumio : unable to resolve host stuehjttalere May 15 16:31:54 stuehjttalere sudo[1360]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:54 stuehjttalere sudo[1360]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 15 16:31:54 stuehjttalere sudo[1360]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:54 stuehjttalere systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 15 16:31:54 stuehjttalere systemd[1]: shairport-sync.service: Succeeded. May 15 16:31:54 stuehjttalere systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 15 16:31:54 stuehjttalere systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 15 16:31:54 stuehjttalere sudo[1357]: pam_unix(sudo:session): session closed for user root May 15 16:31:54 stuehjttalere volumio[1013]: info: An error occurred while refreshing Spotify Token Error: Bad Request May 15 16:31:54 stuehjttalere sudo[1352]: pam_unix(sudo:session): session closed for user root May 15 16:31:54 stuehjttalere volumio[1013]: info: Shairport-Sync Started May 15 16:31:54 stuehjttalere systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 15 16:31:54 stuehjttalere systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 15 16:31:54 stuehjttalere systemd[1]: shairport-sync.service: Succeeded. May 15 16:31:54 stuehjttalere systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 15 16:31:54 stuehjttalere volumio[1013]: Error adding Membership: Error: addMembership EINVAL May 15 16:31:54 stuehjttalere volumio[1013]: info: Shairport-Sync Started May 15 16:31:54 stuehjttalere systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 15 16:31:54 stuehjttalere sudo[1360]: pam_unix(sudo:session): session closed for user root May 15 16:31:54 stuehjttalere volumio[1013]: info: Shairport-Sync Started May 15 16:31:54 stuehjttalere go-librespot[1344]: time="2025-05-15T16:31:54+02:00" level=info msg="generated new device id: 486408ddb3b11040394b3899ee3c188fea95ac10" May 15 16:31:54 stuehjttalere mpd[1298]: May 15 16:31 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 15 16:31:54 stuehjttalere systemd[1]: Started Music Player Daemon. May 15 16:31:54 stuehjttalere sudo[1277]: pam_unix(sudo:session): session closed for user root May 15 16:31:54 stuehjttalere sudo[1286]: pam_unix(sudo:session): session closed for user root May 15 16:31:54 stuehjttalere volumio[1013]: error: MPD error: The expression evaluated to a falsy value: May 15 16:31:54 stuehjttalere volumio[1013]: assert.ok(self.idling) May 15 16:31:54 stuehjttalere volumio[1013]: error: The expression evaluated to a falsy value: May 15 16:31:54 stuehjttalere volumio[1013]: assert.ok(self.idling) May 15 16:31:54 stuehjttalere volumio[1013]: info: MPD running with PID1298 May 15 16:31:54 stuehjttalere volumio[1013]: ,establishing connection May 15 16:31:54 stuehjttalere volumio[1013]: error: updateQueue error: null May 15 16:31:54 stuehjttalere volumio[1013]: error: updateQueue error: null May 15 16:31:55 stuehjttalere go-librespot[1344]: time="2025-05-15T16:31:55+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 15 16:31:55 stuehjttalere go-librespot[1344]: time="2025-05-15T16:31:55+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" May 15 16:31:55 stuehjttalere go-librespot[1344]: time="2025-05-15T16:31:55+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" May 15 16:31:55 stuehjttalere go-librespot[1344]: time="2025-05-15T16:31:55+02:00" level=debug msg="zeroconf server listening on port 37797" May 15 16:31:55 stuehjttalere volumio[1013]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 15 16:31:55 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioRetrievevolume May 15 16:31:55 stuehjttalere volumio[1013]: info: VolumeController:: Volume=27 Mute =false May 15 16:31:55 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioGetState May 15 16:31:55 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:55 stuehjttalere volumio[1013]: info: CoreStateMachine::pushState May 15 16:31:55 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:31:55 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioPushState May 15 16:31:55 stuehjttalere systemd[1]: systemd-hostnamed.service: Succeeded. May 15 16:31:55 stuehjttalere volumio[1013]: info: Completed starting Core Plugins May 15 16:31:55 stuehjttalere volumio[1013]: info: ------------------------------------------- May 15 16:31:55 stuehjttalere volumio[1013]: info: ----- MyVolumio plugins startup ---- May 15 16:31:55 stuehjttalere volumio[1013]: info: ------------------------------------------- May 15 16:31:55 stuehjttalere volumio[1013]: info: [MyVolumio PluginManager] Fetching plans data.... May 15 16:31:56 stuehjttalere sudo[1394]: volumio : unable to resolve host stuehjttalere May 15 16:31:56 stuehjttalere sudo[1394]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:56 stuehjttalere sudo[1394]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 15 16:31:56 stuehjttalere sudo[1394]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:56 stuehjttalere sudo[1394]: pam_unix(sudo:session): session closed for user root May 15 16:31:56 stuehjttalere sudo[1396]: volumio : unable to resolve host stuehjttalere May 15 16:31:56 stuehjttalere sudo[1396]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:56 stuehjttalere sudo[1396]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 15 16:31:56 stuehjttalere sudo[1396]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:56 stuehjttalere sudo[1396]: pam_unix(sudo:session): session closed for user root May 15 16:31:56 stuehjttalere sudo[1398]: volumio : unable to resolve host stuehjttalere May 15 16:31:56 stuehjttalere sudo[1398]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:56 stuehjttalere sudo[1398]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 15 16:31:56 stuehjttalere sudo[1398]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:56 stuehjttalere systemd[1]: Started UPnP Renderer front-end to MPD. May 15 16:31:56 stuehjttalere sudo[1398]: pam_unix(sudo:session): session closed for user root May 15 16:31:56 stuehjttalere volumio[1013]: info: Upmpdcli Daemon Started May 15 16:31:56 stuehjttalere volumio[1402]: Generating RSA private key, 4096 bit long modulus (2 primes) May 15 16:31:57 stuehjttalere volumio[1013]: info: go-librespot daemon successfully initialized May 15 16:31:58 stuehjttalere sudo[1419]: volumio : unable to resolve host stuehjttalere May 15 16:31:58 stuehjttalere sudo[1419]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:31:58 stuehjttalere sudo[1419]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Sebastian,password=A6er?+0599til,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.2/Media/musik /mnt/NAS/Enghave May 15 16:31:58 stuehjttalere sudo[1419]: pam_unix(sudo:session): session opened for user root by (uid=0) May 15 16:31:58 stuehjttalere kernel: CIFS: Attempting to mount //192.168.0.2/Media/musik May 15 16:31:58 stuehjttalere sudo[1419]: pam_unix(sudo:session): session closed for user root May 15 16:31:58 stuehjttalere kernel: CIFS: Status code returned 0xc000006d STATUS_LOGON_FAILURE May 15 16:31:58 stuehjttalere kernel: CIFS: VFS: \\192.168.0.2 Send error in SessSetup = -13 May 15 16:31:58 stuehjttalere kernel: CIFS: VFS: cifs_mount failed w/return code = -13 May 15 16:31:58 stuehjttalere volumio[1013]: info: Cannot mount NAS Enghave at system boot, trial number 2 ,retrying in 5 seconds May 15 16:31:59 stuehjttalere volumio[1013]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 15 16:32:00 stuehjttalere volumio[1013]: info: Initializing connection to go-librespot Websocket May 15 16:32:00 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:00+02:00" level=debug msg="new websocket client" May 15 16:32:00 stuehjttalere volumio[1013]: info: Connection to go-librespot Websocket established May 15 16:32:00 stuehjttalere volumio[1402]: ...........................................++++ May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="obtained new client token: AABY/c+c1B3O81upIsgIwjk1t/LGLbVG9Ow0hfwQ4SMoQTzPQRtwv7G8AhEndB/Fa9w7wptOzVJ6xhICLEX2+v41Vq1cOON/qy75Yx5UvjYTGMgY9WspHbMNuBXQTUEdqr3J7vdBz00JFkSkIJdvwcVewgbPZfeU+S0AKUwp1XBsSup9fsfhUH/fdOR+tRZCeh92i448NVfsIc0pCPFIanksycDHu5gy4vG6re70E23nVjtne5hef5fVstvrsg==" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="completed keyexchange" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="completed challenge" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="authenticated as 11154185281" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="authenticated as 11154185281" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="dealer connection opened" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=info msg="accepted zeroconf user 11154185281 from iPhone" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="autoplay enabled: false" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="received connection id: MTA0NTIzMWQtYzNiNC00YmZkLWI5NjUtZTgxMGQ2ZDRkYzNhK2RlYWxlcit0Y3A6Ly8wYWNhNThkYS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNzU1MTBEMEZBNkZFM0EzNzFFNzE4MzREQjk1NTI1MEFBNTI0OUU1MjI3ODg4QjA1QzIyODQyRUVFOUYzN0Q2Nw==" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="put connect state because NEW_DEVICE" May 15 16:32:01 stuehjttalere volumio-remote-updater[672]: [2025-05-15 16:32:01] [connect] Successful connection May 15 16:32:01 stuehjttalere volumio-remote-updater[672]: [2025-05-15 16:32:01] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1747319521 101 May 15 16:32:01 stuehjttalere volumio[1013]: 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: 2 May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="handling transfer player command from 5d2c13322fd705f2e7b0b6418b5a4ff8bafb77e5" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="resolved context of track" uri="spotify:album:2Cqy1aiXAEPCYFuQl6HNFl" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=trace msg="fetched new page 0 with 9 items (list: 9)" uri="spotify:album:2Cqy1aiXAEPCYFuQl6HNFl" May 15 16:32:01 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:01+02:00" level=debug msg="loading track (paused: true, position: 43336ms)" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=trace msg="emitting websocket event: will_play" May 15 16:32:02 stuehjttalere volumio[1013]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6h9fEqjZksN77Kx5rahNTc","play_origin":"album"}} May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="selected format OGG_VORBIS_320 (13639a831eeb964fc71f4016fafdd64f7fc74be6)" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="requested aes key for file 13639a831eeb964fc71f4016fafdd64f7fc74be6, gid: 6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3178" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched first chunk of 15, total size is 7373253 bytes" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched chunk 2/14, size: 524288" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched chunk 3/14, size: 524288" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=trace msg="seek to 43336ms (diff: 121ms, samples: 1911117, bytes: 1899909)" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="created new output device" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=info msg="loaded track \"Min Bror\" (paused: true, position: 43336ms, duration: 165786ms, prefetched: false)" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched chunk 6/14, size: 524288" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=trace msg="emitting websocket event: metadata" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=trace msg="emitting websocket event: active" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="sending successful reply for dealer request" May 15 16:32:02 stuehjttalere volumio[1013]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6h9fEqjZksN77Kx5rahNTc","name":"Min Bror","artist_names":["Donya","MGP"],"album_name":"MGP 2025","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02189e324d3ec8ca364f013183","position":43336,"duration":165786,"release_date":"year:2025 month:1 day:31","track_number":1,"disc_number":1}} May 15 16:32:02 stuehjttalere volumio[1013]: SPOTIFY: received: {"type":"active","data":null} May 15 16:32:02 stuehjttalere volumio[1013]: info: Aligning Spotify Volume to Volumio Volume May 15 16:32:02 stuehjttalere volumio[1013]: info: CoreCommandRouter::volumioGetState May 15 16:32:02 stuehjttalere volumio[1013]: info: CorePlayQueue::getTrack 0 May 15 16:32:02 stuehjttalere volumio[1013]: info: Setting Spotify Volume from Volumio: 27 May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched chunk 1/14, size: 524288" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched chunk 5/14, size: 524288" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="fetched chunk 4/14, size: 524288" uri="spotify:track:6h9fEqjZksN77Kx5rahNTc" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=trace msg="emitting websocket event: paused" May 15 16:32:02 stuehjttalere volumio[1013]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6h9fEqjZksN77Kx5rahNTc","play_origin":"album"}} May 15 16:32:02 stuehjttalere volumio[1013]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 15 16:32:02 stuehjttalere volumio[1013]: TypeError: Cannot read property 'service' of undefined May 15 16:32:02 stuehjttalere volumio[1013]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 15 16:32:02 stuehjttalere volumio[1013]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:271:18) May 15 16:32:02 stuehjttalere volumio[1013]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 15 16:32:02 stuehjttalere volumio[1013]: at WebSocket.emit (events.js:315:20) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver.emit (events.js:315:20) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 15 16:32:02 stuehjttalere volumio[1013]: at writeOrBuffer (internal/streams/writable.js:358:12) May 15 16:32:02 stuehjttalere volumio[1013]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 15 16:32:02 stuehjttalere volumio[1013]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 15 16:32:02 stuehjttalere volumio[1013]: at Socket.emit (events.js:315:20) May 15 16:32:02 stuehjttalere volumio[1013]: at addChunk (internal/streams/readable.js:309:12) May 15 16:32:02 stuehjttalere volumio[1013]: at readableAddChunk (internal/streams/readable.js:284:9) May 15 16:32:02 stuehjttalere volumio[1013]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 15 16:32:02 stuehjttalere go-librespot[1344]: time="2025-05-15T16:32:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2037" May 15 16:32:02 stuehjttalere sudo[1435]: volumio : unable to resolve host stuehjttalere May 15 16:32:02 stuehjttalere sudo[1435]: volumio : problem with defaults entries ; TTY=unknown ; PWD=/ ; USER=root ; May 15 16:32:02 stuehjttalere sudo[1435]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-15 16:31 May 15 16:32:02 stuehjttalere sudo[1435]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"