-- Logs begin at Thu 2019-02-14 04:11:58 CST, end at Sun 2025-06-15 16:12:08 CDT. -- Jun 15 16:11:45 volumio-living volumio[1168]: info: CoreCommandRouter::volumioPlay Jun 15 16:11:45 volumio-living volumio[1168]: info: CoreStateMachine::play index undefined Jun 15 16:11:45 volumio-living volumio[1168]: info: CoreStateMachine::setConsumeUpdateService undefined Jun 15 16:11:45 volumio-living volumio[1168]: info: CorePlayQueue::getTrack 0 Jun 15 16:11:45 volumio-living volumio[1168]: info: CoreStateMachine::startPlaybackTimer Jun 15 16:11:45 volumio-living volumio[1168]: info: CorePlayQueue::getTrack 0 Jun 15 16:11:45 volumio-living volumio[1168]: info: [1750021905898] ControllerTidal::clearAddPlayTrack Jun 15 16:11:45 volumio-living volumio[1168]: info: Getting stream with soundQuality HI_RES Jun 15 16:11:45 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand stop Jun 15 16:11:45 volumio-living volumio[1168]: info: sendMpdCommand stop took 3 milliseconds Jun 15 16:11:45 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand clear Jun 15 16:11:45 volumio-living volumio[1168]: info: Jun 15 16:11:45 volumio-living volumio[1168]: ---------------------------- MPD announces system playlist update Jun 15 16:11:45 volumio-living volumio[1168]: info: Ignoring MPD Status Update Jun 15 16:11:45 volumio-living volumio[1168]: info: sendMpdCommand clear took 2 milliseconds Jun 15 16:11:45 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/196069712&soundQuality=HI_RES" Jun 15 16:11:45 volumio-living volumio[1168]: error: updateQueue error: null Jun 15 16:11:45 volumio-living volumio[1168]: info: Jun 15 16:11:45 volumio-living volumio[1168]: ---------------------------- MPD announces system playlist update Jun 15 16:11:45 volumio-living volumio[1168]: info: Ignoring MPD Status Update Jun 15 16:11:45 volumio-living volumio[1168]: info: ------------------------------ 3ms Jun 15 16:11:45 volumio-living volumio[1168]: info: sendMpdCommand add "http://127.0.0.1:3245?data=tidal://song/196069712&soundQuality=HI_RES" took 2 milliseconds Jun 15 16:11:45 volumio-living volumio[1168]: info: CoreStateMachine::setConsumeUpdateService mpd Jun 15 16:11:45 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand play Jun 15 16:11:45 volumio-living volumio[1168]: info: ------------------------------ 3ms Jun 15 16:11:45 volumio-living volumio[1168]: info: sendMpdCommand play took 2 milliseconds Jun 15 16:11:45 volumio-living volumio[1168]: STREAMING PROXY: Handling url /?data=tidal://song/196069712&soundQuality=HI_RES Jun 15 16:11:45 volumio-living volumio[1168]: info: Executing endpoint getStreamUrltidal Jun 15 16:11:45 volumio-living volumio[1168]: info: CoreCommandRouter::executeOnPlugin: tidal , getStreamUrlAPI Jun 15 16:11:46 volumio-living volumio[1168]: info: getStreamUrl took 973 milliseconds Jun 15 16:11:46 volumio-living volumio[1168]: STREAMING PROXY: Got real url: http://sp-pr-fa.audio.tidal.com/mediatracks/CAEaKwgDEicwNWE1NWRjMjZiMGJlYjg3Y2Y4NjY1OTQzN2ZkMzk0YV82Mi5tcDQ/0.flac?token=1750025506~OGU5MjdkNzYyMTI3MjQ3YjEzYTk2OTJlNjhjZGQ4Y2U0ZTQ3OWMzZA== Jun 15 16:11:47 volumio-living volumio[1168]: STREAMING PROXY: Response: 200, length: 17843379 Jun 15 16:11:47 volumio-living volumio[1168]: info: Jun 15 16:11:47 volumio-living volumio[1168]: ---------------------------- MPD announces state update: player Jun 15 16:11:47 volumio-living volumio[1168]: info: ControllerMpd::getState Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand status Jun 15 16:11:47 volumio-living volumio[1168]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Jun 15 16:11:47 volumio-living volumio[1168]: info: FusionDsp - ---- read samplerate from file: 44100 Jun 15 16:11:47 volumio-living volumio[1168]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jun 15 16:11:47 volumio-living volumio[1168]: info: Jun 15 16:11:47 volumio-living volumio[1168]: ---------------------------- MPD announces state update: player Jun 15 16:11:47 volumio-living volumio[1168]: info: sendMpdCommand status took 21 milliseconds Jun 15 16:11:47 volumio-living volumio[1168]: info: ControllerMpd::getState Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand status Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::parseState Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 15 16:11:47 volumio-living volumio[1168]: info: sendMpdCommand status took 2 milliseconds Jun 15 16:11:47 volumio-living volumio[1168]: info: sendMpdCommand playlistinfo took 2 milliseconds Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::parseState Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::sendMpdCommand playlistinfo Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::parseTrackInfo Jun 15 16:11:47 volumio-living volumio[1168]: info: ControllerMpd::pushState Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::servicePushState Jun 15 16:11:47 volumio-living volumio[1168]: info: CorePlayQueue::getTrack 0 Jun 15 16:11:47 volumio-living volumio[1168]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":90,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"196069712&soundQuality=HI_RES","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/196069712&soundQuality=HI_RES","trackType":"tidal"} Jun 15 16:11:47 volumio-living volumio[1168]: verbose: CURRENT POSITION 0 Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreStateMachine::syncState stateService play Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreStateMachine::syncState currentStatus stop Jun 15 16:11:47 volumio-living volumio[1168]: info: ------------------------------ 28ms Jun 15 16:11:47 volumio-living volumio[1168]: info: sendMpdCommand playlistinfo took 3 milliseconds Jun 15 16:11:47 volumio-living volumio[1168]: verbose: ControllerMpd::parseTrackInfo Jun 15 16:11:47 volumio-living volumio[1168]: info: ControllerMpd::pushState Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::servicePushState Jun 15 16:11:47 volumio-living volumio[1168]: info: CorePlayQueue::getTrack 0 Jun 15 16:11:47 volumio-living volumio[1168]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":90,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"196069712&soundQuality=HI_RES","artist":null,"album":null,"uri":"http://127.0.0.1:3245?data=tidal://song/196069712&soundQuality=HI_RES","trackType":"tidal"} Jun 15 16:11:47 volumio-living volumio[1168]: verbose: CURRENT POSITION 0 Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreStateMachine::syncState stateService play Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreStateMachine::syncState currentStatus play Jun 15 16:11:47 volumio-living volumio[1168]: info: Received an update from plugin. extracting info from payload Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreStateMachine::pushState Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::volumioPushState Jun 15 16:11:47 volumio-living volumio[1168]: info: MRS: Pushing multiroomSync output update for this device Jun 15 16:11:47 volumio-living volumio[1168]: info: MRS: Pushing multiroomSync output Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::volumioGetState Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreStateMachine::pushState Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::volumioPushState Jun 15 16:11:47 volumio-living volumio[1168]: info: MRS: Pushing multiroomSync output update for this device Jun 15 16:11:47 volumio-living volumio[1168]: info: MRS: Pushing multiroomSync output Jun 15 16:11:47 volumio-living volumio[1168]: info: CoreCommandRouter::volumioGetState Jun 15 16:11:47 volumio-living volumio[1168]: info: ------------------------------ 19ms Jun 15 16:11:47 volumio-living volumio[1168]: info: FusionDsp - {"Reload":{"result":"Ok"}} Jun 15 16:11:47 volumio-living volumio[1168]: STREAMING PROXY: Client dropped request, destroying Jun 15 16:11:58 volumio-living volumio[1168]: info: CoreCommandRouter::executeOnPlugin: multiroom , enableAudioOutput Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: Setting this device as multiroomSync server Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: Setting another device as multiroomSync client Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: Setting this device as Server Jun 15 16:11:58 volumio-living volumio[1168]: info: Jun 15 16:11:58 volumio-living volumio[1168]: [1750021918693] ---------------------------- MRS: Setting Multiroom Server Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: Pushing multiroomSync output Jun 15 16:11:58 volumio-living volumio[1168]: info: Enabled audio output: 36d69642-810d-44df-a647-c9f4def8c263 Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: STARTING SNAPCLIENT Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: STOPPING SNAPCLIENT Jun 15 16:11:58 volumio-living sudo[15777]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioSnapclient Jun 15 16:11:58 volumio-living sudo[15777]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 15 16:11:58 volumio-living systemd[1]: Starting Snapcast client... Jun 15 16:11:58 volumio-living volumio[1168]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 15 16:11:58 volumio-living snapclient[15780]: daemon started Jun 15 16:11:58 volumio-living systemd[1]: Started Snapcast client. Jun 15 16:11:58 volumio-living sudo[15777]: pam_unix(sudo:session): session closed for user root Jun 15 16:11:58 volumio-living volumio[1168]: info: MRS: SNAPCLIENT STARTED Jun 15 16:11:59 volumio-living volumio[1168]: info: MRS: STARTING SNAPSERVER Jun 15 16:11:59 volumio-living volumio[1168]: info: MRS: enable multiroom server output Jun 15 16:11:59 volumio-living volumio[1168]: info: MRS: Set multiroom target PCM to volumioMultiRoom Jun 15 16:11:59 volumio-living volumio[1168]: info: Changed audio target for /tmp/multiroom/server/switch.target to volumioMultiRoom Jun 15 16:11:59 volumio-living volumio[1168]: info: MRS: Set multiroom target PCM to volumioLocalPlayback Jun 15 16:11:59 volumio-living volumio[1168]: info: MRS: Snap server restart Jun 15 16:11:59 volumio-living volumio[1168]: info: Changed audio target for /tmp/multiroom/client/switch.target to volumioLocalPlayback Jun 15 16:11:59 volumio-living sudo[15798]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumioSnapserver Jun 15 16:11:59 volumio-living sudo[15798]: pam_unix(sudo:session): session opened for user root by (uid=0) Jun 15 16:11:59 volumio-living systemd[1]: Starting Snapcast server... Jun 15 16:11:59 volumio-living volumio[1168]: ------------------------------------ BT MESSAGE: BT STATUS: running Jun 15 16:11:59 volumio-living snapserver[15800]: Settings file: "/var/lib/snapserver/server.json" Jun 15 16:11:59 volumio-living snapserver[15800]: pipe:///tmp/multiroom/server/fifo?name=Radio&sampleformat=48000:16:2&codec=flac Jun 15 16:11:59 volumio-living snapserver[15800]: 2025-06-15 16-11-59 [Notice] Settings file: "/var/lib/snapserver/server.json" Jun 15 16:11:59 volumio-living snapserver[15802]: daemon started Jun 15 16:11:59 volumio-living systemd[1]: Started Snapcast server. Jun 15 16:11:59 volumio-living sudo[15798]: pam_unix(sudo:session): session closed for user root Jun 15 16:11:59 volumio-living volumio[1168]: info: MRS: SNAPSERVER STARTED Jun 15 16:11:59 volumio-living kernel: bcm2835_audio bcm2835_audio: failed to close VCHI service connection (status=-11) Jun 15 16:12:00 volumio-living snapclient[15780]: Connected to 169.254.21.28 Jun 15 16:12:00 volumio-living snapserver[15802]: StreamServer::NewConnection: ::ffff:169.254.21.28 Jun 15 16:12:00 volumio-living volumio[1168]: info: FusionDsp - ---- read samplerate, raw: 48000,S32_LE,2,32 Jun 15 16:12:00 volumio-living volumio[1168]: info: FusionDsp - ---- read samplerate from file: 48000 Jun 15 16:12:00 volumio-living volumio[1168]: info: camilladsp stopping service pid 15806... Jun 15 16:12:00 volumio-living kernel: bcm2835_audio bcm2835_audio: failed to close VCHI service connection (status=-11) Jun 15 16:12:00 volumio-living volumio[1168]: info: camilladsp service terminated, instance 1 Jun 15 16:12:00 volumio-living volumio[1168]: info: FusionDsp - If filter freq >samplerate/2 then disable it Jun 15 16:12:00 volumio-living volumio[1168]: info: camilladsp service started and running in background, instance 1 Jun 15 16:12:00 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:00 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:00 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:00 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:00 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:01 volumio-living volumio[1168]: info: MRS: Updating multiroomSync output Jun 15 16:12:03 volumio-living snapserver[15802]: StreamServer::NewConnection: ::ffff:10.2.0.107 Jun 15 16:12:04 volumio-living snapserver[15802]: Exception in StreamSession::reader(): read_some: End of file Jun 15 16:12:08 volumio-living volumio[1168]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay Jun 15 16:12:08 volumio-living volumio[1168]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom Jun 15 16:12:08 volumio-living volumio[1168]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 15 16:12:08 volumio-living volumio[1168]: TypeError: Cannot read property 'then' of undefined Jun 15 16:12:08 volumio-living volumio[1168]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) Jun 15 16:12:08 volumio-living volumio[1168]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2279:30) Jun 15 16:12:08 volumio-living volumio[1168]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1456:26) Jun 15 16:12:08 volumio-living volumio[1168]: at Socket.emit (events.js:315:20) Jun 15 16:12:08 volumio-living volumio[1168]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Jun 15 16:12:08 volumio-living volumio[1168]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Jun 15 16:12:08 volumio-living volumio[1168]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jun 15 16:12:08 volumio-living sudo[15852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-06-15 16:11 Jun 15 16:12:08 volumio-living sudo[15852]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="04c18c158cc4bac70764c3360b25fcce0c69266a" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 10 Jun 2025 04:52:53 PM CEST" VOLUMIO_VERSION="3.816" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="a72866a0de4045751d03a035de6290e1"