May 28 22:09:00 volumio44 volumio[1201]: info: CoreCommandRouter::volumioPlay May 28 22:09:00 volumio44 volumio[1201]: info: CoreStateMachine::play index undefined May 28 22:09:00 volumio44 volumio[1201]: info: CoreStateMachine::setConsumeUpdateService undefined May 28 22:09:00 volumio44 volumio[1201]: info: CorePlayQueue::getTrack 0 May 28 22:09:00 volumio44 volumio[1201]: info: CoreStateMachine::startPlaybackTimer May 28 22:09:00 volumio44 volumio[1201]: info: CorePlayQueue::getTrack 0 May 28 22:09:00 volumio44 volumio[1201]: info: [1779973740226] ControllerSpotify::clearAddPlayTrack May 28 22:09:00 volumio44 volumio[1201]: info: Sending Spotify command with payload to local API: /player/play May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=debug msg="resolved context of track" uri="spotify:track:43IXvQdubHjhzayGFF0hT3" May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:43IXvQdubHjhzayGFF0hT3" May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:43IXvQdubHjhzayGFF0hT3" May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=trace msg="emitting websocket event: will_play" May 28 22:09:00 volumio44 volumio[1201]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:43IXvQdubHjhzayGFF0hT3","uri":"spotify:track:43IXvQdubHjhzayGFF0hT3","play_origin":"go-librespot"}} May 28 22:09:00 volumio44 volumio[1201]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:43IXvQdubHjhzayGFF0hT3","uri":"spotify:track:43IXvQdubHjhzayGFF0hT3","play_origin":"go-librespot"}} May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=debug msg="selected format OGG_VORBIS_320 (4e37cdb180d9af78fc200055412cfaae1d6c1208)" uri="spotify:track:43IXvQdubHjhzayGFF0hT3" May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=debug msg="requested aes key for file 4e37cdb180d9af78fc200055412cfaae1d6c1208, gid: 43IXvQdubHjhzayGFF0hT3" May 28 22:09:00 volumio44 go-librespot[2395]: time="2026-05-28T22:09:00+09:00" level=error msg="failed handling request play" error="failed loading context: failed loading current track (load context): failed creating stream for spotify:track:43IXvQdubHjhzayGFF0hT3: failed retrieving audio key: failed retrieving aes key with code 1" May 28 22:09:00 volumio44 volumio[1201]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error May 28 22:09:02 volumio44 volumio[1201]: info: CoreCommandRouter::volumioGetQueue May 28 22:09:02 volumio44 volumio[1201]: info: CoreStateMachine::getQueue May 28 22:09:02 volumio44 volumio[1201]: info: CorePlayQueue::getQueue May 28 22:09:04 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted May 28 22:09:06 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: ytmusic , handleBrowseUri May 28 22:09:06 volumio44 volumio[1201]: info: [ytmusic-browse] browseUri: ytmusic May 28 22:09:06 volumio44 volumio[1201]: info: Preload queue cleared May 28 22:09:06 volumio44 go-librespot[2395]: time="2026-05-28T22:09:06+09:00" level=trace msg="sent dealer ping" May 28 22:09:06 volumio44 go-librespot[2395]: time="2026-05-28T22:09:06+09:00" level=trace msg="received dealer pong" May 28 22:09:07 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: ytmusic , handleBrowseUri May 28 22:09:07 volumio44 volumio[1201]: info: [ytmusic-browse] browseUri: ytmusic/generic@endpoint:o=%7B%22type%22%3A%22browse%22%2C%22payload%22%3A%7B%22browseId%22%3A%22FEmusic_home%22%7D%7D May 28 22:09:07 volumio44 volumio[1201]: error: VM operation timed out Error: VM operation timed out May 28 22:09:07 volumio44 volumio[1201]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) May 28 22:09:07 volumio44 volumio[1201]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) May 28 22:09:07 volumio44 volumio[1201]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) May 28 22:09:07 volumio44 volumio[1201]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) May 28 22:09:07 volumio44 volumio[1201]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) May 28 22:09:07 volumio44 volumio[1201]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) May 28 22:09:07 volumio44 volumio[1201]: at async MusicItemModel.getInnertube (/data/plugins/music_service/ytmusic/dist/lib/model/BaseModel.js:13:25) May 28 22:09:07 volumio44 volumio[1201]: at async MusicItemModel._MusicItemModel_doGetPlaybackInfo (/data/plugins/music_service/ytmusic/dist/lib/model/MusicItemModel.js:108:27) May 28 22:09:07 volumio44 volumio[1201]: at async PlayController.getPlaybackInfoFromUri (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:251:19) May 28 22:09:07 volumio44 volumio[1201]: at async PlayController.clearAddPlayTrack (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:134:49) May 28 22:09:07 volumio44 volumio[1201]: error: Failed to execute browseSource: Error: VM operation timed out May 28 22:09:11 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: ytmusic , handleBrowseUri May 28 22:09:11 volumio44 volumio[1201]: info: [ytmusic-browse] browseUri: ytmusic May 28 22:09:11 volumio44 volumio[1201]: info: Preload queue cleared May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 28 22:09:13 volumio44 volumio[1201]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates May 28 22:09:13 volumio44 volumio[1201]: info: Received Get System Version May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 28 22:09:13 volumio44 volumio[1201]: info: Received Get System Info May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice May 28 22:09:13 volumio44 volumio[1201]: info: Discovery: Getting this device information May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::volumioGetState May 28 22:09:13 volumio44 volumio[1201]: info: CorePlayQueue::getTrack 0 May 28 22:09:13 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses May 28 22:09:14 volumio44 volumio[1201]: info: CoreCommandRouter::volumioGetState May 28 22:09:14 volumio44 volumio[1201]: info: CorePlayQueue::getTrack 0 May 28 22:09:18 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 28 22:09:18 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 28 22:09:22 volumio44 volumio[1201]: info: CoreCommandRouter::getUIConfigOnPlugin May 28 22:09:22 volumio44 volumio[1201]: error: [ytmusic] Error getting i18n options: VM operation timed out Error: VM operation timed out May 28 22:09:22 volumio44 volumio[1201]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) May 28 22:09:22 volumio44 volumio[1201]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) May 28 22:09:22 volumio44 volumio[1201]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) May 28 22:09:22 volumio44 volumio[1201]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) May 28 22:09:22 volumio44 volumio[1201]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) May 28 22:09:22 volumio44 volumio[1201]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) May 28 22:09:22 volumio44 volumio[1201]: at async MusicItemModel.getInnertube (/data/plugins/music_service/ytmusic/dist/lib/model/BaseModel.js:13:25) May 28 22:09:22 volumio44 volumio[1201]: at async MusicItemModel._MusicItemModel_doGetPlaybackInfo (/data/plugins/music_service/ytmusic/dist/lib/model/MusicItemModel.js:108:27) May 28 22:09:22 volumio44 volumio[1201]: at async PlayController.getPlaybackInfoFromUri (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:251:19) May 28 22:09:22 volumio44 volumio[1201]: at async PlayController.clearAddPlayTrack (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:134:49) May 28 22:09:22 volumio44 volumio[1201]: warn: [ytmusic] Failed to get account config: VM operation timed out Error: VM operation timed out May 28 22:09:22 volumio44 volumio[1201]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) May 28 22:09:22 volumio44 volumio[1201]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) May 28 22:09:22 volumio44 volumio[1201]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) May 28 22:09:22 volumio44 volumio[1201]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) May 28 22:09:22 volumio44 volumio[1201]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) May 28 22:09:22 volumio44 volumio[1201]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) May 28 22:09:22 volumio44 volumio[1201]: at async MusicItemModel.getInnertube (/data/plugins/music_service/ytmusic/dist/lib/model/BaseModel.js:13:25) May 28 22:09:22 volumio44 volumio[1201]: at async MusicItemModel._MusicItemModel_doGetPlaybackInfo (/data/plugins/music_service/ytmusic/dist/lib/model/MusicItemModel.js:108:27) May 28 22:09:22 volumio44 volumio[1201]: at async PlayController.getPlaybackInfoFromUri (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:251:19) May 28 22:09:22 volumio44 volumio[1201]: at async PlayController.clearAddPlayTrack (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:134:49) May 28 22:09:36 volumio44 go-librespot[2395]: time="2026-05-28T22:09:36+09:00" level=trace msg="sent dealer ping" May 28 22:09:36 volumio44 go-librespot[2395]: time="2026-05-28T22:09:36+09:00" level=trace msg="received dealer pong" May 28 22:10:06 volumio44 go-librespot[2395]: time="2026-05-28T22:10:06+09:00" level=trace msg="received accesspoint ping" May 28 22:10:06 volumio44 go-librespot[2395]: time="2026-05-28T22:10:06+09:00" level=trace msg="received accesspoint pong ack" May 28 22:10:06 volumio44 go-librespot[2395]: time="2026-05-28T22:10:06+09:00" level=trace msg="sent dealer ping" May 28 22:10:06 volumio44 go-librespot[2395]: time="2026-05-28T22:10:06+09:00" level=trace msg="received dealer pong" May 28 22:10:07 volumio44 wpa_supplicant[1165]: wlan0: WPA: Group rekeying completed with f8:b7:97:73:a3:22 [GTK=CCMP] May 28 22:10:17 volumio44 volumio[1201]: info: CALLMETHOD: music_service ytmusic configSaveAccount [object Object] May 28 22:10:17 volumio44 volumio[1201]: info: CoreCommandRouter::executeOnPlugin: ytmusic , configSaveAccount May 28 22:10:17 volumio44 volumio[1201]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 28 22:10:17 volumio44 volumio[1201]: Error: VM operation timed out May 28 22:10:17 volumio44 volumio[1201]: at InnertubeWrapper.generatePoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:145:15) May 28 22:10:17 volumio44 volumio[1201]: at process.processTicksAndRejections (node:internal/process/task_queues:95:5) May 28 22:10:17 volumio44 volumio[1201]: at async #generateSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:169:35) May 28 22:10:17 volumio44 volumio[1201]: at async #doGetSessionPoToken (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:113:25) May 28 22:10:17 volumio44 volumio[1201]: at async #init (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:97:9) May 28 22:10:17 volumio44 volumio[1201]: at async InnertubeWrapper.create (/data/plugins/music_service/ytmusic/node_modules/volumio-yt-support/dist/lib/innertube/Wrapper.js:57:9) May 28 22:10:17 volumio44 volumio[1201]: at async MusicItemModel.getInnertube (/data/plugins/music_service/ytmusic/dist/lib/model/BaseModel.js:13:25) May 28 22:10:17 volumio44 volumio[1201]: at async MusicItemModel._MusicItemModel_doGetPlaybackInfo (/data/plugins/music_service/ytmusic/dist/lib/model/MusicItemModel.js:108:27) May 28 22:10:17 volumio44 volumio[1201]: at async PlayController.getPlaybackInfoFromUri (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:251:19) May 28 22:10:17 volumio44 volumio[1201]: at async PlayController.clearAddPlayTrack (/data/plugins/music_service/ytmusic/dist/lib/controller/play/PlayController.js:134:49) May 28 22:10:17 volumio44 volumio[1201]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 28 22:10:17 volumio44 sudo[3013]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-28 22:09' May 28 22:10:17 volumio44 sudo[3013]: 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"