-- Logs begin at Wed 2025-02-19 15:38:58 -03, end at Wed 2025-02-26 10:51:25 -03. -- Feb 26 10:51:16 minidsp-shd ntpd[677]: receive: Unexpected origin timestamp 0xeb60a418.1e1d3b41 does not match aorg 0000000000.00000000 from server@200.89.75.198 xmt 0xeb699ad4.7264767a Feb 26 10:51:16 minidsp-shd systemd[1]: Starting Daily apt download activities... Feb 26 10:51:16 minidsp-shd volumio[697]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 26 10:51:17 minidsp-shd ntpd[677]: Soliciting pool server 194.0.5.123 Feb 26 10:51:17 minidsp-shd systemd[1]: apt-daily.service: Succeeded. Feb 26 10:51:17 minidsp-shd systemd[1]: Started Daily apt download activities. Feb 26 10:51:17 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... Feb 26 10:51:17 minidsp-shd ntpd[677]: Soliciting pool server 64.176.4.213 Feb 26 10:51:17 minidsp-shd volumio[697]: ------------------------------------ BT MESSAGE: BT STATUS: running Feb 26 10:51:17 minidsp-shd volumio[697]: info: Discovery: A device disappeared from network Feb 26 10:51:17 minidsp-shd sudo[1195]: pam_unix(sudo:session): session closed for user root Feb 26 10:51:17 minidsp-shd volumio[697]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Feb 26 10:51:18 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. Feb 26 10:51:18 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. Feb 26 10:51:18 minidsp-shd ntpd[677]: Soliciting pool server 2606:4700:f1::123 Feb 26 10:51:18 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:18-03:00" level=debug msg="fetched first chunk of 23, total size is 12007104 bytes" uri="spotify:track:0Pjsm4AaJGPOXHoB6xCgJB" Feb 26 10:51:18 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:18-03:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:0Pjsm4AaJGPOXHoB6xCgJB" Feb 26 10:51:18 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:18-03:00" level=debug msg="created new output device" Feb 26 10:51:18 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:18-03:00" level=info msg="loaded track \"Mariposa Traicionera\" (paused: false, position: -587395547ms, duration: 264599ms, prefetched: false)" uri="spotify:track:0Pjsm4AaJGPOXHoB6xCgJB" Feb 26 10:51:19 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:19-03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:0Pjsm4AaJGPOXHoB6xCgJB" Feb 26 10:51:19 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:19-03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:0Pjsm4AaJGPOXHoB6xCgJB" Feb 26 10:51:19 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:19-03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:0Pjsm4AaJGPOXHoB6xCgJB" Feb 26 10:51:19 minidsp-shd volumio[697]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Feb 26 10:51:22 minidsp-shd ntpd[677]: Soliciting pool server 200.89.75.197 Feb 26 10:51:22 minidsp-shd ntpd[677]: Soliciting pool server 162.159.200.123 Feb 26 10:51:24 minidsp-shd volumio[697]: error: MyVolumio Plugin failed to start in a timely fashion Feb 26 10:51:24 minidsp-shd volumio[697]: info: BOOT COMPLETED Feb 26 10:51:24 minidsp-shd volumio[697]: [Metrics] CommandRouter: 84s 184.11ms Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::volumiosetStartupVolume Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 26 10:51:24 minidsp-shd volumio[697]: info: VolumeController:: Setting startup Volume 30 Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::executeOnPlugin: inputs , setVolume Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::Close All Modals sent Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::Close All Modals sent Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::volumioGetState Feb 26 10:51:24 minidsp-shd volumio[697]: info: CorePlayQueue::getTrack 0 Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreStateMachine::pushState Feb 26 10:51:24 minidsp-shd volumio[697]: info: CorePlayQueue::getTrack 0 Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::volumioPushState Feb 26 10:51:24 minidsp-shd volumio[697]: info: MRS: Pushing multiroomSync output update for this device Feb 26 10:51:24 minidsp-shd volumio[697]: info: MRS: Pushing multiroomSync output Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=trace msg="scheduling prefetch in 229s" Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=trace msg="emitting websocket event: metadata" Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=trace msg="emitting websocket event: active" Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=debug msg="sending successful reply for dealer request" Feb 26 10:51:24 minidsp-shd volumio[697]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0Pjsm4AaJGPOXHoB6xCgJB","name":"Mariposa Traicionera","artist_names":["Maná"],"album_name":"Revolución De Amor","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0214ba3e999835ddf8012772de","position":-587395547,"duration":264599,"release_date":"year:2002","track_number":7,"disc_number":1}} Feb 26 10:51:24 minidsp-shd volumio[697]: SPOTIFY: received: {"type":"active","data":null} Feb 26 10:51:24 minidsp-shd volumio[697]: info: Aligning Spotify Volume to Volumio Volume Feb 26 10:51:24 minidsp-shd volumio[697]: info: CoreCommandRouter::volumioGetState Feb 26 10:51:24 minidsp-shd volumio[697]: info: CorePlayQueue::getTrack 0 Feb 26 10:51:24 minidsp-shd volumio[697]: info: Setting Spotify Volume from Volumio: 30 Feb 26 10:51:24 minidsp-shd volumio[697]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Feb 26 10:51:24 minidsp-shd volumio[697]: xcb_connection_has_error() returned true Feb 26 10:51:24 minidsp-shd volumio[697]: 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 Feb 26 10:51:24 minidsp-shd volumio[697]: aplay: main:828: audio open error: Device or resource busy Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=trace msg="emitting websocket event: playing" Feb 26 10:51:24 minidsp-shd volumio[697]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:0Pjsm4AaJGPOXHoB6xCgJB","play_origin":"playlist"}} Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Feb 26 10:51:24 minidsp-shd volumio[697]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 10:51:24 minidsp-shd volumio[697]: TypeError: Cannot read property 'service' of undefined Feb 26 10:51:24 minidsp-shd volumio[697]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Feb 26 10:51:24 minidsp-shd volumio[697]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Feb 26 10:51:24 minidsp-shd volumio[697]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Feb 26 10:51:24 minidsp-shd volumio[697]: at WebSocket.emit (events.js:400:28) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver.emit (events.js:400:28) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Feb 26 10:51:24 minidsp-shd volumio[697]: at writeOrBuffer (internal/streams/writable.js:358:12) Feb 26 10:51:24 minidsp-shd volumio[697]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Feb 26 10:51:24 minidsp-shd volumio[697]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Feb 26 10:51:24 minidsp-shd volumio[697]: at Socket.emit (events.js:400:28) Feb 26 10:51:24 minidsp-shd volumio[697]: at addChunk (internal/streams/readable.js:293:12) Feb 26 10:51:24 minidsp-shd volumio[697]: at readableAddChunk (internal/streams/readable.js:267:9) Feb 26 10:51:24 minidsp-shd volumio[697]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1356" Feb 26 10:51:24 minidsp-shd go-librespot[972]: time="2025-02-26T10:51:24-03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1124" Feb 26 10:51:25 minidsp-shd sudo[1324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-26 10:50 Feb 26 10:51:25 minidsp-shd sudo[1324]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="17fcb754ddd6bd152b01008c46cc4ba1ca48bf35" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="281cefcd7a302aa7cfba569185cf7aae19b8c376" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="minidspshd" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 22 Mar 2024 03:00:28 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo2" VOLUMIO_DEVICENAME="NanoPi Neo2" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="29ccfe8a9cff19911db4b736879ac117"