Jul 03 09:13:09 player4 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 03 09:13:13 player4 go-librespot[1608]: time="2025-07-03T09:13:13+05:30" level=debug msg="fetched chunk 5/20, size: 524288" uri="spotify:track:58vrqoqiOhj9nx3lqW1s6L" Jul 03 09:13:21 player4 go-librespot[1608]: time="2025-07-03T09:13:21+05:30" level=trace msg="received accesspoint ping" Jul 03 09:13:21 player4 go-librespot[1608]: time="2025-07-03T09:13:21+05:30" level=trace msg="received accesspoint pong ack" Jul 03 09:13:22 player4 go-librespot[1608]: time="2025-07-03T09:13:22+05:30" level=trace msg="sent dealer ping" Jul 03 09:13:22 player4 go-librespot[1608]: time="2025-07-03T09:13:22+05:30" level=trace msg="received dealer pong" Jul 03 09:13:30 player4 go-librespot[1608]: time="2025-07-03T09:13:30+05:30" level=debug msg="fetched chunk 6/20, size: 524288" uri="spotify:track:58vrqoqiOhj9nx3lqW1s6L" Jul 03 09:13:46 player4 go-librespot[1608]: time="2025-07-03T09:13:46+05:30" level=debug msg="fetched chunk 7/20, size: 524288" uri="spotify:track:58vrqoqiOhj9nx3lqW1s6L" Jul 03 09:13:52 player4 go-librespot[1608]: time="2025-07-03T09:13:52+05:30" level=trace msg="sent dealer ping" Jul 03 09:13:52 player4 go-librespot[1608]: time="2025-07-03T09:13:52+05:30" level=trace msg="received dealer pong" Jul 03 09:13:55 player4 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jul 03 09:13:55 player4 dbus-daemon[654]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.38' (uid=0 pid=2602 comm="timedatectl show --property=NTPSynchronized --valu") Jul 03 09:13:55 player4 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jul 03 09:13:56 player4 dbus-daemon[654]: [system] Successfully activated service 'org.freedesktop.timedate1' Jul 03 09:13:56 player4 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jul 03 09:13:56 player4 setdatetime-helper.sh[2601]: Time is not synchronized. Attempting to sync... Jul 03 09:13:56 player4 sudo[2610]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Thu, 03 Jul 2025 03:43:56 GMT#015' Jul 03 09:13:56 player4 sudo[2610]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jul 03 09:13:56 player4 setdatetime-helper.sh[2611]: Thu Jul 3 09:13:56 IST 2025 Jul 03 09:13:56 player4 setdatetime-helper.sh[2601]: Time synchronized successfully. Jul 03 09:13:56 player4 sudo[2610]: pam_unix(sudo:session): session closed for user root Jul 03 09:13:56 player4 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jul 03 09:13:56 player4 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jul 03 09:13:56 player4 systemd-journald[351]: Time jumped backwards, rotating. Jul 03 09:13:57 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75:3000 from 192.168.29.109 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 7 Jul 03 09:13:57 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75 from 192.168.29.109 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7a Build/BP2A.250605.031.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/137.0.7151.115 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Jul 03 09:13:57 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75 from 192.168.29.109 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7a Build/BP2A.250605.031.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/137.0.7151.115 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Jul 03 09:13:57 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75 from 192.168.29.109 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7a Build/BP2A.250605.031.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/137.0.7151.115 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Jul 03 09:13:58 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75 from 192.168.29.109 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7a Build/BP2A.250605.031.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/137.0.7151.115 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Jul 03 09:13:58 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75 from 192.168.29.109 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7a Build/BP2A.250605.031.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/137.0.7151.115 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=info msg="playback was transferred to Pixel 7a" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=trace msg="closed output device because of stop command" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 330" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1423" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="put connect state inactive" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=trace msg="emitting websocket event: inactive" Jul 03 09:13:59 player4 volumio[1301]: SPOTIFY: received: {"type":"inactive","data":null} Jul 03 09:13:59 player4 volumio[1301]: error: Failed to decode event: inactive Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="dealer connection closed" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="dealer recv loop stopped" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="obtained new client token: AABrhjDzvHSUSnwrf4G6IrHKGNgAMRqQmdB7fhCjyZBH6pqRSen+L8mT6lTqrxtLihm4S+ab2nDNPi0n/owWarVU74rGIn1jovT16naLyYWb9FmAEazAx/5+/aV9ZhOH7ke7AFOSH2ca/M8EvAH0+0rI5Dr4EUgUbU/YAjmfCnvKA1crSja0Hb4j62N/vB41WqY/fis+PJTjrRCzw3iDvPNrthVWiDw0q21P5wkMw2KPGTRBjlLlpb/y" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="connected to ap-gae2.spotify.com:4070" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="completed keyexchange" Jul 03 09:13:59 player4 go-librespot[1608]: time="2025-07-03T09:13:59+05:30" level=debug msg="completed challenge" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=info msg="authenticated AP as 31pizlsiju3dxpbxd2ytuog3tvre" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=info msg="authenticated Login5 as 31pizlsiju3dxpbxd2ytuog3tvre" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="restored session after logout, username: 31pizlsiju3dxpbxd2ytuog3tvre" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="dealer connection opened" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=trace msg="starting accesspoint recv loop" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=trace msg="starting dealer recv loop" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=trace msg="received accesspoint ping" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="received connection id: YjQwYWFmOGQtZjRiYi00NDQ4LTgxMWEtMDEzMzMyZWRlMDJlK2RlYWxlcit0Y3A6Ly8wYWIxNTk4OS5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArMTY0QzIzMjJFMTA2REYyRDJFRTI4ODM5Q0E2ODkyODc5MzFCQTQ3RUFBOUMyNDg4ODUyMUEwQjNGRjdENEVERg==" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=trace msg="received accesspoint pong ack" Jul 03 09:14:00 player4 go-librespot[1608]: time="2025-07-03T09:14:00+05:30" level=debug msg="put connect state because NEW_DEVICE" Jul 03 09:14:01 player4 go-librespot[1608]: time="2025-07-03T09:14:01+05:30" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 03 09:14:01 player4 go-librespot[1608]: time="2025-07-03T09:14:01+05:30" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 330" Jul 03 09:14:11 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75 from 192.168.29.109 UA: Mozilla/5.0 (Linux; Android 16; Pixel 7a Build/BP2A.250605.031.A2; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/137.0.7151.115 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Jul 03 09:14:11 player4 volumio[1301]: info: CoreCommandRouter::volumioGetState Jul 03 09:14:11 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Jul 03 09:14:11 player4 volumio[1301]: info: Listing playlists Jul 03 09:14:15 player4 volumio[1301]: verbose: New Socket.io Connection to 192.168.29.75:3000 from 192.168.29.109 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 13 Jul 03 09:14:16 player4 volumio[1301]: info: CoreCommandRouter::volumioGetVisibleSources Jul 03 09:14:16 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:14:16 player4 volumio[1301]: info: CoreCommandRouter::volumioGetQueue Jul 03 09:14:16 player4 volumio[1301]: info: CoreStateMachine::getQueue Jul 03 09:14:16 player4 volumio[1301]: info: CorePlayQueue::getQueue Jul 03 09:14:23 player4 volumio[1301]: Searching all installed plugins Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: , search Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: mpd , search Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: last_100 , search Jul 03 09:14:23 player4 volumio[1301]: info: Error : CoreCommandRouter::executeOnPlugin: No method [search] in plugin last_100 Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: webradio , search Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: ytmusic , search Jul 03 09:14:23 player4 volumio[1301]: info: [ytmusic] InnertubeLoader: creating Innertube instance... Jul 03 09:14:23 player4 volumio[1301]: info: CoreCommandRouter::executeOnPlugin: spop , search Jul 03 09:14:24 player4 volumio[1301]: Use XMLElement.setAttribute instead Jul 03 09:14:24 player4 volumio[1301]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 03 09:14:24 player4 volumio[1301]: TypeError: children[i].attr(...).value is not a function Jul 03 09:14:24 player4 volumio[1301]: at /volumio/app/plugins/music_service/webradio/index.js:956:46 Jul 03 09:14:24 player4 volumio[1301]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) Jul 03 09:14:24 player4 volumio[1301]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 03 09:14:25 player4 ntpd[922]: CLOCK: time stepped by 0.662173 Jul 03 09:14:25 player4 ntpd[922]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Jul 03 09:14:25 player4 systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities... Jul 03 09:14:26 player4 systemd[1]: systemd-timedated.service: Deactivated successfully. Jul 03 09:14:26 player4 sudo[2692]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-07-03 09:13' Jul 03 09:14:26 player4 sudo[2692]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="cee9bb5b0ee50e4898478097a64b5c6c77d5a212" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jun 14 07:24:14 UTC 2025" VOLUMIO_VERSION="4.012" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b365b054264e3ebc2709665da2b5d1ee"