Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="completed keyexchange" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="completed challenge" Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Go-http-client/1.1 Engine version: 3 Transport: websocket Total Clients: 5 Feb 21 20:58:00 volumio volumio[5443]: SPOTIFY: User informations: {"country":"PL","display_name":"Jacek Pozarzycki","email":"jacekpozarzycki@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/11128507588"},"followers":{"href":null,"total":5},"href":"https://api.spotify.com/v1/users/11128507588","id":"11128507588","images":[{"height":300,"url":"https://scontent-cdg4-1.xx.fbcdn.net/v/t1.30497-1/453178253_471506465671661_2781666950760530985_n.png?stp=dst-png_s320x320&_nc_cat=1&ccb=1-7&_nc_sid=511c1b&_nc_ohc=_KusR6DysGQQ7kNvwEU7lbg&_nc_oc=Adm7x3tDj4hiyj-Mhw03djdmHoz1eZb06ze-7HoP5vTJJPuKod1ZcQ9gPdr6NASeS5sInwOwlwZrTz_JzH-HaGu3&_nc_zt=24&_nc_ht=scontent-cdg4-1.xx&edm=AP4hL3IEAAAA&_nc_tpa=Q5bMBQE7LLbFdf_nie1B2y4HAZw156Jpy-w7NIpwTDSLwskcL_PiL8Vbm9GI5ybh5vuXHh5QP_4K&oh=00_AfvxkD57GR0oF8-kL5YHyvXkJHRIRV21NrvqPhZZb_QQrw&oe=69C0C77A","width":300},{"height":64,"url":"https://scontent-cdg4-1.xx.fbcdn.net/v/t1.30497-1/453178253_471506465671661_2781666950760530985_n.png?stp=cp0_dst-png_s50x50&_nc_cat=1&ccb=1-7&_nc_sid=207b4a&_nc_ohc=_KusR6DysGQQ7kNvwEU7lbg&_nc_oc=Adm7x3tDj4hiyj-Mhw03djdmHoz1eZb06ze-7HoP5vTJJPuKod1ZcQ9gPdr6NASeS5sInwOwlwZrTz_JzH-HaGu3&_nc_zt=24&_nc_ht=scontent-cdg4-1.xx&edm=AP4hL3IEAAAA&_nc_tpa=Q5bMBQFilxxE3cutFNZ7cPGKyb8Q4pq2T6I-gRDoL6hG_LNjSOe7wD3vnLBann96B3rEznnf95Ne&oh=00_Aft9n99FiRJ7oFLuq2wGjmjM32iyciKSEjsMMG2_5ddXsQ&oe=69C0C77A","width":64}],"product":"premium","type":"user","uri":"spotify:user:11128507588"} Feb 21 20:58:00 volumio volumio[5443]: info: Spotify Successfully logged in Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Feb 21 20:58:00 volumio volumio[5443]: info: [1771703880088] CoreMusicLibrary::Adding element Spotify Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 20:58:00 volumio volumio[5443]: Cannot find translation for source 80s80s Radio Feb 21 20:58:00 volumio volumio[5443]: Cannot find translation for source RADIO 357 Feb 21 20:58:00 volumio volumio[5443]: Cannot find translation for source Radio Paradise Feb 21 20:58:00 volumio volumio[5443]: Cannot find translation for source Spotify Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=info msg="authenticated AP" username="11*******88" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=info msg="authenticated Login5" username="11*******88" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="initializing zeroconf session" username="11*******88" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="dealer connection opened" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=trace msg="starting accesspoint recv loop" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=trace msg="starting dealer recv loop" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=trace msg="received accesspoint ping" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="received connection id: MTZkMDVhNDQtN2Q3...ODA1MjUxQjE0Mg==" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=trace msg="received accesspoint pong ack" Feb 21 20:58:00 volumio go-librespot[5652]: time="2026-02-21T20:58:00+01:00" level=debug msg="put connect state because NEW_DEVICE" Feb 21 20:58:00 volumio mpd[5633]: 2026-02-21T20:58:00 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Feb 21 20:58:00 volumio systemd[1]: Started mpd.service - Music Player Daemon. Feb 21 20:58:00 volumio sudo[5587]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:00 volumio sudo[5574]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:00 volumio volumio[5443]: info: Completed starting Core Plugins Feb 21 20:58:00 volumio volumio[5443]: info: ------------------------------------------- Feb 21 20:58:00 volumio volumio[5443]: info: ----- MyVolumio plugins startup ---- Feb 21 20:58:00 volumio volumio[5443]: info: ------------------------------------------- Feb 21 20:58:00 volumio volumio[5443]: info: [MyVolumio PluginManager] Fetching plans data.... Feb 21 20:58:00 volumio volumio[5443]: error: MPD error: The expression evaluated to a falsy value: Feb 21 20:58:00 volumio volumio[5443]: assert.ok(self.idling) Feb 21 20:58:00 volumio volumio[5443]: error: The expression evaluated to a falsy value: Feb 21 20:58:00 volumio volumio[5443]: assert.ok(self.idling) Feb 21 20:58:00 volumio volumio[5443]: error: updateQueue error: null Feb 21 20:58:00 volumio volumio[5443]: info: MPD running with PID5633 Feb 21 20:58:00 volumio volumio[5443]: ,establishing connection Feb 21 20:58:00 volumio volumio[5443]: verbose: New Socket.io Connection to 192.168.1.254 from 192.168.1.172 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/145.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Feb 21 20:58:00 volumio volumio[5443]: error: updateQueue error: null Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:00 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetVisibleSources Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:00 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:00 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Feb 21 20:58:00 volumio volumio[5443]: info: Received Get System Info Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Feb 21 20:58:00 volumio volumio[5443]: info: Discovery: Getting this device information Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:00 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:00 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:00 volumio volumio[5443]: info: Listing playlists Feb 21 20:58:00 volumio volumio[5443]: info: CoreCommandRouter::volumioGetQueue Feb 21 20:58:00 volumio volumio[5443]: info: CoreStateMachine::getQueue Feb 21 20:58:00 volumio volumio[5443]: info: CorePlayQueue::getQueue Feb 21 20:58:02 volumio volumio[5443]: info: go-librespot daemon successfully initialized Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::volumioPlay Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::play index undefined Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::startPlaybackTimer Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883292] [80s80s] clearAddPlayTrack url: http://streams.90s90s.de/grunge/mp3-192/volumio Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883293] [80s80s] getContentOfUrl started with url http://iris-90s90s.loverad.io/flow.json?station=253&count=2 Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883460] [80s80s] received new event containing 2 songs. Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand stop Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand stop took 1 milliseconds Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand clear Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:03 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand clear took 1 milliseconds Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand consume 1 Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:03 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:03 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:03 volumio volumio[5443]: error: updateQueue error: null Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces state update: options Feb 21 20:58:03 volumio volumio[5443]: error: updateQueue error: null Feb 21 20:58:03 volumio volumio[5443]: error: updateQueue error: null Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 5ms Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand consume 1 took 4 milliseconds Feb 21 20:58:03 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 5ms Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 4ms Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883470] [80s80s] adding url: http://streams.90s90s.de/grunge/mp3-192/volumio Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand add "http://streams.90s90s.de/grunge/mp3-192/volumio" Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces state update: options Feb 21 20:58:03 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces state update: options Feb 21 20:58:03 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:03 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand status took 4 milliseconds Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand add "http://streams.90s90s.de/grunge/mp3-192/volumio" took 4 milliseconds Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand status took 3 milliseconds Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand status took 3 milliseconds Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand play Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:03 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:03 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::pushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::volumioPushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:03 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::pushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::volumioPushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:03 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::pushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::volumioPushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 22ms Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 25ms Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 25ms Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:03 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:03 volumio volumio[5443]: info: Feb 21 20:58:03 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:03 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 27ms Feb 21 20:58:03 volumio volumio[5443]: info: sendMpdCommand play took 22 milliseconds Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 3ms Feb 21 20:58:03 volumio volumio[5443]: info: ------------------------------ 3ms Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883501] [80s80s] Pushing the next song state: Soundgarden - Black Hole Sun Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: verbose: STATE SERVICE {"status":"play","service":"80s80s","type":"track","trackType":"80s80s Radio","radioType":"80s80s","albumart":"https://is5-ssl.mzstatic.com/image/thumb/Music125/v4/05/6e/c5/056ec58e-cfc3-47a4-031d-1dc415b23bbf/source/600x600bb.jpg","name":"Soundgarden - Black Hole Sun","title":"Black Hole Sun","artist":"90s90s Grunge","album":"","streaming":true,"disableUiControls":true,"duration":"245","seek":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2} Feb 21 20:58:03 volumio volumio[5443]: verbose: CURRENT POSITION 0 Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::syncState stateService play Feb 21 20:58:03 volumio volumio[5443]: info: CoreStateMachine::syncState currentStatus stop Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883503] [80s80s] PlayNextTrack API delay: 30 Feb 21 20:58:03 volumio volumio[5443]: info: [1771703883513] [80s80s] Setting timer to: 245000 milliseconds. Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:03 volumio volumio[5443]: info: CorePlayQueue::getTrack 1 Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 16 milliseconds Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 16 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 16 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 21ms Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 6 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 5 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 5 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 2 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 1 milliseconds Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 27ms Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 26ms Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 4 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 14ms Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 10ms Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 9ms Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:04 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:04 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:04 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:04 volumio volumio[5443]: info: Feb 21 20:58:04 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 6ms Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 3 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 3ms Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 4 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 3ms Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand status took 2 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 1 milliseconds Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 9ms Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 21 20:58:04 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 2 milliseconds Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:04 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:04 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:04 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 9ms Feb 21 20:58:04 volumio volumio[5443]: info: ------------------------------ 8ms Feb 21 20:58:05 volumio sudo[5721]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Feb 21 20:58:05 volumio sudo[5721]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:05 volumio sudo[5721]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:05 volumio sudo[5723]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Feb 21 20:58:05 volumio sudo[5723]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:05 volumio sudo[5723]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:05 volumio sudo[5726]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Feb 21 20:58:05 volumio sudo[5726]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:05 volumio volumio[5443]: info: Initializing connection to go-librespot Websocket Feb 21 20:58:05 volumio go-librespot[5652]: time="2026-02-21T20:58:05+01:00" level=debug msg="new websocket client" Feb 21 20:58:05 volumio volumio[5443]: info: Connection to go-librespot Websocket established Feb 21 20:58:05 volumio sudo[5726]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:05 volumio volumio[5443]: info: Upmpdcli Daemon Started Feb 21 20:58:05 volumio volumio[5443]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Feb 21 20:58:08 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:08.563+01:00 level=ERROR msg="failed to update discovery on Wi-Fi info change" error="failed to get system info: could not get system info: context deadline exceeded" Feb 21 20:58:08 volumio volumio[5443]: info: Getting Spotify volume Feb 21 20:58:08 volumio volumio[5443]: info: Spotify volume: 100 Feb 21 20:58:08 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 7 Feb 21 20:58:08 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:08 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:08 volumio volumio[5443]: SPOTIFY: RECEIVED VOLUMIO VOLUME 88 Feb 21 20:58:08 volumio volumio[5443]: SPOTIFY: SPOTIFY VOLUME 100 Feb 21 20:58:08 volumio volumio[5443]: SPOTIFY: VOLUMIO VOLUME 88 Feb 21 20:58:08 volumio volumio[5443]: SPOTIFY: DELTA VOLUME ENOUGH: true Feb 21 20:58:08 volumio volumio[5443]: info: Setting Spotify Volume from Volumio: 88 Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin bluetooth to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin multiroom to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin metavolumio to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin cd_controller to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin qobuzconnect to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin smart_inputs to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: Adding plugin tidalconnect to MyMusic Plugins Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Feb 21 20:58:09 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:09 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:09 volumio volumio[5443]: info: Starting MyVolumio Remote Streaming Endpoints Feb 21 20:58:09 volumio volumio[5443]: info: MyVolumio login type: Token Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Feb 21 20:58:09 volumio volumio[5443]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Feb 21 20:58:10 volumio volumio[5443]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Feb 21 20:58:10 volumio volumio[5443]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Feb 21 20:58:10 volumio volumio[5443]: info: Streaming services startup Feb 21 20:58:10 volumio volumio[5443]: info: Starting Streaming Daemon Feb 21 20:58:10 volumio sudo[5742]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 21 20:58:10 volumio sudo[5742]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:10 volumio volumio[5443]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Feb 21 20:58:10 volumio sudo[5742]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:10 volumio volumio[5443]: error: Cannot start Volumio Streaming Daemon Feb 21 20:58:10 volumio volumio[5443]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 21 20:58:10 volumio volumio[5443]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 21 20:58:10 volumio volumio[5443]: SPOTIFY: SETTING SPOTIFY VOLUME 88 Feb 21 20:58:10 volumio volumio[5443]: info: Sending Spotify command with payload to local API: /player/volume Feb 21 20:58:10 volumio volumio[5443]: error: Failed to send command to Spotify local API: /player/volume: Error: Bad Request Feb 21 20:58:10 volumio volumio[5443]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Feb 21 20:58:11 volumio volumio[5443]: info: MyVolumio token set successfully Feb 21 20:58:11 volumio volumio[5443]: info: MYVOLUMIO: Adding device Feb 21 20:58:11 volumio volumio[5443]: info: MYVOLUMIO: Evaluating Server Feb 21 20:58:11 volumio volumio[5443]: info: MyVolumio status changed Feb 21 20:58:11 volumio volumio[5443]: info: Streaming services startup Feb 21 20:58:11 volumio volumio[5443]: info: Starting Streaming Daemon Feb 21 20:58:11 volumio volumio[5443]: info: Removing browser output: myVolumio user plan is not superstar Feb 21 20:58:11 volumio volumio[5443]: info: Removing audio output: Feb 21 20:58:11 volumio volumio[5443]: info: Stoppping Tunnel 1 Feb 21 20:58:11 volumio sudo[5774]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Feb 21 20:58:11 volumio sudo[5774]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:11 volumio sudo[5776]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Feb 21 20:58:11 volumio sudo[5776]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 21 20:58:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 21 20:58:11 volumio sudo[5774]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:11 volumio volumio[5443]: error: Cannot start Volumio Streaming Daemon Feb 21 20:58:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 21 20:58:11 volumio volumio[5443]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Feb 21 20:58:11 volumio volumio[5443]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Feb 21 20:58:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 21 20:58:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:6: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 21 20:58:11 volumio systemd[1]: /lib/systemd/system/sshtunnel.service:7: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Feb 21 20:58:11 volumio sudo[5776]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:11 volumio volumio[5443]: info: Remote SSH Stopped Feb 21 20:58:12 volumio volumio[5443]: info: Setting Geolocation for MyVolumio to eu2 Feb 21 20:58:12 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:12 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:12 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:12 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 20:58:12 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 21 20:58:12 volumio volumio[5443]: info: Successfully Added MyVolumio device Feb 21 20:58:13 volumio volumio[5443]: info: Updating MyVolumio device info Feb 21 20:58:13 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:13 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:13 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:13 volumio volumio[5443]: info: Successfully Updated MyVolumio device Feb 21 20:58:24 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Feb 21 20:58:24 volumio volumio[5443]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Feb 21 20:58:24 volumio volumio[5443]: info: CoreCommandRouter::volumioGetState Feb 21 20:58:24 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:29 volumio volumio[5443]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/now_playing/volumio/bookworm/armhf Feb 21 20:58:29 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:29.104+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Feb 21 20:58:29 volumio volumio-remote-updater[776]: Test mode disabled Feb 21 20:58:29 volumio volumio-remote-updater[776]: Alpha mode disabled Feb 21 20:58:29 volumio volumio-remote-updater[776]: Alpha legacy test mode disabled Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Feb 21 20:58:29 volumio volumio[5443]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::volumioGetBrowseSources Feb 21 20:58:29 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 20:58:30 volumio volumio[5443]: error: MyVolumio Plugin failed to authenticate in a timely fashion Feb 21 20:58:30 volumio volumio[5443]: info: Completed starting MyVolumio Plugin Feb 21 20:58:30 volumio volumio[5443]: [Metrics] CommandRouter: 35s 808.37ms Feb 21 20:58:30 volumio volumio[5443]: info: CoreCommandRouter::volumiosetStartupVolume Feb 21 20:58:30 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Feb 21 20:58:30 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 21 20:58:30 volumio volumio[5443]: info: CoreCommandRouter::Close All Modals sent Feb 21 20:58:30 volumio volumio[5443]: info: CoreCommandRouter::Close All Modals sent Feb 21 20:58:30 volumio volumio[5443]: info: Cannot play startup sound: Error: Command failed: /usr/bin/aplay -D volumio /volumio/app/startup.wav Feb 21 20:58:30 volumio volumio[5443]: aplay: main:831: audio open error: Device or resource busy Feb 21 20:58:30 volumio go-librespot[5652]: time="2026-02-21T20:58:30+01:00" level=trace msg="sent dealer ping" Feb 21 20:58:30 volumio go-librespot[5652]: time="2026-02-21T20:58:30+01:00" level=trace msg="received dealer pong" Feb 21 20:58:31 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Feb 21 20:58:31 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 21 20:58:31 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Feb 21 20:58:31 volumio volumio[5443]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/now_playing/volumio/bookworm/armhf Feb 21 20:58:31 volumio volumio[5443]: info: Folder /tmp/plugins removed Feb 21 20:58:31 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:31.355+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:32 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:32.333+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:32 volumio volumio[5443]: info: Check plugin dependencies Feb 21 20:58:32 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 20:58:32 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:32.393+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:32 volumio volumio[5443]: info: Checking if plugin already exists Feb 21 20:58:32 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:32.398+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:32 volumio volumio[5443]: info: Rename folder Feb 21 20:58:32 volumio volumio[5443]: info: Folder /tmp/downloaded_plugin.zip removed Feb 21 20:58:32 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:32.417+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:32 volumio volumio[5443]: info: Move to category Feb 21 20:58:34 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:34.829+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:34 volumio volumio[5443]: info: Checking if install.sh is present Feb 21 20:58:34 volumio volumio[5443]: info: Executing install.sh Feb 21 20:58:34 volumio volumio[5443]: Upnp client error: Error: This socket has been ended by the other party Feb 21 20:58:34 volumio sudo[5875]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/now_playing/install.sh Feb 21 20:58:34 volumio sudo[5875]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:34 volumio su[5880]: (to volumio) root on none Feb 21 20:58:34 volumio su[5880]: pam_unix(su:session): session opened for user volumio(uid=1000) by (uid=0) Feb 21 20:58:34 volumio volumio[5443]: info: Installing geo-tz node dependency Feb 21 20:58:34 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:34.900+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:34 volumio systemd[1]: Created slice user-1000.slice - User Slice of UID 1000. Feb 21 20:58:35 volumio systemd[1]: Starting user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Feb 21 20:58:35 volumio systemd[1]: Finished user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Feb 21 20:58:35 volumio systemd[1]: Starting user@1000.service - User Manager for UID 1000... Feb 21 20:58:35 volumio (systemd)[5882]: pam_unix(systemd-user:session): session opened for user volumio(uid=1000) by (uid=0) Feb 21 20:58:35 volumio systemd[5882]: Queued start job for default target default.target. Feb 21 20:58:35 volumio systemd[5882]: Created slice app.slice - User Application Slice. Feb 21 20:58:35 volumio systemd[5882]: Reached target paths.target - Paths. Feb 21 20:58:35 volumio systemd[5882]: Reached target timers.target - Timers. Feb 21 20:58:35 volumio systemd[5882]: Listening on dirmngr.socket - GnuPG network certificate management daemon. Feb 21 20:58:35 volumio systemd[5882]: Listening on gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Feb 21 20:58:35 volumio systemd[5882]: Listening on gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Feb 21 20:58:35 volumio systemd[5882]: Listening on gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Feb 21 20:58:35 volumio systemd[5882]: Listening on gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Feb 21 20:58:35 volumio systemd[5882]: Reached target sockets.target - Sockets. Feb 21 20:58:35 volumio systemd[5882]: Reached target basic.target - Basic System. Feb 21 20:58:35 volumio systemd[1]: Started user@1000.service - User Manager for UID 1000. Feb 21 20:58:35 volumio systemd[5882]: Started mpris-proxy.service - Bluetooth mpris proxy. Feb 21 20:58:35 volumio systemd[5882]: Reached target default.target - Main User Target. Feb 21 20:58:35 volumio systemd[5882]: Startup finished in 447ms. Feb 21 20:58:35 volumio systemd[1]: Started session-c1.scope - Session c1 of User volumio. Feb 21 20:58:35 volumio mpris-proxy[5897]: Can't get on session bus Feb 21 20:58:35 volumio systemd[5882]: mpris-proxy.service: Main process exited, code=exited, status=1/FAILURE Feb 21 20:58:35 volumio systemd[5882]: mpris-proxy.service: Failed with result 'exit-code'. Feb 21 20:58:37 volumio volumio[5443]: info: BOOT COMPLETED Feb 21 20:58:39 volumio volumio[5443]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/now_playing/volumio/bookworm/armhf Feb 21 20:58:39 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:39.129+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:41 volumio volumio[5443]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/now_playing/volumio/bookworm/armhf Feb 21 20:58:41 volumio volumio[5443]: info: Folder /tmp/plugins removed Feb 21 20:58:41 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:41.978+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:42 volumio volumio[5443]: info: Feb 21 20:58:42 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:42 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:42 volumio volumio[5443]: info: Feb 21 20:58:42 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:42 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:42 volumio volumio[5443]: info: Feb 21 20:58:42 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:42 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:42 volumio volumio[5443]: info: Feb 21 20:58:42 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:42 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:42 volumio volumio[5443]: info: Feb 21 20:58:42 volumio volumio[5443]: ---------------------------- MPD announces system playlist update Feb 21 20:58:42 volumio volumio[5443]: info: Ignoring MPD Status Update Feb 21 20:58:42 volumio volumio[5443]: info: Feb 21 20:58:42 volumio volumio[5443]: ---------------------------- MPD announces state update: player Feb 21 20:58:42 volumio volumio[5443]: info: ControllerMpd::getState Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand status Feb 21 20:58:42 volumio volumio[5443]: info: ------------------------------ 12ms Feb 21 20:58:42 volumio volumio[5443]: info: sendMpdCommand status took 11 milliseconds Feb 21 20:58:42 volumio volumio[5443]: info: ------------------------------ 10ms Feb 21 20:58:42 volumio volumio[5443]: info: sendMpdCommand status took 9 milliseconds Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:42 volumio volumio[5443]: info: ------------------------------ 12ms Feb 21 20:58:42 volumio volumio[5443]: info: sendMpdCommand status took 6 milliseconds Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::parseState Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 21 20:58:42 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 15 milliseconds Feb 21 20:58:42 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 15 milliseconds Feb 21 20:58:42 volumio volumio[5443]: info: sendMpdCommand playlistinfo took 12 milliseconds Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:42 volumio volumio[5443]: verbose: ControllerMpd::parseTrackInfo Feb 21 20:58:42 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:42 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:42 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:42 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:42 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:42 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:42 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:42 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:42 volumio volumio[5443]: info: ControllerMpd::pushState Feb 21 20:58:42 volumio volumio[5443]: info: CoreCommandRouter::servicePushState Feb 21 20:58:42 volumio volumio[5443]: info: CorePlayQueue::getTrack 0 Feb 21 20:58:42 volumio volumio[5443]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current 80s80s Received mpd Feb 21 20:58:42 volumio volumio[5443]: info: ------------------------------ 35ms Feb 21 20:58:42 volumio volumio[5443]: info: ------------------------------ 32ms Feb 21 20:58:42 volumio volumio[5443]: info: ------------------------------ 27ms Feb 21 20:58:43 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:43.426+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:43 volumio volumio[5443]: info: Check plugin dependencies Feb 21 20:58:43 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Feb 21 20:58:43 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:43.501+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:43 volumio volumio[5443]: info: Checking if plugin already exists Feb 21 20:58:43 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:43.515+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:43 volumio volumio[5443]: info: Rename folder Feb 21 20:58:43 volumio volumio[5443]: info: Folder /tmp/downloaded_plugin.zip removed Feb 21 20:58:43 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:43.553+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:43 volumio volumio[5443]: info: Move to category Feb 21 20:58:49 volumio su[5880]: pam_unix(su:session): session closed for user volumio Feb 21 20:58:49 volumio systemd[1]: session-c1.scope: Deactivated successfully. Feb 21 20:58:49 volumio systemd[1]: session-c1.scope: Consumed 25.702s CPU time. Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.681+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: info: Checking if install.sh is present Feb 21 20:58:49 volumio volumio[5443]: info: Executing install.sh Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: info: added 27 packages, changed 4 packages, and audited 162 packages in 13s Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.710+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: info: 24 packages are looking for funding Feb 21 20:58:49 volumio volumio[5443]: info: run `npm fund` for details Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: info: 5 vulnerabilities (1 low, 4 high) Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: info: To address issues that do not require attention, run: Feb 21 20:58:49 volumio volumio[5443]: info: npm audit fix Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: info: To address all issues (including breaking changes), run: Feb 21 20:58:49 volumio volumio[5443]: info: npm audit fix --force Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: info: Run `npm audit` for details. Feb 21 20:58:49 volumio volumio[5443]: info: Creating user directories (if not exist) Feb 21 20:58:49 volumio sudo[6009]: volumio : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh /data/plugins/user_interface/now_playing/install.sh Feb 21 20:58:49 volumio sudo[6009]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.732+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.733+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.733+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.734+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.734+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.735+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.735+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.736+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.737+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.737+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.738+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.738+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.739+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.739+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.740+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: Upnp client error: Error: This socket has been ended by the other party Feb 21 20:58:49 volumio volumio[5443]: info: Installing geo-tz node dependency Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.779+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: info: Installing geo-tz node dependency Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.785+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio su[6012]: (to volumio) root on none Feb 21 20:58:49 volumio su[6012]: pam_unix(su:session): session opened for user volumio(uid=1000) by (uid=0) Feb 21 20:58:49 volumio sudo[5875]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: Now Playing plugin installed Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.892+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: Plugin install end detected on script Feb 21 20:58:49 volumio volumio[5443]: info: Install script completed Feb 21 20:58:49 volumio volumio[5443]: info: Adding reference to registry Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.904+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.906+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: info: Done installing plugin. Feb 21 20:58:49 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 20:58:49 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 21 20:58:49 volumio volumio[5443]: info: Feb 21 20:58:49 volumio volumio[5443]: Now Playing plugin installed Feb 21 20:58:49 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:49.923+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:49 volumio volumio[5443]: Plugin install end detected on script Feb 21 20:58:49 volumio volumio[5443]: info: Folder /tmp/plugins removed Feb 21 20:58:49 volumio volumio[5443]: info: Folder /tmp/downloaded_plugin.zip removed Feb 21 20:58:49 volumio systemd[1]: Started session-c2.scope - Session c2 of User volumio. Feb 21 20:58:49 volumio volumio[5443]: info: Folder /data/temp removed Feb 21 20:58:51 volumio volumio[5443]: info: Enabling plugin now_playing Feb 21 20:58:51 volumio volumio[5443]: info: Loading plugin "now_playing"... Feb 21 20:58:51 volumio volumio[5443]: error: !!!! WARNING !!!! Feb 21 20:58:51 volumio volumio[5443]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Feb 21 20:58:51 volumio volumio[5443]: Require stack: Feb 21 20:58:51 volumio volumio[5443]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 21 20:58:51 volumio volumio[5443]: - /volumio/app/pluginmanager.js Feb 21 20:58:51 volumio volumio[5443]: - /volumio/app/index.js Feb 21 20:58:51 volumio volumio[5443]: - /volumio/index.js Feb 21 20:58:51 volumio volumio[5443]: error: Stack trace: Error: Cannot find module 'geo-tz' Feb 21 20:58:51 volumio volumio[5443]: Require stack: Feb 21 20:58:51 volumio volumio[5443]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 21 20:58:51 volumio volumio[5443]: - /volumio/app/pluginmanager.js Feb 21 20:58:51 volumio volumio[5443]: - /volumio/app/index.js Feb 21 20:58:51 volumio volumio[5443]: - /volumio/index.js Feb 21 20:58:51 volumio volumio[5443]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Feb 21 20:58:51 volumio volumio[5443]: at Module._load (node:internal/modules/cjs/loader:901:27) Feb 21 20:58:51 volumio volumio[5443]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 21 20:58:51 volumio volumio[5443]: at require (node:internal/modules/helpers:130:18) Feb 21 20:58:51 volumio volumio[5443]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Feb 21 20:58:51 volumio volumio[5443]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Feb 21 20:58:51 volumio volumio[5443]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Feb 21 20:58:51 volumio volumio[5443]: at Module.load (node:internal/modules/cjs/loader:1091:32) Feb 21 20:58:51 volumio volumio[5443]: at Module._load (node:internal/modules/cjs/loader:938:12) Feb 21 20:58:51 volumio volumio[5443]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 21 20:58:51 volumio volumio[5443]: at require (node:internal/modules/helpers:130:18) Feb 21 20:58:51 volumio volumio[5443]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Feb 21 20:58:51 volumio volumio[5443]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Feb 21 20:58:51 volumio volumio[5443]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Feb 21 20:58:51 volumio volumio[5443]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Feb 21 20:58:51 volumio volumio[5443]: error: !!!! WARNING !!!! Feb 21 20:58:51 volumio volumio[5443]: info: Done. Feb 21 20:58:57 volumio su[6012]: pam_unix(su:session): session closed for user volumio Feb 21 20:58:57 volumio systemd[1]: session-c2.scope: Deactivated successfully. Feb 21 20:58:57 volumio systemd[1]: session-c2.scope: Consumed 11.108s CPU time. Feb 21 20:58:57 volumio sudo[6009]: pam_unix(sudo:session): session closed for user root Feb 21 20:58:57 volumio volumio[5443]: info: Install script completed Feb 21 20:58:57 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:57.367+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:58:57 volumio volumio5-onboarding[1585]: time=2026-02-21T20:58:57.372+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:59:00 volumio volumio[5443]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 21 20:59:00 volumio go-librespot[5652]: time="2026-02-21T20:59:00+01:00" level=trace msg="sent dealer ping" Feb 21 20:59:00 volumio go-librespot[5652]: time="2026-02-21T20:59:00+01:00" level=trace msg="received dealer pong" Feb 21 20:59:02 volumio ntpd[1038]: PROTO: 89.161.47.136 unlink local addr 192.168.1.254 -> Feb 21 20:59:06 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 20:59:06 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 21 20:59:07 volumio systemd[1]: Stopping user@1000.service - User Manager for UID 1000... Feb 21 20:59:07 volumio systemd[5882]: Activating special unit exit.target... Feb 21 20:59:07 volumio systemd[5882]: Stopped target default.target - Main User Target. Feb 21 20:59:07 volumio systemd[5882]: Stopped target basic.target - Basic System. Feb 21 20:59:07 volumio systemd[5882]: Stopped target paths.target - Paths. Feb 21 20:59:07 volumio systemd[5882]: Stopped target sockets.target - Sockets. Feb 21 20:59:07 volumio systemd[5882]: Stopped target timers.target - Timers. Feb 21 20:59:07 volumio systemd[5882]: Closed dirmngr.socket - GnuPG network certificate management daemon. Feb 21 20:59:07 volumio systemd[5882]: Closed gpg-agent-browser.socket - GnuPG cryptographic agent and passphrase cache (access for web browsers). Feb 21 20:59:07 volumio systemd[5882]: Closed gpg-agent-extra.socket - GnuPG cryptographic agent and passphrase cache (restricted). Feb 21 20:59:07 volumio systemd[5882]: Closed gpg-agent-ssh.socket - GnuPG cryptographic agent (ssh-agent emulation). Feb 21 20:59:07 volumio systemd[5882]: Closed gpg-agent.socket - GnuPG cryptographic agent and passphrase cache. Feb 21 20:59:07 volumio systemd[5882]: Removed slice app.slice - User Application Slice. Feb 21 20:59:07 volumio systemd[5882]: Reached target shutdown.target - Shutdown. Feb 21 20:59:07 volumio systemd[5882]: Finished systemd-exit.service - Exit the Session. Feb 21 20:59:07 volumio systemd[5882]: Reached target exit.target - Exit the Session. Feb 21 20:59:07 volumio systemd[1]: user@1000.service: Deactivated successfully. Feb 21 20:59:07 volumio systemd[1]: Stopped user@1000.service - User Manager for UID 1000. Feb 21 20:59:07 volumio systemd[1]: Stopping user-runtime-dir@1000.service - User Runtime Directory /run/user/1000... Feb 21 20:59:07 volumio systemd[1]: run-user-1000.mount: Deactivated successfully. Feb 21 20:59:07 volumio systemd[1]: user-runtime-dir@1000.service: Deactivated successfully. Feb 21 20:59:07 volumio systemd[1]: Stopped user-runtime-dir@1000.service - User Runtime Directory /run/user/1000. Feb 21 20:59:07 volumio systemd[1]: Removed slice user-1000.slice - User Slice of UID 1000. Feb 21 20:59:07 volumio systemd[1]: user-1000.slice: Consumed 37.299s CPU time. Feb 21 20:59:11 volumio volumio[5443]: info: Enabling plugin now_playing Feb 21 20:59:11 volumio volumio[5443]: info: Loading plugin "now_playing"... Feb 21 20:59:11 volumio volumio[5443]: error: !!!! WARNING !!!! Feb 21 20:59:11 volumio volumio[5443]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Feb 21 20:59:11 volumio volumio[5443]: Require stack: Feb 21 20:59:11 volumio volumio[5443]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 21 20:59:11 volumio volumio[5443]: - /volumio/app/pluginmanager.js Feb 21 20:59:11 volumio volumio[5443]: - /volumio/app/index.js Feb 21 20:59:11 volumio volumio[5443]: - /volumio/index.js Feb 21 20:59:11 volumio volumio[5443]: error: Stack trace: Error: Cannot find module 'geo-tz' Feb 21 20:59:11 volumio volumio[5443]: Require stack: Feb 21 20:59:11 volumio volumio[5443]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 21 20:59:11 volumio volumio[5443]: - /volumio/app/pluginmanager.js Feb 21 20:59:11 volumio volumio[5443]: - /volumio/app/index.js Feb 21 20:59:11 volumio volumio[5443]: - /volumio/index.js Feb 21 20:59:11 volumio volumio[5443]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Feb 21 20:59:11 volumio volumio[5443]: at Module._load (node:internal/modules/cjs/loader:901:27) Feb 21 20:59:11 volumio volumio[5443]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 21 20:59:11 volumio volumio[5443]: at require (node:internal/modules/helpers:130:18) Feb 21 20:59:11 volumio volumio[5443]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Feb 21 20:59:11 volumio volumio[5443]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Feb 21 20:59:11 volumio volumio[5443]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Feb 21 20:59:11 volumio volumio[5443]: at Module.load (node:internal/modules/cjs/loader:1091:32) Feb 21 20:59:11 volumio volumio[5443]: at Module._load (node:internal/modules/cjs/loader:938:12) Feb 21 20:59:11 volumio volumio[5443]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 21 20:59:11 volumio volumio[5443]: at require (node:internal/modules/helpers:130:18) Feb 21 20:59:11 volumio volumio[5443]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Feb 21 20:59:11 volumio volumio[5443]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Feb 21 20:59:11 volumio volumio[5443]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Feb 21 20:59:11 volumio volumio[5443]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Feb 21 20:59:11 volumio volumio[5443]: error: !!!! WARNING !!!! Feb 21 20:59:11 volumio volumio[5443]: info: Error: TypeError: Cannot read properties of null (reading 'printToastMessage') Feb 21 20:59:13 volumio volumio[5443]: info: Enabling plugin now_playing Feb 21 20:59:13 volumio volumio[5443]: info: Loading plugin "now_playing"... Feb 21 20:59:13 volumio volumio[5443]: error: !!!! WARNING !!!! Feb 21 20:59:13 volumio volumio[5443]: error: The plugin user_interface/now_playing failed to load, setting it to stopped. Error: Error: Cannot find module 'geo-tz' Feb 21 20:59:13 volumio volumio[5443]: Require stack: Feb 21 20:59:13 volumio volumio[5443]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 21 20:59:13 volumio volumio[5443]: - /volumio/app/pluginmanager.js Feb 21 20:59:13 volumio volumio[5443]: - /volumio/app/index.js Feb 21 20:59:13 volumio volumio[5443]: - /volumio/index.js Feb 21 20:59:13 volumio volumio[5443]: error: Stack trace: Error: Cannot find module 'geo-tz' Feb 21 20:59:13 volumio volumio[5443]: Require stack: Feb 21 20:59:13 volumio volumio[5443]: - /data/plugins/user_interface/now_playing/dist/index.js Feb 21 20:59:13 volumio volumio[5443]: - /volumio/app/pluginmanager.js Feb 21 20:59:13 volumio volumio[5443]: - /volumio/app/index.js Feb 21 20:59:13 volumio volumio[5443]: - /volumio/index.js Feb 21 20:59:13 volumio volumio[5443]: at Module._resolveFilename (node:internal/modules/cjs/loader:1048:15) Feb 21 20:59:13 volumio volumio[5443]: at Module._load (node:internal/modules/cjs/loader:901:27) Feb 21 20:59:13 volumio volumio[5443]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 21 20:59:13 volumio volumio[5443]: at require (node:internal/modules/helpers:130:18) Feb 21 20:59:13 volumio volumio[5443]: at Object. (/data/plugins/user_interface/now_playing/dist/index.js:56:34) Feb 21 20:59:13 volumio volumio[5443]: at Module._compile (node:internal/modules/cjs/loader:1233:14) Feb 21 20:59:13 volumio volumio[5443]: at Module._extensions..js (node:internal/modules/cjs/loader:1287:10) Feb 21 20:59:13 volumio volumio[5443]: at Module.load (node:internal/modules/cjs/loader:1091:32) Feb 21 20:59:13 volumio volumio[5443]: at Module._load (node:internal/modules/cjs/loader:938:12) Feb 21 20:59:13 volumio volumio[5443]: at Module.require (node:internal/modules/cjs/loader:1115:19) Feb 21 20:59:13 volumio volumio[5443]: at require (node:internal/modules/helpers:130:18) Feb 21 20:59:13 volumio volumio[5443]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:235:29) Feb 21 20:59:13 volumio volumio[5443]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Feb 21 20:59:13 volumio volumio[5443]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Feb 21 20:59:13 volumio volumio[5443]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Feb 21 20:59:13 volumio volumio[5443]: error: !!!! WARNING !!!! Feb 21 20:59:13 volumio volumio[5443]: info: Error: TypeError: Cannot read properties of null (reading 'printToastMessage') Feb 21 20:59:14 volumio volumio[5443]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 21 20:59:21 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Feb 21 20:59:21 volumio volumio[5443]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Feb 21 20:59:29 volumio volumio[5443]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/Bluetoothremote/volumio/bookworm/armhf Feb 21 20:59:29 volumio volumio5-onboarding[1585]: time=2026-02-21T20:59:29.105+01:00 level=WARN msg="received plugin install progress but no plugin is being installed" component=state Feb 21 20:59:29 volumio volumio[5443]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 20:59:29 volumio volumio[5443]: TypeError: Cannot read properties of null (reading 'broadcastMessage') Feb 21 20:59:29 volumio volumio[5443]: at /volumio/app/index.js:1534:32 Feb 21 20:59:29 volumio volumio[5443]: at fastMap (/volumio/node_modules/fast.js/array/map.js:21:17) Feb 21 20:59:29 volumio volumio[5443]: at Function.fastMap [as map] (/volumio/node_modules/fast.js/map.js:18:12) Feb 21 20:59:29 volumio volumio[5443]: at CoreCommandRouter.broadcastMessage (/volumio/app/index.js:1532:13) Feb 21 20:59:29 volumio volumio[5443]: at PluginManager.pushMessage (/volumio/app/pluginmanager.js:1594:20) Feb 21 20:59:29 volumio volumio[5443]: at PluginManager.installPlugin (/volumio/app/pluginmanager.js:776:8) Feb 21 20:59:29 volumio volumio[5443]: at CoreCommandRouter.installPlugin (/volumio/app/index.js:1453:22) Feb 21 20:59:29 volumio volumio[5443]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1220:47) Feb 21 20:59:29 volumio volumio[5443]: at Socket.emit (node:events:514:28) Feb 21 20:59:29 volumio volumio[5443]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Feb 21 20:59:29 volumio volumio[5443]: at process.processTicksAndRejections (node:internal/process/task_queues:77:11) Feb 21 20:59:29 volumio volumio[5443]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 21 20:59:29 volumio sudo[6217]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-21 20:58' Feb 21 20:59:29 volumio sudo[6217]: 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="a78d359cf1dc63ac74e9d151015afd30d31a709a" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="c1ffe93b2136013fc1b5903a4ed7e3f34e0a7bec" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Feb 5 14:07:07 UTC 2026" VOLUMIO_VERSION="4.096" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5e37060f9823263a753eb5e84030104f"