-- Logs begin at Wed 2025-02-26 11:53:23 PST, end at Wed 2025-02-26 11:56:58 PST. -- Feb 26 11:55:03 volumio sudo[2054]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=neil,password=1,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.46.123/music /mnt/NAS/minty Feb 26 11:55:03 volumio sudo[2054]: pam_unix(sudo:session): session opened for user root by (uid=0) Feb 26 11:55:03 volumio kernel: CIFS: Attempting to mount //192.168.46.123/music Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 26 11:55:04 volumio volumio[1028]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Feb 26 11:55:04 volumio volumio[1028]: info: Received Get System Version Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 26 11:55:04 volumio volumio[1028]: info: Received Get System Info Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 26 11:55:04 volumio volumio[1028]: info: Discovery: Getting this device information Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::volumioGetState Feb 26 11:55:04 volumio volumio[1028]: info: CorePlayQueue::getTrack 0 Feb 26 11:55:04 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 26 11:55:05 volumio volumio[1028]: info: BOOT COMPLETED Feb 26 11:55:09 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation. Feb 26 11:55:09 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113 Feb 26 11:55:09 volumio sudo[2054]: pam_unix(sudo:session): session closed for user root Feb 26 11:55:09 volumio volumio[1028]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Feb 26 11:55:16 volumio go-librespot[1570]: time="2025-02-26T11:55:16+08:00" level=debug msg="handling transfer player command from 0c7b3d56ebcce08d8980eaa387db39a397e9188c" Feb 26 11:55:16 volumio go-librespot[1570]: time="2025-02-26T11:55:16+08:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DX0jgyAiPl8Af" Feb 26 11:55:16 volumio go-librespot[1570]: time="2025-02-26T11:55:16+08:00" level=trace msg="fetched new page 0 with 209 items (list: 209)" uri="spotify:playlist:37i9dQZF1DX0jgyAiPl8Af" Feb 26 11:55:16 volumio go-librespot[1570]: time="2025-02-26T11:55:16+08:00" level=debug msg="loading track (paused: false, position: 69706ms)" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:17 volumio go-librespot[1570]: time="2025-02-26T11:55:17+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:55:17 volumio go-librespot[1570]: time="2025-02-26T11:55:17+08:00" level=trace msg="emitting websocket event: will_play" Feb 26 11:55:17 volumio volumio[1028]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","play_origin":"playlist"}} Feb 26 11:55:17 volumio go-librespot[1570]: time="2025-02-26T11:55:17+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 242" Feb 26 11:55:17 volumio go-librespot[1570]: time="2025-02-26T11:55:17+08:00" level=debug msg="selected format OGG_VORBIS_320 (4e27d21511dc75137a3c13d5c4be167dbbcf38e0)" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:17 volumio go-librespot[1570]: time="2025-02-26T11:55:17+08:00" level=debug msg="requested aes key for file 4e27d21511dc75137a3c13d5c4be167dbbcf38e0, gid: 4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:18 volumio go-librespot[1570]: time="2025-02-26T11:55:18+08:00" level=debug msg="fetched first chunk of 7, total size is 3526056 bytes" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:18 volumio go-librespot[1570]: time="2025-02-26T11:55:18+08:00" level=debug msg="fetched chunk 3/6, size: 524288" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:18 volumio go-librespot[1570]: time="2025-02-26T11:55:18+08:00" level=trace msg="seek to 69706ms (diff: 243ms, samples: 3074034, bytes: 2069869)" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:18 volumio go-librespot[1570]: time="2025-02-26T11:55:18+08:00" level=debug msg="created new output device" Feb 26 11:55:18 volumio go-librespot[1570]: time="2025-02-26T11:55:18+08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Feb 26 11:55:18 volumio go-librespot[1570]: time="2025-02-26T11:55:18+08:00" level=info msg="loaded track \"Song for M\" (paused: false, position: 69706ms, duration: 119000ms, prefetched: false)" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="fetched chunk 6/6, size: 380328" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="fetched chunk 4/6, size: 524288" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="fetched chunk 2/6, size: 524288" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=trace msg="scheduling prefetch in 19s" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=trace msg="emitting websocket event: metadata" Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","name":"Song for M","artist_names":["Leo Ek"],"album_name":"Song for M","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021b500dcd8a27cd9b893065d2","position":69706,"duration":119000,"release_date":"year:2024 month:11 day:1","track_number":1,"disc_number":1}} Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=trace msg="emitting websocket event: active" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="sending successful reply for dealer request" Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: received: {"type":"active","data":null} Feb 26 11:55:19 volumio volumio[1028]: info: Aligning Spotify Volume to Volumio Volume Feb 26 11:55:19 volumio volumio[1028]: info: CoreCommandRouter::volumioGetState Feb 26 11:55:19 volumio volumio[1028]: info: CorePlayQueue::getTrack 0 Feb 26 11:55:19 volumio volumio[1028]: info: Setting Spotify Volume from Volumio: 100 Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="fetched chunk 5/6, size: 524288" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="fetched chunk 1/6, size: 524288" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:55:19 volumio go-librespot[1570]: time="2025-02-26T11:55:19+08:00" level=trace msg="emitting websocket event: playing" Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","play_origin":"playlist"}} Feb 26 11:55:19 volumio volumio[1028]: info: Spotify is playing in volatile mode Feb 26 11:55:19 volumio volumio[1028]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: UNSET VOLATILE Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: {"status":"stop","position":0,"title":"What A Wonderful World","artist":"Eva Cassidy","album":"Nightbird","albumart":"https://i.scdn.co/image/ab67616d0000b273979c1e27d0446d04e336ff28","uri":"spotify:track:2e1v97SlDpniLZZPvrUo45","trackType":"spotify","codec":"ogg","seek":0,"duration":328,"samplerate":"320 kbps","bitdepth":"16 bit","random":null,"repeat":true,"repeatSingle":false,"consume":false,"volume":100,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","updatedb":false,"volatile":false,"service":"spop"} Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: {"status":"play","service":"spop","title":"Song for M","artist":"Leo Ek","album":"Song for M","albumart":"https://i.scdn.co/image/ab67616d00001e021b500dcd8a27cd9b893065d2","uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","trackType":"spotify","seek":69706,"duration":119,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 26 11:55:19 volumio volumio[1028]: info: CoreCommandRouter::servicePushState Feb 26 11:55:19 volumio volumio[1028]: info: CoreStateMachine::pushState Feb 26 11:55:19 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 11:55:19 volumio volumio[1028]: info: CoreCommandRouter::volumioPushState Feb 26 11:55:19 volumio volumio[1028]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 11:55:20 volumio volumio[1028]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 11:55:20 volumio volumio[1028]: SPOTIFY: {"status":"play","service":"spop","title":"Song for M","artist":"Leo Ek","album":"Song for M","albumart":"https://i.scdn.co/image/ab67616d00001e021b500dcd8a27cd9b893065d2","uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","trackType":"spotify","seek":69706,"duration":119,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 26 11:55:20 volumio volumio[1028]: info: CoreCommandRouter::servicePushState Feb 26 11:55:20 volumio volumio[1028]: info: CoreStateMachine::pushState Feb 26 11:55:20 volumio volumio[1028]: info: CoreCommandRouter::volumioPushState Feb 26 11:55:20 volumio go-librespot[1570]: time="2025-02-26T11:55:20+08:00" level=trace msg="sent dealer ping" Feb 26 11:55:20 volumio volumio[1028]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 11:55:20 volumio go-librespot[1570]: time="2025-02-26T11:55:20+08:00" level=trace msg="received dealer pong" Feb 26 11:55:21 volumio volumio[1028]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Feb 26 11:55:21 volumio volumio[1028]: info: Sending Spotify command with payload to local API: /player/volume Feb 26 11:55:21 volumio go-librespot[1570]: time="2025-02-26T11:55:21+08:00" level=debug msg="update volume to 65535/65535" Feb 26 11:55:22 volumio go-librespot[1570]: time="2025-02-26T11:55:22+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 26 11:55:22 volumio go-librespot[1570]: time="2025-02-26T11:55:22+08:00" level=trace msg="emitting websocket event: volume" Feb 26 11:55:22 volumio volumio[1028]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 26 11:55:22 volumio volumio[1028]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 26 11:55:38 volumio go-librespot[1570]: time="2025-02-26T11:55:38+08:00" level=debug msg="prefetching next track" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:38 volumio go-librespot[1570]: time="2025-02-26T11:55:38+08:00" level=debug msg="selected format OGG_VORBIS_320 (e225cd8282c16dd00209dc5bef1e0971c50c6842)" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:38 volumio go-librespot[1570]: time="2025-02-26T11:55:38+08:00" level=debug msg="requested aes key for file e225cd8282c16dd00209dc5bef1e0971c50c6842, gid: 3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:40 volumio go-librespot[1570]: time="2025-02-26T11:55:40+08:00" level=debug msg="fetched first chunk of 12, total size is 5812426 bytes" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:40 volumio go-librespot[1570]: time="2025-02-26T11:55:40+08:00" level=info msg="prefetched track \"Bonanza\" (duration: 168263ms)" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:40 volumio go-librespot[1570]: time="2025-02-26T11:55:40+08:00" level=debug msg="fetched chunk 1/11, size: 524288" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:40 volumio go-librespot[1570]: time="2025-02-26T11:55:40+08:00" level=debug msg="fetched chunk 3/11, size: 524288" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:40 volumio go-librespot[1570]: time="2025-02-26T11:55:40+08:00" level=debug msg="fetched chunk 2/11, size: 524288" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:55:41 volumio volumio[1028]: info: CoreCommandRouter::volumioSeek Feb 26 11:55:41 volumio volumio[1028]: info: CoreStateMachine::seek Feb 26 11:55:41 volumio volumio[1028]: info: Spotify seek to: 79000 Feb 26 11:55:41 volumio volumio[1028]: info: Sending Spotify command with payload to local API: /player/seek Feb 26 11:55:41 volumio volumio[1028]: info: CoreStateMachine::startPlaybackTimer Feb 26 11:55:41 volumio volumio[1028]: info: CorePlayQueue::getTrack 0 Feb 26 11:55:41 volumio volumio[1028]: info: CoreStateMachine::pushState Feb 26 11:55:41 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 11:55:41 volumio volumio[1028]: info: CoreCommandRouter::volumioPushState Feb 26 11:55:41 volumio volumio[1028]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 11:55:41 volumio go-librespot[1570]: time="2025-02-26T11:55:41+08:00" level=debug msg="seek track to 79000ms" Feb 26 11:55:41 volumio go-librespot[1570]: time="2025-02-26T11:55:41+08:00" level=trace msg="seek to 79000ms (diff: 72ms, samples: 3483900, bytes: 2346132)" uri="spotify:track:4rJHvUKN1s4Pqg3LuBdodv" Feb 26 11:55:42 volumio go-librespot[1570]: time="2025-02-26T11:55:42+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:55:42 volumio go-librespot[1570]: time="2025-02-26T11:55:42+08:00" level=trace msg="emitting websocket event: seek" Feb 26 11:55:42 volumio volumio[1028]: SPOTIFY: received: {"type":"seek","data":{"uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","position":79000,"duration":119000,"play_origin":"playlist"}} Feb 26 11:55:42 volumio volumio[1028]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 11:55:42 volumio volumio[1028]: SPOTIFY: {"status":"play","service":"spop","title":"Song for M","artist":"Leo Ek","album":"Song for M","albumart":"https://i.scdn.co/image/ab67616d00001e021b500dcd8a27cd9b893065d2","uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","trackType":"spotify","seek":79000,"duration":119,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 26 11:55:42 volumio volumio[1028]: info: CoreCommandRouter::servicePushState Feb 26 11:55:42 volumio volumio[1028]: info: CoreStateMachine::pushState Feb 26 11:55:42 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 11:55:42 volumio volumio[1028]: info: CoreCommandRouter::volumioPushState Feb 26 11:55:42 volumio volumio[1028]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 11:55:50 volumio go-librespot[1570]: time="2025-02-26T11:55:50+08:00" level=trace msg="sent dealer ping" Feb 26 11:55:50 volumio go-librespot[1570]: time="2025-02-26T11:55:50+08:00" level=trace msg="received dealer pong" Feb 26 11:55:55 volumio ntpd[1024]: Soliciting pool server 2405:a640::149 Feb 26 11:55:58 volumio ntpd[1024]: Soliciting pool server 222.127.1.26 Feb 26 11:55:58 volumio ntpd[1024]: Soliciting pool server 222.127.1.26 Feb 26 11:55:58 volumio ntpd[1024]: Soliciting pool server 222.127.1.27 Feb 26 11:56:13 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Feb 26 11:56:13 volumio volumio[1028]: info: CURURI: music-library Feb 26 11:56:13 volumio volumio[1028]: error: Failed LSINFO: Error: [50@0] {lsinfo} No database Feb 26 11:56:13 volumio mpd[1523]: exception: No database Feb 26 11:56:13 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:18 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 26 11:56:18 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:19 volumio go-librespot[1570]: time="2025-02-26T11:56:19+08:00" level=trace msg="received accesspoint ping" Feb 26 11:56:20 volumio go-librespot[1570]: time="2025-02-26T11:56:20+08:00" level=trace msg="received accesspoint pong ack" Feb 26 11:56:20 volumio go-librespot[1570]: time="2025-02-26T11:56:20+08:00" level=trace msg="sent dealer ping" Feb 26 11:56:20 volumio go-librespot[1570]: time="2025-02-26T11:56:20+08:00" level=trace msg="received dealer pong" Feb 26 11:56:20 volumio go-librespot[1570]: time="2025-02-26T11:56:20+08:00" level=trace msg="emitting websocket event: not_playing" Feb 26 11:56:20 volumio volumio[1028]: SPOTIFY: received: {"type":"not_playing","data":{"uri":"spotify:track:4rJHvUKN1s4Pqg3LuBdodv","play_origin":"playlist"}} Feb 26 11:56:20 volumio volumio[1028]: error: Failed to decode event: not_playing Feb 26 11:56:20 volumio go-librespot[1570]: time="2025-02-26T11:56:20+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:56:20 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=trace msg="emitting websocket event: will_play" Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=info msg="loaded track \"Bonanza\" (paused: false, position: 0ms, duration: 168263ms, prefetched: true)" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:56:21 volumio volumio[1028]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:3edohA9RKNNDPyKyAmc8tH","play_origin":"playlist"}} Feb 26 11:56:21 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=trace msg="scheduling prefetch in 138s" Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=trace msg="emitting websocket event: metadata" Feb 26 11:56:21 volumio volumio[1028]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:3edohA9RKNNDPyKyAmc8tH","name":"Bonanza","artist_names":["Armand Beck"],"album_name":"Bonanza","album_cover_url":"https://i.scdn.co/image/ab67616d00001e023599f8dd6ea7babad0c38f5f","position":0,"duration":168263,"release_date":"year:2024 month:8 day:4","track_number":1,"disc_number":1}} Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 11:56:21 volumio go-librespot[1570]: time="2025-02-26T11:56:21+08:00" level=trace msg="emitting websocket event: playing" Feb 26 11:56:21 volumio volumio[1028]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:3edohA9RKNNDPyKyAmc8tH","play_origin":"playlist"}} Feb 26 11:56:21 volumio volumio[1028]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 11:56:21 volumio volumio[1028]: SPOTIFY: {"status":"play","service":"spop","title":"Bonanza","artist":"Armand Beck","album":"Bonanza","albumart":"https://i.scdn.co/image/ab67616d00001e023599f8dd6ea7babad0c38f5f","uri":"spotify:track:3edohA9RKNNDPyKyAmc8tH","trackType":"spotify","seek":0,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 26 11:56:21 volumio volumio[1028]: info: CoreCommandRouter::servicePushState Feb 26 11:56:21 volumio volumio[1028]: info: CoreStateMachine::pushState Feb 26 11:56:21 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 11:56:21 volumio volumio[1028]: info: CoreCommandRouter::volumioPushState Feb 26 11:56:22 volumio volumio[1028]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 11:56:22 volumio volumio[1028]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 11:56:22 volumio volumio[1028]: SPOTIFY: {"status":"play","service":"spop","title":"Bonanza","artist":"Armand Beck","album":"Bonanza","albumart":"https://i.scdn.co/image/ab67616d00001e023599f8dd6ea7babad0c38f5f","uri":"spotify:track:3edohA9RKNNDPyKyAmc8tH","trackType":"spotify","seek":1000,"duration":168,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Feb 26 11:56:22 volumio volumio[1028]: info: CoreCommandRouter::servicePushState Feb 26 11:56:22 volumio volumio[1028]: info: CoreStateMachine::pushState Feb 26 11:56:22 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 11:56:22 volumio volumio[1028]: info: CoreCommandRouter::volumioPushState Feb 26 11:56:22 volumio volumio[1028]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 11:56:32 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Feb 26 11:56:32 volumio volumio[1028]: info: CURURI: music-library Feb 26 11:56:32 volumio mpd[1523]: exception: No database Feb 26 11:56:32 volumio volumio[1028]: error: Failed LSINFO: Error: [50@0] {lsinfo} No database Feb 26 11:56:32 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:36 volumio go-librespot[1570]: time="2025-02-26T11:56:36+08:00" level=debug msg="fetched chunk 4/11, size: 524288" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:56:47 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 26 11:56:47 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:50 volumio go-librespot[1570]: time="2025-02-26T11:56:50+08:00" level=trace msg="sent dealer ping" Feb 26 11:56:50 volumio go-librespot[1570]: time="2025-02-26T11:56:50+08:00" level=trace msg="received dealer pong" Feb 26 11:56:50 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 26 11:56:50 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:51 volumio go-librespot[1570]: time="2025-02-26T11:56:51+08:00" level=debug msg="fetched chunk 5/11, size: 524288" uri="spotify:track:3edohA9RKNNDPyKyAmc8tH" Feb 26 11:56:55 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 26 11:56:55 volumio volumio[1028]: info: Preload queue cleared Feb 26 11:56:58 volumio volumio[1028]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Feb 26 11:56:58 volumio volumio[1028]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 11:56:58 volumio volumio[1028]: TypeError: Cannot read property 'length' of undefined Feb 26 11:56:58 volumio volumio[1028]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Feb 26 11:56:58 volumio volumio[1028]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Feb 26 11:56:58 volumio volumio[1028]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Feb 26 11:56:58 volumio volumio[1028]: at Parser.emit (events.js:400:28) Feb 26 11:56:58 volumio volumio[1028]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Feb 26 11:56:58 volumio volumio[1028]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Feb 26 11:56:58 volumio volumio[1028]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Feb 26 11:56:58 volumio volumio[1028]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Feb 26 11:56:58 volumio volumio[1028]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Feb 26 11:56:58 volumio volumio[1028]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Feb 26 11:56:58 volumio volumio[1028]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Feb 26 11:56:58 volumio volumio[1028]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Feb 26 11:56:58 volumio volumio[1028]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Feb 26 11:56:58 volumio volumio[1028]: at IncomingMessage.emit (events.js:412:35) Feb 26 11:56:58 volumio volumio[1028]: at endReadableNT (internal/streams/readable.js:1333:12) Feb 26 11:56:58 volumio volumio[1028]: at processTicksAndRejections (internal/process/task_queues.js:82:21) Feb 26 11:56:58 volumio volumio[1028]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 11:56:58 volumio sudo[2350]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-26 11:55 Feb 26 11:56:58 volumio sudo[2350]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 07:25:16 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="66c567362bdbb3dc1644a18f7879afe7"