-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sun 2025-04-13 15:00:29 CEST. -- Apr 13 14:59:31 volumio fake-hwclock[301]: Sun Apr 13 12:59:31 UTC 2025 Apr 13 14:59:31 volumio systemd[1]: Mounted Kernel Configuration File System. Apr 13 14:59:31 volumio systemd[1]: Started Restore / save the current clock. Apr 13 14:59:31 volumio systemd[1]: Starting Create System Users... Apr 13 14:59:31 volumio systemd[1]: Starting Load/Save Random Seed... Apr 13 14:59:31 volumio systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Apr 13 14:59:31 volumio systemd[1]: Started Load/Save Random Seed. Apr 13 14:59:31 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 13 14:59:31 volumio systemd[1]: Started Create System Users. Apr 13 14:59:31 volumio systemd[1]: Starting Create Static Device Nodes in /dev... Apr 13 14:59:31 volumio systemd[1]: Started udev Coldplug all Devices. Apr 13 14:59:31 volumio systemd[1]: Starting Helper to synchronize boot up for ifupdown... Apr 13 14:59:31 volumio systemd[1]: Started Helper to synchronize boot up for ifupdown. Apr 13 14:59:31 volumio systemd[1]: Started Create Static Device Nodes in /dev. Apr 13 14:59:31 volumio systemd[1]: Reached target Local File Systems (Pre). Apr 13 14:59:31 volumio systemd[1]: var-log.mount: Directory /var/log to mount over is not empty, mounting anyway. Apr 13 14:59:31 volumio systemd[1]: Mounting /var/log... Apr 13 14:59:31 volumio systemd[1]: Mounting /var/spool/cups... Apr 13 14:59:31 volumio systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway. Apr 13 14:59:31 volumio systemd[1]: Mounting /tmp... Apr 13 14:59:31 volumio systemd[1]: Starting udev Kernel Device Manager... Apr 13 14:59:31 volumio systemd[1]: Mounted /var/log. Apr 13 14:59:31 volumio systemd[1]: Mounted /var/spool/cups. Apr 13 14:59:31 volumio systemd[1]: Mounted /tmp. Apr 13 14:59:31 volumio systemd[1]: Mounting /var/spool/cups/tmp... Apr 13 14:59:31 volumio systemd[1]: Starting Flush Journal to Persistent Storage... Apr 13 14:59:31 volumio systemd[1]: Mounted /var/spool/cups/tmp. Apr 13 14:59:31 volumio systemd-udevd[337]: Network interface NamePolicy= disabled on kernel command line, ignoring. Apr 13 14:59:31 volumio systemd-journald[309]: Runtime journal (/run/log/journal/d9a3e155a633914cdbe1662066e99934) is 7.5M, max 30.0M, 22.5M free. Apr 13 14:59:31 volumio systemd[1]: Started Flush Journal to Persistent Storage. Apr 13 14:59:31 volumio systemd[1]: Started udev Kernel Device Manager. Apr 13 14:59:31 volumio systemd[1]: Starting Show Plymouth Boot Screen... Apr 13 14:59:31 volumio systemd[1]: plymouth-start.service: Succeeded. Apr 13 14:59:31 volumio systemd[1]: Started Show Plymouth Boot Screen. Apr 13 14:59:31 volumio systemd[1]: Started Forward Password Requests to Plymouth Directory Watch. Apr 13 14:59:31 volumio systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Apr 13 14:59:31 volumio systemd[1]: Reached target Local Encrypted Volumes. Apr 13 14:59:31 volumio systemd[1]: Reached target Paths. Apr 13 14:59:31 volumio kernel: rpi-gpiomem 3f200000.gpiomem: window base 0x3f200000 size 0x00001000 Apr 13 14:59:31 volumio kernel: rpi-gpiomem 3f200000.gpiomem: initialised 1 regions as /dev/gpiomem Apr 13 14:59:31 volumio kernel: vc_sm_cma: module is from the staging directory, the quality is unknown, you have been warned. Apr 13 14:59:31 volumio kernel: bcm2835_vc_sm_cma_probe: Videocore shared memory driver Apr 13 14:59:31 volumio kernel: [vc_sm_connected_init]: start Apr 13 14:59:31 volumio kernel: [vc_sm_connected_init]: installed successfully Apr 13 14:59:31 volumio systemd[1]: Found device /dev/ttyAMA0. Apr 13 14:59:31 volumio kernel: mc: Linux media interface: v0.10 Apr 13 14:59:32 volumio kernel: videodev: Linux video capture interface: v2.00 Apr 13 14:59:32 volumio systemd[1]: Found device /dev/disk/by-uuid/9C48-E5A3. Apr 13 14:59:32 volumio kernel: snd_bcm2835: module is from the staging directory, the quality is unknown, you have been warned. Apr 13 14:59:32 volumio kernel: snd_bcm2835: unknown parameter 'enable_compat_alsa' ignored Apr 13 14:59:32 volumio kernel: usbcore: registered new interface driver ax88179_178a Apr 13 14:59:32 volumio kernel: bcm2835_mmal_vchiq: module is from the staging directory, the quality is unknown, you have been warned. Apr 13 14:59:32 volumio kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Apr 13 14:59:32 volumio kernel: bcm2835_audio bcm2835_audio: card created with 4 channels Apr 13 14:59:32 volumio kernel: bcm2835_v4l2: module is from the staging directory, the quality is unknown, you have been warned. Apr 13 14:59:32 volumio kernel: bcm2835_isp: module is from the staging directory, the quality is unknown, you have been warned. Apr 13 14:59:32 volumio kernel: bcm2835_codec: module is from the staging directory, the quality is unknown, you have been warned. Apr 13 14:59:32 volumio systemd[1]: Starting File System Check on /dev/disk/by-uuid/9C48-E5A3... Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video13 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video14 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video15 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video16 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video10 Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 decode Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node output[0] registered as /dev/video20 Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video11 Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node capture[0] registered as /dev/video21 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node capture[1] registered as /dev/video22 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Device node stats[2] registered as /dev/video23 Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register output node 0 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register capture node 1 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register capture node 2 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Register capture node 3 with media controller Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video12 Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 isp Apr 13 14:59:32 volumio kernel: bcm2835-isp bcm2835-isp: Loaded V4L2 bcm2835-isp Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video18 Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 image_fx Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Device registered as /dev/video31 Apr 13 14:59:32 volumio kernel: bcm2835-codec bcm2835-codec: Loaded V4L2 encode_image Apr 13 14:59:32 volumio systemd-udevd[343]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Apr 13 14:59:32 volumio kernel: usb 1-1.2: 1:3 : unsupported format bits 0x100000000 Apr 13 14:59:32 volumio kernel: usbcore: registered new interface driver snd-usb-audio Apr 13 14:59:32 volumio systemd-udevd[343]: Using default interface naming scheme 'v240'. Apr 13 14:59:32 volumio systemd-udevd[343]: link_config: autonegotiation is unset or enabled, the speed and duplex are not writable. Apr 13 14:59:32 volumio systemd-fsck[434]: fsck.fat 4.1 (2017-01-24) Apr 13 14:59:32 volumio systemd-fsck[434]: /dev/mmcblk0p1: 404 files, 166331/184582 clusters Apr 13 14:59:33 volumio systemd[1]: Started File System Check on /dev/disk/by-uuid/9C48-E5A3. Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in Huge Pages File System being skipped. Apr 13 14:59:33 volumio kernel: alsactl[469]: memfd_create() called without MFD_EXEC or MFD_NOEXEC_SEAL set Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped. Apr 13 14:59:33 volumio systemd-udevd[349]: Process '/usr/sbin/alsactl -E HOME=/run/alsa restore 1' failed with exit code 17. Apr 13 14:59:33 volumio systemd-udevd[348]: Process '/bin/bash -c '/usr/local/bin/volumio usbattach'' failed with exit code 7. Apr 13 14:59:33 volumio systemd[1]: Starting Show Plymouth Boot Screen... Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in Rebuild Hardware Database being skipped. Apr 13 14:59:33 volumio systemd[1]: Mounting /boot... Apr 13 14:59:33 volumio systemd[1]: Started File System Check Daemon to report status. Apr 13 14:59:33 volumio systemd[1]: Found device AX88179 Gigabit Ethernet. Apr 13 14:59:33 volumio systemd[1]: Mounted /boot. Apr 13 14:59:33 volumio systemd[1]: plymouth-start.service: Succeeded. Apr 13 14:59:33 volumio systemd[1]: Started Show Plymouth Boot Screen. Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in Dispatch Password Requests to Console Directory Watch being skipped. Apr 13 14:59:33 volumio systemd[1]: Reached target Local File Systems. Apr 13 14:59:33 volumio systemd[1]: Starting Preprocess NFS configuration... Apr 13 14:59:33 volumio systemd[1]: Starting Create Volatile Files and Directories... Apr 13 14:59:33 volumio systemd[1]: Starting Tell Plymouth To Write Out Runtime Data... Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in Commit a transient machine-id on disk being skipped. Apr 13 14:59:33 volumio systemd[1]: Starting Raise network interfaces... Apr 13 14:59:33 volumio systemd[1]: Started ifup for eth0. Apr 13 14:59:33 volumio systemd[1]: nfs-config.service: Succeeded. Apr 13 14:59:33 volumio systemd[1]: Started Preprocess NFS configuration. Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped. Apr 13 14:59:33 volumio systemd[1]: Condition check resulted in RPC security service for NFS server being skipped. Apr 13 14:59:33 volumio systemd[1]: Reached target NFS client services. Apr 13 14:59:33 volumio systemd[1]: plymouth-read-write.service: Succeeded. Apr 13 14:59:33 volumio systemd[1]: Started Tell Plymouth To Write Out Runtime Data. Apr 13 14:59:33 volumio systemd[1]: Received SIGRTMIN+20 from PID 193 (plymouthd). Apr 13 14:59:33 volumio systemd[1]: Started Create Volatile Files and Directories. Apr 13 14:59:33 volumio systemd[1]: Starting RPC bind portmap service... Apr 13 14:59:33 volumio systemd[1]: Starting Update UTMP about System Boot/Shutdown... Apr 13 14:59:34 volumio systemd[1]: Started Entropy daemon using the HAVEGE algorithm. Apr 13 14:59:34 volumio systemd[1]: Condition check resulted in Network Time Synchronization being skipped. Apr 13 14:59:34 volumio systemd[1]: Started RPC bind portmap service. Apr 13 14:59:34 volumio systemd[1]: Reached target RPC Port Mapper. Apr 13 14:59:34 volumio systemd[1]: Reached target Remote File Systems (Pre). Apr 13 14:59:34 volumio systemd[1]: Reached target Remote File Systems. Apr 13 14:59:34 volumio systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Apr 13 14:59:34 volumio systemd[1]: Started Update UTMP about System Boot/Shutdown. Apr 13 14:59:34 volumio systemd[1]: Reached target System Initialization. Apr 13 14:59:34 volumio systemd[1]: Started Daily apt download activities. Apr 13 14:59:34 volumio systemd[1]: Listening on Avahi mDNS/DNS-SD Stack Activation Socket. Apr 13 14:59:34 volumio systemd[1]: Started Daily apt upgrade and clean activities. Apr 13 14:59:34 volumio systemd[1]: Started Daily Cleanup of Temporary Directories. Apr 13 14:59:34 volumio systemd[1]: Reached target Timers. Apr 13 14:59:34 volumio systemd[1]: Listening on D-Bus System Message Bus Socket. Apr 13 14:59:34 volumio systemd[1]: Listening on triggerhappy.socket. Apr 13 14:59:34 volumio systemd[1]: Reached target Sockets. Apr 13 14:59:34 volumio systemd[1]: Reached target Basic System. Apr 13 14:59:34 volumio systemd[1]: Condition check resulted in getty on tty2-tty6 if dbus and logind are not available being skipped. Apr 13 14:59:34 volumio kernel: cfg80211: Loading compiled-in X.509 certificates for regulatory database Apr 13 14:59:34 volumio kernel: Loaded X.509 cert 'benh@debian.org: 577e021cb980e0e820821ba7b54b4961b8b4fadf' Apr 13 14:59:34 volumio kernel: Loaded X.509 cert 'romain.perier@gmail.com: 3abbc6ec146e09d1b6016ab9d6cf71dd233f0328' Apr 13 14:59:34 volumio kernel: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7' Apr 13 14:59:34 volumio kernel: Loaded X.509 cert 'wens: 61c038651aabdcf94bd0ac7ff06c7248db18c600' Apr 13 14:59:34 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Apr 13 14:59:34 volumio systemd[1]: Condition check resulted in Configure Bluetooth Modems connected by UART being skipped. Apr 13 14:59:34 volumio systemd[1]: Started volumio-remote-updater.service. Apr 13 14:59:34 volumio systemd[1]: Started MPD Monitor Service. Apr 13 14:59:34 volumio systemd[1]: Started Volumio Log Rotation Service. Apr 13 14:59:34 volumio sh[490]: command failed: No such device (-19) Apr 13 14:59:34 volumio systemd[1]: Starting Wireless Services... Apr 13 14:59:34 volumio systemd[1]: Started Manage Sound Card State (restore and store). Apr 13 14:59:34 volumio alsactl[524]: alsactl 1.1.8 daemon started Apr 13 14:59:34 volumio ifup[487]: command failed: No such device (-19) Apr 13 14:59:34 volumio systemd[1]: Starting Save/Restore Sound Card State... Apr 13 14:59:34 volumio systemd[1]: Starting Login Service... Apr 13 14:59:34 volumio systemd[1]: Condition check resulted in Copy user wpa_supplicant.conf being skipped. Apr 13 14:59:34 volumio systemd[1]: Starting dhcpcd on all interfaces... Apr 13 14:59:34 volumio systemd[1]: Starting Volumio Time Update Utility... Apr 13 14:59:34 volumio systemd[1]: Started Volumio Iptables Module. Apr 13 14:59:34 volumio systemd[1]: Started D-Bus System Message Bus. Apr 13 14:59:34 volumio volumio-time-update[532]: volumio-time-update-util: Fetching time from Volumio... Apr 13 14:59:34 volumio systemd[1]: Starting WPA supplicant... Apr 13 14:59:34 volumio systemd[1]: Condition check resulted in Volumio SSH enabler being skipped. Apr 13 14:59:34 volumio dhcpcd[530]: Not running dhcpcd because /etc/network/interfaces Apr 13 14:59:34 volumio dhcpcd[530]: defines some interfaces that will use a Apr 13 14:59:34 volumio dhcpcd[530]: DHCP client or static address Apr 13 14:59:34 volumio systemd[1]: Starting LSB: Load kernel modules needed to enable cpufreq scaling... Apr 13 14:59:34 volumio systemd[1]: Starting Avahi mDNS/DNS-SD Stack... Apr 13 14:59:34 volumio systemd[1]: Starting triggerhappy global hotkey daemon... Apr 13 14:59:34 volumio systemd[1]: Started Save/Restore Sound Card State. Apr 13 14:59:34 volumio systemd[1]: dhcpcd.service: Control process exited, code=exited, status=6/NOTCONFIGURED Apr 13 14:59:34 volumio systemd[1]: dhcpcd.service: Failed with result 'exit-code'. Apr 13 14:59:34 volumio systemd[1]: Failed to start dhcpcd on all interfaces. Apr 13 14:59:34 volumio systemd[1]: Reached target Sound Card. Apr 13 14:59:34 volumio thd[550]: Unable to parse trigger line: Apr 13 14:59:34 volumio thd[550]: Unable to parse trigger line: KEY_MIN_INTERESTING 1 /usr/local/bin/volumio volume toggle Apr 13 14:59:34 volumio thd[550]: Unable to parse trigger line: Apr 13 14:59:34 volumio thd[550]: Found socket passed from systemd Apr 13 14:59:34 volumio systemd-logind[529]: New seat seat0. Apr 13 14:59:34 volumio mpd_monitor.sh[519]: MPD error: Cannot assign requested address Apr 13 14:59:34 volumio mpd_monitor.sh[519]: mpd: no process found Apr 13 14:59:34 volumio ifup[487]: command failed: No such device (-19) Apr 13 14:59:34 volumio avahi-daemon[549]: Found user 'avahi' (UID 110) and group 'avahi' (GID 113). Apr 13 14:59:34 volumio avahi-daemon[549]: Successfully dropped root privileges. Apr 13 14:59:34 volumio avahi-daemon[549]: avahi-daemon 0.7 starting up. Apr 13 14:59:34 volumio volumio-remote-updater[518]: Error: No active session Apr 13 14:59:34 volumio volumio-remote-updater[518]: [2025-04-13 14:59:34] [info] asio async_connect error: system:111 (Connection refused) Apr 13 14:59:34 volumio volumio-remote-updater[518]: [2025-04-13 14:59:34] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Apr 13 14:59:34 volumio volumio-remote-updater[518]: [2025-04-13 14:59:34] [error] handle_connect error: Underlying Transport Error Apr 13 14:59:35 volumio kernel: 8021q: 802.1Q VLAN Support v1.8 Apr 13 14:59:35 volumio volumio-time-update[532]: volumio-time-update-util: Date not found in response Apr 13 14:59:35 volumio volumio-time-update[532]: volumio-time-update-util: Retrying in 5 seconds... Apr 13 14:59:35 volumio avahi-daemon[549]: Successfully called chroot(). Apr 13 14:59:35 volumio avahi-daemon[549]: Successfully dropped remaining capabilities. Apr 13 14:59:35 volumio volumio[510]: Could not open config: /tmp/upmpdcli.conf Apr 13 14:59:35 volumio avahi-daemon[549]: No service file found in /etc/avahi/services. Apr 13 14:59:35 volumio avahi-daemon[549]: Network interface enumeration completed. Apr 13 14:59:35 volumio avahi-daemon[549]: Server startup complete. Host name is volumio.local. Local service cookie is 1392211067. Apr 13 14:59:35 volumio systemd[1]: Started Avahi mDNS/DNS-SD Stack. Apr 13 14:59:35 volumio haveged[508]: haveged: ver: 1.9.1; arch: generic; vend: ; build: (gcc 8.2.0 CTV); collect: 128K Apr 13 14:59:35 volumio haveged[508]: haveged: cpu: (VC); data: 16K (D); inst: 16K (D); idx: 11/40; sz: 14768/63488 Apr 13 14:59:35 volumio haveged[508]: haveged: tot tests(BA8): A:1/1 B:1/1 continuous tests(B): last entropy estimate 8.00055 Apr 13 14:59:35 volumio haveged[508]: haveged: fills: 0, generated: 0 Apr 13 14:59:35 volumio systemd[1]: Started triggerhappy global hotkey daemon. Apr 13 14:59:35 volumio systemd[1]: upmpdcli.service: Main process exited, code=exited, status=1/FAILURE Apr 13 14:59:35 volumio systemd[1]: upmpdcli.service: Failed with result 'exit-code'. Apr 13 14:59:35 volumio wpa_supplicant[543]: Successfully initialized wpa_supplicant Apr 13 14:59:35 volumio systemd[1]: Started Login Service. Apr 13 14:59:35 volumio systemd[1]: Started WPA supplicant. Apr 13 14:59:35 volumio kernel: ax88179_178a 1-1.3:1.0 eth0: Current addr: 00 17 f7 00 ac 2a 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Apr 13 14:59:35 volumio kernel: ax88179_178a 1-1.3:1.0 eth0: Expected addr: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Apr 13 14:59:35 volumio kernel: ------------[ cut here ]------------ Apr 13 14:59:35 volumio kernel: WARNING: CPU: 1 PID: 574 at net/core/dev_addr_lists.c:519 dev_addr_check+0x108/0x138 Apr 13 14:59:35 volumio kernel: netdevice: eth0: Incorrect netdev->dev_addr Apr 13 14:59:35 volumio kernel: Modules linked in: nf_defrag_ipv6 nf_defrag_ipv4 xt_tcpudp nft_compat nf_tables nfnetlink 8021q garp stp llc cfg80211 rfkill snd_usb_audio snd_hwdep snd_usbmidi_lib snd_seq_midi snd_seq_midi_event bcm2835_codec(C) bcm2835_isp(C) bcm2835_v4l2(C) snd_rawmidi v4l2_mem2mem bcm2835_mmal_vchiq(C) snd_bcm2835(C) videobuf2_vmalloc videobuf2_dma_contig videobuf2_memops ax88179_178a videobuf2_v4l2 snd_pcm snd_seq videodev videobuf2_common snd_seq_device snd_timer mc raspberrypi_hwmon vc_sm_cma(C) snd raspberrypi_gpiomem uio_pdrv_genirq uio i2c_dev ip_tables x_tables ipv6 uas squashfs overlay nls_iso8859_1 fuse i2c_bcm2835 fixed Apr 13 14:59:35 volumio kernel: CPU: 1 PID: 574 Comm: dhcpcd Tainted: G C 6.6.62-v7+ #1816 Apr 13 14:59:35 volumio kernel: Hardware name: BCM2835 Apr 13 14:59:35 volumio kernel: unwind_backtrace from show_stack+0x18/0x1c Apr 13 14:59:35 volumio kernel: show_stack from dump_stack_lvl+0x50/0x68 Apr 13 14:59:35 volumio kernel: dump_stack_lvl from __warn+0x84/0x11c Apr 13 14:59:35 volumio kernel: __warn from warn_slowpath_fmt+0x11c/0x190 Apr 13 14:59:35 volumio kernel: warn_slowpath_fmt from dev_addr_check+0x108/0x138 Apr 13 14:59:35 volumio kernel: dev_addr_check from __dev_open+0x40/0x1d0 Apr 13 14:59:35 volumio kernel: __dev_open from __dev_change_flags+0x194/0x210 Apr 13 14:59:35 volumio kernel: __dev_change_flags from dev_change_flags+0x20/0x5c Apr 13 14:59:35 volumio kernel: dev_change_flags from devinet_ioctl+0x790/0x7c4 Apr 13 14:59:35 volumio kernel: devinet_ioctl from inet_ioctl+0x1a4/0x224 Apr 13 14:59:35 volumio kernel: inet_ioctl from sock_ioctl+0x4ac/0x568 Apr 13 14:59:35 volumio kernel: sock_ioctl from sys_ioctl+0x110/0xa20 Apr 13 14:59:35 volumio kernel: sys_ioctl from ret_fast_syscall+0x0/0x4c Apr 13 14:59:35 volumio kernel: Exception stack(0xb8b35fa8 to 0xb8b35ff0) Apr 13 14:59:35 volumio kernel: 5fa0: 01d68c68 00001043 00000007 00008914 7ef099e4 7ef09ac0 Apr 13 14:59:35 volumio kernel: 5fc0: 01d68c68 00001043 0005dca0 00000036 431bde83 000f423f 3b9aca00 01d63660 Apr 13 14:59:35 volumio kernel: 5fe0: 0005dea4 7ef099dc 0001ba6c 76f21e3c Apr 13 14:59:35 volumio kernel: ---[ end trace 0000000000000000 ]--- Apr 13 14:59:35 volumio systemd[1]: Listening on mpd.socket. Apr 13 14:59:35 volumio systemd[1]: Started Raise network interfaces. Apr 13 14:59:35 volumio systemd[1]: Reached target Network. Apr 13 14:59:35 volumio systemd[1]: Condition check resulted in fast remote file copy program daemon being skipped. Apr 13 14:59:35 volumio systemd[1]: Starting Permit User Sessions... Apr 13 14:59:35 volumio systemd[1]: Starting Music Player Daemon... Apr 13 14:59:35 volumio systemd[1]: Starting Network Time Service... Apr 13 14:59:35 volumio systemd[1]: Reached target Network is Online. Apr 13 14:59:35 volumio systemd[1]: Starting /etc/rc.local Compatibility... Apr 13 14:59:35 volumio loadcpufreq[547]: Loading cpufreq kernel modules...done (none). Apr 13 14:59:35 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 14:59:35 volumio systemd[1]: Starting Samba NMB Daemon... Apr 13 14:59:35 volumio systemd[1]: Starting LSB: Brings up/down network automatically... Apr 13 14:59:35 volumio systemd[1]: Started LSB: Load kernel modules needed to enable cpufreq scaling. Apr 13 14:59:35 volumio systemd[1]: iptables.service: Succeeded. Apr 13 14:59:35 volumio systemd[1]: Started Permit User Sessions. Apr 13 14:59:35 volumio systemd[1]: Started /etc/rc.local Compatibility. Apr 13 14:59:35 volumio sh[490]: eth0: waiting for carrier Apr 13 14:59:35 volumio sh[490]: eth0: carrier acquired Apr 13 14:59:35 volumio dhcpcd[574]: eth0: waiting for carrier Apr 13 14:59:35 volumio dhcpcd[574]: eth0: carrier acquired Apr 13 14:59:35 volumio dhcpcd[574]: DUID 00:01:00:01:2e:7c:57:94:00:17:f7:00:ac:2a Apr 13 14:59:35 volumio systemd[1]: Starting Terminate Plymouth Boot Screen... Apr 13 14:59:35 volumio sh[490]: DUID 00:01:00:01:2e:7c:57:94:00:17:f7:00:ac:2a Apr 13 14:59:35 volumio sh[490]: eth0: IAID f7:00:ac:2a Apr 13 14:59:35 volumio dhcpcd[574]: eth0: IAID f7:00:ac:2a Apr 13 14:59:35 volumio sh[490]: eth0: adding address fe80::f2df:522f:1b77:dbb5 Apr 13 14:59:35 volumio sh[490]: ipv6_addaddr1: Permission denied Apr 13 14:59:35 volumio sh[490]: eth0: carrier lost Apr 13 14:59:35 volumio dhcpcd[574]: eth0: adding address fe80::f2df:522f:1b77:dbb5 Apr 13 14:59:35 volumio dhcpcd[574]: ipv6_addaddr1: Permission denied Apr 13 14:59:35 volumio dhcpcd[574]: eth0: carrier lost Apr 13 14:59:35 volumio systemd[1]: Starting Hold until boot process finishes up... Apr 13 14:59:35 volumio systemd[1]: Starting LSB: set CPUFreq kernel parameters... Apr 13 14:59:36 volumio systemd[1]: Received SIGRTMIN+21 from PID 193 (plymouthd). Apr 13 14:59:36 volumio systemd[1]: plymouth-quit.service: Succeeded. Apr 13 14:59:36 volumio systemd[1]: Started Terminate Plymouth Boot Screen. Apr 13 14:59:36 volumio systemd[1]: plymouth-quit-wait.service: Succeeded. Apr 13 14:59:36 volumio systemd[1]: Started Hold until boot process finishes up. Apr 13 14:59:36 volumio systemd[1]: Received SIGRTMIN+21 from PID 193 (n/a). Apr 13 14:59:36 volumio ifplugd(eth0)[716]: ifplugd 0.28 initializing. Apr 13 14:59:36 volumio ifplugd(eth0)[716]: Using interface eth0/00:17:F7:00:AC:2A with driver (version: v2.0.0) Apr 13 14:59:36 volumio ifplugd(eth0)[716]: Using detection mode: SIOCETHTOOL Apr 13 14:59:36 volumio ifplugd(eth0)[716]: Initialization complete, link beat not detected. Apr 13 14:59:36 volumio systemd[1]: Started Serial Getty on ttyAMA0. Apr 13 14:59:36 volumio systemd[1]: Started Getty on tty1. Apr 13 14:59:36 volumio systemd[1]: Reached target Login Prompts. Apr 13 14:59:36 volumio ifplugd[676]: Network Interface Plugging Daemon...start eth0...done. Apr 13 14:59:36 volumio systemd[1]: Started LSB: Brings up/down network automatically. Apr 13 14:59:36 volumio cpufrequtils[684]: CPUFreq Utilities: Setting ondemand CPUFreq governor...CPU0...CPU1...CPU2...CPU3...done. Apr 13 14:59:36 volumio systemd[1]: Started LSB: set CPUFreq kernel parameters. Apr 13 14:59:36 volumio ntpd[671]: ntpd 4.2.8p12@1.3728-o (1): Starting Apr 13 14:59:36 volumio ntpd[671]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g -u 103:103 Apr 13 14:59:36 volumio systemd[1]: Started Network Time Service. Apr 13 14:59:36 volumio ntpd[729]: proto: precision = 0.677 usec (-20) Apr 13 14:59:36 volumio ntpd[729]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): good hash signature Apr 13 14:59:36 volumio ntpd[729]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): loaded, expire=2024-12-28T00:00:00Z last=2017-01-01T00:00:00Z ofs=37 Apr 13 14:59:36 volumio ntpd[729]: leapsecond file ('/usr/share/zoneinfo/leap-seconds.list'): expired less than 107 days ago Apr 13 14:59:36 volumio ntpd[729]: Listen and drop on 0 v6wildcard [::]:123 Apr 13 14:59:36 volumio ntpd[729]: Listen and drop on 1 v4wildcard 0.0.0.0:123 Apr 13 14:59:36 volumio ntpd[729]: Listen normally on 2 lo 127.0.0.1:123 Apr 13 14:59:36 volumio ntpd[729]: Listening on routing socket on fd #19 for interface updates Apr 13 14:59:36 volumio ntpd[729]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 13 14:59:36 volumio ntpd[729]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized Apr 13 14:59:36 volumio sudo[669]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 13 14:59:36 volumio sudo[669]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:36 volumio sudo[669]: /bin/chown: cannot access '/var/log/mpd.log': No such file or directory Apr 13 14:59:36 volumio sudo[669]: pam_unix(sudo:session): session closed for user root Apr 13 14:59:37 volumio ntpd[729]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Apr 13 14:59:37 volumio nmbd[678]: [2025/04/13 14:59:37.793359, 0] ../source3/nmbd/asyncdns.c:158(start_async_dns) Apr 13 14:59:37 volumio nmbd[678]: started asyncdns process 734 Apr 13 14:59:37 volumio nmbd[678]: [2025/04/13 14:59:37.796269, 0] ../lib/util/become_daemon.c:149(daemon_status) Apr 13 14:59:37 volumio nmbd[678]: daemon_status: STATUS=daemon 'nmbd' : No local IPv4 non-loopback interfaces available, waiting for interface ... Apr 13 14:59:37 volumio nmbd[678]: [2025/04/13 14:59:37.796511, 0] ../source3/nmbd/nmbd_subnetdb.c:254(create_subnets) Apr 13 14:59:37 volumio nmbd[678]: NOTE: NetBIOS name resolution is not supported for Internet Protocol Version 6 (IPv6). Apr 13 14:59:38 volumio wireless.js[523]: WIRELESS: No wireless interface, exiting Apr 13 14:59:38 volumio ntpd[729]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Apr 13 14:59:38 volumio iw[739]: command failed: No such device (-19) Apr 13 14:59:38 volumio iwconfig[742]: Error for wireless request "Set Power Management" (8B2C) : Apr 13 14:59:38 volumio iwconfig[742]: SET failed on device wlan0 ; No such device. Apr 13 14:59:38 volumio systemd[1]: wireless.service: Succeeded. Apr 13 14:59:38 volumio systemd[1]: Started Wireless Services. Apr 13 14:59:38 volumio systemd[1]: Started Volumio Backend Module. Apr 13 14:59:38 volumio systemd[1]: Started Volumio Cpu Tweaker. Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: Setting RT Priority for mpd Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: pid 35's current scheduling policy: SCHED_OTHER Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: pid 35's current scheduling priority: 0 Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: Setting MPD Affinity Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: pid 3's current affinity mask: f Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: /bin/volumio_cpu_tweak: line 27: warning: command substitution: ignored null byte in input Apr 13 14:59:38 volumio volumio-cpu-tweak[746]: VOLUMIO CPU TWEAK: Setting CPU Governor: conservative Apr 13 14:59:38 volumio sh[490]: eth0: carrier acquired Apr 13 14:59:38 volumio dhcpcd[574]: eth0: carrier acquired Apr 13 14:59:38 volumio kernel: ax88179_178a 1-1.3:1.0 eth0: link up, 1000Mbps, full-duplex, lpa 0xC5E1 Apr 13 14:59:38 volumio systemd[1]: volumio_cpu_tweak.service: Succeeded. Apr 13 14:59:38 volumio sh[490]: eth0: IAID f7:00:ac:2a Apr 13 14:59:38 volumio dhcpcd[574]: eth0: IAID f7:00:ac:2a Apr 13 14:59:39 volumio sh[490]: eth0: soliciting a DHCP lease Apr 13 14:59:39 volumio dhcpcd[574]: eth0: soliciting a DHCP lease Apr 13 14:59:39 volumio sh[490]: eth0: offered 192.168.1.127 from 192.168.1.1 Apr 13 14:59:39 volumio dhcpcd[574]: eth0: offered 192.168.1.127 from 192.168.1.1 Apr 13 14:59:39 volumio sh[490]: eth0: probing address 192.168.1.127/24 Apr 13 14:59:39 volumio dhcpcd[574]: eth0: probing address 192.168.1.127/24 Apr 13 14:59:39 volumio ifplugd(eth0)[716]: Link beat detected. Apr 13 14:59:39 volumio sh[490]: eth0: soliciting an IPv6 router Apr 13 14:59:39 volumio dhcpcd[574]: eth0: soliciting an IPv6 router Apr 13 14:59:39 volumio ntpd[729]: error resolving pool 2.debian.pool.ntp.org: System error (-11) Apr 13 14:59:39 volumio ifplugd(eth0)[716]: Executing '/etc/ifplugd/ifplugd.action eth0 up'. Apr 13 14:59:39 volumio ifplugd(eth0)[716]: client: ifup: waiting for lock on /run/network/ifstate.eth0 Apr 13 14:59:39 volumio volumio-remote-updater[518]: [2025-04-13 14:59:39] [info] asio async_connect error: system:111 (Connection refused) Apr 13 14:59:39 volumio volumio-remote-updater[518]: [2025-04-13 14:59:39] [info] Error getting remote endpoint: system:107 (Transport endpoint is not connected) Apr 13 14:59:39 volumio volumio-remote-updater[518]: [2025-04-13 14:59:39] [error] handle_connect error: Underlying Transport Error Apr 13 14:59:40 volumio volumio-time-update[532]: volumio-time-update-util: Fetching time from Volumio... Apr 13 14:59:40 volumio volumio-time-update[532]: volumio-time-update-util: Date not found in response Apr 13 14:59:40 volumio volumio-time-update[532]: volumio-time-update-util: Retrying in 5 seconds... Apr 13 14:59:40 volumio ntpd[729]: error resolving pool 3.debian.pool.ntp.org: System error (-11) Apr 13 14:59:41 volumio mpd[732]: Apr 13 14:59 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 13 14:59:42 volumio systemd[1]: Started Music Player Daemon. Apr 13 14:59:42 volumio mpd_monitor.sh[519]: MPD restarted due to no mpc output. Apr 13 14:59:42 volumio volumio[745]: info: ------------------------------------------- Apr 13 14:59:42 volumio volumio[745]: info: ----- Volumio3 ---- Apr 13 14:59:42 volumio volumio[745]: info: ------------------------------------------- Apr 13 14:59:42 volumio volumio[745]: info: ----- System startup ---- Apr 13 14:59:42 volumio volumio[745]: info: ------------------------------------------- Apr 13 14:59:43 volumio volumio[745]: info: MYVOLUMIO Environment detected Apr 13 14:59:43 volumio volumio[745]: info: Plugin folders cleanup Apr 13 14:59:43 volumio volumio[745]: info: Scanning into folder /volumio/app/plugins/ Apr 13 14:59:43 volumio volumio[745]: info: Scanning category audio_interface Apr 13 14:59:43 volumio volumio[745]: info: Scanning category miscellanea Apr 13 14:59:43 volumio volumio[745]: info: Scanning category music_service Apr 13 14:59:43 volumio volumio[745]: info: Scanning category plugins.json Apr 13 14:59:43 volumio volumio[745]: info: Scanning category system_controller Apr 13 14:59:43 volumio volumio[745]: info: Scanning category user_interface Apr 13 14:59:43 volumio volumio[745]: info: Scanning into folder /data/plugins/ Apr 13 14:59:43 volumio volumio[745]: info: Scanning category music_service Apr 13 14:59:43 volumio volumio[745]: info: Plugin folders cleanup completed Apr 13 14:59:43 volumio volumio[745]: info: ------------------------------------------- Apr 13 14:59:43 volumio volumio[745]: info: ----- Core plugins startup ---- Apr 13 14:59:43 volumio volumio[745]: info: ------------------------------------------- Apr 13 14:59:43 volumio volumio[745]: info: Loading plugins from folder /volumio/app/plugins/ Apr 13 14:59:43 volumio volumio[745]: info: Adding plugin upnp to MyMusic Plugins Apr 13 14:59:43 volumio volumio[745]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 13 14:59:43 volumio volumio[745]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 13 14:59:43 volumio volumio[745]: info: Loading plugins from folder /data/plugins/ Apr 13 14:59:43 volumio volumio[745]: info: Loading plugin "system"... Apr 13 14:59:43 volumio volumio[745]: info: Loading plugin "appearance"... Apr 13 14:59:44 volumio sh[490]: eth0: leased 192.168.1.127 for 86400 seconds Apr 13 14:59:44 volumio dhcpcd[574]: eth0: leased 192.168.1.127 for 86400 seconds Apr 13 14:59:44 volumio sh[490]: eth0: adding route to 192.168.1.0/24 Apr 13 14:59:44 volumio sh[490]: eth0: adding default route via 192.168.1.1 Apr 13 14:59:44 volumio avahi-daemon[549]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.1.127. Apr 13 14:59:44 volumio avahi-daemon[549]: New relevant interface eth0.IPv4 for mDNS. Apr 13 14:59:44 volumio avahi-daemon[549]: Registering new address record for 192.168.1.127 on eth0.IPv4. Apr 13 14:59:44 volumio dhcpcd[574]: eth0: adding route to 192.168.1.0/24 Apr 13 14:59:44 volumio dhcpcd[574]: eth0: adding default route via 192.168.1.1 Apr 13 14:59:44 volumio sh[490]: forked to background, child pid 809 Apr 13 14:59:44 volumio dhcpcd[574]: forked to background, child pid 809 Apr 13 14:59:44 volumio ifplugd(eth0)[716]: client: ifup: interface eth0 already configured Apr 13 14:59:44 volumio sh[490]: eth0=eth0 Apr 13 14:59:44 volumio ifplugd(eth0)[716]: Program executed successfully. Apr 13 14:59:45 volumio volumio-time-update[532]: volumio-time-update-util: Fetching time from Volumio... Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "network"... Apr 13 14:59:45 volumio volumio[745]: info: Refreshing Cached IP Addresses Apr 13 14:59:45 volumio sudo[840]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 13 14:59:45 volumio sudo[840]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:45 volumio sudo[842]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 14:59:45 volumio sudo[840]: pam_unix(sudo:session): session closed for user root Apr 13 14:59:45 volumio sudo[842]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "services"... Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "alsa_controller"... Apr 13 14:59:45 volumio sudo[851]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 13 14:59:45 volumio sudo[851]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:45 volumio sudo[842]: pam_unix(sudo:session): session closed for user root Apr 13 14:59:45 volumio sudo[851]: pam_unix(sudo:session): session closed for user root Apr 13 14:59:45 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "wizard"... Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "networkfs"... Apr 13 14:59:45 volumio sudo[872]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Wszyscy,password=,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.105/MUSIC /mnt/NAS/Music Apr 13 14:59:45 volumio sudo[872]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:45 volumio volumio[745]: info: Starting Udev Watcher for removable devices Apr 13 14:59:45 volumio sudo[874]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Wszyscy,password=,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.105/LIBRARY /mnt/NAS/Library Apr 13 14:59:45 volumio sudo[874]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:45 volumio volumio[745]: info: Ignoring mount for partition: boot Apr 13 14:59:45 volumio volumio[745]: info: Ignoring mount for partition: volumio Apr 13 14:59:45 volumio volumio[745]: info: Ignoring mount for partition: volumio_data Apr 13 14:59:45 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "volumio_command_line_client"... Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "upnp"... Apr 13 14:59:45 volumio volumio-time-update[532]: volumio-time-update-util: Setting system time to: 2025-04-13 15:00:06 Apr 13 14:59:45 volumio sudo[885]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/timedatectl set-time 2025-04-13 15:00:06 Apr 13 14:59:45 volumio sudo[885]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 14:59:45 volumio volumio[745]: info: [1744549185765] Starting Upmpd Daemon Apr 13 14:59:45 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "my_music"... Apr 13 14:59:45 volumio volumio[745]: info: Loading plugin "mpd"... Apr 13 14:59:45 volumio dbus-daemon[537]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.5' (uid=0 pid=886 comm="timedatectl set-time 2025-04-13 15:00:06 ") Apr 13 14:59:45 volumio kernel: Key type cifs.spnego registered Apr 13 14:59:45 volumio kernel: Key type cifs.idmap registered Apr 13 14:59:45 volumio kernel: CIFS: No dialect specified on mount. Default has changed to a more secure dialect, SMB2.1 or later (e.g. SMB3.1.1), from CIFS (SMB1). To use the less secure SMB1 dialect to access old servers which do not support SMB3.1.1 (or even SMB3 or SMB2.1) specify vers=1.0 on mount. Apr 13 14:59:45 volumio kernel: CIFS: Attempting to mount //192.168.1.105/MUSIC Apr 13 14:59:45 volumio systemd[1]: Starting Time & Date Service... Apr 13 14:59:46 volumio dbus-daemon[537]: [system] Successfully activated service 'org.freedesktop.timedate1' Apr 13 14:59:46 volumio systemd[1]: Started Time & Date Service. Apr 13 15:00:06 volumio systemd-timedated[888]: Changed local time to Sun Apr 13 15:00:06 2025 Apr 13 15:00:06 volumio sudo[885]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:06 volumio volumio-time-update[532]: volumio-time-update-util: System time updated successfully. Apr 13 15:00:06 volumio systemd[1]: Started Volumio Time Update Utility. Apr 13 15:00:06 volumio volumio[745]: info: Loading plugin "upnp_browser"... Apr 13 15:00:06 volumio ntpd[729]: Listen normally on 3 eth0 192.168.1.127:123 Apr 13 15:00:06 volumio ntpd[729]: new interface(s) found: waking up resolver Apr 13 15:00:06 volumio volumio[745]: info: Loading plugin "alarm-clock"... Apr 13 15:00:06 volumio volumio[745]: info: Loading plugin "airplay_emulation"... Apr 13 15:00:06 volumio volumio[745]: info: Starting Shairport Sync Apr 13 15:00:06 volumio volumio[745]: info: Loading plugin "last_100"... Apr 13 15:00:06 volumio volumio[745]: info: Loading plugin "webradio"... Apr 13 15:00:07 volumio volumio[745]: info: Loading plugin "i2s_dacs"... Apr 13 15:00:07 volumio volumio[745]: info: I2S DAC not set, start Auto-detection Apr 13 15:00:07 volumio volumio[745]: info: Loading plugin "volumiodiscovery"... Apr 13 15:00:07 volumio volumio[745]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 13 15:00:07 volumio volumio[745]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 15:00:07 volumio volumio[745]: *** WARNING *** For more information see Apr 13 15:00:07 volumio volumio[745]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 13 15:00:07 volumio node[745]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 13 15:00:07 volumio volumio[745]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 15:00:07 volumio volumio[745]: *** WARNING *** For more information see Apr 13 15:00:07 volumio node[745]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 15:00:07 volumio node[745]: *** WARNING *** For more information see Apr 13 15:00:07 volumio node[745]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 13 15:00:07 volumio node[745]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 13 15:00:07 volumio node[745]: *** WARNING *** For more information see Apr 13 15:00:07 volumio volumio[745]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 13 15:00:07 volumio volumio[745]: info: Discovery: Started advertising with name: Volumio Apr 13 15:00:07 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 13 15:00:07 volumio volumio[745]: info: Loading plugin "spop"... Apr 13 15:00:07 volumio volumio-remote-updater[518]: [2025-04-13 15:00:07] [connect] Successful connection Apr 13 15:00:07 volumio nmbd[678]: [2025/04/13 15:00:07.692274, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 13 15:00:07 volumio nmbd[678]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Apr 13 15:00:07 volumio systemd[1]: Started Samba NMB Daemon. Apr 13 15:00:07 volumio systemd[1]: Starting Samba Winbind Daemon... Apr 13 15:00:08 volumio winbindd[900]: [2025/04/13 15:00:08.070212, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Apr 13 15:00:08 volumio winbindd[900]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Apr 13 15:00:08 volumio winbindd[900]: [2025/04/13 15:00:08.102757, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 13 15:00:08 volumio systemd[1]: Started Samba Winbind Daemon. Apr 13 15:00:08 volumio winbindd[900]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Apr 13 15:00:08 volumio systemd[1]: Starting Samba SMB Daemon... Apr 13 15:00:08 volumio smbd[905]: [2025/04/13 15:00:08.729563, 0] ../lib/util/become_daemon.c:138(daemon_ready) Apr 13 15:00:08 volumio smbd[905]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Apr 13 15:00:08 volumio systemd[1]: Started Samba SMB Daemon. Apr 13 15:00:08 volumio systemd[1]: Reached target Multi-User System. Apr 13 15:00:08 volumio systemd[1]: Reached target Graphical Interface. Apr 13 15:00:08 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Apr 13 15:00:08 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Apr 13 15:00:08 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Apr 13 15:00:08 volumio systemd[1]: Startup finished in 14.001s (kernel) + 19.326s (userspace) = 33.327s. Apr 13 15:00:09 volumio volumio[745]: info: Loading plugin "outputs"... Apr 13 15:00:09 volumio volumio[745]: info: Loading plugin "albumart"... Apr 13 15:00:09 volumio volumio[745]: info: Plugin example_plugin is not enabled Apr 13 15:00:09 volumio volumio[745]: info: Loading plugin "inputs"... Apr 13 15:00:09 volumio volumio[745]: info: Loading plugin "updater_comm"... Apr 13 15:00:09 volumio volumio[745]: info: Plugin mpdemulation is not enabled Apr 13 15:00:09 volumio volumio[745]: info: Loading plugin "rest_api"... Apr 13 15:00:09 volumio volumio[745]: info: Loading plugin "websocket"... Apr 13 15:00:09 volumio volumio[745]: info: Starting Socket.io Server version 2.3.0 Apr 13 15:00:09 volumio volumio[745]: info: Loading i18n strings for locale en Apr 13 15:00:09 volumio volumio[745]: Updating browse sources language Apr 13 15:00:09 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 15:00:09 volumio volumio[745]: Forking 3 albumart workers Apr 13 15:00:09 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 15:00:09 volumio volumio[745]: info: CoreCommandRouter::initPlayerControls Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 15:00:10 volumio volumio[745]: Express server listening on port 3000 Apr 13 15:00:10 volumio volumio[745]: [Metrics] WebUI: 9s 33.79ms Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::resetVolumioState Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::getcurrentVolume Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::volumioRetrievevolume Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:10 volumio volumio[745]: info: Volumio Network Manager: Network status updated: 1 Apr 13 15:00:10 volumio volumio[745]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Apr 13 15:00:10 volumio volumio[745]: wlan0 Interface doesn't support scanning. Apr 13 15:00:10 volumio volumio[745]: info: Cannot use regular scanning, forcing with ap-force Apr 13 15:00:10 volumio sudo[947]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Apr 13 15:00:10 volumio sudo[947]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:10 volumio sudo[947]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:10 volumio volumio[745]: command failed: No such device (-19) Apr 13 15:00:10 volumio volumio[745]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Apr 13 15:00:10 volumio volumio[745]: command failed: No such device (-19) Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Apr 13 15:00:10 volumio volumio-remote-updater[518]: [2025-04-13 15:00:10] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1744549207 101 Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 2 Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Apr 13 15:00:10 volumio volumio[745]: info: Reloading queue from file Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::setRepeat null single undefined Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::pushState Apr 13 15:00:10 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::volumioPushState Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::setRandom false Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::pushState Apr 13 15:00:10 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::volumioPushState Apr 13 15:00:10 volumio volumio[745]: info: Setting Device type: Raspberry PI Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Apr 13 15:00:10 volumio volumio[745]: info: VolumeController:: Volume=100 Mute =false Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::pushState Apr 13 15:00:10 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::volumioPushState Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::updateTrackBlock Apr 13 15:00:10 volumio volumio[745]: info: CorePlayQueue::getTrackBlock Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::volumioRetrievevolume Apr 13 15:00:10 volumio volumio[745]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Apr 13 15:00:10 volumio volumio[745]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a02100 Apr 13 15:00:10 volumio volumio[745]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Apr 13 15:00:10 volumio volumio[745]: Starting albumart workers Apr 13 15:00:10 volumio volumio[745]: Starting albumart workers Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Apr 13 15:00:10 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Apr 13 15:00:10 volumio volumio[745]: Starting albumart workers Apr 13 15:00:10 volumio volumio[745]: info: VolumeController:: Volume=100 Mute =false Apr 13 15:00:10 volumio volumio[745]: info: CoreStateMachine::pushState Apr 13 15:00:10 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:10 volumio volumio[745]: info: CoreCommandRouter::volumioPushState Apr 13 15:00:11 volumio volumio[745]: verbose: New Socket.io Connection to 192.168.1.127 from 192.168.1.165 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/135.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Apr 13 15:00:11 volumio volumio[745]: info: CoreCommandRouter::volumioGetState Apr 13 15:00:11 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:11 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 13 15:00:11 volumio volumio[745]: info: Listing playlists Apr 13 15:00:11 volumio volumio[745]: info: CoreCommandRouter::volumioGetQueue Apr 13 15:00:11 volumio volumio[745]: info: CoreStateMachine::getQueue Apr 13 15:00:11 volumio volumio[745]: info: CorePlayQueue::getQueue Apr 13 15:00:12 volumio volumio[745]: info: Discovery: adding 9a1fc2c9-ee0a-4d3a-82a0-1a5735d306f9 Apr 13 15:00:12 volumio volumio[745]: info: Discovery: Found device Volumio Apr 13 15:00:12 volumio volumio[745]: info: CoreCommandRouter::volumioGetState Apr 13 15:00:12 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:12 volumio sudo[872]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:12 volumio volumio[745]: info: Cannot mount NAS Music at system boot, trial number 1 ,retrying in 5 seconds Apr 13 15:00:12 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Apr 13 15:00:12 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Apr 13 15:00:12 volumio kernel: CIFS: Attempting to mount //192.168.1.105/LIBRARY Apr 13 15:00:15 volumio sudo[1001]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 13 15:00:15 volumio sudo[1001]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:15 volumio sudo[1001]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:15 volumio sudo[1003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 13 15:00:15 volumio sudo[1003]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:15 volumio sudo[1007]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 13 15:00:15 volumio sudo[1003]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:15 volumio sudo[1007]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:15 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Apr 13 15:00:15 volumio sudo[1007]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:15 volumio volumio[745]: info: Upmpdcli Daemon Started Apr 13 15:00:15 volumio volumio[1011]: Generating RSA private key, 4096 bit long modulus (2 primes) Apr 13 15:00:17 volumio sudo[1028]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Wszyscy,password=,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.105/MUSIC /mnt/NAS/Music Apr 13 15:00:17 volumio sudo[1028]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:18 volumio sudo[874]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:18 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Apr 13 15:00:18 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Apr 13 15:00:18 volumio kernel: CIFS: Attempting to mount //192.168.1.105/MUSIC Apr 13 15:00:18 volumio volumio[745]: info: Cannot mount NAS Library at system boot, trial number 1 ,retrying in 5 seconds Apr 13 15:00:18 volumio volumio[745]: info: Completed loading Core Plugins Apr 13 15:00:18 volumio volumio[745]: info: Preparing to generate the ALSA configuration file Apr 13 15:00:18 volumio volumio[745]: info: Asound.conf file unchanged, so no further update is needed Apr 13 15:00:18 volumio volumio[745]: info: Output device has changed, restarting MPD Apr 13 15:00:18 volumio volumio[745]: info: Output device has changed, restarting Shairport Sync Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:18 volumio sudo[1033]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:18 volumio sudo[1033]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:18 volumio sudo[1033]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:18 volumio sudo[1035]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 13 15:00:18 volumio sudo[1035]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:18 volumio systemd[1]: Stopping Music Player Daemon... Apr 13 15:00:18 volumio volumio[745]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 15:00:18 volumio volumio[745]: info: ___________ START PLUGINS ___________ Apr 13 15:00:18 volumio volumio[745]: info: ControllerMpd::onStart: Initializing MPD Apr 13 15:00:18 volumio volumio[745]: info: Creating MPD Configuration file Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 13 15:00:18 volumio sudo[1042]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 15:00:18 volumio volumio[745]: info: [1744549218474] CoreMusicLibrary::Adding element Media Servers Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 15:00:18 volumio sudo[1042]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:18 volumio sudo[1042]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:18 volumio sudo[1044]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 13 15:00:18 volumio sudo[1044]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:18 volumio volumio[745]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:18 volumio volumio[745]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 15:00:18 volumio volumio[745]: info: [1744549218624] CoreMusicLibrary::Adding element Last_100 Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 15:00:18 volumio volumio[745]: info: [1744549218628] CoreMusicLibrary::Adding element Webradio Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 15:00:18 volumio volumio[745]: info: Initializing BBC Radios Apr 13 15:00:18 volumio systemd[1]: mpd.service: Succeeded. Apr 13 15:00:18 volumio systemd[1]: Stopped Music Player Daemon. Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:18 volumio volumio[745]: info: Creating Spotify config file Apr 13 15:00:18 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:18 volumio systemd[1]: Starting Music Player Daemon... Apr 13 15:00:18 volumio volumio[745]: info: Volumio Calling Home Apr 13 15:00:18 volumio sudo[1056]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Apr 13 15:00:18 volumio sudo[1056]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:18 volumio sudo[1056]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:18 volumio volumio[745]: info: MPD Permissions set Apr 13 15:00:18 volumio volumio[745]: info: MPD Permissions set Apr 13 15:00:19 volumio volumio[745]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11 Apr 13 15:00:19 volumio volumio[745]: info: Spotify config file written Apr 13 15:00:19 volumio sudo[1071]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 13 15:00:19 volumio sudo[1071]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: No need to fix Spotify hosts Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 13 15:00:19 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 13 15:00:19 volumio systemd[1]: Started go-librespot Daemon. Apr 13 15:00:19 volumio volumio[745]: info: Starting Shairport Sync Apr 13 15:00:19 volumio go-librespot[1074]: Librespot-go daemon starting... Apr 13 15:00:19 volumio sudo[1071]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:19 volumio volumio[745]: info: Starting Shairport Sync Apr 13 15:00:19 volumio sudo[1084]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 15:00:19 volumio sudo[1084]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:19 volumio volumio[745]: info: Starting Shairport Sync Apr 13 15:00:19 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 13 15:00:19 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 13 15:00:19 volumio sudo[1087]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 15:00:19 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 13 15:00:19 volumio sudo[1087]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:19 volumio sudo[1089]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 13 15:00:19 volumio sudo[1089]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:19 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 15:00:19 volumio sudo[1084]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:19 volumio volumio[745]: info: Shairport-Sync Started Apr 13 15:00:19 volumio volumio[745]: Error adding Membership: Error: addMembership EINVAL Apr 13 15:00:19 volumio shairport-sync[1091]: free(): double free detected in tcache 2 Apr 13 15:00:19 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 13 15:00:19 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=6/ABRT Apr 13 15:00:19 volumio systemd[1]: shairport-sync.service: Failed with result 'signal'. Apr 13 15:00:19 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 13 15:00:19 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 13 15:00:19 volumio sudo[1089]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:19 volumio volumio[745]: info: Shairport-Sync Started Apr 13 15:00:19 volumio sudo[1087]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:19 volumio volumio[745]: info: Shairport-Sync Started Apr 13 15:00:19 volumio go-librespot[1074]: time="2025-04-13T15:00:19+02:00" level=info msg="generated new device id: 18c4bc5bc22375afee0651163a65bd470cb19417" Apr 13 15:00:19 volumio go-librespot[1074]: time="2025-04-13T15:00:19+02:00" level=debug msg="stored credentials found for tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:19 volumio volumio[745]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 13 15:00:19 volumio volumio[745]: SPOTIFY: BQCjzJX_j4Vts6Y3RiYo0uBTm6R-g7m-NEdNoBDJWe212_twMhJ5xbngIcgRh2MsGhBhbytWVyJpeCyuWaI_530NEitqphUD6EK3KluJ3Q_kXBbKBbO7WUgc6syNROc69nJ7y0GiVzcKx9o7FP-hPSkEO7eVPYKkCYBDeJAb4mq7n-Af7dRhLLfWjzbiRNz-5-ekJOAZvxrhsX3X4B_JrebgjhQHxReiyfTk24xqCmm1zrSCNgPZRCw2qWiZWbuVvfxX2xnzmeEaqb6HY9CqvhyZ-omu9H7xiSTpzKBY-iY Apr 13 15:00:19 volumio volumio[745]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 13 15:00:19 volumio volumio[745]: info: New Spotify access token = BQCjzJX_j4Vts6Y3RiYo0uBTm6R-g7m-NEdNoBDJWe212_twMhJ5xbngIcgRh2MsGhBhbytWVyJpeCyuWaI_530NEitqphUD6EK3KluJ3Q_kXBbKBbO7WUgc6syNROc69nJ7y0GiVzcKx9o7FP-hPSkEO7eVPYKkCYBDeJAb4mq7n-Af7dRhLLfWjzbiRNz-5-ekJOAZvxrhsX3X4B_JrebgjhQHxReiyfTk24xqCmm1zrSCNgPZRCw2qWiZWbuVvfxX2xnzmeEaqb6HY9CqvhyZ-omu9H7xiSTpzKBY-iY Apr 13 15:00:19 volumio volumio[745]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="zeroconf server listening on port 38091" Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="obtained new client token: AACwFZIUzOqPEi3MrcKBA4tGuBlya72266pY21QHCv1GQAo/1lATckv7dbjrMzY0tkKVkVR3SywuGH4phP6cG3LD9sghC8RvKFnMaY76djL6d295UcOSHeWcmLOOM60jtYc1Tr5wSwjW3PhxY/5NNSLjydldYr8pcFnADZN42ba/ZqXPxYgMXao6HHYqR/rdsgSnvYvE8p36W/aXaUcHe+Hj0VklaHoQrNYS/c/5z1bYz2drR4QJ+Sl98Oo=" Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="completed keyexchange" Apr 13 15:00:20 volumio mpd[1068]: Apr 13 15:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="completed challenge" Apr 13 15:00:20 volumio volumio[745]: info: CoreCommandRouter::volumioGetState Apr 13 15:00:20 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="authenticated as tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:20 volumio volumio[745]: SPOTIFY: User informations: {"country":"PL","display_name":"Roger","email":"rkw.priv@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/tp12gapnxf4e160ki0az2oc7z"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/tp12gapnxf4e160ki0az2oc7z","id":"tp12gapnxf4e160ki0az2oc7z","images":[],"product":"premium","type":"user","uri":"spotify:user:tp12gapnxf4e160ki0az2oc7z"} Apr 13 15:00:20 volumio volumio[745]: info: Spotify Successfully logged in Apr 13 15:00:20 volumio volumio[745]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 13 15:00:20 volumio volumio[745]: info: [1744549220911] CoreMusicLibrary::Adding element Spotify Apr 13 15:00:20 volumio volumio[745]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 13 15:00:20 volumio volumio[745]: Cannot find translation for source Spotify Apr 13 15:00:20 volumio go-librespot[1074]: time="2025-04-13T15:00:20+02:00" level=debug msg="authenticated as tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="dealer connection opened" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="initializing zeroconf session, username: tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="received connection id: YzNiZTdlNDEtYTcwNy00ZjM2LWIxMTItZjA4MDA2NDMxNjlkK2RlYWxlcit0Y3A6Ly8wYWNhNTg0OS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDM5MUNBMzc5MTVBNEVFQUJFMUE4NDI1NjY2OUY5RUU0QTBERTZBMzc4RTZFMTNGMEE5NjA2NThBMTZFRTg0Qg==" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 13 15:00:21 volumio go-librespot[1074]: time="2025-04-13T15:00:21+02:00" level=debug msg="autoplay enabled: false" Apr 13 15:00:21 volumio systemd[1]: Started Music Player Daemon. Apr 13 15:00:21 volumio sudo[1044]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:21 volumio sudo[1035]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:21 volumio volumio[745]: info: Completed starting Core Plugins Apr 13 15:00:21 volumio volumio[745]: info: ------------------------------------------- Apr 13 15:00:21 volumio volumio[745]: info: ----- MyVolumio plugins startup ---- Apr 13 15:00:21 volumio volumio[745]: info: ------------------------------------------- Apr 13 15:00:21 volumio volumio[745]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 13 15:00:21 volumio volumio[745]: info: MPD running with PID1068 Apr 13 15:00:21 volumio volumio[745]: ,establishing connection Apr 13 15:00:21 volumio volumio[745]: error: MPD error: The expression evaluated to a falsy value: Apr 13 15:00:21 volumio volumio[745]: assert.ok(self.idling) Apr 13 15:00:21 volumio volumio[745]: error: The expression evaluated to a falsy value: Apr 13 15:00:21 volumio volumio[745]: assert.ok(self.idling) Apr 13 15:00:21 volumio volumio[745]: error: MPD error: The expression evaluated to a falsy value: Apr 13 15:00:21 volumio volumio[745]: assert.ok(self.idling) Apr 13 15:00:21 volumio volumio[745]: error: The expression evaluated to a falsy value: Apr 13 15:00:21 volumio volumio[745]: assert.ok(self.idling) Apr 13 15:00:21 volumio volumio[745]: error: updateQueue error: null Apr 13 15:00:22 volumio volumio[745]: info: go-librespot daemon successfully initialized Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=debug msg="handling transfer player command from 271f7b54d200ff5ba5a5413215d27dbf84b57dc4" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=debug msg="resolved context of track" uri="spotify:album:2YumG5RQZkxUTDZuJPcR2J" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=trace msg="fetched new page 0 with 3 items (list: 3)" uri="spotify:album:2YumG5RQZkxUTDZuJPcR2J" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=debug msg="loading track (paused: false, position: 111613ms)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=trace msg="emitting websocket event: will_play" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=debug msg="selected format OGG_VORBIS_320 (df03d862d0040181b2f59e2e7c423fd4fcd4eeb4)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:22 volumio go-librespot[1074]: time="2025-04-13T15:00:22+02:00" level=debug msg="requested aes key for file df03d862d0040181b2f59e2e7c423fd4fcd4eeb4, gid: 1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1124" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched first chunk of 123, total size is 64106996 bytes" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio sudo[1114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=Wszyscy,password=,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.1.105/LIBRARY /mnt/NAS/Library Apr 13 15:00:23 volumio sudo[1114]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 1/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 11/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 10/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 2/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 3/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 9/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="seek to 111613ms (diff: 121ms, samples: 4922133, bytes: 4993520)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="fetched chunk 12/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="created new output device" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=info msg="loaded track \"Logos - Pt.1 / Live From The Dominion Theatre, London / 6th November 1982\" (paused: false, position: 111613ms, duration: 1548478ms, prefetched: false)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:23 volumio systemd[1]: systemd-fsckd.service: Succeeded. Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="scheduling prefetch in 1407s" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="emitting websocket event: metadata" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="emitting websocket event: active" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="sending successful reply for dealer request" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="emitting websocket event: playing" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="closed output device because of stop command" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=debug msg="put connect state inactive" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="emitting websocket event: inactive" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=trace msg="emitting websocket event: stopped" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Apr 13 15:00:23 volumio go-librespot[1074]: time="2025-04-13T15:00:23+02:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.1.127:40206->34.158.1.133:4070: use of closed network connection" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="obtained new client token: AABi5VpersY6Rpu2ahBdTVui8w9lekt5jJo6lBuEkp90rz+MCGZq4r/2WxWIwOuoFTDopmKDSQNTdwM/LsZVIObKH6kmNx832JLWZJtJ5UnHPrLtmnCxYbefhbgjtGOHpim6BRk1vHJdQwwYUuodw2D7HE2Unsg3GOPLmS/JsfrGmUnVfbTN4DRJeleUAcBrawdKyQOug7U6szK/6CGjYbZ82AJ1vwJMfSiCpWZ6KLAm+odtWJ11ZfxwI6E=" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="completed keyexchange" Apr 13 15:00:24 volumio sudo[1028]: pam_unix(sudo:session): session closed for user root Apr 13 15:00:24 volumio volumio[745]: info: Cannot mount NAS Music at system boot, trial number 2 ,retrying in 5 seconds Apr 13 15:00:24 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Apr 13 15:00:24 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Apr 13 15:00:24 volumio kernel: CIFS: Attempting to mount //192.168.1.105/LIBRARY Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="completed challenge" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="authenticated as tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="authenticated as tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="dealer connection opened" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="restored session after logout, username: tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="autoplay enabled: false" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="received connection id: OGU0NjdjNDEtOGQ4NC00MzBhLThiYTItYzc0ZWUzNjBmYjVlK2RlYWxlcit0Y3A6Ly8wYWNhNWE1MS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArOTY4Q0YzNzNFMDQ1OTJFMUZFQjEyRkY4MEY4QjRCM0Q3N0FDNTFGRTc3NkVBQkMzNEM2MUNGNjFDRjQxRkUxMQ==" Apr 13 15:00:24 volumio go-librespot[1074]: time="2025-04-13T15:00:24+02:00" level=debug msg="put connect state because NEW_DEVICE" Apr 13 15:00:25 volumio volumio[745]: info: Initializing connection to go-librespot Websocket Apr 13 15:00:25 volumio go-librespot[1074]: time="2025-04-13T15:00:25+02:00" level=debug msg="new websocket client" Apr 13 15:00:25 volumio volumio[745]: info: Connection to go-librespot Websocket established Apr 13 15:00:27 volumio volumio[1011]: ................................................................................++++ Apr 13 15:00:27 volumio volumio[745]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="handling transfer player command from 271f7b54d200ff5ba5a5413215d27dbf84b57dc4" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="resolved context of track" uri="spotify:album:2YumG5RQZkxUTDZuJPcR2J" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=trace msg="fetched new page 0 with 3 items (list: 3)" uri="spotify:album:2YumG5RQZkxUTDZuJPcR2J" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="loading track (paused: false, position: 116870ms)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=trace msg="emitting websocket event: will_play" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="selected format OGG_VORBIS_320 (df03d862d0040181b2f59e2e7c423fd4fcd4eeb4)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="requested aes key for file df03d862d0040181b2f59e2e7c423fd4fcd4eeb4, gid: 1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio volumio[745]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1nTevJWMVhFnpengBcRE95","play_origin":"android-auto"}} Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched first chunk of 123, total size is 64106996 bytes" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio volumio[745]: info: Getting Spotify volume Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 3/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 1/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 2/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 12/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 9/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=trace msg="seek to 116870ms (diff: 197ms, samples: 5153967, bytes: 5207182)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="created new output device" Apr 13 15:00:28 volumio volumio[745]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 11/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=info msg="loaded track \"Logos - Pt.1 / Live From The Dominion Theatre, London / 6th November 1982\" (paused: false, position: 116870ms, duration: 1548478ms, prefetched: false)" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:28 volumio go-librespot[1074]: time="2025-04-13T15:00:28+02:00" level=debug msg="fetched chunk 10/122, size: 524288" uri="spotify:track:1nTevJWMVhFnpengBcRE95" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="scheduling prefetch in 1402s" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="emitting websocket event: metadata" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="emitting websocket event: active" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="sending successful reply for dealer request" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="emitting websocket event: playing" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="closed output device because of stop command" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="put connect state inactive" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="emitting websocket event: inactive" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=trace msg="emitting websocket event: stopped" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.1.127:51126->34.158.1.133:4070: use of closed network connection" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="obtained new client token: AACa3HgYPQZlj8eON3JNZ1TEN4hWl5sf+0VnDc8Ye2RQxHd7fLQh37raV+eth5ncDhpP0gxv64RRjp6vTnRc7cqCeO9H3GdJm/ZrYnLpZowZArAvKlCPPSo3h2Wg9is6K/bMwa+xXHsQlVcNwLxnmZD02e3KVYNEk5sbKB0Ke8KzezunsKdutGOZ1y1AgXgaK+E93mPeOD92NZlUo4yjacbHWKrjnJa0KKcthVss9gGPsV4QuyZWPNkLfd0=" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" Apr 13 15:00:29 volumio volumio[745]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1nTevJWMVhFnpengBcRE95","name":"Logos - Pt.1 / Live From The Dominion Theatre, London / 6th November 1982","artist_names":["Tangerine Dream"],"album_name":"Logos (Live / Remastered 2020)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023ea479290f13bb7265323702","position":116870,"duration":1548478,"release_date":"year:1982 month:12 day:1","track_number":1,"disc_number":1}} Apr 13 15:00:29 volumio volumio[745]: SPOTIFY: received: {"type":"active","data":null} Apr 13 15:00:29 volumio volumio[745]: info: Aligning Spotify Volume to Volumio Volume Apr 13 15:00:29 volumio volumio[745]: info: CoreCommandRouter::volumioGetState Apr 13 15:00:29 volumio volumio[745]: info: CorePlayQueue::getTrack 0 Apr 13 15:00:29 volumio volumio[745]: info: Setting Spotify Volume from Volumio: 100 Apr 13 15:00:29 volumio volumio[745]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1nTevJWMVhFnpengBcRE95","play_origin":"android-auto"}} Apr 13 15:00:29 volumio volumio[745]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 13 15:00:29 volumio volumio[745]: TypeError: Cannot read property 'service' of undefined Apr 13 15:00:29 volumio volumio[745]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Apr 13 15:00:29 volumio volumio[745]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Apr 13 15:00:29 volumio volumio[745]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Apr 13 15:00:29 volumio volumio[745]: at WebSocket.emit (events.js:315:20) Apr 13 15:00:29 volumio volumio[745]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Apr 13 15:00:29 volumio volumio[745]: at Receiver.emit (events.js:315:20) Apr 13 15:00:29 volumio volumio[745]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Apr 13 15:00:29 volumio volumio[745]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Apr 13 15:00:29 volumio volumio[745]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Apr 13 15:00:29 volumio volumio[745]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Apr 13 15:00:29 volumio volumio[745]: at writeOrBuffer (internal/streams/writable.js:358:12) Apr 13 15:00:29 volumio volumio[745]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Apr 13 15:00:29 volumio volumio[745]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Apr 13 15:00:29 volumio volumio[745]: at Socket.emit (events.js:315:20) Apr 13 15:00:29 volumio volumio[745]: at addChunk (internal/streams/readable.js:309:12) Apr 13 15:00:29 volumio volumio[745]: at readableAddChunk (internal/streams/readable.js:284:9) Apr 13 15:00:29 volumio volumio[745]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="completed keyexchange" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="completed challenge" Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="authenticated as tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:29 volumio sudo[1142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-13 14:59 Apr 13 15:00:29 volumio sudo[1142]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 13 15:00:29 volumio go-librespot[1074]: time="2025-04-13T15:00:29+02:00" level=debug msg="authenticated as tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="dealer connection opened" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="restored session after logout, username: tp12gapnxf4e160ki0az2oc7z" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="autoplay enabled: false" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Apr 13 15:00:30 volumio go-librespot[1074]: time="2025-04-13T15:00:30+02:00" level=debug msg="received connection id: ZTg0YjQyMDktYWMzNi00OGNhLWJmZmMtYjVmMTk3MTIyMjA5K2RlYWxlcit0Y3A6Ly8wYWNhNWEzMy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMTU0QTE2MjVGMEJBM0NBOThGMzA2QkNBODk0OTlBMDk3QzIxQjE3MjM0RkRFRjFGNzE0ODJBODMxNEFEOUNCMQ==" 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"