Apr 12 15:03:44 musicpi systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Apr 12 15:03:44 musicpi systemd[1]: Starting e2scrub_all.service - Online ext4 Metadata Check for All Filesystems... Apr 12 15:03:44 musicpi systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Apr 12 15:03:44 musicpi systemd[1]: setdatetime-helper.service: Deactivated successfully. Apr 12 15:03:44 musicpi systemd[1]: Finished setdatetime-helper.service - Time Synchronization Helper Service. Apr 12 15:03:44 musicpi systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Apr 12 15:03:44 musicpi systemd[1]: e2scrub_all.service: Deactivated successfully. Apr 12 15:03:44 musicpi systemd[1]: Finished e2scrub_all.service - Online ext4 Metadata Check for All Filesystems. Apr 12 15:03:44 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:44 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:44 musicpi systemd[1]: dpkg-db-backup.service: Deactivated successfully. Apr 12 15:03:44 musicpi systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Apr 12 15:03:44 musicpi volumio[1344]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Apr 12 15:03:44 musicpi volumio[1344]: SPOTIFY: SPOTIFY VOLUME undefined Apr 12 15:03:44 musicpi volumio[1344]: SPOTIFY: VOLUMIO VOLUME 100 Apr 12 15:03:44 musicpi volumio[1344]: info: Aligning Spotify Volume to Volumio Volume Apr 12 15:03:44 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:44 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:44 musicpi volumio[1344]: info: Setting Spotify Volume from Volumio: 100 Apr 12 15:03:44 musicpi volumio[1344]: SPOTIFY: User informations: {"country":"US","display_name":"Sjbekemeier1","email":"sjbekemeier1@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/634q9gr7c6agk15a5g7n2jyyi"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/634q9gr7c6agk15a5g7n2jyyi","id":"634q9gr7c6agk15a5g7n2jyyi","images":[],"product":"premium","type":"user","uri":"spotify:user:634q9gr7c6agk15a5g7n2jyyi"} Apr 12 15:03:44 musicpi volumio[1344]: info: Spotify Successfully logged in Apr 12 15:03:44 musicpi volumio[1344]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 12 15:03:44 musicpi volumio[1344]: info: [1776020624900] CoreMusicLibrary::Adding element Spotify Apr 12 15:03:44 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 15:03:44 musicpi volumio[1344]: Cannot find translation for source 80s80s Radio Apr 12 15:03:44 musicpi volumio[1344]: Cannot find translation for source Pandora Radio Apr 12 15:03:44 musicpi volumio[1344]: Cannot find translation for source Spotify Apr 12 15:03:45 musicpi volumio[1344]: info: AutoStart - Check #4/60 - VOLUMIO_SYSTEM_STATUS = starting Apr 12 15:03:45 musicpi volumio[1344]: info: [1776020625634] [Pandora] checkPing: ***LOOKS GOOD, ICE DOWN THE BEERS IN THE COOLER*** Apr 12 15:03:45 musicpi volumio[1344]: info: [1776020625635] ControllerPandora::checkHTTP Apr 12 15:03:45 musicpi volumio[1344]: info: Discovery: A device disappeared from network Apr 12 15:03:45 musicpi volumio[1344]: info: Discovery: A device disappeared from network Apr 12 15:03:45 musicpi volumio[1344]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Apr 12 15:03:45 musicpi volumio[1344]: info: Sending Spotify command with payload to local API: /player/volume Apr 12 15:03:46 musicpi volumio[1344]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Apr 12 15:03:46 musicpi volumio[1344]: info: New access token = BQCTa-C4k9FyC7mT0P9dcvgWEtlkShP51qUsg1oEujEH3ZUuM3fGi8QN0xDCBG9wbJ3jA9OaxrPC-vj0NVEc0E9P2DAK-jJjoQuSv5mY6t54OqsipVq0yQ9cDo8-UAk4CS67BvkjA1jkj9X_MR2A0Vb-rpAZB-XDwEP23mpWi3wi_ahYDMInvlAdokwgl0aJ4TIWjKRReVNfd76-iaLBr7jdsIJtxzpQp-tzvuUKWWdqsKGBz559E9Xo-QLsxstTJDeSNp6yrbA-UY1g4MD9flu73TIkojD6ufi_ZRrBgGgvjjf-6C0P3wt95w Apr 12 15:03:47 musicpi volumio[1344]: info: New access token = BQBKrFyocivm75poBv951wOhTbGPv0mXmpsUBRkxvxeVUH99eHepV5bVhTOmPpn2yqZEP90Bf81a0PGN-C0BzkvHHSaWar76vAb0yE_JXrA_wdzN_3SJfvcsdDNe9tFIXuurGIuA7hmJA8YxudrcSmDJvFx9Ti4psANEsuPKUVNNLCXMhQvFRnsZ_gz4l-6sFddUpl8oiWgWGGCgIaMs5vrvj8TMxtzsJboW_kD9rQU9DdsWoKbbGSYGgS4PT3PTnLYP4Q8-_RoUU6yGeWyPpJJGHn6fVDkqGLTUdRzZHH7U-zGv7Bk3G_neOg Apr 12 15:03:47 musicpi volumio[1344]: info: Discovery: adding e7740091-2be5-4db0-b232-707cba317624 Apr 12 15:03:47 musicpi volumio[1344]: info: Discovery: Found device MusicPi Apr 12 15:03:47 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:47 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:47 musicpi volumio[1344]: info: Discovery: this is already registered, e7740091-2be5-4db0-b232-707cba317624 Apr 12 15:03:47 musicpi volumio[1344]: info: Discovery: Found device MusicPi Apr 12 15:03:47 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:47 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:47 musicpi upmpdcli[2207]: writing RSA key Apr 12 15:03:48 musicpi volumio[1344]: info: New access token = BQDp1Undfi6wu1oAhDyk5PMFp0x3jDFRimjrf8LIhogQwHruBNEsQ_ZG8Zla5jDy_Ei4SK0EubA6KiuC9N7AmOXFqbKSIeL3La02S0mk5PLmv2kFV_TupaN2Yr_ibG_TyKjw9WnOHoOeZsHOaL4KtljDD3bZFohRwRO_WPJ-dNbnEjWTRcWVl_byEc5uq_GR_IbfyfAkSOD_ItY7pim0HcWiYo5RPWu7Ovzoqlhwx7l0gd76p7z8rW_PQFG_olOfwKon1f6r8nz_AlQ8OMm1CS2B_05czhAZrGXFkLJmNN2g86GW2d69Oy3TVw Apr 12 15:03:49 musicpi volumio[1344]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Apr 12 15:03:50 musicpi volumio[1344]: info: AutoStart - Check #5/60 - VOLUMIO_SYSTEM_STATUS = starting Apr 12 15:03:50 musicpi ntpd[1095]: DNS: dns_check: processing 0.debian.pool.ntp.org, 8, 101 Apr 12 15:03:50 musicpi ntpd[1095]: DNS: Pool taking: 158.51.99.19 Apr 12 15:03:50 musicpi ntpd[1095]: DNS: Pool taking: 23.186.168.125 Apr 12 15:03:50 musicpi ntpd[1095]: DNS: Pool taking: 45.83.234.123 Apr 12 15:03:50 musicpi ntpd[1095]: DNS: Pool taking: 141.11.89.193 Apr 12 15:03:50 musicpi ntpd[1095]: DNS: dns_take_status: 0.debian.pool.ntp.org=>good, 8 Apr 12 15:03:50 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetVisibleSources Apr 12 15:03:50 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 15:03:51 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 12 15:03:51 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:51 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:51 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 12 15:03:51 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 12 15:03:51 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 12 15:03:51 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 12 15:03:51 musicpi volumio[1344]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS x86_64 14541.0.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/142.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Apr 12 15:03:52 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:52 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:52 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 12 15:03:52 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetVisibleSources Apr 12 15:03:52 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 12 15:03:53 musicpi volumio[1344]: info: Listing playlists Apr 12 15:03:53 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Apr 12 15:03:53 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Apr 12 15:03:53 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Apr 12 15:03:53 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Apr 12 15:03:55 musicpi volumio[1344]: info: Bluetoothremote--- Checking for trusted devices to reconnect... Apr 12 15:03:55 musicpi volumio[1344]: info: Bluetoothremote--- Device list cleared and placeholder written. Apr 12 15:03:55 musicpi volumio[1344]: info: AutoStart - Check #6/60 - VOLUMIO_SYSTEM_STATUS = starting Apr 12 15:03:55 musicpi bluetoothd[927]: Adv Monitor app :1.31 disconnected from D-Bus Apr 12 15:03:55 musicpi volumio[1344]: info: CoreCommandRouter::getUIConfigOnPlugin Apr 12 15:03:56 musicpi volumio[1344]: info: Bluetoothremote--- Device found: Press scan to detect BT device - xx Apr 12 15:03:56 musicpi bluetoothd[927]: Adv Monitor app :1.32 disconnected from D-Bus Apr 12 15:03:56 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Apr 12 15:03:56 musicpi volumio[1344]: info: Received Get System Info Apr 12 15:03:56 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 12 15:03:56 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 12 15:03:56 musicpi volumio[1344]: info: Discovery: Getting this device information Apr 12 15:03:56 musicpi volumio[1344]: info: CoreCommandRouter::volumioGetState Apr 12 15:03:56 musicpi volumio[1344]: info: CorePlayQueue::getTrack 0 Apr 12 15:03:56 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 12 15:04:00 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 12 15:04:00 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 12 15:04:00 musicpi volumio[1344]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 12 15:04:00 musicpi volumio[1344]: error: Plugin music_service pandora failed to complete 'onStart' in a timely fashion Apr 12 15:04:00 musicpi volumio[1344]: info: ------------------------------------------- Apr 12 15:04:00 musicpi volumio[1344]: info: ----- MyVolumio plugins startup ---- Apr 12 15:04:00 musicpi volumio[1344]: info: ------------------------------------------- Apr 12 15:04:00 musicpi volumio[1344]: info: [MyVolumio PluginManager] Fetching plans data.... Apr 12 15:04:00 musicpi volumio[1344]: info: AutoStart - Check #7/60 - VOLUMIO_SYSTEM_STATUS = starting Apr 12 15:04:00 musicpi volumio[1344]: info: [1776020640654] [Pandora] checkHTTP: Ping works but web requests are not working. Still waiting.... Apr 12 15:04:04 musicpi volumio[1344]: error: An error occurred while listing Spotify new albums Error: Client network socket disconnected before secure TLS connection was established Apr 12 15:04:04 musicpi volumio[1344]: info: An error occurred while getting Spotify ROOT Discover Folders: Apr 12 15:04:05 musicpi volumio[1344]: info: AutoStart - Check #8/60 - VOLUMIO_SYSTEM_STATUS = starting Apr 12 15:04:10 musicpi volumio[1344]: info: AutoStart - Check #9/60 - VOLUMIO_SYSTEM_STATUS = starting Apr 12 15:04:10 musicpi volumio[1344]: info: [1776020650690] [Pandora] checkHTTP: Fetch https://8.8.8.8, attempt 5 failed Apr 12 15:04:11 musicpi go-librespot[1837]: time="2026-04-12T15:04:11-04:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating with login5: failed requesting login5 endpoint: failed requesting login5: Post \"https://login5.spotify.com/v3/login\": net/http: TLS handshake timeout" Apr 12 15:04:11 musicpi systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 12 15:04:11 musicpi systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 12 15:04:11 musicpi volumio[1344]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 15:04:11 musicpi volumio[1344]: Error: socket hang up Apr 12 15:04:11 musicpi volumio[1344]: at connResetException (node:internal/errors:720:14) Apr 12 15:04:11 musicpi volumio[1344]: at Socket.socketOnEnd (node:_http_client:519:23) Apr 12 15:04:11 musicpi volumio[1344]: at Socket.emit (node:events:526:35) Apr 12 15:04:11 musicpi volumio[1344]: at endReadableNT (node:internal/streams/readable:1376:12) Apr 12 15:04:11 musicpi volumio[1344]: at process.processTicksAndRejections (node:internal/process/task_queues:82:21) { Apr 12 15:04:11 musicpi volumio[1344]: code: 'ECONNRESET', Apr 12 15:04:11 musicpi volumio[1344]: response: undefined Apr 12 15:04:11 musicpi volumio[1344]: } Apr 12 15:04:11 musicpi volumio[1344]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 12 15:04:14 musicpi sudo[2280]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-04-12 15:03' Apr 12 15:04:14 musicpi sudo[2280]: 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="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:20:52 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="d0c2fd9dbc5e70e58c32413c12353563"