-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Wed 2025-02-26 15:27:45 CET. -- Feb 26 15:26:02 volumio volumio[838]: info: CoreCommandRouter::volumioPlay Feb 26 15:26:02 volumio volumio[838]: info: CoreStateMachine::play index undefined Feb 26 15:26:02 volumio volumio[838]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 26 15:26:02 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:02 volumio volumio[838]: info: CoreStateMachine::startPlaybackTimer Feb 26 15:26:02 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:02 volumio volumio[838]: info: [1740579962730] ControllerSpotify::clearAddPlayTrack Feb 26 15:26:02 volumio volumio[838]: info: Sending Spotify command with payload to local API: /player/play Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=debug msg="resolved context of track" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=trace msg="emitting websocket event: will_play" Feb 26 15:26:02 volumio volumio[838]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","play_origin":"go-librespot"}} Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=debug msg="selected format OGG_VORBIS_320 (e25d708ba31d98cd5b1bd76b632c4e79fd0171ce)" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:02 volumio go-librespot[1199]: time="2025-02-26T15:26:02+01:00" level=debug msg="requested aes key for file e25d708ba31d98cd5b1bd76b632c4e79fd0171ce, gid: 4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="fetched first chunk of 43, total size is 22370448 bytes" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="created new output device" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=info msg="loaded track \"Milestones\" (paused: false, position: 0ms, duration: 506453ms, prefetched: false)" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="fetched chunk 3/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=trace msg="scheduling prefetch in 476s" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=trace msg="emitting websocket event: metadata" Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","name":"Milestones","artist_names":["Shook"],"album_name":"Spectrum","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029916251dfb1ef7ab1b4b1fda","position":0,"duration":506453,"release_date":"year:2014 month:11 day:19","track_number":10,"disc_number":1}} Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="fetched chunk 1/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="fetched chunk 2/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 26 15:26:03 volumio go-librespot[1199]: time="2025-02-26T15:26:03+01:00" level=trace msg="emitting websocket event: playing" Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","play_origin":"go-librespot"}} Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: {"status":"play","service":"spop","title":"Milestones","artist":"Shook","album":"Spectrum","albumart":"https://i.scdn.co/image/ab67616d00001e029916251dfb1ef7ab1b4b1fda","uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","trackType":"spotify","seek":0,"duration":506,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 26 15:26:03 volumio volumio[838]: info: CoreCommandRouter::servicePushState Feb 26 15:26:03 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:03 volumio volumio[838]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Milestones","artist":"Shook","album":"Spectrum","albumart":"https://i.scdn.co/image/ab67616d00001e029916251dfb1ef7ab1b4b1fda","uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","trackType":"spotify","seek":0,"duration":506,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 26 15:26:03 volumio volumio[838]: verbose: CURRENT POSITION 69 Feb 26 15:26:03 volumio volumio[838]: info: CoreStateMachine::syncState stateService play Feb 26 15:26:03 volumio volumio[838]: info: CoreStateMachine::syncState currentStatus stop Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: PUSH STATE SPOTIFY Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: {"status":"play","service":"spop","title":"Milestones","artist":"Shook","album":"Spectrum","albumart":"https://i.scdn.co/image/ab67616d00001e029916251dfb1ef7ab1b4b1fda","uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","trackType":"spotify","seek":0,"duration":506,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 26 15:26:03 volumio volumio[838]: info: CoreCommandRouter::servicePushState Feb 26 15:26:03 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:03 volumio volumio[838]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Milestones","artist":"Shook","album":"Spectrum","albumart":"https://i.scdn.co/image/ab67616d00001e029916251dfb1ef7ab1b4b1fda","uri":"spotify:track:4H3ZV1gtveBXnzEEtEmf4e","trackType":"spotify","seek":0,"duration":506,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Feb 26 15:26:03 volumio volumio[838]: verbose: CURRENT POSITION 69 Feb 26 15:26:03 volumio volumio[838]: info: CoreStateMachine::syncState stateService play Feb 26 15:26:03 volumio volumio[838]: info: CoreStateMachine::syncState currentStatus play Feb 26 15:26:03 volumio volumio[838]: info: Received an update from plugin. extracting info from payload Feb 26 15:26:03 volumio volumio[838]: info: CoreStateMachine::pushState Feb 26 15:26:03 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:03 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 15:26:03 volumio volumio[838]: info: CoreCommandRouter::volumioPushState Feb 26 15:26:03 volumio volumio[838]: info: CoreStateMachine::pushState Feb 26 15:26:03 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:03 volumio volumio[838]: info: CoreCommandRouter::volumioPushState Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 15:26:03 volumio volumio[838]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 15:26:11 volumio volumio[838]: info: VolumeController::SetAlsaVolume63 Feb 26 15:26:11 volumio volumio[838]: info: CoreStateMachine::pushState Feb 26 15:26:11 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:11 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 15:26:11 volumio volumio[838]: info: CoreCommandRouter::volumioPushState Feb 26 15:26:11 volumio volumio[838]: SPOTIFY: RECEIVED VOLUMIO VOLUME 63 Feb 26 15:26:11 volumio volumio[838]: SPOTIFY: SPOTIFY VOLUME 100 Feb 26 15:26:11 volumio volumio[838]: SPOTIFY: VOLUMIO VOLUME 63 Feb 26 15:26:11 volumio volumio[838]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 26 15:26:11 volumio volumio[838]: info: Setting Spotify Volume from Volumio: 63 Feb 26 15:26:13 volumio volumio[838]: info: VolumeController::SetAlsaVolume100 Feb 26 15:26:13 volumio volumio[838]: info: CoreStateMachine::pushState Feb 26 15:26:13 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:26:13 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 26 15:26:13 volumio volumio[838]: info: CoreCommandRouter::volumioPushState Feb 26 15:26:13 volumio volumio[838]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Feb 26 15:26:13 volumio volumio[838]: SPOTIFY: SPOTIFY VOLUME 63 Feb 26 15:26:13 volumio volumio[838]: SPOTIFY: VOLUMIO VOLUME 100 Feb 26 15:26:13 volumio volumio[838]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 26 15:26:13 volumio volumio[838]: info: Setting Spotify Volume from Volumio: 100 Feb 26 15:26:14 volumio volumio[838]: SPOTIFY: SETTING SPOTIFY VOLUME 100 Feb 26 15:26:14 volumio volumio[838]: info: Sending Spotify command with payload to local API: /player/volume Feb 26 15:26:14 volumio go-librespot[1199]: time="2025-02-26T15:26:14+01:00" level=debug msg="update volume to 65535/65535" Feb 26 15:26:15 volumio go-librespot[1199]: time="2025-02-26T15:26:15+01:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 26 15:26:15 volumio go-librespot[1199]: time="2025-02-26T15:26:15+01:00" level=trace msg="emitting websocket event: volume" Feb 26 15:26:15 volumio volumio[838]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Feb 26 15:26:15 volumio volumio[838]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Feb 26 15:26:16 volumio go-librespot[1199]: time="2025-02-26T15:26:16+01:00" level=debug msg="fetched chunk 4/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:20 volumio go-librespot[1199]: time="2025-02-26T15:26:20+01:00" level=trace msg="sent dealer ping" Feb 26 15:26:20 volumio go-librespot[1199]: time="2025-02-26T15:26:20+01:00" level=trace msg="received dealer pong" Feb 26 15:26:29 volumio go-librespot[1199]: time="2025-02-26T15:26:29+01:00" level=debug msg="fetched chunk 5/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:29 volumio volumio[838]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 26 15:26:29 volumio volumio[838]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 26 15:26:29 volumio volumio[838]: info: Retrieving Cloud Streaming UI Feb 26 15:26:29 volumio volumio[838]: info: Getting Tidal Cloud Configuration Feb 26 15:26:29 volumio volumio[838]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 26 15:26:29 volumio volumio[838]: info: Getting Qobuz Cloud Configuration Feb 26 15:26:29 volumio volumio[838]: info: Asking plugin for UI Config Feb 26 15:26:29 volumio volumio[838]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 26 15:26:29 volumio volumio[838]: info: Getting Spotify Cloud Configuration Feb 26 15:26:29 volumio volumio[838]: info: Asking plugin for UI Config Feb 26 15:26:29 volumio volumio[838]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 26 15:26:29 volumio volumio[838]: info: Saving Spotify Acccount Feb 26 15:26:29 volumio volumio[838]: info: Got Tidal Cloud Configuration Feb 26 15:26:29 volumio volumio[838]: info: Got it Feb 26 15:26:29 volumio volumio[838]: info: Got it Feb 26 15:26:29 volumio volumio[838]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Feb 26 15:26:29 volumio volumio[838]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 26 15:26:29 volumio volumio[838]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::volumioGetBrowseSources Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::volumioGetBrowseSources Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::volumioGetBrowseSources Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 26 15:26:30 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Feb 26 15:26:34 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 26 15:26:36 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: networkfs , deleteShare Feb 26 15:26:37 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Feb 26 15:26:38 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 26 15:26:41 volumio go-librespot[1199]: time="2025-02-26T15:26:41+01:00" level=debug msg="fetched chunk 6/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:42 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 26 15:26:46 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 26 15:26:50 volumio volumio[838]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Feb 26 15:26:50 volumio go-librespot[1199]: time="2025-02-26T15:26:50+01:00" level=trace msg="sent dealer ping" Feb 26 15:26:50 volumio go-librespot[1199]: time="2025-02-26T15:26:50+01:00" level=trace msg="received dealer pong" Feb 26 15:26:52 volumio go-librespot[1199]: time="2025-02-26T15:26:52+01:00" level=debug msg="fetched chunk 7/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:26:52 volumio volumio[838]: info: CoreCommandRouter::volumioGetState Feb 26 15:26:52 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:27:04 volumio go-librespot[1199]: time="2025-02-26T15:27:04+01:00" level=debug msg="fetched chunk 8/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:27:15 volumio go-librespot[1199]: time="2025-02-26T15:27:15+01:00" level=debug msg="fetched chunk 9/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:27:20 volumio go-librespot[1199]: time="2025-02-26T15:27:20+01:00" level=trace msg="received accesspoint ping" Feb 26 15:27:20 volumio go-librespot[1199]: time="2025-02-26T15:27:20+01:00" level=trace msg="received accesspoint pong ack" Feb 26 15:27:20 volumio go-librespot[1199]: time="2025-02-26T15:27:20+01:00" level=trace msg="sent dealer ping" Feb 26 15:27:20 volumio go-librespot[1199]: time="2025-02-26T15:27:20+01:00" level=trace msg="received dealer pong" Feb 26 15:27:23 volumio volumio[838]: info: CoreCommandRouter::volumioGetState Feb 26 15:27:23 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:27:27 volumio go-librespot[1199]: time="2025-02-26T15:27:27+01:00" level=debug msg="fetched chunk 10/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:27:29 volumio volumio[838]: info: CoreCommandRouter::volumioGetState Feb 26 15:27:29 volumio volumio[838]: info: CorePlayQueue::getTrack 69 Feb 26 15:27:39 volumio sudo[918]: pam_unix(sudo:session): session closed for user root Feb 26 15:27:39 volumio volumio[838]: info: Cannot mount NAS tomas at system boot, trial number 1 ,retrying in 5 seconds Feb 26 15:27:39 volumio go-librespot[1199]: time="2025-02-26T15:27:39+01:00" level=debug msg="fetched chunk 11/42, size: 524288" uri="spotify:track:4H3ZV1gtveBXnzEEtEmf4e" Feb 26 15:27:44 volumio volumio[838]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 15:27:44 volumio volumio[838]: TypeError: Cannot read property 'replace' of undefined Feb 26 15:27:44 volumio volumio[838]: at ControllerNetworkfs.mountShare (/volumio/app/plugins/system_controller/networkfs/index.js:202:28) Feb 26 15:27:44 volumio volumio[838]: at Timeout._onTimeout (/volumio/app/plugins/system_controller/networkfs/index.js:255:20) Feb 26 15:27:44 volumio volumio[838]: at listOnTimeout (internal/timers.js:554:17) Feb 26 15:27:44 volumio volumio[838]: at processTimers (internal/timers.js:497:7) Feb 26 15:27:44 volumio volumio[838]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 26 15:27:45 volumio sudo[1625]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-02-26 15:26 Feb 26 15:27:45 volumio sudo[1625]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"