Mar 27 21:12:20 volumio kernel: ata1.00: exception Emask 0x0 SAct 0x2 SErr 0x0 action 0x6 frozen Mar 27 21:12:20 volumio kernel: ata1.00: failed command: WRITE FPDMA QUEUED Mar 27 21:12:20 volumio kernel: ata1.00: cmd 61/02:08:22:f0:b6/00:00:00:00:00/40 tag 1 ncq dma 1024 out res 40/00:01:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout) Mar 27 21:12:20 volumio kernel: ata1.00: status: { DRDY } Mar 27 21:12:20 volumio kernel: ata1: hard resetting link Mar 27 21:12:20 volumio kernel: clocksource: Long readout interval, skipping watchdog check: cs_nsec: 8415986016 wd_nsec: 8415986362 Mar 27 21:12:20 volumio kernel: ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300) Mar 27 21:12:20 volumio kernel: ata1.00: LPM support broken, forcing max_power Mar 27 21:12:20 volumio kernel: ata1.00: LPM support broken, forcing max_power Mar 27 21:12:20 volumio kernel: ata1.00: configured for UDMA/100 Mar 27 21:12:20 volumio kernel: ata1: EH complete Mar 27 21:12:22 volumio volumio[972]: Searching plugin music_service/webradio Mar 27 21:12:22 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: webradio , search Mar 27 21:12:22 volumio volumio[972]: Searching plugin music_service/webradio Mar 27 21:12:22 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: webradio , search Mar 27 21:12:22 volumio volumio[972]: Searching plugin music_service/webradio Mar 27 21:12:22 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: webradio , search Mar 27 21:12:23 volumio volumio[972]: info: All search sources collected, pushing search results Mar 27 21:12:23 volumio volumio[972]: info: All search sources collected, pushing search results Mar 27 21:12:23 volumio volumio[972]: info: All search sources collected, pushing search results Mar 27 21:12:23 volumio volumio[972]: info: All search sources collected, pushing search results Mar 27 21:12:37 volumio volumio[972]: Searching plugin music_service/webradio Mar 27 21:12:37 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: webradio , search Mar 27 21:12:37 volumio volumio[972]: info: All search sources collected, pushing search results Mar 27 21:12:39 volumio volumio[972]: info: Preload queue cleared Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::volumioReplaceandPlayItems Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::ClearQueue Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::stop Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::clearPlayQueue Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::saveQueue Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::volumioPushQueue Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::addQueueItems Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::addQueueItems Mar 27 21:12:39 volumio volumio[972]: info: Preload queue cleared Mar 27 21:12:39 volumio volumio[972]: info: Adding Item to queue: http://opml.radiotime.com/Tune.ashx?id=s50411 Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: webradio , explodeUri Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::volumioPushQueue Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::saveQueue Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::updateTrackBlock Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrackBlock Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::volumioPlay Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::play index 0 Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::stop Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::play index undefined Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::setConsumeUpdateService undefined Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::startPlaybackTimer Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:39 volumio volumio[972]: info: [1774642359373] ControllerWebradio::clearAddPlayTrack Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand stop Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand stop took 0 milliseconds Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand clear Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:39 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand clear took 0 milliseconds Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand load "http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein" Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:39 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:39 volumio volumio[972]: error: updateQueue error: null Mar 27 21:12:39 volumio volumio[972]: error: updateQueue error: null Mar 27 21:12:39 volumio volumio[972]: info: ------------------------------ 310ms Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand add "http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein" Mar 27 21:12:39 volumio volumio[972]: info: ------------------------------ 310ms Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:39 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand add "http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein" took 0 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::setConsumeUpdateService mpd Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand play Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:39 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:39 volumio volumio[972]: info: ------------------------------ 1ms Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand play took 2 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: ------------------------------ 3ms Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces state update: player Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::getState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand status Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces state update: player Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::getState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand status Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces state update: player Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand status took 40 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::getState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand status Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 27 21:12:39 volumio volumio[972]: info: Mar 27 21:12:39 volumio volumio[972]: ---------------------------- MPD announces state update: player Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::getState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand status Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand status took 41 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand status took 1 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand playlistinfo took 2 milliseconds Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseTrackInfo Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::pushState Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::servicePushState Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:39 volumio volumio[972]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream.mp3?aggregator=tunein","artist":null,"album":null,"uri":"http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein","trackType":""} Mar 27 21:12:39 volumio volumio[972]: verbose: CURRENT POSITION 0 Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::syncState stateService play Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::syncState currentStatus stop Mar 27 21:12:39 volumio volumio[972]: info: ------------------------------ 43ms Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand status took 2 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 27 21:12:39 volumio volumio[972]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseState Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseTrackInfo Mar 27 21:12:39 volumio volumio[972]: verbose: ControllerMpd::parseTrackInfo Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::pushState Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::servicePushState Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:39 volumio volumio[972]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream.mp3?aggregator=tunein","artist":null,"album":null,"uri":"http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein","trackType":""} Mar 27 21:12:39 volumio volumio[972]: verbose: CURRENT POSITION 0 Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::syncState stateService play Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::syncState currentStatus play Mar 27 21:12:39 volumio volumio[972]: info: Received an update from plugin. extracting info from payload Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:39 volumio volumio[972]: info: ControllerMpd::pushState Mar 27 21:12:39 volumio volumio[972]: info: CoreCommandRouter::servicePushState Mar 27 21:12:39 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:39 volumio volumio[972]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream.mp3?aggregator=tunein","artist":null,"album":null,"uri":"http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein","trackType":""} Mar 27 21:12:39 volumio volumio[972]: verbose: CURRENT POSITION 0 Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::syncState stateService play Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::syncState currentStatus play Mar 27 21:12:39 volumio volumio[972]: info: Received an update from plugin. extracting info from payload Mar 27 21:12:39 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 52ms Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 12ms Mar 27 21:12:40 volumio volumio[972]: info: sendMpdCommand playlistinfo took 10 milliseconds Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::parseTrackInfo Mar 27 21:12:40 volumio volumio[972]: info: ControllerMpd::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::servicePushState Mar 27 21:12:40 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:40 volumio volumio[972]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"stream.mp3?aggregator=tunein","artist":null,"album":null,"uri":"http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein","trackType":""} Mar 27 21:12:40 volumio volumio[972]: verbose: CURRENT POSITION 0 Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::syncState stateService play Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::syncState currentStatus play Mar 27 21:12:40 volumio volumio[972]: info: Received an update from plugin. extracting info from payload Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 16ms Mar 27 21:12:40 volumio volumio[972]: info: Mar 27 21:12:40 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:40 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:40 volumio volumio[972]: info: Mar 27 21:12:40 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:40 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:40 volumio volumio[972]: info: Mar 27 21:12:40 volumio volumio[972]: ---------------------------- MPD announces state update: player Mar 27 21:12:40 volumio volumio[972]: info: ControllerMpd::getState Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand status Mar 27 21:12:40 volumio volumio[972]: info: Mar 27 21:12:40 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:40 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:40 volumio volumio[972]: info: Mar 27 21:12:40 volumio volumio[972]: ---------------------------- MPD announces state update: player Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 2ms Mar 27 21:12:40 volumio volumio[972]: info: ControllerMpd::getState Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand status Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 1ms Mar 27 21:12:40 volumio volumio[972]: info: Mar 27 21:12:40 volumio volumio[972]: ---------------------------- MPD announces system playlist update Mar 27 21:12:40 volumio volumio[972]: info: Ignoring MPD Status Update Mar 27 21:12:40 volumio volumio[972]: info: sendMpdCommand status took 1 milliseconds Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::parseState Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 2ms Mar 27 21:12:40 volumio volumio[972]: info: sendMpdCommand status took 2 milliseconds Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 2ms Mar 27 21:12:40 volumio volumio[972]: info: sendMpdCommand playlistinfo took 1 milliseconds Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::parseState Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::sendMpdCommand playlistinfo Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::parseTrackInfo Mar 27 21:12:40 volumio volumio[972]: info: ControllerMpd::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::servicePushState Mar 27 21:12:40 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:40 volumio volumio[972]: verbose: STATE SERVICE {"status":"play","position":0,"seek":649,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Heaven 17 - Temptation ","artist":"Bremen Eins","album":null,"uri":"http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein","trackType":""} Mar 27 21:12:40 volumio volumio[972]: verbose: CURRENT POSITION 0 Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::syncState stateService play Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::syncState currentStatus play Mar 27 21:12:40 volumio volumio[972]: info: Received an update from plugin. extracting info from payload Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 8ms Mar 27 21:12:40 volumio volumio[972]: info: sendMpdCommand playlistinfo took 6 milliseconds Mar 27 21:12:40 volumio volumio[972]: verbose: ControllerMpd::parseTrackInfo Mar 27 21:12:40 volumio volumio[972]: info: ControllerMpd::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::servicePushState Mar 27 21:12:40 volumio volumio[972]: info: CorePlayQueue::getTrack 0 Mar 27 21:12:40 volumio volumio[972]: verbose: STATE SERVICE {"status":"play","position":0,"seek":649,"duration":0,"samplerate":"48 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"Heaven 17 - Temptation ","artist":"Bremen Eins","album":null,"uri":"http://icecast.radiobremen.de/rb/bremeneins/live/mp3/128/stream.mp3?aggregator=tunein","trackType":""} Mar 27 21:12:40 volumio volumio[972]: verbose: CURRENT POSITION 0 Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::syncState stateService play Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::syncState currentStatus play Mar 27 21:12:40 volumio volumio[972]: info: Received an update from plugin. extracting info from payload Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: CoreStateMachine::pushState Mar 27 21:12:40 volumio volumio[972]: info: CoreCommandRouter::volumioPushState Mar 27 21:12:40 volumio volumio[972]: info: ------------------------------ 14ms Mar 27 21:12:42 volumio volumio[972]: info: CoreCommandRouter::volumioGetState Mar 27 21:12:53 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:12:53 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 27 21:13:03 volumio volumio[972]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/now_playing/volumio/bookworm/amd64 Mar 27 21:13:03 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:03.616Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:05 volumio volumio[972]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/now_playing/volumio/bookworm/amd64 Mar 27 21:13:05 volumio volumio[972]: info: Folder /tmp/plugins removed Mar 27 21:13:05 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:05.819Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:06.135Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio volumio[972]: info: Check plugin dependencies Mar 27 21:13:06 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 27 21:13:06 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:06.178Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio volumio[972]: info: Checking if plugin already exists Mar 27 21:13:06 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:06.180Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio volumio[972]: info: Rename folder Mar 27 21:13:06 volumio volumio[972]: info: Folder /tmp/downloaded_plugin.zip removed Mar 27 21:13:06 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:06.196Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio volumio[972]: info: Move to category Mar 27 21:13:06 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:06.441Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio volumio[972]: info: Checking if install.sh is present Mar 27 21:13:06 volumio volumio[972]: info: Executing install.sh Mar 27 21:13:06 volumio sudo[3549]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/now_playing/install.sh Mar 27 21:13:06 volumio sudo[3549]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Mar 27 21:13:06 volumio volumio[972]: info: Installing geo-tz node dependency Mar 27 21:13:06 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:06.517Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:06 volumio su[3552]: (to volumio) root on none Mar 27 21:13:06 volumio su[3552]: pam_unix(su:session): session opened for user volumio(uid=1000) by (uid=0) Mar 27 21:13:06 volumio systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. Mar 27 21:13:06 volumio systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Mar 27 21:13:06 volumio systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Mar 27 21:13:06 volumio systemd[1]: Starting user@1000.service - User Manager for UID 1000... Mar 27 21:13:06 volumio (systemd)[3554]: pam_unix(systemd-user:session): session opened for user volumio(uid=1000) by (uid=0) Mar 27 21:13:06 volumio systemd[3554]: Queued start job for default target default.target. Mar 27 21:13:06 volumio systemd[3554]: Created slice app.slice - User Application Slice. Mar 27 21:13:06 volumio systemd[3554]: Reached target paths.target - Paths. Mar 27 21:13:06 volumio systemd[3554]: Reached target timers.target - Timers. Mar 27 21:13:06 volumio systemd[3554]: Starting dbus.socket - D-Bus User Message Bus Socket... Mar 27 21:13:06 volumio systemd[3554]: Listening on dirmngr.socket - GnuPG network certificate management daemon. Mar 27 21:13:06 volumio systemd[3554]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Mar 27 21:13:06 volumio systemd[3554]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Mar 27 21:13:06 volumio systemd[3554]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Mar 27 21:13:06 volumio systemd[3554]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Mar 27 21:13:06 volumio systemd[3554]: Listening on dbus.socket - D-Bus User Message Bus Socket. Mar 27 21:13:06 volumio systemd[3554]: Reached target sockets.target - Sockets. Mar 27 21:13:06 volumio systemd[3554]: Reached target basic.target - Basic System. Mar 27 21:13:06 volumio systemd[1]: Started user@1000.service - User Manager for UID 1000. Mar 27 21:13:06 volumio systemd[1]: Started session-c1.scope - Session c1 of User volumio. Mar 27 21:13:06 volumio systemd[3554]: Started mpris-proxy.service - Bluetooth mpris proxy. Mar 27 21:13:06 volumio systemd[3554]: Reached target default.target - Main User Target. Mar 27 21:13:06 volumio systemd[3554]: Startup finished in 218ms. Mar 27 21:13:06 volumio systemd[3554]: Created slice session.slice - User Core Session Slice. Mar 27 21:13:06 volumio systemd[3554]: Starting dbus.service - D-Bus User Message Bus... Mar 27 21:13:06 volumio systemd[3554]: Started dbus.service - D-Bus User Message Bus. Mar 27 21:13:12 volumio su[3552]: pam_unix(su:session): session closed for user volumio Mar 27 21:13:12 volumio systemd[1]: session-c1.scope: Deactivated successfully. Mar 27 21:13:12 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:12.139Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:12 volumio volumio[972]: info: Creating user directories (if not exist) Mar 27 21:13:12 volumio systemd[1]: session-c1.scope: Consumed 7.668s CPU time. Mar 27 21:13:12 volumio sudo[3549]: pam_unix(sudo:session): session closed for user root Mar 27 21:13:12 volumio volumio[972]: info: Install script completed Mar 27 21:13:12 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:12.159Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:12 volumio volumio[972]: info: Adding reference to registry Mar 27 21:13:12 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:12.165Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:12 volumio volumio[972]: info: Done installing plugin. Mar 27 21:13:12 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:13:12 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 27 21:13:12 volumio volumio[972]: info: Folder /tmp/plugins removed Mar 27 21:13:12 volumio volumio[972]: info: Folder /tmp/downloaded_plugin.zip removed Mar 27 21:13:12 volumio volumio[972]: info: Now Playing plugin installed Mar 27 21:13:12 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:12.192Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:12 volumio volumio[972]: Plugin install end detected on script Mar 27 21:13:12 volumio volumio[972]: info: Folder /data/temp removed Mar 27 21:13:21 volumio volumio[972]: info: Enabling plugin now_playing Mar 27 21:13:21 volumio volumio[972]: info: Loading plugin "now_playing"... Mar 27 21:13:21 volumio volumio[972]: error: !!!! WARNING !!!! Mar 27 21:13:21 volumio volumio[972]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Mar 27 21:13:21 volumio volumio[972]: Require stack: Mar 27 21:13:21 volumio volumio[972]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 27 21:13:21 volumio volumio[972]: - /volumio/app/pluginmanager.js Mar 27 21:13:21 volumio volumio[972]: - /volumio/app/index.js Mar 27 21:13:21 volumio volumio[972]: - /volumio/index.js Mar 27 21:13:21 volumio volumio[972]: error: Stack trace: Error: Cannot find module 'geo-tz' Mar 27 21:13:21 volumio volumio[972]: Require stack: Mar 27 21:13:21 volumio volumio[972]: - /data/plugins/user_interface/now_playing/dist/index.js Mar 27 21:13:21 volumio volumio[972]: - /volumio/app/pluginmanager.js Mar 27 21:13:21 volumio volumio[972]: - /volumio/app/index.js Mar 27 21:13:21 volumio volumio[972]: - /volumio/index.js Mar 27 21:13:21 volumio volumio[972]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Mar 27 21:13:21 volumio volumio[972]: at Module._load (node:internal/modules/cjs/loader:901:27) Mar 27 21:13:21 volumio volumio[972]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 27 21:13:21 volumio volumio[972]: at require (node:internal/modules/helpers:130:18) Mar 27 21:13:21 volumio volumio[972]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Mar 27 21:13:21 volumio volumio[972]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Mar 27 21:13:21 volumio volumio[972]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Mar 27 21:13:21 volumio volumio[972]: at Module.load (node:internal/modules/cjs/loader:1091:32) Mar 27 21:13:21 volumio volumio[972]: at Module._load (node:internal/modules/cjs/loader:938:12) Mar 27 21:13:21 volumio volumio[972]: at Module.require (node:internal/modules/cjs/loader:1115:19) Mar 27 21:13:21 volumio volumio[972]: at require (node:internal/modules/helpers:130:18) Mar 27 21:13:21 volumio volumio[972]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Mar 27 21:13:21 volumio volumio[972]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Mar 27 21:13:21 volumio volumio[972]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Mar 27 21:13:21 volumio volumio[972]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Mar 27 21:13:21 volumio volumio[972]: error: !!!! WARNING !!!! Mar 27 21:13:21 volumio volumio[972]: info: Done. Mar 27 21:13:22 volumio systemd[1]: Stopping user@1000.service - User Manager for UID 1000... Mar 27 21:13:22 volumio systemd[3554]: Activating special unit exit.target... Mar 27 21:13:22 volumio systemd[3554]: Stopped target default.target - Main User Target. Mar 27 21:13:22 volumio systemd[3554]: Stopping mpris-proxy.service - Bluetooth mpris proxy... Mar 27 21:13:22 volumio mpris-proxy[3570]: org.bluez appeared Mar 27 21:13:22 volumio mpris-proxy[3570]: org.bluez disappeared Mar 27 21:13:22 volumio systemd[3554]: Stopped mpris-proxy.service - Bluetooth mpris proxy. Mar 27 21:13:22 volumio systemd[3554]: Stopping dbus.service - D-Bus User Message Bus... Mar 27 21:13:22 volumio systemd[3554]: Stopped dbus.service - D-Bus User Message Bus. Mar 27 21:13:22 volumio systemd[3554]: Removed slice session.slice - User Core Session Slice. Mar 27 21:13:22 volumio systemd[3554]: Stopped target basic.target - Basic System. Mar 27 21:13:22 volumio systemd[3554]: Stopped target paths.target - Paths. Mar 27 21:13:22 volumio systemd[3554]: Stopped target sockets.target - Sockets. Mar 27 21:13:22 volumio systemd[3554]: Stopped target timers.target - Timers. Mar 27 21:13:22 volumio systemd[3554]: Closed dbus.socket - D-Bus User Message Bus Socket. Mar 27 21:13:22 volumio systemd[3554]: Closed dirmngr.socket - GnuPG network certificate management daemon. Mar 27 21:13:22 volumio systemd[3554]: Closed gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Mar 27 21:13:22 volumio systemd[3554]: Closed gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Mar 27 21:13:22 volumio systemd[3554]: Closed gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Mar 27 21:13:22 volumio systemd[3554]: Closed gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Mar 27 21:13:22 volumio systemd[3554]: Removed slice app.slice - User Application Slice. Mar 27 21:13:22 volumio systemd[3554]: Reached target shutdown.target - Shutdown. Mar 27 21:13:22 volumio systemd[3554]: Finished systemd-exit.service - Exit the Session. Mar 27 21:13:22 volumio systemd[3554]: Reached target exit.target - Exit the Session. Mar 27 21:13:22 volumio systemd[1]: user@1000.service: Deactivated successfully. Mar 27 21:13:22 volumio systemd[1]: Stopped user@1000.service - User Manager for UID 1000. Mar 27 21:13:22 volumio systemd[1]: Stopping user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Mar 27 21:13:22 volumio systemd[1]: run-user-1000.mount: Deactivated successfully. Mar 27 21:13:22 volumio systemd[1]: user-runtime-dir@1000.service: Deactivated successfully. Mar 27 21:13:22 volumio systemd[1]: Stopped user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Mar 27 21:13:22 volumio systemd[1]: Removed slice user-1000.slice - User Slice of UID 1000. Mar 27 21:13:22 volumio systemd[1]: user-1000.slice: Consumed 7.917s CPU time. Mar 27 21:13:24 volumio volumio[972]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 27 21:13:26 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 27 21:13:26 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 27 21:13:32 volumio volumio[972]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 27 21:13:34 volumio volumio[972]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/download/now_playing/1.0.6/volumio/bookworm/amd64 Mar 27 21:13:34 volumio volumio5-onboarding[1391]: time=2026-03-27T20:13:34.372Z level=WARN msg="received plugin install progress but no plugin is being installed" component=state Mar 27 21:13:34 volumio volumio[972]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 21:13:34 volumio volumio[972]: TypeError: Cannot read properties of null (reading 'broadcastMessage') Mar 27 21:13:34 volumio volumio[972]: at /volumio/app/index.js:1534:32 Mar 27 21:13:34 volumio volumio[972]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Mar 27 21:13:34 volumio volumio[972]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Mar 27 21:13:34 volumio volumio[972]: at CoreCommandRouter.broadcastMessage (/volumio/app/index.js:1532:13) Mar 27 21:13:34 volumio volumio[972]: at PluginManager.pushMessage (/volumio/app/pluginmanager.js:1594:20) Mar 27 21:13:34 volumio volumio[972]: at PluginManager.installPlugin (/volumio/app/pluginmanager.js:776:8) Mar 27 21:13:34 volumio volumio[972]: at CoreCommandRouter.installPlugin (/volumio/app/index.js:1453:22) Mar 27 21:13:34 volumio volumio[972]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1220:47) Mar 27 21:13:34 volumio volumio[972]: at Socket.emit (node:events:514:28) Mar 27 21:13:34 volumio volumio[972]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Mar 27 21:13:34 volumio volumio[972]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Mar 27 21:13:34 volumio volumio[972]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 27 21:13:34 volumio sudo[3689]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-03-27 21:12' Mar 27 21:13:34 volumio sudo[3689]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="18952480e8d8c63f22208e9007a0f47a9563eae6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="0e58f1861fa88e02087981b8d91f7511f0e7011b" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue Mar 24 17:45:45 UTC 2026" VOLUMIO_VERSION="4.119" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="6bf7cd61fe53483b72878254df87f1c0"