-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Tue 2025-02-25 14:22:40 CET. -- Feb 25 14:21:00 volumio systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Feb 25 14:21:00 volumio kernel: Bluetooth: hci0: BCM: features 0x2f Feb 25 14:21:00 volumio kernel: Bluetooth: hci0: BCM43455 37.4MHz Raspberry Pi 3+ Feb 25 14:21:00 volumio kernel: Bluetooth: hci0: BCM4345C0 (003.001.025) build 0342 Feb 25 14:21:00 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled Feb 25 14:21:00 volumio systemd[1]: Started Update UTMP about System Boot/Shutdown. Feb 25 14:21:00 volumio systemd[1]: Reached target System Initialization. Feb 25 14:21:00 volumio systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Feb 25 14:21:00 volumio systemd[1]: Started Daily apt download activities. Feb 25 14:21:00 volumio kernel: 8021q: 802.1Q VLAN Support v1.8 Feb 25 14:21:00 volumio systemd[1]: Listening on D-Bus System Message Bus Socket. Feb 25 14:21:00 volumio systemd[1]: Listening on triggerhappy.socket. Feb 25 14:21:00 volumio systemd[1]: Reached target Sockets. Feb 25 14:21:00 volumio systemd[1]: Started Daily Cleanup of Temporary Directories. Feb 25 14:21:00 volumio systemd[1]: Started Daily apt upgrade and clean activities. Feb 25 14:21:00 volumio systemd[1]: Reached target Timers. Feb 25 14:21:00 volumio systemd[1]: Reached target Basic System. Feb 25 14:21:00 volumio kernel: bcmgenet fd580000.ethernet: configuring instance for external RGMII (RX delay) Feb 25 14:21:00 volumio kernel: bcmgenet fd580000.ethernet eth0: Link is Down Feb 25 14:21:00 volumio dhcpcd[584]: eth0: waiting for carrier Feb 25 14:21:00 volumio sh[547]: eth0: waiting for carrier Feb 25 14:21:00 volumio systemd[1]: Starting triggerhappy global hotkey daemon... Feb 25 14:21:00 volumio systemd[1]: Started D-Bus System Message Bus. Feb 25 14:21:00 volumio systemd[1]: Starting WPA supplicant... Feb 25 14:21:00 volumio systemd[1]: Starting Volumio Time Update Utility... Feb 25 14:21:00 volumio systemd[1]: Started MPD Monitor Service. Feb 25 14:21:00 volumio systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Feb 25 14:21:00 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Feb 25 14:21:00 volumio systemd[1]: Started Manage Sound Card State (restore and store). Feb 25 14:21:00 volumio systemd[1]: Started Volumio Iptables Module. Feb 25 14:21:00 volumio thd[605]: Unable to parse trigger line: Feb 25 14:21:00 volumio thd[605]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Feb 25 14:21:00 volumio thd[605]: Unable to parse trigger line: Feb 25 14:21:00 volumio thd[605]: Found socket passed from systemd Feb 25 14:21:00 volumio alsactl[625]: alsactl 1.1.8 daemon started Feb 25 14:21:00 volumio systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Feb 25 14:21:00 volumio systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Feb 25 14:21:00 volumio systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Feb 25 14:21:00 volumio systemd[1]: Starting Login Service... Feb 25 14:21:00 volumio systemd[1]: Started Volumio Log Rotation Service. Feb 25 14:21:00 volumio volumio-time-update[622]: volumio-time-update-util: Fetching time from Volumio... Feb 25 14:21:00 volumio systemd[1]: Starting Save/Restore Sound Card State... Feb 25 14:21:00 volumio systemd[1]: Starting Configure Bluetooth Modems connected by UART... Feb 25 14:21:00 volumio systemd[1]: Starting dhcpcd on all interfaces... Feb 25 14:21:00 volumio systemd[1]: Started volumio-remote-updater.service. Feb 25 14:21:00 volumio systemd[1]: Starting Wireless Services... Feb 25 14:21:00 volumio systemd[1]: Started RPC bind portmap service. Feb 25 14:21:00 volumio systemd[1]: Started triggerhappy global hotkey daemon. Feb 25 14:21:00 volumio systemd[1]: Reached target RPC Port Mapper. Feb 25 14:21:00 volumio systemd[1]: Reached target Remote File Systems (Pre). Feb 25 14:21:00 volumio systemd[1]: Reached target Remote File Systems. Feb 25 14:21:00 volumio systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Feb 25 14:21:00 volumio dhcpcd[637]: Not running dhcpcd because /etc/network/interfaces Feb 25 14:21:00 volumio dhcpcd[637]: defines some interfaces that will use a Feb 25 14:21:00 volumio dhcpcd[637]: DHCP client or static address Feb 25 14:21:00 volumio sh[550]: wlan0=wlan0 Feb 25 14:21:00 volumio systemd-logind[628]: New seat seat0. Feb 25 14:21:00 volumio avahi-daemon[627]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Feb 25 14:21:00 volumio avahi-daemon[627]: Successfully dropped root privileges. Feb 25 14:21:00 volumio avahi-daemon[627]: avahi-daemon 0.7 starting up. Feb 25 14:21:00 volumio mpd_monitor.sh[623]: MPD error: Cannot assign requested address Feb 25 14:21:00 volumio mpd_monitor.sh[623]: mpd: no process found Feb 25 14:21:00 volumio systemd[1]: Started Login Service. Feb 25 14:21:00 volumio wpa_supplicant[621]: Successfully initialized wpa_supplicant Feb 25 14:21:00 volumio systemd[1]: Started Save/Restore Sound Card State. Feb 25 14:21:00 volumio avahi-daemon[627]: Successfully called chroot(). Feb 25 14:21:00 volumio systemd[1]: hciuart.service: Succeeded. Feb 25 14:21:00 volumio avahi-daemon[627]: Successfully dropped remaining capabilities. Feb 25 14:21:00 volumio systemd[1]: Started Configure Bluetooth Modems connected by UART. Feb 25 14:21:00 volumio avahi-daemon[627]: No service file found in /etc/avahi/services. Feb 25 14:21:00 volumio systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Feb 25 14:21:00 volumio avahi-daemon[627]: Network interface enumeration completed. Feb 25 14:21:00 volumio systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Feb 25 14:21:00 volumio systemd[1]: Failed to start dhcpcd on all interfaces. Feb 25 14:21:00 volumio avahi-daemon[627]: Server startup complete. Host name is volumio.local. Local service cookie is 3217490656. Feb 25 14:21:00 volumio systemd[1]: Started WPA supplicant. Feb 25 14:21:00 volumio systemd[1]: Started Avahi mDNS/DNS-SD Stack. Feb 25 14:21:01 volumio volumio-remote-updater[638]: Error: No active session Feb 25 14:21:01 volumio volumio-remote-updater[638]: [2025-02-25 14:21:01] [info] asio async_connect error: system:111 (Connection refused) Feb 25 14:21:01 volumio volumio-remote-updater[638]: [2025-02-25 14:21:01] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Feb 25 14:21:01 volumio volumio-remote-updater[638]: [2025-02-25 14:21:01] [error] handle_connect error: Underlying Transport Error Feb 25 14:21:01 volumio systemd[1]: Listening on mpd.socket. Feb 25 14:21:01 volumio systemd[1]: Starting Raspberry Pi bluetooth helper... Feb 25 14:21:01 volumio systemd[1]: Reached target Sound Card. Feb 25 14:21:01 volumio volumio[624]: Could not open config: /tmp/upmpdcli.conf Feb 25 14:21:01 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Feb 25 14:21:01 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Feb 25 14:21:01 volumio bthelper[679]: Raspberry Pi BDADDR already set Feb 25 14:21:01 volumio volumio-time-update[622]: volumio-time-update-util: Date not found in response Feb 25 14:21:01 volumio volumio-time-update[622]: volumio-time-update-util: Retrying in 5 seconds... Feb 25 14:21:01 volumio systemd[1]: Started Raspberry Pi bluetooth helper. Feb 25 14:21:01 volumio haveged[586]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Feb 25 14:21:01 volumio haveged[586]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Feb 25 14:21:01 volumio haveged[586]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00103 Feb 25 14:21:01 volumio haveged[586]: haveged: fills: 0, generated: 0 Feb 25 14:21:01 volumio loadcpufreq[641]: Loading cpufreq kernel modules...done (none). Feb 25 14:21:01 volumio systemd[1]: Starting Bluetooth service... Feb 25 14:21:01 volumio systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Feb 25 14:21:01 volumio systemd[1]: Starting LSB: set CPUFreq kernel parameters... Feb 25 14:21:01 volumio systemd[1]: iptables.service: Succeeded. Feb 25 14:21:01 volumio cpufrequtils[716]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Feb 25 14:21:01 volumio systemd[1]: Started LSB: set CPUFreq kernel parameters. Feb 25 14:21:01 volumio bluetoothd[704]: Bluetooth daemon 5.50 Feb 25 14:21:01 volumio bluetoothd[704]: Unknown key AutoConnectTimeout for group General in /etc/bluetooth/main.conf Feb 25 14:21:01 volumio systemd[1]: Started Bluetooth service. Feb 25 14:21:01 volumio systemd[1]: Reached target Bluetooth. Feb 25 14:21:01 volumio bluetoothd[704]: Starting SDP server Feb 25 14:21:01 volumio bluetoothd[704]: Excluding (cli) sap Feb 25 14:21:01 volumio kernel: Bluetooth: BNEP (Ethernet Emulation) ver 1.3 Feb 25 14:21:01 volumio kernel: Bluetooth: BNEP filters: protocol multicast Feb 25 14:21:01 volumio kernel: Bluetooth: BNEP socket layer initialized Feb 25 14:21:01 volumio bluetoothd[704]: Bluetooth management interface 1.22 initialized Feb 25 14:21:01 volumio dbus-daemon[620]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.4' (uid=0 pid=704 comm="/usr/lib/bluetooth/bluetoothd --noplugin=sap ") Feb 25 14:21:01 volumio kernel: Bluetooth: MGMT ver 1.22 Feb 25 14:21:01 volumio bluetoothd[704]: Failed to set privacy: Rejected (0x0b) Feb 25 14:21:01 volumio systemd[1]: Starting Hostname Service... Feb 25 14:21:01 volumio dbus-daemon[620]: [system] Successfully activated service 'org.freedesktop.hostname1' Feb 25 14:21:01 volumio systemd[1]: Started Hostname Service. Feb 25 14:21:02 volumio wireless.js[639]: Cleaning previous... Feb 25 14:21:02 volumio sudo[745]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0 Feb 25 14:21:02 volumio sudo[745]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:02 volumio sudo[745]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:02 volumio sudo[747]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down Feb 25 14:21:02 volumio sudo[747]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:02 volumio systemd[1]: Started Helper to synchronize boot up for ifupdown. Feb 25 14:21:02 volumio systemd[1]: Starting Raise network interfaces... Feb 25 14:21:02 volumio sudo[747]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:02 volumio wireless.js[639]: Stopped aP Feb 25 14:21:02 volumio wireless.js[639]: Wireless Networking DISABLED, not starting wireless flow Feb 25 14:21:02 volumio systemd[1]: wireless.service: Succeeded. Feb 25 14:21:02 volumio systemd[1]: Started Wireless Services. Feb 25 14:21:02 volumio systemd[1]: Started Volumio Backend Module. Feb 25 14:21:02 volumio systemd[1]: Started Volumio Cpu Tweaker. Feb 25 14:21:02 volumio systemd[1]: Started Raise network interfaces. Feb 25 14:21:02 volumio systemd[1]: Reached target Network. Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: Setting RT Priority for mpd Feb 25 14:21:02 volumio systemd[1]: Starting Music Player Daemon... Feb 25 14:21:02 volumio systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Feb 25 14:21:02 volumio systemd[1]: Starting Permit User Sessions... Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: pid 35's current scheduling policy: SCHED_OTHER Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: pid 35's current scheduling priority: 0 Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: Setting MPD Affinity Feb 25 14:21:02 volumio systemd[1]: Starting Network Time Service... Feb 25 14:21:02 volumio systemd[1]: Reached target Network is Online. Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: pid 3's current affinity mask: f Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Feb 25 14:21:02 volumio volumio-cpu-tweak[800]: VOLUMIO CPU TWEAK: Setting CPU Governor: performance Feb 25 14:21:02 volumio systemd[1]: Starting Samba NMB Daemon... Feb 25 14:21:02 volumio systemd[1]: Starting LSB: Brings up/down network automatically... Feb 25 14:21:02 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:02 volumio systemd[1]: Starting /etc/rc.local Compatibility... Feb 25 14:21:02 volumio systemd[1]: Started Permit User Sessions. Feb 25 14:21:02 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Feb 25 14:21:02 volumio systemd[1]: Started /etc/rc.local Compatibility. Feb 25 14:21:03 volumio systemd[1]: Starting Hold until boot process finishes up... Feb 25 14:21:03 volumio sudo[823]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 25 14:21:03 volumio systemd[1]: Starting Terminate Plymouth Boot Screen... Feb 25 14:21:03 volumio sudo[823]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:03 volumio sudo[823]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Feb 25 14:21:03 volumio sudo[823]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:03 volumio systemd[1]: plymouth-quit-wait.service: Succeeded. Feb 25 14:21:03 volumio systemd[1]: Started Hold until boot process finishes up. Feb 25 14:21:03 volumio systemd[1]: plymouth-quit.service: Succeeded. Feb 25 14:21:03 volumio systemd[1]: Started Terminate Plymouth Boot Screen. Feb 25 14:21:03 volumio systemd[1]: Received SIGRTMIN+21 from PID 210 (n/a). Feb 25 14:21:03 volumio systemd[1]: Received SIGRTMIN+21 from PID 210 (n/a). Feb 25 14:21:03 volumio systemd[1]: Started Getty on tty1. Feb 25 14:21:03 volumio systemd[1]: Reached target Login Prompts. Feb 25 14:21:03 volumio ifplugd(eth0)[856]: ifplugd 0.28 initializing. Feb 25 14:21:03 volumio ifplugd(eth0)[856]: Using interface eth0/D8:3A:DD:97:E1:2C with driver (version: 6.6.62-v7l+) Feb 25 14:21:03 volumio ifplugd(eth0)[856]: Using detection mode: SIOCETHTOOL Feb 25 14:21:03 volumio ifplugd(eth0)[856]: Initialization complete, link beat not detected. Feb 25 14:21:03 volumio ntpd[828]: ntpd 4.2.8p12@1.3728-o (1): Starting Feb 25 14:21:03 volumio ntpd[828]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Feb 25 14:21:03 volumio systemd[1]: Started Network Time Service. Feb 25 14:21:03 volumio ntpd[860]: proto: precision = 0.796 usec (-20) Feb 25 14:21:03 volumio ntpd[860]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Feb 25 14:21:03 volumio ntpd[860]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Feb 25 14:21:03 volumio ntpd[860]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 60 days ago Feb 25 14:21:03 volumio ntpd[860]: Listen and drop on 0 v6wildcard [::]:123 Feb 25 14:21:03 volumio ntpd[860]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Feb 25 14:21:03 volumio ntpd[860]: Listen normally on 2 lo 127.0.0.1:123 Feb 25 14:21:03 volumio ntpd[860]: Listening on routing socket on fd #19 for interface updates Feb 25 14:21:03 volumio ntpd[860]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Feb 25 14:21:03 volumio ntpd[860]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Feb 25 14:21:03 volumio ifplugd[832]: Network Interface Plugging Daemon...start eth0...done. Feb 25 14:21:03 volumio systemd[1]: Started LSB: Brings up/down network automatically. Feb 25 14:21:03 volumio nmbd[837]: [2025/02/25 14:21:03.905758, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Feb 25 14:21:03 volumio nmbd[837]: started asyncdns process 862 Feb 25 14:21:03 volumio nmbd[837]: [2025/02/25 14:21:03.908024, 0] ../lib/util/become_daemon.c:149(daemon_status) Feb 25 14:21:03 volumio nmbd[837]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Feb 25 14:21:03 volumio nmbd[837]: [2025/02/25 14:21:03.908121, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Feb 25 14:21:03 volumio nmbd[837]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Feb 25 14:21:04 volumio ntpd[860]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Feb 25 14:21:04 volumio sh[547]: eth0: carrier acquired Feb 25 14:21:04 volumio dhcpcd[584]: eth0: carrier acquired Feb 25 14:21:04 volumio kernel: bcmgenet fd580000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx Feb 25 14:21:04 volumio sh[547]: DUID 00:01:00:01:2e:f2:a2:d8:d8:3a:dd:97:e1:2c Feb 25 14:21:04 volumio sh[547]: eth0: IAID dd:97:e1:2c Feb 25 14:21:04 volumio sh[547]: eth0: adding address fe80::da3a:ddff:fe97:e12c Feb 25 14:21:04 volumio sh[547]: ipv6_addaddr1: Permission denied Feb 25 14:21:04 volumio dhcpcd[584]: DUID 00:01:00:01:2e:f2:a2:d8:d8:3a:dd:97:e1:2c Feb 25 14:21:04 volumio dhcpcd[584]: eth0: IAID dd:97:e1:2c Feb 25 14:21:04 volumio dhcpcd[584]: eth0: adding address fe80::da3a:ddff:fe97:e12c Feb 25 14:21:04 volumio dhcpcd[584]: ipv6_addaddr1: Permission denied Feb 25 14:21:04 volumio sh[547]: eth0: soliciting an IPv6 router Feb 25 14:21:04 volumio dhcpcd[584]: eth0: soliciting an IPv6 router Feb 25 14:21:04 volumio systemd[1]: systemd-rfkill.service: Succeeded. Feb 25 14:21:04 volumio sh[547]: eth0: soliciting a DHCP lease Feb 25 14:21:04 volumio dhcpcd[584]: eth0: soliciting a DHCP lease Feb 25 14:21:05 volumio ntpd[860]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Feb 25 14:21:05 volumio ifplugd(eth0)[856]: Link beat detected. Feb 25 14:21:05 volumio ifplugd(eth0)[856]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Feb 25 14:21:05 volumio ifplugd(eth0)[856]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Feb 25 14:21:05 volumio mpd[846]: Feb 25 14:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 25 14:21:05 volumio systemd[1]: Started Music Player Daemon. Feb 25 14:21:05 volumio mpd_monitor.sh[623]: MPD restarted due to no mpc output. Feb 25 14:21:05 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:05 volumio volumio[796]: info: ----- Volumio3 ---- Feb 25 14:21:05 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:05 volumio volumio[796]: info: ----- System startup ---- Feb 25 14:21:05 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:05 volumio sh[547]: eth0: offered 192.168.9.177 from 192.168.9.1 Feb 25 14:21:05 volumio dhcpcd[584]: eth0: offered 192.168.9.177 from 192.168.9.1 Feb 25 14:21:05 volumio sh[547]: eth0: probing address 192.168.9.177/24 Feb 25 14:21:05 volumio dhcpcd[584]: eth0: probing address 192.168.9.177/24 Feb 25 14:21:06 volumio volumio-remote-updater[638]: [2025-02-25 14:21:06] [connect] Successful connection Feb 25 14:21:06 volumio volumio-time-update[622]: volumio-time-update-util: Fetching time from Volumio... Feb 25 14:21:06 volumio ntpd[860]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Feb 25 14:21:06 volumio volumio-time-update[622]: volumio-time-update-util: Date not found in response Feb 25 14:21:06 volumio volumio-time-update[622]: volumio-time-update-util: Retrying in 5 seconds... Feb 25 14:21:06 volumio bthelper[679]: Changing power off succeeded Feb 25 14:21:06 volumio bthelper[679]: [CHG] Controller D8:3A:DD:97:E1:31 Class: 0x0000041c Feb 25 14:21:06 volumio bthelper[679]: Changing power on succeeded Feb 25 14:21:06 volumio volumio[796]: info: MYVOLUMIO Environment detected Feb 25 14:21:06 volumio volumio[796]: info: Plugin folders cleanup Feb 25 14:21:06 volumio volumio[796]: info: Scanning into folder /volumio/app/plugins/ Feb 25 14:21:06 volumio volumio[796]: info: Scanning category audio_interface Feb 25 14:21:06 volumio volumio[796]: info: Scanning category miscellanea Feb 25 14:21:06 volumio volumio[796]: info: Scanning category music_service Feb 25 14:21:06 volumio volumio[796]: info: Scanning category plugins.json Feb 25 14:21:06 volumio volumio[796]: info: Scanning category system_controller Feb 25 14:21:06 volumio volumio[796]: info: Scanning category user_interface Feb 25 14:21:06 volumio volumio[796]: info: Scanning into folder /data/plugins/ Feb 25 14:21:06 volumio volumio[796]: info: Scanning category audio_interface Feb 25 14:21:06 volumio volumio[796]: info: Scanning category music_service Feb 25 14:21:06 volumio volumio[796]: info: Scanning category system_controller Feb 25 14:21:06 volumio volumio[796]: info: Plugin folders cleanup completed Feb 25 14:21:06 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:06 volumio volumio[796]: info: ----- Core plugins startup ---- Feb 25 14:21:06 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:06 volumio volumio[796]: info: Loading plugins from folder /volumio/app/plugins/ Feb 25 14:21:06 volumio volumio[796]: info: Adding plugin upnp to MyMusic Plugins Feb 25 14:21:06 volumio volumio[796]: info: Adding plugin airplay_emulation to MyMusic Plugins Feb 25 14:21:06 volumio volumio[796]: info: Adding plugin upnp_browser to MyMusic Plugins Feb 25 14:21:06 volumio volumio[796]: info: Loading plugins from folder /data/plugins/ Feb 25 14:21:06 volumio volumio[796]: info: Loading plugin "system"... Feb 25 14:21:06 volumio volumio[796]: info: Loading plugin "ampswitch"... Feb 25 14:21:06 volumio volumio[796]: info: Applying required configuration parameters for plugin ampswitch Feb 25 14:21:07 volumio volumio[796]: info: Loading plugin "appearance"... Feb 25 14:21:07 volumio ntpd[860]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Feb 25 14:21:07 volumio volumio[796]: info: Loading plugin "network"... Feb 25 14:21:07 volumio volumio[796]: info: Refreshing Cached IP Addresses Feb 25 14:21:07 volumio sudo[900]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 25 14:21:07 volumio sudo[900]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:07 volumio sudo[900]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:07 volumio sudo[902]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 25 14:21:07 volumio sudo[902]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:07 volumio volumio[796]: info: Loading plugin "services"... Feb 25 14:21:07 volumio sudo[902]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:07 volumio volumio[796]: info: Loading plugin "alsa_controller"... Feb 25 14:21:08 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "wizard"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "networkfs"... Feb 25 14:21:08 volumio volumio[796]: info: Starting Udev Watcher for removable devices Feb 25 14:21:08 volumio volumio[796]: info: Ignoring mount for partition: boot Feb 25 14:21:08 volumio volumio[796]: info: Ignoring mount for partition: volumio Feb 25 14:21:08 volumio volumio[796]: info: Ignoring mount for partition: volumio_data Feb 25 14:21:08 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "volumio_command_line_client"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "upnp"... Feb 25 14:21:08 volumio volumio[796]: info: [1740489668169] Starting Upmpd Daemon Feb 25 14:21:08 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "my_music"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "mpd"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "upnp_browser"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "alarm-clock"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "airplay_emulation"... Feb 25 14:21:08 volumio volumio[796]: info: Starting Shairport Sync Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "last_100"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "webradio"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "i2s_dacs"... Feb 25 14:21:08 volumio volumio[796]: info: Loading plugin "volumiodiscovery"... Feb 25 14:21:09 volumio volumio[796]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 25 14:21:09 volumio volumio[796]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 25 14:21:09 volumio volumio[796]: *** WARNING *** For more information see Feb 25 14:21:09 volumio node[796]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Feb 25 14:21:09 volumio volumio[796]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 25 14:21:09 volumio volumio[796]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 25 14:21:09 volumio volumio[796]: *** WARNING *** For more information see Feb 25 14:21:09 volumio node[796]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 25 14:21:09 volumio node[796]: *** WARNING *** For more information see Feb 25 14:21:09 volumio node[796]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Feb 25 14:21:09 volumio node[796]: *** WARNING *** Please fix your application to use the native API of Avahi! Feb 25 14:21:09 volumio node[796]: *** WARNING *** For more information see Feb 25 14:21:09 volumio volumio[796]: info: Applying required configuration parameters for plugin volumiodiscovery Feb 25 14:21:09 volumio volumio[796]: info: Discovery: Started advertising with name: Volumio Feb 25 14:21:09 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Feb 25 14:21:09 volumio volumio[796]: info: Loading plugin "spop"... Feb 25 14:21:10 volumio volumio[796]: info: Plugin autostart is not enabled Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "outputs"... Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "albumart"... Feb 25 14:21:10 volumio volumio[796]: info: Plugin example_plugin is not enabled Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "inputs"... Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "updater_comm"... Feb 25 14:21:10 volumio sh[547]: eth0: leased 192.168.9.177 for 86400 seconds Feb 25 14:21:10 volumio sh[547]: eth0: adding route to 192.168.9.0/24 Feb 25 14:21:10 volumio sh[547]: eth0: adding default route via 192.168.9.1 Feb 25 14:21:10 volumio dhcpcd[584]: eth0: leased 192.168.9.177 for 86400 seconds Feb 25 14:21:10 volumio avahi-daemon[627]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.9.177. Feb 25 14:21:10 volumio dhcpcd[584]: eth0: adding route to 192.168.9.0/24 Feb 25 14:21:10 volumio avahi-daemon[627]: New relevant interface eth0.IPv4 for mDNS. Feb 25 14:21:10 volumio dhcpcd[584]: eth0: adding default route via 192.168.9.1 Feb 25 14:21:10 volumio avahi-daemon[627]: Registering new address record for 192.168.9.177 on eth0.IPv4. Feb 25 14:21:10 volumio sh[547]: forked to background, child pid 954 Feb 25 14:21:10 volumio dhcpcd[584]: forked to background, child pid 954 Feb 25 14:21:10 volumio volumio[796]: info: Plugin mpdemulation is not enabled Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "rest_api"... Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "websocket"... Feb 25 14:21:10 volumio volumio[796]: info: Starting Socket.io Server version 2.3.0 Feb 25 14:21:10 volumio volumio[796]: info: Loading plugin "fusiondsp"... Feb 25 14:21:10 volumio volumio[796]: Forking 3 albumart workers Feb 25 14:21:10 volumio sh[547]: eth0=eth0 Feb 25 14:21:10 volumio ifplugd(eth0)[856]: client: ifup: interface eth0 already configured Feb 25 14:21:10 volumio ifplugd(eth0)[856]: Program executed successfully. Feb 25 14:21:10 volumio volumio[796]: info: Applying required configuration parameters for plugin fusiondsp Feb 25 14:21:10 volumio volumio[796]: info: Loading i18n strings for locale pl Feb 25 14:21:10 volumio volumio[796]: Updating browse sources language Feb 25 14:21:10 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 25 14:21:11 volumio volumio[796]: Starting albumart workers Feb 25 14:21:11 volumio volumio[796]: Starting albumart workers Feb 25 14:21:11 volumio volumio[796]: Starting albumart workers Feb 25 14:21:11 volumio volumio-time-update[622]: volumio-time-update-util: Fetching time from Volumio... Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::initPlayerControls Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 25 14:21:11 volumio volumio[796]: Express server listening on port 3000 Feb 25 14:21:11 volumio volumio[796]: [Metrics] WebUI: 6s 268.49ms Feb 25 14:21:11 volumio volumio[796]: info: CoreStateMachine::resetVolumioState Feb 25 14:21:11 volumio volumio[796]: info: CoreStateMachine::getcurrentVolume Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::volumioRetrievevolume Feb 25 14:21:11 volumio volumio-time-update[622]: volumio-time-update-util: Setting system time to: 2025-02-25 14:21:43 Feb 25 14:21:11 volumio volumio[796]: info: Volumio Network Manager: Network status updated: 0 Feb 25 14:21:11 volumio sudo[1010]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-02-25 14:21:43 Feb 25 14:21:11 volumio sudo[1010]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:11 volumio dbus-daemon[620]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.11' (uid=0 pid=1011 comm="timedatectl set-time 2025-02-25 14:21:43 ") Feb 25 14:21:11 volumio systemd[1]: Starting Time & Date Service... Feb 25 14:21:11 volumio volumio[796]: verbose: New Socket.io Connection to 192.168.9.177 from 192.168.9.179 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/133.0.6943.120 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 1 Feb 25 14:21:11 volumio volumio[796]: verbose: New Socket.io Connection to 192.168.9.177 from 192.168.9.179 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/133.0.6943.120 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 2 Feb 25 14:21:11 volumio volumio[796]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Feb 25 14:21:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:11 volumio volumio[796]: info: Executing start script for DAC IQaudIO DAC Plus Feb 25 14:21:11 volumio dbus-daemon[620]: [system] Successfully activated service 'org.freedesktop.timedate1' Feb 25 14:21:11 volumio systemd[1]: Started Time & Date Service. Feb 25 14:21:43 volumio systemd-timedated[1025]: Changed local time to Tue Feb 25 14:21:43 2025 Feb 25 14:21:43 volumio volumio[796]: info: Reloading queue from file Feb 25 14:21:43 volumio sudo[1010]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio volumio-time-update[622]: volumio-time-update-util: System time updated successfully. Feb 25 14:21:43 volumio systemd[1]: Started Volumio Time Update Utility. Feb 25 14:21:43 volumio volumio[796]: info: VolumeController:: Volume=100 Mute =false Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::updateTrackBlock Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrackBlock Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioRetrievevolume Feb 25 14:21:43 volumio volumio[796]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Feb 25 14:21:43 volumio volumio[796]: info: USB Boot Capable - System SBC Revision found in cpuinfo: d03115 Feb 25 14:21:43 volumio volumio[796]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::setRepeat null single undefined Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::setRandom null Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:43 volumio volumio[796]: info: Setting Device type: Raspberry PI Feb 25 14:21:43 volumio volumio[796]: info: DAC script executed Feb 25 14:21:43 volumio volumio[796]: info: Completed loading Core Plugins Feb 25 14:21:43 volumio volumio[796]: info: Preparing to generate the ALSA configuration file Feb 25 14:21:43 volumio volumio[796]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Feb 25 14:21:43 volumio volumio[796]: info: Reading ALSA contributions from plugins. Feb 25 14:21:43 volumio volumio[796]: verbose: New Socket.io Connection to 192.168.9.177 from 192.168.9.179 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/133.0.6943.120 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 4 Feb 25 14:21:43 volumio volumio[796]: info: VolumeController:: Volume=100 Mute =false Feb 25 14:21:43 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:43 volumio volumio[796]: info: Asound.conf file unchanged, so no further update is needed Feb 25 14:21:43 volumio volumio[796]: info: Output device has changed, restarting MPD Feb 25 14:21:43 volumio sudo[1050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 25 14:21:43 volumio sudo[1050]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio volumio[796]: info: Output device has changed, restarting Shairport Sync Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio sudo[1050]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio sudo[1052]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 25 14:21:43 volumio sudo[1052]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio systemd[1]: Stopping Music Player Daemon... Feb 25 14:21:43 volumio volumio[796]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 25 14:21:43 volumio volumio[796]: info: ___________ START PLUGINS ___________ Feb 25 14:21:43 volumio volumio[796]: info: ControllerMpd::onStart: Initializing MPD Feb 25 14:21:43 volumio volumio[796]: info: Creating MPD Configuration file Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 25 14:21:43 volumio volumio[796]: info: [1740489703296] CoreMusicLibrary::Adding element Serwery Mediów Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 25 14:21:43 volumio sudo[1071]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 25 14:21:43 volumio sudo[1071]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio sudo[1071]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio sudo[1073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 25 14:21:43 volumio sudo[1073]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio systemd[1]: mpd.service: Succeeded. Feb 25 14:21:43 volumio systemd[1]: Stopped Music Player Daemon. Feb 25 14:21:43 volumio volumio[796]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 25 14:21:43 volumio volumio[796]: info: [1740489703381] CoreMusicLibrary::Adding element Last_100 Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 25 14:21:43 volumio volumio[796]: info: [1740489703383] CoreMusicLibrary::Adding element Webradio Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 25 14:21:43 volumio volumio[796]: info: Initializing BBC Radios Feb 25 14:21:43 volumio systemd[1]: Starting Music Player Daemon... Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: Creating Spotify config file Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: Loading i18n strings for locale pl Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: FusionDsp - mixtype--------------------- Hardware Feb 25 14:21:43 volumio volumio[796]: info: Volumio Calling Home Feb 25 14:21:43 volumio sudo[1079]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 25 14:21:43 volumio sudo[1079]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio sudo[1079]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio volumio[796]: info: Preparing to generate the ALSA configuration file Feb 25 14:21:43 volumio ntpd[860]: Listen normally on 3 eth0 192.168.9.177:123 Feb 25 14:21:43 volumio ntpd[860]: new interface(s) found: waking up resolver Feb 25 14:21:43 volumio volumio[796]: info: Discovery: adding b6ab7f75-377a-4e72-98a5-fa7e5dee30b4 Feb 25 14:21:43 volumio volumio[796]: info: Discovery: Found device Volumio Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf Feb 25 14:21:43 volumio volumio[796]: info: Reading ALSA contributions from plugins. Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: [ASDebug] CurState: stop PrevState: na Feb 25 14:21:43 volumio volumio[796]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Feb 25 14:21:43 volumio volumio[796]: info: [ASDebug] CurState: stop PrevState: na Feb 25 14:21:43 volumio volumio[796]: info: [ASDebug] InitTimeout - Amp off in: 720 ms Feb 25 14:21:43 volumio volumio[796]: info: MPD Permissions set Feb 25 14:21:43 volumio volumio[796]: info: MPD Permissions set Feb 25 14:21:43 volumio volumio[796]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 Feb 25 14:21:43 volumio volumio[796]: info: Spotify config file written Feb 25 14:21:43 volumio volumio[796]: info: No need to fix Spotify hosts Feb 25 14:21:43 volumio sudo[1099]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Feb 25 14:21:43 volumio sudo[1099]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio systemd[1]: Started go-librespot Daemon. Feb 25 14:21:43 volumio go-librespot[1101]: go-librespot daemon starting... Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio sudo[1099]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio volumio[796]: info: Volumio called home Feb 25 14:21:43 volumio volumio[796]: info: Starting Shairport Sync Feb 25 14:21:43 volumio volumio[796]: info: Starting Shairport Sync Feb 25 14:21:43 volumio sudo[1112]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 25 14:21:43 volumio sudo[1112]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:43 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:43 volumio volumio[796]: info: Starting Shairport Sync Feb 25 14:21:43 volumio sudo[1114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 25 14:21:43 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 25 14:21:43 volumio sudo[1114]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio systemd[1]: shairport-sync.service: Succeeded. Feb 25 14:21:43 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:43 volumio sudo[1118]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 25 14:21:43 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:43 volumio sudo[1112]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio sudo[1118]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 25 14:21:43 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Feb 25 14:21:43 volumio systemd[1]: shairport-sync.service: Succeeded. Feb 25 14:21:43 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:43 volumio volumio[796]: info: Shairport-Sync Started Feb 25 14:21:43 volumio volumio[796]: Error adding Membership: Error: addMembership EINVAL Feb 25 14:21:43 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:43 volumio volumio[796]: info: Asound.conf file unchanged, so no further update is needed Feb 25 14:21:43 volumio volumio[796]: info: Output device has changed, restarting MPD Feb 25 14:21:43 volumio sudo[1114]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio sudo[1118]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio volumio[796]: info: Output device has changed, restarting Shairport Sync Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:43 volumio sudo[1128]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Feb 25 14:21:43 volumio sudo[1128]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio sudo[1128]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:43 volumio sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Feb 25 14:21:43 volumio sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:43 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Feb 25 14:21:43 volumio systemd[1]: mpd.service: Succeeded. Feb 25 14:21:43 volumio systemd[1]: Stopped Music Player Daemon. Feb 25 14:21:43 volumio volumio[796]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Feb 25 14:21:43 volumio volumio[796]: info: MPD Permissions set Feb 25 14:21:43 volumio volumio[796]: info: Shairport-Sync Started Feb 25 14:21:43 volumio volumio[796]: info: Shairport-Sync Started Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:43 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:44 volumio volumio[796]: info: Starting Shairport Sync Feb 25 14:21:44 volumio systemd[1]: Starting Music Player Daemon... Feb 25 14:21:44 volumio sudo[1144]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Feb 25 14:21:44 volumio sudo[1144]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:44 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Feb 25 14:21:44 volumio systemd[1]: shairport-sync.service: Succeeded. Feb 25 14:21:44 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:44 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Feb 25 14:21:44 volumio sudo[1144]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:44 volumio volumio[796]: info: Shairport-Sync Started Feb 25 14:21:44 volumio sudo[1138]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Feb 25 14:21:44 volumio sudo[1138]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:44 volumio sudo[1138]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=info msg="running go-librespot 0.2.0" Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=debug msg="app state loaded" Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=debug msg="stored credentials not found" Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=info msg="api server listening on 127.0.0.1:9879" Feb 25 14:21:44 volumio volumio[796]: info: [ASDebug] Togle GPIO: OFF Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01: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-gae2.spotify.com:80]" Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 25 14:21:44 volumio go-librespot[1101]: time="2025-02-25T14:21:44+01:00" level=info msg="zeroconf server listening on port 43425" Feb 25 14:21:44 volumio mpd[1148]: Feb 25 14:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 25 14:21:44 volumio systemd[1]: Started Music Player Daemon. Feb 25 14:21:44 volumio sudo[1073]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:44 volumio sudo[1130]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:44 volumio sudo[1052]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:44 volumio volumio[796]: info: Completed starting Core Plugins Feb 25 14:21:44 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:44 volumio volumio[796]: info: ----- MyVolumio plugins startup ---- Feb 25 14:21:44 volumio volumio[796]: info: ------------------------------------------- Feb 25 14:21:44 volumio volumio[796]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 25 14:21:44 volumio volumio[796]: error: MPD error: The expression evaluated to a falsy value: Feb 25 14:21:44 volumio volumio[796]: assert.ok(self.idling) Feb 25 14:21:44 volumio volumio[796]: error: The expression evaluated to a falsy value: Feb 25 14:21:44 volumio volumio[796]: assert.ok(self.idling) Feb 25 14:21:44 volumio volumio[796]: info: MPD running with PID1148 Feb 25 14:21:44 volumio volumio[796]: ,establishing connection Feb 25 14:21:44 volumio volumio[796]: error: MPD error: The expression evaluated to a falsy value: Feb 25 14:21:44 volumio volumio[796]: assert.ok(self.idling) Feb 25 14:21:44 volumio volumio[796]: error: The expression evaluated to a falsy value: Feb 25 14:21:44 volumio volumio[796]: assert.ok(self.idling) Feb 25 14:21:44 volumio volumio[796]: error: MPD error: The expression evaluated to a falsy value: Feb 25 14:21:44 volumio volumio[796]: assert.ok(self.idling) Feb 25 14:21:44 volumio volumio[796]: error: The expression evaluated to a falsy value: Feb 25 14:21:44 volumio volumio[796]: assert.ok(self.idling) Feb 25 14:21:44 volumio volumio[796]: error: updateQueue error: null Feb 25 14:21:44 volumio volumio[796]: verbose: New Socket.io Connection to 192.168.9.177 from 192.168.9.179 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_3_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) CriOS/133.0.6943.120 Mobile/15E148 Safari/604.1 Engine version: 3 Transport: polling Total Clients: 6 Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::volumioGetVisibleSources Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:44 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 25 14:21:44 volumio volumio[796]: info: Received Get System Info Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 25 14:21:44 volumio volumio[796]: info: Discovery: Getting this device information Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:44 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 25 14:21:44 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:44 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:44 volumio volumio[796]: info: Listing playlists Feb 25 14:21:45 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:21:45 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:21:45 volumio nmbd[837]: [2025/02/25 14:21:45.294719, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 25 14:21:45 volumio nmbd[837]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Feb 25 14:21:45 volumio systemd[1]: Started Samba NMB Daemon. Feb 25 14:21:45 volumio systemd[1]: Starting Samba Winbind Daemon... Feb 25 14:21:45 volumio volumio[796]: info: camilladsp spawned new process with pid 1165, instance 1, run: true Feb 25 14:21:45 volumio volumio[796]: info: camilladsp service started and running in background, instance 1 Feb 25 14:21:45 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:21:45 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Feb 25 14:21:45 volumio winbindd[1157]: [2025/02/25 14:21:45.557209, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Feb 25 14:21:45 volumio winbindd[1157]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Feb 25 14:21:45 volumio volumio[796]: info: FusionDsp - AAAAAAAAAAAAAA-> 22050 44100 48000 88200 96000 176400 192000 384000 <-AAAAAAAAAAAAA Feb 25 14:21:45 volumio volumio[796]: info: FusionDsp loaded Feb 25 14:21:45 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 25 14:21:45 volumio sudo[1170]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Feb 25 14:21:45 volumio sudo[1170]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:45 volumio volumio[796]: info: FusionDsp - Reporting Fusion DSP Enabled Feb 25 14:21:45 volumio volumio[796]: info: Adding Signal Path Element [object Object] Feb 25 14:21:45 volumio volumio[796]: info: Adding fusiondspeq DSP Signal Path Element Feb 25 14:21:45 volumio volumio[796]: info: FusionDsp - ---- installed callbackRead Feb 25 14:21:45 volumio volumio[796]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 25 14:21:45 volumio volumio[796]: error: FusionDsp - WebSocket error: [object Object] Feb 25 14:21:45 volumio volumio[796]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 25 14:21:45 volumio winbindd[1157]: [2025/02/25 14:21:45.643839, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 25 14:21:45 volumio winbindd[1157]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Feb 25 14:21:45 volumio systemd[1]: Started FusionDsp Daemon. Feb 25 14:21:45 volumio systemd[1]: Started Samba Winbind Daemon. Feb 25 14:21:45 volumio systemd[1]: Starting Samba SMB Daemon... Feb 25 14:21:45 volumio sudo[1170]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:45 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Feb 25 14:21:46 volumio winbindd[1157]: [2025/02/25 14:21:46.113378, 0] ../source3/winbindd/wb_lookupsids.c:659(wb_lookupsids_recv) Feb 25 14:21:46 volumio winbindd[1157]: res_names->count = 3, expected 4 Feb 25 14:21:46 volumio smbd[1181]: [2025/02/25 14:21:46.130303, 0] ../lib/util/become_daemon.c:138(daemon_ready) Feb 25 14:21:46 volumio smbd[1181]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Feb 25 14:21:46 volumio systemd[1]: Started Samba SMB Daemon. Feb 25 14:21:46 volumio systemd[1]: Reached target Multi-User System. Feb 25 14:21:46 volumio systemd[1]: Reached target Graphical Interface. Feb 25 14:21:46 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Feb 25 14:21:46 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Feb 25 14:21:46 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Feb 25 14:21:46 volumio systemd[1]: Startup finished in 12.049s (kernel) + 17.910s (userspace) = 29.960s. Feb 25 14:21:46 volumio volumio[796]: info: go-librespot daemon successfully initialized Feb 25 14:21:49 volumio volumio[796]: info: Volumio Network Manager: Network status updated: 1 Feb 25 14:21:49 volumio sudo[1208]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 25 14:21:49 volumio sudo[1208]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:49 volumio sudo[1208]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:49 volumio sudo[1210]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 25 14:21:49 volumio sudo[1210]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:49 volumio sudo[1210]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:49 volumio sudo[1214]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 25 14:21:49 volumio sudo[1214]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:49 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Feb 25 14:21:49 volumio sudo[1214]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:49 volumio volumio[796]: info: Upmpdcli Daemon Started Feb 25 14:21:49 volumio volumio[796]: info: Initializing connection to go-librespot Websocket Feb 25 14:21:49 volumio go-librespot[1101]: time="2025-02-25T14:21:49+01:00" level=debug msg="new websocket client" Feb 25 14:21:49 volumio volumio[796]: info: Connection to go-librespot Websocket established Feb 25 14:21:49 volumio volumio[796]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 25 14:21:49 volumio volumio[1216]: Generating RSA private key, 4096 bit long modulus (2 primes) Feb 25 14:21:49 volumio volumio-remote-updater[638]: [2025-02-25 14:21:49] [connect] Successful connection Feb 25 14:21:49 volumio volumio[796]: 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: 8 Feb 25 14:21:49 volumio volumio-remote-updater[638]: [2025-02-25 14:21:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1740489709 101 Feb 25 14:21:52 volumio volumio[796]: info: Getting Spotify volume Feb 25 14:21:52 volumio volumio[796]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Feb 25 14:21:52 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:52 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:52 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:21:52 volumio volumio[796]: SPOTIFY: SPOTIFY VOLUME undefined Feb 25 14:21:52 volumio volumio[796]: SPOTIFY: VOLUMIO VOLUME 100 Feb 25 14:21:52 volumio volumio[796]: info: Aligning Spotify Volume to Volumio Volume Feb 25 14:21:52 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:21:52 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:52 volumio volumio[796]: info: Setting Spotify Volume from Volumio: 100 Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 25 14:21:53 volumio volumio[796]: info: Adding plugin bluetooth to MyMusic Plugins Feb 25 14:21:53 volumio volumio[796]: info: Adding plugin multiroom to MyMusic Plugins Feb 25 14:21:53 volumio volumio[796]: info: Adding plugin metavolumio to MyMusic Plugins Feb 25 14:21:53 volumio volumio[796]: info: Adding plugin cd_controller to MyMusic Plugins Feb 25 14:21:53 volumio volumio[796]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 25 14:21:53 volumio volumio[796]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 25 14:21:53 volumio volumio[796]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 25 14:21:54 volumio volumio[796]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 25 14:21:54 volumio volumio[796]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 25 14:21:54 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:54 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:54 volumio volumio[796]: info: Starting MyVolumio Remote Streaming Endpoints Feb 25 14:21:54 volumio volumio[796]: info: MyVolumio login type: Token Feb 25 14:21:54 volumio volumio[796]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 25 14:21:54 volumio volumio[796]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 25 14:21:55 volumio volumio[796]: info: Starting Streaming Service Transparent Proxy Feb 25 14:21:55 volumio volumio[796]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 25 14:21:55 volumio volumio[796]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 25 14:21:55 volumio volumio[796]: info: Streaming services startup Feb 25 14:21:55 volumio volumio[796]: info: Starting Streaming Daemon Feb 25 14:21:55 volumio sudo[1240]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 25 14:21:55 volumio sudo[1240]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:55 volumio sudo[1240]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:55 volumio volumio[796]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 25 14:21:55 volumio volumio[796]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Feb 25 14:21:55 volumio volumio[796]: info: Sending Spotify command with payload to local API: /player/volume Feb 25 14:21:55 volumio volumio[796]: info: CoreCommandRouter::volumioPlay Feb 25 14:21:55 volumio volumio[796]: info: CoreStateMachine::play index undefined Feb 25 14:21:55 volumio volumio[796]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 25 14:21:55 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:55 volumio volumio[796]: info: CoreStateMachine::startPlaybackTimer Feb 25 14:21:55 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:55 volumio volumio[796]: info: [1740489715183] ControllerWebradio::clearAddPlayTrack Feb 25 14:21:55 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand stop Feb 25 14:21:55 volumio volumio[796]: error: Cannot start Volumio Streaming Daemon Feb 25 14:21:55 volumio volumio[796]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 25 14:21:55 volumio volumio[796]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 25 14:21:55 volumio volumio[796]: info: sendMpdCommand stop took 81 milliseconds Feb 25 14:21:55 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand clear Feb 25 14:21:55 volumio volumio[796]: info: Feb 25 14:21:55 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:55 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:55 volumio volumio[796]: info: sendMpdCommand clear took 4 milliseconds Feb 25 14:21:55 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand load "https://stream.rcs.revma.com/gzwc1xcq042vv" Feb 25 14:21:55 volumio volumio[796]: info: Feb 25 14:21:55 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:55 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:55 volumio volumio[796]: info: Feb 25 14:21:55 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:55 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:55 volumio volumio[796]: info: Feb 25 14:21:55 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:55 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:55 volumio volumio[796]: error: updateQueue error: null Feb 25 14:21:55 volumio volumio[796]: info: ------------------------------ 55ms Feb 25 14:21:55 volumio volumio[796]: STREAMING PROXY: Starting server on port 3245 Feb 25 14:21:55 volumio volumio[796]: Node JS runtime: 14 Feb 25 14:21:56 volumio volumio[796]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 25 14:21:56 volumio volumio[796]: info: MyVolumio token set successfully Feb 25 14:21:56 volumio volumio[796]: info: MYVOLUMIO: Adding device Feb 25 14:21:56 volumio volumio[796]: info: MYVOLUMIO: Evaluating Server Feb 25 14:21:56 volumio volumio[796]: info: MyVolumio status changed Feb 25 14:21:56 volumio volumio[796]: info: Streaming services startup Feb 25 14:21:56 volumio volumio[796]: info: Starting Streaming Daemon Feb 25 14:21:57 volumio volumio[796]: info: Removing browser output: myVolumio user plan is not superstar Feb 25 14:21:57 volumio volumio[796]: info: Removing audio output: Feb 25 14:21:57 volumio volumio[796]: info: Stoppping Tunnel 1 Feb 25 14:21:57 volumio sudo[1269]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 25 14:21:57 volumio sudo[1269]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:57 volumio sudo[1272]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Feb 25 14:21:57 volumio sudo[1272]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:21:57 volumio sudo[1269]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:57 volumio volumio[796]: error: Cannot start Volumio Streaming Daemon Feb 25 14:21:57 volumio volumio[796]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 25 14:21:57 volumio volumio[796]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 25 14:21:57 volumio sudo[1272]: pam_unix(sudo:session): session closed for user root Feb 25 14:21:57 volumio volumio[796]: info: Remote SSH Stopped Feb 25 14:21:57 volumio volumio[796]: info: Setting Geolocation for MyVolumio to eu10 Feb 25 14:21:57 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:57 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:57 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:57 volumio volumio[796]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Feb 25 14:21:58 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand add "https://stream.rcs.revma.com/gzwc1xcq042vv" Feb 25 14:21:58 volumio volumio[796]: error: updateQueue error: null Feb 25 14:21:58 volumio volumio[796]: error: updateQueue error: null Feb 25 14:21:58 volumio volumio[796]: error: updateQueue error: null Feb 25 14:21:58 volumio volumio[796]: info: Feb 25 14:21:58 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:58 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 2746ms Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 2731ms Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 2730ms Feb 25 14:21:58 volumio volumio[796]: info: sendMpdCommand add "https://stream.rcs.revma.com/gzwc1xcq042vv" took 2 milliseconds Feb 25 14:21:58 volumio volumio[796]: info: CoreStateMachine::setConsumeUpdateService mpd Feb 25 14:21:58 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand play Feb 25 14:21:58 volumio volumio[796]: Upnp client error: Error: This socket has been ended by the other party Feb 25 14:21:58 volumio volumio[796]: info: Feb 25 14:21:58 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:58 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:58 volumio volumio[796]: info: Feb 25 14:21:58 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:58 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:58 volumio volumio[796]: info: Feb 25 14:21:58 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:58 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 9ms Feb 25 14:21:58 volumio volumio[796]: info: sendMpdCommand play took 7 milliseconds Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 5ms Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 3ms Feb 25 14:21:58 volumio volumio[796]: info: ------------------------------ 3ms Feb 25 14:21:58 volumio volumio[796]: info: Updating MyVolumio device info Feb 25 14:21:58 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:58 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:58 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:21:58 volumio volumio[1216]: ...................................................................................................++++ Feb 25 14:21:58 volumio volumio[796]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Feb 25 14:21:59 volumio volumio[796]: info: FusionDsp - ---- read samplerate from file: 44100 Feb 25 14:21:59 volumio volumio[796]: info: camilladsp stopping service pid 1165... Feb 25 14:21:59 volumio volumio[796]: info: camilladsp service terminated, instance 1 Feb 25 14:21:59 volumio volumio[796]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 25 14:21:59 volumio volumio[796]: info: camilladsp service started and running in background, instance 1 Feb 25 14:21:59 volumio volumio[796]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Feb 25 14:21:59 volumio volumio[796]: info: FusionDsp - ---- read samplerate from file: 44100 Feb 25 14:21:59 volumio volumio[796]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:59 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 77 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 57 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 55 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 54 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: camilladsp spawned new process with pid 1305, instance 1, run: true Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 32 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: ------------------------------ 35ms Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 31 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand playlistinfo took 31 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand playlistinfo took 30 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand playlistinfo took 31 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand playlistinfo took 30 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 23 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 22 milliseconds Feb 25 14:21:59 volumio volumio[796]: info: sendMpdCommand status took 22 milliseconds Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:21:59 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus stop Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:21:59 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:21:59 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:21:59 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:21:59 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:21:59 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:21:59 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:59 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:59 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:21:59 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:21:59 volumio volumio[796]: info: ------------------------------ 144ms Feb 25 14:21:59 volumio kernel: pcm512x 1-004c: No SCLK, using BCLK: -2 Feb 25 14:21:59 volumio volumio[796]: info: ------------------------------ 170ms Feb 25 14:21:59 volumio volumio[796]: info: ------------------------------ 150ms Feb 25 14:21:59 volumio volumio[796]: info: ------------------------------ 149ms Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:59 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:21:59 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:21:59 volumio volumio[796]: info: Feb 25 14:21:59 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:21:59 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:21:59 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:22:00 volumio volumio[796]: info: Feb 25 14:22:00 volumio volumio[796]: ---------------------------- MPD announces system playlist update Feb 25 14:22:00 volumio volumio[796]: info: Ignoring MPD Status Update Feb 25 14:22:00 volumio volumio[796]: info: Feb 25 14:22:00 volumio volumio[796]: ---------------------------- MPD announces state update: player Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::getState Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand status Feb 25 14:22:00 volumio volumio[796]: error: FusionDsp - WebSocket error: [object Object] Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 66 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 63 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 63 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 62 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 8ms Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand status took 7 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 7ms Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand status took 6 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 5ms Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand status took 4 milliseconds Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseState Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":982,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 167ms Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 167ms Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 160ms Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 155ms Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 154ms Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: stop Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] Togle GPIO: ON Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 97 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 97 milliseconds Feb 25 14:22:00 volumio volumio[796]: info: sendMpdCommand playlistinfo took 97 milliseconds Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: verbose: ControllerMpd::parseTrackInfo Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1611,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1611,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ControllerMpd::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::servicePushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1611,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"gzwc1xcq042vv","artist":"Muzyczne Radio Live 192 kbps","album":null,"uri":"https://stream.rcs.revma.com/gzwc1xcq042vv","trackType":""} Feb 25 14:22:00 volumio volumio[796]: verbose: CURRENT POSITION 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState stateService play Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::syncState currentStatus play Feb 25 14:22:00 volumio volumio[796]: info: Received an update from plugin. extracting info from payload Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CorePlayQueue::getTrack 0 Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: CoreStateMachine::pushState Feb 25 14:22:00 volumio volumio[796]: info: CoreCommandRouter::volumioPushState Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 143ms Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 142ms Feb 25 14:22:00 volumio volumio[796]: info: ------------------------------ 141ms Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: info: [ASDebug] CurState: play PrevState: play Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[796]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 25 14:22:00 volumio volumio[1216]: ..............++++ Feb 25 14:22:00 volumio volumio[1216]: e is 65537 (0x010001) Feb 25 14:22:00 volumio volumio[1216]: writing RSA key Feb 25 14:22:01 volumio systemd[1]: systemd-fsckd.service: Succeeded. Feb 25 14:22:01 volumio volumio[796]: info: MYVOLUMIO: Adding device Feb 25 14:22:01 volumio volumio[796]: info: MYVOLUMIO: Evaluating Server Feb 25 14:22:02 volumio volumio[796]: info: Setting Geolocation for MyVolumio to eu6 Feb 25 14:22:02 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:02 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:02 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:02 volumio volumio[796]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Feb 25 14:22:03 volumio systemd[1]: systemd-hostnamed.service: Succeeded. Feb 25 14:22:03 volumio volumio[796]: info: Updating MyVolumio device info Feb 25 14:22:03 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:03 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:03 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:04 volumio volumio[796]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Feb 25 14:22:09 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 25 14:22:09 volumio volumio[796]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 10 Feb 25 14:22:09 volumio volumio[796]: info: CoreCommandRouter::volumioGetState Feb 25 14:22:11 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:22:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 25 14:22:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 25 14:22:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 25 14:22:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Feb 25 14:22:11 volumio volumio[796]: info: Received Get System Version Feb 25 14:22:11 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 25 14:22:13 volumio systemd[1]: systemd-timedated.service: Succeeded. Feb 25 14:22:13 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 25 14:22:13 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:13 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 25 14:22:13 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Feb 25 14:22:13 volumio volumio-remote-updater[638]: No test mode Feb 25 14:22:13 volumio volumio-remote-updater[638]: No alpha test mode Feb 25 14:22:13 volumio volumio[796]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 25 14:22:13 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::volumioGetBrowseSources Feb 25 14:22:14 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 25 14:22:15 volumio volumio[796]: error: MyVolumio Plugin failed to authenticate in a timely fashion Feb 25 14:22:15 volumio volumio[796]: info: Completed starting MyVolumio Plugin Feb 25 14:22:15 volumio volumio[796]: [Metrics] CommandRouter: 37s 971.35ms Feb 25 14:22:15 volumio volumio[796]: info: CoreCommandRouter::volumiosetStartupVolume Feb 25 14:22:15 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 25 14:22:15 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 25 14:22:15 volumio volumio[796]: info: CoreCommandRouter::Close All Modals sent Feb 25 14:22:15 volumio volumio[796]: info: CoreCommandRouter::Close All Modals sent Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - ---- read samplerate from file: 44100 Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - ---- read samplerate from file: 44100 Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - If filter freq >samplerate/2 then disable it Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - {"Reload":{"result":"Ok"}} Feb 25 14:22:15 volumio volumio[796]: info: FusionDsp - {"Reload":{"result":"Ok"}} Feb 25 14:22:16 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Feb 25 14:22:16 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 25 14:22:16 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Feb 25 14:22:20 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 25 14:22:20 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 25 14:22:20 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:22:20 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:22:22 volumio volumio[796]: info: BOOT COMPLETED Feb 25 14:22:27 volumio volumio[796]: info: Starting Uninstall of plugin system_controller - autostart Feb 25 14:22:27 volumio volumio[796]: info: Uninstalling plugin autostart Feb 25 14:22:27 volumio volumio[796]: info: Disabling plugin autostart Feb 25 14:22:27 volumio volumio[796]: info: Checking if uninstall.sh is present Feb 25 14:22:27 volumio volumio[796]: info: Executing uninstall.sh Feb 25 14:22:27 volumio sudo[1462]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/system_controller/autostart/uninstall.sh Feb 25 14:22:27 volumio sudo[1462]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 25 14:22:27 volumio sudo[1462]: pam_unix(sudo:session): session closed for user root Feb 25 14:22:27 volumio volumio[796]: info: Uninstall script completed Feb 25 14:22:27 volumio volumio[796]: info: Removing plugin autostart from configuration Feb 25 14:22:27 volumio volumio[796]: info: Successfully removed autostart configuration files Feb 25 14:22:27 volumio volumio[796]: info: Plugin folders cleanup Feb 25 14:22:27 volumio volumio[796]: info: Scanning into folder /volumio/app/plugins/ Feb 25 14:22:27 volumio volumio[796]: info: Scanning category audio_interface Feb 25 14:22:27 volumio volumio[796]: info: Scanning category miscellanea Feb 25 14:22:27 volumio volumio[796]: info: Scanning category music_service Feb 25 14:22:27 volumio volumio[796]: info: Scanning category plugins.json Feb 25 14:22:27 volumio volumio[796]: info: Scanning category system_controller Feb 25 14:22:27 volumio volumio[796]: info: Scanning category user_interface Feb 25 14:22:27 volumio volumio[796]: info: Scanning into folder /data/plugins/ Feb 25 14:22:27 volumio volumio[796]: info: Scanning category audio_interface Feb 25 14:22:27 volumio volumio[796]: info: Scanning category music_service Feb 25 14:22:27 volumio volumio[796]: info: Scanning category system_controller Feb 25 14:22:27 volumio volumio[796]: info: Cleaning folder for autostart Feb 25 14:22:27 volumio volumio[796]: info: Plugin folders cleanup completed Feb 25 14:22:27 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 25 14:22:27 volumio volumio[796]: info: [{"prettyName":"FusionDsp","name":"fusiondsp","category":"audio_interface","version":"1.0.54","icon":"fa-sliders fa-rotate-90","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Spotify","name":"spop","category":"music_service","version":"4.1.3","icon":"fa-spotify","isManuallyInstalled":false,"enabled":true,"active":true},{"prettyName":"Amplifier Switch","name":"ampswitch","category":"system_controller","version":"0.2.1","icon":"fa-power-off","isManuallyInstalled":false,"enabled":true,"active":true}] Feb 25 14:22:27 volumio volumio[796]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 25 14:22:27 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:22:27 volumio volumio[796]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 25 14:22:32 volumio volumio[796]: info: Starting Uninstall of plugin system_controller - ampswitch Feb 25 14:22:32 volumio volumio[796]: info: Uninstalling plugin ampswitch Feb 25 14:22:32 volumio volumio[796]: info: [ASDebug] Port: 24 Feb 25 14:22:32 volumio volumio[796]: info: [ASDebug] Inverted: false Feb 25 14:22:32 volumio volumio[796]: info: [ASDebug] Delay: 720 Feb 25 14:22:40 volumio volumio[796]: info: Starting Uninstall of plugin system_controller - ampswitch Feb 25 14:22:40 volumio volumio[796]: info: Uninstalling plugin ampswitch Feb 25 14:22:40 volumio volumio[796]: info: [ASDebug] Port: 24 Feb 25 14:22:40 volumio volumio[796]: info: [ASDebug] Inverted: false Feb 25 14:22:40 volumio volumio[796]: info: [ASDebug] Delay: 720 Feb 25 14:22:40 volumio volumio[796]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 25 14:22:40 volumio volumio[796]: Error: EBADF: bad file descriptor, close Feb 25 14:22:40 volumio volumio[796]: at Object.closeSync (fs.js:439:3) Feb 25 14:22:40 volumio volumio[796]: at Object.closeSync (/volumio/node_modules/graceful-fs/graceful-fs.js:74:20) Feb 25 14:22:40 volumio volumio[796]: at Object.closeSync (/data/plugins/system_controller/ampswitch/node_modules/graceful-fs/graceful-fs.js:51:27) Feb 25 14:22:40 volumio volumio[796]: at Gpio.unexport (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:307:8) Feb 25 14:22:40 volumio volumio[796]: at AmpSwitchController.freeGPIO (/data/plugins/system_controller/ampswitch/index.js:242:19) Feb 25 14:22:40 volumio volumio[796]: at AmpSwitchController.onStop (/data/plugins/system_controller/ampswitch/index.js:90:10) Feb 25 14:22:40 volumio volumio[796]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) Feb 25 14:22:40 volumio volumio[796]: at PluginManager.unInstallPlugin (/volumio/app/pluginmanager.js:1449:10) Feb 25 14:22:40 volumio volumio[796]: at CoreCommandRouter.unInstallPlugin (/volumio/app/index.js:1478:22) Feb 25 14:22:40 volumio volumio[796]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1254:45) Feb 25 14:22:40 volumio volumio[796]: at Socket.emit (events.js:315:20) Feb 25 14:22:40 volumio volumio[796]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Feb 25 14:22:40 volumio volumio[796]: at processTicksAndRejections (internal/process/task_queues.js:75:11) { Feb 25 14:22:40 volumio volumio[796]: errno: -9, Feb 25 14:22:40 volumio volumio[796]: syscall: 'close', Feb 25 14:22:40 volumio volumio[796]: code: 'EBADF' Feb 25 14:22:40 volumio volumio[796]: } Feb 25 14:22:40 volumio volumio[796]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 25 14:22:40 volumio ntpd[860]: Soliciting pool server 193.25.222.136 Feb 25 14:22:40 volumio sudo[1576]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-25 14:21 Feb 25 14:22:40 volumio sudo[1576]: 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"