May 24 20:55:06 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:06 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:16 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:16 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:17 volumio volumio[1145]: info: Listing playlists May 24 20:55:17 volumio volumio[1145]: info: Listing playlists May 24 20:55:26 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:26 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:36 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:36 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:37 volumio volumio[1145]: info: Listing playlists May 24 20:55:37 volumio volumio[1145]: info: Listing playlists May 24 20:55:40 volumio volumio[1145]: info: Enabling plugin podcast May 24 20:55:40 volumio volumio[1145]: info: Loading plugin "podcast"... May 24 20:55:40 volumio volumio[1145]: info: ControllerPodcast::constructor May 24 20:55:40 volumio volumio[1145]: info: PLUGIN START: podcast May 24 20:55:40 volumio volumio[1145]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 20:55:40 volumio volumio[1145]: info: [1779670540408] CoreMusicLibrary::Adding element Podcast May 24 20:55:40 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 20:55:40 volumio volumio[1145]: Cannot find translation for source Jellyfin May 24 20:55:40 volumio volumio[1145]: Cannot find translation for source Radio Browser May 24 20:55:40 volumio volumio[1145]: Cannot find translation for source Radio Paradise May 24 20:55:40 volumio volumio[1145]: Cannot find translation for source Radio Paradise (RP2) May 24 20:55:40 volumio volumio[1145]: Cannot find translation for source FM/DAB Radio May 24 20:55:40 volumio volumio[1145]: Cannot find translation for source Podcast May 24 20:55:40 volumio volumio[1145]: info: Done. May 24 20:55:42 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:42 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: info: CoreCommandRouter::volumioPlay May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::play index undefined May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 20:55:43 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::startPlaybackTimer May 24 20:55:43 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::clearAddPlayTracks NAS/Media/FLAC/Now That's What I Call Music! 1-118 (1983-2024)/2002. Now That's What I Call Music! 53/CD1/06. Blue - One Love.flac May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand stop May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand stop took 2 milliseconds May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand clear May 24 20:55:43 volumio volumio[1145]: info: May 24 20:55:43 volumio volumio[1145]: ---------------------------- MPD announces system playlist update May 24 20:55:43 volumio volumio[1145]: info: Ignoring MPD Status Update May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand clear took 3 milliseconds May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand add "NAS/Media/FLAC/Now That's What I Call Music! 1-118 (1983-2024)/2002. Now That's What I Call Music! 53/CD1/06. Blue - One Love.flac" May 24 20:55:43 volumio volumio[1145]: error: updateQueue error: null May 24 20:55:43 volumio volumio[1145]: info: May 24 20:55:43 volumio volumio[1145]: ---------------------------- MPD announces system playlist update May 24 20:55:43 volumio volumio[1145]: info: Ignoring MPD Status Update May 24 20:55:43 volumio volumio[1145]: info: ------------------------------ 5ms May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand add "NAS/Media/FLAC/Now That's What I Call Music! 1-118 (1983-2024)/2002. Now That's What I Call Music! 53/CD1/06. Blue - One Love.flac" took 4 milliseconds May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand play May 24 20:55:43 volumio volumio[1145]: info: ------------------------------ 2ms May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand play took 1 milliseconds May 24 20:55:43 volumio kernel: bcm2835-i2s 3f203000.i2s: I2S SYNC error! May 24 20:55:43 volumio volumio[1145]: info: May 24 20:55:43 volumio volumio[1145]: ---------------------------- MPD announces state update: player May 24 20:55:43 volumio volumio[1145]: info: ControllerMpd::getState May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand status May 24 20:55:43 volumio volumio[1145]: info: May 24 20:55:43 volumio volumio[1145]: ---------------------------- MPD announces state update: player May 24 20:55:43 volumio volumio[1145]: info: ControllerMpd::getState May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand status May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand status took 3 milliseconds May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand status took 1 milliseconds May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::parseState May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::parseState May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand playlistinfo took 2 milliseconds May 24 20:55:43 volumio volumio[1145]: info: sendMpdCommand playlistinfo took 2 milliseconds May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::parseTrackInfo May 24 20:55:43 volumio volumio[1145]: verbose: ControllerMpd::parseTrackInfo May 24 20:55:43 volumio volumio[1145]: info: ControllerMpd::pushState May 24 20:55:43 volumio volumio[1145]: info: CoreCommandRouter::servicePushState May 24 20:55:43 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":206,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"One Love","artist":"Blue","album":"Now That's What I Call Music! 53","uri":"NAS/Media/FLAC/Now That's What I Call Music! 1-118 (1983-2024)/2002. Now That's What I Call Music! 53/CD1/06. Blue - One Love.flac","trackType":"flac"} May 24 20:55:43 volumio volumio[1145]: verbose: CURRENT POSITION 1964 May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::syncState stateService play May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::syncState currentStatus stop May 24 20:55:43 volumio volumio[1145]: info: ControllerMpd::pushState May 24 20:55:43 volumio volumio[1145]: info: CoreCommandRouter::servicePushState May 24 20:55:43 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":206,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"One Love","artist":"Blue","album":"Now That's What I Call Music! 53","uri":"NAS/Media/FLAC/Now That's What I Call Music! 1-118 (1983-2024)/2002. Now That's What I Call Music! 53/CD1/06. Blue - One Love.flac","trackType":"flac"} May 24 20:55:43 volumio volumio[1145]: verbose: CURRENT POSITION 1964 May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::syncState stateService play May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::syncState currentStatus play May 24 20:55:43 volumio volumio[1145]: info: Received an update from plugin. extracting info from payload May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::pushState May 24 20:55:43 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 20:55:43 volumio volumio[1145]: info: CoreCommandRouter::volumioPushState May 24 20:55:43 volumio volumio[1145]: info: CoreStateMachine::pushState May 24 20:55:43 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:43 volumio volumio[1145]: info: CoreCommandRouter::volumioPushState May 24 20:55:43 volumio volumio[1145]: info: ------------------------------ 21ms May 24 20:55:43 volumio volumio[1145]: info: ------------------------------ 28ms May 24 20:55:46 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:46 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:49 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 24 20:55:49 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 24 20:55:56 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:56 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:57 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:55:57 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:55:57 volumio volumio[1145]: info: Listing playlists May 24 20:55:57 volumio volumio[1145]: info: Listing playlists May 24 20:55:58 volumio volumio[1145]: info: CoreCommandRouter::volumioGetQueue May 24 20:55:58 volumio volumio[1145]: info: CoreStateMachine::getQueue May 24 20:55:58 volumio volumio[1145]: info: CorePlayQueue::getQueue May 24 20:56:00 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: radio_paradise , handleBrowseUri May 24 20:56:00 volumio volumio[1145]: info: Preload queue cleared May 24 20:56:04 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:56:04 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:56:07 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:56:07 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:56:13 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: rp2 , handleBrowseUri May 24 20:56:14 volumio volumio[1145]: info: Preload queue cleared May 24 20:56:17 volumio volumio[1145]: info: CoreCommandRouter::volumioGetState May 24 20:56:17 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:56:17 volumio volumio[1145]: info: Listing playlists May 24 20:56:17 volumio volumio[1145]: info: Listing playlists May 24 20:56:21 volumio volumio[1145]: info: Preload queue cleared May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::volumioReplaceandPlayItems May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::ClearQueue May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::stop May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::stPlaybackTimer May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::updateTrackBlock May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrackBlock May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::pushState May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::volumioPushState May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::serviceStop May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrack 1964 May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::serviceStop May 24 20:56:21 volumio volumio[1145]: info: ControllerMpd::stop May 24 20:56:21 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand stop May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::clearPlayQueue May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::saveQueue May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::volumioPushQueue May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::addQueueItems May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::addQueueItems May 24 20:56:21 volumio volumio[1145]: info: Preload queue cleared May 24 20:56:21 volumio volumio[1145]: info: Adding Item to queue: rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D0%22%2C%22name%22%3A%22The%20Main%20Mix%22%2C%22title%22%3A%22The%20Main%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F0%2Fcover_512x512%2F0.jpg%22%7D May 24 20:56:21 volumio volumio[1145]: info: Exploding uri rp2/channel@qi=%7B%22service%22%3A%22rp2%22%2C%22uri%22%3A%22rp2%2Fchannel%40id%3D0%22%2C%22name%22%3A%22The%20Main%20Mix%22%2C%22title%22%3A%22The%20Main%20Mix%22%2C%22artist%22%3A%22Radio%20Paradise%22%2C%22albumart%22%3A%22https%3A%2F%2Fimg.radioparadise.com%2Fchannels%2F0%2F0%2Fcover_512x512%2F0.jpg%22%7D in service rp2 May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::volumioPushQueue May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::saveQueue May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::updateTrackBlock May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrackBlock May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::volumioPlay May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::play index 0 May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::stop May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::play index undefined May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::setConsumeUpdateService undefined May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrack 0 May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::startPlaybackTimer May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrack 0 May 24 20:56:21 volumio volumio[1145]: info: [rp2] clearAddPlayTrack: rp2/channel@id=0 May 24 20:56:21 volumio volumio[1145]: info: May 24 20:56:21 volumio volumio[1145]: ---------------------------- MPD announces state update: player May 24 20:56:21 volumio volumio[1145]: info: sendMpdCommand stop took 51 milliseconds May 24 20:56:21 volumio volumio[1145]: info: ControllerMpd::getState May 24 20:56:21 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand status May 24 20:56:21 volumio volumio[1145]: info: sendMpdCommand status took 8 milliseconds May 24 20:56:21 volumio volumio[1145]: verbose: ControllerMpd::parseState May 24 20:56:21 volumio volumio[1145]: verbose: ControllerMpd::sendMpdCommand playlistinfo May 24 20:56:21 volumio volumio[1145]: info: sendMpdCommand playlistinfo took 2 milliseconds May 24 20:56:21 volumio volumio[1145]: verbose: ControllerMpd::parseTrackInfo May 24 20:56:21 volumio volumio[1145]: info: ControllerMpd::pushState May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::servicePushState May 24 20:56:21 volumio volumio[1145]: info: CoreStateMachine::pushState May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrack 0 May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 24 20:56:21 volumio volumio[1145]: info: CoreCommandRouter::volumioPushState May 24 20:56:21 volumio volumio[1145]: info: CorePlayQueue::getTrack 0 May 24 20:56:21 volumio volumio[1145]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current rp2 Received mpd May 24 20:56:21 volumio volumio[1145]: info: ------------------------------ 26ms May 24 20:56:21 volumio volumio[1145]: verbose: [rp2] API: https://api.radioparadise.com/api/play?source=24&event=0&elapsed=0&bitrate=4&action=start&player_id=********&info=true&chan=0&audio_type= May 24 20:56:22 volumio volumio[1145]: info: [rp2] Obtained block for channel "0" May 24 20:56:22 volumio volumio[1145]: info: [rp2] ------------- May 24 20:56:22 volumio volumio[1145]: info: [rp2] Block summary May 24 20:56:22 volumio volumio[1145]: info: [rp2] ------------- May 24 20:56:22 volumio volumio[1145]: info: [rp2] Stream URL: https://audio-geo.radioparadise.com/chan/0/x/1847/4/b/1847-0.flac May 24 20:56:22 volumio volumio[1145]: info: [rp2] Tracks: May 24 20:56:22 volumio volumio[1145]: info: [rp2] 0. Bad Neighbors (3:49 | elapsed: 22m 58s) May 24 20:56:22 volumio volumio[1145]: info: [rp2] 1. Animal Zoo (3:05 | elapsed: 26m 48s) May 24 20:56:22 volumio volumio[1145]: info: [rp2] May 24 20:56:22 volumio volumio[1145]: verbose: [rp2] Current track scheduled playback vs. current time: 5/24/2026, 8:52:40 PM <-> 5/24/2026, 8:56:22 PM May 24 20:56:22 volumio volumio[1145]: info: [rp2] Going to start playback of current track at 3:41 (track position in stream: 22:58) May 24 20:56:22 volumio volumio[1145]: info: [rp2] Starting mpv May 24 20:56:22 volumio volumio[1145]: /bin/sh: 1: mpv: not found May 24 20:56:22 volumio volumio[1145]: error: [rp2] [mpv] Failed to get mpv version: Command failed: mpv --version May 24 20:56:22 volumio volumio[1145]: /bin/sh: 1: mpv: not found May 24 20:56:22 volumio volumio[1145]: info: [rp2] [mpv] mpv process spawned May 24 20:56:22 volumio volumio[1145]: verbose: [rp2] Waiting for player event "playing"... May 24 20:56:22 volumio volumio[1145]: info: [rp2] [mpv] (PID: 7752) /bin/sh: 1: mpv: not found May 24 20:56:22 volumio volumio[1145]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 20:56:22 volumio volumio[1145]: TypeError: Cannot read properties of null (reading 'reset') May 24 20:56:22 volumio volumio[1145]: at /data/plugins/music_service/rp2/node_modules/volumio-ext-players/dist/mpv/MPVService.js:207:48 May 24 20:56:22 volumio volumio[1145]: at ChildProcess. (/data/plugins/music_service/rp2/node_modules/volumio-ext-players/dist/mpv/MPVService.js:221:19) May 24 20:56:22 volumio volumio[1145]: at ChildProcess.emit (node:events:514:28) May 24 20:56:22 volumio volumio[1145]: at maybeClose (node:internal/child_process:1105:16) May 24 20:56:22 volumio volumio[1145]: at Socket. (node:internal/child_process:457:11) May 24 20:56:22 volumio volumio[1145]: at Socket.emit (node:events:514:28) May 24 20:56:22 volumio volumio[1145]: at Pipe. (node:net:337:12) May 24 20:56:22 volumio volumio[1145]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 20:56:23 volumio sudo[7767]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-05-24 20:55' May 24 20:56:23 volumio sudo[7767]: 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"