Jun 14 19:31:02 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Jun 14 19:31:02 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Streaming services startup Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Starting Streaming Daemon Jun 14 19:31:02 volumiopi4 sudo[1865]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 14 19:31:02 volumiopi4 sudo[1865]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:02 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Jun 14 19:31:02 volumiopi4 sudo[1865]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Jun 14 19:31:02 volumiopi4 volumio[1221]: info: AutoStart - Plugin is starting Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioGetQueue Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::getQueue Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CorePlayQueue::getQueue Jun 14 19:31:02 volumiopi4 volumio[1221]: info: AutoStart - start playing Jun 14 19:31:02 volumiopi4 volumio[1221]: info: AutoStart - start playing with no specific position Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPlay Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::play index 0 Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::stop Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::play index undefined Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CoreStateMachine::startPlaybackTimer Jun 14 19:31:02 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:02 volumiopi4 volumio[1221]: info: [1749922262618] ControllerWebradio::clearAddPlayTrack Jun 14 19:31:02 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand stop Jun 14 19:31:02 volumiopi4 volumio[1221]: info: sendMpdCommand stop took 17 milliseconds Jun 14 19:31:02 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand clear Jun 14 19:31:02 volumiopi4 volumio[1221]: error: Cannot start Volumio Streaming Daemon Jun 14 19:31:02 volumiopi4 volumio[1221]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 14 19:31:02 volumiopi4 volumio[1221]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Jun 14 19:31:02 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:02 volumiopi4 volumio[1221]: info: sendMpdCommand clear took 83 milliseconds Jun 14 19:31:02 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand load "http://www.1.fm/tunestream/caferadio/listen.pls" Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Jun 14 19:31:02 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Jun 14 19:31:02 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:02 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:02 volumiopi4 volumio[1221]: error: updateQueue error: null Jun 14 19:31:02 volumiopi4 volumio[1221]: info: ------------------------------ 24ms Jun 14 19:31:03 volumiopi4 volumio[1221]: error: MyVolumio Custom Token format not valid, refreshing it Jun 14 19:31:03 volumiopi4 volumio-remote-updater[679]: Test mode enabled Jun 14 19:31:03 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Jun 14 19:31:04 volumiopi4 volumio-remote-updater[679]: Alpha mode disabled Jun 14 19:31:04 volumiopi4 volumio-remote-updater[679]: Alpha legacy test mode disabled Jun 14 19:31:04 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jun 14 19:31:04 volumiopi4 volumio[1221]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Jun 14 19:31:04 volumiopi4 volumio[1221]: info: MyVolumio login type: Token Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Jun 14 19:31:05 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Jun 14 19:31:05 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioGetState Jun 14 19:31:05 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Jun 14 19:31:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:05 volumiopi4 volumio[1221]: info: sendMpdCommand load "http://www.1.fm/tunestream/caferadio/listen.pls" took 3165 milliseconds Jun 14 19:31:05 volumiopi4 volumio[1221]: info: ------------------------------ 3153ms Jun 14 19:31:05 volumiopi4 volumio[1221]: info: ------------------------------ 3152ms Jun 14 19:31:05 volumiopi4 volumio[1221]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 14 19:31:05 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand play Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Jun 14 19:31:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Jun 14 19:31:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:05 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:05 volumiopi4 volumio[1221]: info: ------------------------------ 19ms Jun 14 19:31:05 volumiopi4 volumio[1221]: info: sendMpdCommand play took 19 milliseconds Jun 14 19:31:05 volumiopi4 volumio[1221]: info: ------------------------------ 13ms Jun 14 19:31:05 volumiopi4 volumio[1221]: info: ------------------------------ 11ms Jun 14 19:31:06 volumiopi4 volumio[1221]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioGetBrowseSources Jun 14 19:31:10 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jun 14 19:31:10 volumiopi4 volumio[1221]: Upnp client error: Error: This socket has been ended by the other party Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand status took 193 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand status took 207 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand status took 207 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 13 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand status took 11 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Cafe Radio","artist":null,"album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus stop Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ------------------------------ 229ms Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Jun 14 19:31:14 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand status took 43 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 40 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 42 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 49 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: info: sendMpdCommand status took 32 milliseconds Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:14 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:14 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:14 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 448ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 447ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 251ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Jun 14 19:31:15 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Jun 14 19:31:15 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Jun 14 19:31:15 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Jun 14 19:31:15 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 273ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand status took 258 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 266ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand status took 255 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 241 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 236 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 61ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand status took 24 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 24ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand status took 23 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":884,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":884,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 412ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 397ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Jun 14 19:31:15 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Jun 14 19:31:15 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 193 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 204 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 205 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 204 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 89ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand status took 84 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":884,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":884,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1079,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1079,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 613ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 616ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 413ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 375ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: sendMpdCommand playlistinfo took 144 milliseconds Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseTrackInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ControllerMpd::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::servicePushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CorePlayQueue::getTrack 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1285,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"192 Kbps","isStreaming":false,"title":"Simply Red - Stars","artist":"caferadio","album":null,"uri":"http://strm112.1.fm:80/caferadio_mobile_mp3","trackType":""} Jun 14 19:31:15 volumiopi4 volumio[1221]: verbose: CURRENT POSITION 0 Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState stateService play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::syncState currentStatus play Jun 14 19:31:15 volumiopi4 volumio[1221]: info: Received an update from plugin. extracting info from payload Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:15 volumiopi4 volumio[1221]: info: ------------------------------ 288ms Jun 14 19:31:15 volumiopi4 volumio[1221]: info: touch_display: Setting screensaver timeout to 0 seconds. Jun 14 19:31:21 volumiopi4 volumio[1221]: info: MyVolumio token set successfully Jun 14 19:31:21 volumiopi4 volumio[1221]: info: MYVOLUMIO: Adding device Jun 14 19:31:21 volumiopi4 volumio[1221]: info: MYVOLUMIO: Evaluating Server Jun 14 19:31:23 volumiopi4 volumio[1221]: error: MyVolumio Plugin failed to authenticate in a timely fashion Jun 14 19:31:23 volumiopi4 volumio[1221]: info: Completed starting MyVolumio Plugin Jun 14 19:31:23 volumiopi4 volumio[1221]: [Metrics] CommandRouter: 87s 951.68ms Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumiosetStartupVolume Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jun 14 19:31:23 volumiopi4 volumio[1221]: info: VolumeController:: Setting startup Volume 50 Jun 14 19:31:23 volumiopi4 volumio[1221]: info: VolumeController::SetAlsaVolume50 Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::Close All Modals sent Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::Close All Modals sent Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreStateMachine::pushState Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 14 19:31:23 volumiopi4 volumio[1221]: info: CoreCommandRouter::volumioPushState Jun 14 19:31:23 volumiopi4 volumio[1221]: info: MyVolumio Plan changed: premium Jun 14 19:31:23 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Subscribed plan changed to premium Jun 14 19:31:23 volumiopi4 volumio[1221]: info: Removing browser output: myVolumio user plan is not superstar Jun 14 19:31:23 volumiopi4 volumio[1221]: info: Removing audio output: Jun 14 19:31:23 volumiopi4 volumio[1221]: info: MYVOLUMIO: Adding device Jun 14 19:31:23 volumiopi4 volumio[1221]: info: MYVOLUMIO: Evaluating Server Jun 14 19:31:23 volumiopi4 volumio[1221]: info: Remote config written successfully Jun 14 19:31:23 volumiopi4 volumio[1221]: info: Starting Tunnel 1 Jun 14 19:31:23 volumiopi4 volumio[1221]: info: Starting Tunnel Connection Checker Jun 14 19:31:24 volumiopi4 volumio[1221]: info: MYVolumio Device enabled Jun 14 19:31:24 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Device activated, enabling myvolumio plugins... Jun 14 19:31:24 volumiopi4 volumio[1221]: info: MyVolumio status changed Jun 14 19:31:24 volumiopi4 volumio[1221]: info: Streaming services startup Jun 14 19:31:24 volumiopi4 volumio[1221]: info: Starting Streaming Daemon Jun 14 19:31:24 volumiopi4 volumio[1221]: info: Setting Geolocation for MyVolumio to eu8 Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jun 14 19:31:24 volumiopi4 volumio[1221]: info: Setting Geolocation for MyVolumio to eu3 Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:24 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 volumio[1221]: info: Updating MyVolumio device info Jun 14 19:31:25 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 sudo[2024]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Jun 14 19:31:25 volumiopi4 sudo[2024]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:25 volumiopi4 volumio[1221]: info: Successfully Added MyVolumio device Jun 14 19:31:25 volumiopi4 volumio[1221]: info: Updating MyVolumio device info Jun 14 19:31:25 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jun 14 19:31:25 volumiopi4 systemd[1]: Starting setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service... Jun 14 19:31:25 volumiopi4 sudo[2024]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:25 volumiopi4 dbus-daemon[657]: [system] Activating via systemd: service name='org.freedesktop.timedate1' unit='dbus-org.freedesktop.timedate1.service' requested by ':1.45' (uid=0 pid=2032 comm="timedatectl show --property=NTPSynchronized --valu") Jun 14 19:31:25 volumiopi4 volumio[1221]: error: Cannot start Volumio Streaming Daemon Jun 14 19:31:25 volumiopi4 volumio[1221]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Jun 14 19:31:25 volumiopi4 volumio[1221]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Jun 14 19:31:25 volumiopi4 volumio[1221]: info: Successfully Updated MyVolumio device Jun 14 19:31:25 volumiopi4 volumio[1221]: info: Successfully Added MyVolumio device Jun 14 19:31:26 volumiopi4 systemd[1]: Starting systemd-timedated.service - Time & Date Service... Jun 14 19:31:26 volumiopi4 volumio[1221]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getHwuuid Jun 14 19:31:26 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Plugin music_service/qobuzconnect is enabled for this plan, but could not be found on the local filesystem! Jun 14 19:31:26 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "bluetooth"... Jun 14 19:31:26 volumiopi4 dbus-daemon[657]: [system] Successfully activated service 'org.freedesktop.timedate1' Jun 14 19:31:26 volumiopi4 systemd[1]: Started systemd-timedated.service - Time & Date Service. Jun 14 19:31:26 volumiopi4 setdatetime-helper.sh[2031]: Time is not synchronized. Attempting to sync... Jun 14 19:31:26 volumiopi4 sudo[2041]: root : PWD=/ ; USER=root ; COMMAND=/usr/bin/date -s 'Sat, 14 Jun 2025 17:31:26 GMT#015' Jun 14 19:31:26 volumiopi4 sudo[2041]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0) Jun 14 19:31:26 volumiopi4 setdatetime-helper.sh[2042]: Sat Jun 14 19:31:26 SAST 2025 Jun 14 19:31:26 volumiopi4 systemd-journald[341]: Time jumped backwards, rotating. Jun 14 19:31:26 volumiopi4 sudo[2041]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:26 volumiopi4 setdatetime-helper.sh[2031]: Time synchronized successfully. Jun 14 19:31:26 volumiopi4 systemd[1]: setdatetime-helper.timer.service: Deactivated successfully. Jun 14 19:31:26 volumiopi4 systemd[1]: Finished setdatetime-helper.timer.service - Volumio Time Sync Watchdog Service. Jun 14 19:31:26 volumiopi4 volumio[1221]: ------------------------------------ BT MESSAGE: [FUNC] onVolumioStart Jun 14 19:31:26 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "multiroom"... Jun 14 19:31:47 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin multiroom Jun 14 19:31:47 volumiopi4 sudo[2157]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -rf /tmp/multiroom Jun 14 19:31:47 volumiopi4 sudo[2157]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:47 volumiopi4 sudo[2157]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:48 volumiopi4 volumio[1221]: info: MRS: MultiRoom plugin initialized Jun 14 19:31:48 volumiopi4 volumio[1221]: info: MRS: STOPPING SNAPCLIENT Jun 14 19:31:48 volumiopi4 volumio[1221]: info: MRS: Snap server stop Jun 14 19:31:48 volumiopi4 sudo[2178]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapclient Jun 14 19:31:48 volumiopi4 sudo[2178]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:48 volumiopi4 volumio[1221]: info: MRS: STOPPING volumioStreaming Jun 14 19:31:48 volumiopi4 sudo[2178]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:48 volumiopi4 sudo[2183]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioSnapserver Jun 14 19:31:48 volumiopi4 sudo[2183]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:48 volumiopi4 sudo[2185]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop volumioStreaming Jun 14 19:31:48 volumiopi4 sudo[2185]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:48 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "metavolumio"... Jun 14 19:31:48 volumiopi4 sudo[2189]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/rm -f /tmp/hls/* Jun 14 19:31:48 volumiopi4 sudo[2189]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jun 14 19:31:48 volumiopi4 sudo[2183]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:48 volumiopi4 sudo[2189]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:48 volumiopi4 sudo[2185]: pam_unix(sudo:session): session closed for user root Jun 14 19:31:49 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "manifestui"... Jun 14 19:31:55 volumiopi4 systemd[1]: systemd-timedated.service: Deactivated successfully. Jun 14 19:31:56 volumiopi4 dbus-daemon[657]: [system] Connection has not authenticated soon enough, closing it (auth_timeout=30000ms, elapsed: 30002ms) Jun 14 19:32:03 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "cd_controller"... Jun 14 19:32:04 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "smart_inputs"... Jun 14 19:32:04 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "hi_res_audio"... Jun 14 19:32:04 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Applying required configuration parameters for plugin hi_res_audio Jun 14 19:32:05 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "tidal"... Jun 14 19:32:05 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "qobuz"... Jun 14 19:32:05 volumiopi4 volumio[1221]: info: [MyVolumio PluginManager] Loading plugin "tidalconnect"... Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Preparing to generate the ALSA configuration file Jun 14 19:32:05 volumiopi4 volumio[1221]: info: BOOT COMPLETED Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Successfully Updated MyVolumio device Jun 14 19:32:05 volumiopi4 volumio[1221]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Jun 14 19:32:05 volumiopi4 volumio[1221]: info: The plugin multiroom has an ALSA contribution file volumioMultiRoomServer.postMultiRoom.1000.conf Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Reading ALSA contributions from plugins. Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Jun 14 19:32:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Jun 14 19:32:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:32:05 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:32:05 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Jun 14 19:32:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Jun 14 19:32:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:32:05 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:32:05 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Jun 14 19:32:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces system playlist update Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Ignoring MPD Status Update Jun 14 19:32:05 volumiopi4 volumio[1221]: info: Jun 14 19:32:05 volumiopi4 volumio[1221]: ---------------------------- MPD announces state update: player Jun 14 19:32:05 volumiopi4 volumio[1221]: info: ControllerMpd::getState Jun 14 19:32:05 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand status Jun 14 19:32:05 volumiopi4 volumio[1221]: info: ------------------------------ 21ms Jun 14 19:32:05 volumiopi4 volumio[1221]: info: sendMpdCommand status took 20 milliseconds Jun 14 19:32:05 volumiopi4 volumio[1221]: info: ------------------------------ 3ms Jun 14 19:32:05 volumiopi4 volumio[1221]: verbose: ControllerMpd::parseState Jun 14 19:32:05 volumiopi4 volumio[1221]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 14 19:32:05 volumiopi4 volumio[1221]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 14 19:32:06 volumiopi4 volumio[1221]: Error: write EPIPE Jun 14 19:32:06 volumiopi4 volumio[1221]: at afterWriteDispatched (node:internal/stream_base_commons:160:15) Jun 14 19:32:06 volumiopi4 volumio[1221]: at writeGeneric (node:internal/stream_base_commons:151:3) Jun 14 19:32:06 volumiopi4 volumio[1221]: at Socket._writeGeneric (node:net:952:11) Jun 14 19:32:06 volumiopi4 volumio[1221]: at Socket._write (node:net:964:8) Jun 14 19:32:06 volumiopi4 volumio[1221]: at writeOrBuffer (node:internal/streams/writable:399:12) Jun 14 19:32:06 volumiopi4 volumio[1221]: at _write (node:internal/streams/writable:340:10) Jun 14 19:32:06 volumiopi4 volumio[1221]: at Writable.write (node:internal/streams/writable:344:10) Jun 14 19:32:06 volumiopi4 volumio[1221]: at auth (/myvolumio/plugins/audio_interface/bluetooth/node_modules/dbus-next/lib/handshake.js:67:10) Jun 14 19:32:06 volumiopi4 volumio[1221]: at Socket. (/myvolumio/plugins/audio_interface/bluetooth/node_modules/dbus-next/lib/connection.js:137:32) Jun 14 19:32:06 volumiopi4 volumio[1221]: at Object.onceWrapper (node:events:628:28) Jun 14 19:32:06 volumiopi4 volumio[1221]: at Socket.emit (node:events:514:28) Jun 14 19:32:06 volumiopi4 volumio[1221]: at PipeConnectWrap.afterConnect [as oncomplete] (node:net:1580:10) { Jun 14 19:32:06 volumiopi4 volumio[1221]: errno: -32, Jun 14 19:32:06 volumiopi4 volumio[1221]: code: 'EPIPE', Jun 14 19:32:06 volumiopi4 volumio[1221]: syscall: 'write' Jun 14 19:32:06 volumiopi4 volumio[1221]: } Jun 14 19:32:06 volumiopi4 volumio[1221]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 14 19:32:07 volumiopi4 sudo[2249]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-06-14 19:31' Jun 14 19:32:08 volumiopi4 sudo[2249]: 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="cee9bb5b0ee50e4898478097a64b5c6c77d5a212" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Sat Jun 14 07:24:14 UTC 2025" VOLUMIO_VERSION="4.012" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b365b054264e3ebc2709665da2b5d1ee"