-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Tue 2025-05-27 21:04:42 CEST. --
May 27 21:03:43 volumio-jonas systemd-timedated[749]: Changed local time to Tue May 27 21:03:43 2025
May 27 21:03:43 volumio-jonas sudo[744]: pam_unix(sudo:session): session closed for user root
May 27 21:03:43 volumio-jonas volumio-time-update[454]: volumio-time-update-util: System time updated successfully.
May 27 21:03:43 volumio-jonas systemd[1]: Starting Daily apt download activities...
May 27 21:03:43 volumio-jonas systemd[1]: Started Volumio Time Update Utility.
May 27 21:03:43 volumio-jonas winbindd[733]: [2025/05/27 21:03:43.321902, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv)
May 27 21:03:43 volumio-jonas winbindd[733]: res_names->count = 3, expected 4
May 27 21:03:43 volumio-jonas smbd[738]: [2025/05/27 21:03:43.453482, 0] ../lib/util/become_daemon.c:138(daemon_ready)
May 27 21:03:43 volumio-jonas systemd[1]: Started Samba SMB Daemon.
May 27 21:03:43 volumio-jonas smbd[738]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections
May 27 21:03:43 volumio-jonas systemd[1]: Reached target Multi-User System.
May 27 21:03:43 volumio-jonas systemd[1]: Reached target Graphical Interface.
May 27 21:03:43 volumio-jonas systemd[1]: Starting Update UTMP about System Runlevel Changes...
May 27 21:03:43 volumio-jonas systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
May 27 21:03:43 volumio-jonas systemd[1]: Started Update UTMP about System Runlevel Changes.
May 27 21:03:43 volumio-jonas nmbd[611]: [2025/05/27 21:03:43.752374, 0] ../source3/nmbd/nmbd_namequery.c:109(query_name_response)
May 27 21:03:43 volumio-jonas nmbd[611]: query_name_response: Multiple (2) responses received for a query on subnet 192.168.179.88 for name WORKGROUP<1d>.
May 27 21:03:43 volumio-jonas nmbd[611]: This response was from IP 192.168.179.48, reporting an IP address of 192.168.179.48.
May 27 21:03:44 volumio-jonas volumio-remote-updater[446]: [2025-05-27 21:03:44] [connect] Successful connection
May 27 21:03:45 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:03:45 volumio-jonas volumio[664]: info: ----- Volumio3 ----
May 27 21:03:45 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:03:45 volumio-jonas volumio[664]: info: ----- System startup ----
May 27 21:03:45 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:03:48 volumio-jonas volumio[664]: info: MYVOLUMIO Environment detected
May 27 21:03:49 volumio-jonas volumio[664]: info: Plugin folders cleanup
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning into folder /volumio/app/plugins/
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category audio_interface
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category miscellanea
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category music_service
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category plugins.json
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category system_controller
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category user_interface
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning into folder /data/plugins/
May 27 21:03:49 volumio-jonas volumio[664]: info: Scanning category music_service
May 27 21:03:49 volumio-jonas volumio[664]: info: Plugin folders cleanup completed
May 27 21:03:49 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:03:49 volumio-jonas volumio[664]: info: ----- Core plugins startup ----
May 27 21:03:49 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:03:49 volumio-jonas volumio[664]: info: Loading plugins from folder /volumio/app/plugins/
May 27 21:03:49 volumio-jonas volumio[664]: info: Adding plugin upnp to MyMusic Plugins
May 27 21:03:49 volumio-jonas volumio[664]: info: Adding plugin airplay_emulation to MyMusic Plugins
May 27 21:03:49 volumio-jonas volumio[664]: info: Adding plugin upnp_browser to MyMusic Plugins
May 27 21:03:49 volumio-jonas volumio[664]: info: Loading plugins from folder /data/plugins/
May 27 21:03:49 volumio-jonas volumio[664]: info: Loading plugin "system"...
May 27 21:03:49 volumio-jonas volumio[664]: info: Loading plugin "appearance"...
May 27 21:03:49 volumio-jonas systemd[1]: apt-daily.service: Succeeded.
May 27 21:03:49 volumio-jonas systemd[1]: Started Daily apt download activities.
May 27 21:03:49 volumio-jonas systemd[1]: Starting Daily apt upgrade and clean activities...
May 27 21:03:53 volumio-jonas volumio[664]: info: Loading plugin "network"...
May 27 21:03:53 volumio-jonas volumio[664]: info: Refreshing Cached IP Addresses
May 27 21:03:53 volumio-jonas sudo[866]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
May 27 21:03:53 volumio-jonas sudo[866]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:03:53 volumio-jonas sudo[868]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
May 27 21:03:53 volumio-jonas sudo[868]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:03:53 volumio-jonas sudo[866]: pam_unix(sudo:session): session closed for user root
May 27 21:03:53 volumio-jonas volumio[664]: info: Loading plugin "services"...
May 27 21:03:53 volumio-jonas volumio[664]: info: Loading plugin "alsa_controller"...
May 27 21:03:53 volumio-jonas sudo[868]: pam_unix(sudo:session): session closed for user root
May 27 21:03:53 volumio-jonas sudo[880]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
May 27 21:03:53 volumio-jonas sudo[880]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:03:53 volumio-jonas systemd[1]: apt-daily-upgrade.service: Succeeded.
May 27 21:03:53 volumio-jonas systemd[1]: Started Daily apt upgrade and clean activities.
May 27 21:03:53 volumio-jonas systemd[1]: Startup finished in 16.523s (kernel) + 33.762s (userspace) = 50.285s.
May 27 21:03:53 volumio-jonas sudo[880]: pam_unix(sudo:session): session closed for user root
May 27 21:03:54 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
May 27 21:03:54 volumio-jonas volumio[664]: info: Loading plugin "wizard"...
May 27 21:03:54 volumio-jonas volumio[664]: info: Loading plugin "networkfs"...
May 27 21:03:54 volumio-jonas volumio[664]: info: Starting Udev Watcher for removable devices
May 27 21:03:54 volumio-jonas sudo[903]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.179.48/Hoerspiele /mnt/NAS/Hoerspiele
May 27 21:03:54 volumio-jonas sudo[903]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:03:54 volumio-jonas sudo[905]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.179.48/Kindermusik /mnt/NAS/Kindermusik
May 27 21:03:54 volumio-jonas sudo[905]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:03:54 volumio-jonas volumio[664]: info: Ignoring mount for partition: boot
May 27 21:03:54 volumio-jonas volumio[664]: info: Ignoring mount for partition: volumio
May 27 21:03:54 volumio-jonas volumio[664]: info: Ignoring mount for partition: volumio_data
May 27 21:03:54 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
May 27 21:03:54 volumio-jonas volumio[664]: info: Loading plugin "volumio_command_line_client"...
May 27 21:03:54 volumio-jonas volumio[664]: info: Loading plugin "upnp"...
May 27 21:03:54 volumio-jonas volumio[664]: info: [1748372634499] Starting Upmpd Daemon
May 27 21:03:54 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
May 27 21:03:54 volumio-jonas volumio[664]: info: Loading plugin "my_music"...
May 27 21:03:54 volumio-jonas volumio[664]: info: Loading plugin "mpd"...
May 27 21:03:54 volumio-jonas kernel: Key type cifs.spnego registered
May 27 21:03:54 volumio-jonas kernel: Key type cifs.idmap registered
May 27 21:03:54 volumio-jonas 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 27 21:03:54 volumio-jonas kernel: CIFS: Attempting to mount //192.168.179.48/Kindermusik
May 27 21:03:55 volumio-jonas kernel: cryptd: max_cpu_qlen set to 1000
May 27 21:03:55 volumio-jonas sudo[905]: pam_unix(sudo:session): session closed for user root
May 27 21:03:55 volumio-jonas kernel: CIFS: Attempting to mount //192.168.179.48/Hoerspiele
May 27 21:03:55 volumio-jonas sudo[903]: pam_unix(sudo:session): session closed for user root
May 27 21:03:56 volumio-jonas volumio[664]: info: Loading plugin "upnp_browser"...
May 27 21:03:57 volumio-jonas volumio[664]: info: Loading plugin "alarm-clock"...
May 27 21:03:57 volumio-jonas volumio[664]: info: Loading plugin "airplay_emulation"...
May 27 21:03:57 volumio-jonas volumio[664]: info: Starting Shairport Sync
May 27 21:03:57 volumio-jonas volumio[664]: info: Loading plugin "last_100"...
May 27 21:03:57 volumio-jonas volumio[664]: info: Loading plugin "webradio"...
May 27 21:03:58 volumio-jonas systemd[1]: systemd-fsckd.service: Succeeded.
May 27 21:03:58 volumio-jonas volumio[664]: info: Loading plugin "i2s_dacs"...
May 27 21:03:58 volumio-jonas volumio[664]: info: I2S DAC not set, start Auto-detection
May 27 21:03:58 volumio-jonas volumio[664]: info: Loading plugin "volumiodiscovery"...
May 27 21:03:58 volumio-jonas volumio[664]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
May 27 21:03:58 volumio-jonas volumio[664]: *** WARNING *** Please fix your application to use the native API of Avahi!
May 27 21:03:58 volumio-jonas node[664]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
May 27 21:03:58 volumio-jonas volumio[664]: *** WARNING *** For more information see
May 27 21:03:58 volumio-jonas volumio[664]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
May 27 21:03:58 volumio-jonas volumio[664]: *** WARNING *** Please fix your application to use the native API of Avahi!
May 27 21:03:58 volumio-jonas volumio[664]: *** WARNING *** For more information see
May 27 21:03:58 volumio-jonas node[664]: *** WARNING *** Please fix your application to use the native API of Avahi!
May 27 21:03:58 volumio-jonas node[664]: *** WARNING *** For more information see
May 27 21:03:58 volumio-jonas node[664]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
May 27 21:03:58 volumio-jonas node[664]: *** WARNING *** Please fix your application to use the native API of Avahi!
May 27 21:03:58 volumio-jonas node[664]: *** WARNING *** For more information see
May 27 21:03:58 volumio-jonas volumio[664]: info: Applying required configuration parameters for plugin volumiodiscovery
May 27 21:03:58 volumio-jonas volumio[664]: info: Discovery: Started advertising with name: Volumio Jonas
May 27 21:03:58 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback
May 27 21:03:58 volumio-jonas volumio[664]: info: Loading plugin "spop"...
May 27 21:03:59 volumio-jonas volumio-remote-updater[446]: [2025-05-27 21:03:59] [connect] Successful connection
May 27 21:04:02 volumio-jonas volumio[664]: info: Loading plugin "youtube2"...
May 27 21:04:11 volumio-jonas volumio[664]: info: Loading plugin "ytcr"...
May 27 21:04:13 volumio-jonas systemd[1]: systemd-timedated.service: Succeeded.
May 27 21:04:14 volumio-jonas volumio-remote-updater[446]: [2025-05-27 21:04:14] [connect] Successful connection
May 27 21:04:24 volumio-jonas volumio[664]: info: Loading plugin "outputs"...
May 27 21:04:24 volumio-jonas volumio[664]: info: Loading plugin "albumart"...
May 27 21:04:24 volumio-jonas volumio[664]: info: Plugin example_plugin is not enabled
May 27 21:04:24 volumio-jonas volumio[664]: info: Loading plugin "inputs"...
May 27 21:04:24 volumio-jonas volumio[664]: info: Loading plugin "updater_comm"...
May 27 21:04:25 volumio-jonas volumio[664]: info: Plugin mpdemulation is not enabled
May 27 21:04:25 volumio-jonas volumio[664]: info: Loading plugin "rest_api"...
May 27 21:04:25 volumio-jonas volumio[664]: info: Loading plugin "websocket"...
May 27 21:04:25 volumio-jonas volumio[664]: info: Starting Socket.io Server version 2.3.0
May 27 21:04:25 volumio-jonas volumio[664]: info: Loading i18n strings for locale de
May 27 21:04:25 volumio-jonas volumio[664]: Updating browse sources language
May 27 21:04:25 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 27 21:04:25 volumio-jonas volumio[664]: Forking 3 albumart workers
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::initPlayerControls
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
May 27 21:04:26 volumio-jonas volumio[664]: Express server listening on port 3000
May 27 21:04:26 volumio-jonas volumio[664]: [Metrics] WebUI: 43s 571.48ms
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreStateMachine::resetVolumioState
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreStateMachine::getcurrentVolume
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioRetrievevolume
May 27 21:04:26 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:26 volumio-jonas sudo[1036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
May 27 21:04:26 volumio-jonas sudo[1036]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:26 volumio-jonas sudo[1036]: pam_unix(sudo:session): session closed for user root
May 27 21:04:26 volumio-jonas sudo[1038]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
May 27 21:04:26 volumio-jonas sudo[1038]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:26 volumio-jonas volumio[664]: info: Volumio Network Manager: Network status updated: 1
May 27 21:04:26 volumio-jonas sudo[1038]: pam_unix(sudo:session): session closed for user root
May 27 21:04:26 volumio-jonas volumio[664]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan
May 27 21:04:26 volumio-jonas volumio[664]: wlan0 Interface doesn't support scanning.
May 27 21:04:26 volumio-jonas volumio[664]: info: Cannot use regular scanning, forcing with ap-force
May 27 21:04:27 volumio-jonas sudo[1045]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force
May 27 21:04:27 volumio-jonas sudo[1045]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:27 volumio-jonas sudo[1045]: pam_unix(sudo:session): session closed for user root
May 27 21:04:27 volumio-jonas volumio[664]: command failed: No such device (-19)
May 27 21:04:27 volumio-jonas volumio[664]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force
May 27 21:04:27 volumio-jonas volumio[664]: command failed: No such device (-19)
May 27 21:04:27 volumio-jonas volumio[664]: info: VolumeController:: Volume=35 Mute =false
May 27 21:04:27 volumio-jonas volumio[664]: info: CoreStateMachine::pushState
May 27 21:04:27 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:27 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 27 21:04:27 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioPushState
May 27 21:04:27 volumio-jonas volumio[664]: info: CoreStateMachine::updateTrackBlock
May 27 21:04:27 volumio-jonas volumio[664]: info: CorePlayQueue::getTrackBlock
May 27 21:04:27 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioRetrievevolume
May 27 21:04:28 volumio-jonas volumio[664]: info: Reloading queue from file
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreStateMachine::setRepeat false single undefined
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreStateMachine::pushState
May 27 21:04:28 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioPushState
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreStateMachine::setRandom null
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreStateMachine::pushState
May 27 21:04:28 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioPushState
May 27 21:04:28 volumio-jonas volumio[664]: info: Setting Device type: Raspberry PI
May 27 21:04:28 volumio-jonas volumio[664]: Starting albumart workers
May 27 21:04:28 volumio-jonas volumio[664]: info: VolumeController:: Volume=35 Mute =false
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreStateMachine::pushState
May 27 21:04:28 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioPushState
May 27 21:04:28 volumio-jonas volumio[664]: Starting albumart workers
May 27 21:04:28 volumio-jonas volumio[664]: info: Discovery: adding f9038885-80c4-4f07-9f0d-7c31dd2a5854
May 27 21:04:28 volumio-jonas volumio[664]: info: Discovery: Found device VolumioTabea
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioGetState
May 27 21:04:28 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:28 volumio-jonas volumio[664]: info: Completed loading Core Plugins
May 27 21:04:28 volumio-jonas sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
May 27 21:04:28 volumio-jonas sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:28 volumio-jonas volumio[664]: info: Preparing to generate the ALSA configuration file
May 27 21:04:28 volumio-jonas volumio[664]: info: Discovery: this is already registered, f9038885-80c4-4f07-9f0d-7c31dd2a5854
May 27 21:04:28 volumio-jonas volumio[664]: info: Discovery: Found device Volumio Jonas
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioGetState
May 27 21:04:28 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:28 volumio-jonas volumio[664]: info: Asound.conf file unchanged, so no further update is needed
May 27 21:04:28 volumio-jonas volumio[664]: info: Output device has changed, restarting MPD
May 27 21:04:28 volumio-jonas systemd[1]: Started UPnP Renderer front-end to MPD.
May 27 21:04:28 volumio-jonas sudo[1058]: pam_unix(sudo:session): session closed for user root
May 27 21:04:28 volumio-jonas volumio[664]: Starting albumart workers
May 27 21:04:28 volumio-jonas sudo[1062]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
May 27 21:04:28 volumio-jonas sudo[1062]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:28 volumio-jonas volumio[664]: info: Output device has changed, restarting Shairport Sync
May 27 21:04:28 volumio-jonas sudo[1062]: pam_unix(sudo:session): session closed for user root
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:28 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:28 volumio-jonas sudo[1064]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
May 27 21:04:28 volumio-jonas sudo[1064]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:28 volumio-jonas systemd[1]: Stopping Music Player Daemon...
May 27 21:04:29 volumio-jonas volumio-remote-updater[446]: [2025-05-27 21:04:29] [connect] Successful connection
May 27 21:04:29 volumio-jonas volumio[664]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
May 27 21:04:29 volumio-jonas volumio[664]: info: ___________ START PLUGINS ___________
May 27 21:04:29 volumio-jonas volumio[664]: info: ControllerMpd::onStart: Initializing MPD
May 27 21:04:29 volumio-jonas volumio[664]: info: Creating MPD Configuration file
May 27 21:04:29 volumio-jonas systemd[1]: mpd.service: Succeeded.
May 27 21:04:29 volumio-jonas systemd[1]: Stopped Music Player Daemon.
May 27 21:04:29 volumio-jonas systemd[1]: Starting Music Player Daemon...
May 27 21:04:29 volumio-jonas sudo[1072]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
May 27 21:04:29 volumio-jonas sudo[1072]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:29 volumio-jonas sudo[1072]: pam_unix(sudo:session): session closed for user root
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
May 27 21:04:29 volumio-jonas volumio[664]: info: [1748372669428] CoreMusicLibrary::Adding element Medienserver
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 27 21:04:29 volumio-jonas sudo[1075]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
May 27 21:04:29 volumio-jonas sudo[1075]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:29 volumio-jonas systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM
May 27 21:04:29 volumio-jonas systemd[1]: mpd.service: Succeeded.
May 27 21:04:29 volumio-jonas systemd[1]: Stopped Music Player Daemon.
May 27 21:04:29 volumio-jonas systemd[1]: Starting Music Player Daemon...
May 27 21:04:29 volumio-jonas volumio[664]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:29 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:30 volumio-jonas volumio[664]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
May 27 21:04:30 volumio-jonas volumio[664]: info: [1748372670042] CoreMusicLibrary::Adding element Last_100
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
May 27 21:04:30 volumio-jonas volumio[664]: info: [1748372670056] CoreMusicLibrary::Adding element Webradio
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
May 27 21:04:30 volumio-jonas volumio[664]: info: Initializing BBC Radios
May 27 21:04:30 volumio-jonas sudo[1078]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
May 27 21:04:30 volumio-jonas sudo[1078]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:30 volumio-jonas sudo[1078]: pam_unix(sudo:session): session closed for user root
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:30 volumio-jonas volumio[664]: info: Creating Spotify config file
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object]
May 27 21:04:30 volumio-jonas volumio[664]: info: [1748372670470] CoreMusicLibrary::Adding element YouTube2
May 27 21:04:30 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
May 27 21:04:30 volumio-jonas volumio[664]: Cannot find translation for source YouTube2
May 27 21:04:30 volumio-jonas volumio[664]: info: Volumio Calling Home
May 27 21:04:31 volumio-jonas volumiologrotate[482]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory
May 27 21:04:31 volumio-jonas volumiologrotate[482]: ls: cannot access 'JONAS': No such file or directory
May 27 21:04:32 volumio-jonas volumio[664]: info: MPD Permissions set
May 27 21:04:32 volumio-jonas volumio[664]: info: MPD Permissions set
May 27 21:04:32 volumio-jonas volumio[664]: info: Upmpdcli Daemon Started
May 27 21:04:32 volumio-jonas volumio-remote-updater[446]: [2025-05-27 21:04:32] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748372669 101
May 27 21:04:32 volumio-jonas volumio[664]: 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
May 27 21:04:32 volumio-jonas volumio[664]: info: Volumio called home
May 27 21:04:32 volumio-jonas volumio[664]: info: Spotify config file written
May 27 21:04:32 volumio-jonas sudo[1165]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
May 27 21:04:32 volumio-jonas sudo[1165]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:32 volumio-jonas systemd[1]: Started go-librespot Daemon.
May 27 21:04:32 volumio-jonas go-librespot[1167]: go-librespot daemon starting...
May 27 21:04:32 volumio-jonas sudo[1165]: pam_unix(sudo:session): session closed for user root
May 27 21:04:33 volumio-jonas volumio[664]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2
May 27 21:04:33 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:33+02:00" level=info msg="running go-librespot 0.2.0"
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:33+02:00" level=debug msg="app state loaded"
May 27 21:04:33 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:33+02:00" level=debug msg="stored credentials not found"
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:33+02:00" level=info msg="api server listening on 127.0.0.1:9879"
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
May 27 21:04:33 volumio-jonas volumio[664]: info: No need to fix Spotify hosts
May 27 21:04:33 volumio-jonas volumio[664]: info: Starting Shairport Sync
May 27 21:04:33 volumio-jonas volumio[664]: info: Starting Shairport Sync
May 27 21:04:33 volumio-jonas sudo[1185]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
May 27 21:04:33 volumio-jonas sudo[1185]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:33 volumio-jonas volumio[664]: info: Starting Shairport Sync
May 27 21:04:34 volumio-jonas sudo[1187]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
May 27 21:04:34 volumio-jonas sudo[1187]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:34 volumio-jonas systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
May 27 21:04:34 volumio-jonas systemd[1]: shairport-sync.service: Succeeded.
May 27 21:04:34 volumio-jonas systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
May 27 21:04:34 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:34+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 27 21:04:34 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:34+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 27 21:04:34 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:34+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 27 21:04:34 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:34+02:00" level=info msg="zeroconf server listening on port 35859"
May 27 21:04:34 volumio-jonas sudo[1192]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
May 27 21:04:34 volumio-jonas sudo[1192]: pam_unix(sudo:session): session opened for user root by (uid=0)
May 27 21:04:34 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioGetState
May 27 21:04:34 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:34 volumio-jonas systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 27 21:04:34 volumio-jonas sudo[1185]: pam_unix(sudo:session): session closed for user root
May 27 21:04:34 volumio-jonas systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
May 27 21:04:34 volumio-jonas systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM
May 27 21:04:34 volumio-jonas systemd[1]: shairport-sync.service: Succeeded.
May 27 21:04:34 volumio-jonas systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
May 27 21:04:34 volumio-jonas systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
May 27 21:04:34 volumio-jonas volumio[664]: info: Shairport-Sync Started
May 27 21:04:34 volumio-jonas volumio[664]: Error adding Membership: Error: addMembership EINVAL
May 27 21:04:34 volumio-jonas sudo[1187]: pam_unix(sudo:session): session closed for user root
May 27 21:04:34 volumio-jonas sudo[1192]: pam_unix(sudo:session): session closed for user root
May 27 21:04:34 volumio-jonas volumio[664]: info: Shairport-Sync Started
May 27 21:04:34 volumio-jonas volumio[664]: info: Shairport-Sync Started
May 27 21:04:34 volumio-jonas mpd[1091]: May 27 21:04 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
May 27 21:04:34 volumio-jonas systemd[1]: Started Music Player Daemon.
May 27 21:04:34 volumio-jonas sudo[1064]: pam_unix(sudo:session): session closed for user root
May 27 21:04:34 volumio-jonas sudo[1075]: pam_unix(sudo:session): session closed for user root
May 27 21:04:34 volumio-jonas volumio[664]: Upnp client error: Error: This socket has been ended by the other party
May 27 21:04:35 volumio-jonas volumio[664]: error: MPD error: The expression evaluated to a falsy value:
May 27 21:04:35 volumio-jonas volumio[664]: assert.ok(self.idling)
May 27 21:04:35 volumio-jonas volumio[664]: error: The expression evaluated to a falsy value:
May 27 21:04:35 volumio-jonas volumio[664]: assert.ok(self.idling)
May 27 21:04:35 volumio-jonas volumio[664]: error: updateQueue error: null
May 27 21:04:35 volumio-jonas volumio[664]: info: MPD running with PID1091
May 27 21:04:35 volumio-jonas volumio[664]: ,establishing connection
May 27 21:04:35 volumio-jonas volumio[664]: error: updateQueue error: null
May 27 21:04:35 volumio-jonas volumio[1060]: Generating RSA private key, 4096 bit long modulus (2 primes)
May 27 21:04:35 volumio-jonas volumio[664]: info: [yt-cast-receiver] DIAL server listening on port 8098
May 27 21:04:35 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioRetrievevolume
May 27 21:04:35 volumio-jonas volumio[664]: info: VolumeController:: Volume=35 Mute =false
May 27 21:04:35 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioGetState
May 27 21:04:35 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:35 volumio-jonas volumio[664]: info: CoreStateMachine::pushState
May 27 21:04:35 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:35 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioPushState
May 27 21:04:36 volumio-jonas volumio[664]: info: Completed starting Core Plugins
May 27 21:04:36 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:04:36 volumio-jonas volumio[664]: info: ----- MyVolumio plugins startup ----
May 27 21:04:36 volumio-jonas volumio[664]: info: -------------------------------------------
May 27 21:04:36 volumio-jonas volumio[664]: info: [MyVolumio PluginManager] Fetching plans data....
May 27 21:04:36 volumio-jonas volumio[664]: info: go-librespot daemon successfully initialized
May 27 21:04:38 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:38+02:00" level=debug msg="obtained new client token: AAAsSCGgAq6xZSOzttmNBNAQZYlo/WZZcXpRfiMdFn1cU+yFBCZWIrR6voD4NaExKBJpijJmQgZaUglVVn/wYR3FTWJd98MPmHgA7LgH/dkHhUiB1vhgQ3IXS0/pCCePVGhiZCCVlOqDRlzLITD/+2hINCHwvvrrQs9PJoHiHa7uF8NB+ltPBybTPTAqncRkeSkcUx3Dn7Vam+FkZ5ac71DQDo+nXu9g1XyWu87UzYweXi9c25riRe+hSw=="
May 27 21:04:38 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:38+02:00" level=debug msg="connected to ap-gew4.spotify.com:4070"
May 27 21:04:38 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:38+02:00" level=debug msg="completed keyexchange"
May 27 21:04:38 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:38+02:00" level=debug msg="completed challenge"
May 27 21:04:38 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:38+02:00" level=info msg="authenticated AP as sr2831"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=info msg="authenticated Login5 as sr2831"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=info msg="accepted zeroconf user sr2831 from TuxDesktop"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="dealer connection opened"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=trace msg="starting accesspoint recv loop"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=trace msg="starting dealer recv loop"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=trace msg="received accesspoint ping"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="received connection id: NTQyZGYwZjMtN2FkYS00MDcxLWE0NGItMTNlNDc2ZDYzYzQzK2RlYWxlcit0Y3A6Ly8wYWNhNTk5Ny5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDc3REY0M0FFMzA2Q0MzM0ZDMDc5MTg1ODkyMzhGOERCNjVDNzcyNTMwOEQxQzUzMTlDRTE5QUY3QTQ5QUNFNQ=="
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="put connect state because NEW_DEVICE"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=trace msg="received accesspoint pong ack"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="handling transfer player command from 69e80b5078f6bc90cbe8c619d2e20b8aefdf09b3"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="resolved context of track" uri="spotify:search:balbina+seife"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:balbina+seife"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="loading track (paused: true, position: 0ms)" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=trace msg="emitting websocket event: will_play"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="selected format OGG_VORBIS_320 (a65547367b57d7ca04be42e88a03d312f3b8e8c3)" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="requested aes key for file a65547367b57d7ca04be42e88a03d312f3b8e8c3, gid: 0ber5FA222ioBTrWK4u74n"
May 27 21:04:39 volumio-jonas volumio[664]: info: Initializing connection to go-librespot Websocket
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1330"
May 27 21:04:39 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:39+02:00" level=debug msg="new websocket client"
May 27 21:04:39 volumio-jonas volumio[664]: info: Connection to go-librespot Websocket established
May 27 21:04:39 volumio-jonas volumio[664]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1112"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="fetched first chunk of 19, total size is 9853056 bytes" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="created new output device"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=info msg="loaded track \"Seife (feat. Maeckes)\" (paused: true, position: 0ms, duration: 238933ms, prefetched: false)" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=trace msg="emitting websocket event: metadata"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=trace msg="emitting websocket event: active"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="sending successful reply for dealer request"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
May 27 21:04:40 volumio-jonas volumio[664]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0ber5FA222ioBTrWK4u74n","name":"Seife (feat. Maeckes)","artist_names":["Balbina","Maeckes"],"album_name":"Nichtstun - EP","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02252ab2867ef3765601f7a590","position":0,"duration":238933,"release_date":"year:2014 month:6 day:27","track_number":4,"disc_number":1}}
May 27 21:04:40 volumio-jonas volumio[664]: SPOTIFY: received: {"type":"active","data":null}
May 27 21:04:40 volumio-jonas volumio[664]: info: Aligning Spotify Volume to Volumio Volume
May 27 21:04:40 volumio-jonas volumio[664]: info: CoreCommandRouter::volumioGetState
May 27 21:04:40 volumio-jonas volumio[664]: info: CorePlayQueue::getTrack 0
May 27 21:04:40 volumio-jonas volumio[664]: info: Setting Spotify Volume from Volumio: 35
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=trace msg="emitting websocket event: paused"
May 27 21:04:40 volumio-jonas volumio[664]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0ber5FA222ioBTrWK4u74n","play_origin":"search"}}
May 27 21:04:40 volumio-jonas volumio[664]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
May 27 21:04:40 volumio-jonas volumio[664]: TypeError: Cannot read property 'service' of undefined
May 27 21:04:40 volumio-jonas volumio[664]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50)
May 27 21:04:40 volumio-jonas volumio[664]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:274:18)
May 27 21:04:40 volumio-jonas volumio[664]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14)
May 27 21:04:40 volumio-jonas volumio[664]: at WebSocket.emit (events.js:315:20)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver.emit (events.js:315:20)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10)
May 27 21:04:40 volumio-jonas volumio[664]: at writeOrBuffer (internal/streams/writable.js:358:12)
May 27 21:04:40 volumio-jonas volumio[664]: at Receiver.Writable.write (internal/streams/writable.js:303:10)
May 27 21:04:40 volumio-jonas volumio[664]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35)
May 27 21:04:40 volumio-jonas volumio[664]: at Socket.emit (events.js:315:20)
May 27 21:04:40 volumio-jonas volumio[664]: at addChunk (internal/streams/readable.js:309:12)
May 27 21:04:40 volumio-jonas volumio[664]: at readableAddChunk (internal/streams/readable.js:284:9)
May 27 21:04:40 volumio-jonas volumio[664]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:40 volumio-jonas ntpd[631]: Soliciting pool server 144.76.59.37
May 27 21:04:40 volumio-jonas go-librespot[1167]: time="2025-05-27T21:04:40+02:00" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:0ber5FA222ioBTrWK4u74n"
May 27 21:04:41 volumio-jonas ntpd[631]: Soliciting pool server 217.160.19.219
May 27 21:04:42 volumio-jonas sudo[1243]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-27 21:03
May 27 21:04:42 volumio-jonas sudo[1243]: 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="e32c2c71ae78852844c70357816bdd871c155ab8"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Mon 31 Mar 2025 06:54:47 PM CEST"
VOLUMIO_VERSION="3.799"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="436f3f84f6d0b4ffc344f0bc132a32e8"