-- Logs begin at Wed 2024-07-10 02:32:54 +07, end at Wed 2024-07-10 02:54:14 +07. -- Jul 10 02:53:07 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 10 02:53:07 volumio volumio[909]: info: In handleBrowseUri, curUri=spotify:artist:4uwTmw5UgEFA4l55p8ee4W Jul 10 02:53:07 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:5Ur2wjfvQvAFaSOzqZmegz Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:3cebvzFZmKpIvDTNOTpKLw Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:4R7gYtLpjgODhv0w27aINo Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:7xsVHSRzkv6PnrBOWDRZjX Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:6IRDYIrcGPD22Ahi93vgPh Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:3mOp0JlEwai9DJNVJMVSeQ Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:2eV6J6WWVYBnnBPDXth3g9 Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:3cYlmD87iJ0jQpweFKppvF Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:2Z6Xh9Va89WDQ1jOtIscub Jul 10 02:53:07 volumio volumio[909]: info: Preloading song: spotify:track:5gaNZ1IsEQ0lMNcb9uYoKb Jul 10 02:53:07 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:07 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:19 volumio volumio[909]: info: CoreCommandRouter::volumioAddQueueItems Jul 10 02:53:19 volumio volumio[909]: info: CoreStateMachine::addQueueItems Jul 10 02:53:19 volumio volumio[909]: info: CorePlayQueue::addQueueItems Jul 10 02:53:19 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:19 volumio volumio[909]: info: Adding Item to queue: spotify:artist:4uwTmw5UgEFA4l55p8ee4W Jul 10 02:53:19 volumio volumio[909]: info: Exploding uri spotify:artist:4uwTmw5UgEFA4l55p8ee4W in service spop Jul 10 02:53:19 volumio volumio[909]: SPOTIFY: EXPLODING URI:spotify:artist:4uwTmw5UgEFA4l55p8ee4W Jul 10 02:53:20 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue Jul 10 02:53:20 volumio volumio[909]: info: CorePlayQueue::saveQueue Jul 10 02:53:20 volumio volumio[909]: info: CoreStateMachine::updateTrackBlock Jul 10 02:53:20 volumio volumio[909]: info: CorePlayQueue::getTrackBlock Jul 10 02:53:31 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: spop , handleBrowseUri Jul 10 02:53:31 volumio volumio[909]: info: In handleBrowseUri, curUri=spotify:album:3zOXb7gscB8Df5VRovWA7b Jul 10 02:53:31 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:31 volumio volumio[909]: info: Preloading song: spotify:track:36PQxDj7daQ404Lf3yJmUv Jul 10 02:53:31 volumio volumio[909]: info: Exploding uri spotify:track:36PQxDj7daQ404Lf3yJmUv in service spop Jul 10 02:53:31 volumio volumio[909]: SPOTIFY: EXPLODING URI:spotify:track:36PQxDj7daQ404Lf3yJmUv Jul 10 02:53:31 volumio volumio[909]: SPOTIFY: GET TRACK: [{"uri":"spotify:track:36PQxDj7daQ404Lf3yJmUv","service":"spop","name":"Đêm Nhớ Người Tình","artist":"Khánh Linh","album":"Đêm Nhớ Người Tình","type":"song","duration":260,"albumart":"https://i.scdn.co/image/ab67616d0000b2738ff17b5d73556718be9f34b7","samplerate":"320 kbps","bitdepth":"16 bit","bitrate":"","codec":"ogg","trackType":"spotify"}] Jul 10 02:53:34 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:34 volumio volumio[909]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::ClearQueue Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::stop Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::clearPlayQueue Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::saveQueue Jul 10 02:53:34 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::addQueueItems Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::addQueueItems Jul 10 02:53:34 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:34 volumio volumio[909]: info: Adding Item to queue: spotify:album:3zOXb7gscB8Df5VRovWA7b Jul 10 02:53:34 volumio volumio[909]: info: Exploding uri spotify:album:3zOXb7gscB8Df5VRovWA7b in service spop Jul 10 02:53:34 volumio volumio[909]: SPOTIFY: EXPLODING URI:spotify:album:3zOXb7gscB8Df5VRovWA7b Jul 10 02:53:34 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::saveQueue Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::updateTrackBlock Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::getTrackBlock Jul 10 02:53:34 volumio volumio[909]: info: CoreCommandRouter::volumioPlay Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::play index 0 Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::stop Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::play index undefined Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 10 02:53:34 volumio volumio[909]: info: CoreStateMachine::startPlaybackTimer Jul 10 02:53:34 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 10 02:53:34 volumio volumio[909]: info: [1720554814731] ControllerSpotify::clearAddPlayTrack Jul 10 02:53:34 volumio volumio[909]: info: Sending Spotify command with payload to local API: /player/play Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=debug msg="loading track spotify:track:36PQxDj7daQ404Lf3yJmUv (paused: false, position: 0ms)" Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=trace msg="emitting websocket event: will_play" Jul 10 02:53:34 volumio volumio[909]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:36PQxDj7daQ404Lf3yJmUv","play_origin":"go-librespot"}} Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:36PQxDj7daQ404Lf3yJmUv" Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=debug msg="requested aes key for file 80ce54dcf391bfc77c4cac1a97d18b4fa8d536f0, gid: 36PQxDj7daQ404Lf3yJmUv" Jul 10 02:53:34 volumio go-librespot[1436]: time="2024-07-10T02:53:34+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream: failed retrieving audio key: failed retrieving aes key with code 1" Jul 10 02:53:35 volumio volumio[909]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jul 10 02:53:44 volumio ntpd[886]: Soliciting pool server 2400:8904:e001:18d:0:a789:b456:c123 Jul 10 02:53:46 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: youtube2 , handleBrowseUri Jul 10 02:53:46 volumio volumio[909]: info: [youtube2-browse] browseUri: youtube2 Jul 10 02:53:46 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:46 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:46 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:51 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:51 volumio volumio[909]: info: CoreCommandRouter::volumioReplaceandPlayItems Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::ClearQueue Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::stop Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::clearPlayQueue Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::saveQueue Jul 10 02:53:51 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::addQueueItems Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::addQueueItems Jul 10 02:53:51 volumio volumio[909]: info: Preload queue cleared Jul 10 02:53:51 volumio volumio[909]: info: Adding Item to queue: spotify:artist:4uwTmw5UgEFA4l55p8ee4W Jul 10 02:53:51 volumio volumio[909]: info: Using cached record of: spotify:artist:4uwTmw5UgEFA4l55p8ee4W Jul 10 02:53:51 volumio volumio[909]: info: CoreCommandRouter::volumioPushQueue Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::saveQueue Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::updateTrackBlock Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::getTrackBlock Jul 10 02:53:51 volumio volumio[909]: info: CoreCommandRouter::volumioPlay Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::play index 0 Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::stop Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::play index undefined Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 10 02:53:51 volumio volumio[909]: info: CoreStateMachine::startPlaybackTimer Jul 10 02:53:51 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 10 02:53:51 volumio volumio[909]: info: [1720554831689] ControllerSpotify::clearAddPlayTrack Jul 10 02:53:51 volumio volumio[909]: info: Sending Spotify command with payload to local API: /player/play Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=debug msg="loading track spotify:track:5Ur2wjfvQvAFaSOzqZmegz (paused: false, position: 0ms)" Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=trace msg="emitting websocket event: will_play" Jul 10 02:53:51 volumio volumio[909]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:5Ur2wjfvQvAFaSOzqZmegz","play_origin":"go-librespot"}} Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:5Ur2wjfvQvAFaSOzqZmegz" Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=debug msg="requested aes key for file b89df1834d220b6896960cf3d5173e0fa81b4aa8, gid: 5Ur2wjfvQvAFaSOzqZmegz" Jul 10 02:53:51 volumio go-librespot[1436]: time="2024-07-10T02:53:51+07:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed creating stream: failed retrieving audio key: failed retrieving aes key with code 1" Jul 10 02:53:51 volumio volumio[909]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Jul 10 02:53:56 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Jul 10 02:53:56 volumio volumio[909]: info: Received Get System Info Jul 10 02:53:56 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 10 02:53:56 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 10 02:53:56 volumio volumio[909]: info: Discovery: Getting this device information Jul 10 02:53:56 volumio volumio[909]: info: CoreCommandRouter::volumioGetState Jul 10 02:53:56 volumio volumio[909]: info: CorePlayQueue::getTrack 0 Jul 10 02:53:56 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 02:53:59 volumio volumio[909]: info: Retrieving Cloud Streaming UI Jul 10 02:53:59 volumio volumio[909]: info: Getting Tidal Cloud Configuration Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 02:53:59 volumio volumio[909]: info: Getting Qobuz Cloud Configuration Jul 10 02:53:59 volumio volumio[909]: info: Asking plugin for UI Config Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 02:53:59 volumio volumio[909]: info: Getting Spotify Cloud Configuration Jul 10 02:53:59 volumio volumio[909]: info: Asking plugin for UI Config Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 02:53:59 volumio volumio[909]: info: Saving Spotify Acccount Jul 10 02:53:59 volumio volumio[909]: info: Got Tidal Cloud Configuration Jul 10 02:53:59 volumio volumio[909]: info: Got it Jul 10 02:53:59 volumio volumio[909]: info: Got it Jul 10 02:53:59 volumio volumio[909]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 02:53:59 volumio volumio[909]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::volumioGetBrowseSources Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::volumioGetBrowseSources Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::volumioGetBrowseSources Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 10 02:53:59 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jul 10 02:54:03 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 10 02:54:07 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 10 02:54:07 volumio kernel: EDID block 0 is all zeroes Jul 10 02:54:07 volumio kernel: EDID block 0 is all zeroes Jul 10 02:54:07 volumio kernel: EDID block 0 is all zeroes Jul 10 02:54:07 volumio kernel: EDID block 0 is all zeroes Jul 10 02:54:11 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jul 10 02:54:11 volumio volumio[909]: info: Disabling MyMusic plugin upnp Jul 10 02:54:11 volumio sudo[3257]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Jul 10 02:54:11 volumio sudo[3257]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 10 02:54:11 volumio systemd[1]: Stopping UPnP Renderer front-end to MPD... Jul 10 02:54:11 volumio volumio[909]: error: Upnp client error: Error: This socket has been ended by the other party Jul 10 02:54:14 volumio volumio[909]: info: Enabling MyMusic plugin upnp Jul 10 02:54:14 volumio volumio[909]: info: Enabling plugin upnp Jul 10 02:54:14 volumio volumio[909]: info: Loading plugin "upnp"... Jul 10 02:54:14 volumio volumio[909]: info: [1720554854514] Starting Upmpd Daemon Jul 10 02:54:14 volumio volumio[909]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Jul 10 02:54:14 volumio volumio[909]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 10 02:54:14 volumio volumio[909]: Error: listen EADDRINUSE: address already in use :::6599 Jul 10 02:54:14 volumio volumio[909]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Jul 10 02:54:14 volumio volumio[909]: at listenInCluster (net.js:1379:12) Jul 10 02:54:14 volumio volumio[909]: at Server.listen (net.js:1465:7) Jul 10 02:54:14 volumio volumio[909]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Jul 10 02:54:14 volumio volumio[909]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Jul 10 02:54:14 volumio volumio[909]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Jul 10 02:54:14 volumio volumio[909]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Jul 10 02:54:14 volumio volumio[909]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Jul 10 02:54:14 volumio volumio[909]: code: 'EADDRINUSE', Jul 10 02:54:14 volumio volumio[909]: errno: -98, Jul 10 02:54:14 volumio volumio[909]: syscall: 'listen', Jul 10 02:54:14 volumio volumio[909]: address: '::', Jul 10 02:54:14 volumio volumio[909]: port: 6599 Jul 10 02:54:14 volumio volumio[909]: } Jul 10 02:54:14 volumio volumio[909]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 10 02:54:14 volumio sudo[3268]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-10 02:53 Jul 10 02:54:14 volumio sudo[3268]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="4b122b2365bb8c09786cd63b50d1ea6db780eb4e" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="49f98390f2d84c6549f33dc85b694fbd99e4c720" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 04 Jun 2024 09:13:11 PM CEST" VOLUMIO_VERSION="3.703" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ac782621640fcc70c07e91a81b6d958b"