-- Logs begin at Tue 2025-05-20 17:53:51 CEST, end at Thu 2025-07-03 18:09:08 CEST. -- Jul 03 18:09:02 volumio systemd-timedated[1074]: Changed local time to Thu Jul 3 18:09:02 2025 Jul 03 18:09:02 volumio sudo[1034]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio volumio-time-update[580]: volumio-time-update-util: System time updated successfully. Jul 03 18:09:02 volumio systemd[1]: Started Volumio Time Update Utility. Jul 03 18:09:02 volumio ifplugd(eth0)[799]: Program executed successfully. Jul 03 18:09:02 volumio systemd[1]: Starting Daily apt download activities... Jul 03 18:09:02 volumio volumio[835]: info: MPD Permissions set Jul 03 18:09:02 volumio volumio[835]: info: VolumeController:: Volume=87 Mute =false Jul 03 18:09:02 volumio volumio[835]: info: CoreStateMachine::pushState Jul 03 18:09:02 volumio volumio[835]: info: CorePlayQueue::getTrack 0 Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::volumioPushState Jul 03 18:09:02 volumio volumio[835]: info: Spotify config file written Jul 03 18:09:02 volumio sudo[1094]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Jul 03 18:09:02 volumio sudo[1094]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:02 volumio volumio[835]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Jul 03 18:09:02 volumio volumio[835]: info: Volumio called home Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 03 18:09:02 volumio volumio[835]: info: No need to fix Spotify hosts Jul 03 18:09:02 volumio systemd[1]: Started go-librespot Daemon. Jul 03 18:09:02 volumio go-librespot[1103]: go-librespot daemon starting... Jul 03 18:09:02 volumio sudo[1094]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio volumio[835]: info: Starting Shairport Sync Jul 03 18:09:02 volumio volumio[835]: info: Starting Shairport Sync Jul 03 18:09:02 volumio sudo[1127]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 03 18:09:02 volumio sudo[1127]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:02 volumio volumio[835]: info: Starting Shairport Sync Jul 03 18:09:02 volumio sudo[1130]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 03 18:09:02 volumio sudo[1130]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:02 volumio volumio[835]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 03 18:09:02 volumio volumio[835]: SPOTIFY: BQDwyCx5NTr32RPjUygfTz7ypUPfrxrFAvUkzp-fnuIx6LIi2MH42WxHVtS570EdX8VJEjtaVml4Jd_8LoXGNv_XUjR3UfMt2YRCLSW07RfvEay-rbo17JctdJd1v7zaoas6g7hCEe0mNTWHrtKRr0y4HGUnifykNp0nYUMw3vJgxhaKzyv1K8czQ1Nt-0XQ2B0CSAsYWUFNq7I2Djoked1nfm1aen9A38KcVNqp7FgJ1XsbTqgjAEDbjVu8RKfIqDlBuCltdrcMqeDVO9qXdtzObB8 Jul 03 18:09:02 volumio volumio[835]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Jul 03 18:09:02 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 03 18:09:02 volumio sudo[1134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Jul 03 18:09:02 volumio volumio[835]: info: New Spotify access token = BQDwyCx5NTr32RPjUygfTz7ypUPfrxrFAvUkzp-fnuIx6LIi2MH42WxHVtS570EdX8VJEjtaVml4Jd_8LoXGNv_XUjR3UfMt2YRCLSW07RfvEay-rbo17JctdJd1v7zaoas6g7hCEe0mNTWHrtKRr0y4HGUnifykNp0nYUMw3vJgxhaKzyv1K8czQ1Nt-0XQ2B0CSAsYWUFNq7I2Djoked1nfm1aen9A38KcVNqp7FgJ1XsbTqgjAEDbjVu8RKfIqDlBuCltdrcMqeDVO9qXdtzObB8 Jul 03 18:09:02 volumio volumio[835]: info: Spotify credentials grant success - running version from March 24, 2019 Jul 03 18:09:02 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 03 18:09:02 volumio sudo[1134]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:02 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 03 18:09:02 volumio volumio[835]: info: Discovery: A device disappeared from network Jul 03 18:09:02 volumio volumio[835]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::volumioGetState Jul 03 18:09:02 volumio volumio[835]: info: CorePlayQueue::getTrack 0 Jul 03 18:09:02 volumio volumio[835]: info: Discovery: adding 799f1985-2b0e-445c-84c5-068762011240 Jul 03 18:09:02 volumio volumio[835]: info: Discovery: Found device Volumio Jul 03 18:09:02 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::volumioGetState Jul 03 18:09:02 volumio volumio[835]: info: CorePlayQueue::getTrack 0 Jul 03 18:09:02 volumio sudo[1127]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio sudo[1130]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Jul 03 18:09:02 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Jul 03 18:09:02 volumio systemd[1]: shairport-sync.service: Succeeded. Jul 03 18:09:02 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Jul 03 18:09:02 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Jul 03 18:09:02 volumio sudo[1134]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio volumio[835]: info: Shairport-Sync Started Jul 03 18:09:02 volumio volumio[835]: Error adding Membership: Error: addMembership EINVAL Jul 03 18:09:02 volumio volumio[835]: info: Shairport-Sync Started Jul 03 18:09:02 volumio volumio[835]: info: Discovery: this is already registered, 799f1985-2b0e-445c-84c5-068762011240 Jul 03 18:09:02 volumio volumio[835]: info: Discovery: Found device Volumio Jul 03 18:09:02 volumio ntpd[1019]: Soliciting pool server 217.160.19.219 Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::volumioGetState Jul 03 18:09:02 volumio volumio[835]: info: CorePlayQueue::getTrack 0 Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=info msg="running go-librespot 0.2.0" Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=debug msg="app state loaded" Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=info msg="api server listening on 127.0.0.1:9879" Jul 03 18:09:02 volumio volumio[835]: SPOTIFY: User informations: {"country":"DE","display_name":"Matthias Rie","email":"m.rieder@me.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/1173157703"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/1173157703","id":"1173157703","images":[{"height":300,"url":"https://scontent-cdg4-3.xx.fbcdn.net/v/t39.30808-1/463879848_9272215609474817_4571273263608457566_n.jpg?stp=c362.106.1324.1324a_dst-jpg_s320x320_tt6&_nc_cat=106&ccb=1-7&_nc_sid=79bf43&_nc_ohc=FN5xdZbqxDkQ7kNvwHCEjpe&_nc_oc=AdmT415gDf4bdQ5_EdvRbt1kJxtFbITs0E3J3Uvu5sKUJWfL_4hIgP3pZ1jYC_xu-C0x6dLksfBlJdwYZeXKxNK8&_nc_zt=24&_nc_ht=scontent-cdg4-3.xx&edm=AP4hL3IEAAAA&_nc_gid=ESaG0dvrv48H_Vu18yKCwA&oh=00_AfPBgohy88V1o0msThWTTvEKfk7Heen2Tjx07IWDC5SOGQ&oe=686C5BB4","width":300},{"height":64,"url":"https://scontent-cdg4-3.xx.fbcdn.net/v/t39.30808-1/463879848_9272215609474817_4571273263608457566_n.jpg?stp=c362.106.1324.1324a_cp0_dst-jpg_s50x50_tt6&_nc_cat=106&ccb=1-7&_nc_sid=28885b&_nc_ohc=FN5xdZbqxDkQ7kNvwHCEjpe&_nc_oc=AdmT415gDf4bdQ5_EdvRbt1kJxtFbITs0E3J3Uvu5sKUJWfL_4hIgP3pZ1jYC_xu-C0x6dLksfBlJdwYZeXKxNK8&_nc_zt=24&_nc_ht=scontent-cdg4-3.xx&edm=AP4hL3IEAAAA&_nc_gid=ESaG0dvrv48H_Vu18yKCwA&oh=00_AfN3WPMfWnOcoknrkmThvsZ6z_cLjw9qyDvgropr72igiA&oe=686C5BB4","width":64}],"product":"premium","type":"user","uri":"spotify:user:1173157703"} Jul 03 18:09:02 volumio volumio[835]: info: Spotify Successfully logged in Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Jul 03 18:09:02 volumio volumio[835]: info: [1751558942790] CoreMusicLibrary::Adding element Spotify Jul 03 18:09:02 volumio volumio[835]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Jul 03 18:09:02 volumio volumio[835]: Cannot find translation for source SoundCloud Jul 03 18:09:02 volumio volumio[835]: Cannot find translation for source Spotify Jul 03 18:09:02 volumio mpd[1038]: Jul 03 18:09 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Jul 03 18:09:02 volumio systemd[1]: Started Music Player Daemon. Jul 03 18:09:02 volumio sudo[998]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio sudo[958]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:02 volumio volumio[835]: info: Completed starting Core Plugins Jul 03 18:09:02 volumio volumio[835]: info: ------------------------------------------- Jul 03 18:09:02 volumio volumio[835]: info: ----- MyVolumio plugins startup ---- Jul 03 18:09:02 volumio volumio[835]: info: ------------------------------------------- Jul 03 18:09:02 volumio volumio[835]: info: [MyVolumio PluginManager] Fetching plans data.... Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Jul 03 18:09:02 volumio volumio[835]: error: MPD error: The expression evaluated to a falsy value: Jul 03 18:09:02 volumio volumio[835]: assert.ok(self.idling) Jul 03 18:09:02 volumio volumio[835]: error: The expression evaluated to a falsy value: Jul 03 18:09:02 volumio volumio[835]: assert.ok(self.idling) Jul 03 18:09:02 volumio volumio[835]: info: MPD running with PID1038 Jul 03 18:09:02 volumio volumio[835]: ,establishing connection Jul 03 18:09:02 volumio go-librespot[1103]: time="2025-07-03T18:09:02+02:00" level=info msg="zeroconf server listening on port 39993" Jul 03 18:09:02 volumio volumio[835]: error: MPD error: The expression evaluated to a falsy value: Jul 03 18:09:02 volumio volumio[835]: assert.ok(self.idling) Jul 03 18:09:02 volumio volumio[835]: error: The expression evaluated to a falsy value: Jul 03 18:09:02 volumio volumio[835]: assert.ok(self.idling) Jul 03 18:09:02 volumio volumio[835]: error: updateQueue error: null Jul 03 18:09:02 volumio volumio[835]: info: New access token = BQBozupOuu62LQJmMWDsuUBsELAxaL_cgItDwK9E1GJaxkWtr4iJerWXAJtlf-vxqOpdsC7EG4yxRmZ3IT7z2MknoPBlM0SLptvV3Fzi7-9XtdRiijTGABgFV9TEFLBpu2dKGglQFsZlk6nAuEvY5DmehTVQSqfGDmjdO8WVG6YDDYQ1HxInhVXKlEuYJsyPgHGMSH7hs4L_8wUMdEioYKkRcwXvYWhp3jNCJbfaDs5MfSyrXJ2zmN0cgvObUkKTJYe5bXADmJhZZsofHfNw0pC4ASU Jul 03 18:09:02 volumio systemd[1]: apt-daily.service: Succeeded. Jul 03 18:09:02 volumio systemd[1]: Started Daily apt download activities. Jul 03 18:09:02 volumio volumio[835]: info: New access token = BQCnoqFpiSFrPOWZ8G-hEsnKpXWt5eaf1eLMMlu4lRuz53CWtxvl1CsgpGEIw3oj2sEUrYZhpDwxUJ0QdwvzAgTT5C8ripCQcp20R2Yq37Znm0dfY5dJ7TwUwmLnlndjNpbCaxiDYmQnXqsz1S0o18N0so5UjU5tWrVWMKvifHMUXQmL-Wdik4-n4XrvEoGEszcD1Ixk1_yWPI0DI631vtRx_qMaz3__3ZiHVCmxFTApp2SM-FSy-jBCGmDFXLBGp3ZqbGEnjfc7gY_5TqWUqNfJz-E Jul 03 18:09:02 volumio volumio[835]: info: New access token = BQA0_TitCg5V-rZ6yLfadR6zjUXAXx4IqwZhTx0sVv7-5NRpgtJ7kIoO8ZY0jhwWc-vzUcly_AxWQEVlbwN3KeaGDVf7H79JRMSUJzWegXTYi8mvTHT0v4MVEpOontSRIxLGxsK8BKTRf5inLlQ32QecsqzyDPUZXDB1MMCUzc2aRB7vjVp3BJWz9otcVfR5Sw3P4VyUdv0zrmX7W5OctxK4azyFu1ubNNjPX7kwYEvcg3eW8JvjA9y-Xze0tmPfvcjmK39wvelhlwIFl9VwNEOAa9Y Jul 03 18:09:02 volumio nmbd[782]: [2025/07/03 18:09:02.992312, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 03 18:09:02 volumio nmbd[782]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="obtained new client token: AACgAp5bmJTAWliL8m3hn0wjYPJ6VB1ld4FaR1+Eoi6rUWHZ4AHuSKKaAZRl7epNIg06FnLH5AqgF8y+6PPk80R4jqIOaoRQ7JcF+x7x8qQH2WnSdgJthXibgV/lpEIL3fAUTDMBahrkzUP+trbpnvpCSNTNo5NgltviO+bBmazu6qiixQb1VgnRG4psOmgcQg/1wrLJQ7+AQ5GSqaoWgVQE4I4K4YsK5DINCMdjMgz792xOMPhYsAkuO4uc" Jul 03 18:09:03 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Jul 03 18:09:03 volumio systemd[1]: Started Samba NMB Daemon. Jul 03 18:09:03 volumio systemd[1]: Starting Samba Winbind Daemon... Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=warning msg="failed to connect to AP ap-gew4.spotify.com:4070, retrying with a different AP" error="dial tcp 34.158.1.133:4070: connect: connection refused" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="connected to ap-gew4.spotify.com:443" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="completed keyexchange" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="completed challenge" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=info msg="authenticated AP as 1173157703" Jul 03 18:09:03 volumio winbindd[1181]: [2025/07/03 18:09:03.248764, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Jul 03 18:09:03 volumio winbindd[1181]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Jul 03 18:09:03 volumio winbindd[1181]: [2025/07/03 18:09:03.268747, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 03 18:09:03 volumio systemd[1]: Started Samba Winbind Daemon. Jul 03 18:09:03 volumio winbindd[1181]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=info msg="authenticated Login5 as 1173157703" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="initializing zeroconf session, username: 1173157703" Jul 03 18:09:03 volumio systemd[1]: Starting Samba SMB Daemon... Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="dealer connection opened" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=trace msg="starting accesspoint recv loop" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=trace msg="starting dealer recv loop" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=trace msg="received accesspoint ping" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="received connection id: YTM5MDcxY2YtMzNiOC00ZjM1LTg1OWItMzNkY2MyMjA1MGE1K2RlYWxlcit0Y3A6Ly8wYWIxNTIwOS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQjMxNzU1QjA1M0U5ODE1RjU3OTdGREUzRTVFOEFDMjc2MjFDOEZDODczRTI0QkRFMDc1NzNENzUxM0VCQkQ4Ng==" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=trace msg="received accesspoint pong ack" Jul 03 18:09:03 volumio go-librespot[1103]: time="2025-07-03T18:09:03+02:00" level=debug msg="put connect state because NEW_DEVICE" Jul 03 18:09:03 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Jul 03 18:09:03 volumio systemd[1]: Started Daily apt upgrade and clean activities. Jul 03 18:09:03 volumio smbd[1213]: [2025/07/03 18:09:03.648821, 0] ../lib/util/become_daemon.c:138(daemon_ready) Jul 03 18:09:03 volumio systemd[1]: Started Samba SMB Daemon. Jul 03 18:09:03 volumio smbd[1213]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Jul 03 18:09:03 volumio systemd[1]: Reached target Multi-User System. Jul 03 18:09:03 volumio systemd[1]: Reached target Graphical Interface. Jul 03 18:09:03 volumio ntpd[1019]: Soliciting pool server 162.159.200.123 Jul 03 18:09:03 volumio ntpd[1019]: Soliciting pool server 217.79.189.239 Jul 03 18:09:03 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Jul 03 18:09:03 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Jul 03 18:09:03 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Jul 03 18:09:03 volumio systemd[1]: Startup finished in 11.860s (kernel) + 15.876s (userspace) = 27.736s. Jul 03 18:09:04 volumio ntpd[1019]: Soliciting pool server 185.244.195.159 Jul 03 18:09:04 volumio ntpd[1019]: Soliciting pool server 148.251.235.164 Jul 03 18:09:04 volumio ntpd[1019]: Soliciting pool server 141.144.241.16 Jul 03 18:09:05 volumio volumio[835]: info: go-librespot daemon successfully initialized Jul 03 18:09:05 volumio ntpd[1019]: Soliciting pool server 85.215.93.134 Jul 03 18:09:05 volumio ntpd[1019]: Soliciting pool server 130.162.237.177 Jul 03 18:09:05 volumio ntpd[1019]: Soliciting pool server 80.153.195.191 Jul 03 18:09:05 volumio ntpd[1019]: Soliciting pool server 194.50.19.117 Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="handling transfer player command from 0b44cd102fc77816017ecb3b0c787d2e8e369c82" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:7hVFQrPEuMjvMdl2znVyoK" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=trace msg="fetched new page 0 with 82 items (list: 82)" uri="spotify:playlist:7hVFQrPEuMjvMdl2znVyoK" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="loading track (paused: true, position: 73961ms)" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=trace msg="emitting websocket event: will_play" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="selected format OGG_VORBIS_320 (a00a04a56de1c5ffcc7b449a4d1b4afa700ac747)" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="requested aes key for file a00a04a56de1c5ffcc7b449a4d1b4afa700ac747, gid: 5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 3260" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched first chunk of 14, total size is 7254465 bytes" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 8/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 7/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 9/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="fetched chunk 6/13, size: 524288" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=trace msg="seek to 73961ms (diff: 208ms, samples: 3261680, bytes: 3305941)" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="created new output device" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=info msg="loaded track \"Amore Mio\" (paused: true, position: 73961ms, duration: 163760ms, prefetched: false)" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2074" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=trace msg="emitting websocket event: metadata" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=trace msg="emitting websocket event: active" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="sending successful reply for dealer request" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 03 18:09:06 volumio go-librespot[1103]: time="2025-07-03T18:09:06+02:00" level=trace msg="emitting websocket event: paused" Jul 03 18:09:06 volumio ntpd[1019]: Soliciting pool server 129.70.132.32 Jul 03 18:09:06 volumio ntpd[1019]: Soliciting pool server 51.75.67.47 Jul 03 18:09:06 volumio ntpd[1019]: Soliciting pool server 45.145.40.190 Jul 03 18:09:07 volumio ntpd[1019]: Soliciting pool server 176.9.157.155 Jul 03 18:09:07 volumio ntpd[1019]: Soliciting pool server 85.215.189.120 Jul 03 18:09:07 volumio volumio[835]: info: Volumio Network Manager: Network status updated: 1 Jul 03 18:09:07 volumio sudo[1257]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Jul 03 18:09:07 volumio sudo[1257]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:07 volumio sudo[1257]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:07 volumio sudo[1259]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Jul 03 18:09:07 volumio sudo[1259]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:07 volumio sudo[1259]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:07 volumio sudo[1263]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Jul 03 18:09:07 volumio sudo[1263]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 03 18:09:07 volumio volumio[835]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Jul 03 18:09:07 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Jul 03 18:09:07 volumio sudo[1263]: pam_unix(sudo:session): session closed for user root Jul 03 18:09:07 volumio volumio[835]: info: Upmpdcli Daemon Started Jul 03 18:09:08 volumio volumio[1265]: Generating RSA private key, 4096 bit long modulus (2 primes) Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=debug msg="handling resume player command from 0b44cd102fc77816017ecb3b0c787d2e8e369c82" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=trace msg="seek to 73961ms (diff: 208ms, samples: 3261680, bytes: 3305941)" uri="spotify:track:5ZK7opIgmOaOOSWyOjVG8R" Jul 03 18:09:08 volumio volumio[835]: info: Initializing connection to go-librespot Websocket Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=debug msg="new websocket client" Jul 03 18:09:08 volumio volumio[835]: info: Connection to go-librespot Websocket established Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02: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" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=debug msg="resume track at 73753ms" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=trace msg="scheduling prefetch in 60s" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=debug msg="sending successful reply for dealer request" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 03 18:09:08 volumio go-librespot[1103]: time="2025-07-03T18:09:08+02:00" level=trace msg="emitting websocket event: playing" Jul 03 18:09:08 volumio volumio[835]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:5ZK7opIgmOaOOSWyOjVG8R","play_origin":"playlist/ondemand"}} Jul 03 18:09:08 volumio volumio[835]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 03 18:09:08 volumio volumio[835]: TypeError: Cannot read property 'service' of undefined Jul 03 18:09:08 volumio volumio[835]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:340:50) Jul 03 18:09:08 volumio volumio[835]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:266:18) Jul 03 18:09:08 volumio volumio[835]: at WebSocket.message (/data/plugins/music_service/spop/index.js:193:14) Jul 03 18:09:08 volumio volumio[835]: at WebSocket.emit (events.js:315:20) Jul 03 18:09:08 volumio volumio[835]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Jul 03 18:09:08 volumio volumio[835]: at Receiver.emit (events.js:315:20) Jul 03 18:09:08 volumio volumio[835]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Jul 03 18:09:08 volumio volumio[835]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Jul 03 18:09:08 volumio volumio[835]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Jul 03 18:09:08 volumio volumio[835]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Jul 03 18:09:08 volumio volumio[835]: at writeOrBuffer (internal/streams/writable.js:358:12) Jul 03 18:09:08 volumio volumio[835]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Jul 03 18:09:08 volumio volumio[835]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Jul 03 18:09:08 volumio volumio[835]: at Socket.emit (events.js:315:20) Jul 03 18:09:08 volumio volumio[835]: at addChunk (internal/streams/readable.js:309:12) Jul 03 18:09:08 volumio volumio[835]: at readableAddChunk (internal/streams/readable.js:284:9) Jul 03 18:09:08 volumio volumio[835]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 03 18:09:08 volumio ntpd[1019]: Soliciting pool server 45.157.234.88 Jul 03 18:09:08 volumio ntpd[1019]: Soliciting pool server 2003:a:843:7c00::3 Jul 03 18:09:08 volumio sudo[1290]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-03 18:08 Jul 03 18:09:08 volumio sudo[1290]: 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="570c5791513f5bac7da274aba6690c1a961705de" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="35e4a13c94df42ebab19fd6178d6be47190c244d" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 13 May 2025 05:16:30 PM CEST" VOLUMIO_VERSION="3.812" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3934ee440d5d3f0186049a23752ad680"