-- Logs begin at Thu 2024-04-25 21:26:54 EDT, end at Thu 2024-04-25 22:14:35 EDT. --
Apr 25 22:13:02 volumio volumio[801]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 25 22:13:02 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:09 volumio volumio[801]: info: CALLMETHOD: user_interface peppy_screensaver savePeppyMeterConf [object Object]
Apr 25 22:13:09 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: peppy_screensaver , savePeppyMeterConf
Apr 25 22:13:09 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:09 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:09 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:09 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:09 volumio volumio[801]: warn: peppy_screensaver: An error occurred when change MPD output Command failed: sed -i '/---> output peppymeter/,+2{/---> output peppymeter/,+1{b};s/no/yes/}' /etc/mpd_include.conf
Apr 25 22:13:09 volumio volumio[801]: sed: can't read /etc/mpd_include.conf: No such file or directory
Apr 25 22:13:09 volumio volumio[801]: {"killed":false,"code":2,"signal":null,"cmd":"sed -i '/---> output peppymeter/,+2{/---> output peppymeter/,+1{b};s/no/yes/}' /etc/mpd_include.conf","stack":"Error: Command failed: sed -i '/---> output peppymeter/,+2{/---> output peppymeter/,+1{b};s/no/yes/}' /etc/mpd_include.conf\nsed: can't read /etc/mpd_include.conf: No such file or directory\n\n at ChildProcess.exithandler (child_process.js:308:12)\n at ChildProcess.emit (events.js:315:20)\n at maybeClose (internal/child_process.js:1048:16)\n at Socket. (internal/child_process.js:439:11)\n at Socket.emit (events.js:315:20)\n at Pipe. (net.js:673:12)"}
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPlay
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::play index undefined
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::startPlaybackTimer
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand stop
Apr 25 22:13:13 volumio volumio[801]: info: sendMpdCommand stop took 57 milliseconds
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand clear
Apr 25 22:13:13 volumio volumio[801]: info:
Apr 25 22:13:13 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:13 volumio volumio[801]: info:
Apr 25 22:13:13 volumio volumio[801]: ---------------------------- MPD announces system playlist update
Apr 25 22:13:13 volumio volumio[801]: info: Ignoring MPD Status Update
Apr 25 22:13:13 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:13 volumio volumio[801]: info: sendMpdCommand clear took 13 milliseconds
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3"
Apr 25 22:13:13 volumio volumio[801]: info:
Apr 25 22:13:13 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:13 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:13 volumio volumio[801]: info:
Apr 25 22:13:13 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:13 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:13 volumio volumio[801]: error: updateQueue error: null
Apr 25 22:13:13 volumio volumio[801]: info:
Apr 25 22:13:13 volumio volumio[801]: ---------------------------- MPD announces system playlist update
Apr 25 22:13:13 volumio volumio[801]: info: Ignoring MPD Status Update
Apr 25 22:13:13 volumio volumio[801]: info: sendMpdCommand status took 50 milliseconds
Apr 25 22:13:13 volumio volumio[801]: info: ------------------------------ 59ms
Apr 25 22:13:13 volumio volumio[801]: info: sendMpdCommand add "NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3" took 45 milliseconds
Apr 25 22:13:13 volumio volumio[801]: info: sendMpdCommand status took 35 milliseconds
Apr 25 22:13:13 volumio volumio[801]: info: sendMpdCommand status took 18 milliseconds
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand play
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:13 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:13 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: 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 25 22:13:13 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::syncState stateService stop
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: No code
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: 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 25 22:13:13 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::syncState stateService stop
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: No code
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: 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 25 22:13:13 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::syncState stateService stop
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:13 volumio volumio[801]: info: No code
Apr 25 22:13:13 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:13 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:13 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:14 volumio volumio[801]: info: ------------------------------ 1301ms
Apr 25 22:13:14 volumio volumio[801]: info: ------------------------------ 1283ms
Apr 25 22:13:14 volumio volumio[801]: info: ------------------------------ 1279ms
Apr 25 22:13:14 volumio volumio[801]: info:
Apr 25 22:13:14 volumio volumio[801]: ---------------------------- MPD announces system playlist update
Apr 25 22:13:14 volumio volumio[801]: info: Ignoring MPD Status Update
Apr 25 22:13:14 volumio volumio[801]: info:
Apr 25 22:13:14 volumio volumio[801]: ---------------------------- MPD announces system playlist update
Apr 25 22:13:14 volumio volumio[801]: info: Ignoring MPD Status Update
Apr 25 22:13:14 volumio volumio[801]: info:
Apr 25 22:13:14 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:14 volumio volumio[801]: info:
Apr 25 22:13:14 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:14 volumio volumio[801]: info: ------------------------------ 1285ms
Apr 25 22:13:14 volumio volumio[801]: info: sendMpdCommand play took 1274 milliseconds
Apr 25 22:13:14 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:14 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:14 volumio volumio[801]: info: ------------------------------ 32ms
Apr 25 22:13:14 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:14 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:14 volumio volumio[801]: info: ------------------------------ 31ms
Apr 25 22:13:14 volumio volumio[801]: info:
Apr 25 22:13:14 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:14 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:14 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:14 volumio volumio[801]: info:
Apr 25 22:13:14 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:14 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:14 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:14 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:15 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:15 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand clearerror
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand status took 527 milliseconds
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand clearerror
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand status took 529 milliseconds
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand clearerror
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand status took 523 milliseconds
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand clearerror
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand status took 510 milliseconds
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand clearerror took 183 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand clearerror took 179 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand clearerror took 173 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand clearerror took 163 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand playlistinfo took 52 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand playlistinfo took 52 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand playlistinfo took 44 milliseconds
Apr 25 22:13:15 volumio volumio[801]: info: sendMpdCommand playlistinfo took 42 milliseconds
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:13:15 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:13:15 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":362,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2 Minutes to Midnight","artist":"Iron Maiden","album":"Powerslave","uri":"NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3","trackType":"mp3"}
Apr 25 22:13:15 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState stateService pause
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:15 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":362,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2 Minutes to Midnight","artist":"Iron Maiden","album":"Powerslave","uri":"NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3","trackType":"mp3"}
Apr 25 22:13:15 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState stateService pause
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:15 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":362,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2 Minutes to Midnight","artist":"Iron Maiden","album":"Powerslave","uri":"NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3","trackType":"mp3"}
Apr 25 22:13:15 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState stateService pause
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:15 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":0,"duration":362,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2 Minutes to Midnight","artist":"Iron Maiden","album":"Powerslave","uri":"NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3","trackType":"mp3"}
Apr 25 22:13:15 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState stateService pause
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:15 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:15 volumio volumio[801]: info: ------------------------------ 1258ms
Apr 25 22:13:15 volumio volumio[801]: info: ------------------------------ 1258ms
Apr 25 22:13:15 volumio volumio[801]: info: ------------------------------ 1239ms
Apr 25 22:13:15 volumio volumio[801]: info: ------------------------------ 1223ms
Apr 25 22:13:16 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:16 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:16 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:16 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:25 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Apr 25 22:13:25 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken
Apr 25 22:13:26 volumio go-librespot[1657]: time="2024-04-25T22:13:26-04:00" level=error msg="did not receive last pong from dealer, 60s passed"
Apr 25 22:13:30 volumio volumio[801]: info: Starting Uninstall of plugin user_interface - peppy_screensaver
Apr 25 22:13:30 volumio volumio[801]: info: Uninstalling plugin peppy_screensaver
Apr 25 22:13:30 volumio volumio[801]: info: CoreStateMachine::stop
Apr 25 22:13:30 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:13:30 volumio sudo[1924]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount /volumio/app/plugins/music_service/mpd/mpd.conf.tmpl
Apr 25 22:13:30 volumio sudo[1924]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:30 volumio sudo[1924]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:30 volumio systemd[1]: volumio-app-plugins-music_service-mpd-mpd.conf.tmpl.mount: Succeeded.
Apr 25 22:13:30 volumio volumio[801]: info: Disabling plugin peppy_screensaver
Apr 25 22:13:30 volumio volumio[801]: info: Preparing to generate the ALSA configuration file
Apr 25 22:13:30 volumio sudo[1929]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount /volumio/app/plugins/music_service/airplay_emulation/shairport-sync.conf.tmpl
Apr 25 22:13:30 volumio sudo[1929]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:30 volumio sudo[1929]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:30 volumio systemd[1]: volumio-app-plugins-music_service-airplay_emulation-shairport\x2dsync.conf.tmpl.mount: Succeeded.
Apr 25 22:13:30 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: spop , initializeLibrespotDaemon
Apr 25 22:13:30 volumio volumio[801]: info: Creating Spotify config file
Apr 25 22:13:30 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:30 volumio volumio[801]: info: Spotify config file written
Apr 25 22:13:30 volumio volumio[801]: info: Asound.conf file written
Apr 25 22:13:30 volumio sudo[1932]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service
Apr 25 22:13:30 volumio sudo[1932]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:30 volumio systemd[1]: Stopping go-librespot Daemon...
Apr 25 22:13:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM
Apr 25 22:13:30 volumio systemd[1]: go-librespot-daemon.service: Succeeded.
Apr 25 22:13:30 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 25 22:13:30 volumio sudo[1935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf
Apr 25 22:13:30 volumio sudo[1935]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:30 volumio systemd[1]: Started go-librespot Daemon.
Apr 25 22:13:30 volumio go-librespot[1936]: Librespot-go daemon starting...
Apr 25 22:13:31 volumio sudo[1935]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:31 volumio sudo[1932]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:31 volumio go-librespot[1936]: time="2024-04-25T22:13:31-04:00" level=info msg="generated new device id: a99ba8e554fcfe6b31c7e271deb6c572a93c6c67"
Apr 25 22:13:31 volumio go-librespot[1936]: time="2024-04-25T22:13:31-04:00" level=debug msg="stored credentials found for 1249171035"
Apr 25 22:13:31 volumio volumio[801]: No state is present for card Dummy
Apr 25 22:13:31 volumio volumio[801]: Found hardware: "Dummy" "Dummy Mixer" "" "" ""
Apr 25 22:13:31 volumio volumio[801]: Hardware is initialized using a generic method
Apr 25 22:13:31 volumio volumio[801]: No state is present for card Dummy
Apr 25 22:13:31 volumio volumio[801]: info: Output device has changed, restarting MPD
Apr 25 22:13:31 volumio sudo[1948]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Apr 25 22:13:31 volumio sudo[1948]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:31 volumio volumio[801]: info: Output device has changed, restarting Shairport Sync
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:31 volumio sudo[1948]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:31 volumio sudo[1951]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Apr 25 22:13:31 volumio sudo[1951]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:31 volumio systemd[1]: Stopping Music Player Daemon...
Apr 25 22:13:31 volumio volumio[801]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0
Apr 25 22:13:31 volumio volumio[801]: info: Checking if uninstall.sh is present
Apr 25 22:13:31 volumio volumio[801]: info: Executing uninstall.sh
Apr 25 22:13:31 volumio sudo[1959]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/user_interface/peppy_screensaver/uninstall.sh
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up
Apr 25 22:13:31 volumio sudo[1959]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/volume: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: (node:801) UnhandledPromiseRejectionWarning: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: at connResetException (internal/errors.js:607:14)
Apr 25 22:13:31 volumio volumio[801]: at Socket.socketOnEnd (_http_client.js:493:23)
Apr 25 22:13:31 volumio volumio[801]: at Socket.emit (events.js:327:22)
Apr 25 22:13:31 volumio volumio[801]: at endReadableNT (internal/streams/readable.js:1327:12)
Apr 25 22:13:31 volumio volumio[801]: at processTicksAndRejections (internal/process/task_queues.js:80:21)
Apr 25 22:13:31 volumio volumio[801]: (Use `node --trace-warnings ...` to show where the warning was created)
Apr 25 22:13:31 volumio volumio[801]: (node:801) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
Apr 25 22:13:31 volumio volumio[801]: (node:801) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
Apr 25 22:13:31 volumio volumio[801]: error: Failed to send command to Spotify local API: /player/play: Error: socket hang up
Apr 25 22:13:31 volumio volumio[801]: info: MPD Permissions set
Apr 25 22:13:31 volumio go-librespot[1936]: time="2024-04-25T22:13:31-04:00" level=debug msg="obtained new client token: AADU9s3tD3RJOzG2xOm3hUKoFW1bJV1aFIO2RDM2AYXSdc26W0QnyyQoTAI1mQvuWhhtDc2T2ePj1Wtx5q/k8dMd97pILnLcaZAXNziYxnWf3LvfwEZnfm9lvIZut/H+WUUIaPrlKyI8t159EqiKuV4IdCL0XwP6tZpQY2zvoh4EucsTpuo3wOUqiQorU8RJjGUUs7iihFlVlkeOSR+zSyMjk1r8fjYwJUzqjA6hmz+Huc5Kl1pSPNaQn8Yv/Ho="
Apr 25 22:13:31 volumio systemd[1]: mpd.service: Succeeded.
Apr 25 22:13:31 volumio volumio[801]: info: Connection to go-librespot Websocket closed
Apr 25 22:13:31 volumio systemd[1]: Stopped Music Player Daemon.
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio systemd[1]: Starting Music Player Daemon...
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 25 22:13:31 volumio volumio[801]: info: Starting Shairport Sync
Apr 25 22:13:31 volumio go-librespot[1936]: time="2024-04-25T22:13:31-04:00" level=debug msg="fetched new accesspoints: [ap-guc3.spotify.com:4070 ap-guc3.spotify.com:443 ap-guc3.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 25 22:13:32 volumio sudo[1979]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync
Apr 25 22:13:32 volumio sudo[1979]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 25 22:13:32 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver...
Apr 25 22:13:32 volumio systemd[1]: shairport-sync.service: Succeeded.
Apr 25 22:13:32 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver.
Apr 25 22:13:32 volumio go-librespot[1936]: time="2024-04-25T22:13:32-04:00" level=debug msg="completed keyexchange"
Apr 25 22:13:32 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver.
Apr 25 22:13:32 volumio sudo[1979]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:32 volumio volumio[801]: info: Shairport-Sync Started
Apr 25 22:13:32 volumio go-librespot[1936]: time="2024-04-25T22:13:32-04:00" level=debug msg="completed challenge"
Apr 25 22:13:32 volumio go-librespot[1936]: time="2024-04-25T22:13:32-04:00" level=debug msg="authenticated as 1249171035"
Apr 25 22:13:33 volumio sudo[1959]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:33 volumio volumio[801]: info: Uninstall script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/user_interface/peppy_screensaver/uninstall.sh > /tmp/installog
Apr 25 22:13:33 volumio volumio[801]: [137B blob data]
Apr 25 22:13:33 volumio volumio[801]: [137B blob data]
Apr 25 22:13:33 volumio volumio[801]: /data/plugins/user_interface/peppy_screensaver/uninstall.sh: 9: cd: can't cd to /data/plugins/user_interface/peppy_screensaver
Apr 25 22:13:33 volumio volumio[801]: [138B blob data]
Apr 25 22:13:33 volumio volumio[801]: df: '/volumio/app/plugins/music_service/mpd/mpd.conf.tmpl'$'\r': No such file or directory
Apr 25 22:13:33 volumio volumio[801]: [138B blob data]
Apr 25 22:13:33 volumio volumio[801]: internal/modules/cjs/loader.js:883
Apr 25 22:13:33 volumio volumio[801]: throw err;
Apr 25 22:13:33 volumio volumio[801]: ^
Apr 25 22:13:33 volumio volumio[801]: [43B blob data]
Apr 25 22:13:33 volumio volumio[801]: at Function.Module._resolveFilename (internal/modules/cjs/loader.js:880:15)
Apr 25 22:13:33 volumio volumio[801]: at Function.Module._load (internal/modules/cjs/loader.js:725:27)
Apr 25 22:13:33 volumio volumio[801]: at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:72:12)
Apr 25 22:13:33 volumio volumio[801]: at internal/main/run_main_module.js:17:47 {
Apr 25 22:13:33 volumio volumio[801]: code: 'MODULE_NOT_FOUND',
Apr 25 22:13:33 volumio volumio[801]: requireStack: []
Apr 25 22:13:33 volumio volumio[801]: }
Apr 25 22:13:33 volumio volumio[801]: [138B blob data]
Apr 25 22:13:33 volumio volumio[801]: /data/plugins/user_interface/peppy_screensaver/uninstall.sh: 36: /data/plugins/user_interface/peppy_screensaver/uninstall.sh: Syntax error: end of file unexpected (expecting "then")
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="authenticated as 1249171035"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="fetched new spclients: [guc3-spclient.spotify.com:443 gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="fetched new dealers: [guc3-dealer.spotify.com:443 gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="dealer connection opened"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513"
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="received connection id: N2RkYTE3ZGQtMDk4OC00ZjRlLTliMTItMmNjNjk5ZDUzNTcwK2RlYWxlcit0Y3A6Ly9ndWMzLWRlYWxlci1hLWhtM3EuZ3VjMy5zcG90aWZ5Lm5ldDo1NzAwKzYwOEVBNUVGMTI2MjVGMzdGQzIwQkVGNDc3NUVCMDM0OThGQzkxMTZBNEM0MEYyMzc1RUJFMUMxMzEzQTJFN0E="
Apr 25 22:13:33 volumio go-librespot[1936]: time="2024-04-25T22:13:33-04:00" level=debug msg="put connect state because NEW_DEVICE"
Apr 25 22:13:34 volumio volumio[801]: info: go-librespot daemon successfully initialized
Apr 25 22:13:34 volumio volumio[801]: info: Initializing connection to go-librespot Websocket
Apr 25 22:13:34 volumio go-librespot[1936]: time="2024-04-25T22:13:34-04:00" level=debug msg="new websocket client"
Apr 25 22:13:34 volumio volumio[801]: info: Connection to go-librespot Websocket established
Apr 25 22:13:35 volumio mpd[1965]: Apr 25 22:13 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Apr 25 22:13:35 volumio systemd[1]: Started Music Player Daemon.
Apr 25 22:13:35 volumio sudo[1951]: pam_unix(sudo:session): session closed for user root
Apr 25 22:13:35 volumio volumio[801]: error: updateQueue error: null
Apr 25 22:13:37 volumio volumio[801]: info: Initializing connection to go-librespot Websocket
Apr 25 22:13:37 volumio go-librespot[1936]: time="2024-04-25T22:13:37-04:00" level=debug msg="new websocket client"
Apr 25 22:13:37 volumio volumio[801]: info: Connection to go-librespot Websocket established
Apr 25 22:13:37 volumio volumio[801]: info: Getting Spotify volume
Apr 25 22:13:37 volumio volumio[801]: info: Spotify volume: 100
Apr 25 22:13:37 volumio volumio[801]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12
Apr 25 22:13:38 volumio volumio[801]: info: CoreCommandRouter::volumioGetState
Apr 25 22:13:38 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:38 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:38 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 100
Apr 25 22:13:38 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 40
Apr 25 22:13:38 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:13:38 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 40
Apr 25 22:13:39 volumio volumio[801]: SPOTIFY: SETTING SPOTIFY VOLUME 40
Apr 25 22:13:39 volumio volumio[801]: info: Sending Spotify command with payload to local API: /player/volume
Apr 25 22:13:39 volumio go-librespot[1936]: time="2024-04-25T22:13:39-04:00" level=debug msg="update volume to 26214/65535"
Apr 25 22:13:39 volumio go-librespot[1936]: time="2024-04-25T22:13:39-04:00" level=debug msg="put connect state because VOLUME_CHANGED"
Apr 25 22:13:39 volumio go-librespot[1936]: time="2024-04-25T22:13:39-04:00" level=trace msg="emitting websocket event: volume"
Apr 25 22:13:39 volumio volumio[801]: SPOTIFY: received: {"type":"volume","data":{"value":40,"max":100}}
Apr 25 22:13:39 volumio volumio[801]: SPOTIFY: RECEIVED SPOTIFY VOLUME 40
Apr 25 22:13:39 volumio volumio[801]: SPOTIFY: received: {"type":"volume","data":{"value":40,"max":100}}
Apr 25 22:13:39 volumio volumio[801]: SPOTIFY: RECEIVED SPOTIFY VOLUME 40
Apr 25 22:13:40 volumio volumio[801]: info: Getting Spotify volume
Apr 25 22:13:40 volumio volumio[801]: info: Spotify volume: 40
Apr 25 22:13:40 volumio volumio[801]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 12
Apr 25 22:13:40 volumio volumio[801]: info: CoreCommandRouter::volumioGetState
Apr 25 22:13:40 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:40 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:40 volumio volumio[801]: info: CoreCommandRouter::volumioPlay
Apr 25 22:13:40 volumio volumio[801]: info: CoreStateMachine::play index undefined
Apr 25 22:13:40 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:13:40 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:40 volumio volumio[801]: info: CoreStateMachine::startPlaybackTimer
Apr 25 22:13:40 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:40 volumio volumio[801]: verbose: ControllerMpd::clearAddPlayTracks NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3
Apr 25 22:13:40 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand stop
Apr 25 22:13:40 volumio volumio[801]: info: sendMpdCommand stop took 2 milliseconds
Apr 25 22:13:40 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand clear
Apr 25 22:13:40 volumio volumio[801]: info:
Apr 25 22:13:40 volumio volumio[801]: ---------------------------- MPD announces system playlist update
Apr 25 22:13:40 volumio volumio[801]: info: Ignoring MPD Status Update
Apr 25 22:13:40 volumio volumio[801]: info: sendMpdCommand clear took 3 milliseconds
Apr 25 22:13:40 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand add "NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3"
Apr 25 22:13:40 volumio volumio[801]: error: updateQueue error: null
Apr 25 22:13:40 volumio volumio[801]: info:
Apr 25 22:13:40 volumio volumio[801]: ---------------------------- MPD announces system playlist update
Apr 25 22:13:40 volumio volumio[801]: info: Ignoring MPD Status Update
Apr 25 22:13:40 volumio volumio[801]: info: ------------------------------ 17ms
Apr 25 22:13:40 volumio volumio[801]: info: sendMpdCommand add "NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3" took 14 milliseconds
Apr 25 22:13:40 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand play
Apr 25 22:13:40 volumio volumio[801]: info: ------------------------------ 5ms
Apr 25 22:13:40 volumio volumio[801]: info: sendMpdCommand play took 4 milliseconds
Apr 25 22:13:41 volumio volumio[801]: info:
Apr 25 22:13:41 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:41 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:41 volumio volumio[801]: info:
Apr 25 22:13:41 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:13:41 volumio volumio[801]: info: sendMpdCommand status took 59 milliseconds
Apr 25 22:13:41 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:13:41 volumio volumio[801]: info: sendMpdCommand status took 6 milliseconds
Apr 25 22:13:41 volumio volumio[801]: info: sendMpdCommand playlistinfo took 6 milliseconds
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:13:41 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:41 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:41 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:41 volumio volumio[801]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":362,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2 Minutes to Midnight","artist":"Iron Maiden","album":"Powerslave","uri":"NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3","trackType":"mp3"}
Apr 25 22:13:41 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:41 volumio volumio[801]: info: CoreStateMachine::syncState stateService play
Apr 25 22:13:41 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:13:41 volumio volumio[801]: info: ------------------------------ 90ms
Apr 25 22:13:41 volumio volumio[801]: info: sendMpdCommand playlistinfo took 17 milliseconds
Apr 25 22:13:41 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:13:41 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:13:41 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:13:41 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:41 volumio volumio[801]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":362,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"2 Minutes to Midnight","artist":"Iron Maiden","album":"Powerslave","uri":"NAS/Music/Iron Maiden/Powerslave/02. 2 Minutes To Midnight.mp3","trackType":"mp3"}
Apr 25 22:13:41 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:13:41 volumio volumio[801]: info: CoreStateMachine::syncState stateService play
Apr 25 22:13:41 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus play
Apr 25 22:13:41 volumio volumio[801]: info: Received an update from plugin. extracting info from payload
Apr 25 22:13:41 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:41 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:41 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:13:41 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:41 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:41 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:41 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:41 volumio volumio[801]: info: ------------------------------ 180ms
Apr 25 22:13:41 volumio volumio[801]: info: [LastFM] Current track has sufficient metadata: title (2 Minutes to Midnight) and artist (Iron Maiden) passed on explicitly
Apr 25 22:13:41 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:41 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 40
Apr 25 22:13:42 volumio volumio[801]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"2 Minutes to Midnight","mbid":"3b863253-035c-4520-81be-b5a644539f0f","url":"https://www.last.fm/music/Iron+Maiden/_/2+Minutes+to+Midnight","duration":"363000","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"482757","playcount":"3580018","artist":{"name":"Iron Maiden","mbid":"ca891d65-d9b0-4258-89f7-e6ba29d83767","url":"https://www.last.fm/music/Iron+Maiden"},"album":{"@":{"position":"2"},"artist":"Iron Maiden","title":"Powerslave","mbid":"556c0066-8114-33ad-aa45-ab2f203e2777","url":"https://www.last.fm/music/Iron+Maiden/Powerslave","image":[{"#":"https://lastfm.freetls.fastly.net/i/u/34s/fb8a432b8a23a386b9fbaaa4756800b2.png","@":{"size":"small"}},{"#":"https://lastfm.freetls.fastly.net/i/u/64s/fb8a432b8a23a386b9fbaaa4756800b2.png","@":{"size":"medium"}},{"#":"https://lastfm.freetls.fastly.net/i/u/174s/fb8a432b8a23a386b9fbaaa4756800b2.png","@":{"size":"large"}},{"#":"https://lastfm.freetls.fastly.net/i/u/300x300/fb8a432b8a23a386b9fbaaa4756800b2.png","@":{"size":"extralarge"}}]},"userplaycount":"1","userloved":"0","toptags":{"tag":[{"name":"heavy metal","url":"https://www.last.fm/tag/heavy+metal"},{"name":"metal","url":"https://www.last.fm/tag/metal"},{"name":"Iron Maiden","url":"https://www.last.fm/tag/Iron+Maiden"},{"name":"NWOBHM","url":"https://www.last.fm/tag/NWOBHM"},{"name":"rock","url":"https://www.last.fm/tag/rock"}]},"wiki":{"published":"24 Jul 2008, 22:09","summary":"\"2 Minutes to Midnight\" is the tenth single released by Iron Maiden and the second track from their 1984 album Powerslave. The single was released on August 6, 1984 and rose to number 11 in the UK Singles Chart. The song was written by Adrian Smith and Bruce Dickinson. The song has references to the Doomsday Clock, the symbolic clock used by the Bulletin of the Atomic Scientists. In September 1953 the clock reached 11:58, the closest the clock ever got to midnight. Read more on Last.fm.","content":"\"2 Minutes to Midnight\" is the tenth single released by Iron Maiden and the second track from their 1984 album Powerslave. The single was released on August 6, 1984 and rose to number 11 in the UK Singles Chart. The song was written by Adrian Smith and Bruce Dickinson. The song has references to the Doomsday Clock, the symbolic clock used by the Bulletin of the Atomic Scientists. In September 1953 the clock reached 11:58, the closest the clock ever got to midnight. This occurred when the United States and Soviet Union tested H-bombs within nine months of one another. This song is clearly presenting an anti-war view. The first guitar solo is played by Dave Murray followed by a guitar solo played by Adrian Smith. The first B-side is a cover of British progressive rock band Beckett's \"Rainbow's Gold\". Another B-side, entitled \"Mission from 'Arry\", is a recording of an argument between bassist Steve Harris and drummer Nicko McBrain. The argument happened after a show in Allentown, Pennsylvania during the band's World Piece Tour, and occurred due to a misunderstanding on stage between the two due to technical issues with Harris' bass, which had led to McBrain's drum solo going wrong. Vocalist Bruce Dickinson was recording the argument with a concealed tape recorder. Trivia The video of the song is featured on the 2003 video collection Visions of the Beast. The song was included in Grand Theft Auto: Vice City. United States Ambassador Ryan Crocker has a poster of the album in his office. [1] The guitar riff in the beginning has been adapted in many other metal songs including: \"Welcome to Hell\" by Venom, \"Hellbound\" by Tygers of Pan Tang, \"Flash Rockin' Man\" by Accept and \"Live Fast Die Young\" by Saxon. The song was covered by the all-female tribute band The Iron Maidens on their self-titled debut album. It was also covered in 2008 by Glamour Of The Kill on the tribute CD Maiden Heaven: A Tribute to Iron Maiden released by Kerrang! magazine. The song is 5 minutes and 59 seconds long, which when doubled yields 11:58, just as the time the song describes. Read more on Last.fm. User-contributed text is available under the Creative Commons By-SA License; additional terms may apply."}}}
Apr 25 22:13:44 volumio volumio[801]: info: VolumeController::SetAlsaVolume30
Apr 25 22:13:44 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:44 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:44 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:13:44 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 40
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 30
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:13:44 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 30
Apr 25 22:13:44 volumio volumio[801]: info: VolumeController::SetAlsaVolume15
Apr 25 22:13:44 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:44 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:44 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:13:44 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 15
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 30
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 15
Apr 25 22:13:44 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:13:44 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 15
Apr 25 22:13:45 volumio volumio[801]: info: VolumeController::SetAlsaVolume25
Apr 25 22:13:45 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:13:45 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:13:45 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:13:45 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:13:45 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 25
Apr 25 22:13:45 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 15
Apr 25 22:13:45 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 25
Apr 25 22:13:45 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:13:45 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 25
Apr 25 22:13:46 volumio volumio[801]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 25 22:13:46 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:47 volumio volumio[801]: SPOTIFY: SETTING SPOTIFY VOLUME 25
Apr 25 22:13:47 volumio volumio[801]: info: Sending Spotify command with payload to local API: /player/volume
Apr 25 22:13:47 volumio go-librespot[1936]: time="2024-04-25T22:13:47-04:00" level=debug msg="update volume to 16383/65535"
Apr 25 22:13:47 volumio go-librespot[1936]: time="2024-04-25T22:13:47-04:00" level=debug msg="put connect state because VOLUME_CHANGED"
Apr 25 22:13:47 volumio go-librespot[1936]: time="2024-04-25T22:13:47-04:00" level=trace msg="emitting websocket event: volume"
Apr 25 22:13:47 volumio volumio[801]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}}
Apr 25 22:13:47 volumio volumio[801]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25
Apr 25 22:13:47 volumio volumio[801]: SPOTIFY: received: {"type":"volume","data":{"value":25,"max":100}}
Apr 25 22:13:47 volumio volumio[801]: SPOTIFY: RECEIVED SPOTIFY VOLUME 25
Apr 25 22:13:56 volumio volumio[801]: info: CALLMETHOD: user_interface peppy_screensaver savePeppyMeterConf [object Object]
Apr 25 22:13:56 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: peppy_screensaver , savePeppyMeterConf
Apr 25 22:13:56 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:56 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:56 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 25 22:13:56 volumio volumio[801]: warn: peppy_screensaver: An error occurred when change MPD output Command failed: sed -i '/---> output peppymeter/,+2{/---> output peppymeter/,+1{b};s/yes/no/}' /etc/mpd_include.conf
Apr 25 22:13:56 volumio volumio[801]: sed: can't read /etc/mpd_include.conf: No such file or directory
Apr 25 22:13:56 volumio volumio[801]: {"killed":false,"code":2,"signal":null,"cmd":"sed -i '/---> output peppymeter/,+2{/---> output peppymeter/,+1{b};s/yes/no/}' /etc/mpd_include.conf","stack":"Error: Command failed: sed -i '/---> output peppymeter/,+2{/---> output peppymeter/,+1{b};s/yes/no/}' /etc/mpd_include.conf\nsed: can't read /etc/mpd_include.conf: No such file or directory\n\n at ChildProcess.exithandler (child_process.js:308:12)\n at ChildProcess.emit (events.js:315:20)\n at maybeClose (internal/child_process.js:1048:16)\n at Socket. (internal/child_process.js:439:11)\n at Socket.emit (events.js:315:20)\n at Pipe. (net.js:673:12)"}
Apr 25 22:14:00 volumio volumio[801]: info: CALLMETHOD: user_interface peppy_screensaver saveVUMeterConf [object Object]
Apr 25 22:14:00 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: peppy_screensaver , saveVUMeterConf
Apr 25 22:14:04 volumio volumio[801]: info: VolumeController::SetAlsaVolume30
Apr 25 22:14:04 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:04 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:04 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:04 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 30
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 25
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 30
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:14:04 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 30
Apr 25 22:14:04 volumio volumio[801]: info: VolumeController::SetAlsaVolume35
Apr 25 22:14:04 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:04 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:04 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:04 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 30
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 35
Apr 25 22:14:04 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:14:04 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 35
Apr 25 22:14:05 volumio volumio[801]: info: VolumeController::SetAlsaVolume50
Apr 25 22:14:05 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:05 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:05 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:05 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:05 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 50
Apr 25 22:14:05 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 35
Apr 25 22:14:05 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 50
Apr 25 22:14:05 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:14:05 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 50
Apr 25 22:14:05 volumio volumio[801]: info: VolumeController::SetAlsaVolume60
Apr 25 22:14:05 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:05 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:06 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:06 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:06 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:06 volumio volumio[801]: SPOTIFY: SPOTIFY VOLUME 50
Apr 25 22:14:06 volumio volumio[801]: SPOTIFY: VOLUMIO VOLUME 60
Apr 25 22:14:06 volumio volumio[801]: SPOTIFY: DELTA VOLUME ENOUGH: true
Apr 25 22:14:06 volumio volumio[801]: info: Setting Spotify Volume from Volumio: 60
Apr 25 22:14:07 volumio volumio[801]: SPOTIFY: SETTING SPOTIFY VOLUME 60
Apr 25 22:14:07 volumio volumio[801]: info: Sending Spotify command with payload to local API: /player/volume
Apr 25 22:14:07 volumio go-librespot[1936]: time="2024-04-25T22:14:07-04:00" level=debug msg="update volume to 39321/65535"
Apr 25 22:14:07 volumio go-librespot[1936]: time="2024-04-25T22:14:07-04:00" level=debug msg="put connect state because VOLUME_CHANGED"
Apr 25 22:14:07 volumio go-librespot[1936]: time="2024-04-25T22:14:07-04:00" level=trace msg="emitting websocket event: volume"
Apr 25 22:14:07 volumio volumio[801]: SPOTIFY: received: {"type":"volume","data":{"value":60,"max":100}}
Apr 25 22:14:07 volumio volumio[801]: SPOTIFY: RECEIVED SPOTIFY VOLUME 60
Apr 25 22:14:07 volumio volumio[801]: SPOTIFY: received: {"type":"volume","data":{"value":60,"max":100}}
Apr 25 22:14:07 volumio volumio[801]: SPOTIFY: RECEIVED SPOTIFY VOLUME 60
Apr 25 22:14:15 volumio volumio[801]: info: Preload queue cleared
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::volumioReplaceandPlayItems
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::ClearQueue
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::stop
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::stPlaybackTimer
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::updateTrackBlock
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::getTrackBlock
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::serviceStop
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::serviceStop
Apr 25 22:14:15 volumio volumio[801]: info: ControllerMpd::stop
Apr 25 22:14:15 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand stop
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::clearPlayQueue
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::saveQueue
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushQueue
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::addQueueItems
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::addQueueItems
Apr 25 22:14:15 volumio volumio[801]: info: Preload queue cleared
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:7i9763l5SSfOnqZ35VOcfy
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:7i9763l5SSfOnqZ35VOcfy
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:2Z8WuEywRWYTKe1NybPQEW
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:2Z8WuEywRWYTKe1NybPQEW
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:1s9xuJxhYM0LdVqksjegcg
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:1s9xuJxhYM0LdVqksjegcg
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:3bnVBN67NBEzedqQuWrpP4
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:3bnVBN67NBEzedqQuWrpP4
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:2P61EK6DMGyVyssLWS4fKy
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:2P61EK6DMGyVyssLWS4fKy
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:1lguQJjlNrIOoOylYVZN3M
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:1lguQJjlNrIOoOylYVZN3M
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:57yL3161hUMuw06zzzUCHi
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:57yL3161hUMuw06zzzUCHi
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:6GmkJJMe9U1tEcrJ3Hq3A1
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:6GmkJJMe9U1tEcrJ3Hq3A1
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:22OqansuvEMQu9W0EfiGTI
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:22OqansuvEMQu9W0EfiGTI
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:4Oyl6oYSNeeZZP0OAxPVaU
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:4Oyl6oYSNeeZZP0OAxPVaU
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:40sRwFjfrRnaTdYPJIg4CP
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:40sRwFjfrRnaTdYPJIg4CP
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:7qxjGHW485TL8ciwkHD5MK
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:7qxjGHW485TL8ciwkHD5MK
Apr 25 22:14:15 volumio volumio[801]: info: Adding Item to queue: spotify:track:5P3yUXUC9rZPJPNmYGKEAz
Apr 25 22:14:15 volumio volumio[801]: info: Using cached record of: spotify:track:5P3yUXUC9rZPJPNmYGKEAz
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::volumioPushQueue
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::saveQueue
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::updateTrackBlock
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::getTrackBlock
Apr 25 22:14:15 volumio volumio[801]: info: CoreCommandRouter::volumioPlay
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::play index 1
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::stop
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::play index undefined
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:15 volumio volumio[801]: info: CoreStateMachine::startPlaybackTimer
Apr 25 22:14:15 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:15 volumio volumio[801]: info: [1714097655987] ControllerSpotify::clearAddPlayTrack
Apr 25 22:14:15 volumio volumio[801]: info: Sending Spotify command with payload to local API: /player/play
Apr 25 22:14:16 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:16 volumio volumio[801]: info:
Apr 25 22:14:16 volumio volumio[801]: ---------------------------- MPD announces state update: player
Apr 25 22:14:16 volumio volumio[801]: info: sendMpdCommand stop took 189 milliseconds
Apr 25 22:14:16 volumio volumio[801]: info: ControllerMpd::getState
Apr 25 22:14:16 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand status
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=trace msg="fetched new page 0 with 1 items (list: 1)"
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="loading track spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn (paused: false, position: 1ms)"
Apr 25 22:14:16 volumio volumio[801]: info: sendMpdCommand status took 76 milliseconds
Apr 25 22:14:16 volumio volumio[801]: verbose: ControllerMpd::parseState
Apr 25 22:14:16 volumio volumio[801]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Apr 25 22:14:16 volumio volumio[801]: info: sendMpdCommand playlistinfo took 4 milliseconds
Apr 25 22:14:16 volumio volumio[801]: verbose: ControllerMpd::parseTrackInfo
Apr 25 22:14:16 volumio volumio[801]: info: ControllerMpd::pushState
Apr 25 22:14:16 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:14:16 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:16 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:16 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:16 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:16 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:16 volumio volumio[801]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current spop Received mpd
Apr 25 22:14:16 volumio volumio[801]: info: ------------------------------ 166ms
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1900"
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=trace msg="emitting websocket event: will_play"
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1896"
Apr 25 22:14:16 volumio volumio[801]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","play_origin":"go-librespot"}}
Apr 25 22:14:16 volumio volumio[801]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","play_origin":"go-librespot"}}
Apr 25 22:14:16 volumio volumio[801]: info: touch_display: Setting screensaver timeout to 161 seconds.
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="selected format OGG_VORBIS_160 for spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn"
Apr 25 22:14:16 volumio go-librespot[1936]: time="2024-04-25T22:14:16-04:00" level=debug msg="requested aes key for file 3711c8120b29d9ed3865aee94985e0d9bbc8f643, gid: 3CRDbSIZ4r5MsZ0YwxuEkn"
Apr 25 22:14:16 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=debug msg="fetched first chunk of 8, total size is 3980500 bytes"
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=trace msg="seek to 1ms (diff: -430ms, samples: 44, bytes: 0)"
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=info msg="loaded track \"Stressed Out\" (uri: spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn, paused: false, position: 1ms, duration: 202333ms)"
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=debug msg="vorbis: corrupt or missing data in bitstream"
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=trace msg="emitting websocket event: metadata"
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","name":"Stressed Out","artist_names":["Twenty One Pilots"],"album_name":"Blurryface","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","position":1,"duration":202333,"release_date":"year:2015 month:5 day:15","track_number":2,"disc_number":1}}
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","name":"Stressed Out","artist_names":["Twenty One Pilots"],"album_name":"Blurryface","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","position":1,"duration":202333,"release_date":"year:2015 month:5 day:15","track_number":2,"disc_number":1}}
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=trace msg="emitting websocket event: playing"
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","play_origin":"go-librespot"}}
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: PUSH STATE SPOTIFY
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:17 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::syncState stateService play
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus stop
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","play_origin":"go-librespot"}}
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: PUSH STATE SPOTIFY
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:17 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::syncState stateService play
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus play
Apr 25 22:14:17 volumio volumio[801]: info: Received an update from plugin. extracting info from payload
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:17 volumio go-librespot[1936]: time="2024-04-25T22:14:17-04:00" level=debug msg="fetched chunk 1/7, size: 524288"
Apr 25 22:14:17 volumio volumio[801]: info: [LastFM] Current track has sufficient metadata: title (Stressed Out) and artist (Twenty One Pilots) passed on explicitly
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::volumioPlay
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::play index undefined
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::setConsumeUpdateService undefined
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: PUSH STATE SPOTIFY
Apr 25 22:14:17 volumio volumio[801]: SPOTIFY: {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:17 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::syncState stateService play
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus play
Apr 25 22:14:17 volumio volumio[801]: info: Received an update from plugin. extracting info from payload
Apr 25 22:14:17 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:17 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:17 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:18 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:18 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:18 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:18 volumio go-librespot[1936]: time="2024-04-25T22:14:18-04:00" level=debug msg="fetched chunk 3/7, size: 524288"
Apr 25 22:14:18 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:18 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:18 volumio volumio[801]: SPOTIFY: PUSH STATE SPOTIFY
Apr 25 22:14:18 volumio volumio[801]: SPOTIFY: {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:18 volumio volumio[801]: info: CoreCommandRouter::servicePushState
Apr 25 22:14:18 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:18 volumio volumio[801]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Stressed Out","artist":"Twenty One Pilots","album":"Blurryface","albumart":"https://i.scdn.co/image/ab67616d00001e02352e5ec301a02278ffe53d14","uri":"spotify:track:3CRDbSIZ4r5MsZ0YwxuEkn","trackType":"spotify","seek":1,"duration":202,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"160 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Apr 25 22:14:18 volumio volumio[801]: verbose: CURRENT POSITION 1
Apr 25 22:14:18 volumio volumio[801]: info: CoreStateMachine::syncState stateService play
Apr 25 22:14:18 volumio volumio[801]: info: CoreStateMachine::syncState currentStatus play
Apr 25 22:14:18 volumio volumio[801]: info: Received an update from plugin. extracting info from payload
Apr 25 22:14:18 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:18 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:18 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:18 volumio go-librespot[1936]: time="2024-04-25T22:14:18-04:00" level=debug msg="fetched chunk 2/7, size: 524288"
Apr 25 22:14:18 volumio volumio[801]: info: CoreStateMachine::pushState
Apr 25 22:14:18 volumio volumio[801]: info: CorePlayQueue::getTrack 1
Apr 25 22:14:18 volumio volumio[801]: info: CoreCommandRouter::volumioPushState
Apr 25 22:14:18 volumio volumio[801]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Stressed Out","url":"https://www.last.fm/music/Twenty+One+Pilots/_/Stressed+Out","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"1253349","playcount":"12758867","artist":{"name":"Twenty One Pilots","mbid":"a6c6897a-7415-4f8d-b5a5-3a5e05f3be67","url":"https://www.last.fm/music/Twenty+One+Pilots"},"userplaycount":"6","userloved":"0","toptags":{"tag":[{"name":"indie pop","url":"https://www.last.fm/tag/indie+pop"},{"name":"alternative","url":"https://www.last.fm/tag/alternative"},{"name":"indie","url":"https://www.last.fm/tag/indie"},{"name":"alternative hip hop","url":"https://www.last.fm/tag/alternative+hip+hop"},{"name":"hip hop","url":"https://www.last.fm/tag/hip+hop"}]},"wiki":{"published":"06 Aug 2016, 05:24","summary":"\"Stressed Out\" is a song written and recorded by American alternative hip-hop band Twenty One Pilots for their fourth studio album, Blurryface. Written by Tyler Joseph and produced by Mike Elizondo, the lyrics discuss the harsh end of adolescence and the transition to adulthood. The song was released as a single on April 28, 2015 on the Google Play Store and Amazon, and was issued to top 40 radio stations on November 10. \"Stressed Out\" reached number two on the US Billboard Hot 100, and number one on Hot Rock Songs and Mainstream Top 40. Read more on Last.fm.","content":"\"Stressed Out\" is a song written and recorded by American alternative hip-hop band Twenty One Pilots for their fourth studio album, Blurryface. Written by Tyler Joseph and produced by Mike Elizondo, the lyrics discuss the harsh end of adolescence and the transition to adulthood. The song was released as a single on April 28, 2015 on the Google Play Store and Amazon, and was issued to top 40 radio stations on November 10. \"Stressed Out\" reached number two on the US Billboard Hot 100, and number one on Hot Rock Songs and Mainstream Top 40. Read more on Last.fm. User-contributed text is available under the Creative Commons By-SA License; additional terms may apply."}}}
Apr 25 22:14:18 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:18 volumio volumio[801]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60
Apr 25 22:14:28 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri
Apr 25 22:14:28 volumio volumio[801]: info: Preload queue cleared
Apr 25 22:14:29 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri
Apr 25 22:14:29 volumio volumio[801]: info: Preload queue cleared
Apr 25 22:14:33 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri
Apr 25 22:14:33 volumio volumio[801]: info: Preload queue cleared
Apr 25 22:14:34 volumio volumio[801]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri
Apr 25 22:14:34 volumio volumio[801]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 25 22:14:34 volumio volumio[801]: TypeError: Cannot read property 'length' of undefined
Apr 25 22:14:34 volumio volumio[801]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25
Apr 25 22:14:34 volumio volumio[801]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13
Apr 25 22:14:34 volumio volumio[801]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18)
Apr 25 22:14:34 volumio volumio[801]: at Parser.emit (events.js:315:20)
Apr 25 22:14:34 volumio volumio[801]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26)
Apr 25 22:14:34 volumio volumio[801]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35)
Apr 25 22:14:34 volumio volumio[801]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5)
Apr 25 22:14:34 volumio volumio[801]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7)
Apr 25 22:14:34 volumio volumio[801]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13)
Apr 25 22:14:34 volumio volumio[801]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31)
Apr 25 22:14:34 volumio volumio[801]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59)
Apr 25 22:14:34 volumio volumio[801]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19)
Apr 25 22:14:34 volumio volumio[801]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15)
Apr 25 22:14:34 volumio volumio[801]: at IncomingMessage.emit (events.js:327:22)
Apr 25 22:14:34 volumio volumio[801]: at endReadableNT (internal/streams/readable.js:1327:12)
Apr 25 22:14:34 volumio volumio[801]: at processTicksAndRejections (internal/process/task_queues.js:80:21)
Apr 25 22:14:34 volumio volumio[801]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 25 22:14:35 volumio sudo[2066]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-25 22:13
Apr 25 22:14:35 volumio sudo[2066]: pam_unix(sudo:session): session opened for user root by (uid=0)
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
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="b51559ff3f3719e35ff52cb9ccf2ff401b5ecb06"
VOLUMIO_FE_VERSION="5d5e99f8f803b3ec5fc5e8ca13bb4023600f3eee"
VOLUMIO_FE3_VERSION="a6ae210575eae1ff43f06ab71e1cd17576840623"
VOLUMIO_BE_VERSION="9f81dc1810002a5ad8861a42d98d57bc06a5d5d3"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Wed 17 Apr 2024 07:54:00 PM CEST"
VOLUMIO_VERSION="3.649"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="9c6dee1ade565aed57d77a70a260b988"