-- Logs begin at Thu 2019-02-14 12:11:58 EET, end at Wed 2024-08-28 03:09:08 EEST. -- Aug 28 03:09:03 volumio-rpi5-8g-128gb ntpd[1008]: receive: Unexpected origin timestamp 0xea78e818.01ede963 does not match aorg 0000000000.00000000 from server@92.86.106.228 xmt 0xea78e91f.2319d3a6 Aug 28 03:09:03 volumio-rpi5-8g-128gb ntpd[1008]: receive: Unexpected origin timestamp 0xea78e818.01f57adc does not match aorg 0000000000.00000000 from server@93.190.144.3 xmt 0xea78e91f.2b4e79fa Aug 28 03:09:04 volumio-rpi5-8g-128gb ntpd[1008]: Soliciting pool server 89.36.93.9 Aug 28 03:09:04 volumio-rpi5-8g-128gb ntpd[1008]: Soliciting pool server 2606:4700:f1::1 Aug 28 03:09:04 volumio-rpi5-8g-128gb volumio[1204]: info: MRS: Pushing audio output on request Aug 28 03:09:04 volumio-rpi5-8g-128gb volumio[1204]: info: MRS: Pushing multiroomSync output Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CoreCommandRouter::executeOnPlugin: system , getHwuuid Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: Playing Remote Device: http://192.168.3.66 Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: ---------------------------- Client requests Volumio play Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CoreCommandRouter::volumioPlay Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CoreStateMachine::play index undefined Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CorePlayQueue::getTrack 0 Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CoreStateMachine::startPlaybackTimer Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: CorePlayQueue::getTrack 0 Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: [1724803746392] ControllerSpotify::clearAddPlayTrack Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: Sending Spotify command with payload to local API: /player/play Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: info: Done playing: Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=debug msg="resolved context of track" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=trace msg="emitting websocket event: will_play" Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4GSDkZt7GcmzBWmsMcpaVO","play_origin":"go-librespot"}} Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=debug msg="selected format OGG_VORBIS_320 (d621edddc2ff937231e1dc66bce27c8c8d6eb6e9)" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=debug msg="requested aes key for file d621edddc2ff937231e1dc66bce27c8c8d6eb6e9, gid: 4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=debug msg="fetched first chunk of 14, total size is 7154568 bytes" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: ALSA lib pcm_hw.c:1822:(_snd_pcm_hw_open) Invalid value for card Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:143:(_snd_pcm_volumioswitch_open_target_pcm) PCM Volumio ALSA Switch Plugin failed to open the switcher target pcm volumioLocalPlayback Aug 28 03:09:06 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:06+03:00" level=error msg="failed handling status request" error="failed loading context: failed loading current track (load context): failed setting stream for spotify:track:4GSDkZt7GcmzBWmsMcpaVO: ALSA error at snd_pcm_open: No such device" Aug 28 03:09:06 volumio-rpi5-8g-128gb volumio[1204]: error: Failed to send command to Spotify local API: /player/play: Error: Internal Server Error Aug 28 03:09:07 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:07+03:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:07 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:07+03:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:07 volumio-rpi5-8g-128gb go-librespot[1376]: time="2024-08-28T03:09:07+03:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:4GSDkZt7GcmzBWmsMcpaVO" Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: info: CoreCommandRouter::executeOnPlugin: multiroom , audioOutputPlay Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: info: Error : CoreCommandRouter::executeOnPlugin: No method [audioOutputPlay] in plugin multiroom Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: TypeError: Cannot read property 'then' of undefined Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: at outputs.audioOutputPlay (/volumio/app/plugins/audio_interface/outputs/index.js:367:9) Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: at CoreCommandRouter.audioOutputPlay (/volumio/app/index.js:2260:30) Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1442:26) Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: at Socket.emit (events.js:315:20) Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Aug 28 03:09:08 volumio-rpi5-8g-128gb volumio[1204]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 28 03:09:08 volumio-rpi5-8g-128gb sudo[1709]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-28 03:08 Aug 28 03:09:08 volumio-rpi5-8g-128gb sudo[1709]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"