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"