Oct 16 16:28:11 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Oct 16 16:28:11 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Oct 16 16:28:11 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 16:28:11 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 16:28:11 volumio-3b volumio[1218]: info: Starting MyVolumio Remote Streaming Endpoints Oct 16 16:28:11 volumio-3b volumio[1218]: info: MyVolumio not started Oct 16 16:28:11 volumio-3b volumio[1218]: info: Initializing device activation check Oct 16 16:28:11 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Oct 16 16:28:11 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Oct 16 16:28:18 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Oct 16 16:28:18 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Oct 16 16:28:18 volumio-3b volumio[1218]: info: Streaming services startup Oct 16 16:28:18 volumio-3b volumio[1218]: info: Starting Streaming Daemon Oct 16 16:28:19 volumio-3b sudo[1781]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Oct 16 16:28:19 volumio-3b volumio[1218]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Oct 16 16:28:19 volumio-3b sudo[1781]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:19 volumio-3b sudo[1781]: pam_unix(sudo:session): session closed for user root Oct 16 16:28:19 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 16:28:19 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 16:28:19 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 16 16:28:20 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 16 16:28:20 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPlay Oct 16 16:28:20 volumio-3b volumio[1218]: info: CoreStateMachine::play index undefined Oct 16 16:28:20 volumio-3b volumio[1218]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 16 16:28:20 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:20 volumio-3b volumio[1218]: info: CoreStateMachine::startPlaybackTimer Oct 16 16:28:20 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:20 volumio-3b volumio[1218]: verbose: ControllerMpd::clearAddPlayTracks USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff Oct 16 16:28:20 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand stop Oct 16 16:28:20 volumio-3b volumio[1218]: error: Cannot start Volumio Streaming Daemon Oct 16 16:28:20 volumio-3b volumio[1218]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Oct 16 16:28:20 volumio-3b volumio[1218]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Oct 16 16:28:20 volumio-3b volumio[1218]: info: sendMpdCommand stop took 522 milliseconds Oct 16 16:28:20 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand clear Oct 16 16:28:21 volumio-3b volumio[1218]: info: Oct 16 16:28:21 volumio-3b volumio[1218]: ---------------------------- MPD announces system playlist update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Ignoring MPD Status Update Oct 16 16:28:21 volumio-3b volumio[1218]: info: sendMpdCommand clear took 174 milliseconds Oct 16 16:28:21 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand add "USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff" Oct 16 16:28:21 volumio-3b volumio[1218]: info: Oct 16 16:28:21 volumio-3b volumio[1218]: ---------------------------- MPD announces system playlist update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Ignoring MPD Status Update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Oct 16 16:28:21 volumio-3b volumio[1218]: ---------------------------- MPD announces system playlist update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Ignoring MPD Status Update Oct 16 16:28:21 volumio-3b volumio[1218]: error: updateQueue error: null Oct 16 16:28:21 volumio-3b volumio[1218]: info: Oct 16 16:28:21 volumio-3b volumio[1218]: ---------------------------- MPD announces system playlist update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Ignoring MPD Status Update Oct 16 16:28:21 volumio-3b volumio[1218]: info: ------------------------------ 340ms Oct 16 16:28:21 volumio-3b volumio[1218]: info: sendMpdCommand add "USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff" took 319 milliseconds Oct 16 16:28:21 volumio-3b volumio[1218]: info: ------------------------------ 298ms Oct 16 16:28:21 volumio-3b volumio[1218]: info: ------------------------------ 272ms Oct 16 16:28:21 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand play Oct 16 16:28:21 volumio-3b volumio[1218]: info: Oct 16 16:28:21 volumio-3b volumio[1218]: ---------------------------- MPD announces system playlist update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Ignoring MPD Status Update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Oct 16 16:28:21 volumio-3b volumio[1218]: ---------------------------- MPD announces system playlist update Oct 16 16:28:21 volumio-3b volumio[1218]: info: Ignoring MPD Status Update Oct 16 16:28:21 volumio-3b volumio[1218]: info: ------------------------------ 245ms Oct 16 16:28:21 volumio-3b volumio[1218]: info: sendMpdCommand play took 188 milliseconds Oct 16 16:28:21 volumio-3b volumio[1218]: info: ------------------------------ 131ms Oct 16 16:28:21 volumio-3b volumio[1218]: info: ------------------------------ 127ms Oct 16 16:28:22 volumio-3b volumio[1218]: info: Oct 16 16:28:22 volumio-3b volumio[1218]: ---------------------------- MPD announces state update: player Oct 16 16:28:22 volumio-3b volumio[1218]: info: ControllerMpd::getState Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand status Oct 16 16:28:22 volumio-3b volumio[1218]: info: Oct 16 16:28:22 volumio-3b volumio[1218]: ---------------------------- MPD announces state update: player Oct 16 16:28:22 volumio-3b volumio[1218]: info: ControllerMpd::getState Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand status Oct 16 16:28:22 volumio-3b volumio[1218]: info: Oct 16 16:28:22 volumio-3b volumio[1218]: ---------------------------- MPD announces state update: player Oct 16 16:28:22 volumio-3b volumio[1218]: info: Oct 16 16:28:22 volumio-3b volumio[1218]: ---------------------------- MPD announces state update: player Oct 16 16:28:22 volumio-3b volumio[1218]: info: ControllerMpd::getState Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand status Oct 16 16:28:22 volumio-3b volumio[1218]: info: sendMpdCommand status took 64 milliseconds Oct 16 16:28:22 volumio-3b volumio[1218]: info: ControllerMpd::getState Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand status Oct 16 16:28:22 volumio-3b volumio[1218]: info: sendMpdCommand status took 80 milliseconds Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::parseState Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::parseState Oct 16 16:28:22 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 16:28:22 volumio-3b volumio[1218]: info: CoreCommandRouter::Close All Modals sent Oct 16 16:28:22 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: appearance , setTOSAccepted Oct 16 16:28:23 volumio-3b volumio[1218]: info: Oct 16 16:28:23 volumio-3b volumio[1218]: ---------------------------- MPD announces state update: player Oct 16 16:28:23 volumio-3b volumio[1218]: info: ControllerMpd::getState Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand status Oct 16 16:28:23 volumio-3b volumio[1218]: info: Oct 16 16:28:23 volumio-3b volumio[1218]: ---------------------------- MPD announces state update: player Oct 16 16:28:23 volumio-3b volumio[1218]: info: ControllerMpd::getState Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand status Oct 16 16:28:23 volumio-3b volumio[1218]: info: sendMpdCommand status took 620 milliseconds Oct 16 16:28:23 volumio-3b volumio[1218]: info: sendMpdCommand status took 582 milliseconds Oct 16 16:28:23 volumio-3b volumio[1218]: info: sendMpdCommand playlistinfo took 563 milliseconds Oct 16 16:28:23 volumio-3b volumio[1218]: info: sendMpdCommand playlistinfo took 576 milliseconds Oct 16 16:28:23 volumio-3b volumio[1218]: info: sendMpdCommand status took 204 milliseconds Oct 16 16:28:23 volumio-3b volumio[1218]: info: sendMpdCommand status took 201 milliseconds Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::parseState Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::parseState Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::parseTrackInfo Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::parseTrackInfo Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::parseState Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::parseState Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: ControllerMpd::sendMpdCommand playlistinfo Oct 16 16:28:23 volumio-3b volumio[1218]: info: ControllerMpd::pushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreCommandRouter::servicePushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"BEYOND - 不可一世.dff","artist":null,"album":null,"uri":"USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff","trackType":"dff"} Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: CURRENT POSITION 0 Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreStateMachine::syncState stateService play Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreStateMachine::syncState currentStatus stop Oct 16 16:28:23 volumio-3b volumio[1218]: info: ControllerMpd::pushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreCommandRouter::servicePushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"BEYOND - 不可一世.dff","artist":null,"album":null,"uri":"USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff","trackType":"dff"} Oct 16 16:28:23 volumio-3b volumio[1218]: verbose: CURRENT POSITION 0 Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreStateMachine::syncState stateService play Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreStateMachine::syncState currentStatus play Oct 16 16:28:23 volumio-3b volumio[1218]: info: Received an update from plugin. extracting info from payload Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:23 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:23 volumio-3b volumio[1218]: info: ------------------------------ 1280ms Oct 16 16:28:23 volumio-3b volumio[1218]: info: ------------------------------ 1363ms Oct 16 16:28:24 volumio-3b volumio[1218]: info: sendMpdCommand playlistinfo took 898 milliseconds Oct 16 16:28:24 volumio-3b volumio[1218]: info: sendMpdCommand playlistinfo took 897 milliseconds Oct 16 16:28:24 volumio-3b volumio[1218]: info: sendMpdCommand playlistinfo took 832 milliseconds Oct 16 16:28:24 volumio-3b volumio[1218]: info: sendMpdCommand playlistinfo took 858 milliseconds Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: ControllerMpd::parseTrackInfo Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: ControllerMpd::parseTrackInfo Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: ControllerMpd::parseTrackInfo Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: ControllerMpd::parseTrackInfo Oct 16 16:28:24 volumio-3b volumio[1218]: info: ControllerMpd::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::servicePushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"BEYOND - 不可一世.dff","artist":null,"album":null,"uri":"USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff","trackType":"dff"} Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: CURRENT POSITION 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState stateService play Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState currentStatus play Oct 16 16:28:24 volumio-3b volumio[1218]: info: Received an update from plugin. extracting info from payload Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: ControllerMpd::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::servicePushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":254,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"BEYOND - 不可一世.dff","artist":null,"album":null,"uri":"USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff","trackType":"dff"} Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: CURRENT POSITION 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState stateService play Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState currentStatus play Oct 16 16:28:24 volumio-3b volumio[1218]: info: Received an update from plugin. extracting info from payload Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: ControllerMpd::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::servicePushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1209,"duration":254,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"5644 Kbps","isStreaming":false,"title":"BEYOND - 不可一世.dff","artist":null,"album":null,"uri":"USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff","trackType":"dff"} Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: CURRENT POSITION 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState stateService play Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState currentStatus play Oct 16 16:28:24 volumio-3b volumio[1218]: info: Received an update from plugin. extracting info from payload Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: ControllerMpd::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::servicePushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1209,"duration":254,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"5644 Kbps","isStreaming":false,"title":"BEYOND - 不可一世.dff","artist":null,"album":null,"uri":"USB/HIKSEMI/Shared Music/BEYOND - 不可一世.dff","trackType":"dff"} Oct 16 16:28:24 volumio-3b volumio[1218]: verbose: CURRENT POSITION 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState stateService play Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::syncState currentStatus play Oct 16 16:28:24 volumio-3b volumio[1218]: info: Received an update from plugin. extracting info from payload Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreStateMachine::pushState Oct 16 16:28:24 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:24 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioPushState Oct 16 16:28:25 volumio-3b volumio[1218]: info: ------------------------------ 2795ms Oct 16 16:28:25 volumio-3b volumio[1218]: info: ------------------------------ 2794ms Oct 16 16:28:25 volumio-3b volumio[1218]: info: ------------------------------ 2194ms Oct 16 16:28:25 volumio-3b volumio[1218]: info: ------------------------------ 2262ms Oct 16 16:28:26 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 16 16:28:27 volumio-3b volumio-remote-updater[754]: Test mode disabled Oct 16 16:28:27 volumio-3b volumio-remote-updater[754]: Alpha mode disabled Oct 16 16:28:27 volumio-3b volumio-remote-updater[754]: Alpha legacy test mode disabled Oct 16 16:28:27 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Oct 16 16:28:27 volumio-3b volumio[1218]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 16 16:28:28 volumio-3b volumio[1218]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Oct 16 16:28:28 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Oct 16 16:28:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:28:29 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:29 volumio-3b volumio[1218]: verbose: New Socket.io Connection to 192.168.4.24 from 192.168.4.88 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Oct 16 16:28:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:28:29 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:28:30 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetQueue Oct 16 16:28:30 volumio-3b volumio[1218]: info: CoreStateMachine::getQueue Oct 16 16:28:30 volumio-3b volumio[1218]: info: CorePlayQueue::getQueue Oct 16 16:28:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Oct 16 16:28:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getUpdaterChannel Oct 16 16:28:30 volumio-3b volumio[1218]: info: CALLMETHOD: music_service inputs serialMonitorAction [object Object] Oct 16 16:28:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: inputs , serialMonitorAction Oct 16 16:28:30 volumio-3b volumio[1218]: info: Error : CoreCommandRouter::executeOnPlugin: No method [serialMonitorAction] in plugin inputs Oct 16 16:28:30 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller motivocontrol displaySelection [object Object] Oct 16 16:28:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: motivocontrol , displaySelection Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetBrowseSources Oct 16 16:28:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 16 16:28:32 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller system setTestPlugins true Oct 16 16:28:32 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , setTestPlugins Oct 16 16:28:32 volumio-3b volumio[1218]: info: Plugins store is now in test mode Oct 16 16:28:33 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller system enableSSH true Oct 16 16:28:33 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , enableSSH Oct 16 16:28:33 volumio-3b sudo[1830]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start ssh.service Oct 16 16:28:34 volumio-3b sudo[1830]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:34 volumio-3b systemd[1]: Starting ssh.service - OpenBSD Secure Shell server... Oct 16 16:28:34 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller system setTestPlugins true Oct 16 16:28:34 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , setTestPlugins Oct 16 16:28:34 volumio-3b volumio[1218]: info: Plugins store is now in test mode Oct 16 16:28:34 volumio-3b sshd[1833]: Server listening on 0.0.0.0 port 22. Oct 16 16:28:34 volumio-3b sshd[1833]: Server listening on :: port 22. Oct 16 16:28:34 volumio-3b systemd[1]: Started ssh.service - OpenBSD Secure Shell server. Oct 16 16:28:34 volumio-3b sudo[1830]: pam_unix(sudo:session): session closed for user root Oct 16 16:28:35 volumio-3b sudo[1834]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable ssh.service Oct 16 16:28:35 volumio-3b sudo[1834]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:35 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller system enableSSH true Oct 16 16:28:35 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , enableSSH Oct 16 16:28:35 volumio-3b sudo[1840]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start ssh.service Oct 16 16:28:35 volumio-3b sudo[1840]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:35 volumio-3b sudo[1840]: pam_unix(sudo:session): session closed for user root Oct 16 16:28:36 volumio-3b sudo[1842]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable ssh.service Oct 16 16:28:36 volumio-3b sudo[1842]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:37 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller system setTestPlugins true Oct 16 16:28:37 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , setTestPlugins Oct 16 16:28:37 volumio-3b volumio[1218]: info: Plugins store is now in test mode Oct 16 16:28:37 volumio-3b volumio[1218]: info: CALLMETHOD: system_controller system enableSSH true Oct 16 16:28:37 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , enableSSH Oct 16 16:28:38 volumio-3b sudo[1850]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start ssh.service Oct 16 16:28:38 volumio-3b sudo[1850]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:38 volumio-3b sudo[1850]: pam_unix(sudo:session): session closed for user root Oct 16 16:28:38 volumio-3b sudo[1861]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl enable ssh.service Oct 16 16:28:38 volumio-3b sudo[1861]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Oct 16 16:28:39 volumio-3b systemd[1]: Reloading. Oct 16 16:28:39 volumio-3b volumio[1218]: error: MyVolumio Plugin failed to authenticate in a timely fashion Oct 16 16:28:39 volumio-3b volumio[1218]: info: Completed starting MyVolumio Plugin Oct 16 16:28:39 volumio-3b volumio[1218]: [Metrics] CommandRouter: 100s 489.93ms Oct 16 16:28:39 volumio-3b volumio[1218]: info: CoreCommandRouter::volumiosetStartupVolume Oct 16 16:28:39 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 16 16:28:39 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 16 16:28:39 volumio-3b volumio[1218]: info: CoreCommandRouter::Close All Modals sent Oct 16 16:28:39 volumio-3b volumio[1218]: info: CoreCommandRouter::Close All Modals sent Oct 16 16:28:40 volumio-3b volumio[1218]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Oct 16 16:28:40 volumio-3b volumio[1218]: aplay: main:831: audio open error: Device or resource busy Oct 16 16:28:40 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Oct 16 16:28:40 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Oct 16 16:28:40 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Oct 16 16:28:40 volumio-3b sshd[1871]: Accepted password for volumio from 192.168.4.88 port 57971 ssh2 Oct 16 16:28:40 volumio-3b sshd[1871]: pam_unix(sshd:session): session opened for user volumio(uid=1000) by (uid=0) Oct 16 16:28:42 volumio-3b systemd[1]: Reloading. Oct 16 16:28:46 volumio-3b volumio[1218]: info: BOOT COMPLETED Oct 16 16:28:46 volumio-3b systemd[1]: Reloading. Oct 16 16:28:50 volumio-3b systemd[1]: Reloading. Oct 16 16:28:54 volumio-3b systemd[1]: Reloading. Oct 16 16:28:58 volumio-3b systemd[1]: Reloading. Oct 16 16:29:01 volumio-3b systemd[1]: Reloading. Oct 16 16:29:01 volumio-3b sudo[1834]: pam_unix(sudo:session): session closed for user root Oct 16 16:29:01 volumio-3b volumio[1218]: info: enable SSH service success Oct 16 16:29:04 volumio-3b systemd[1]: Reloading. Oct 16 16:29:07 volumio-3b sudo[1842]: pam_unix(sudo:session): session closed for user root Oct 16 16:29:07 volumio-3b volumio[1218]: info: enable SSH service success Oct 16 16:29:08 volumio-3b systemd-logind[749]: New session 1 of user volumio. Oct 16 16:29:08 volumio-3b systemd[1]: Reloading. Oct 16 16:29:11 volumio-3b systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. Oct 16 16:29:11 volumio-3b sudo[1861]: pam_unix(sudo:session): session closed for user root Oct 16 16:29:11 volumio-3b volumio[1218]: info: enable SSH service success Oct 16 16:29:11 volumio-3b systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Oct 16 16:29:12 volumio-3b systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Oct 16 16:29:12 volumio-3b systemd[1]: Starting user@1000.service - User Manager for UID 1000... Oct 16 16:29:12 volumio-3b (systemd)[2135]: pam_unix(systemd-user:session): session opened for user volumio(uid=1000) by (uid=0) Oct 16 16:29:14 volumio-3b systemd[2135]: Queued start job for default target default.target. Oct 16 16:29:14 volumio-3b systemd[2135]: Created slice app.slice - User Application Slice. Oct 16 16:29:14 volumio-3b systemd[2135]: Reached target paths.target - Paths. Oct 16 16:29:14 volumio-3b systemd[2135]: Reached target timers.target - Timers. Oct 16 16:29:14 volumio-3b systemd[2135]: Listening on dirmngr.socket - GnuPG network certificate management daemon. Oct 16 16:29:14 volumio-3b systemd[2135]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Oct 16 16:29:14 volumio-3b systemd[2135]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Oct 16 16:29:14 volumio-3b systemd[2135]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Oct 16 16:29:14 volumio-3b systemd[2135]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Oct 16 16:29:14 volumio-3b systemd[2135]: Reached target sockets.target - Sockets. Oct 16 16:29:14 volumio-3b systemd[2135]: Reached target basic.target - Basic System. Oct 16 16:29:14 volumio-3b systemd[1]: Started user@1000.service - User Manager for UID 1000. Oct 16 16:29:14 volumio-3b systemd[2135]: Started mpris-proxy.service - Bluetooth mpris proxy. Oct 16 16:29:14 volumio-3b systemd[2135]: Reached target default.target - Main User Target. Oct 16 16:29:14 volumio-3b systemd[2135]: Startup finished in 1.938s. Oct 16 16:29:14 volumio-3b systemd[1]: Started session-1.scope - Session 1 of User volumio. Oct 16 16:29:14 volumio-3b systemd[2135]: mpris-proxy.service: Main process exited, code=exited, status=1/FAILURE Oct 16 16:29:15 volumio-3b mpris-proxy[2168]: Can't get on session bus Oct 16 16:29:14 volumio-3b systemd[2135]: mpris-proxy.service: Failed with result 'exit-code'. Oct 16 16:29:15 volumio-3b sshd[1871]: pam_env(sshd:session): deprecated reading of user environment enabled Oct 16 16:29:28 volumio-3b volumio[1218]: verbose: New Socket.io Connection to 192.168.4.24 from 192.168.4.88 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/132.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetVisibleSources Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:29:29 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Oct 16 16:29:29 volumio-3b volumio[1218]: info: Received Get System Info Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 16:29:29 volumio-3b volumio[1218]: info: Discovery: Getting this device information Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:29:29 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:29:29 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:29:29 volumio-3b volumio[1218]: info: Listing playlists Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Oct 16 16:29:29 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:29:29 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:29:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Oct 16 16:29:30 volumio-3b volumio[1218]: info: Received Get System Info Oct 16 16:29:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 16 16:29:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 16 16:29:30 volumio-3b volumio[1218]: info: Discovery: Getting this device information Oct 16 16:29:30 volumio-3b volumio[1218]: info: CoreCommandRouter::volumioGetState Oct 16 16:29:30 volumio-3b volumio[1218]: info: CorePlayQueue::getTrack 0 Oct 16 16:29:30 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 16 16:29:31 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Oct 16 16:29:38 volumio-3b volumio[1218]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Oct 16 16:29:42 volumio-3b volumio[1218]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 16 16:29:42 volumio-3b volumio[1218]: Error: connect ETIMEDOUT 128.242.240.180:443 Oct 16 16:29:42 volumio-3b volumio[1218]: at TCPConnectWrap.afterConnect [as oncomplete] (node:net:1595:16) { Oct 16 16:29:42 volumio-3b volumio[1218]: errno: -110, Oct 16 16:29:42 volumio-3b volumio[1218]: code: 'ETIMEDOUT', Oct 16 16:29:42 volumio-3b volumio[1218]: syscall: 'connect', Oct 16 16:29:42 volumio-3b volumio[1218]: address: '128.242.240.180', Oct 16 16:29:42 volumio-3b volumio[1218]: port: 443 Oct 16 16:29:42 volumio-3b volumio[1218]: } Oct 16 16:29:42 volumio-3b volumio[1218]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 16 16:29:50 volumio-3b sudo[2471]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-10-16 16:28' Oct 16 16:29:50 volumio-3b sudo[2471]: 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"