Oct 25 23:08:14 volumio-car ntpd[1041]: CLOCK: time stepped by 1162912.058252 Oct 25 23:08:14 volumio-car ntpd[1041]: CLOCK: time changed from 2025-10-12 to 2025-10-25 Oct 25 23:08:14 volumio-car ntpd[1041]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Oct 25 23:08:14 volumio-car volumio[1816]: Starting albumart workers Oct 25 23:08:15 volumio-car systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Oct 25 23:08:15 volumio-car systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Oct 25 23:08:15 volumio-car systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Oct 25 23:08:15 volumio-car systemd[1]: e2scrub_all.service: Deactivated successfully. Oct 25 23:08:15 volumio-car systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Oct 25 23:08:15 volumio-car systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Oct 25 23:08:15 volumio-car systemd[1]: dpkg-db-backup.service: Deactivated successfully. Oct 25 23:08:15 volumio-car systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Oct 25 23:08:15 volumio-car volumio[1747]: info: MPD Permissions set Oct 25 23:08:15 volumio-car volumio[1747]: info: MPD Permissions set Oct 25 23:08:15 volumio-car volumio[1747]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 1 Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: A device disappeared from network Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: Browse raised the following error TypeError: Cannot read properties of undefined (reading 'toLowerCase') Oct 25 23:08:15 volumio-car volumio[1747]: info: Spotify config file written Oct 25 23:08:15 volumio-car sudo[1921]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 25 23:08:15 volumio-car sudo[1921]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: A device disappeared from network Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: Browse raised the following error TypeError: Cannot read properties of undefined (reading 'toLowerCase') Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car go-librespot[1691]: time="2025-10-25T23:08:15+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1341" Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car go-librespot[1691]: time="2025-10-25T23:08:15+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 475" Oct 25 23:08:15 volumio-car systemd[1]: Stopping go-librespot-daemon.service - go-librespot Daemon... Oct 25 23:08:15 volumio-car systemd[1]: go-librespot-daemon.service: Deactivated successfully. Oct 25 23:08:15 volumio-car systemd[1]: Stopped go-librespot-daemon.service - go-librespot Daemon. Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 25 23:08:15 volumio-car volumio[1747]: info: No need to fix Spotify hosts Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: adding 0036ccce-53cd-4c8b-9b94-3cf423a702d7 Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: Found device Volumio Car Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::volumioGetState Oct 25 23:08:15 volumio-car volumio[1747]: info: CorePlayQueue::getTrack 0 Oct 25 23:08:15 volumio-car systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Oct 25 23:08:15 volumio-car go-librespot[1930]: go-librespot daemon starting... Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: this is already registered, 0036ccce-53cd-4c8b-9b94-3cf423a702d7 Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: Found device Volumio Car Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::volumioGetState Oct 25 23:08:15 volumio-car volumio[1747]: info: CorePlayQueue::getTrack 0 Oct 25 23:08:15 volumio-car sudo[1921]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=info msg="running go-librespot 0.2.0" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="app state loaded" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=info msg="api server listening on 127.0.0.1:9879" Oct 25 23:08:15 volumio-car volumio[1747]: info: Starting Shairport Sync Oct 25 23:08:15 volumio-car volumio[1747]: info: Starting Shairport Sync Oct 25 23:08:15 volumio-car volumio[1747]: info: Starting Shairport Sync Oct 25 23:08:15 volumio-car sudo[1951]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 23:08:15 volumio-car sudo[1953]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 23:08:15 volumio-car sudo[1953]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:15 volumio-car sudo[1951]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: this is already registered, 0036ccce-53cd-4c8b-9b94-3cf423a702d7 Oct 25 23:08:15 volumio-car sudo[1949]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: Found device Volumio Car Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::volumioGetState Oct 25 23:08:15 volumio-car volumio[1747]: info: CorePlayQueue::getTrack 0 Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: this is already registered, 0036ccce-53cd-4c8b-9b94-3cf423a702d7 Oct 25 23:08:15 volumio-car volumio[1747]: info: Discovery: Found device Volumio Car Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::volumioGetState Oct 25 23:08:15 volumio-car sudo[1949]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:15 volumio-car volumio[1747]: info: CorePlayQueue::getTrack 0 Oct 25 23:08:15 volumio-car systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 23:08:15 volumio-car systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 23:08:15 volumio-car systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 23:08:15 volumio-car systemd[1]: shairport-sync.service: Consumed 1.571s CPU time. Oct 25 23:08:15 volumio-car systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 23:08:15 volumio-car volumio[1747]: info: Volumio called home Oct 25 23:08:15 volumio-car sudo[1953]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:15 volumio-car sudo[1951]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::volumioGetState Oct 25 23:08:15 volumio-car volumio[1747]: info: CorePlayQueue::getTrack 0 Oct 25 23:08:15 volumio-car systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Oct 25 23:08:15 volumio-car systemd[1]: shairport-sync.service: Deactivated successfully. Oct 25 23:08:15 volumio-car volumio[1747]: info: Shairport-Sync Started Oct 25 23:08:15 volumio-car volumio[1747]: Error adding Membership: Error: addMembership EINVAL Oct 25 23:08:15 volumio-car volumio[1747]: info: Shairport-Sync Started Oct 25 23:08:15 volumio-car systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 23:08:15 volumio-car systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Oct 25 23:08:15 volumio-car sudo[1949]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:15 volumio-car volumio[1747]: info: Shairport-Sync Started Oct 25 23:08:15 volumio-car volumio[1747]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 25 23:08:15 volumio-car volumio[1747]: SPOTIFY: BQAe8UJ-31I8-OcmBrI7zpYcgs0gbd2Poz_wXSlqUKaP3QvWdOTcF1QlgUKRQqaZnkMrZNMgnjvOai5wJKYvtzhGV2tpKUkFIayLt_-JC07hYXbLecyMeXDHPz91fGx9HVxUVFiEuVA30TQTIGhuWnCgBHivGXGdHMkdk_PfyC69quOWpzB11ZYuDCU6r-FEN8wX1V4fO4cMcDkA7ssP_OH4CYSFDAOs59irfI5glNr0OT3bM0QjlGeoye8jgizbdclIUQAJ4ufaz_RPC1FRpgT0SbRwvnVAJ7JtJ5ZihPH5p2VK8zKeLtzuf0ccEi3pXEFsBq-usoHjfm8iNTRQTZZ0dU62ZdJEkF3Om2DNj7y3IQ Oct 25 23:08:15 volumio-car volumio[1747]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 25 23:08:15 volumio-car volumio[1747]: info: New Spotify access token = BQAe8UJ-31I8-OcmBrI7zpYcgs0gbd2Poz_wXSlqUKaP3QvWdOTcF1QlgUKRQqaZnkMrZNMgnjvOai5wJKYvtzhGV2tpKUkFIayLt_-JC07hYXbLecyMeXDHPz91fGx9HVxUVFiEuVA30TQTIGhuWnCgBHivGXGdHMkdk_PfyC69quOWpzB11ZYuDCU6r-FEN8wX1V4fO4cMcDkA7ssP_OH4CYSFDAOs59irfI5glNr0OT3bM0QjlGeoye8jgizbdclIUQAJ4ufaz_RPC1FRpgT0SbRwvnVAJ7JtJ5ZihPH5p2VK8zKeLtzuf0ccEi3pXEFsBq-usoHjfm8iNTRQTZZ0dU62ZdJEkF3Om2DNj7y3IQ Oct 25 23:08:15 volumio-car volumio[1747]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=info msg="zeroconf server listening on port 43689" Oct 25 23:08:15 volumio-car mpd[1896]: 2025-10-25T23:08:15 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 25 23:08:15 volumio-car systemd[1]: Started mpd.service - Music Player Daemon. Oct 25 23:08:15 volumio-car sudo[1859]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:15 volumio-car sudo[1869]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:15 volumio-car volumio[1747]: info: Completed starting Core Plugins Oct 25 23:08:15 volumio-car volumio[1747]: info: ------------------------------------------- Oct 25 23:08:15 volumio-car volumio[1747]: info: ----- MyVolumio plugins startup ---- Oct 25 23:08:15 volumio-car volumio[1747]: info: ------------------------------------------- Oct 25 23:08:15 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 25 23:08:15 volumio-car volumio[1747]: error: MPD error: The expression evaluated to a falsy value: Oct 25 23:08:15 volumio-car volumio[1747]: assert.ok(self.idling) Oct 25 23:08:15 volumio-car volumio[1747]: error: The expression evaluated to a falsy value: Oct 25 23:08:15 volumio-car volumio[1747]: assert.ok(self.idling) Oct 25 23:08:15 volumio-car volumio[1747]: info: MPD running with PID1896 Oct 25 23:08:15 volumio-car volumio[1747]: ,establishing connection Oct 25 23:08:15 volumio-car volumio[1747]: error: updateQueue error: null Oct 25 23:08:15 volumio-car volumio[1747]: error: updateQueue error: null Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="obtained new client token: AABVrJZ0ZtKtnotdy/hWvydIzvUTdfUfqKwvq6Tjj5xcLQ5MBRrptbFaTXVGa+HuYZb28DjuhsbTp0sZZka43MtzZ01395XaWNNrt9Jl1VQb81JlS34hk9ETNhQrhFg1PQEZC00Y2h0wWK/EGJUyV6x5IzO3fbnrzhYdLwXI9HStdKLqaxEqU/2LUx6/v/9yyKA9FUvzx4nXbvICeUlVuYRAfuUBtDAMaHJSB9oE2WjXAA4GINWRI/c=" Oct 25 23:08:15 volumio-car volumio[1747]: SPOTIFY: User informations: {"country":"UA","display_name":"Roman Parkhomchuk","email":"roman.parkhomchuk@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/12158021378"},"followers":{"href":null,"total":4},"href":"https://api.spotify.com/v1/users/12158021378","id":"12158021378","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85bc23d811a440592c4f905ac0","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82bc23d811a440592c4f905ac0","width":64}],"product":"premium","type":"user","uri":"spotify:user:12158021378"} Oct 25 23:08:15 volumio-car volumio[1747]: info: Spotify Successfully logged in Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 25 23:08:15 volumio-car volumio[1747]: info: [1761422895831] CoreMusicLibrary::Adding element Spotify Oct 25 23:08:15 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 25 23:08:15 volumio-car volumio[1747]: Cannot find translation for source Spotify Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="completed keyexchange" Oct 25 23:08:15 volumio-car go-librespot[1941]: time="2025-10-25T23:08:15+03:00" level=debug msg="completed challenge" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=info msg="authenticated AP as 12158021378" Oct 25 23:08:16 volumio-car volumio[1747]: info: New access token = BQA9gpQbSc1bDO0g88EnfOrsS0uGQoxkUv22dZPwyGSQRnXchJkSuD2pYV-0Oe-FISYtNQZA11x5vw9nAgD724vMlpCl4u9TWY4EfpRvtMh0REr2GJKMxy5fZo_qyXGgyvWplTClfDGuZjzx9OrPZCJ2TuNrx3e7CDBGt0D0Dyv5eo_vp9VWPz0ddong7yvtrGC3oyl9KQ6DdD7HOE0xRSReNvjhd5XEhUZuuDmrsAYFAUZ_q_plAQ-FiJr09nrfnSIK2TCXKvk7wOXyU9yCfO8qdfuPeVdMoh5ZQwhCFo-168-MVhJUI61Y78_zAaKQ7CKhMfUSJAEGZa0ex8Ti8YPYSsK2p2yFy6Dl8UhGUjgJ8A Oct 25 23:08:16 volumio-car volumio[1747]: info: New access token = BQC7kHppjJZmEzexClF7OoE-eluabbXruj8aS_uw-jDVXZAlVLb9oKguq2-x_NDOxxJoTKpJSiP4tt_d9O-V1mOmd6oENxUFzUbvE72DCD98jtBNJOguWk0dBYe9It0UbFez5NW5dJRb_sRxNOU8jBR3jry6Lm8uHYhpTK_2Y1po6CjteJ_ygydo1F2kGju0ygySDYIYHmZ_au4emnoJj9pStZgbT897P2f-i_t987xbRRWdcKZKI_67pgAfcJu-E-4pRFrD5khkkE3WdLEVaQ810CTqTmR69LC91KEbx0d8lP5gbSXuPbsKMS9Mqs0MnZ-mI_z9AUwRI-ytR4btLvzIcXpq_cjSCs82OcamFgmvwQ Oct 25 23:08:16 volumio-car volumio[1747]: info: New access token = BQCXbbQz7Lo_Uam5vMscAfu6S8IplOnTyYp0qexveiW1-AlYQZ1ErmTxsG40o4hUOh6eXz1egeU1iarqSz-jWoS6tS5VYHLQDpVnhZPUY654TopOe0C45uLl4_yBIoYzeFcP5wD6rMZXzQM-Y67TEG3aDWAu9rEDcLxt-LgMQ3uHrVzYYhlR4G7ANHGAbXz377a-God-GYxq8CppUZxvpa_4SqxXtyTPHcMK1CEtAkIt887D83mCLt-YjSDJTQ415mm68zgYKhIk58Xejgs-qBcgFOSmMpLlgs1pGjjJSmBvPtMARazYVvbFIEzcN-P9y7C3lBU5Dg40KnXST0z0rkJJGII4sApSXj8avHShbd_9WQ Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=info msg="authenticated Login5 as 12158021378" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="initializing zeroconf session, username: 12158021378" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="dealer connection opened" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=trace msg="starting accesspoint recv loop" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=trace msg="starting dealer recv loop" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="received connection id: MzEwMGZlYmYtMjliYi00ZTFiLWIwMDYtNDgyZjVmYTNhNzlmK2RlYWxlcit0Y3A6Ly8wYWNhNDA1Yi5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMkYwQ0UzNjIyQkFGNUQyOTI2RUJFMzBEMUIyOUIyQzgzMjY5REM4QjlGNERFNzYwMjI2NzVGNDUxMTY0QkNCOA==" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=trace msg="received accesspoint ping" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="put connect state because NEW_DEVICE" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="update volume to 65535/65535" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Oct 25 23:08:16 volumio-car go-librespot[1941]: time="2025-10-25T23:08:16+03:00" level=trace msg="received accesspoint pong ack" Oct 25 23:08:17 volumio-car volumio-remote-updater[888]: [2025-10-25 23:08:17] [connect] Successful connection Oct 25 23:08:17 volumio-car volumio-remote-updater[888]: [2025-10-25 23:08:17] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=3&transport=websocket&t=1761422897 101 Oct 25 23:08:17 volumio-car volumio[1747]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 3 Transport: websocket Total Clients: 2 Oct 25 23:08:18 volumio-car go-librespot[1941]: time="2025-10-25T23:08:18+03:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 25 23:08:18 volumio-car go-librespot[1941]: time="2025-10-25T23:08:18+03:00" level=trace msg="emitting websocket event: volume" Oct 25 23:08:18 volumio-car volumio[1747]: info: go-librespot daemon successfully initialized Oct 25 23:08:20 volumio-car volumio[1747]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Oct 25 23:08:20 volumio-car volumio[1747]: Cannot compose Albumart path Oct 25 23:08:21 volumio-car volumio[1747]: info: Initializing connection to go-librespot Websocket Oct 25 23:08:21 volumio-car go-librespot[1941]: time="2025-10-25T23:08:21+03:00" level=debug msg="new websocket client" Oct 25 23:08:21 volumio-car volumio[1747]: info: Connection to go-librespot Websocket established Oct 25 23:08:23 volumio-car sudo[2001]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 25 23:08:23 volumio-car sudo[2001]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:23 volumio-car sudo[2001]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:23 volumio-car sudo[2003]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 25 23:08:23 volumio-car sudo[2003]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:23 volumio-car sudo[2003]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:23 volumio-car sudo[2006]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 25 23:08:23 volumio-car sudo[2006]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:23 volumio-car sudo[2006]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:23 volumio-car volumio[1747]: info: Upmpdcli Daemon Started Oct 25 23:08:24 volumio-car volumio[1747]: info: Getting Spotify volume Oct 25 23:08:24 volumio-car volumio[1747]: info: Spotify volume: 100 Oct 25 23:08:24 volumio-car volumio[1747]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Oct 25 23:08:24 volumio-car volumio[1747]: info: CoreCommandRouter::volumioGetState Oct 25 23:08:24 volumio-car volumio[1747]: info: CorePlayQueue::getTrack 0 Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin bluetooth to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin multiroom to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin metavolumio to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin cd_controller to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin qobuzconnect to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin smart_inputs to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: Adding plugin tidalconnect to MyMusic Plugins Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 25 23:08:24 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 23:08:24 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 25 23:08:24 volumio-car volumio[1747]: info: Starting MyVolumio Remote Streaming Endpoints Oct 25 23:08:24 volumio-car volumio[1747]: info: MyVolumio login type: Token Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 25 23:08:24 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 25 23:08:25 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 25 23:08:25 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 25 23:08:25 volumio-car volumio[1747]: info: Streaming services startup Oct 25 23:08:25 volumio-car volumio[1747]: info: Starting Streaming Daemon Oct 25 23:08:25 volumio-car sudo[2012]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 25 23:08:25 volumio-car sudo[2012]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:25 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 25 23:08:25 volumio-car sudo[2012]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:25 volumio-car volumio[1747]: error: Cannot start Volumio Streaming Daemon Oct 25 23:08:25 volumio-car volumio[1747]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 25 23:08:25 volumio-car volumio[1747]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 25 23:08:25 volumio-car volumio[1747]: error: MyVolumio Custom Token format not valid, refreshing it Oct 25 23:08:26 volumio-car volumio[1747]: info: MyVolumio login type: Token Oct 25 23:08:27 volumio-car volumio[1747]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Oct 25 23:08:27 volumio-car volumio[1747]: info: MyVolumio token set successfully Oct 25 23:08:27 volumio-car volumio[1747]: info: MYVOLUMIO: Adding device Oct 25 23:08:27 volumio-car volumio[1747]: info: MYVOLUMIO: Evaluating Server Oct 25 23:08:28 volumio-car volumio[1747]: info: MyVolumio Plan changed: premium Oct 25 23:08:28 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Oct 25 23:08:28 volumio-car volumio[1747]: info: Removing browser output: myVolumio user plan is not superstar Oct 25 23:08:28 volumio-car volumio[1747]: info: Removing audio output: Oct 25 23:08:28 volumio-car volumio[1747]: info: MYVOLUMIO: Adding device Oct 25 23:08:28 volumio-car volumio[1747]: info: MYVOLUMIO: Evaluating Server Oct 25 23:08:28 volumio-car volumio[1747]: info: Remote config written successfully Oct 25 23:08:28 volumio-car volumio[1747]: info: Starting Tunnel 1 Oct 25 23:08:28 volumio-car volumio[1747]: info: Starting Tunnel Connection Checker Oct 25 23:08:28 volumio-car volumio[1747]: info: Completed starting MyVolumio Plugin Oct 25 23:08:28 volumio-car volumio[1747]: info: MYVolumio Device enabled Oct 25 23:08:28 volumio-car volumio[1747]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Oct 25 23:08:28 volumio-car volumio[1747]: info: MyVolumio status changed Oct 25 23:08:28 volumio-car volumio[1747]: info: Streaming services startup Oct 25 23:08:28 volumio-car volumio[1747]: info: Starting Streaming Daemon Oct 25 23:08:28 volumio-car sudo[2051]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 25 23:08:28 volumio-car sudo[2051]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:28 volumio-car volumio[1747]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Oct 25 23:08:28 volumio-car volumio[1747]: error: [MyVolumio PluginManager] Cache data is invalid! Oct 25 23:08:28 volumio-car systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Oct 25 23:08:28 volumio-car sudo[2051]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:28 volumio-car volumio[1747]: error: Cannot start Volumio Streaming Daemon Oct 25 23:08:28 volumio-car volumio[1747]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 25 23:08:28 volumio-car volumio[1747]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 25 23:08:28 volumio-car dbus-daemon[866]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.27' (uid=0 pid=2055 comm="timedatectl show --property=NTPSynchronized --valu") Oct 25 23:08:28 volumio-car systemd[1]: Starting systemd-timedated.service - Time & Date Service... Oct 25 23:08:28 volumio-car dbus-daemon[866]: [system] Successfully activated service 'org.freedesktop.timedate1' Oct 25 23:08:28 volumio-car systemd[1]: Started systemd-timedated.service - Time & Date Service. Oct 25 23:08:28 volumio-car setdatetime-helper.sh[2054]: Time is not synchronized. Attempting to sync... Oct 25 23:08:28 volumio-car sudo[2063]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Sat, 25 Oct 2025 20:08:28 GMT#015' Oct 25 23:08:28 volumio-car sudo[2063]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Oct 25 23:08:28 volumio-car setdatetime-helper.sh[2064]: Sat Oct 25 23:08:28 EEST 2025 Oct 25 23:08:28 volumio-car systemd-journald[426]: Time jumped backwards, rotating. Oct 25 23:08:28 volumio-car sudo[2063]: pam_unix(sudo:session): session closed for user root Oct 25 23:08:28 volumio-car setdatetime-helper.sh[2054]: Time synchronized successfully. Oct 25 23:08:28 volumio-car systemd[1]: Starting apt-daily-upgrade.service - Daily apt upgrade and clean activities... Oct 25 23:08:28 volumio-car systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Oct 25 23:08:28 volumio-car systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Oct 25 23:08:28 volumio-car volumio[1747]: error: Failed to ping endpoint au1.myvolumio.org : unknown error Oct 25 23:08:28 volumio-car volumio[1747]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 23:08:28 volumio-car volumio[1747]: Error: Unable to resolve or reject the same promise twice Oct 25 23:08:28 volumio-car volumio[1747]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Oct 25 23:08:28 volumio-car volumio[1747]: at Socket. (/myvolumio/plugins/system_controller/my_volumio/my_volumio_real:1:32371) Oct 25 23:08:28 volumio-car volumio[1747]: at Socket.emit (node:events:514:28) Oct 25 23:08:28 volumio-car volumio[1747]: at addChunk (node:internal/streams/readable:343:12) Oct 25 23:08:28 volumio-car volumio[1747]: at readableAddChunk (node:internal/streams/readable:316:9) Oct 25 23:08:28 volumio-car volumio[1747]: at Readable.push (node:internal/streams/readable:253:10) Oct 25 23:08:28 volumio-car volumio[1747]: at Pipe.onStreamRead (node:internal/stream_base_commons:190:23) Oct 25 23:08:28 volumio-car volumio[1747]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 25 23:08:28 volumio-car sudo[2122]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-10-25 23:07' Oct 25 23:08:28 volumio-car sudo[2122]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 25 23:08:28 volumio-car systemd[1]: apt-daily-upgrade.service: Deactivated successfully. Oct 25 23:08:28 volumio-car systemd[1]: Finished apt-daily-upgrade.service - Daily apt upgrade and clean activities. 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="f9454895cc8e2f1971c705a815a7226e021e37d7" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1fc282af1865fae9b40239cedf2cc17c112eef0d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jun 28 16:48:46 UTC 2025" VOLUMIO_VERSION="4.014" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="1b557e4869cd2eea14f4113140ecea1c"