-- Logs begin at Fri 2024-11-22 11:14:50 JST, end at Sun 2024-11-24 22:48:49 JST. -- Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Proxy server started on port 40655 Nov 24 22:47:00 volumio sudo[20150]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Nov 24 22:47:00 volumio sudo[20150]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::volumioRetrievevolume Nov 24 22:47:00 volumio volumio[19943]: info: CoreStateMachine::pushState Nov 24 22:47:00 volumio volumio[19943]: info: CorePlayQueue::getTrack 0 Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::volumioPushState Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Server discovery started Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Player finder started Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Nov 24 22:47:00 volumio volumio[19943]: info: Cannot mount NAS nas at system boot, trial number 2 ,retrying in 5 seconds Nov 24 22:47:00 volumio volumio[19943]: info: Discovery: adding bbb23684-8478-4de5-9ee9-f60a0d11ce0f Nov 24 22:47:00 volumio volumio[19943]: info: Discovery: Found device Volumio Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::volumioGetState Nov 24 22:47:00 volumio volumio[19943]: info: CorePlayQueue::getTrack 0 Nov 24 22:47:00 volumio volumio[19943]: info: logitechmediaserver started Nov 24 22:47:00 volumio volumio[19943]: info: MPD Permissions set Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Card 2 supports the following ALSA formats: ["S16_LE","S24_LE","S32_LE"] Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"2","mixerType":"None","mixer":null} Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Nov 24 22:47:00 volumio volumio[19943]: info: Spotify config file written Nov 24 22:47:00 volumio sudo[20168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Nov 24 22:47:00 volumio sudo[20168]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:00 volumio sudo[20168]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:00 volumio sudo[20171]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 24 22:47:00 volumio sudo[20171]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:00 volumio systemd[1]: Stopping go-librespot Daemon... Nov 24 22:47:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Nov 24 22:47:00 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Nov 24 22:47:00 volumio systemd[1]: Stopped go-librespot Daemon. Nov 24 22:47:00 volumio volumio[19943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio systemd[1]: Started go-librespot Daemon. Nov 24 22:47:00 volumio go-librespot[20175]: Librespot-go daemon starting... Nov 24 22:47:00 volumio sudo[20171]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:00 volumio go-librespot[20175]: time="2024-11-24T22:47:00+09:00" level=info msg="generated new device id: 497eebf8c88e383f4dce9de64b9ea5516c6fb09b" Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio go-librespot[20175]: time="2024-11-24T22:47:00+09:00" level=debug msg="stored credentials found for 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:00 volumio volumio[19943]: info: Volumio called home Nov 24 22:47:00 volumio volumio[19943]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Nov 24 22:47:00 volumio sudo[20150]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:00 volumio sudo[20195]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Nov 24 22:47:00 volumio sudo[20195]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:00 volumio volumio[19943]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 24 22:47:00 volumio volumio[19943]: SPOTIFY: BQByS2sTDxOra-Ykno2wHm9XVIWaF9_cgNgeSMBI_uT2RdghLqcZ4wr8W1vt5RdPL2AUrqZ-_ID5w30L2BHL5Hy8Mqu32MCK6nUTQ5o6yzn_MNRjPejQheVUfUIUrYlgnD-cvMJmrvZF2Uyq6xklP0FiE5qKRJriwuU4DF5R_wJSSXn9rUrV6lVVJXkHvgvPAzgs_s94olOug5TEVaKMvHVbj5JkYHeQ3P6PO3GFBG4b3iSDnijDxXV3n69izQ49F_E9zfNB8n2oteehjo0 Nov 24 22:47:00 volumio volumio[19943]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 24 22:47:00 volumio volumio[19943]: info: New Spotify access token = BQByS2sTDxOra-Ykno2wHm9XVIWaF9_cgNgeSMBI_uT2RdghLqcZ4wr8W1vt5RdPL2AUrqZ-_ID5w30L2BHL5Hy8Mqu32MCK6nUTQ5o6yzn_MNRjPejQheVUfUIUrYlgnD-cvMJmrvZF2Uyq6xklP0FiE5qKRJriwuU4DF5R_wJSSXn9rUrV6lVVJXkHvgvPAzgs_s94olOug5TEVaKMvHVbj5JkYHeQ3P6PO3GFBG4b3iSDnijDxXV3n69izQ49F_E9zfNB8n2oteehjo0 Nov 24 22:47:00 volumio volumio[19943]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 24 22:47:00 volumio sudo[20195]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio volumio[19943]: info: Starting Shairport Sync Nov 24 22:47:01 volumio volumio[19943]: info: Starting Shairport Sync Nov 24 22:47:01 volumio sudo[20202]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 24 22:47:01 volumio sudo[20202]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:01 volumio volumio[19943]: info: Starting Shairport Sync Nov 24 22:47:01 volumio sudo[20205]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 24 22:47:01 volumio sudo[20205]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:01 volumio go-librespot[20175]: time="2024-11-24T22:47:01+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 24 22:47:01 volumio go-librespot[20175]: time="2024-11-24T22:47:01+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 24 22:47:01 volumio go-librespot[20175]: time="2024-11-24T22:47:01+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 24 22:47:01 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 24 22:47:01 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 24 22:47:01 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 24 22:47:01 volumio volumio[19943]: info: CoreCommandRouter::volumioGetState Nov 24 22:47:01 volumio volumio[19943]: info: CorePlayQueue::getTrack 0 Nov 24 22:47:01 volumio go-librespot[20175]: time="2024-11-24T22:47:01+09:00" level=debug msg="zeroconf server listening on port 34233" Nov 24 22:47:01 volumio volumio[19943]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Nov 24 22:47:01 volumio sudo[20208]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 24 22:47:01 volumio sudo[20208]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:01 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 24 22:47:01 volumio sudo[20202]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 24 22:47:01 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 24 22:47:01 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 24 22:47:01 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 24 22:47:01 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 24 22:47:01 volumio sudo[20205]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio sudo[20200]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Nov 24 22:47:01 volumio sudo[20200]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:01 volumio sudo[20208]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio volumio[19943]: info: Shairport-Sync Started Nov 24 22:47:01 volumio volumio[19943]: Error adding Membership: Error: addMembership EINVAL Nov 24 22:47:01 volumio volumio[19943]: info: Shairport-Sync Started Nov 24 22:47:01 volumio sudo[20213]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Nov 24 22:47:01 volumio sudo[20213]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:01 volumio mpd[20101]: Nov 24 22:47 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 24 22:47:01 volumio systemd[1]: Started Music Player Daemon. Nov 24 22:47:01 volumio sudo[20069]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio sudo[20078]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio sudo[20213]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:01 volumio go-librespot[20175]: time="2024-11-24T22:47:01+09:00" level=debug msg="obtained new client token: AADkEouDoTz6TDtY/WzLxHpoZ18omI+FZdwPNQ8V8Ct2XmANx9TzKpviKJKnL+J+WG0wkgC4hjIDtlHc7Mm11bZF/2/SuehDSimuG74Pxi+2ZbXsvBhD++9lHpl31djUrZ1vmMRWcrrd79mztUPsf3CVygyfGVb4CutQmHtoiYiu7TqySQ9+/Up/AGnx9GhmwPmDJD+7QVrBWFlWnXlk3yVNYQcM7JCwURGgAS+3VWu6iypMtVtUTHufRIM=" Nov 24 22:47:01 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Nov 24 22:47:01 volumio systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Nov 24 22:47:01 volumio sudo[20228]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Nov 24 22:47:01 volumio sudo[20228]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:01 volumio volumio[19943]: info: MPD running with PID20101 Nov 24 22:47:01 volumio volumio[19943]: ,establishing connection Nov 24 22:47:01 volumio systemd[1]: Reloading. Nov 24 22:47:01 volumio volumio[19943]: error: MPD error: The expression evaluated to a falsy value: Nov 24 22:47:01 volumio volumio[19943]: assert.ok(self.idling) Nov 24 22:47:01 volumio volumio[19943]: error: The expression evaluated to a falsy value: Nov 24 22:47:01 volumio volumio[19943]: assert.ok(self.idling) Nov 24 22:47:01 volumio volumio[19943]: error: MPD error: The expression evaluated to a falsy value: Nov 24 22:47:01 volumio volumio[19943]: assert.ok(self.idling) Nov 24 22:47:01 volumio volumio[19943]: error: The expression evaluated to a falsy value: Nov 24 22:47:01 volumio volumio[19943]: assert.ok(self.idling) Nov 24 22:47:01 volumio go-librespot[20175]: time="2024-11-24T22:47:01+09:00" level=debug msg="completed keyexchange" Nov 24 22:47:01 volumio volumio[19943]: error: updateQueue error: null Nov 24 22:47:01 volumio volumio[19943]: SPOTIFY: User informations: {"country":"JP","display_name":"Shiny","email":"justice.breaker@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31ybykreksedm4kfy3cuvqv2qj2u"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31ybykreksedm4kfy3cuvqv2qj2u","id":"31ybykreksedm4kfy3cuvqv2qj2u","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85c2144647eb544652e458d9d0","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82c2144647eb544652e458d9d0","width":64}],"product":"premium","type":"user","uri":"spotify:user:31ybykreksedm4kfy3cuvqv2qj2u"} Nov 24 22:47:01 volumio volumio[19943]: info: Spotify Successfully logged in Nov 24 22:47:01 volumio volumio[19943]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 22:47:01 volumio volumio[19943]: info: [1732456021677] CoreMusicLibrary::Adding element Spotify Nov 24 22:47:01 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 22:47:01 volumio volumio[19943]: Cannot find translation for source 80s80s Radio Nov 24 22:47:01 volumio volumio[19943]: Cannot find translation for source Spotify Nov 24 22:47:01 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="completed challenge" Nov 24 22:47:02 volumio volumio[20224]: cset: --> shielding system active with Nov 24 22:47:02 volumio volumio[20224]: cset: "system" cpuset of CPUSPEC(1-3) with 125 tasks running Nov 24 22:47:02 volumio volumio[20224]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="authenticated as 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:47:02 volumio systemd[1]: /data/plugins/music_service/lms/unit/logitechmediaserver.service:7: PIDFile= references path below legacy directory /var/run/, updating /var/run/logitechmediaserver.pid → /run/logitechmediaserver.pid; please update the unit file accordingly. Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="authenticated as 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:47:02 volumio systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Nov 24 22:47:02 volumio sudo[20228]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:02 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:02 volumio systemd[1]: Reloading. Nov 24 22:47:02 volumio sudo[20262]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:02 volumio sudo[20262]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="dealer connection opened" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="initializing zeroconf session, username: 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="autoplay enabled: false" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="received connection id: MTA2Y2NkYzYtYTJkNC00ZDYwLThjMDEtZGFhNmU4MTRiNTdkK2RlYWxlcit0Y3A6Ly8wYWM5NDk4Yy5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQTYyN0MzRURFMTM1NUFGM0RBOTFGNTYyODM3RTQ4MUJGOEQ5MUI3NzczODQ3NDg1MTBENDc2M0JGQzMyQjUyNA==" Nov 24 22:47:02 volumio go-librespot[20175]: time="2024-11-24T22:47:02+09:00" level=debug msg="put connect state because NEW_DEVICE" Nov 24 22:47:02 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 24 22:47:03 volumio systemd[1]: /data/plugins/music_service/lms/unit/logitechmediaserver.service:7: PIDFile= references path below legacy directory /var/run/, updating /var/run/logitechmediaserver.pid → /run/logitechmediaserver.pid; please update the unit file accordingly. Nov 24 22:47:03 volumio sudo[20200]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:03 volumio volumio[19943]: info: succeeded Nov 24 22:47:03 volumio sudo[20262]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:03 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Nov 24 22:47:03 volumio sudo[20278]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Nov 24 22:47:03 volumio sudo[20278]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:03 volumio systemd[1]: Stopping Squeezelite lightweight headless Squeezebox emulator... Nov 24 22:47:03 volumio systemd[1]: squeezelite.service: Succeeded. Nov 24 22:47:03 volumio systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Nov 24 22:47:03 volumio sudo[20278]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:03 volumio sudo[20295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 24 22:47:03 volumio sudo[20295]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:03 volumio sudo[20295]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:03 volumio sudo[20297]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 24 22:47:03 volumio sudo[20297]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:03 volumio sudo[20297]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:03 volumio volumio[19943]: info: go-librespot daemon successfully initialized Nov 24 22:47:03 volumio sudo[20301]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 24 22:47:03 volumio sudo[20301]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:03 volumio sudo[20301]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:03 volumio volumio[19943]: info: Upmpdcli Daemon Started Nov 24 22:47:04 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:04 volumio sudo[20304]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:04 volumio sudo[20304]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:04 volumio sudo[20304]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:04 volumio volumio[19943]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Nov 24 22:47:04 volumio sudo[20308]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Nov 24 22:47:04 volumio sudo[20308]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:04 volumio sudo[20308]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:04 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Nov 24 22:47:04 volumio sudo[20311]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Nov 24 22:47:04 volumio sudo[20311]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:04 volumio systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Nov 24 22:47:04 volumio systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Nov 24 22:47:04 volumio sudo[20311]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:04 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:04 volumio sudo[20318]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:04 volumio sudo[20318]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:04 volumio sudo[20318]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:05 volumio volumio[19943]: info: Cannot mount NAS nas at system boot, trial number 3 ,retrying in 5 seconds Nov 24 22:47:05 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:05 volumio sudo[20321]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:05 volumio sudo[20321]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:05 volumio sudo[20321]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:05 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:06 volumio sudo[20324]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:06 volumio sudo[20324]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:06 volumio sudo[20324]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:06 volumio volumio[19943]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 24 22:47:06 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:06 volumio sudo[20327]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:06 volumio sudo[20327]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:06 volumio sudo[20327]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:06 volumio volumio[19943]: info: Initializing connection to go-librespot Websocket Nov 24 22:47:06 volumio go-librespot[20175]: time="2024-11-24T22:47:06+09:00" level=debug msg="new websocket client" Nov 24 22:47:06 volumio volumio[19943]: info: Connection to go-librespot Websocket established Nov 24 22:47:07 volumio volumio[19943]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:47:07 volumio sudo[20330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:47:07 volumio sudo[20330]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:07 volumio sudo[20330]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:07 volumio volumio[19943]: info: Completed starting Core Plugins Nov 24 22:47:07 volumio volumio[19943]: info: ------------------------------------------- Nov 24 22:47:07 volumio volumio[19943]: info: ----- MyVolumio plugins startup ---- Nov 24 22:47:07 volumio volumio[19943]: info: ------------------------------------------- Nov 24 22:47:07 volumio volumio[19943]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 24 22:47:09 volumio volumio[19943]: info: Getting Spotify volume Nov 24 22:47:09 volumio volumio[19943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 3 Nov 24 22:47:09 volumio volumio[19943]: info: Spotify volume: 100 Nov 24 22:47:10 volumio volumio[19943]: info: CoreCommandRouter::volumioGetState Nov 24 22:47:10 volumio volumio[19943]: info: CorePlayQueue::getTrack 0 Nov 24 22:47:10 volumio volumio[19943]: info: Cannot mount NAS nas at system boot, trial number 4 ,retrying in 5 seconds Nov 24 22:47:15 volumio volumio[19943]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Nov 24 22:47:15 volumio volumio[19943]: info: Adding plugin bluetooth to MyMusic Plugins Nov 24 22:47:15 volumio volumio[19943]: info: Adding plugin multiroom to MyMusic Plugins Nov 24 22:47:15 volumio volumio[19943]: info: Adding plugin metavolumio to MyMusic Plugins Nov 24 22:47:15 volumio volumio[19943]: info: Adding plugin cd_controller to MyMusic Plugins Nov 24 22:47:15 volumio volumio[19943]: info: Adding plugin smart_inputs to MyMusic Plugins Nov 24 22:47:15 volumio volumio[19943]: info: Adding plugin tidalconnect to MyMusic Plugins Nov 24 22:47:15 volumio volumio[19943]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Nov 24 22:47:16 volumio volumio[19943]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Nov 24 22:47:16 volumio volumio[19943]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Nov 24 22:47:16 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:16 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:16 volumio volumio[19943]: info: Starting MyVolumio Remote Streaming Endpoints Nov 24 22:47:16 volumio volumio[19943]: info: MyVolumio login type: Token Nov 24 22:47:16 volumio volumio[19943]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Nov 24 22:47:16 volumio volumio[19943]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Nov 24 22:47:17 volumio volumio[19943]: info: Starting Streaming Service Transparent Proxy Nov 24 22:47:17 volumio volumio[19943]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Nov 24 22:47:17 volumio volumio[19943]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Nov 24 22:47:17 volumio volumio[19943]: info: Streaming services startup Nov 24 22:47:17 volumio volumio[19943]: info: Starting Streaming Daemon Nov 24 22:47:17 volumio sudo[20395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 24 22:47:17 volumio sudo[20395]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:17 volumio sudo[20395]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:17 volumio volumio[19943]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Nov 24 22:47:17 volumio volumio[19943]: error: Cannot start Volumio Streaming Daemon Nov 24 22:47:17 volumio volumio[19943]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 24 22:47:17 volumio volumio[19943]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 24 22:47:18 volumio volumio[19943]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN Nov 24 22:47:18 volumio volumio[19943]: STREAMING PROXY: Starting server on port 3245 Nov 24 22:47:18 volumio volumio[19943]: Node JS runtime: 14 Nov 24 22:47:19 volumio volumio[19943]: info: MyVolumio token set successfully Nov 24 22:47:19 volumio volumio[19943]: info: MYVOLUMIO: Adding device Nov 24 22:47:19 volumio volumio[19943]: info: MYVOLUMIO: Evaluating Server Nov 24 22:47:19 volumio volumio[19943]: info: MyVolumio status changed Nov 24 22:47:19 volumio volumio[19943]: info: Streaming services startup Nov 24 22:47:19 volumio volumio[19943]: info: Starting Streaming Daemon Nov 24 22:47:19 volumio volumio[19943]: info: Removing browser output: myVolumio user plan is not superstar Nov 24 22:47:19 volumio volumio[19943]: info: Removing audio output: Nov 24 22:47:19 volumio volumio[19943]: info: Stoppping Tunnel 1 Nov 24 22:47:19 volumio sudo[20420]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Nov 24 22:47:19 volumio sudo[20420]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:19 volumio sudo[20423]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service Nov 24 22:47:19 volumio sudo[20423]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:47:19 volumio sudo[20420]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:19 volumio volumio[19943]: error: Cannot start Volumio Streaming Daemon Nov 24 22:47:19 volumio volumio[19943]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service Nov 24 22:47:19 volumio volumio[19943]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found. Nov 24 22:47:19 volumio sudo[20423]: pam_unix(sudo:session): session closed for user root Nov 24 22:47:19 volumio volumio[19943]: info: Remote SSH Stopped Nov 24 22:47:20 volumio volumio[19943]: info: Setting Geolocation for MyVolumio to as1 Nov 24 22:47:20 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:21 volumio volumio[19943]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 24 22:47:21 volumio volumio[19943]: info: Updating MyVolumio device info Nov 24 22:47:21 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:22 volumio volumio[19943]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 24 22:47:25 volumio volumio[19943]: info: MYVOLUMIO: Adding device Nov 24 22:47:25 volumio volumio[19943]: info: MYVOLUMIO: Evaluating Server Nov 24 22:47:25 volumio volumio[19943]: info: Setting Geolocation for MyVolumio to as1 Nov 24 22:47:25 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:25 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:25 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:26 volumio volumio[19943]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"} Nov 24 22:47:26 volumio volumio[19943]: info: Updating MyVolumio device info Nov 24 22:47:26 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:26 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:26 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:27 volumio volumio[19943]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"} Nov 24 22:47:29 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 22:47:29 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:29 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 24 22:47:29 volumio volumio-remote-updater[584]: No test mode Nov 24 22:47:29 volumio volumio-remote-updater[584]: No alpha test mode Nov 24 22:47:29 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled Nov 24 22:47:30 volumio volumio[19943]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} Nov 24 22:47:30 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache Nov 24 22:47:31 volumio ntpd[778]: Soliciting pool server 2606:4700:f1::1 Nov 24 22:47:31 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Nov 24 22:47:31 volumio volumio[19943]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 Nov 24 22:47:31 volumio volumio[19943]: info: CoreCommandRouter::volumioGetState Nov 24 22:47:31 volumio volumio[19943]: info: CorePlayQueue::getTrack 0 Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::volumioGetBrowseSources Nov 24 22:47:36 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 22:47:37 volumio volumio[19943]: error: MyVolumio Plugin failed to authenticate in a timely fashion Nov 24 22:47:37 volumio volumio[19943]: info: Completed starting MyVolumio Plugin Nov 24 22:47:37 volumio volumio[19943]: [Metrics] CommandRouter: 46s 212.16ms Nov 24 22:47:37 volumio volumio[19943]: info: CoreCommandRouter::volumiosetStartupVolume Nov 24 22:47:37 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:47:37 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:47:37 volumio volumio[19943]: info: CoreCommandRouter::Close All Modals sent Nov 24 22:47:37 volumio volumio[19943]: info: CoreCommandRouter::Close All Modals sent Nov 24 22:47:38 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Nov 24 22:47:38 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Nov 24 22:47:38 volumio volumio[19943]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Nov 24 22:47:44 volumio volumio[19943]: info: BOOT COMPLETED Nov 24 22:47:52 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-DISCONNECTED bssid=96:18:65:17:ee:f3 reason=0 locally_generated=1 Nov 24 22:47:52 volumio dhcpcd[924]: wlan0: carrier lost Nov 24 22:47:52 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Nov 24 22:47:52 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=JP Nov 24 22:47:52 volumio avahi-daemon[594]: Withdrawing address record for 192.168.1.229 on wlan0. Nov 24 22:47:52 volumio avahi-daemon[594]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.229. Nov 24 22:47:52 volumio dhcpcd[924]: wlan0: deleting route to 192.168.1.0/24 Nov 24 22:47:52 volumio dhcpcd[924]: wlan0: deleting default route via 192.168.1.1 Nov 24 22:47:52 volumio avahi-daemon[594]: Interface wlan0.IPv4 no longer relevant for mDNS. Nov 24 22:47:52 volumio volumio[19943]: info: Discovery: A device disappeared from network Nov 24 22:47:52 volumio volumio[19943]: info: Discovery: Device volumio disappeared from network Nov 24 22:47:52 volumio nmbd[754]: [2024/11/24 22:47:52.895206, 0] ../source3/libsmb/nmblib.c:917(send_udp) Nov 24 22:47:52 volumio nmbd[754]: Packet send failed to 192.168.1.255(137) ERRNO=Network is unreachable Nov 24 22:47:52 volumio nmbd[754]: [2024/11/24 22:47:52.895516, 0] ../source3/nmbd/nmbd_packets.c:1639(retransmit_or_expire_response_records) Nov 24 22:47:52 volumio nmbd[754]: retransmit_or_expire_response_records: Failed to resend packet id 14421 to IP 192.168.1.255 on subnet 192.168.1.229 Nov 24 22:47:52 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air-ABABA_2.4GHz' Nov 24 22:47:53 volumio nmbd[754]: [2024/11/24 22:47:53.896536, 0] ../source3/libsmb/nmblib.c:917(send_udp) Nov 24 22:47:53 volumio nmbd[754]: Packet send failed to 192.168.1.255(138) ERRNO=Network is unreachable Nov 24 22:47:53 volumio volumio[19943]: info: Volumio Network Manager: Network status updated: 0 Nov 24 22:47:54 volumio ntpd[778]: Deleting interface #6 wlan0, 192.168.1.229#123, interface stats: received=30, sent=30, dropped=0, active_time=59 secs Nov 24 22:47:54 volumio ntpd[778]: 162.159.200.1 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 172.105.240.243 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 45.76.218.37 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 202.181.103.212 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 133.243.238.243 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 160.16.113.133 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 45.76.211.39 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 167.179.119.205 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 172.105.204.105 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 45.77.20.103 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 133.243.238.163 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 108.160.132.224 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 122.215.240.51 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 129.250.35.250 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 133.130.121.141 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio ntpd[778]: 162.159.200.123 local addr 192.168.1.229 -> Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: carrier acquired Nov 24 22:47:54 volumio wpa_supplicant[912]: wlan0: Associated with 96:18:65:17:ee:f3 Nov 24 22:47:54 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-CONNECTED - Connection to 96:18:65:17:ee:f3 completed [id=0 id_str=] Nov 24 22:47:54 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Nov 24 22:47:54 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=JP Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: IAID eb:bb:88:44 Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: carrier lost Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: carrier acquired Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: IAID eb:bb:88:44 Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: rebinding lease of 192.168.1.229 Nov 24 22:47:54 volumio dhcpcd[924]: wlan0: probing address 192.168.1.229/24 Nov 24 22:47:55 volumio dhcpcd[924]: wlan0: soliciting an IPv6 router Nov 24 22:47:59 volumio dhcpcd[924]: wlan0: leased 192.168.1.229 for 86400 seconds Nov 24 22:47:59 volumio avahi-daemon[594]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.229. Nov 24 22:47:59 volumio avahi-daemon[594]: New relevant interface wlan0.IPv4 for mDNS. Nov 24 22:47:59 volumio dhcpcd[924]: wlan0: adding route to 192.168.1.0/24 Nov 24 22:47:59 volumio avahi-daemon[594]: Registering new address record for 192.168.1.229 on wlan0.IPv4. Nov 24 22:47:59 volumio dhcpcd[924]: wlan0: adding default route via 192.168.1.1 Nov 24 22:48:00 volumio volumio[19943]: info: Discovery: adding bbb23684-8478-4de5-9ee9-f60a0d11ce0f Nov 24 22:48:00 volumio volumio[19943]: info: Discovery: Found device Volumio Nov 24 22:48:00 volumio volumio[19943]: info: CoreCommandRouter::volumioGetState Nov 24 22:48:00 volumio volumio[19943]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:01 volumio ntpd[778]: Listen normally on 7 wlan0 192.168.1.229:123 Nov 24 22:48:01 volumio ntpd[778]: new interface(s) found: waking up resolver Nov 24 22:48:03 volumio volumio[19943]: info: Volumio Network Manager: Network status updated: 2 Nov 24 22:48:10 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-DISCONNECTED bssid=96:18:65:17:ee:f3 reason=0 locally_generated=1 Nov 24 22:48:10 volumio dhcpcd[924]: wlan0: carrier lost Nov 24 22:48:10 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD Nov 24 22:48:10 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=USER type=COUNTRY alpha2=JP Nov 24 22:48:11 volumio avahi-daemon[594]: Withdrawing address record for 192.168.1.229 on wlan0. Nov 24 22:48:11 volumio avahi-daemon[594]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.229. Nov 24 22:48:11 volumio dhcpcd[924]: wlan0: deleting route to 192.168.1.0/24 Nov 24 22:48:11 volumio dhcpcd[924]: wlan0: deleting default route via 192.168.1.1 Nov 24 22:48:11 volumio avahi-daemon[594]: Interface wlan0.IPv4 no longer relevant for mDNS. Nov 24 22:48:11 volumio volumio[19943]: info: Discovery: A device disappeared from network Nov 24 22:48:11 volumio volumio[19943]: info: Discovery: Device volumio disappeared from network Nov 24 22:48:11 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air-ABABA_2.4GHz' Nov 24 22:48:13 volumio ntpd[778]: Deleting interface #7 wlan0, 192.168.1.229#123, interface stats: received=18, sent=18, dropped=0, active_time=12 secs Nov 24 22:48:13 volumio ntpd[778]: 172.105.240.243 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 45.76.218.37 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 202.181.103.212 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 133.243.238.243 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 160.16.113.133 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 45.76.211.39 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 167.179.119.205 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 172.105.204.105 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 45.77.20.103 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 133.243.238.163 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 108.160.132.224 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 122.215.240.51 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 129.250.35.250 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 133.130.121.141 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 162.159.200.123 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio ntpd[778]: 162.159.200.1 local addr 192.168.1.229 -> Nov 24 22:48:13 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=00:00:00:00:00:00 status_code=16 Nov 24 22:48:13 volumio volumio[19943]: info: Volumio Network Manager: Network status updated: 0 Nov 24 22:48:14 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air_Guest' Nov 24 22:48:18 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=96:18:65:27:ee:f3 status_code=16 Nov 24 22:48:19 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air_Guest' Nov 24 22:48:22 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=96:18:65:27:ee:f3 status_code=16 Nov 24 22:48:22 volumio ntpd[778]: error resolving pool 0.debian.pool.ntp.org: System error (-11) Nov 24 22:48:23 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air-ABABA_2.4GHz' Nov 24 22:48:23 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=96:18:65:27:ee:f3 status_code=16 Nov 24 22:48:24 volumio dhcpcd[924]: wlan0: carrier acquired Nov 24 22:48:24 volumio dhcpcd[924]: wlan0: IAID eb:bb:88:44 Nov 24 22:48:24 volumio dhcpcd[924]: wlan0: soliciting an IPv6 router Nov 24 22:48:24 volumio dhcpcd[924]: wlan0: rebinding lease of 192.168.1.229 Nov 24 22:48:25 volumio dhcpcd[924]: wlan0: probing address 192.168.1.229/24 Nov 24 22:48:25 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air-ABABA_2.4GHz' Nov 24 22:48:25 volumio dhcpcd[924]: wlan0: carrier lost Nov 24 22:48:27 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-ASSOC-REJECT bssid=96:18:65:17:ee:f3 status_code=16 Nov 24 22:48:29 volumio wpa_supplicant[912]: wlan0: Trying to associate with SSID 'Air-ABABA_2.4GHz' Nov 24 22:48:30 volumio volumio[19943]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 22:48:30 volumio volumio[19943]: Error: send ENETUNREACH 255.255.255.255:3483 Nov 24 22:48:30 volumio volumio[19943]: at doSend (dgram.js:692:16) Nov 24 22:48:30 volumio volumio[19943]: at defaultTriggerAsyncIdScope (internal/async_hooks.js:430:12) Nov 24 22:48:30 volumio volumio[19943]: at afterDns (dgram.js:638:5) Nov 24 22:48:30 volumio volumio[19943]: at processTicksAndRejections (internal/process/task_queues.js:81:21) { Nov 24 22:48:30 volumio volumio[19943]: errno: -101, Nov 24 22:48:30 volumio volumio[19943]: code: 'ENETUNREACH', Nov 24 22:48:30 volumio volumio[19943]: syscall: 'send', Nov 24 22:48:30 volumio volumio[19943]: address: '255.255.255.255', Nov 24 22:48:30 volumio volumio[19943]: port: 3483 Nov 24 22:48:30 volumio volumio[19943]: } Nov 24 22:48:30 volumio volumio[19943]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 22:48:30 volumio sudo[20732]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-24 22:47 Nov 24 22:48:30 volumio sudo[20732]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:30 volumio sudo[20732]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:30 volumio volumio-remote-updater[584]: [2024-11-24 22:48:30] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Nov 24 22:48:30 volumio volumio-remote-updater[584]: [2024-11-24 22:48:30] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Nov 24 22:48:30 volumio go-librespot[20175]: time="2024-11-24T22:48:30+09:00" level=error msg="websocket connection errored" error="failed to get reader: failed to read frame header: EOF" Nov 24 22:48:30 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Nov 24 22:48:30 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Nov 24 22:48:31 volumio systemd[1]: Started dynamicswap service. Nov 24 22:48:31 volumio wpa_supplicant[912]: wlan0: Associated with 96:18:65:17:ee:f3 Nov 24 22:48:31 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-CONNECTED - Connection to 96:18:65:17:ee:f3 completed [id=0 id_str=] Nov 24 22:48:31 volumio dhcpcd[924]: wlan0: carrier acquired Nov 24 22:48:31 volumio systemd[1]: dynamicswap.service: Succeeded. Nov 24 22:48:31 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-SUBNET-STATUS-UPDATE status=0 Nov 24 22:48:31 volumio wpa_supplicant[912]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=JP Nov 24 22:48:31 volumio dhcpcd[924]: wlan0: IAID eb:bb:88:44 Nov 24 22:48:31 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Nov 24 22:48:31 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 4. Nov 24 22:48:31 volumio systemd[1]: Stopped Volumio Backend Module. Nov 24 22:48:31 volumio dhcpcd[924]: wlan0: soliciting an IPv6 router Nov 24 22:48:31 volumio systemd[1]: Started Volumio Backend Module. Nov 24 22:48:31 volumio systemd[1]: Started dynamicswap service. Nov 24 22:48:31 volumio systemd[1]: dynamicswap.service: Succeeded. Nov 24 22:48:31 volumio ntpd[778]: error resolving pool 1.debian.pool.ntp.org: System error (-11) Nov 24 22:48:31 volumio dhcpcd[924]: wlan0: rebinding lease of 192.168.1.229 Nov 24 22:48:31 volumio dhcpcd[924]: wlan0: probing address 192.168.1.229/24 Nov 24 22:48:33 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:33 volumio volumio[20746]: info: ----- Volumio3 ---- Nov 24 22:48:33 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:33 volumio volumio[20746]: info: ----- System startup ---- Nov 24 22:48:33 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:33 volumio volumio[20746]: info: MYVOLUMIO Environment detected Nov 24 22:48:33 volumio volumio[20746]: info: Plugin folders cleanup Nov 24 22:48:33 volumio volumio[20746]: info: Scanning into folder /volumio/app/plugins/ Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category audio_interface Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category miscellanea Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category music_service Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category plugins.json Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category system_controller Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category user_interface Nov 24 22:48:33 volumio volumio[20746]: info: Scanning into folder /data/plugins/ Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category music_service Nov 24 22:48:33 volumio volumio[20746]: info: Scanning category system_hardware Nov 24 22:48:33 volumio volumio[20746]: info: Plugin folders cleanup completed Nov 24 22:48:33 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:33 volumio volumio[20746]: info: ----- Core plugins startup ---- Nov 24 22:48:33 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:33 volumio volumio[20746]: info: Loading plugins from folder /volumio/app/plugins/ Nov 24 22:48:33 volumio volumio[20746]: info: Adding plugin upnp to MyMusic Plugins Nov 24 22:48:33 volumio volumio[20746]: info: Adding plugin airplay_emulation to MyMusic Plugins Nov 24 22:48:33 volumio volumio[20746]: info: Adding plugin upnp_browser to MyMusic Plugins Nov 24 22:48:33 volumio volumio[20746]: info: Loading plugins from folder /data/plugins/ Nov 24 22:48:33 volumio volumio[20746]: info: Loading plugin "system"... Nov 24 22:48:34 volumio volumio[20746]: info: Loading plugin "appearance"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "network"... Nov 24 22:48:35 volumio volumio[20746]: info: Refreshing Cached IP Addresses Nov 24 22:48:35 volumio sudo[20777]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 24 22:48:35 volumio sudo[20777]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:35 volumio sudo[20777]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:35 volumio sudo[20779]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 24 22:48:35 volumio sudo[20779]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:35 volumio sudo[20779]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "services"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "alsa_controller"... Nov 24 22:48:35 volumio sudo[20789]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Nov 24 22:48:35 volumio sudo[20789]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:35 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "wizard"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "networkfs"... Nov 24 22:48:35 volumio volumio[20746]: info: Cannot mount NAS nas at system boot, trial number 1 ,retrying in 5 seconds Nov 24 22:48:35 volumio volumio[20746]: info: Starting Udev Watcher for removable devices Nov 24 22:48:35 volumio volumio[20746]: info: Ignoring mount for partition: boot Nov 24 22:48:35 volumio volumio[20746]: info: Ignoring mount for partition: volumio Nov 24 22:48:35 volumio volumio[20746]: info: Ignoring mount for partition: volumio_data Nov 24 22:48:35 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "volumio_command_line_client"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "upnp"... Nov 24 22:48:35 volumio volumio[20746]: info: [1732456115285] Starting Upmpd Daemon Nov 24 22:48:35 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "my_music"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "mpd"... Nov 24 22:48:35 volumio volumio[20746]: info: Plugin upnp_browser is not enabled Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "alarm-clock"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "airplay_emulation"... Nov 24 22:48:35 volumio volumio[20746]: info: Starting Shairport Sync Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "last_100"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "webradio"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "i2s_dacs"... Nov 24 22:48:35 volumio volumio[20746]: info: Loading plugin "volumiodiscovery"... Nov 24 22:48:35 volumio volumio-remote-updater[584]: [2024-11-24 22:48:35] [connect] Successful connection Nov 24 22:48:36 volumio volumio[20746]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 24 22:48:36 volumio volumio[20746]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 22:48:36 volumio volumio[20746]: *** WARNING *** For more information see Nov 24 22:48:36 volumio volumio[20746]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 24 22:48:36 volumio node[20746]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Nov 24 22:48:36 volumio volumio[20746]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 22:48:36 volumio volumio[20746]: *** WARNING *** For more information see Nov 24 22:48:36 volumio node[20746]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 22:48:36 volumio node[20746]: *** WARNING *** For more information see Nov 24 22:48:36 volumio node[20746]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Nov 24 22:48:36 volumio node[20746]: *** WARNING *** Please fix your application to use the native API of Avahi! Nov 24 22:48:36 volumio node[20746]: *** WARNING *** For more information see Nov 24 22:48:36 volumio volumio[20746]: info: Applying required configuration parameters for plugin volumiodiscovery Nov 24 22:48:36 volumio volumio[20746]: info: Discovery: Started advertising with name: Volumio Nov 24 22:48:36 volumio sudo[20789]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:36 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Nov 24 22:48:36 volumio volumio[20746]: info: Loading plugin "spop"... Nov 24 22:48:36 volumio dhcpcd[924]: wlan0: leased 192.168.1.229 for 86400 seconds Nov 24 22:48:36 volumio avahi-daemon[594]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.1.229. Nov 24 22:48:36 volumio avahi-daemon[594]: New relevant interface wlan0.IPv4 for mDNS. Nov 24 22:48:36 volumio dhcpcd[924]: wlan0: adding route to 192.168.1.0/24 Nov 24 22:48:36 volumio avahi-daemon[594]: Registering new address record for 192.168.1.229 on wlan0.IPv4. Nov 24 22:48:36 volumio dhcpcd[924]: wlan0: adding default route via 192.168.1.1 Nov 24 22:48:37 volumio volumio[20746]: info: Loading plugin "squeezelite_mc"... Nov 24 22:48:37 volumio ntpd[778]: Soliciting pool server 2406:da14:10c4:9aa0:123:: Nov 24 22:48:37 volumio ntpd[778]: Listen normally on 8 wlan0 192.168.1.229:123 Nov 24 22:48:37 volumio ntpd[778]: new interface(s) found: waking up resolver Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "outputs"... Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "albumart"... Nov 24 22:48:38 volumio volumio[20746]: info: Plugin example_plugin is not enabled Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "inputs"... Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "updater_comm"... Nov 24 22:48:38 volumio volumio[20746]: info: Plugin mpdemulation is not enabled Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "rest_api"... Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "websocket"... Nov 24 22:48:38 volumio volumio[20746]: info: Starting Socket.io Server version 2.3.0 Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "80s80s"... Nov 24 22:48:38 volumio volumio[20746]: Forking 3 albumart workers Nov 24 22:48:38 volumio volumio[20746]: info: Applying required configuration parameters for plugin 80s80s Nov 24 22:48:38 volumio volumio[20746]: info: [1732456118605] [80s80s] API delay: 30 Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "lms"... Nov 24 22:48:38 volumio volumio[20746]: info: Loading plugin "music_services_shield"... Nov 24 22:48:39 volumio volumio[20746]: info: Applying required configuration parameters for plugin music_services_shield Nov 24 22:48:39 volumio volumio[20746]: info: Loading i18n strings for locale en Nov 24 22:48:39 volumio volumio[20746]: Updating browse sources language Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::initPlayerControls Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: Express server listening on port 3000 Nov 24 22:48:39 volumio volumio[20746]: [Metrics] WebUI: 7s 30.05ms Nov 24 22:48:39 volumio volumio[20746]: Starting albumart workers Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::resetVolumioState Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::getcurrentVolume Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::volumioRetrievevolume Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::pushState Nov 24 22:48:39 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::volumioPushState Nov 24 22:48:39 volumio volumio[20746]: info: Volumio Network Manager: Network status updated: 0 Nov 24 22:48:39 volumio volumio-remote-updater[584]: [2024-11-24 22:48:39] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732456115 101 Nov 24 22:48:39 volumio volumio[20746]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 1 Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:39 volumio volumio[20746]: info: Setting Device type: Raspberry PI Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::setRepeat null single undefined Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::pushState Nov 24 22:48:39 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::volumioPushState Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::setRandom null Nov 24 22:48:39 volumio volumio[20746]: info: CoreStateMachine::pushState Nov 24 22:48:39 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:39 volumio volumio[20746]: info: CoreCommandRouter::volumioPushState Nov 24 22:48:40 volumio volumio[20746]: info: USB Boot Capable - Checking Install to Disk functions for: bootusb Nov 24 22:48:40 volumio volumio[20746]: info: USB Boot Capable - System SBC Revision found in cpuinfo: a22082 Nov 24 22:48:40 volumio volumio[20746]: info: USB Boot Capable - Found matching device in SBC capable list: Raspberry PI Nov 24 22:48:40 volumio volumio[20746]: info: Completed loading Core Plugins Nov 24 22:48:40 volumio volumio[20746]: info: Preparing to generate the ALSA configuration file Nov 24 22:48:40 volumio volumio[20746]: info: Asound.conf file unchanged, so no further update is needed Nov 24 22:48:40 volumio volumio[20746]: info: Output device has changed, restarting MPD Nov 24 22:48:40 volumio volumio[20746]: Starting albumart workers Nov 24 22:48:40 volumio volumio[20746]: info: Output device has changed, restarting Shairport Sync Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:40 volumio sudo[20864]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 24 22:48:40 volumio sudo[20864]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:40 volumio sudo[20864]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:40 volumio sudo[20866]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 24 22:48:40 volumio sudo[20866]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:40 volumio volumio[20746]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 24 22:48:40 volumio systemd[1]: musicservicesshield.service: Succeeded. Nov 24 22:48:40 volumio volumio[20746]: info: ___________ START PLUGINS ___________ Nov 24 22:48:40 volumio systemd[1]: Stopped Shield Volumio Music Services in the User CPU Set. Nov 24 22:48:40 volumio systemd[1]: Stopping Shield Volumio Music Services in the User CPU Set... Nov 24 22:48:40 volumio systemd[1]: Stopping Music Player Daemon... Nov 24 22:48:40 volumio volumio[20746]: info: ControllerMpd::onStart: Initializing MPD Nov 24 22:48:40 volumio volumio[20746]: info: Creating MPD Configuration file Nov 24 22:48:40 volumio systemd[1]: mpd.service: Succeeded. Nov 24 22:48:40 volumio systemd[1]: Stopped Music Player Daemon. Nov 24 22:48:40 volumio sudo[20873]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:40 volumio sudo[20873]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:40 volumio systemd[1]: Starting Music Player Daemon... Nov 24 22:48:40 volumio sudo[20873]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:40 volumio sudo[20876]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 24 22:48:40 volumio sudo[20876]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:40 volumio volumio[20746]: Starting albumart workers Nov 24 22:48:40 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Nov 24 22:48:40 volumio systemd[1]: mpd.service: Succeeded. Nov 24 22:48:40 volumio systemd[1]: Stopped Music Player Daemon. Nov 24 22:48:40 volumio systemd[1]: Starting Music Player Daemon... Nov 24 22:48:40 volumio volumio[20746]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:40 volumio ntpd[778]: 172.105.204.105 local addr 192.168.1.229 -> Nov 24 22:48:40 volumio sudo[20886]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 24 22:48:40 volumio sudo[20886]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:40 volumio sudo[20886]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:40 volumio volumio[20746]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 22:48:40 volumio volumio[20746]: info: [1732456120658] CoreMusicLibrary::Adding element Last_100 Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 22:48:40 volumio volumio[20746]: info: [1732456120665] CoreMusicLibrary::Adding element Webradio Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 22:48:40 volumio volumio[20746]: info: Initializing BBC Radios Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:40 volumio volumio[20746]: info: Creating Spotify config file Nov 24 22:48:40 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Starting proxy server... Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 22:48:41 volumio volumio[20746]: info: [1732456121208] CoreMusicLibrary::Adding element 80s80s Radio Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 22:48:41 volumio volumio[20746]: Cannot find translation for source 80s80s Radio Nov 24 22:48:41 volumio sudo[20917]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Nov 24 22:48:41 volumio sudo[20917]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:41 volumio systemd[1]: Starting Logitech Media Server Daemon... Nov 24 22:48:41 volumio systemd[1]: Started Logitech Media Server Daemon. Nov 24 22:48:41 volumio systemd[20941]: logitechmediaserver.service: Failed to execute command: No such file or directory Nov 24 22:48:41 volumio systemd[20941]: logitechmediaserver.service: Failed at step EXEC spawning /usr/sbin/squeezeboxserver: No such file or directory Nov 24 22:48:41 volumio sudo[20917]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:41 volumio systemd[1]: logitechmediaserver.service: Main process exited, code=exited, status=203/EXEC Nov 24 22:48:41 volumio systemd[1]: logitechmediaserver.service: Failed with result 'exit-code'. Nov 24 22:48:41 volumio volumio[20746]: info: Volumio Calling Home Nov 24 22:48:41 volumio sudo[20955]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/moveallprocesses.sh Nov 24 22:48:41 volumio sudo[20955]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Proxy server started on port 38325 Nov 24 22:48:41 volumio go-librespot[20175]: time="2024-11-24T22:48:41+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 24 22:48:41 volumio go-librespot[20175]: time="2024-11-24T22:48:41+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::volumioRetrievevolume Nov 24 22:48:41 volumio go-librespot[20175]: time="2024-11-24T22:48:41+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 24 22:48:41 volumio volumio[20746]: info: CoreStateMachine::pushState Nov 24 22:48:41 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::volumioPushState Nov 24 22:48:41 volumio go-librespot[20175]: time="2024-11-24T22:48:41+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1732" Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Server discovery started Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Player finder started Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Executing aplay -D hw:2 --nonblock -f MPEG /dev/zero 2>&1 || true Nov 24 22:48:41 volumio volumio[20746]: info: Cannot mount NAS nas at system boot, trial number 2 ,retrying in 5 seconds Nov 24 22:48:41 volumio volumio[20746]: info: Discovery: adding bbb23684-8478-4de5-9ee9-f60a0d11ce0f Nov 24 22:48:41 volumio volumio[20746]: info: Discovery: Found device Volumio Nov 24 22:48:41 volumio volumio[20746]: info: CoreCommandRouter::volumioGetState Nov 24 22:48:41 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:41 volumio volumio[20746]: info: logitechmediaserver started Nov 24 22:48:41 volumio volumio[20746]: info: MPD Permissions set Nov 24 22:48:41 volumio volumio[20746]: info: MPD Permissions set Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Card 2 supports the following ALSA formats: ["S16_LE","S24_LE","S32_LE"] Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Starting Squeezelite service with params: {"type":"basic","playerName":"volumio","dsdFormat":null,"card":"2","mixerType":"None","mixer":null} Nov 24 22:48:41 volumio volumio[20746]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Nov 24 22:48:41 volumio volumio[20746]: info: Spotify config file written Nov 24 22:48:42 volumio sudo[20977]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 24 22:48:42 volumio sudo[20977]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio systemd[1]: Stopping go-librespot Daemon... Nov 24 22:48:42 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Nov 24 22:48:42 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Nov 24 22:48:42 volumio systemd[1]: Stopped go-librespot Daemon. Nov 24 22:48:42 volumio systemd[1]: Started go-librespot Daemon. Nov 24 22:48:42 volumio volumio[20746]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 24 22:48:42 volumio go-librespot[20979]: Librespot-go daemon starting... Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio sudo[20977]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=info msg="generated new device id: 22ad7c46db51dea648299767f25407baf0bbe3d3" Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="stored credentials found for 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:48:42 volumio sudo[20975]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/alsa/100-squeezelite.conf.template.out /etc/alsa/conf.d/100-squeezelite.conf Nov 24 22:48:42 volumio sudo[20975]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio sudo[20975]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 24 22:48:42 volumio volumio[20746]: info: Volumio called home Nov 24 22:48:42 volumio volumio[20746]: info: [squeezelite_mc] Executing alsactl -L -R nrestore Nov 24 22:48:42 volumio sudo[20955]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio volumio[20746]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 24 22:48:42 volumio volumio[20746]: SPOTIFY: BQCkrwYsJt-LpemmTPT2ih3zOUmiruvLsTJTdD4NhEm38QbGozIUg7DnHF8-mfwi_gM30OwJ2ZT1c3OPt1uo3BKva7IYB-Px8qTPo-KtZbjHSDBodH8qkH_aX76aeQ_zU50-EHWnrQCubX9EHqpxdmReOSoszNBWdPqlY4MYsdlXEFiYL4BBMa11-KAhbw629vo5L-GA2o6pTVeIQXZjI-rvu4Wh02ofirtTy2AhPs2NSOmcPCMr8uLLH-OyCQDWGCMN29B_Z4FU4ydg8o8 Nov 24 22:48:42 volumio volumio[20746]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 24 22:48:42 volumio volumio[20746]: info: New Spotify access token = BQCkrwYsJt-LpemmTPT2ih3zOUmiruvLsTJTdD4NhEm38QbGozIUg7DnHF8-mfwi_gM30OwJ2ZT1c3OPt1uo3BKva7IYB-Px8qTPo-KtZbjHSDBodH8qkH_aX76aeQ_zU50-EHWnrQCubX9EHqpxdmReOSoszNBWdPqlY4MYsdlXEFiYL4BBMa11-KAhbw629vo5L-GA2o6pTVeIQXZjI-rvu4Wh02ofirtTy2AhPs2NSOmcPCMr8uLLH-OyCQDWGCMN29B_Z4FU4ydg8o8 Nov 24 22:48:42 volumio volumio[20746]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 24 22:48:42 volumio sudo[21003]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/sbin/alsactl -L -R nrestore Nov 24 22:48:42 volumio sudo[21003]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]" Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="zeroconf server listening on port 41613" Nov 24 22:48:42 volumio sudo[21003]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio volumio[20746]: info: Starting Shairport Sync Nov 24 22:48:42 volumio volumio[20746]: info: Starting Shairport Sync Nov 24 22:48:42 volumio sudo[21009]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 24 22:48:42 volumio sudo[21009]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio volumio[20746]: info: Starting Shairport Sync Nov 24 22:48:42 volumio sudo[21012]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 24 22:48:42 volumio sudo[21012]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="obtained new client token: AADx1HAHCqhSpAkEUnV+MtEKMhOQkw0X30bK90qbR/jsGJkteoLRekt8jyCARkRE/8b3TMHllHU4JVjMd1TDEkTmJCVZrWyZ8fwvXLBnf/5dhoTm4Q3KxDQcytPOvAWiBsglFUFcdjDwfpkjdT0vC4DJCXpWfTOdOv4uaMESNU75Zddi1CbMmIaTH8kdCYAI5NiqwjHzGqAqk8Ekb/C6Bc1B8w2H3H99bsadCw58CHdIsfzOnXAuL6ZdeD8=" Nov 24 22:48:42 volumio volumio[20746]: info: CoreCommandRouter::volumioGetState Nov 24 22:48:42 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:42 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 24 22:48:42 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 24 22:48:42 volumio volumio[20746]: info: [squeezelite_mc] Executing cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Nov 24 22:48:42 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 24 22:48:42 volumio sudo[21007]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/data/plugins/system_hardware/music_services_shield/addservice.sh Nov 24 22:48:42 volumio mpd[20895]: Nov 24 22:48 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 24 22:48:42 volumio sudo[21007]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 24 22:48:42 volumio sudo[21015]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 24 22:48:42 volumio sudo[21015]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio systemd[1]: Started Music Player Daemon. Nov 24 22:48:42 volumio sudo[20876]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio go-librespot[20979]: time="2024-11-24T22:48:42+09:00" level=debug msg="completed keyexchange" Nov 24 22:48:42 volumio sudo[20866]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio sudo[21009]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio sudo[21012]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 24 22:48:42 volumio systemd[1]: Starting Shield Volumio Music Services in the User CPU Set... Nov 24 22:48:42 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 24 22:48:42 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 24 22:48:42 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 24 22:48:42 volumio sudo[21015]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio sudo[21022]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/cp /data/plugins/music_service/squeezelite_mc/dist/lib/../templates/systemd/squeezelite.service.template.out /etc/systemd/system/squeezelite.service Nov 24 22:48:42 volumio sudo[21022]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:42 volumio sudo[21022]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:42 volumio volumio[20746]: info: Shairport-Sync Started Nov 24 22:48:42 volumio volumio[20746]: Error adding Membership: Error: addMembership EINVAL Nov 24 22:48:42 volumio volumio[20746]: info: Shairport-Sync Started Nov 24 22:48:42 volumio volumio[20746]: info: Shairport-Sync Started Nov 24 22:48:43 volumio volumio[20746]: error: MPD error: The expression evaluated to a falsy value: Nov 24 22:48:43 volumio volumio[20746]: assert.ok(self.idling) Nov 24 22:48:43 volumio volumio[20746]: error: The expression evaluated to a falsy value: Nov 24 22:48:43 volumio volumio[20746]: assert.ok(self.idling) Nov 24 22:48:43 volumio volumio[20746]: info: MPD running with PID20895 Nov 24 22:48:43 volumio volumio[20746]: ,establishing connection Nov 24 22:48:43 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl daemon-reload || true Nov 24 22:48:43 volumio volumio[20746]: error: updateQueue error: null Nov 24 22:48:43 volumio sudo[21049]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Nov 24 22:48:43 volumio sudo[21049]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:43 volumio systemd[1]: Reloading. Nov 24 22:48:43 volumio volumio[20746]: error: updateQueue error: null Nov 24 22:48:43 volumio volumio[20746]: SPOTIFY: User informations: {"country":"JP","display_name":"Shiny","email":"justice.breaker@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31ybykreksedm4kfy3cuvqv2qj2u"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31ybykreksedm4kfy3cuvqv2qj2u","id":"31ybykreksedm4kfy3cuvqv2qj2u","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee85c2144647eb544652e458d9d0","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b82c2144647eb544652e458d9d0","width":64}],"product":"premium","type":"user","uri":"spotify:user:31ybykreksedm4kfy3cuvqv2qj2u"} Nov 24 22:48:43 volumio volumio[20746]: info: Spotify Successfully logged in Nov 24 22:48:43 volumio volumio[20746]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 24 22:48:43 volumio volumio[20746]: info: [1732456123149] CoreMusicLibrary::Adding element Spotify Nov 24 22:48:43 volumio volumio[20746]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 24 22:48:43 volumio volumio[20746]: Cannot find translation for source 80s80s Radio Nov 24 22:48:43 volumio volumio[20746]: Cannot find translation for source Spotify Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="completed challenge" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="authenticated as 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="authenticated as 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="dealer connection opened" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="initializing zeroconf session, username: 31ybykreksedm4kfy3cuvqv2qj2u" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="autoplay enabled: false" Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="received connection id: MjcwNDg5NjctOWZhOC00NWI5LTk0NWItMGQ4YjQyNWM2YjdhK2RlYWxlcit0Y3A6Ly8wYWM5NDk0My5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArM0JGQzQ4OUE3QzQ0OUZBNzUwODRFM0I3MUYzMzIwNjFEM0Q5QjhDQThGNkI2NzhCMkFCOTJGRTQxOUY0OEZBQg==" Nov 24 22:48:43 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 24 22:48:43 volumio volumio[21033]: cset: --> shielding system active with Nov 24 22:48:43 volumio volumio[21033]: cset: "system" cpuset of CPUSPEC(1-3) with 125 tasks running Nov 24 22:48:43 volumio volumio[21033]: cset: "user" cpuset of CPUSPEC(0) with 3 tasks running Nov 24 22:48:43 volumio go-librespot[20979]: time="2024-11-24T22:48:43+09:00" level=debug msg="put connect state because NEW_DEVICE" Nov 24 22:48:43 volumio systemd[1]: /data/plugins/music_service/lms/unit/logitechmediaserver.service:7: PIDFile= references path below legacy directory /var/run/, updating /var/run/logitechmediaserver.pid → /run/logitechmediaserver.pid; please update the unit file accordingly. Nov 24 22:48:44 volumio systemd[1]: Started Shield Volumio Music Services in the User CPU Set. Nov 24 22:48:44 volumio sudo[21049]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:44 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:44 volumio systemd[1]: Reloading. Nov 24 22:48:44 volumio sudo[21072]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:44 volumio sudo[21072]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:44 volumio systemd[1]: /lib/systemd/system/winbind.service:8: PIDFile= references path below legacy directory /var/run/, updating /var/run/samba/winbindd.pid → /run/samba/winbindd.pid; please update the unit file accordingly. Nov 24 22:48:44 volumio systemd[1]: /data/plugins/music_service/lms/unit/logitechmediaserver.service:7: PIDFile= references path below legacy directory /var/run/, updating /var/run/logitechmediaserver.pid → /run/logitechmediaserver.pid; please update the unit file accordingly. Nov 24 22:48:45 volumio sudo[21007]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio volumio[20746]: info: succeeded Nov 24 22:48:45 volumio sudo[21072]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl stop squeezelite || true Nov 24 22:48:45 volumio sudo[21088]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop squeezelite Nov 24 22:48:45 volumio sudo[21088]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio systemd[1]: Stopping Squeezelite lightweight headless Squeezebox emulator... Nov 24 22:48:45 volumio volumio[20746]: info: Volumio Network Manager: Network status updated: 2 Nov 24 22:48:45 volumio systemd[1]: squeezelite.service: Succeeded. Nov 24 22:48:45 volumio systemd[1]: Stopped Squeezelite lightweight headless Squeezebox emulator. Nov 24 22:48:45 volumio sudo[21088]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio sudo[21105]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 24 22:48:45 volumio sudo[21105]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio sudo[21105]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio sudo[21107]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 24 22:48:45 volumio sudo[21107]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio sudo[21107]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio sudo[21111]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 24 22:48:45 volumio sudo[21111]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio sudo[21111]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio volumio[20746]: info: Upmpdcli Daemon Started Nov 24 22:48:45 volumio volumio[20746]: info: go-librespot daemon successfully initialized Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="handling transfer player command from 4c7e02ecacaf0a5506a5a40720e2e46cf6928da1" Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="resolved context of track" uri="spotify:user:31ybykreksedm4kfy3cuvqv2qj2u:collection" Nov 24 22:48:45 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=trace msg="fetched new page 0 with 1266 items (list: 1266)" uri="spotify:user:31ybykreksedm4kfy3cuvqv2qj2u:collection" Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="shuffled context with seed 16790563299887103921 (len: 1266, keep: 41)" Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="loading track (paused: false, position: 4239ms)" uri="spotify:track:4hBkq8YlxcgfdFybN03hjf" Nov 24 22:48:45 volumio sudo[21114]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:45 volumio sudo[21114]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio sudo[21114]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio volumio[20746]: info: [squeezelite_mc] Executing rm /tmp/squeezelite.log Nov 24 22:48:45 volumio sudo[21118]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/rm /tmp/squeezelite.log Nov 24 22:48:45 volumio sudo[21118]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=trace msg="emitting websocket event: will_play" Nov 24 22:48:45 volumio sudo[21118]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:45 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl start squeezelite || true Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 24 22:48:45 volumio sudo[21121]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start squeezelite Nov 24 22:48:45 volumio sudo[21121]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="selected format OGG_VORBIS_320 (61ae5d7fa9730f251a26d616353e448dc2f390dd)" uri="spotify:track:4hBkq8YlxcgfdFybN03hjf" Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="requested aes key for file 61ae5d7fa9730f251a26d616353e448dc2f390dd, gid: 4hBkq8YlxcgfdFybN03hjf" Nov 24 22:48:45 volumio go-librespot[20979]: time="2024-11-24T22:48:45+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1694" Nov 24 22:48:45 volumio systemd[1]: Starting Squeezelite lightweight headless Squeezebox emulator... Nov 24 22:48:46 volumio systemd[1]: Started Squeezelite lightweight headless Squeezebox emulator. Nov 24 22:48:46 volumio sudo[21121]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:46 volumio go-librespot[20979]: time="2024-11-24T22:48:46+09:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1291" Nov 24 22:48:46 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:46 volumio sudo[21128]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:46 volumio sudo[21128]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:46 volumio sudo[21128]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:46 volumio volumio[20746]: info: Cannot mount NAS nas at system boot, trial number 3 ,retrying in 5 seconds Nov 24 22:48:47 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:47 volumio sudo[21131]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:47 volumio sudo[21131]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:47 volumio sudo[21131]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:47 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:47 volumio sudo[21134]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:47 volumio sudo[21134]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:47 volumio sudo[21134]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:47 volumio volumio[20746]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 24 22:48:48 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:48 volumio sudo[21137]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:48 volumio sudo[21137]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:48 volumio sudo[21137]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:48 volumio volumio[20746]: info: Initializing connection to go-librespot Websocket Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="new websocket client" Nov 24 22:48:48 volumio volumio[20746]: info: Connection to go-librespot Websocket established Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="fetched first chunk of 25, total size is 12750000 bytes" uri="spotify:track:4hBkq8YlxcgfdFybN03hjf" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=trace msg="seek to 4239ms (diff: 148ms, samples: 186939, bytes: 148364)" uri="spotify:track:4hBkq8YlxcgfdFybN03hjf" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="created new output device" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=info msg="loaded track \"FINAL DISTANCE\" (paused: false, position: 4239ms, duration: 338493ms, prefetched: false)" uri="spotify:track:4hBkq8YlxcgfdFybN03hjf" Nov 24 22:48:48 volumio volumio[20746]: info: [squeezelite_mc] Executing /usr/bin/sudo /bin/systemctl status squeezelite || true Nov 24 22:48:48 volumio sudo[21140]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl status squeezelite Nov 24 22:48:48 volumio sudo[21140]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 24 22:48:48 volumio sudo[21140]: pam_unix(sudo:session): session closed for user root Nov 24 22:48:48 volumio volumio[20746]: info: Completed starting Core Plugins Nov 24 22:48:48 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:48 volumio volumio[20746]: info: ----- MyVolumio plugins startup ---- Nov 24 22:48:48 volumio volumio[20746]: info: ------------------------------------------- Nov 24 22:48:48 volumio volumio[20746]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=trace msg="scheduling prefetch in 304s" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=trace msg="emitting websocket event: metadata" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=trace msg="emitting websocket event: active" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="sending successful reply for dealer request" Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 24 22:48:48 volumio go-librespot[20979]: time="2024-11-24T22:48:48+09:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 24 22:48:48 volumio volumio[20746]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4hBkq8YlxcgfdFybN03hjf","name":"FINAL DISTANCE","artist_names":["Hikaru Utada"],"album_name":"DEEP RIVER","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02b8ae5963d06963607272f19d","position":4239,"duration":338493,"release_date":"year:2002 month:6 day:19","track_number":10,"disc_number":1}} Nov 24 22:48:48 volumio volumio[20746]: SPOTIFY: received: {"type":"active","data":null} Nov 24 22:48:48 volumio volumio[20746]: info: Aligning Spotify Volume to Volumio Volume Nov 24 22:48:48 volumio volumio[20746]: info: CoreCommandRouter::volumioGetState Nov 24 22:48:48 volumio volumio[20746]: info: CorePlayQueue::getTrack 0 Nov 24 22:48:49 volumio go-librespot[20979]: time="2024-11-24T22:48:49+09:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 24 22:48:49 volumio go-librespot[20979]: time="2024-11-24T22:48:49+09:00" level=trace msg="emitting websocket event: playing" Nov 24 22:48:49 volumio volumio[20746]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4hBkq8YlxcgfdFybN03hjf","play_origin":"your_library"}} Nov 24 22:48:49 volumio volumio[20746]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 22:48:49 volumio volumio[20746]: TypeError: Cannot read property 'service' of undefined Nov 24 22:48:49 volumio volumio[20746]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 24 22:48:49 volumio volumio[20746]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) Nov 24 22:48:49 volumio volumio[20746]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 24 22:48:49 volumio volumio[20746]: at WebSocket.emit (events.js:315:20) Nov 24 22:48:49 volumio volumio[20746]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 24 22:48:49 volumio volumio[20746]: at Receiver.emit (events.js:315:20) Nov 24 22:48:49 volumio volumio[20746]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 24 22:48:49 volumio volumio[20746]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 24 22:48:49 volumio volumio[20746]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 24 22:48:49 volumio volumio[20746]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 24 22:48:49 volumio volumio[20746]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 24 22:48:49 volumio sudo[21152]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-24 22:47 Nov 24 22:48:49 volumio sudo[21152]: 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="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"