-- Logs begin at Thu 2019-02-14 18:11:59 +08, end at Tue 2024-07-09 22:33:32 +08. -- Jul 09 22:33:28 minidsp-shd volumio[624]: info: Connection to go-librespot Websocket established Jul 09 22:33:28 minidsp-shd systemd[1]: Starting Daily apt download activities... Jul 09 22:33:28 minidsp-shd volumio[624]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 09 22:33:28 minidsp-shd volumio[872]: Generating RSA private key, 4096 bit long modulus (2 primes) Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.881583, 0] ../source3/libsmb/nmblib.c:917(send_udp) Jul 09 22:33:28 minidsp-shd nmbd[572]: Packet send failed to 169.254.255.255(138) ERRNO=Network is unreachable Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.885213, 0] ../source3/libsmb/nmblib.c:917(send_udp) Jul 09 22:33:28 minidsp-shd nmbd[572]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.885573, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Jul 09 22:33:28 minidsp-shd nmbd[572]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.885796, 0] ../source3/libsmb/nmblib.c:917(send_udp) Jul 09 22:33:28 minidsp-shd nmbd[572]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.886055, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Jul 09 22:33:28 minidsp-shd nmbd[572]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.886313, 0] ../source3/libsmb/nmblib.c:917(send_udp) Jul 09 22:33:28 minidsp-shd nmbd[572]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.886492, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Jul 09 22:33:28 minidsp-shd nmbd[572]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.886695, 0] ../source3/libsmb/nmblib.c:917(send_udp) Jul 09 22:33:28 minidsp-shd nmbd[572]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.886858, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Jul 09 22:33:28 minidsp-shd nmbd[572]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.887156, 0] ../source3/libsmb/nmblib.c:917(send_udp) Jul 09 22:33:28 minidsp-shd nmbd[572]: Packet send failed to 127.0.0.1(137) ERRNO=Network is unreachable Jul 09 22:33:28 minidsp-shd nmbd[572]: [2024/07/09 22:33:28.887342, 0] ../source3/nmbd/nmbd_packets.c:180(send_netbios_packet) Jul 09 22:33:28 minidsp-shd nmbd[572]: send_netbios_packet: send_packet() to IP 127.0.0.1 port 137 failed Jul 09 22:33:28 minidsp-shd volumio[872]: ...++++ Jul 09 22:33:29 minidsp-shd volumio[624]: info: Discovery: A device disappeared from network Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 09 22:33:29 minidsp-shd volumio[624]: info: Not Reporting Auto name since its the default one Jul 09 22:33:29 minidsp-shd volumio[624]: info: RAAT Overriding default device vendor model Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkCurrentAudioDeviceAvailable Jul 09 22:33:29 minidsp-shd volumio[624]: xcb_connection_has_error() returned true Jul 09 22:33:29 minidsp-shd sudo[1163]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart raat-daemon.service Jul 09 22:33:29 minidsp-shd sudo[1163]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 09 22:33:29 minidsp-shd volumio[624]: info: Discovery: adding af39b90a-5d20-40d8-9783-27bb6f8f87f5 Jul 09 22:33:29 minidsp-shd volumio[624]: info: Discovery: Found device miniDSP SHD Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Jul 09 22:33:29 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Jul 09 22:33:29 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:29+08:00" level=debug msg="handling transfer player command from a3d240e3d757dfab3421bdbe6171c6c79b1ee09d" Jul 09 22:33:29 minidsp-shd systemd[1]: Stopping RAAT DAEMON... Jul 09 22:33:29 minidsp-shd systemd[1]: raat-daemon.service: Main process exited, code=killed, status=15/TERM Jul 09 22:33:29 minidsp-shd systemd[1]: raat-daemon.service: Succeeded. Jul 09 22:33:29 minidsp-shd systemd[1]: Stopped RAAT DAEMON. Jul 09 22:33:29 minidsp-shd volumio[624]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 09 22:33:29 minidsp-shd systemd[1]: Started RAAT DAEMON. Jul 09 22:33:29 minidsp-shd volumio[624]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Jul 09 22:33:29 minidsp-shd sudo[1163]: pam_unix(sudo:session): session closed for user root Jul 09 22:33:29 minidsp-shd volumio[624]: info: Raat Daemon started successfully Jul 09 22:33:29 minidsp-shd volumio[624]: info: Executing endpoint restartRAATSocket Jul 09 22:33:29 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: raat , establishDaemonConnection Jul 09 22:33:29 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:29+08:00" level=trace msg="fetched new page 0 with 1045 items (list: 1045)" Jul 09 22:33:29 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:29+08:00" level=debug msg="loading track spotify:track:3255Dmkjsh8Nepdp7RL0Vv (paused: false, position: 5863ms)" Jul 09 22:33:29 minidsp-shd systemd[1]: apt-daily.service: Succeeded. Jul 09 22:33:29 minidsp-shd systemd[1]: Started Daily apt download activities. Jul 09 22:33:29 minidsp-shd systemd[1]: Starting Daily apt upgrade and clean activities... Jul 09 22:33:29 minidsp-shd volumio[624]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Jul 09 22:33:29 minidsp-shd volumio[624]: ------------------------------------ BT MESSAGE: BT STATUS: running Jul 09 22:33:29 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:29+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 09 22:33:29 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:29+08:00" level=trace msg="emitting websocket event: will_play" Jul 09 22:33:29 minidsp-shd volumio[624]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3255Dmkjsh8Nepdp7RL0Vv","play_origin":"collection-songs"}} Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:3255Dmkjsh8Nepdp7RL0Vv" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="requested aes key for file de63d69c4907a44d31684f897699c34fc74bdb4d, gid: 3255Dmkjsh8Nepdp7RL0Vv" Jul 09 22:33:30 minidsp-shd volumio[624]: info: CoreCommandRouter::executeOnPlugin: raat , updateDSP Jul 09 22:33:30 minidsp-shd volumio[624]: info: updateDSP function in raat called! Jul 09 22:33:30 minidsp-shd volumio[624]: info: Updating RAAT Signal Path Jul 09 22:33:30 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Jul 09 22:33:30 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="fetched first chunk of 10, total size is 4793000 bytes" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=trace msg="seek to 5863ms (diff: 111ms, samples: 258558, bytes: 159565)" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="fetched chunk 1/9, size: 524288" Jul 09 22:33:30 minidsp-shd go-librespot[992]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:257:(_snd_pcm_volumioswitch_hw_params) PCM volumioMultiRoomServer has buffer size 65536, but target_pcm volumioOutput has buffer size 4096 Jul 09 22:33:30 minidsp-shd go-librespot[992]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:268:(_snd_pcm_volumioswitch_hw_params) PCM volumioMultiRoomServer has buffer size 65536, but target_pcm volumioOutput has buffer size 4096 Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=info msg="loaded track \"A Foggy Day\" (uri: spotify:track:3255Dmkjsh8Nepdp7RL0Vv, paused: false, position: 5863ms, duration: 164200ms)" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="fetched chunk 3/9, size: 524288" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="fetched chunk 2/9, size: 524288" Jul 09 22:33:30 minidsp-shd go-librespot[992]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:912:(_snd_pcm_volumioswitch_advance) PCM volumioMultiRoomServer cannot write to target PCM volumioOutput as it has failed its update check. Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=trace msg="emitting websocket event: metadata" Jul 09 22:33:30 minidsp-shd volumio[624]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3255Dmkjsh8Nepdp7RL0Vv","name":"A Foggy Day","artist_names":["Cannonball Adderley"],"album_name":"Cannonball Adderley's Finest Hour","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02f00b929b7f78a0ce33157621","position":5863,"duration":164200,"release_date":"year:2001 month:5 day:14","track_number":4,"disc_number":1}} Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=trace msg="emitting websocket event: active" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="sending successful reply for delaer request" Jul 09 22:33:30 minidsp-shd volumio[624]: SPOTIFY: received: {"type":"active","data":null} Jul 09 22:33:30 minidsp-shd volumio[624]: info: Aligning Spotify Volume to Volumio Volume Jul 09 22:33:30 minidsp-shd volumio[624]: info: CoreCommandRouter::volumioGetState Jul 09 22:33:30 minidsp-shd volumio[624]: info: CorePlayQueue::getTrack 0 Jul 09 22:33:30 minidsp-shd go-librespot[992]: ALSA lib /home/pi/volumio-alsa-plugin/src/pcm_volumioswitch.c:912:(_snd_pcm_volumioswitch_advance) PCM volumioMultiRoomServer cannot write to target PCM volumioOutput as it has failed its update check. Jul 09 22:33:30 minidsp-shd volumio[624]: info: Setting Spotify Volume from Volumio: 84 Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=trace msg="emitting websocket event: playing" Jul 09 22:33:30 minidsp-shd volumio[624]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3255Dmkjsh8Nepdp7RL0Vv","play_origin":"collection-songs"}} Jul 09 22:33:30 minidsp-shd volumio[624]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 09 22:33:30 minidsp-shd volumio[624]: TypeError: Cannot read property 'service' of undefined Jul 09 22:33:30 minidsp-shd volumio[624]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Jul 09 22:33:30 minidsp-shd volumio[624]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Jul 09 22:33:30 minidsp-shd volumio[624]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Jul 09 22:33:30 minidsp-shd volumio[624]: at WebSocket.emit (events.js:400:28) Jul 09 22:33:30 minidsp-shd volumio[624]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) Jul 09 22:33:30 minidsp-shd volumio[624]: at Receiver.emit (events.js:400:28) Jul 09 22:33:30 minidsp-shd volumio[624]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 Jul 09 22:33:30 minidsp-shd volumio[624]: at internal/process/task_queues.js:141:7 Jul 09 22:33:30 minidsp-shd volumio[624]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) Jul 09 22:33:30 minidsp-shd volumio[624]: at AsyncResource.runMicrotask (internal/process/task_queues.js:138:8) Jul 09 22:33:30 minidsp-shd volumio[624]: at processTicksAndRejections (internal/process/task_queues.js:95:5) Jul 09 22:33:30 minidsp-shd volumio[624]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 09 22:33:30 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:30+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1637" Jul 09 22:33:31 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:31+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 09 22:33:31 minidsp-shd go-librespot[992]: time="2024-07-09T22:33:31+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1395" Jul 09 22:33:31 minidsp-shd systemd[1]: apt-daily-upgrade.service: Succeeded. Jul 09 22:33:31 minidsp-shd systemd[1]: Started Daily apt upgrade and clean activities. Jul 09 22:33:32 minidsp-shd sudo[1285]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-07-09 22:32 Jul 09 22:33:32 minidsp-shd sudo[1285]: 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:13:25 PM CET" VOLUMIO_VERSION="3.608" VOLUMIO_HARDWARE="nanopineo3" VOLUMIO_DEVICENAME="Nanopi Neo3" VOLUMIO_VENDOR="miniDSP" VOLUMIO_MODEL="SHD" VOLUMIO_VENDOR_MODEL="miniDSP SHD" VOLUMIO_HASH="18533ba33f8f92d7e7e459bb30f70beb"