Jan 27 14:20:05 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:20:11 volumio go-librespot[4304]: time="2026-01-27T14:20:11+09:00" level=debug msg="prefetching next track" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:11 volumio go-librespot[4304]: time="2026-01-27T14:20:11+09:00" level=debug msg="selected format OGG_VORBIS_320 (3aae5d5f58cf91a23d2e91048e737dc02188c299)" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:11 volumio go-librespot[4304]: time="2026-01-27T14:20:11+09:00" level=debug msg="requested aes key for file 3aae5d5f58cf91a23d2e91048e737dc02188c299, gid: 151aH59c2XxRefmARqoje3" Jan 27 14:20:12 volumio go-librespot[4304]: time="2026-01-27T14:20:12+09:00" level=trace msg="found 2 cdn urls" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:12 volumio go-librespot[4304]: time="2026-01-27T14:20:12+09:00" level=debug msg="fetched first chunk of 11, total size is 5268436 bytes" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:12 volumio go-librespot[4304]: time="2026-01-27T14:20:12+09:00" level=info msg="prefetched track \"Stringiti alla mia mano\" (duration: 221988ms)" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:12 volumio go-librespot[4304]: time="2026-01-27T14:20:12+09:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:12 volumio go-librespot[4304]: time="2026-01-27T14:20:12+09:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:13 volumio go-librespot[4304]: time="2026-01-27T14:20:13+09:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:16 volumio go-librespot[4304]: time="2026-01-27T14:20:16+09:00" level=trace msg="sent dealer ping" Jan 27 14:20:16 volumio go-librespot[4304]: time="2026-01-27T14:20:16+09:00" level=trace msg="received dealer pong" Jan 27 14:20:26 volumio volumio[4112]: info: [squeezelite_mc] Server discovered: {"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"} Jan 27 14:20:27 volumio volumio[4112]: info: [squeezelite_mc] Notification listener started Jan 27 14:20:27 volumio volumio[4112]: info: [squeezelite_mc] Getting players connected to daphile (192.168.0.63) Jan 27 14:20:27 volumio volumio[4112]: info: [squeezelite_mc] Players connected to daphile (192.168.0.63): [{"id":"5a:c2:dd:1b:41:14","uuid":null,"ip":"127.0.0.1","name":"HDA Intel PCH","server":{"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"}},{"id":"b8:27:eb:57:9c:3d","uuid":null,"ip":"192.168.0.44","name":"justboomdac","server":{"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"}},{"id":"e4:5f:01:1a:c9:5d","uuid":null,"ip":"192.168.0.58","name":"volumio","server":{"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"}},{"id":"bb:bb:9f:96:f2:12","uuid":null,"ip":"192.168.0.63","name":"JustboomDAC-UPnP/AV","server":{"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"}},{"id":"bb:bb:99:ae:ae:97","uuid":null,"ip":"192.168.0.63","name":"Volumio-UPnP/AV","server":{"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"}}] Jan 27 14:20:27 volumio volumio[4112]: info: [squeezelite_mc] Player found: {"id":"e4:5f:01:1a:c9:5d","uuid":null,"ip":"192.168.0.58","name":"volumio","server":{"ip":"192.168.0.63","name":"daphile","ver":"9.0.3","uuid":"3aa1c5d9-b12b-4cff-9b3b-2fb0d0f2b50f","jsonPort":"9000","cliPort":"9090"}} Jan 27 14:20:28 volumio volumio[4112]: info: CoreCommandRouter::volumioGetState Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=trace msg="emitting websocket event: not_playing" Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:user:khb998:collection","uri":"spotify:track:2AtqkQHVlOBTu9jmBuTtQd","play_origin":"your_library"}} Jan 27 14:20:41 volumio volumio[4112]: error: Failed to decode event: not_playing Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=trace msg="emitting websocket event: will_play" Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=info msg="loaded track \"Stringiti alla mia mano\" (paused: false, position: 0ms, duration: 221988ms, prefetched: true)" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:user:khb998:collection","uri":"spotify:track:151aH59c2XxRefmARqoje3","play_origin":"your_library"}} Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=trace msg="scheduling prefetch in 192s" Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=trace msg="emitting websocket event: metadata" Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:151aH59c2XxRefmARqoje3","name":"Stringiti alla mia mano","artist_names":["Miranda Martino"],"album_name":"Il Meglio di Miranda Martino","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b55e8ae2a9f4024c7a736af4","position":0,"duration":221988,"release_date":"year:2014 month:2 day:24","track_number":3,"disc_number":1}} Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jan 27 14:20:41 volumio go-librespot[4304]: time="2026-01-27T14:20:41+09:00" level=trace msg="emitting websocket event: playing" Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:user:khb998:collection","uri":"spotify:track:151aH59c2XxRefmARqoje3","resume":false,"play_origin":"your_library"}} Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: PUSH STATE SPOTIFY Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: {"status":"play","service":"spop","title":"Stringiti alla mia mano","artist":"Miranda Martino","album":"Il Meglio di Miranda Martino","albumart":"https://i.scdn.co/image/ab67616d00001e02b55e8ae2a9f4024c7a736af4","uri":"spotify:track:151aH59c2XxRefmARqoje3","trackType":"spotify","seek":0,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 27 14:20:41 volumio volumio[4112]: info: CoreCommandRouter::servicePushState Jan 27 14:20:41 volumio volumio[4112]: info: CoreStateMachine::pushState Jan 27 14:20:41 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 14:20:41 volumio volumio[4112]: info: CoreCommandRouter::volumioPushState Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: PUSH STATE SPOTIFY Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: {"status":"play","service":"spop","title":"Stringiti alla mia mano","artist":"Miranda Martino","album":"Il Meglio di Miranda Martino","albumart":"https://i.scdn.co/image/ab67616d00001e02b55e8ae2a9f4024c7a736af4","uri":"spotify:track:151aH59c2XxRefmARqoje3","trackType":"spotify","seek":0,"duration":221,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jan 27 14:20:41 volumio volumio[4112]: info: CoreCommandRouter::servicePushState Jan 27 14:20:41 volumio volumio[4112]: info: CoreStateMachine::pushState Jan 27 14:20:41 volumio volumio[4112]: info: CoreCommandRouter::volumioPushState Jan 27 14:20:41 volumio volumio[4112]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 14:20:42 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:20:45 volumio go-librespot[4304]: time="2026-01-27T14:20:45+09:00" level=trace msg="received accesspoint ping" Jan 27 14:20:45 volumio go-librespot[4304]: time="2026-01-27T14:20:45+09:00" level=trace msg="received accesspoint pong ack" Jan 27 14:20:46 volumio go-librespot[4304]: time="2026-01-27T14:20:46+09:00" level=trace msg="sent dealer ping" Jan 27 14:20:46 volumio go-librespot[4304]: time="2026-01-27T14:20:46+09:00" level=trace msg="received dealer pong" Jan 27 14:21:03 volumio go-librespot[4304]: time="2026-01-27T14:21:03+09:00" level=debug msg="fetched chunk 4/10, size: 524288" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:21:16 volumio go-librespot[4304]: time="2026-01-27T14:21:16+09:00" level=trace msg="sent dealer ping" Jan 27 14:21:16 volumio go-librespot[4304]: time="2026-01-27T14:21:16+09:00" level=trace msg="received dealer pong" Jan 27 14:21:20 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:20 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:24 volumio go-librespot[4304]: time="2026-01-27T14:21:24+09:00" level=debug msg="fetched chunk 5/10, size: 524288" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:21:24 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:28 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:32 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:36 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: networkfs , addShare Jan 27 14:21:36 volumio volumio[4112]: info: Adding a new share Jan 27 14:21:36 volumio volumio[4112]: info: No correspondence found in configuration for share music on IP 192.168.0.63 Jan 27 14:21:36 volumio volumio[4112]: info: Executing SMB command: smbclient --debuglevel=4 -L 192.168.0.63 -N -m SMB3_11 Jan 27 14:21:36 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:37 volumio volumio[4112]: info: Negotiated SMB version with music: SMB3_11 Jan 27 14:21:37 volumio volumio[4112]: info: Detected device music with version SMB3_11 Jan 27 14:21:37 volumio volumio[4112]: info: Guest mount: forcing fallback SMB version 2.1 for music Jan 27 14:21:37 volumio volumio[4112]: info: Set SMB version 3.11 in CIFS options: vers=2.1 Jan 27 14:21:37 volumio sudo[9652]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o guest,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft,vers=2.1 //192.168.0.63/book/music/ /mnt/NAS/music Jan 27 14:21:37 volumio sudo[9652]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Jan 27 14:21:37 volumio kernel: CIFS: Attempting to mount //192.168.0.63/book/music Jan 27 14:21:37 volumio sudo[9652]: pam_unix(sudo:session): session closed for user root Jan 27 14:21:37 volumio volumio[4112]: verbose: ControllerMpd::sendMpdCommand status Jan 27 14:21:37 volumio volumio[4112]: info: Jan 27 14:21:37 volumio volumio[4112]: ---------------------------- MPD announces state update: update Jan 27 14:21:37 volumio volumio[4112]: info: ControllerMpd::getState Jan 27 14:21:37 volumio volumio[4112]: verbose: ControllerMpd::sendMpdCommand status Jan 27 14:21:37 volumio volumio[4112]: info: sendMpdCommand status took 4 milliseconds Jan 27 14:21:37 volumio volumio[4112]: info: sendMpdCommand status took 2 milliseconds Jan 27 14:21:37 volumio volumio[4112]: verbose: ControllerMpd::parseState Jan 27 14:21:37 volumio volumio[4112]: info: Command Router : Notfying DB Updatetrue Jan 27 14:21:37 volumio volumio[4112]: verbose: ControllerMpd::parseState Jan 27 14:21:37 volumio volumio[4112]: info: ControllerMpd::pushState Jan 27 14:21:37 volumio volumio[4112]: info: CoreCommandRouter::servicePushState Jan 27 14:21:37 volumio volumio[4112]: info: CoreStateMachine::pushState Jan 27 14:21:37 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jan 27 14:21:37 volumio volumio[4112]: info: CoreCommandRouter::volumioPushState Jan 27 14:21:37 volumio volumio[4112]: info: CorePlayQueue::getTrack 0 Jan 27 14:21:37 volumio volumio[4112]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Jan 27 14:21:37 volumio volumio[4112]: verbose: CURRENT POSITION 0 Jan 27 14:21:37 volumio volumio[4112]: info: CoreStateMachine::syncState stateService stop Jan 27 14:21:37 volumio volumio[4112]: info: CoreStateMachine::syncState currentStatus play Jan 27 14:21:37 volumio volumio[4112]: info: CoreCommandRouter::volumioPushState Jan 27 14:21:37 volumio volumio[4112]: info: CoreStateMachine::stPlaybackTimer Jan 27 14:21:37 volumio volumio[4112]: info: ------------------------------ 61ms Jan 27 14:21:37 volumio volumio[4112]: info: [1769491297733] Database update started Jan 27 14:21:37 volumio volumio[4112]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 14:21:37 volumio volumio[4112]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jan 27 14:21:38 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Jan 27 14:21:40 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:42 volumio volumio[4112]: info: CoreCommandRouter::Close All Modals sent Jan 27 14:21:44 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Jan 27 14:21:46 volumio go-librespot[4304]: time="2026-01-27T14:21:46+09:00" level=trace msg="sent dealer ping" Jan 27 14:21:46 volumio go-librespot[4304]: time="2026-01-27T14:21:46+09:00" level=trace msg="received dealer pong" Jan 27 14:21:46 volumio go-librespot[4304]: time="2026-01-27T14:21:46+09:00" level=debug msg="fetched chunk 6/10, size: 524288" uri="spotify:track:151aH59c2XxRefmARqoje3" Jan 27 14:21:47 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: networkfs , discoverShares Jan 27 14:21:47 volumio volumio[4112]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , browseForService Jan 27 14:21:47 volumio volumio[4112]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 14:21:47 volumio volumio[4112]: Error: getaddrinfo -3007 Jan 27 14:21:47 volumio volumio[4112]: at errnoException (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:199:11) Jan 27 14:21:47 volumio volumio[4112]: at getaddrinfo_complete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:112:10) Jan 27 14:21:47 volumio volumio[4112]: at GetAddrInfoReqWrap.oncomplete (/volumio/node_modules/mdns/lib/resolver_sequence_tasks.js:120:9) { Jan 27 14:21:47 volumio volumio[4112]: code: -3007, Jan 27 14:21:47 volumio volumio[4112]: errno: -3007, Jan 27 14:21:47 volumio volumio[4112]: syscall: 'getaddrinfo' Jan 27 14:21:47 volumio volumio[4112]: } Jan 27 14:21:47 volumio volumio[4112]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jan 27 14:21:48 volumio sudo[9711]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-01-27 14:20' Jan 27 14:21:48 volumio sudo[9711]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:13:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="792f09af7488531aecd1aadcaa9b175e"