-- Logs begin at Thu 2019-02-14 18:12:00 CST, end at Sun 2025-12-14 19:58:20 CST. -- Dec 14 19:57:00 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:00 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:00 volumio volumio[943]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Dec 14 19:57:00 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 25) Dec 14 19:57:00 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Dec 14 19:57:00 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:00 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:00 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:01 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:02 volumio kernel: hwmon hwmon1: Voltage normalised Dec 14 19:57:02 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:02 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:02 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:02 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Dec 14 19:57:02 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:02 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:02 volumio go-librespot[2216]: Librespot-go daemon starting... Dec 14 19:57:02 volumio go-librespot[2216]: time="2025-12-14T19:57:02+08:00" level=info msg="generated new device id: aeeb89e405aeeeae0ca8262e0016d58908358dcc" Dec 14 19:57:02 volumio go-librespot[2216]: time="2025-12-14T19:57:02+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:02 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:02 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:03 volumio sudo[2224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 14 19:57:03 volumio sudo[2224]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:57:03 volumio sudo[2224]: pam_unix(sudo:session): session closed for user root Dec 14 19:57:03 volumio sudo[2227]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 14 19:57:03 volumio sudo[2227]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:57:03 volumio sudo[2227]: pam_unix(sudo:session): session closed for user root Dec 14 19:57:03 volumio volumio[943]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 8 Dec 14 19:57:04 volumio sudo[2230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 14 19:57:04 volumio sudo[2230]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:57:04 volumio sudo[2230]: pam_unix(sudo:session): session closed for user root Dec 14 19:57:04 volumio sudo[2233]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 14 19:57:04 volumio sudo[2233]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:57:04 volumio sudo[2233]: pam_unix(sudo:session): session closed for user root Dec 14 19:57:04 volumio volumio[943]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 9 Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::volumioGetVisibleSources Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:04 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::volumioGetQueue Dec 14 19:57:04 volumio volumio[943]: info: CoreStateMachine::getQueue Dec 14 19:57:04 volumio volumio[943]: info: CorePlayQueue::getQueue Dec 14 19:57:04 volumio volumio[943]: info: Listing playlists Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 14 19:57:04 volumio volumio[943]: info: Received Get System Info Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 14 19:57:04 volumio volumio[943]: info: Discovery: Getting this device information Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:04 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:04 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 14 19:57:04 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 14 19:57:05 volumio go-librespot[2216]: time="2025-12-14T19:57:05+08:00" level=debug msg="obtained new client token: AAB76Jr/gzzmpbmLLvICJ6cSraIqUDIGK7TZv+dzAQe47g+ZZYjmkuBYxJujY585Gq2ei7l+ddxUYxJIZDYPcB3aW6RVabR3uR+yzfd9rnFUaoQMKBVqeHeOist20+EyWR+tj0H4bZLfUb7LWA5bXUdcw8HHDiwmNAs8AFV7nMqNiC8sLNTnPEZOTUh3Ugfad4DCxntTSYsL+kvWQusZfXdxAXjpfwZR7NlnxYdh3Is/uFySMUf8Sw8Dw5ae2xOLTA==" Dec 14 19:57:05 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:05 volumio go-librespot[2216]: time="2025-12-14T19:57:05+08:00" level=debug msg="new websocket client" Dec 14 19:57:05 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:06 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Dec 14 19:57:06 volumio volumio[943]: info: Received Get System Info Dec 14 19:57:06 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 14 19:57:06 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 14 19:57:06 volumio volumio[943]: info: Discovery: Getting this device information Dec 14 19:57:06 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:06 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:06 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 14 19:57:06 volumio go-librespot[2216]: time="2025-12-14T19:57:06+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 14 19:57:06 volumio go-librespot[2216]: time="2025-12-14T19:57:06+08:00" level=debug msg="completed keyexchange" Dec 14 19:57:07 volumio go-librespot[2216]: time="2025-12-14T19:57:07+08:00" level=debug msg="completed challenge" Dec 14 19:57:07 volumio go-librespot[2216]: time="2025-12-14T19:57:07+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:57:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:57:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:57:07 volumio volumio[943]: info: Connection to go-librespot Websocket closed Dec 14 19:57:07 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:08 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:08 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:08 volumio volumio[943]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Dec 14 19:57:08 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 26) Dec 14 19:57:08 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Dec 14 19:57:08 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:08 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:08 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:09 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:09 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:10 volumio kernel: usb 2-1: USB disconnect, device number 3 Dec 14 19:57:10 volumio volumio[943]: info: Partition removed: {"syspath":"/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb2/2-1/2-1:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","ACTION":"remove","DEVLINKS":"/dev/disk/by-id/usb-USB_SanDisk_3.2Gen1_010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1-0:0-part1 /dev/disk/by-path/platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1:1.0-scsi-0:0:0:0-part1 /dev/disk/by-partuuid/be90ae9a-01 /dev/disk/by-uuid/288016118015E65A","DEVNAME":"/dev/sda1","DEVPATH":"/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb2/2-1/2-1:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","DEVTYPE":"partition","DISKSEQ":"28","ID_BUS":"usb","ID_FS_TYPE":"ntfs","ID_FS_USAGE":"filesystem","ID_FS_UUID":"288016118015E65A","ID_FS_UUID_ENC":"288016118015E65A","ID_INSTANCE":"0:0","ID_MODEL":"SanDisk_3.2Gen1","ID_MODEL_ENC":"\\x20SanDisk\\x203.2Gen1","ID_MODEL_ID":"5591","ID_PART_ENTRY_DISK":"8:0","ID_PART_ENTRY_NUMBER":"1","ID_PART_ENTRY_OFFSET":"32","ID_PART_ENTRY_SCHEME":"dos","ID_PART_ENTRY_SIZE":"240328672","ID_PART_ENTRY_TYPE":"0x7","ID_PART_ENTRY_UUID":"be90ae9a-01","ID_PART_TABLE_TYPE":"dos","ID_PART_TABLE_UUID":"be90ae9a","ID_PATH":"platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1:1.0-scsi-0:0:0:0","ID_PATH_TAG":"platform-fd500000_pcie-pci-0000_01_00_0-usb-0_1_1_0-scsi-0_0_0_0","ID_REVISION":"1.00","ID_SERIAL":"USB_SanDisk_3.2Gen1_010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1-0:0","ID_SERIAL_SHORT":"010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1","ID_TYPE":"disk","ID_USB_DRIVER":"usb-storage","ID_USB_INTERFACES":":080650:","ID_USB_INTERFACE_NUM":"00","ID_VENDOR":"USB","ID_VENDOR_ENC":"\\x20USB\\x20\\x20\\x20\\x20","ID_VENDOR_ID":"0781","MAJOR":"8","MINOR":"1","PARTN":"1","SEQNUM":"1881","SUBSYSTEM":"block","TAGS":":systemd:","USEC_INITIALIZED":"285334791"} Dec 14 19:57:10 volumio sudo[2241]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /dev/sda1 Dec 14 19:57:10 volumio sudo[2241]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:57:10 volumio sudo[2241]: pam_unix(sudo:session): session closed for user root Dec 14 19:57:10 volumio volumio[943]: umount: /dev/sda1: no mount point specified. Dec 14 19:57:10 volumio volumio[943]: error: Failed to umount 288016118015E65A: Error: Command failed: /usr/bin/sudo /bin/umount -f "/dev/sda1" Dec 14 19:57:10 volumio volumio[943]: umount: /dev/sda1: no mount point specified. Dec 14 19:57:10 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:10 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 24. Dec 14 19:57:10 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:10 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:10 volumio go-librespot[2243]: Librespot-go daemon starting... Dec 14 19:57:10 volumio go-librespot[2243]: time="2025-12-14T19:57:10+08:00" level=info msg="generated new device id: f31c9f14e90444ccf1b8a4bd5e7464f265399b2c" Dec 14 19:57:10 volumio go-librespot[2243]: time="2025-12-14T19:57:10+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:11 volumio go-librespot[2243]: time="2025-12-14T19:57:11+08:00" level=debug msg="obtained new client token: AAB72uY6DxL6jgxFEG5Mz9XOlfgFz4hrJ8zZ/kOUchAW4HeGjzTBATm3QfWb4PUKwDdTui5IEEuWPeEApF4QFxq03HSQ0wlvn+B6FEmFJ0tkEPTpmo1vxpp8Rbvi8YfKCzcrkO6Sw/5q1J3sxzXd7+sGFULSLSkiJh9QvjvYfW+b8CbozncRJTqatKiHeXZR15Kh/HH4KZEp2SDsERSg/dLH/Zw2B4GG44/eNpVNDI2lJSAY9am/r7WueQuPKyM62w==" Dec 14 19:57:13 volumio go-librespot[2243]: time="2025-12-14T19:57:13+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 14 19:57:13 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:13 volumio go-librespot[2243]: time="2025-12-14T19:57:13+08:00" level=debug msg="new websocket client" Dec 14 19:57:13 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:13 volumio go-librespot[2243]: time="2025-12-14T19:57:13+08:00" level=debug msg="completed keyexchange" Dec 14 19:57:13 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:14 volumio go-librespot[2243]: time="2025-12-14T19:57:14+08:00" level=debug msg="completed challenge" Dec 14 19:57:14 volumio go-librespot[2243]: time="2025-12-14T19:57:14+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:57:14 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:57:14 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:57:14 volumio volumio[943]: info: Connection to go-librespot Websocket closed Dec 14 19:57:16 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:16 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:16 volumio volumio[943]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Dec 14 19:57:16 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 27) Dec 14 19:57:16 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Dec 14 19:57:16 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:16 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:16 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:17 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:17 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:17 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:17 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 25. Dec 14 19:57:17 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:17 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:17 volumio go-librespot[2252]: Librespot-go daemon starting... Dec 14 19:57:17 volumio go-librespot[2252]: time="2025-12-14T19:57:17+08:00" level=info msg="generated new device id: e8244f724c27097656ca8281e13f06621fb215e5" Dec 14 19:57:17 volumio go-librespot[2252]: time="2025-12-14T19:57:17+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:19 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:19 volumio go-librespot[2252]: time="2025-12-14T19:57:19+08:00" level=debug msg="obtained new client token: AADxN4EN6ZEOyOf3p8FBsEeYvTwhUxU0zTJHmInUO6Gj3eyVk4L+hU3LwSEZ0rxRUTPX8e5suPN0hkpsZijp/SUL/wOxR2H8UphVzZGsTbXOOtu9or1xGvCR6htNvXo6HWIdebJvNmaJZ3+Bl8TcmeEtY8ylbOdMuSxctuZQ7Xo6zVvvVVU5jhsufMoVSPUjV6oI5mX3IDqKPLYeyW08waQPtt49DeD+ZnGpj120dC0+o1pMG/JE7FcBcC8oPZuCPA==" Dec 14 19:57:20 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:20 volumio go-librespot[2252]: time="2025-12-14T19:57:20+08:00" level=debug msg="new websocket client" Dec 14 19:57:20 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:21 volumio go-librespot[2252]: time="2025-12-14T19:57:21+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 14 19:57:23 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:23 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Dec 14 19:57:23 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:23 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:23 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:23 volumio kernel: usb 1-1.3: new high-speed USB device number 4 using xhci_hcd Dec 14 19:57:23 volumio go-librespot[2252]: time="2025-12-14T19:57:23+08:00" level=debug msg="completed keyexchange" Dec 14 19:57:23 volumio kernel: usb 1-1.3: New USB device found, idVendor=0781, idProduct=5591, bcdDevice= 1.00 Dec 14 19:57:23 volumio kernel: usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Dec 14 19:57:23 volumio kernel: usb 1-1.3: Product: SanDisk 3.2Gen1 Dec 14 19:57:23 volumio kernel: usb 1-1.3: Manufacturer: USB Dec 14 19:57:23 volumio kernel: usb 1-1.3: SerialNumber: 010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1 Dec 14 19:57:23 volumio kernel: usb-storage 1-1.3:1.0: USB Mass Storage device detected Dec 14 19:57:23 volumio kernel: scsi host0: usb-storage 1-1.3:1.0 Dec 14 19:57:24 volumio go-librespot[2252]: time="2025-12-14T19:57:24+08:00" level=debug msg="completed challenge" Dec 14 19:57:24 volumio go-librespot[2252]: time="2025-12-14T19:57:24+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:57:24 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:57:24 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:57:24 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: socket hang up Dec 14 19:57:24 volumio volumio[943]: at connResetException (internal/errors.js:607:14) Dec 14 19:57:24 volumio volumio[943]: at Socket.socketOnEnd (_http_client.js:493:23) Dec 14 19:57:24 volumio volumio[943]: at Socket.emit (events.js:327:22) Dec 14 19:57:24 volumio volumio[943]: at endReadableNT (internal/streams/readable.js:1327:12) Dec 14 19:57:24 volumio volumio[943]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Dec 14 19:57:24 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 28) Dec 14 19:57:24 volumio volumio[943]: info: Connection to go-librespot Websocket closed Dec 14 19:57:24 volumio kernel: scsi 0:0:0:0: Direct-Access USB SanDisk 3.2Gen1 1.00 PQ: 0 ANSI: 6 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] 240328704 512-byte logical blocks: (123 GB/115 GiB) Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] Write Protect is off Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA Dec 14 19:57:24 volumio kernel: sda: sda1 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk Dec 14 19:57:24 volumio kernel: scsi_io_completion_action: 2 callbacks suppressed Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f8 00 00 01 00 Dec 14 19:57:24 volumio kernel: blk_print_req_error: 2 callbacks suppressed Dec 14 19:57:24 volumio kernel: critical medium error, dev sda, sector 240328696 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f9 00 00 01 00 Dec 14 19:57:24 volumio kernel: critical medium error, dev sda, sector 240328697 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2 Dec 14 19:57:24 volumio kernel: Buffer I/O error on dev sda, logical block 30041087, async page read Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f8 00 00 01 00 Dec 14 19:57:24 volumio kernel: critical medium error, dev sda, sector 240328696 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2 Dec 14 19:57:24 volumio volumio[943]: error: Cannot associate FS Label, not mounting Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:24 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f9 00 00 01 00 Dec 14 19:57:24 volumio kernel: critical medium error, dev sda, sector 240328697 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2 Dec 14 19:57:24 volumio kernel: Buffer I/O error on dev sda1, logical block 30041083, async page read Dec 14 19:57:25 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:27 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:27 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 26. Dec 14 19:57:27 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:27 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:27 volumio go-librespot[2309]: Librespot-go daemon starting... Dec 14 19:57:27 volumio go-librespot[2309]: time="2025-12-14T19:57:27+08:00" level=info msg="generated new device id: ae27e6d51593ef5641a9ebb14b7c3ccc907b3c8b" Dec 14 19:57:27 volumio go-librespot[2309]: time="2025-12-14T19:57:27+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:28 volumio go-librespot[2309]: time="2025-12-14T19:57:28+08:00" level=debug msg="obtained new client token: AACGU7QJ8ducLW4zqb6aJk+X1fxDyVYgQTDVFQSS23NgoXekss67ri82Z8hY09rxqs5EY8CZxQ8pRpb/rcstvX5yl56oQzo6qIkXEubdM6MJCuKHvhxz3BCBSGLBBryXbOekL8xuAGINpoJZQEDwRSuT5qaoL5gqxhwp5lW7akwFwC1vqudvolICJ6pqV7ph9UkbKqMu23gjCzGYtCCMPGCWDL8Eff6rNu/NjF+uMXsOWY9PHxO4l9bxQvRmFPLHaQ==" Dec 14 19:57:29 volumio go-librespot[2309]: time="2025-12-14T19:57:29+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 14 19:57:30 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:30 volumio go-librespot[2309]: time="2025-12-14T19:57:30+08:00" level=debug msg="new websocket client" Dec 14 19:57:30 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:31 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:32 volumio go-librespot[2309]: time="2025-12-14T19:57:32+08:00" level=debug msg="completed keyexchange" Dec 14 19:57:33 volumio go-librespot[2309]: time="2025-12-14T19:57:33+08:00" level=debug msg="completed challenge" Dec 14 19:57:33 volumio go-librespot[2309]: time="2025-12-14T19:57:33+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:57:33 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:57:33 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:57:33 volumio volumio[943]: info: Connection to go-librespot Websocket closed Dec 14 19:57:33 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:33 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:33 volumio volumio[943]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Dec 14 19:57:33 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 29) Dec 14 19:57:33 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Dec 14 19:57:33 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:33 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:33 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:36 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:36 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:36 volumio kernel: usb 1-1.3: USB disconnect, device number 4 Dec 14 19:57:36 volumio volumio[943]: info: Partition removed: {"syspath":"/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","ACTION":"remove","DEVLINKS":"/dev/disk/by-id/usb-USB_SanDisk_3.2Gen1_010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1-0:0-part1 /dev/disk/by-path/platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1.3:1.0-scsi-0:0:0:0-part1","DEVNAME":"/dev/sda1","DEVPATH":"/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/1-1.3:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","DEVTYPE":"partition","DISKSEQ":"29","ID_BUS":"usb","ID_INSTANCE":"0:0","ID_MODEL":"SanDisk_3.2Gen1","ID_MODEL_ENC":"\\x20SanDisk\\x203.2Gen1","ID_MODEL_ID":"5591","ID_PATH":"platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1.3:1.0-scsi-0:0:0:0","ID_PATH_TAG":"platform-fd500000_pcie-pci-0000_01_00_0-usb-0_1_3_1_0-scsi-0_0_0_0","ID_REVISION":"1.00","ID_SERIAL":"USB_SanDisk_3.2Gen1_010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1-0:0","ID_SERIAL_SHORT":"010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1","ID_TYPE":"disk","ID_USB_DRIVER":"usb-storage","ID_USB_INTERFACES":":080650:","ID_USB_INTERFACE_NUM":"00","ID_VENDOR":"USB","ID_VENDOR_ENC":"\\x20USB\\x20\\x20\\x20\\x20","ID_VENDOR_ID":"0781","MAJOR":"8","MINOR":"1","PARTN":"1","SEQNUM":"1915","SUBSYSTEM":"block","TAGS":":systemd:","USEC_INITIALIZED":"327667761"} Dec 14 19:57:36 volumio volumio[943]: error: Cannot associate FS Label, not mounting Dec 14 19:57:36 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:36 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 27. Dec 14 19:57:36 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:36 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:36 volumio go-librespot[2322]: Librespot-go daemon starting... Dec 14 19:57:36 volumio go-librespot[2322]: time="2025-12-14T19:57:36+08:00" level=info msg="generated new device id: 85ff9b2088a3f57d7df1e20fe866a6b95c09023b" Dec 14 19:57:36 volumio go-librespot[2322]: time="2025-12-14T19:57:36+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:37 volumio go-librespot[2322]: time="2025-12-14T19:57:37+08:00" level=debug msg="obtained new client token: AADj3p2G+prex1SMTUIqgjdVxD3WqdjVFfzb3XdCwEiK2lB2VWAGlHE0eI84+9/Vwe+CLuc/G+IdzfuDgo2aoMCwlbzkxyy9rLNzK5JHtmX6R7mMEiwnr9I8fb93xug7vwXN3YJV6rAydE52zKN7T4w5dDFz4t9KxgxCdd+peNcre5jdVIPxlwe1Nttkp70ccHVtmk+wvo9ZKZmQW0GjSgS9BSXtOCUekHArbomf1asFldl3s2WvnlKd+RteaYY=" Dec 14 19:57:37 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:38 volumio kernel: usb 2-1: new SuperSpeed USB device number 4 using xhci_hcd Dec 14 19:57:38 volumio kernel: usb 2-1: New USB device found, idVendor=0781, idProduct=5591, bcdDevice= 1.00 Dec 14 19:57:38 volumio kernel: usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Dec 14 19:57:38 volumio kernel: usb 2-1: Product: SanDisk 3.2Gen1 Dec 14 19:57:38 volumio kernel: usb 2-1: Manufacturer: USB Dec 14 19:57:38 volumio kernel: usb 2-1: SerialNumber: 010119094c7551071594a7780ce8fbb8a1567d5e4af944f916af92ef3df693a1d31f000000000000000000002aaba6e8ff130c0091558107832eddb1 Dec 14 19:57:38 volumio kernel: usb-storage 2-1:1.0: USB Mass Storage device detected Dec 14 19:57:38 volumio kernel: scsi host0: usb-storage 2-1:1.0 Dec 14 19:57:39 volumio go-librespot[2322]: time="2025-12-14T19:57:39+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Dec 14 19:57:39 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:39 volumio go-librespot[2322]: time="2025-12-14T19:57:39+08:00" level=debug msg="new websocket client" Dec 14 19:57:39 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:39 volumio kernel: scsi 0:0:0:0: Direct-Access USB SanDisk 3.2Gen1 1.00 PQ: 0 ANSI: 6 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] 240328704 512-byte logical blocks: (123 GB/115 GiB) Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] Write Protect is off Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] Mode Sense: 43 00 00 00 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA Dec 14 19:57:39 volumio kernel: sda: sda1 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f8 00 00 01 00 Dec 14 19:57:39 volumio kernel: critical medium error, dev sda, sector 240328696 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f9 00 00 01 00 Dec 14 19:57:39 volumio kernel: critical medium error, dev sda, sector 240328697 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2 Dec 14 19:57:39 volumio kernel: Buffer I/O error on dev sda, logical block 30041087, async page read Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f8 00 00 01 00 Dec 14 19:57:39 volumio kernel: critical medium error, dev sda, sector 240328696 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 2 Dec 14 19:57:39 volumio volumio[943]: error: Cannot associate FS Label, not mounting Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 UNKNOWN(0x2003) Result: hostbyte=0x00 driverbyte=DRIVER_OK cmd_age=0s Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 Sense Key : 0x3 [current] Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 ASC=0x11 ASCQ=0x0 Dec 14 19:57:39 volumio kernel: sd 0:0:0:0: [sda] tag#0 CDB: opcode=0x28 28 00 0e 53 1f f9 00 00 01 00 Dec 14 19:57:39 volumio kernel: critical medium error, dev sda, sector 240328697 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 2 Dec 14 19:57:39 volumio kernel: Buffer I/O error on dev sda1, logical block 30041083, async page read Dec 14 19:57:41 volumio go-librespot[2322]: time="2025-12-14T19:57:41+08:00" level=debug msg="completed keyexchange" Dec 14 19:57:42 volumio go-librespot[2322]: time="2025-12-14T19:57:42+08:00" level=debug msg="completed challenge" Dec 14 19:57:42 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:42 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Dec 14 19:57:42 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:42 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:42 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:42 volumio go-librespot[2322]: time="2025-12-14T19:57:42+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:57:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:57:42 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:57:42 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: socket hang up Dec 14 19:57:42 volumio volumio[943]: at connResetException (internal/errors.js:607:14) Dec 14 19:57:42 volumio volumio[943]: at Socket.socketOnEnd (_http_client.js:493:23) Dec 14 19:57:42 volumio volumio[943]: at Socket.emit (events.js:327:22) Dec 14 19:57:42 volumio volumio[943]: at endReadableNT (internal/streams/readable.js:1327:12) Dec 14 19:57:42 volumio volumio[943]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Dec 14 19:57:42 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 30) Dec 14 19:57:42 volumio volumio[943]: info: Connection to go-librespot Websocket closed Dec 14 19:57:43 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:45 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:45 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:45 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:45 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 28. Dec 14 19:57:45 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:45 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:45 volumio go-librespot[2335]: Librespot-go daemon starting... Dec 14 19:57:45 volumio go-librespot[2335]: time="2025-12-14T19:57:45+08:00" level=info msg="generated new device id: c3ce7d4223c1dfbfe1c7d08b8374910e7f6de0c7" Dec 14 19:57:45 volumio go-librespot[2335]: time="2025-12-14T19:57:45+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:46 volumio go-librespot[2335]: time="2025-12-14T19:57:46+08:00" level=debug msg="obtained new client token: AAA6aELeYmhQ5Ifupp6vqTXVeji9CjtkLOTY/5VkaMPdBv91m+uLIs+EpUY0tuXIidMCx2X5XdZrCayIcM9wb6CR+V/queWvCFr2zTAB9h7Jc8aCJexwlyGeJ/jH8ZaxBHFqxi/NWOKpNvIR1CJPMaaP4518QFGgIn4N2DveClI9TNKuXe0gk6Qxn1iojpQT4Q6XFqV7kF6P1DDxS7J+o5hOx1uXjWWyf3azplWBNI1ERaKaZLCfX/6ZzmSvL6I+sg==" Dec 14 19:57:47 volumio go-librespot[2335]: time="2025-12-14T19:57:47+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 14 19:57:48 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:48 volumio go-librespot[2335]: time="2025-12-14T19:57:48+08:00" level=debug msg="new websocket client" Dec 14 19:57:48 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:49 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:50 volumio go-librespot[2335]: time="2025-12-14T19:57:50+08:00" level=debug msg="completed keyexchange" Dec 14 19:57:50 volumio volumio[943]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 9 Dec 14 19:57:50 volumio volumio[943]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 10 Dec 14 19:57:50 volumio go-librespot[2335]: time="2025-12-14T19:57:50+08:00" level=debug msg="completed challenge" Dec 14 19:57:50 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:50 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:50 volumio go-librespot[2335]: time="2025-12-14T19:57:50+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:57:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:57:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:57:50 volumio volumio[943]: info: Connection to go-librespot Websocket closed Dec 14 19:57:51 volumio volumio[943]: info: Getting Spotify volume Dec 14 19:57:51 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:51 volumio volumio[943]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Dec 14 19:57:51 volumio volumio[943]: (node:943) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 31) Dec 14 19:57:51 volumio volumio[943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:51 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:51 volumio volumio[943]: SPOTIFY: RECEIVED VOLUMIO VOLUME 0 Dec 14 19:57:51 volumio volumio[943]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 11 Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::volumioGetVisibleSources Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:51 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::volumioGetQueue Dec 14 19:57:51 volumio volumio[943]: info: CoreStateMachine::getQueue Dec 14 19:57:51 volumio volumio[943]: info: CorePlayQueue::getQueue Dec 14 19:57:51 volumio volumio[943]: info: Listing playlists Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 14 19:57:51 volumio volumio[943]: info: Received Get System Info Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 14 19:57:51 volumio volumio[943]: info: Discovery: Getting this device information Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:51 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 14 19:57:51 volumio volumio[943]: info: CoreCommandRouter::volumioGetState Dec 14 19:57:51 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:53 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:53 volumio volumio[943]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Dec 14 19:57:53 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:57:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 29. Dec 14 19:57:53 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:57:53 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:57:53 volumio go-librespot[2343]: Librespot-go daemon starting... Dec 14 19:57:54 volumio go-librespot[2343]: time="2025-12-14T19:57:54+08:00" level=info msg="generated new device id: fe1a70d01de6f3d5a688ec7bffdb277b19479399" Dec 14 19:57:54 volumio go-librespot[2343]: time="2025-12-14T19:57:54+08:00" level=debug msg="stored credentials not found" Dec 14 19:57:54 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Dec 14 19:57:54 volumio volumio[943]: info: [1765713474586] [80s80s] handleBrowseUri curUri: 80s80s Dec 14 19:57:54 volumio volumio[943]: info: Preload queue cleared Dec 14 19:57:55 volumio volumio[943]: info: CoreCommandRouter::executeOnPlugin: 80s80s , handleBrowseUri Dec 14 19:57:55 volumio volumio[943]: info: [1765713475754] [80s80s] handleBrowseUri curUri: 80s80s/eighties Dec 14 19:57:55 volumio volumio[943]: info: [1765713475755] [80s80s] getRadioContent url: eighties Dec 14 19:57:55 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:57:55 volumio volumio[943]: info: Preload queue cleared Dec 14 19:57:56 volumio volumio[943]: info: Initializing connection to go-librespot Websocket Dec 14 19:57:56 volumio go-librespot[2343]: time="2025-12-14T19:57:56+08:00" level=debug msg="new websocket client" Dec 14 19:57:56 volumio volumio[943]: info: Connection to go-librespot Websocket established Dec 14 19:57:58 volumio go-librespot[2343]: time="2025-12-14T19:57:58+08:00" level=debug msg="obtained new client token: AAB4WtNE157xg6PZlAC4hOyuqSjPH+aujB9TVfAF2JPaKS4e8YAIHAnSbEOPF3h+3cIJv7PrgvqTV0RgDnRfSour2YjG190j16vIhtO+5v0Q7T5iNLDTVlbbhUi/lfIP71d0LQy3ArG1hpoVUZhtlbnQC5gNOLszRx1UHpeCpnFp490GtFH6Gsqgw2rKgr0R8kD7TMX2WDtBIV6or2s25hYMCb2UW0XURD7fGcMJRT8aaZD9l3yaGjSRrKbHZ+Nilw==" Dec 14 19:57:58 volumio volumio[943]: info: Preload queue cleared Dec 14 19:57:58 volumio volumio[943]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::ClearQueue Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::stop Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::clearPlayQueue Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::saveQueue Dec 14 19:57:58 volumio volumio[943]: info: CoreCommandRouter::volumioPushQueue Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::addQueueItems Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::addQueueItems Dec 14 19:57:58 volumio volumio[943]: info: Preload queue cleared Dec 14 19:57:58 volumio volumio[943]: info: Adding Item to queue: webeighties/2 Dec 14 19:57:58 volumio volumio[943]: info: Exploding uri webeighties/2 in service 80s80s Dec 14 19:57:58 volumio volumio[943]: info: [1765713478477] [80s80s] explodeUri: webeighties/2 Dec 14 19:57:58 volumio volumio[943]: info: CoreCommandRouter::volumioPushQueue Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::saveQueue Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::updateTrackBlock Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::getTrackBlock Dec 14 19:57:58 volumio volumio[943]: info: CoreCommandRouter::volumioPlay Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::play index 0 Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::stop Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::play index undefined Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:58 volumio volumio[943]: info: CoreStateMachine::startPlaybackTimer Dec 14 19:57:58 volumio volumio[943]: info: CorePlayQueue::getTrack 0 Dec 14 19:57:58 volumio volumio[943]: info: [1765713478495] [80s80s] clearAddPlayTrack url: http://streams.80s80s.de/love/mp3-192/volumio Dec 14 19:57:58 volumio volumio[943]: info: [1765713478496] [80s80s] getContentOfUrl started with url http://iris-80s80s.loverad.io/flow.json?station=85&count=2 Dec 14 19:57:58 volumio volumio[943]: info: [1765713478869] [80s80s] Failed to query api, status code: 404 Dec 14 19:57:58 volumio volumio[943]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 14 19:57:58 volumio volumio[943]: Error: ENOENT: no such file or directory, open '/data/plugins/music_service/80s80s/fake-data.json' Dec 14 19:57:58 volumio volumio[943]: at Object.openSync (fs.js:476:3) Dec 14 19:57:58 volumio volumio[943]: at Object.readFileSync (fs.js:377:35) Dec 14 19:57:58 volumio volumio[943]: at ClientRequest. (/data/plugins/music_service/80s80s/index.js:485:23) Dec 14 19:57:58 volumio volumio[943]: at Object.onceWrapper (events.js:422:26) Dec 14 19:57:58 volumio volumio[943]: at ClientRequest.emit (events.js:315:20) Dec 14 19:57:58 volumio volumio[943]: at HTTPParser.parserOnIncomingClient [as onIncoming] (_http_client.js:641:27) Dec 14 19:57:58 volumio volumio[943]: at HTTPParser.parserOnHeadersComplete (_http_common.js:126:17) Dec 14 19:57:58 volumio volumio[943]: at Socket.socketOnData (_http_client.js:509:22) Dec 14 19:57:58 volumio volumio[943]: at Socket.emit (events.js:315:20) Dec 14 19:57:58 volumio volumio[943]: at addChunk (internal/streams/readable.js:309:12) Dec 14 19:57:58 volumio volumio[943]: at readableAddChunk (internal/streams/readable.js:284:9) Dec 14 19:57:58 volumio volumio[943]: at Socket.Readable.push (internal/streams/readable.js:223:10) Dec 14 19:57:58 volumio volumio[943]: at TCP.onStreamRead (internal/stream_base_commons.js:188:23) { Dec 14 19:57:58 volumio volumio[943]: errno: -2, Dec 14 19:57:58 volumio volumio[943]: syscall: 'open', Dec 14 19:57:58 volumio volumio[943]: code: 'ENOENT', Dec 14 19:57:58 volumio volumio[943]: path: '/data/plugins/music_service/80s80s/fake-data.json' Dec 14 19:57:58 volumio volumio[943]: } Dec 14 19:57:58 volumio volumio[943]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 14 19:57:59 volumio go-librespot[2343]: time="2025-12-14T19:57:59+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 14 19:57:59 volumio sudo[2362]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-14 19:56 Dec 14 19:57:59 volumio sudo[2362]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:57:59 volumio sudo[2362]: pam_unix(sudo:session): session closed for user root Dec 14 19:57:59 volumio go-librespot[2343]: time="2025-12-14T19:57:59+08:00" level=debug msg="completed keyexchange" Dec 14 19:58:00 volumio go-librespot[2343]: time="2025-12-14T19:58:00+08:00" level=debug msg="completed challenge" Dec 14 19:58:00 volumio go-librespot[2343]: time="2025-12-14T19:58:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:58:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:58:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:58:01 volumio volumio-remote-updater[543]: [2025-12-14 19:58:01] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Dec 14 19:58:01 volumio volumio-remote-updater[543]: [2025-12-14 19:58:01] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Dec 14 19:58:01 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:58:01 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Dec 14 19:58:01 volumio systemd[1]: Started dynamicswap service. Dec 14 19:58:01 volumio systemd[1]: dynamicswap.service: Succeeded. Dec 14 19:58:01 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:58:01 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Dec 14 19:58:01 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 1. Dec 14 19:58:01 volumio systemd[1]: Started dynamicswap service. Dec 14 19:58:01 volumio systemd[1]: Stopped Volumio Backend Module. Dec 14 19:58:02 volumio systemd[1]: Started Volumio Backend Module. Dec 14 19:58:02 volumio systemd[1]: dynamicswap.service: Succeeded. Dec 14 19:58:03 volumio volumio[2377]: info: ------------------------------------------- Dec 14 19:58:03 volumio volumio[2377]: info: ----- Volumio3 ---- Dec 14 19:58:03 volumio volumio[2377]: info: ------------------------------------------- Dec 14 19:58:03 volumio volumio[2377]: info: ----- System startup ---- Dec 14 19:58:03 volumio volumio[2377]: info: ------------------------------------------- Dec 14 19:58:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:58:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 30. Dec 14 19:58:03 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:58:03 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:58:03 volumio go-librespot[2397]: Librespot-go daemon starting... Dec 14 19:58:03 volumio go-librespot[2397]: time="2025-12-14T19:58:03+08:00" level=info msg="generated new device id: 37d518e5642e4fc2dd13c195887c6f96badc3723" Dec 14 19:58:03 volumio go-librespot[2397]: time="2025-12-14T19:58:03+08:00" level=debug msg="stored credentials not found" Dec 14 19:58:03 volumio volumio[2377]: info: MYVOLUMIO Environment detected Dec 14 19:58:03 volumio volumio[2377]: info: Plugin folders cleanup Dec 14 19:58:03 volumio volumio[2377]: info: Scanning into folder /volumio/app/plugins/ Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category audio_interface Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category miscellanea Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category music_service Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category plugins.json Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category system_controller Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category user_interface Dec 14 19:58:03 volumio volumio[2377]: info: Scanning into folder /data/plugins/ Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category music_service Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category system_controller Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category system_hardware Dec 14 19:58:03 volumio volumio[2377]: info: Scanning category user_interface Dec 14 19:58:03 volumio volumio[2377]: info: Plugin folders cleanup completed Dec 14 19:58:03 volumio volumio[2377]: info: ------------------------------------------- Dec 14 19:58:03 volumio volumio[2377]: info: ----- Core plugins startup ---- Dec 14 19:58:03 volumio volumio[2377]: info: ------------------------------------------- Dec 14 19:58:03 volumio volumio[2377]: info: Loading plugins from folder /volumio/app/plugins/ Dec 14 19:58:03 volumio volumio[2377]: info: Adding plugin upnp to MyMusic Plugins Dec 14 19:58:03 volumio volumio[2377]: info: Adding plugin airplay_emulation to MyMusic Plugins Dec 14 19:58:03 volumio volumio[2377]: info: Adding plugin upnp_browser to MyMusic Plugins Dec 14 19:58:03 volumio volumio[2377]: info: Loading plugins from folder /data/plugins/ Dec 14 19:58:03 volumio volumio[2377]: info: Loading plugin "system"... Dec 14 19:58:03 volumio volumio[2377]: info: Loading plugin "appearance"... Dec 14 19:58:04 volumio go-librespot[2397]: time="2025-12-14T19:58:04+08:00" level=debug msg="obtained new client token: AADwy1aUXvo8FuKPNB670Ys6mHnnfkCNb/B7iXWx42GtaRx5/QCf5uESLxhXKHBeGUScYilmKAkHScP9yYDdjazFFCFNpIvKffm3efNmjSyv2m+GlZwd77bTjFVMymigPqS+WYU03mj7JQyPMSJmfajCC5UyhvbYhBex6S+hYL4Uluk+jkHjyOIbjI5jbu/0kq4ox3cNyEgdlzfXTKprj/C9URkBAEmkndKgk+kaUu+TlBmatksgUswmrRfmwzNGZA==" Dec 14 19:58:04 volumio volumio[2377]: info: Loading plugin "network"... Dec 14 19:58:04 volumio volumio[2377]: info: Refreshing Cached IP Addresses Dec 14 19:58:04 volumio sudo[2412]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 14 19:58:04 volumio sudo[2412]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:04 volumio sudo[2412]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:04 volumio sudo[2414]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 14 19:58:04 volumio volumio[2377]: info: Loading plugin "services"... Dec 14 19:58:04 volumio sudo[2414]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:04 volumio volumio[2377]: info: Loading plugin "alsa_controller"... Dec 14 19:58:04 volumio sudo[2414]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:04 volumio sudo[2418]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Dec 14 19:58:04 volumio sudo[2418]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:05 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:05 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 Dec 14 19:58:05 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:05 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Dec 14 19:58:05 volumio volumio[2377]: info: Loading plugin "wizard"... Dec 14 19:58:05 volumio volumio[2377]: info: Loading plugin "networkfs"... Dec 14 19:58:05 volumio volumio[2377]: info: Starting Udev Watcher for removable devices Dec 14 19:58:05 volumio volumio[2377]: info: Ignoring mount for partition: boot Dec 14 19:58:05 volumio volumio[2377]: info: Ignoring mount for partition: volumio Dec 14 19:58:05 volumio volumio[2377]: info: Ignoring mount for partition: volumio_data Dec 14 19:58:05 volumio volumio[2377]: error: Cannot associate FS Label, not mounting Dec 14 19:58:05 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 14 19:58:05 volumio volumio[2377]: info: Loading plugin "volumio_command_line_client"... Dec 14 19:58:05 volumio volumio[2377]: info: Plugin upnp is not enabled Dec 14 19:58:05 volumio volumio[2377]: info: Loading plugin "my_music"... Dec 14 19:58:05 volumio volumio[2377]: info: Loading plugin "mpd"... Dec 14 19:58:05 volumio volumio[2377]: info: Loading plugin "upnp_browser"... Dec 14 19:58:05 volumio sudo[2418]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:06 volumio volumio[2377]: info: Loading plugin "alarm-clock"... Dec 14 19:58:06 volumio volumio[2377]: info: Plugin airplay_emulation is not enabled Dec 14 19:58:06 volumio volumio[2377]: info: Loading plugin "last_100"... Dec 14 19:58:06 volumio volumio[2377]: info: Loading plugin "webradio"... Dec 14 19:58:06 volumio volumio-remote-updater[543]: [2025-12-14 19:58:06] [connect] Successful connection Dec 14 19:58:06 volumio volumio[2377]: info: Loading plugin "i2s_dacs"... Dec 14 19:58:06 volumio volumio[2377]: info: Loading plugin "volumiodiscovery"... Dec 14 19:58:06 volumio volumio[2377]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 14 19:58:06 volumio volumio[2377]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 14 19:58:06 volumio node[2377]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Dec 14 19:58:06 volumio volumio[2377]: *** WARNING *** For more information see Dec 14 19:58:06 volumio volumio[2377]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 14 19:58:06 volumio volumio[2377]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 14 19:58:06 volumio volumio[2377]: *** WARNING *** For more information see Dec 14 19:58:06 volumio node[2377]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 14 19:58:06 volumio node[2377]: *** WARNING *** For more information see Dec 14 19:58:06 volumio node[2377]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Dec 14 19:58:06 volumio node[2377]: *** WARNING *** Please fix your application to use the native API of Avahi! Dec 14 19:58:06 volumio node[2377]: *** WARNING *** For more information see Dec 14 19:58:06 volumio volumio[2377]: info: Applying required configuration parameters for plugin volumiodiscovery Dec 14 19:58:06 volumio volumio[2377]: info: Discovery: Started advertising with name: Volumio Dec 14 19:58:06 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Dec 14 19:58:06 volumio volumio[2377]: info: Loading plugin "spop"... Dec 14 19:58:06 volumio go-librespot[2397]: time="2025-12-14T19:58:06+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 14 19:58:07 volumio kernel: hwmon hwmon1: Undervoltage detected! Dec 14 19:58:07 volumio go-librespot[2397]: time="2025-12-14T19:58:07+08:00" level=debug msg="completed keyexchange" Dec 14 19:58:07 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:58:07 volumio go-librespot[2397]: time="2025-12-14T19:58:07+08:00" level=debug msg="completed challenge" Dec 14 19:58:08 volumio go-librespot[2397]: time="2025-12-14T19:58:08+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:58:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:58:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:58:08 volumio volumio[2377]: info: Loading plugin "autostart"... Dec 14 19:58:09 volumio volumio[2377]: info: Applying required configuration parameters for plugin autostart Dec 14 19:58:09 volumio volumio[2377]: info: AutoStart - onVolumioStart - read config.json Dec 14 19:58:09 volumio volumio[2377]: info: Loading plugin "now_playing"... Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "peppy_screensaver"... Dec 14 19:58:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:58:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 31. Dec 14 19:58:11 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:58:11 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:58:11 volumio go-librespot[2428]: Librespot-go daemon starting... Dec 14 19:58:11 volumio go-librespot[2428]: time="2025-12-14T19:58:11+08:00" level=info msg="generated new device id: 95dfe34df877f0c8b35bdd71207efb1569caa875" Dec 14 19:58:11 volumio go-librespot[2428]: time="2025-12-14T19:58:11+08:00" level=debug msg="stored credentials not found" Dec 14 19:58:11 volumio volumio[2377]: info: Applying required configuration parameters for plugin peppy_screensaver Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "outputs"... Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "albumart"... Dec 14 19:58:11 volumio volumio[2377]: info: Plugin example_plugin is not enabled Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "inputs"... Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "updater_comm"... Dec 14 19:58:11 volumio volumio[2377]: info: Plugin mpdemulation is not enabled Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "rest_api"... Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "websocket"... Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "80s80s"... Dec 14 19:58:11 volumio volumio[2377]: Forking 3 albumart workers Dec 14 19:58:11 volumio volumio[2377]: info: Applying required configuration parameters for plugin 80s80s Dec 14 19:58:11 volumio volumio[2377]: info: [1765713491938] [80s80s] API delay: 30 Dec 14 19:58:11 volumio volumio[2377]: info: Loading plugin "RoonBridge"... Dec 14 19:58:12 volumio volumio[2377]: info: Applying required configuration parameters for plugin RoonBridge Dec 14 19:58:12 volumio volumio[2377]: info: Loading plugin "lms"... Dec 14 19:58:12 volumio volumio[2377]: info: Loading plugin "podcast"... Dec 14 19:58:12 volumio volumio[2377]: info: ControllerPodcast::constructor Dec 14 19:58:12 volumio volumio[2377]: info: Loading plugin "ir_controller"... Dec 14 19:58:12 volumio volumio[2377]: info: Applying required configuration parameters for plugin ir_controller Dec 14 19:58:12 volumio volumio[2377]: Starting albumart workers Dec 14 19:58:13 volumio volumio[2377]: Starting albumart workers Dec 14 19:58:13 volumio volumio[2377]: Starting albumart workers Dec 14 19:58:13 volumio volumio[2377]: info: Loading plugin "Systeminfo"... Dec 14 19:58:13 volumio go-librespot[2428]: time="2025-12-14T19:58:13+08:00" level=debug msg="obtained new client token: AAASfQiLblGHsC91FONZKZtdTH8uZl9+DejgfJJpZ1SfdS2478jMbjKC42/EW8QXqQtO47/L4PORUDqd+/WIT9sbaGGlcOnoRSNYIvqcliwXSrOrefQa+8/QVilLs4Ylwo1pxjMwdQMIy5AlHNg8NsWuEltXS7UGaGTm3TgJzXQjozSmlE6OkO9VaqcOjBRC/XIqBwx6fnkr/PhbbaFFkHxSWRv1KyCEcSItFvY7CsE3DNBluCWehqZy6zRuWwMC6A==" Dec 14 19:58:13 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:58:14 volumio volumio[2377]: info: Loading plugin "touch_display"... Dec 14 19:58:14 volumio volumio[2377]: info: Applying required configuration parameters for plugin touch_display Dec 14 19:58:14 volumio volumio[2377]: info: Loading i18n strings for locale zh Dec 14 19:58:14 volumio volumio[2377]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Dec 14 19:58:14 volumio volumio[2377]: error: ir_controller: Fetching language file: Error: i18n file complementing the system language not found. Dec 14 19:58:14 volumio volumio[2377]: Updating browse sources language Dec 14 19:58:14 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 14 19:58:14 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::initPlayerControls Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Dec 14 19:58:15 volumio volumio[2377]: Express server listening on port 3000 Dec 14 19:58:15 volumio volumio[2377]: [Metrics] WebUI: 12s 238.29ms Dec 14 19:58:15 volumio volumio[2377]: info: CoreStateMachine::resetVolumioState Dec 14 19:58:15 volumio volumio[2377]: info: CoreStateMachine::getcurrentVolume Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::volumioRetrievevolume Dec 14 19:58:15 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:15 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 Dec 14 19:58:15 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 1 Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Total Clients: 2 Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 3 Dec 14 19:58:15 volumio go-librespot[2428]: time="2025-12-14T19:58:15+08:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 4 Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 5 Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:15 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:15 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:15 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 Dec 14 19:58:15 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:15 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Dec 14 19:58:15 volumio volumio[2377]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 7 Dec 14 19:58:15 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 14 19:58:16 volumio volumio[2377]: info: VolumeController:: Volume=76 Mute =true Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::pushState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioPushState Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::updateTrackBlock Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrackBlock Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioRetrievevolume Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::setRepeat false single undefined Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::pushState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioPushState Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::setRandom false Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::pushState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioPushState Dec 14 19:58:16 volumio volumio[2377]: info: Setting Device type: Raspberry PI Dec 14 19:58:16 volumio go-librespot[2428]: time="2025-12-14T19:58:16+08:00" level=debug msg="completed keyexchange" Dec 14 19:58:16 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:16 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 Dec 14 19:58:16 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:16 volumio volumio[2377]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Dec 14 19:58:16 volumio volumio[2377]: error: Failed callmethod call: TypeError: Cannot read property 'has' of undefined Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio volumio[2377]: info: Listing playlists Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetQueue Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::getQueue Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getQueue Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetVisibleSources Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio volumio[2377]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Dec 14 19:58:16 volumio volumio[2377]: error: Failed callmethod call: TypeError: Cannot read property 'has' of undefined Dec 14 19:58:16 volumio volumio[2377]: info: Listing playlists Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetQueue Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::getQueue Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getQueue Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetVisibleSources Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:16 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000020] -121 Dec 14 19:58:16 volumio kernel: i-sabre-codec-i2c 1-0048: ASoC: error at soc_component_read_no_lock on i-sabre-codec-i2c.1-0048 for register: [0x00000021] -121 Dec 14 19:58:16 volumio volumio[2377]: info: VolumeController:: Volume=76 Mute =true Dec 14 19:58:16 volumio volumio[2377]: info: CoreStateMachine::pushState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioPushState Dec 14 19:58:16 volumio volumio[2377]: info: Discovery: adding eaa2afdc-3fa0-4a8a-925d-a9b0c99b88c0 Dec 14 19:58:16 volumio volumio[2377]: info: Discovery: Found device Volumio Dec 14 19:58:16 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:16 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:16 volumio go-librespot[2428]: time="2025-12-14T19:58:16+08:00" level=debug msg="completed challenge" Dec 14 19:58:16 volumio go-librespot[2428]: time="2025-12-14T19:58:16+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: BadCredentials" Dec 14 19:58:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Dec 14 19:58:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Dec 14 19:58:16 volumio sudo[2505]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 14 19:58:16 volumio sudo[2505]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:16 volumio sudo[2505]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:16 volumio sudo[2508]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 14 19:58:16 volumio sudo[2508]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:16 volumio sudo[2508]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:17 volumio volumio[2377]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 8 Dec 14 19:58:17 volumio sudo[2511]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 14 19:58:17 volumio sudo[2511]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:17 volumio sudo[2511]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:17 volumio sudo[2514]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 14 19:58:17 volumio sudo[2514]: pam_unix(sudo:session): session opened for user root by (uid=0) Dec 14 19:58:17 volumio sudo[2514]: pam_unix(sudo:session): session closed for user root Dec 14 19:58:17 volumio volumio[2377]: verbose: New Socket.io Connection to 192.168.101.4 from 192.168.101.3 UA: Mozilla/5.0 (Linux; Android 15; SM-S9010 Build/AP3A.240905.015.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/131.0.6778.260 Mobile Safari/537.36 Total Clients: 9 Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::volumioGetVisibleSources Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:17 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::volumioGetQueue Dec 14 19:58:17 volumio volumio[2377]: info: CoreStateMachine::getQueue Dec 14 19:58:17 volumio volumio[2377]: info: CorePlayQueue::getQueue Dec 14 19:58:17 volumio volumio[2377]: info: Listing playlists Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Dec 14 19:58:17 volumio volumio[2377]: info: Received Get System Info Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Dec 14 19:58:17 volumio volumio[2377]: info: Discovery: Getting this device information Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:17 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::volumioGetState Dec 14 19:58:17 volumio volumio[2377]: info: CorePlayQueue::getTrack 0 Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Dec 14 19:58:17 volumio volumio[2377]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Dec 14 19:58:19 volumio volumio-remote-updater[543]: [2025-12-14 19:58:19] [connect] Successful connection Dec 14 19:58:19 volumio volumio-remote-updater[543]: [2025-12-14 19:58:19] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1765713499 101 Dec 14 19:58:19 volumio volumio[2377]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 10 Dec 14 19:58:19 volumio volumio[2377]: info: Preload queue cleared Dec 14 19:58:19 volumio volumio[2377]: info: CoreCommandRouter::volumioReplaceandPlayItems Dec 14 19:58:19 volumio volumio[2377]: info: CoreStateMachine::ClearQueue Dec 14 19:58:19 volumio volumio[2377]: info: CoreStateMachine::stop Dec 14 19:58:19 volumio volumio[2377]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 14 19:58:19 volumio volumio[2377]: info: CorePlayQueue::clearPlayQueue Dec 14 19:58:19 volumio volumio[2377]: info: CorePlayQueue::saveQueue Dec 14 19:58:19 volumio volumio[2377]: info: CoreCommandRouter::volumioPushQueue Dec 14 19:58:19 volumio volumio[2377]: info: CoreStateMachine::addQueueItems Dec 14 19:58:19 volumio volumio[2377]: info: CorePlayQueue::addQueueItems Dec 14 19:58:19 volumio volumio[2377]: info: Preload queue cleared Dec 14 19:58:19 volumio volumio[2377]: info: Adding Item to queue: webeighties/2 Dec 14 19:58:19 volumio volumio[2377]: info: Exploding uri webeighties/2 in service 80s80s Dec 14 19:58:19 volumio volumio[2377]: info: [1765713499199] [80s80s] explodeUri: webeighties/2 Dec 14 19:58:19 volumio volumio[2377]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 14 19:58:19 volumio volumio[2377]: TypeError: Cannot read property 'PLUGIN_NAME' of undefined Dec 14 19:58:19 volumio volumio[2377]: at Controller80s80s.getRadioI18nString (/data/plugins/music_service/80s80s/index.js:518:25) Dec 14 19:58:19 volumio volumio[2377]: at Controller80s80s.explodeUri (/data/plugins/music_service/80s80s/index.js:395:33) Dec 14 19:58:19 volumio volumio[2377]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1359:16) Dec 14 19:58:19 volumio volumio[2377]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Dec 14 19:58:19 volumio volumio[2377]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Dec 14 19:58:19 volumio volumio[2377]: at CorePlayQueue.addQueueItems (/volumio/app/playqueue.js:223:30) Dec 14 19:58:19 volumio volumio[2377]: at CoreStateMachine.addQueueItems (/volumio/app/statemachine.js:247:25) Dec 14 19:58:19 volumio volumio[2377]: at CoreCommandRouter.replaceAndPlay (/volumio/app/index.js:507:23) Dec 14 19:58:19 volumio volumio[2377]: at CoreCommandRouter.playItemsList (/volumio/app/index.js:477:17) Dec 14 19:58:19 volumio volumio[2377]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:118:33) Dec 14 19:58:19 volumio volumio[2377]: at Socket.emit (events.js:315:20) Dec 14 19:58:19 volumio volumio[2377]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Dec 14 19:58:19 volumio volumio[2377]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Dec 14 19:58:19 volumio volumio[2377]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 14 19:58:19 volumio wpa_supplicant[784]: wlan0: Failed to initiate sched scan Dec 14 19:58:19 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Dec 14 19:58:19 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 32. Dec 14 19:58:19 volumio systemd[1]: Stopped go-librespot Daemon. Dec 14 19:58:19 volumio systemd[1]: Started go-librespot Daemon. Dec 14 19:58:19 volumio go-librespot[2548]: Librespot-go daemon starting... Dec 14 19:58:20 volumio go-librespot[2548]: time="2025-12-14T19:58:20+08:00" level=info msg="generated new device id: 9828e05e1a1f3d66604d787a66c187001f7dfb94" Dec 14 19:58:20 volumio go-librespot[2548]: time="2025-12-14T19:58:20+08:00" level=debug msg="stored credentials not found" Dec 14 19:58:20 volumio sudo[2566]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-14 19:57 Dec 14 19:58:20 volumio sudo[2566]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"