-- Logs begin at Thu 2019-02-14 17:11:59 +07, end at Tue 2023-08-15 12:41:49 +07. --
Aug 15 12:40:00 volumio volumio[669]: info: Volumio called home
Aug 15 12:40:03 volumio sudo[931]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Aug 15 12:40:03 volumio sudo[931]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 15 12:40:03 volumio sudo[931]: pam_unix(sudo:session): session closed for user root
Aug 15 12:40:03 volumio sudo[933]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Aug 15 12:40:03 volumio sudo[933]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 15 12:40:03 volumio sudo[933]: pam_unix(sudo:session): session closed for user root
Aug 15 12:40:03 volumio sudo[937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Aug 15 12:40:03 volumio sudo[937]: pam_unix(sudo:session): session opened for user root by (uid=0)
Aug 15 12:40:03 volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Aug 15 12:40:03 volumio sudo[937]: pam_unix(sudo:session): session closed for user root
Aug 15 12:40:03 volumio volumio[669]: info: Upmpdcli Daemon Started
Aug 15 12:40:03 volumio volumio[939]: Generating RSA private key, 4096 bit long modulus (2 primes)
Aug 15 12:40:07 volumio volumio-remote-updater[513]: [2023-08-15 12:40:07] [connect] Successful connection
Aug 15 12:40:07 volumio volumio-remote-updater[513]: [2023-08-15 12:40:07] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1692078007 101
Aug 15 12:40:07 volumio volumio[669]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 2
Aug 15 12:40:07 volumio systemd[1]: systemd-fsckd.service: Succeeded.
Aug 15 12:40:16 volumio systemd[1]: systemd-hostnamed.service: Succeeded.
Aug 15 12:40:16 volumio volumio[939]: ...............................................................................................................................................++++
Aug 15 12:40:18 volumio volumio[669]: error: MyVolumio Plugin failed to start in a timely fashion
Aug 15 12:40:18 volumio volumio[669]: info: BOOT COMPLETED
Aug 15 12:40:18 volumio volumio[669]: [Metrics] CommandRouter: 29s 361.30ms
Aug 15 12:40:18 volumio volumio[669]: info: CoreCommandRouter::volumiosetStartupVolume
Aug 15 12:40:18 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Aug 15 12:40:18 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 15 12:40:18 volumio volumio[669]: info: CoreCommandRouter::Close All Modals sent
Aug 15 12:40:18 volumio volumio[669]: info: CoreCommandRouter::Close All Modals sent
Aug 15 12:40:19 volumio volumio[939]: ................................++++
Aug 15 12:40:19 volumio volumio[939]: e is 65537 (0x010001)
Aug 15 12:40:19 volumio volumio[939]: writing RSA key
Aug 15 12:40:19 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Aug 15 12:40:19 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Aug 15 12:40:20 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Aug 15 12:40:28 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Aug 15 12:40:28 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Aug 15 12:40:28 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Aug 15 12:40:46 volumio ntpd[637]: Soliciting pool server 103.130.217.41
Aug 15 12:40:48 volumio volumio[669]: error: error
Aug 15 12:40:49 volumio ntpd[637]: Soliciting pool server 2001:19f0:4400:7d02:5400:5ff:fe04:48b6
Aug 15 12:40:53 volumio volumio[669]: info: Clearing queue after UPNP request
Aug 15 12:40:54 volumio volumio[669]: info: CoreStateMachine::ClearQueue
Aug 15 12:40:54 volumio volumio[669]: info: CoreStateMachine::stop
Aug 15 12:40:54 volumio volumio[669]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 15 12:40:54 volumio volumio[669]: info: CorePlayQueue::clearPlayQueue
Aug 15 12:40:54 volumio volumio[669]: info: CorePlayQueue::saveQueue
Aug 15 12:40:54 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:40:54 volumio volumio[669]: info: CoreCommandRouter::volumioPushQueue
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: error: updateQueue error: null
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 3ms
Aug 15 12:40:54 volumio volumio[669]: info: Starting UPNP Playback
Aug 15 12:40:54 volumio volumio[669]: info: Preparing playback through UPNP
Aug 15 12:40:54 volumio volumio[669]: info: CoreCommandRouter::volumioGetState
Aug 15 12:40:54 volumio volumio[669]: info: CorePlayQueue::getTrack 0
Aug 15 12:40:54 volumio volumio[669]: info: CoreStateMachine::setConsumeUpdateService mpd
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 3ms
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 2ms
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:40:54 volumio volumio[669]: info:
Aug 15 12:40:54 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:40:54 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:40:54 volumio volumio[669]: info: ------------------------------ 2ms
Aug 15 12:40:55 volumio volumio[669]: info:
Aug 15 12:40:55 volumio volumio[669]: ---------------------------- MPD announces state update: player
Aug 15 12:40:55 volumio volumio[669]: info: ControllerMpd::getState
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand status
Aug 15 12:40:55 volumio volumio[669]: info:
Aug 15 12:40:55 volumio volumio[669]: ---------------------------- MPD announces state update: player
Aug 15 12:40:55 volumio volumio[669]: info: sendMpdCommand status took 49 milliseconds
Aug 15 12:40:55 volumio volumio[669]: info: ControllerMpd::getState
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand status
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::parseState
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Aug 15 12:40:55 volumio volumio[669]: info: sendMpdCommand status took 4 milliseconds
Aug 15 12:40:55 volumio volumio[669]: info: sendMpdCommand playlistinfo took 2 milliseconds
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::parseState
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::parseTrackInfo
Aug 15 12:40:55 volumio volumio[669]: info: ControllerMpd::pushState
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::servicePushState
Aug 15 12:40:55 volumio volumio[669]: verbose: In UPNP mode
Aug 15 12:40:55 volumio volumio[669]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":231,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"1 Kbps","isStreaming":false,"title":"A Woman's Heart","artist":"Various Artists","album":"A Woman's Heart","uri":"http://10.0.0.2:15595/qobuz/22585145.flac","trackType":"qobuz"}
Aug 15 12:40:55 volumio volumio[669]: verbose: CURRENT POSITION 0
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::syncState stateService play
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::syncState currentStatus stop
Aug 15 12:40:55 volumio volumio[669]: info: ------------------------------ 65ms
Aug 15 12:40:55 volumio volumio[669]: info: sendMpdCommand playlistinfo took 9 milliseconds
Aug 15 12:40:55 volumio volumio[669]: verbose: ControllerMpd::parseTrackInfo
Aug 15 12:40:55 volumio volumio[669]: info: ControllerMpd::pushState
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::servicePushState
Aug 15 12:40:55 volumio volumio[669]: verbose: In UPNP mode
Aug 15 12:40:55 volumio volumio[669]: verbose: STATE SERVICE {"status":"play","position":0,"seek":22,"duration":231,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"327 Kbps","isStreaming":false,"title":"A Woman's Heart","artist":"Various Artists","album":"A Woman's Heart","uri":"http://10.0.0.2:15595/qobuz/22585145.flac","trackType":"qobuz"}
Aug 15 12:40:55 volumio volumio[669]: verbose: CURRENT POSITION 0
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::syncState stateService play
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::syncState currentStatus play
Aug 15 12:40:55 volumio volumio[669]: info: Received an update from plugin. extracting info from payload
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:40:55 volumio volumio[669]: info: ------------------------------ 36ms
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:40:55 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:40:55 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:40:55 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:40:55 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:09 volumio volumio[939]: 94
Aug 15 12:41:09 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:09 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:09 volumio volumio[669]: info:
Aug 15 12:41:09 volumio volumio[669]: ---------------------------- Client requests Volume 94
Aug 15 12:41:09 volumio volumio[669]: info: VolumeController::SetAlsaVolume94
Aug 15 12:41:09 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:09 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:09 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:09 volumio volumio[939]: [158B blob data]
Aug 15 12:41:09 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:09 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:09 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:09 volumio volumio[939]: {"time":1692078069934,"response":"volume Success"}94
Aug 15 12:41:10 volumio volumio[939]: 88
Aug 15 12:41:10 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:10 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:10 volumio volumio[669]: info:
Aug 15 12:41:10 volumio volumio[669]: ---------------------------- Client requests Volume 88
Aug 15 12:41:10 volumio volumio[669]: info: VolumeController::SetAlsaVolume88
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:10 volumio volumio[939]: [158B blob data]
Aug 15 12:41:10 volumio volumio[939]: {"time":1692078070244,"response":"volume Success"}88
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:10 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:10 volumio volumio[939]: 81
Aug 15 12:41:10 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:10 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:10 volumio volumio[669]: info:
Aug 15 12:41:10 volumio volumio[669]: ---------------------------- Client requests Volume 81
Aug 15 12:41:10 volumio volumio[669]: info: VolumeController::SetAlsaVolume81
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:10 volumio volumio[939]: [158B blob data]
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:10 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:10 volumio volumio[939]: {"time":1692078070322,"response":"volume Success"}81
Aug 15 12:41:10 volumio volumio[939]: 75
Aug 15 12:41:10 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:10 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:10 volumio volumio[669]: info:
Aug 15 12:41:10 volumio volumio[669]: ---------------------------- Client requests Volume 75
Aug 15 12:41:10 volumio volumio[669]: info: VolumeController::SetAlsaVolume75
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:10 volumio volumio[939]: [158B blob data]
Aug 15 12:41:10 volumio volumio[939]: {"time":1692078070454,"response":"volume Success"}75
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:10 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:10 volumio volumio[939]: 69
Aug 15 12:41:10 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:10 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:10 volumio volumio[669]: info:
Aug 15 12:41:10 volumio volumio[669]: ---------------------------- Client requests Volume 69
Aug 15 12:41:10 volumio volumio[669]: info: VolumeController::SetAlsaVolume69
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:10 volumio volumio[939]: [158B blob data]
Aug 15 12:41:10 volumio volumio[939]: {"time":1692078070539,"response":"volume Success"}69
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:10 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:10 volumio volumio[939]: 63
Aug 15 12:41:10 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:10 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:10 volumio volumio[669]: info:
Aug 15 12:41:10 volumio volumio[669]: ---------------------------- Client requests Volume 63
Aug 15 12:41:10 volumio volumio[669]: info: VolumeController::SetAlsaVolume63
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:10 volumio volumio[939]: [158B blob data]
Aug 15 12:41:10 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:10 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:10 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:10 volumio volumio[939]: {"time":1692078070678,"response":"volume Success"}63
Aug 15 12:41:11 volumio volumio[939]: 69
Aug 15 12:41:11 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:11 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:11 volumio volumio[669]: info:
Aug 15 12:41:11 volumio volumio[669]: ---------------------------- Client requests Volume 69
Aug 15 12:41:11 volumio volumio[669]: info: VolumeController::SetAlsaVolume69
Aug 15 12:41:11 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:11 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:11 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:11 volumio volumio[939]: [158B blob data]
Aug 15 12:41:11 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:11 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:11 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:11 volumio volumio[939]: {"time":1692078071253,"response":"volume Success"}69
Aug 15 12:41:11 volumio volumio[939]: 75
Aug 15 12:41:11 volumio volumio[939]: % Total % Received % Xferd Average Speed Time Time Time Current
Aug 15 12:41:11 volumio volumio[939]: Dload Upload Total Spent Left Speed
Aug 15 12:41:11 volumio volumio[669]: info:
Aug 15 12:41:11 volumio volumio[669]: ---------------------------- Client requests Volume 75
Aug 15 12:41:11 volumio volumio[669]: info: VolumeController::SetAlsaVolume75
Aug 15 12:41:11 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:11 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:11 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:11 volumio volumio[939]: [158B blob data]
Aug 15 12:41:11 volumio volumio[939]: {"time":1692078071572,"response":"volume Success"}75
Aug 15 12:41:11 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:11 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:11 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:33 volumio volumio[669]: info:
Aug 15 12:41:33 volumio volumio[669]: ---------------------------- MPD announces state update: player
Aug 15 12:41:33 volumio volumio[669]: info: ControllerMpd::getState
Aug 15 12:41:33 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand status
Aug 15 12:41:33 volumio volumio[669]: info: sendMpdCommand status took 1 milliseconds
Aug 15 12:41:33 volumio volumio[669]: verbose: ControllerMpd::parseState
Aug 15 12:41:33 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Aug 15 12:41:33 volumio volumio[669]: info: sendMpdCommand playlistinfo took 1 milliseconds
Aug 15 12:41:33 volumio volumio[669]: verbose: ControllerMpd::parseTrackInfo
Aug 15 12:41:33 volumio volumio[669]: info: ControllerMpd::pushState
Aug 15 12:41:33 volumio volumio[669]: info: CoreCommandRouter::servicePushState
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:33 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:33 volumio volumio[669]: info: CorePlayQueue::getTrack 0
Aug 15 12:41:33 volumio volumio[669]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"A Woman's Heart","artist":"Various Artists","album":"A Woman's Heart","uri":"http://10.0.0.2:15595/qobuz/22585145.flac","trackType":"qobuz"}
Aug 15 12:41:33 volumio volumio[669]: verbose: CURRENT POSITION 0
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::syncState stateService stop
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::syncState currentStatus play
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::play index undefined
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:33 volumio volumio[669]: info: CorePlayQueue::getTrack 0
Aug 15 12:41:33 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:33 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:33 volumio volumio[669]: info: CorePlayQueue::getTrack 0
Aug 15 12:41:33 volumio volumio[669]: info: ------------------------------ 16ms
Aug 15 12:41:33 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:33 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:33 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:36 volumio volumio[669]: info: Clearing queue after UPNP request
Aug 15 12:41:37 volumio volumio[669]: info: CoreStateMachine::ClearQueue
Aug 15 12:41:37 volumio volumio[669]: info: CoreStateMachine::stop
Aug 15 12:41:37 volumio volumio[669]: info: CoreStateMachine::setConsumeUpdateService undefined
Aug 15 12:41:37 volumio volumio[669]: info: CorePlayQueue::clearPlayQueue
Aug 15 12:41:37 volumio volumio[669]: info: CorePlayQueue::saveQueue
Aug 15 12:41:37 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:37 volumio volumio[669]: info: CoreCommandRouter::volumioPushQueue
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: error: updateQueue error: null
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:41:37 volumio volumio[669]: info: Starting UPNP Playback
Aug 15 12:41:37 volumio volumio[669]: info: Preparing playback through UPNP
Aug 15 12:41:37 volumio volumio[669]: info: CoreCommandRouter::volumioGetState
Aug 15 12:41:37 volumio volumio[669]: info: CorePlayQueue::getTrack 0
Aug 15 12:41:37 volumio volumio[669]: info: CoreStateMachine::setConsumeUpdateService mpd
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 2ms
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 2ms
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:41:37 volumio volumio[669]: info:
Aug 15 12:41:37 volumio volumio[669]: ---------------------------- MPD announces system playlist update
Aug 15 12:41:37 volumio volumio[669]: info: Ignoring MPD Status Update
Aug 15 12:41:37 volumio volumio[669]: info: ------------------------------ 1ms
Aug 15 12:41:38 volumio volumio[669]: info:
Aug 15 12:41:38 volumio volumio[669]: ---------------------------- MPD announces state update: player
Aug 15 12:41:38 volumio volumio[669]: info: ControllerMpd::getState
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand status
Aug 15 12:41:38 volumio volumio[669]: info:
Aug 15 12:41:38 volumio volumio[669]: ---------------------------- MPD announces state update: player
Aug 15 12:41:38 volumio volumio[669]: info: sendMpdCommand status took 20 milliseconds
Aug 15 12:41:38 volumio volumio[669]: info: ControllerMpd::getState
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand status
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::parseState
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Aug 15 12:41:38 volumio volumio[669]: info: sendMpdCommand status took 1 milliseconds
Aug 15 12:41:38 volumio volumio[669]: info: sendMpdCommand playlistinfo took 2 milliseconds
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::parseState
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::parseTrackInfo
Aug 15 12:41:38 volumio volumio[669]: info: ControllerMpd::pushState
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::servicePushState
Aug 15 12:41:38 volumio volumio[669]: verbose: In UPNP mode
Aug 15 12:41:38 volumio volumio[669]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":238,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Air Circus #1","artist":"Dean Peer","album":"Think... It's All Good","uri":"http://10.0.0.2:15595/qobuz/73258142.flac","trackType":"qobuz"}
Aug 15 12:41:38 volumio volumio[669]: verbose: CURRENT POSITION 0
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::syncState stateService play
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::syncState currentStatus stop
Aug 15 12:41:38 volumio volumio[669]: info: ------------------------------ 27ms
Aug 15 12:41:38 volumio volumio[669]: info: sendMpdCommand playlistinfo took 2 milliseconds
Aug 15 12:41:38 volumio volumio[669]: verbose: ControllerMpd::parseTrackInfo
Aug 15 12:41:38 volumio volumio[669]: info: ControllerMpd::pushState
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::servicePushState
Aug 15 12:41:38 volumio volumio[669]: verbose: In UPNP mode
Aug 15 12:41:38 volumio volumio[669]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":238,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"337 Kbps","isStreaming":false,"title":"Air Circus #1","artist":"Dean Peer","album":"Think... It's All Good","uri":"http://10.0.0.2:15595/qobuz/73258142.flac","trackType":"qobuz"}
Aug 15 12:41:38 volumio volumio[669]: verbose: CURRENT POSITION 0
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::syncState stateService play
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::syncState currentStatus play
Aug 15 12:41:38 volumio volumio[669]: info: Received an update from plugin. extracting info from payload
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::pushState
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::volumioPushState
Aug 15 12:41:38 volumio volumio[669]: info: ------------------------------ 20ms
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:38 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:38 volumio volumio[669]: info: CoreCommandRouter::volumioGetQueue
Aug 15 12:41:38 volumio volumio[669]: info: CoreStateMachine::getQueue
Aug 15 12:41:38 volumio volumio[669]: info: CorePlayQueue::getQueue
Aug 15 12:41:38 volumio volumio[669]: error: error
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Aug 15 12:41:47 volumio volumio[669]: info: Discovery: Getting this device information
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::volumioGetState
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Aug 15 12:41:47 volumio volumio[669]: verbose: New Socket.io Connection to 10.0.0.3 from 10.0.0.2 UA: unknown Total Clients: 3
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::volumioGetState
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard
Aug 15 12:41:47 volumio volumio[669]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard
Aug 15 12:41:48 volumio volumio[669]: An internal error occurred while serving an albumart. Details: Error: ENOENT: no such file or directory, stat '/data/albumart/web/Dean%20Peer/Think...%20It's%20All%20Good/9f338af5-b3c1-4a9e-be9c-f34967d0f296.jpg'
Aug 15 12:41:48 volumio volumio[669]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Aug 15 12:41:48 volumio volumio[669]: Error: certificate is not yet valid
Aug 15 12:41:48 volumio volumio[669]: at TLSSocket.onConnectSecure (_tls_wrap.js:1497:34)
Aug 15 12:41:48 volumio volumio[669]: at TLSSocket.emit (events.js:315:20)
Aug 15 12:41:48 volumio volumio[669]: at TLSSocket._finishInit (_tls_wrap.js:932:8)
Aug 15 12:41:48 volumio volumio[669]: at TLSWrap.ssl.onhandshakedone (_tls_wrap.js:706:12) {
Aug 15 12:41:48 volumio volumio[669]: code: 'CERT_NOT_YET_VALID'
Aug 15 12:41:48 volumio volumio[669]: }
Aug 15 12:41:48 volumio volumio[669]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Aug 15 12:41:49 volumio sudo[1223]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2023-08-15 12:40
Aug 15 12:41:49 volumio sudo[1223]: 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="b1c3cf61c2a0027c66bab1eb0a3795f80c1f2e95"
VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71"
VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1"
VOLUMIO_BE_VERSION="e3eb3ee5b16063502f3a1735e11a28cfe54a0f46"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Sun 25 Jun 2023 07:20:58 PM CEST"
VOLUMIO_VERSION="3.512"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="946a42b62509f37b5e7e2d86a2932a62"