-- Logs begin at Fri 2024-03-22 17:18:45 CST, end at Thu 2024-04-11 15:51:58 CST. -- Apr 11 15:50:15 volumio volumio[5527]: info: CoreCommandRouter::volumioNext Apr 11 15:50:15 volumio volumio[5527]: info: CoreStateMachine::next Apr 11 15:50:15 volumio volumio[5527]: info: ControllerMpd::next Apr 11 15:50:15 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand next Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand next took 212 milliseconds Apr 11 15:50:16 volumio volumio[5527]: info: Apr 11 15:50:16 volumio volumio[5527]: ---------------------------- MPD announces state update: player Apr 11 15:50:16 volumio volumio[5527]: info: ControllerMpd::getState Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand status Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand status took 5 milliseconds Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::parseState Apr 11 15:50:16 volumio volumio[5527]: info: ControllerMpd::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::servicePushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 0 Apr 11 15:50:16 volumio volumio[5527]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 11 15:50:16 volumio volumio[5527]: verbose: CURRENT POSITION 0 Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::syncState stateService stop Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::syncState currentStatus play Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::play index undefined Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 1 Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 1 Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::startPlaybackTimer Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 1 Apr 11 15:50:16 volumio volumio[5527]: info: [1712821816200] ControllerUPNPBrowser::clearAddPlayTrack Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand stop Apr 11 15:50:16 volumio volumio[5527]: info: ------------------------------ 67ms Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 1 Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand stop took 25 milliseconds Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand clear Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::volumioGetQueue Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::getQueue Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getQueue Apr 11 15:50:16 volumio volumio[5527]: info: Apr 11 15:50:16 volumio volumio[5527]: ---------------------------- MPD announces system playlist update Apr 11 15:50:16 volumio volumio[5527]: info: Ignoring MPD Status Update Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand clear took 25 milliseconds Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.23.23:50002/m/NDLNA/4551.dff" Apr 11 15:50:16 volumio volumio[5527]: error: updateQueue error: null Apr 11 15:50:16 volumio volumio[5527]: info: ------------------------------ 19ms Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.23.23:50002/m/NDLNA/4551.dff" Apr 11 15:50:16 volumio volumio[5527]: info: Apr 11 15:50:16 volumio volumio[5527]: ---------------------------- MPD announces system playlist update Apr 11 15:50:16 volumio volumio[5527]: info: Ignoring MPD Status Update Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand add "http://192.168.23.23:50002/m/NDLNA/4551.dff" took 5 milliseconds Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand play Apr 11 15:50:16 volumio volumio[5527]: info: ------------------------------ 10ms Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand play took 5 milliseconds Apr 11 15:50:16 volumio volumio[5527]: info: Apr 11 15:50:16 volumio volumio[5527]: ---------------------------- MPD announces state update: player Apr 11 15:50:16 volumio kernel: [SNDCODEC][sunxi_card_hw_params][614]:invalid rate setting Apr 11 15:50:16 volumio kernel: sunxi-codec-machine 2030340.sound: ASoC: machine hw_params failed: -22 Apr 11 15:50:16 volumio volumio[5527]: info: ControllerMpd::getState Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand status Apr 11 15:50:16 volumio volumio[5527]: info: Apr 11 15:50:16 volumio volumio[5527]: ---------------------------- MPD announces state update: player Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand clearerror Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand status took 25 milliseconds Apr 11 15:50:16 volumio volumio[5527]: info: ControllerMpd::getState Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand status Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::parseState Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand clearerror took 16 milliseconds Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand status took 11 milliseconds Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand playlistinfo took 8 milliseconds Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::parseState Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::parseTrackInfo Apr 11 15:50:16 volumio volumio[5527]: info: ControllerMpd::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::servicePushState Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 1 Apr 11 15:50:16 volumio volumio[5527]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":265,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4551.dff","artist":null,"album":null,"uri":"http://192.168.23.23:50002/m/NDLNA/4551.dff","trackType":"dff"} Apr 11 15:50:16 volumio volumio[5527]: verbose: CURRENT POSITION 1 Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::syncState stateService pause Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::syncState currentStatus stop Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:16 volumio volumio[5527]: info: ------------------------------ 80ms Apr 11 15:50:16 volumio volumio[5527]: info: sendMpdCommand playlistinfo took 35 milliseconds Apr 11 15:50:16 volumio volumio[5527]: verbose: ControllerMpd::parseTrackInfo Apr 11 15:50:16 volumio volumio[5527]: info: ControllerMpd::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::servicePushState Apr 11 15:50:16 volumio volumio[5527]: info: CorePlayQueue::getTrack 1 Apr 11 15:50:16 volumio volumio[5527]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":265,"samplerate":"2.82 MHz","bitdepth":"1 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4551.dff","artist":null,"album":null,"uri":"http://192.168.23.23:50002/m/NDLNA/4551.dff","trackType":"dff"} Apr 11 15:50:16 volumio volumio[5527]: verbose: CURRENT POSITION 1 Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::syncState stateService pause Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::syncState currentStatus stop Apr 11 15:50:16 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:16 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:16 volumio volumio[5527]: info: ------------------------------ 98ms Apr 11 15:50:19 volumio volumio[5527]: info: CoreCommandRouter::volumioPlay Apr 11 15:50:19 volumio volumio[5527]: verbose: UNSET VOLATILE Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::play index 3 Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::stop Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 11 15:50:19 volumio volumio[5527]: verbose: UNSET VOLATILE Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::play index undefined Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 11 15:50:19 volumio volumio[5527]: info: CorePlayQueue::getTrack 3 Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::startPlaybackTimer Apr 11 15:50:19 volumio volumio[5527]: info: CorePlayQueue::getTrack 3 Apr 11 15:50:19 volumio volumio[5527]: info: [1712821819830] ControllerUPNPBrowser::clearAddPlayTrack Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand stop Apr 11 15:50:19 volumio volumio[5527]: info: Apr 11 15:50:19 volumio volumio[5527]: ---------------------------- MPD announces state update: player Apr 11 15:50:19 volumio volumio[5527]: info: sendMpdCommand stop took 15 milliseconds Apr 11 15:50:19 volumio volumio[5527]: info: ControllerMpd::getState Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand status Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand clear Apr 11 15:50:19 volumio volumio[5527]: info: Apr 11 15:50:19 volumio volumio[5527]: ---------------------------- MPD announces system playlist update Apr 11 15:50:19 volumio volumio[5527]: info: Ignoring MPD Status Update Apr 11 15:50:19 volumio volumio[5527]: info: sendMpdCommand status took 8 milliseconds Apr 11 15:50:19 volumio volumio[5527]: info: sendMpdCommand clear took 8 milliseconds Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::parseState Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand load "http://192.168.23.23:50002/m/NDLNA/4584.ape" Apr 11 15:50:19 volumio volumio[5527]: error: updateQueue error: null Apr 11 15:50:19 volumio volumio[5527]: info: ------------------------------ 17ms Apr 11 15:50:19 volumio volumio[5527]: info: sendMpdCommand playlistinfo took 10 milliseconds Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::parseTrackInfo Apr 11 15:50:19 volumio volumio[5527]: error: ControllerMpd::pushError: TypeError: Cannot read property 'split' of undefined Apr 11 15:50:19 volumio volumio[5527]: info: ------------------------------ 30ms Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand add "http://192.168.23.23:50002/m/NDLNA/4584.ape" Apr 11 15:50:19 volumio volumio[5527]: info: Apr 11 15:50:19 volumio volumio[5527]: ---------------------------- MPD announces system playlist update Apr 11 15:50:19 volumio volumio[5527]: info: Ignoring MPD Status Update Apr 11 15:50:19 volumio volumio[5527]: info: sendMpdCommand add "http://192.168.23.23:50002/m/NDLNA/4584.ape" took 17 milliseconds Apr 11 15:50:19 volumio volumio[5527]: info: CoreStateMachine::setConsumeUpdateService mpd Apr 11 15:50:19 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand play Apr 11 15:50:19 volumio volumio[5527]: info: ------------------------------ 31ms Apr 11 15:50:19 volumio volumio[5527]: info: sendMpdCommand play took 13 milliseconds Apr 11 15:50:20 volumio volumio[5527]: info: Apr 11 15:50:20 volumio volumio[5527]: ---------------------------- MPD announces state update: player Apr 11 15:50:20 volumio volumio[5527]: info: ControllerMpd::getState Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand status Apr 11 15:50:20 volumio kernel: [SNDCODEC][sunxi_card_hw_params][620]:stream_flag: 0 Apr 11 15:50:20 volumio volumio[5527]: info: sendMpdCommand status took 216 milliseconds Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::parseState Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 11 15:50:20 volumio volumio[5527]: info: Apr 11 15:50:20 volumio volumio[5527]: ---------------------------- MPD announces state update: player Apr 11 15:50:20 volumio volumio[5527]: info: ControllerMpd::getState Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand status Apr 11 15:50:20 volumio volumio[5527]: info: sendMpdCommand playlistinfo took 6 milliseconds Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::parseTrackInfo Apr 11 15:50:20 volumio volumio[5527]: info: ControllerMpd::pushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::servicePushState Apr 11 15:50:20 volumio volumio[5527]: info: CorePlayQueue::getTrack 3 Apr 11 15:50:20 volumio volumio[5527]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":325,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4584.ape","artist":null,"album":null,"uri":"http://192.168.23.23:50002/m/NDLNA/4584.ape","trackType":"ape"} Apr 11 15:50:20 volumio volumio[5527]: verbose: CURRENT POSITION 3 Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::syncState stateService play Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::syncState currentStatus stop Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:20 volumio volumio[5527]: info: ------------------------------ 270ms Apr 11 15:50:20 volumio volumio[5527]: info: sendMpdCommand status took 53 milliseconds Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::parseState Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::sendMpdCommand playlistinfo Apr 11 15:50:20 volumio volumio[5527]: info: sendMpdCommand playlistinfo took 32 milliseconds Apr 11 15:50:20 volumio volumio[5527]: verbose: ControllerMpd::parseTrackInfo Apr 11 15:50:20 volumio volumio[5527]: info: ControllerMpd::pushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::servicePushState Apr 11 15:50:20 volumio volumio[5527]: info: CorePlayQueue::getTrack 3 Apr 11 15:50:20 volumio volumio[5527]: verbose: STATE SERVICE {"status":"play","position":0,"seek":868,"duration":325,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"4584.ape","artist":null,"album":null,"uri":"http://192.168.23.23:50002/m/NDLNA/4584.ape","trackType":"ape"} Apr 11 15:50:20 volumio volumio[5527]: verbose: CURRENT POSITION 3 Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::syncState stateService play Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::syncState currentStatus play Apr 11 15:50:20 volumio volumio[5527]: info: Received an update from plugin. extracting info from payload Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:20 volumio volumio[5527]: info: CoreStateMachine::pushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::volumioPushState Apr 11 15:50:20 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 11 15:50:20 volumio volumio[5527]: info: ------------------------------ 210ms Apr 11 15:51:05 volumio volumio[5527]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 11 15:51:05 volumio volumio[5527]: info: CURURI: genres:// Apr 11 15:51:57 volumio volumio[5527]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 11 15:51:57 volumio volumio[5527]: { Error: connect ETIMEDOUT 45.114.11.25:443 Apr 11 15:51:57 volumio volumio[5527]: at Object._errnoException (util.js:1022:11) Apr 11 15:51:57 volumio volumio[5527]: at _exceptionWithHostPort (util.js:1044:20) Apr 11 15:51:57 volumio volumio[5527]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1198:14) Apr 11 15:51:57 volumio volumio[5527]: code: 'ETIMEDOUT', Apr 11 15:51:57 volumio volumio[5527]: errno: 'ETIMEDOUT', Apr 11 15:51:57 volumio volumio[5527]: syscall: 'connect', Apr 11 15:51:57 volumio volumio[5527]: address: '45.114.11.25', Apr 11 15:51:57 volumio volumio[5527]: port: 443 } Apr 11 15:51:57 volumio volumio[5527]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 11 15:51:58 volumio sudo[8768]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-11 15:50 Apr 11 15:51:58 volumio sudo[8768]: pam_env(sudo:session): Unable to open env file: /etc/default/locale: No such file or directory Apr 11 15:51:58 volumio sudo[8768]: pam_unix(sudo:session): session opened for user root by (uid=0) NAME="Ubuntu" VERSION="20.04.5 LTS (Focal Fossa)" ID=ubuntu ID_LIKE=debian PRETTY_NAME="Ubuntu 20.04.5 LTS" VERSION_ID="20.04" HOME_URL="https://www.ubuntu.com/" SUPPORT_URL="https://help.ubuntu.com/" BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/" PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy" VERSION_CODENAME=focal UBUNTU_CODENAME=focal