-- 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"