-- Logs begin at Mon 2025-01-20 16:40:56 CET, end at Mon 2025-05-26 22:24:04 CEST. -- May 26 22:23:39 volumio-sz systemd-timedated[901]: Changed local time to Mon May 26 22:23:39 2025 May 26 22:23:39 volumio-sz sudo[895]: pam_unix(sudo:session): session closed for user root May 26 22:23:39 volumio-sz volumio-time-update[615]: volumio-time-update-util: System time updated successfully. May 26 22:23:39 volumio-sz systemd[1]: Starting Daily apt download activities... May 26 22:23:39 volumio-sz systemd[1]: Started Volumio Time Update Utility. May 26 22:23:39 volumio-sz sudo[905]: pam_unix(sudo:session): session closed for user root May 26 22:23:39 volumio-sz wireless.js[611]: Stopped aP May 26 22:23:39 volumio-sz sudo[914]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up May 26 22:23:39 volumio-sz sudo[914]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:39 volumio-sz sudo[914]: pam_unix(sudo:session): session closed for user root May 26 22:23:39 volumio-sz kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 26 22:23:39 volumio-sz sudo[918]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get May 26 22:23:39 volumio-sz sudo[918]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:39 volumio-sz sudo[918]: pam_unix(sudo:session): session closed for user root May 26 22:23:39 volumio-sz sudo[927]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up May 26 22:23:39 volumio-sz sudo[927]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:39 volumio-sz sudo[927]: pam_unix(sudo:session): session closed for user root May 26 22:23:39 volumio-sz sudo[930]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan May 26 22:23:39 volumio-sz sudo[930]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:40 volumio-sz sudo[930]: pam_unix(sudo:session): session closed for user root May 26 22:23:40 volumio-sz wireless.js[611]: SETTING APPROPRIATE REG DOMAIN: DE May 26 22:23:40 volumio-sz sudo[947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up May 26 22:23:40 volumio-sz sudo[947]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:40 volumio-sz sudo[947]: pam_unix(sudo:session): session closed for user root May 26 22:23:40 volumio-sz sudo[949]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set DE May 26 22:23:40 volumio-sz sudo[949]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:40 volumio-sz sudo[949]: pam_unix(sudo:session): session closed for user root May 26 22:23:40 volumio-sz wireless.js[611]: SUCCESSFULLY SET NEW REGDOMAIN: DE May 26 22:23:40 volumio-sz sudo[957]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 May 26 22:23:40 volumio-sz sudo[957]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:40 volumio-sz sudo[957]: pam_unix(sudo:session): session closed for user root May 26 22:23:40 volumio-sz sudo[959]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down May 26 22:23:40 volumio-sz sudo[959]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:41 volumio-sz systemd[1]: apt-daily.service: Succeeded. May 26 22:23:41 volumio-sz systemd[1]: Started Daily apt download activities. May 26 22:23:41 volumio-sz sudo[959]: pam_unix(sudo:session): session closed for user root May 26 22:23:41 volumio-sz avahi-daemon[613]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1. May 26 22:23:41 volumio-sz kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled May 26 22:23:41 volumio-sz avahi-daemon[613]: New relevant interface wlan0.IPv4 for mDNS. May 26 22:23:41 volumio-sz avahi-daemon[613]: Registering new address record for 192.168.211.1 on wlan0.IPv4. May 26 22:23:41 volumio-sz systemd[1]: Starting Daily apt upgrade and clean activities... May 26 22:23:41 volumio-sz systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... May 26 22:23:41 volumio-sz systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... May 26 22:23:41 volumio-sz dnsmasq[996]: dnsmasq: syntax check OK. May 26 22:23:41 volumio-sz hostapd[997]: Configuration file: /etc/hostapd/hostapd.conf May 26 22:23:41 volumio-sz hostapd[997]: wlan0: Could not connect to kernel driver May 26 22:23:41 volumio-sz hostapd[997]: Using interface wlan0 with hwaddr b8:27:eb:ab:1f:87 and ssid "Volumio-6B948" May 26 22:23:41 volumio-sz dnsmasq[1006]: started, version 2.80 cachesize 150 May 26 22:23:41 volumio-sz dnsmasq[1006]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile May 26 22:23:41 volumio-sz dnsmasq-dhcp[1006]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d May 26 22:23:41 volumio-sz dnsmasq[1006]: reading /etc/resolv.conf May 26 22:23:41 volumio-sz dnsmasq[1006]: using nameserver 192.168.20.2#53 May 26 22:23:41 volumio-sz dnsmasq[1006]: using nameserver 208.67.222.222#53 May 26 22:23:41 volumio-sz dnsmasq[1006]: using nameserver 208.67.220.220#53 May 26 22:23:41 volumio-sz dnsmasq[1006]: read /etc/hosts - 1 addresses May 26 22:23:41 volumio-sz systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. May 26 22:23:41 volumio-sz systemd[1]: Reached target Host and Network Name Lookups. May 26 22:23:41 volumio-sz hostapd[997]: wlan0: interface state UNINITIALIZED->ENABLED May 26 22:23:41 volumio-sz hostapd[997]: wlan0: AP-ENABLED May 26 22:23:41 volumio-sz systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. May 26 22:23:41 volumio-sz iwconfig[1026]: Error for wireless request "Set Power Management" (8B2C) : May 26 22:23:41 volumio-sz iwconfig[1026]: SET failed on device wlan0 ; Invalid argument. May 26 22:23:41 volumio-sz systemd[1]: wireless.service: Succeeded. May 26 22:23:41 volumio-sz systemd[1]: Started Wireless Services. May 26 22:23:41 volumio-sz systemd[1]: Started Volumio Backend Module. May 26 22:23:41 volumio-sz systemd[1]: Started Volumio Cpu Tweaker. May 26 22:23:41 volumio-sz volumio-cpu-tweak[1028]: Setting RT Priority for mpd May 26 22:23:41 volumio-sz volumio-cpu-tweak[1028]: pid 35's current scheduling policy: SCHED_OTHER May 26 22:23:41 volumio-sz volumio-cpu-tweak[1028]: pid 35's current scheduling priority: 0 May 26 22:23:41 volumio-sz volumio-cpu-tweak[1028]: Setting MPD Affinity May 26 22:23:41 volumio-sz volumio-cpu-tweak[1028]: pid 3's current affinity mask: f May 26 22:23:42 volumio-sz volumio-cpu-tweak[1028]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input May 26 22:23:42 volumio-sz volumio-cpu-tweak[1028]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance May 26 22:23:42 volumio-sz systemd[1]: volumio_cpu_tweak.service: Succeeded. May 26 22:23:42 volumio-sz nmbd[750]: [2025/05/26 22:23:42.198713, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 22:23:42 volumio-sz systemd[1]: Started Samba NMB Daemon. May 26 22:23:42 volumio-sz nmbd[750]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 26 22:23:42 volumio-sz systemd[1]: Starting Samba Winbind Daemon... May 26 22:23:42 volumio-sz systemd[1]: apt-daily-upgrade.service: Succeeded. May 26 22:23:42 volumio-sz systemd[1]: Started Daily apt upgrade and clean activities. May 26 22:23:42 volumio-sz ntpd[786]: Listen normally on 3 eth0 192.168.30.31:123 May 26 22:23:42 volumio-sz ntpd[786]: Listen normally on 4 wlan0 192.168.211.1:123 May 26 22:23:42 volumio-sz ntpd[786]: new interface(s) found: waking up resolver May 26 22:23:43 volumio-sz winbindd[1066]: [2025/05/26 22:23:43.085564, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 26 22:23:43 volumio-sz winbindd[1066]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 26 22:23:43 volumio-sz winbindd[1066]: [2025/05/26 22:23:43.165750, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 22:23:43 volumio-sz systemd[1]: Started Samba Winbind Daemon. May 26 22:23:43 volumio-sz winbindd[1066]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 26 22:23:43 volumio-sz mpd[833]: May 26 22:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 26 22:23:43 volumio-sz systemd[1]: Starting Samba SMB Daemon... May 26 22:23:43 volumio-sz systemd[1]: Started Music Player Daemon. May 26 22:23:43 volumio-sz mpd_monitor.sh[616]: MPD restarted due to no mpc output. May 26 22:23:44 volumio-sz smbd[1081]: [2025/05/26 22:23:44.013661, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 26 22:23:44 volumio-sz systemd[1]: Started Samba SMB Daemon. May 26 22:23:44 volumio-sz smbd[1081]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 26 22:23:44 volumio-sz systemd[1]: Reached target Multi-User System. May 26 22:23:44 volumio-sz systemd[1]: Reached target Graphical Interface. May 26 22:23:44 volumio-sz systemd[1]: Starting Update UTMP about System Runlevel Changes... May 26 22:23:44 volumio-sz systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 26 22:23:44 volumio-sz systemd[1]: Started Update UTMP about System Runlevel Changes. May 26 22:23:44 volumio-sz systemd[1]: Startup finished in 15.271s (kernel) + 22.209s (userspace) = 37.480s. May 26 22:23:45 volumio-sz volumio-remote-updater[604]: [2025-05-26 22:23:45] [connect] Successful connection May 26 22:23:45 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:45 volumio-sz volumio[1027]: info: ----- Volumio3 ---- May 26 22:23:45 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:45 volumio-sz volumio[1027]: info: ----- System startup ---- May 26 22:23:45 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:47 volumio-sz volumio[1027]: info: MYVOLUMIO Environment detected May 26 22:23:47 volumio-sz volumio[1027]: info: Plugin folders cleanup May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning into folder /volumio/app/plugins/ May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category audio_interface May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category miscellanea May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category music_service May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category plugins.json May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category system_controller May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category user_interface May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning into folder /data/plugins/ May 26 22:23:47 volumio-sz volumio[1027]: info: Scanning category music_service May 26 22:23:47 volumio-sz volumio[1027]: info: Plugin folders cleanup completed May 26 22:23:47 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:47 volumio-sz volumio[1027]: info: ----- Core plugins startup ---- May 26 22:23:47 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:47 volumio-sz volumio[1027]: info: Loading plugins from folder /volumio/app/plugins/ May 26 22:23:47 volumio-sz volumio[1027]: info: Adding plugin upnp to MyMusic Plugins May 26 22:23:47 volumio-sz volumio[1027]: info: Adding plugin airplay_emulation to MyMusic Plugins May 26 22:23:47 volumio-sz volumio[1027]: info: Adding plugin upnp_browser to MyMusic Plugins May 26 22:23:47 volumio-sz volumio[1027]: info: Loading plugins from folder /data/plugins/ May 26 22:23:47 volumio-sz volumio[1027]: info: Loading plugin "system"... May 26 22:23:47 volumio-sz volumio[1027]: info: Loading plugin "appearance"... May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "network"... May 26 22:23:49 volumio-sz volumio[1027]: info: Refreshing Cached IP Addresses May 26 22:23:49 volumio-sz sudo[1107]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 26 22:23:49 volumio-sz sudo[1107]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:49 volumio-sz sudo[1107]: pam_unix(sudo:session): session closed for user root May 26 22:23:49 volumio-sz sudo[1109]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 22:23:49 volumio-sz sudo[1109]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:49 volumio-sz sudo[1109]: pam_unix(sudo:session): session closed for user root May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "services"... May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "alsa_controller"... May 26 22:23:49 volumio-sz sudo[1118]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan May 26 22:23:49 volumio-sz sudo[1118]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:49 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "wizard"... May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "networkfs"... May 26 22:23:49 volumio-sz volumio[1027]: info: Starting Udev Watcher for removable devices May 26 22:23:49 volumio-sz sudo[1135]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=mediaplayer,password=k3UjjBaHeAk3O823zPr1JXDFEnSanW,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //oafs01.in-oarp.net/Media /mnt/NAS/OAFS01_Media May 26 22:23:49 volumio-sz sudo[1135]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:49 volumio-sz volumio[1027]: info: Ignoring mount for partition: boot May 26 22:23:49 volumio-sz volumio[1027]: info: Ignoring mount for partition: volumio May 26 22:23:49 volumio-sz volumio[1027]: info: Ignoring mount for partition: volumio_data May 26 22:23:49 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "volumio_command_line_client"... May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "upnp"... May 26 22:23:49 volumio-sz volumio[1027]: info: [1748291029782] Starting Upmpd Daemon May 26 22:23:49 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "my_music"... May 26 22:23:49 volumio-sz volumio[1027]: info: Loading plugin "mpd"... May 26 22:23:49 volumio-sz kernel: Key type cifs.spnego registered May 26 22:23:49 volumio-sz kernel: Key type cifs.idmap registered May 26 22:23:49 volumio-sz 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 26 22:23:49 volumio-sz kernel: CIFS: Attempting to mount //oafs01.in-oarp.net/Media May 26 22:23:50 volumio-sz kernel: cryptd: max_cpu_qlen set to 1000 May 26 22:23:50 volumio-sz sudo[1135]: pam_unix(sudo:session): session closed for user root May 26 22:23:50 volumio-sz sudo[1118]: pam_unix(sudo:session): session closed for user root May 26 22:23:50 volumio-sz volumio[1027]: info: Loading plugin "upnp_browser"... May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "alarm-clock"... May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "airplay_emulation"... May 26 22:23:51 volumio-sz volumio[1027]: info: Starting Shairport Sync May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "last_100"... May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "webradio"... May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "i2s_dacs"... May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "volumiodiscovery"... May 26 22:23:51 volumio-sz volumio[1027]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 26 22:23:51 volumio-sz volumio[1027]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:23:51 volumio-sz volumio[1027]: *** WARNING *** For more information see May 26 22:23:51 volumio-sz volumio[1027]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 26 22:23:51 volumio-sz volumio[1027]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:23:51 volumio-sz node[1027]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. May 26 22:23:51 volumio-sz volumio[1027]: *** WARNING *** For more information see May 26 22:23:51 volumio-sz node[1027]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:23:51 volumio-sz node[1027]: *** WARNING *** For more information see May 26 22:23:51 volumio-sz node[1027]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. May 26 22:23:51 volumio-sz node[1027]: *** WARNING *** Please fix your application to use the native API of Avahi! May 26 22:23:51 volumio-sz node[1027]: *** WARNING *** For more information see May 26 22:23:51 volumio-sz volumio[1027]: info: Applying required configuration parameters for plugin volumiodiscovery May 26 22:23:51 volumio-sz volumio[1027]: info: Discovery: Started advertising with name: Volumio-SZ May 26 22:23:51 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback May 26 22:23:51 volumio-sz volumio[1027]: info: Loading plugin "spop"... May 26 22:23:53 volumio-sz volumio[1027]: info: Loading plugin "outputs"... May 26 22:23:53 volumio-sz volumio[1027]: info: Loading plugin "albumart"... May 26 22:23:54 volumio-sz volumio[1027]: info: Plugin example_plugin is not enabled May 26 22:23:54 volumio-sz volumio[1027]: info: Loading plugin "inputs"... May 26 22:23:54 volumio-sz volumio[1027]: info: Loading plugin "updater_comm"... May 26 22:23:54 volumio-sz volumio[1027]: info: Plugin mpdemulation is not enabled May 26 22:23:54 volumio-sz volumio[1027]: info: Loading plugin "rest_api"... May 26 22:23:54 volumio-sz volumio[1027]: info: Loading plugin "websocket"... May 26 22:23:54 volumio-sz volumio[1027]: info: Starting Socket.io Server version 2.3.0 May 26 22:23:54 volumio-sz volumio[1027]: info: Loading i18n strings for locale de May 26 22:23:54 volumio-sz volumio[1027]: Updating browse sources language May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:23:54 volumio-sz volumio[1027]: Forking 3 albumart workers May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::initPlayerControls May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 22:23:54 volumio-sz volumio[1027]: Express server listening on port 3000 May 26 22:23:54 volumio-sz volumio[1027]: [Metrics] WebUI: 9s 966.36ms May 26 22:23:54 volumio-sz volumio[1027]: info: CoreStateMachine::resetVolumioState May 26 22:23:54 volumio-sz volumio[1027]: info: CoreStateMachine::getcurrentVolume May 26 22:23:54 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioRetrievevolume May 26 22:23:54 volumio-sz volumio[1027]: info: Volumio Network Manager: Network status updated: 1 May 26 22:23:55 volumio-sz volumio[1027]: verbose: New Socket.io Connection to 192.168.30.31:3000 from 192.168.30.32 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 May 26 22:23:55 volumio-sz volumio[1027]: verbose: New Socket.io Connection to 192.168.30.31:3000 from 192.168.30.32 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 May 26 22:23:55 volumio-sz volumio[1027]: info: Reloading queue from file May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:55 volumio-sz volumio[1027]: info: Setting Device type: Raspberry PI May 26 22:23:55 volumio-sz volumio[1027]: info: CoreStateMachine::setRepeat true single undefined May 26 22:23:55 volumio-sz volumio[1027]: info: CoreStateMachine::pushState May 26 22:23:55 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioPushState May 26 22:23:55 volumio-sz volumio[1027]: info: CoreStateMachine::setRandom null May 26 22:23:55 volumio-sz volumio[1027]: info: CoreStateMachine::pushState May 26 22:23:55 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioPushState May 26 22:23:55 volumio-sz volumio[1027]: info: Completed loading Core Plugins May 26 22:23:55 volumio-sz volumio[1027]: info: Preparing to generate the ALSA configuration file May 26 22:23:55 volumio-sz volumio[1027]: info: VolumeController:: Volume=93 Mute =false May 26 22:23:55 volumio-sz volumio[1027]: info: CoreStateMachine::pushState May 26 22:23:55 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:55 volumio-sz volumio[1027]: Starting albumart workers May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioPushState May 26 22:23:55 volumio-sz volumio[1027]: info: CoreStateMachine::updateTrackBlock May 26 22:23:55 volumio-sz volumio[1027]: info: CorePlayQueue::getTrackBlock May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioRetrievevolume May 26 22:23:55 volumio-sz volumio[1027]: Starting albumart workers May 26 22:23:55 volumio-sz volumio[1027]: Starting albumart workers May 26 22:23:55 volumio-sz volumio[1027]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf May 26 22:23:55 volumio-sz volumio[1027]: info: Reading ALSA contributions from plugins. May 26 22:23:55 volumio-sz volumio[1027]: info: Asound.conf file unchanged, so no further update is needed May 26 22:23:55 volumio-sz volumio[1027]: info: Output device has changed, restarting MPD May 26 22:23:55 volumio-sz volumio[1027]: info: Output device has changed, restarting Shairport Sync May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:55 volumio-sz sudo[1220]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 26 22:23:55 volumio-sz sudo[1220]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:55 volumio-sz sudo[1220]: pam_unix(sudo:session): session closed for user root May 26 22:23:55 volumio-sz sudo[1222]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 26 22:23:55 volumio-sz sudo[1222]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:55 volumio-sz volumio[1027]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 26 22:23:55 volumio-sz volumio[1027]: info: ___________ START PLUGINS ___________ May 26 22:23:55 volumio-sz volumio[1027]: info: ControllerMpd::onStart: Initializing MPD May 26 22:23:55 volumio-sz volumio[1027]: info: Creating MPD Configuration file May 26 22:23:55 volumio-sz systemd[1]: Stopping Music Player Daemon... May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 26 22:23:55 volumio-sz sudo[1229]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:23:55 volumio-sz sudo[1229]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:55 volumio-sz sudo[1229]: pam_unix(sudo:session): session closed for user root May 26 22:23:55 volumio-sz volumio[1027]: info: [1748291035803] CoreMusicLibrary::Adding element Medienserver May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:23:55 volumio-sz sudo[1231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 26 22:23:55 volumio-sz sudo[1231]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:55 volumio-sz volumio[1027]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:55 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:23:56 volumio-sz volumio[1027]: info: [1748291036058] CoreMusicLibrary::Adding element Last_100 May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:23:56 volumio-sz volumio[1027]: info: [1748291036063] CoreMusicLibrary::Adding element Webradio May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 22:23:56 volumio-sz volumio[1027]: info: Initializing BBC Radios May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:56 volumio-sz systemd[1]: mpd.service: Succeeded. May 26 22:23:56 volumio-sz systemd[1]: Stopped Music Player Daemon. May 26 22:23:56 volumio-sz volumio[1027]: info: Creating Spotify config file May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz systemd[1]: Starting Music Player Daemon... May 26 22:23:56 volumio-sz volumio[1027]: info: Volumio Calling Home May 26 22:23:56 volumio-sz sudo[1266]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 26 22:23:56 volumio-sz sudo[1266]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:56 volumio-sz sudo[1266]: pam_unix(sudo:session): session closed for user root May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: adding c735bc3b-08ea-4896-8b81-283b0e33fd13 May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: Found device Volumio-SZ May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:23:56 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: this is already registered, c735bc3b-08ea-4896-8b81-283b0e33fd13 May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: Found device Volumio-SZ May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:23:56 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: adding 7d84ad1e-6014-48bc-9d9f-f08a70f63956 May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: Found device Volumio-WZ May 26 22:23:56 volumio-sz volumio[1027]: info: Discovery: Connecting to remote: 192.168.211.1 May 26 22:23:56 volumio-sz systemd[1]: systemd-fsckd.service: Succeeded. May 26 22:23:56 volumio-sz volumio[1027]: info: MPD Permissions set May 26 22:23:56 volumio-sz volumio[1027]: info: MPD Permissions set May 26 22:23:56 volumio-sz volumio[1027]: info: VolumeController:: Volume=93 Mute =false May 26 22:23:56 volumio-sz volumio[1027]: info: CoreStateMachine::pushState May 26 22:23:56 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioPushState May 26 22:23:56 volumio-sz volumio[1027]: info: Volumio called home May 26 22:23:56 volumio-sz volumio[1027]: info: Spotify config file written May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:23:56 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:56 volumio-sz sudo[1281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 26 22:23:56 volumio-sz sudo[1281]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:56 volumio-sz volumio[1027]: verbose: New Socket.io Connection to 192.168.211.1:3000 from 192.168.211.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 May 26 22:23:56 volumio-sz volumio[1027]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:56 volumio-sz systemd[1]: Started go-librespot Daemon. May 26 22:23:56 volumio-sz go-librespot[1283]: Librespot-go daemon starting... May 26 22:23:56 volumio-sz sudo[1281]: pam_unix(sudo:session): session closed for user root May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 26 22:23:56 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 26 22:23:57 volumio-sz volumio[1027]: info: Discovery: Connected to remote: 192.168.211.1 May 26 22:23:57 volumio-sz volumio[1027]: info: Listing playlists May 26 22:23:57 volumio-sz volumio[1027]: info: Listing playlists May 26 22:23:57 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket May 26 22:23:57 volumio-sz volumio[1027]: info: Starting Shairport Sync May 26 22:23:57 volumio-sz volumio[1027]: info: Starting Shairport Sync May 26 22:23:57 volumio-sz volumio[1027]: info: Starting Shairport Sync May 26 22:23:57 volumio-sz sudo[1294]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 26 22:23:57 volumio-sz sudo[1294]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:57 volumio-sz sudo[1296]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 26 22:23:57 volumio-sz sudo[1296]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:57 volumio-sz sudo[1299]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 26 22:23:57 volumio-sz sudo[1299]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:57 volumio-sz systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 26 22:23:57 volumio-sz systemd[1]: shairport-sync.service: Succeeded. May 26 22:23:57 volumio-sz systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 26 22:23:57 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:23:57 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:57 volumio-sz systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 26 22:23:57 volumio-sz sudo[1294]: pam_unix(sudo:session): session closed for user root May 26 22:23:57 volumio-sz sudo[1296]: pam_unix(sudo:session): session closed for user root May 26 22:23:57 volumio-sz sudo[1299]: pam_unix(sudo:session): session closed for user root May 26 22:23:57 volumio-sz volumio[1027]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 26 22:23:57 volumio-sz volumio[1027]: SPOTIFY: BQBFJ-iRrk75DKKGOJL-FyUpTE3DgKcqvGzGLhhDM2Mi9lH02KuBnmyr0XR3E0xH8o3HayI-ienPifaLXbXBzOrLPuVFEZCk02p-FujNCeKakpKBbAKfx-gCbmG3ZVuU8OVsBUi0BV_IIdfQez4JqlAZ4oJgJj8PwizSuRla3y465L430vSDVIWZHrZrfe6xskfMu87FlLWeB5_dymfpKpx4EgjK-GOaKra1UUlE7RsL1HyjDfBZjrjAoRwl5w_5OPh-RpnVcQ-KEe3fCperpPtmqWohpgMRh95pAuUuT_Vl62Q May 26 22:23:57 volumio-sz volumio[1027]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 26 22:23:57 volumio-sz volumio[1027]: info: New Spotify access token = BQBFJ-iRrk75DKKGOJL-FyUpTE3DgKcqvGzGLhhDM2Mi9lH02KuBnmyr0XR3E0xH8o3HayI-ienPifaLXbXBzOrLPuVFEZCk02p-FujNCeKakpKBbAKfx-gCbmG3ZVuU8OVsBUi0BV_IIdfQez4JqlAZ4oJgJj8PwizSuRla3y465L430vSDVIWZHrZrfe6xskfMu87FlLWeB5_dymfpKpx4EgjK-GOaKra1UUlE7RsL1HyjDfBZjrjAoRwl5w_5OPh-RpnVcQ-KEe3fCperpPtmqWohpgMRh95pAuUuT_Vl62Q May 26 22:23:57 volumio-sz volumio[1027]: info: Spotify credentials grant success - running version from March 24, 2019 May 26 22:23:57 volumio-sz volumio[1027]: info: Shairport-Sync Started May 26 22:23:57 volumio-sz volumio[1027]: Error adding Membership: Error: addMembership EINVAL May 26 22:23:57 volumio-sz volumio[1027]: info: Shairport-Sync Started May 26 22:23:57 volumio-sz volumio[1027]: info: Shairport-Sync Started May 26 22:23:57 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:23:57 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:57 volumio-sz volumio[1027]: SPOTIFY: User informations: {"country":"DE","display_name":"Oliver","email":"oarp@gmx.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/toyefi2t3k7kcmfqg2cgjckf1"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/toyefi2t3k7kcmfqg2cgjckf1","id":"toyefi2t3k7kcmfqg2cgjckf1","images":[],"product":"premium","type":"user","uri":"spotify:user:toyefi2t3k7kcmfqg2cgjckf1"} May 26 22:23:57 volumio-sz volumio[1027]: info: Spotify Successfully logged in May 26 22:23:57 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 26 22:23:57 volumio-sz volumio[1027]: info: [1748291037598] CoreMusicLibrary::Adding element Spotify May 26 22:23:57 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 26 22:23:57 volumio-sz volumio[1027]: Cannot find translation for source Spotify May 26 22:23:58 volumio-sz mpd[1278]: May 26 22:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 26 22:23:58 volumio-sz systemd[1]: Started Music Player Daemon. May 26 22:23:58 volumio-sz sudo[1222]: pam_unix(sudo:session): session closed for user root May 26 22:23:58 volumio-sz sudo[1231]: pam_unix(sudo:session): session closed for user root May 26 22:23:58 volumio-sz volumio[1027]: info: Completed starting Core Plugins May 26 22:23:58 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:58 volumio-sz volumio[1027]: info: ----- MyVolumio plugins startup ---- May 26 22:23:58 volumio-sz volumio[1027]: info: ------------------------------------------- May 26 22:23:58 volumio-sz volumio[1027]: info: [MyVolumio PluginManager] Fetching plans data.... May 26 22:23:58 volumio-sz volumio[1027]: error: MPD error: The expression evaluated to a falsy value: May 26 22:23:58 volumio-sz volumio[1027]: assert.ok(self.idling) May 26 22:23:58 volumio-sz volumio[1027]: error: The expression evaluated to a falsy value: May 26 22:23:58 volumio-sz volumio[1027]: assert.ok(self.idling) May 26 22:23:58 volumio-sz volumio[1027]: info: MPD running with PID1278 May 26 22:23:58 volumio-sz volumio[1027]: ,establishing connection May 26 22:23:58 volumio-sz volumio[1027]: error: MPD error: The expression evaluated to a falsy value: May 26 22:23:58 volumio-sz volumio[1027]: assert.ok(self.idling) May 26 22:23:58 volumio-sz volumio[1027]: error: The expression evaluated to a falsy value: May 26 22:23:58 volumio-sz volumio[1027]: assert.ok(self.idling) May 26 22:23:58 volumio-sz volumio[1027]: error: updateQueue error: null May 26 22:23:58 volumio-sz volumio[1027]: verbose: New Socket.io Connection to 192.168.30.31:3000 from 192.168.30.32 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 26 22:23:58 volumio-sz volumio[1027]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , initSocket May 26 22:23:58 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:23:58 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:23:59 volumio-sz go-librespot[1283]: time="2025-05-26T22:23:59+02:00" level=info msg="generated new device id: 0558139d33d3f5729e61cf2505af2ac4fad4a4ba" May 26 22:23:59 volumio-sz go-librespot[1283]: time="2025-05-26T22:23:59+02:00" level=debug msg="stored credentials found for toyefi2t3k7kcmfqg2cgjckf1" May 26 22:23:59 volumio-sz go-librespot[1283]: time="2025-05-26T22:23:59+02:00" level=debug msg="obtained new client token: AAD4bVeIQR2uN2HEqZFfOkTjh+yP0M3JyqwbKdOQwnO2ChSWNZm4wXsNENgxn3j+KfHFZVsR8bWsdsG4rCcY5ih5HwhXTOpOF3vSvIIs3l3iEIJ7lCzOMV3MzN4dtHhupr3SFFaNH3QVxd2rpKnR0xAV8T1YRiuojaLZZth8efKOAFB5pkelQTjEIrhyVjSQAagIACa+I/mmZdTaQzz1Vbh4TOg1CLokwbaypp9kbQ44ZGcVnodKFOQPw+VQU+M=" May 26 22:23:59 volumio-sz go-librespot[1283]: time="2025-05-26T22:23:59+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 26 22:23:59 volumio-sz sudo[1331]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 26 22:23:59 volumio-sz sudo[1331]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:59 volumio-sz sudo[1331]: pam_unix(sudo:session): session closed for user root May 26 22:23:59 volumio-sz sudo[1333]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 26 22:23:59 volumio-sz sudo[1333]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:59 volumio-sz sudo[1333]: pam_unix(sudo:session): session closed for user root May 26 22:23:59 volumio-sz go-librespot[1283]: time="2025-05-26T22:23:59+02:00" level=debug msg="completed keyexchange" May 26 22:23:59 volumio-sz sudo[1337]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 26 22:23:59 volumio-sz sudo[1337]: pam_unix(sudo:session): session opened for user root by (uid=0) May 26 22:23:59 volumio-sz systemd[1]: Started UPnP Renderer front-end to MPD. May 26 22:23:59 volumio-sz sudo[1337]: pam_unix(sudo:session): session closed for user root May 26 22:23:59 volumio-sz volumio[1027]: info: Upmpdcli Daemon Started May 26 22:24:00 volumio-sz volumio[1027]: info: go-librespot daemon successfully initialized May 26 22:24:00 volumio-sz volumio[1339]: Generating RSA private key, 4096 bit long modulus (2 primes) May 26 22:24:00 volumio-sz volumio-remote-updater[604]: [2025-05-26 22:24:00] [connect] Successful connection May 26 22:24:00 volumio-sz volumio-remote-updater[604]: [2025-05-26 22:24:00] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1748291040 101 May 26 22:24:00 volumio-sz volumio[1027]: 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: 6 May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="completed challenge" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="authenticated as toyefi2t3k7kcmfqg2cgjckf1" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="authenticated as toyefi2t3k7kcmfqg2cgjckf1" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="dealer connection opened" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="received connection id: NGM0NmE0ZWYtOTczZC00ZjVkLWJmYmYtZDFlN2U1MWU2ZjE2K2RlYWxlcit0Y3A6Ly8wYWNhNTg1Yy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMjI3RTU0M0YyRTJEN0Y0QkIyMTQ2OUFCRTExMTI4MkQwMzZFN0QxQUE3OEMyMTk1QzJENTg2NzQyMjdFOUU5OQ==" May 26 22:24:00 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:00+02:00" level=debug msg="put connect state because NEW_DEVICE" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="handling transfer player command from c71a5a2ac8437d1e330221dcad61d8ec02eb17b3" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=trace msg="fetched new page 0 with 20 items (list: 20)" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="loading track spotify:track:49ht4DycqeC1qBak1HKbrN (paused: false, position: 149502ms)" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1128" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=trace msg="emitting websocket event: will_play" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:49ht4DycqeC1qBak1HKbrN" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="requested aes key for file ed264d162b5906a4e48a2c7d95d9c618a4951692, gid: 49ht4DycqeC1qBak1HKbrN" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="fetched first chunk of 46, total size is 23737616 bytes" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="fetched chunk 1/45, size: 524288" May 26 22:24:02 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:02+02:00" level=debug msg="fetched chunk 2/45, size: 524288" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="fetched chunk 3/45, size: 524288" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="fetched chunk 17/45, size: 524288" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=trace msg="seek to 149502ms (diff: 62ms, samples: 6593038, bytes: 9065299)" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="fetched chunk 20/45, size: 524288" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="fetched chunk 18/45, size: 524288" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="fetched chunk 19/45, size: 524288" May 26 22:24:03 volumio-sz volumio[1027]: info: Initializing connection to go-librespot Websocket May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="new websocket client" May 26 22:24:03 volumio-sz volumio[1027]: info: Connection to go-librespot Websocket established May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=info msg="loaded track \"Freedom from Oneself\" (uri: spotify:track:49ht4DycqeC1qBak1HKbrN, paused: false, position: 149502ms, duration: 394933ms)" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=trace msg="emitting websocket event: metadata" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=trace msg="emitting websocket event: active" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="sending successful reply for delaer request" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 26 22:24:03 volumio-sz volumio[1027]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:49ht4DycqeC1qBak1HKbrN","name":"Freedom from Oneself","artist_names":["Parijat"],"album_name":"Offerings","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02c2497073ab32275e4455e167","position":149502,"duration":394933,"release_date":"year:2010 month:4 day:14","track_number":6,"disc_number":1}} May 26 22:24:03 volumio-sz volumio[1027]: SPOTIFY: received: {"type":"active","data":null} May 26 22:24:03 volumio-sz volumio[1027]: info: Aligning Spotify Volume to Volumio Volume May 26 22:24:03 volumio-sz volumio[1027]: info: CoreCommandRouter::volumioGetState May 26 22:24:03 volumio-sz volumio[1027]: info: CorePlayQueue::getTrack 0 May 26 22:24:03 volumio-sz volumio[1027]: info: Setting Spotify Volume from Volumio: 93 May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 26 22:24:03 volumio-sz go-librespot[1283]: time="2025-05-26T22:24:03+02:00" level=trace msg="emitting websocket event: playing" May 26 22:24:03 volumio-sz volumio[1027]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 26 22:24:03 volumio-sz volumio[1027]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:49ht4DycqeC1qBak1HKbrN","play_origin":"playlist"}} May 26 22:24:03 volumio-sz volumio[1027]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 22:24:03 volumio-sz volumio[1027]: TypeError: Cannot read property 'service' of undefined May 26 22:24:03 volumio-sz volumio[1027]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) May 26 22:24:03 volumio-sz volumio[1027]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) May 26 22:24:03 volumio-sz volumio[1027]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) May 26 22:24:03 volumio-sz volumio[1027]: at WebSocket.emit (events.js:315:20) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1209:20) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver.emit (events.js:315:20) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:594:14) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 26 22:24:03 volumio-sz volumio[1027]: at writeOrBuffer (internal/streams/writable.js:358:12) May 26 22:24:03 volumio-sz volumio[1027]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 26 22:24:03 volumio-sz volumio[1027]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1303:35) May 26 22:24:03 volumio-sz volumio[1027]: at Socket.emit (events.js:315:20) May 26 22:24:03 volumio-sz volumio[1027]: at addChunk (internal/streams/readable.js:309:12) May 26 22:24:03 volumio-sz volumio[1027]: at readableAddChunk (internal/streams/readable.js:284:9) May 26 22:24:03 volumio-sz volumio[1027]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 26 22:24:04 volumio-sz sudo[1369]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-26 22:23 May 26 22:24:04 volumio-sz sudo[1369]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"