-- Logs begin at Sun 2024-04-14 14:23:07 CST, end at Sun 2024-04-14 15:12:59 CST. -- Apr 14 15:11:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 66. Apr 14 15:11:00 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:00 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:00 volumio go-librespot[13250]: Librespot-go daemon starting... Apr 14 15:11:00 volumio go-librespot[13250]: time="2024-04-14T15:11:00+08:00" level=info msg="generated new device id: eb555e598de6bc62af0b68c456fb8a90e135d2af" Apr 14 15:11:00 volumio go-librespot[13250]: time="2024-04-14T15:11:00+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:00 volumio volumio[13107]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 7 Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:00 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 14 15:11:00 volumio volumio[13107]: info: Received Get System Info Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 14 15:11:00 volumio volumio[13107]: info: Discovery: Getting this device information Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:00 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:00 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:00 volumio volumio[13107]: info: Listing playlists Apr 14 15:11:00 volumio volumio[13107]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:11:00 volumio volumio[13107]: info: CoreStateMachine::getQueue Apr 14 15:11:00 volumio volumio[13107]: info: CorePlayQueue::getQueue Apr 14 15:11:01 volumio go-librespot[13250]: time="2024-04-14T15:11:01+08:00" level=debug msg="obtained new client token: AACsDpPD5TxcpBhPzdVBKaZYLYxj2GmZF7o0pv14oEnkZXKYZCLIM4c0cooy200aJpZ3BoUhooXnq/R8KW2CO4ixbxG/ciCjbR3rzBYakeA29eCp1JmN3LATJ3kOUMhQdFxvEx6RVVqeEDCTjv/7FmXGsRqUd0/VGUQK/n7+uH4a2yPgv0Bk6nO1D+RO8QPxVl1JUCS0NubMmtMf3UFinjjSDVt+Fc8oWNJPTdhNpcVnkIMYF6+qZUhx6xyFsQ==" Apr 14 15:11:02 volumio go-librespot[13250]: time="2024-04-14T15:11:02+08: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]" Apr 14 15:11:02 volumio volumio-remote-updater[517]: [2024-04-14 15:11:02] [connect] Successful connection Apr 14 15:11:02 volumio volumio-remote-updater[517]: [2024-04-14 15:11:02] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1713078662 101 Apr 14 15:11:02 volumio volumio[13107]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 8 Apr 14 15:11:02 volumio go-librespot[13250]: time="2024-04-14T15:11:02+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:02 volumio go-librespot[13250]: time="2024-04-14T15:11:02+08:00" level=debug msg="completed challenge" Apr 14 15:11:03 volumio go-librespot[13250]: time="2024-04-14T15:11:03+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 67. Apr 14 15:11:06 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:06 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:06 volumio go-librespot[13261]: Librespot-go daemon starting... Apr 14 15:11:06 volumio go-librespot[13261]: time="2024-04-14T15:11:06+08:00" level=info msg="generated new device id: 944c4bf635c43f9b984583d29ef983eb47685629" Apr 14 15:11:06 volumio go-librespot[13261]: time="2024-04-14T15:11:06+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:07 volumio go-librespot[13261]: time="2024-04-14T15:11:07+08:00" level=debug msg="obtained new client token: AAApvNs3EYvvHV8XiZcKIzkmPgVWlBOWOkBrZPkliKWqRWFlfHKHNFWSzbN+zFPm4osbNQD/CDOybFSQMw6nSYjiJYyng+0H1wokX75L9FPm+lms17mX+rzo+2yjT2oMHyVKkCj1hXtaFtkkbqrIjgArlhzcfevOMr/Bbs4aFZwqb9DOAyntc0Im0UZje5A2E3dmRIIEMs2WhkppQ/vJ7N5OwpU4K1ryubRH1OhZCfNJGS8l/k/5Zo/mgFnqL//o" Apr 14 15:11:07 volumio go-librespot[13261]: time="2024-04-14T15:11:07+08: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]" Apr 14 15:11:07 volumio go-librespot[13261]: time="2024-04-14T15:11:07+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:08 volumio go-librespot[13261]: time="2024-04-14T15:11:08+08:00" level=debug msg="completed challenge" Apr 14 15:11:08 volumio go-librespot[13261]: time="2024-04-14T15:11:08+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 68. Apr 14 15:11:11 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:11 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:11 volumio go-librespot[13270]: Librespot-go daemon starting... Apr 14 15:11:11 volumio go-librespot[13270]: time="2024-04-14T15:11:11+08:00" level=info msg="generated new device id: 67d94fcde0e7f6d8a0d414940e1bcb48f44538ba" Apr 14 15:11:11 volumio go-librespot[13270]: time="2024-04-14T15:11:11+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:12 volumio go-librespot[13270]: time="2024-04-14T15:11:12+08:00" level=debug msg="obtained new client token: AAApr5yMcOGvuBQCSIHyhWFvKqf5vYnglXaeYUaviaJhFhWTYXCgRZoCeTv7twCZpY6Uc0iClebVyeuIpOyNBlaQqa9b4VeB4ImDGFPHqLVwHvvlSyQgyzft1juvpO6ijBFnYvvixwFgQK9sZblP+0tlXbs11mm2rJVrAr+dCLw0jrBWTgcYUohMc5ODIOEmREW0bW4Nl9AZ0AVdK0nKYzJazV6I7xq9C7IxWVApA64X1Nx3eXSf9O5g9oIyiw==" Apr 14 15:11:12 volumio go-librespot[13270]: time="2024-04-14T15:11:12+08: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:11:12 volumio go-librespot[13270]: time="2024-04-14T15:11:12+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:13 volumio go-librespot[13270]: time="2024-04-14T15:11:13+08:00" level=debug msg="completed challenge" Apr 14 15:11:13 volumio go-librespot[13270]: time="2024-04-14T15:11:13+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:13 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:13 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:16 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:16 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 69. Apr 14 15:11:16 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:16 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:16 volumio go-librespot[13278]: Librespot-go daemon starting... Apr 14 15:11:16 volumio go-librespot[13278]: time="2024-04-14T15:11:16+08:00" level=info msg="generated new device id: 500ea79c80a72cdfc3cfcf607484c686c948fb8b" Apr 14 15:11:16 volumio go-librespot[13278]: time="2024-04-14T15:11:16+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:17 volumio go-librespot[13278]: time="2024-04-14T15:11:17+08:00" level=debug msg="obtained new client token: AAAmCJoR6NVdYFdXRVfHYGohYbMzElZBVd9GWOe0y+8PUzeK/TMqjTKOCXDYW3M+KdmWa+t8Ewxdqm+vU3eQqjxfQktRTqJf9m5opA0/Jy2dlLUnBu6+FlmCbWa/UZKXoAfjuKZ2QGvvxQEYFjDA2579JWAfyiSh/mVsuQAC98JEwE4814mfqT8MtKMzTiNjSEg978SHNavL7k4HuhalFZUyg5dRD4Wy7QIHfMcH09gljDv8FxWsuO/DnNWM7God" Apr 14 15:11:17 volumio go-librespot[13278]: time="2024-04-14T15:11:17+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:11:18 volumio go-librespot[13278]: time="2024-04-14T15:11:18+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:18 volumio go-librespot[13278]: time="2024-04-14T15:11:18+08:00" level=debug msg="completed challenge" Apr 14 15:11:18 volumio go-librespot[13278]: time="2024-04-14T15:11:18+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:18 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:18 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:21 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:21 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 70. Apr 14 15:11:21 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:21 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:21 volumio go-librespot[13286]: Librespot-go daemon starting... Apr 14 15:11:21 volumio go-librespot[13286]: time="2024-04-14T15:11:21+08:00" level=info msg="generated new device id: 0b574c7c05e1efcd6bdc6578198151ebfd009661" Apr 14 15:11:21 volumio go-librespot[13286]: time="2024-04-14T15:11:21+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:22 volumio go-librespot[13286]: time="2024-04-14T15:11:22+08:00" level=debug msg="obtained new client token: AABGe3Wylli8X6FX1JlrENFjAzD3za8z1iNACfMs0nBKBSsvjEuypDgCnMj/Er1pGv5GVz2tg5wcU0oNjDryNkrMYJAGYEDl/mxJantghEN84UhwIyeRnY7YwEc7Tu29RqUVn81Ic1kyOiYEfguilQ1Nl3OP2K5C1zzzZiPmrHmGyJyBVy9crY2fvpOA72URLFAZ7bph7+x4f3z41I7hUsp/p1C+fhPEW87Bpx01eZBKqhuJYMbZXrpboeTiBNmf" Apr 14 15:11:22 volumio go-librespot[13286]: time="2024-04-14T15:11:22+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:11:23 volumio go-librespot[13286]: time="2024-04-14T15:11:23+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:23 volumio go-librespot[13286]: time="2024-04-14T15:11:23+08:00" level=debug msg="completed challenge" Apr 14 15:11:23 volumio go-librespot[13286]: time="2024-04-14T15:11:23+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:25 volumio volumio[13107]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion Apr 14 15:11:25 volumio volumio[13107]: info: Preparing to generate the ALSA configuration file Apr 14 15:11:25 volumio volumio[13107]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Apr 14 15:11:25 volumio volumio[13107]: info: The plugin peppy_screensaver has an ALSA contribution file Peppyalsa.postPeppyalsa.5.conf Apr 14 15:11:25 volumio volumio[13107]: info: Reading ALSA contributions from plugins. Apr 14 15:11:25 volumio volumio[13107]: info: Asound.conf file unchanged, so no further update is needed Apr 14 15:11:25 volumio volumio[13107]: info: Output device has changed, restarting MPD Apr 14 15:11:25 volumio sudo[13295]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 14 15:11:25 volumio sudo[13295]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:25 volumio sudo[13295]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:25 volumio volumio[13107]: info: Output device has changed, restarting Shairport Sync Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:25 volumio sudo[13299]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 14 15:11:25 volumio sudo[13299]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:25 volumio systemd[1]: Stopping Music Player Daemon... Apr 14 15:11:25 volumio systemd[1]: mpd.service: Succeeded. Apr 14 15:11:25 volumio systemd[1]: Stopped Music Player Daemon. Apr 14 15:11:25 volumio volumio[13107]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:11:25 volumio volumio[13107]: info: ___________ START PLUGINS ___________ Apr 14 15:11:25 volumio volumio[13107]: info: ControllerMpd::onStart: Initializing MPD Apr 14 15:11:25 volumio volumio[13107]: info: Creating MPD Configuration file Apr 14 15:11:25 volumio systemd[1]: Starting Music Player Daemon... Apr 14 15:11:25 volumio sudo[13306]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 14 15:11:25 volumio sudo[13306]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:25 volumio sudo[13306]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:11:25 volumio volumio[13107]: info: [1713078685752] CoreMusicLibrary::Adding element 媒体服务器 Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:25 volumio sudo[13309]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 14 15:11:25 volumio sudo[13309]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:25 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Apr 14 15:11:25 volumio systemd[1]: mpd.service: Succeeded. Apr 14 15:11:25 volumio systemd[1]: Stopped Music Player Daemon. Apr 14 15:11:25 volumio systemd[1]: Starting Music Player Daemon... Apr 14 15:11:25 volumio volumio[13107]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:25 volumio volumio[13107]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:11:25 volumio volumio[13107]: info: [1713078685905] CoreMusicLibrary::Adding element Last_100 Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:11:25 volumio volumio[13107]: info: [1713078685909] CoreMusicLibrary::Adding element Webradio Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:11:25 volumio volumio[13107]: info: Creating Spotify config file Apr 14 15:11:25 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: AutoStart - onStart Apr 14 15:11:26 volumio volumio[13107]: info: [now-playing] ConfigUpdater: config is up to date. Apr 14 15:11:26 volumio volumio[13107]: info: Loading i18n strings for locale zh Apr 14 15:11:26 volumio volumio[13107]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Apr 14 15:11:26 volumio volumio[13107]: info: /tmp/myfifo created Apr 14 15:11:26 volumio sudo[13321]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd-dummy index=7 pcm_substreams=1 Apr 14 15:11:26 volumio sudo[13321]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio sudo[13321]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:26 volumio volumio[13107]: info: snd-dummy loaded Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startShairportSync Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:11:26 volumio volumio[13107]: info: [1713078686245] CoreMusicLibrary::Adding element 80s80s Radio Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:26 volumio volumio[13107]: Cannot find translation for source 80s80s Radio Apr 14 15:11:26 volumio sudo[13327]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Apr 14 15:11:26 volumio sudo[13327]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:11:26 volumio sudo[13327]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:26 volumio volumio[13107]: info: [1713078686329] CoreMusicLibrary::Adding element Podcast Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:26 volumio volumio[13107]: Cannot find translation for source 80s80s Radio Apr 14 15:11:26 volumio volumio[13107]: Cannot find translation for source Podcast Apr 14 15:11:26 volumio volumio[13107]: info: Loading i18n strings for locale zh Apr 14 15:11:26 volumio sudo[13330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Apr 14 15:11:26 volumio sudo[13330]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio volumio[13107]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:11:26 volumio volumio[13107]: info: Volumio Calling Home Apr 14 15:11:26 volumio systemd[1]: Starting Logitech Media Server Daemon... Apr 14 15:11:26 volumio systemd[1]: Started Logitech Media Server Daemon. Apr 14 15:11:26 volumio systemd[13337]: logitechmediaserver.service: Failed to execute command: No such file or directory Apr 14 15:11:26 volumio systemd[13337]: logitechmediaserver.service: Failed at step EXEC spawning /usr/sbin/squeezeboxserver: No such file or directory Apr 14 15:11:26 volumio sudo[13330]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:26 volumio systemd[1]: logitechmediaserver.service: Main process exited, code=exited, status=203/EXEC Apr 14 15:11:26 volumio systemd[1]: logitechmediaserver.service: Failed with result 'exit-code'. Apr 14 15:11:26 volumio sudo[13339]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Apr 14 15:11:26 volumio sudo[13339]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio systemd[1]: Reloading. Apr 14 15:11:26 volumio volumio[13107]: info: [now-playing] App is listening on port 4004. Apr 14 15:11:26 volumio mpd[13312]: Apr 14 15:11 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 14 15:11:26 volumio volumio[13107]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:26 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:26 volumio volumio[13107]: info: logitechmediaserver started Apr 14 15:11:26 volumio volumio[13107]: info: MPD Permissions set Apr 14 15:11:26 volumio volumio[13107]: info: MPD Permissions set Apr 14 15:11:26 volumio volumio[13107]: info: Spotify config file written Apr 14 15:11:26 volumio sudo[13344]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 14 15:11:26 volumio sudo[13344]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio volumio[13107]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:26 volumio volumio[13107]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Apr 14 15:11:26 volumio volumio[13107]: info: Starting Shairport Sync Apr 14 15:11:26 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. Apr 14 15:11:26 volumio volumio[13107]: info: Starting Shairport Sync Apr 14 15:11:26 volumio sudo[13368]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:11:26 volumio sudo[13368]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio volumio[13107]: info: Starting Shairport Sync Apr 14 15:11:26 volumio sudo[13371]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:11:26 volumio sudo[13371]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:26 volumio volumio[13107]: info: Starting Shairport Sync Apr 14 15:11:26 volumio sudo[13374]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:11:26 volumio sudo[13374]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:27 volumio sudo[13377]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:11:27 volumio sudo[13377]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:27 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:27 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:27 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. Apr 14 15:11:27 volumio systemd[1]: Started Music Player Daemon. Apr 14 15:11:27 volumio sudo[13339]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio sudo[13309]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:27 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 71. Apr 14 15:11:27 volumio sudo[13299]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio volumio[13107]: info: touch_display: systemctl daemon-reload succeeded. Apr 14 15:11:27 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 14 15:11:27 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:27 volumio sudo[13382]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Apr 14 15:11:27 volumio sudo[13382]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:27 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:27 volumio volumio[13107]: info: MPD running with PID13312 Apr 14 15:11:27 volumio volumio[13107]: ,establishing connection Apr 14 15:11:27 volumio go-librespot[13383]: Librespot-go daemon starting... Apr 14 15:11:27 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 14 15:11:27 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 14 15:11:27 volumio sudo[13344]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio sudo[13382]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio volumio[13107]: error: MPD error: The expression evaluated to a falsy value: Apr 14 15:11:27 volumio volumio[13107]: assert.ok(self.idling) Apr 14 15:11:27 volumio volumio[13107]: error: The expression evaluated to a falsy value: Apr 14 15:11:27 volumio volumio[13107]: assert.ok(self.idling) Apr 14 15:11:27 volumio go-librespot[13383]: time="2024-04-14T15:11:27+08:00" level=info msg="generated new device id: 34023370014480c572611deca341e996e7e4466a" Apr 14 15:11:27 volumio go-librespot[13383]: time="2024-04-14T15:11:27+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:27 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 14 15:11:27 volumio sudo[13371]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio volumio[13107]: error: MPD error: The expression evaluated to a falsy value: Apr 14 15:11:27 volumio volumio[13107]: assert.ok(self.idling) Apr 14 15:11:27 volumio volumio[13107]: error: The expression evaluated to a falsy value: Apr 14 15:11:27 volumio volumio[13107]: assert.ok(self.idling) Apr 14 15:11:27 volumio volumio[13107]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Apr 14 15:11:27 volumio volumio[13107]: info: touch_display: Volumio Kiosk started Apr 14 15:11:27 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:27 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:27 volumio sudo[13374]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio sudo[13368]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio sudo[13377]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:27 volumio volumio[13107]: error: updateQueue error: null Apr 14 15:11:27 volumio volumio[13107]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:27 volumio volumio[13107]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:27 volumio volumio[13107]: info: Shairport-Sync Started Apr 14 15:11:27 volumio volumio[13107]: Error adding Membership: Error: addMembership EINVAL Apr 14 15:11:27 volumio volumio[13107]: info: Shairport-Sync Started Apr 14 15:11:27 volumio volumio[13107]: info: Shairport-Sync Started Apr 14 15:11:27 volumio volumio[13107]: info: Shairport-Sync Started Apr 14 15:11:27 volumio volumio[13107]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 14 15:11:27 volumio volumio[13107]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 14 15:11:27 volumio volumio[13107]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 14 15:11:27 volumio volumio[13107]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 14 15:11:27 volumio volumio[13107]: SPOTIFY: BQDlHYdVFxRC3M0L2BufDv2f2QTInPr_4ufr7Vcp9jbb_m7EhgOc624HTjCJTYsmNmPDKshhxEBeKVZvzyQHkBYKxwhhm8ZpvulF6rYeuPClvAHcMwdHtMTDuxpCe1WoC0yYYg_Auv9Luv549Tk1X__A2I4M7HOKf-7cG6m5VvVFIcBfwjVoW3xtSGCse81zRehVy_ubRmZiihMNK_0DjrrSUvVVsk0gClVPUW5a57sv4TzK95B-QpDNaOsnJ6gHpjdbE4o Apr 14 15:11:27 volumio volumio[13107]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 14 15:11:27 volumio volumio[13107]: info: New Spotify access token = BQDlHYdVFxRC3M0L2BufDv2f2QTInPr_4ufr7Vcp9jbb_m7EhgOc624HTjCJTYsmNmPDKshhxEBeKVZvzyQHkBYKxwhhm8ZpvulF6rYeuPClvAHcMwdHtMTDuxpCe1WoC0yYYg_Auv9Luv549Tk1X__A2I4M7HOKf-7cG6m5VvVFIcBfwjVoW3xtSGCse81zRehVy_ubRmZiihMNK_0DjrrSUvVVsk0gClVPUW5a57sv4TzK95B-QpDNaOsnJ6gHpjdbE4o Apr 14 15:11:27 volumio volumio[13107]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 14 15:11:28 volumio volumio[13107]: info: Volumio called home Apr 14 15:11:28 volumio go-librespot[13383]: time="2024-04-14T15:11:28+08:00" level=debug msg="obtained new client token: AADPgSr6VPsrtjAxbj+2S6/CDIM5LxyNEBsIj78WHJlLu8SC7mHcsvROx41Z4skBeDXeEnfcMUx/DjdqFxRaIctld3o5STUZ0fuzljrHxcWt0vOv60X88CkiBUt0AZ3WRHpNAAqU29N2Nito/lpkMwQ2YVjSd1xujkJHWFmvqdSGIa/FjpJPE/8YMIqwdXoT9Ko/CTYe6c3Z6uCAXjlzvPKn/+klC5RQhMdr6nR/EVfzhUS5QHIUbpouvKstLg==" Apr 14 15:11:28 volumio volumio[13107]: SPOTIFY: User informations: {"display_name":"邱瑞华","external_urls":{"spotify":"https://open.spotify.com/user/31dd2kulom3iljqxj6iee4jqblee"},"href":"https://api.spotify.com/v1/users/31dd2kulom3iljqxj6iee4jqblee","id":"31dd2kulom3iljqxj6iee4jqblee","images":[],"type":"user","uri":"spotify:user:31dd2kulom3iljqxj6iee4jqblee","followers":{"href":null,"total":0},"country":"US","product":"free","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"466223606@qq.com"} Apr 14 15:11:28 volumio volumio[13107]: info: Spotify Successfully logged in Apr 14 15:11:28 volumio volumio[13107]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:11:28 volumio volumio[13107]: info: [1713078688707] CoreMusicLibrary::Adding element Spotify Apr 14 15:11:28 volumio volumio[13107]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:28 volumio volumio[13107]: Cannot find translation for source 80s80s Radio Apr 14 15:11:28 volumio volumio[13107]: Cannot find translation for source Podcast Apr 14 15:11:28 volumio volumio[13107]: Cannot find translation for source Spotify Apr 14 15:11:28 volumio go-librespot[13383]: time="2024-04-14T15:11:28+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:11:28 volumio go-librespot[13383]: time="2024-04-14T15:11:28+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:29 volumio go-librespot[13383]: time="2024-04-14T15:11:29+08:00" level=debug msg="completed challenge" Apr 14 15:11:29 volumio go-librespot[13383]: time="2024-04-14T15:11:29+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:29 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:29 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:30 volumio volumio[13107]: info: go-librespot daemon successfully initialized Apr 14 15:11:30 volumio volumio[13107]: info: Preload queue cleared Apr 14 15:11:30 volumio volumio[13107]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 14 15:11:30 volumio volumio[13107]: info: CoreStateMachine::ClearQueue Apr 14 15:11:30 volumio volumio[13107]: info: CoreStateMachine::stop Apr 14 15:11:30 volumio volumio[13107]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:11:30 volumio volumio[13107]: info: CorePlayQueue::clearPlayQueue Apr 14 15:11:30 volumio volumio[13107]: info: CorePlayQueue::saveQueue Apr 14 15:11:30 volumio volumio[13107]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:11:30 volumio volumio[13107]: info: CoreStateMachine::addQueueItems Apr 14 15:11:30 volumio volumio[13107]: info: CorePlayQueue::addQueueItems Apr 14 15:11:30 volumio volumio[13107]: info: Preload queue cleared Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/c8，大峡谷..mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/天堂庾澄庆.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/天堂庾澄庆.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/春泥庾澄庆.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/春泥庾澄庆.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/三国庾澄庆.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/三国庾澄庆.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/梦回唐朝.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/梦回唐朝.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/潇洒的走.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/潇洒的走.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/长城.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/长城.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/c彩云伴海鸥.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/c彩云伴海鸥.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/何映达-薇拉.wma Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/何映达-薇拉.wma in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01] Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01] in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/王杰 Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/王杰 in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: Adding Item to queue: music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3) Apr 14 15:11:30 volumio volumio[13107]: info: Exploding uri music-library/USB/A27B-C06F/蔡琴.-.[民歌蔡琴].专辑.(MP3) in service mpd Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%C3%84%C3%A1%C2%B9%C3%85%C3%80%C2%AD%C3%8B%C2%B9.%C2%B9%C3%85%C2%B6%C3%B7//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2Fc8%EF%BC%8C%E5%A4%A7%E5%B3%A1%E8%B0%B7..mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E5%A4%A9%E5%A0%82%E5%BA%BE%E6%BE%84%E5%BA%86.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/天堂庾澄庆.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%A2%81%E5%B1%B1%E4%BC%AF%E4%B8%8E%E6%9C%B1%E4%B8%BD%E5%8F%B6-%E6%9B%B9%E6%A0%BC.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/梁山伯与朱丽叶-曹格.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%C3%A2%C3%97%C2%B3%C3%8E%C3%87%C3%AC/%C2%B9%C3%BE%C3%81%C3%96%C3%8C%C3%AC%C3%8C%C3%83/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%98%A5%E6%B3%A5%E5%BA%BE%E6%BE%84%E5%BA%86.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/春泥庾澄庆.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%C3%A2%C3%97%C2%B3%C3%8E%C3%87%C3%AC/%C2%B9%C3%BE%C3%81%C3%96%C3%8C%C3%AC%C3%8C%C3%83/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E4%B8%89%E5%9B%BD%E5%BA%BE%E6%BE%84%E5%BA%86.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/三国庾澄庆.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%C3%8C%C3%86%C2%B3%C2%AF%C3%80%C3%96%C2%B6%C3%93/%C3%83%C3%8E%C2%BB%C3%98%C3%8C%C3%86%C2%B3%C2%AF/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%A2%A6%E5%9B%9E%E5%94%90%E6%9C%9D.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/梦回唐朝.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%C2%B8%C3%9F%C3%8A%C2%A4%C3%83%C3%80/%C3%A4%C3%AC%C3%88%C3%B7%C2%B5%C3%84%C3%97%C3%9F/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E6%BD%87%E6%B4%92%E7%9A%84%E8%B5%B0.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/潇洒的走.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=http%3A%2F%2Fwww.uptu.com%20-%20Beyond/Beyond%20%C2%B3%C2%AC%C3%94%C2%BD%20Beyond%20Live%2003/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E9%95%BF%E5%9F%8E.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/长城.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%C2%B8%C3%9F%C3%8A%C2%A4%C3%83%C3%80/%C3%8D%C2%B8%C3%83%C3%B7%C3%93%C3%AA%C2%B9%C2%A4%C3%97%C3%B7%C3%8A%C3%92/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2Fc%E5%BD%A9%E4%BA%91%E4%BC%B4%E6%B5%B7%E9%B8%A5.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/c彩云伴海鸥.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=michael%20jackson/qQ%2C104644489%2C/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FWearetheworld-michaeljackson.mp3&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/Wearetheworld-michaeljackson.mp3 Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%E4%BD%95%E6%98%A0%E8%BE%BE/%E6%8D%AE%E6%88%91%E6%89%80%E7%9F%A5/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E4%BD%95%E6%98%A0%E8%BE%BE-%E8%96%87%E6%8B%89.wma&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/何映达-薇拉.wma Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.ape&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.ape Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%3F%3F%3F%3F/%3F%3F%3F%3F%3F%3F%3F%D5%B5%3F01/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.cue&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.cue Apr 14 15:11:30 volumio volumio[13107]: info: ALBUMART /albumart?cacheid=378&web=%3F%3F%3F%3F/%3F%3F%3F%3F%3F%3F%3F%D5%B5%3F01/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.cue&metadata=false Apr 14 15:11:30 volumio volumio[13107]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.cue Apr 14 15:11:30 volumio volumio[13107]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:11:30 volumio volumio[13107]: Error: Unable to resolve or reject the same promise twice Apr 14 15:11:30 volumio volumio[13107]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Apr 14 15:11:30 volumio volumio[13107]: at /volumio/app/plugins/music_service/mpd/index.js:2568:21 Apr 14 15:11:30 volumio volumio[13107]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Apr 14 15:11:30 volumio volumio[13107]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Apr 14 15:11:30 volumio volumio[13107]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Apr 14 15:11:30 volumio volumio[13107]: at Socket.emit (events.js:315:20) Apr 14 15:11:30 volumio volumio[13107]: at addChunk (internal/streams/readable.js:309:12) Apr 14 15:11:30 volumio volumio[13107]: at readableAddChunk (internal/streams/readable.js:280:11) Apr 14 15:11:30 volumio volumio[13107]: at Socket.Readable.push (internal/streams/readable.js:223:10) Apr 14 15:11:30 volumio volumio[13107]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Apr 14 15:11:30 volumio volumio[13107]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:11:31 volumio sudo[13413]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-14 15:10 Apr 14 15:11:31 volumio sudo[13413]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:31 volumio sudo[13413]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:31 volumio volumio-remote-updater[517]: [2024-04-14 15:11:31] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Apr 14 15:11:31 volumio volumio-remote-updater[517]: [2024-04-14 15:11:31] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Apr 14 15:11:31 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:31 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Apr 14 15:11:31 volumio systemd[1]: Started dynamicswap service. Apr 14 15:11:31 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 14 15:11:31 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Apr 14 15:11:31 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 21. Apr 14 15:11:31 volumio systemd[1]: Started dynamicswap service. Apr 14 15:11:31 volumio systemd[1]: Stopped Volumio Backend Module. Apr 14 15:11:31 volumio systemd[1]: Started Volumio Backend Module. Apr 14 15:11:31 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 14 15:11:32 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:32 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 72. Apr 14 15:11:32 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:32 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:32 volumio go-librespot[13436]: Librespot-go daemon starting... Apr 14 15:11:32 volumio go-librespot[13436]: time="2024-04-14T15:11:32+08:00" level=info msg="generated new device id: 6eb60391d0061b5565f7e5f4774c9e9b168ad720" Apr 14 15:11:32 volumio go-librespot[13436]: time="2024-04-14T15:11:32+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:33 volumio volumio[13424]: info: ------------------------------------------- Apr 14 15:11:33 volumio volumio[13424]: info: ----- Volumio3 ---- Apr 14 15:11:33 volumio volumio[13424]: info: ------------------------------------------- Apr 14 15:11:33 volumio volumio[13424]: info: ----- System startup ---- Apr 14 15:11:33 volumio volumio[13424]: info: ------------------------------------------- Apr 14 15:11:33 volumio go-librespot[13436]: time="2024-04-14T15:11:33+08:00" level=debug msg="obtained new client token: AAAnyOF0p057BYcsRvWRuxAnVI9p7tcLFGkDxI/YP2/ScFR1icY80izNqE0HF90xYiUYQClB5DgJpr0fEGvThm5zJjfcmVXLn06uRINN9aLkcrt6VS67dmytVEjX5ATtdUv1LV8P/YqaQ2Va3PZMKBoTVjg412vKRpx7ApnC10IDUNkUYI1Lwm+Z9lYSOaZcbX+Ela3wvuHeRqVnjT8F0KCed6iVbwQxxT0m8P6/GDN7linktjcO0GFXZrl+dQ==" Apr 14 15:11:33 volumio go-librespot[13436]: time="2024-04-14T15:11:33+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:11:33 volumio volumio[13424]: info: MYVOLUMIO Environment detected Apr 14 15:11:33 volumio volumio[13424]: info: Plugin folders cleanup Apr 14 15:11:33 volumio volumio[13424]: info: Scanning into folder /volumio/app/plugins/ Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category audio_interface Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category miscellanea Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category music_service Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category plugins.json Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category system_controller Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category user_interface Apr 14 15:11:33 volumio volumio[13424]: info: Scanning into folder /data/plugins/ Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category music_service Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category system_controller Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category system_hardware Apr 14 15:11:33 volumio volumio[13424]: info: Scanning category user_interface Apr 14 15:11:33 volumio volumio[13424]: info: Plugin folders cleanup completed Apr 14 15:11:33 volumio volumio[13424]: info: ------------------------------------------- Apr 14 15:11:33 volumio volumio[13424]: info: ----- Core plugins startup ---- Apr 14 15:11:33 volumio volumio[13424]: info: ------------------------------------------- Apr 14 15:11:33 volumio volumio[13424]: info: Loading plugins from folder /volumio/app/plugins/ Apr 14 15:11:33 volumio volumio[13424]: info: Adding plugin upnp to MyMusic Plugins Apr 14 15:11:33 volumio volumio[13424]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 14 15:11:33 volumio volumio[13424]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 14 15:11:33 volumio volumio[13424]: info: Loading plugins from folder /data/plugins/ Apr 14 15:11:33 volumio volumio[13424]: info: Loading plugin "system"... Apr 14 15:11:34 volumio go-librespot[13436]: time="2024-04-14T15:11:34+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:34 volumio volumio[13424]: info: Loading plugin "appearance"... Apr 14 15:11:34 volumio go-librespot[13436]: time="2024-04-14T15:11:34+08:00" level=debug msg="completed challenge" Apr 14 15:11:34 volumio go-librespot[13436]: time="2024-04-14T15:11:34+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:34 volumio volumio[13424]: info: Loading plugin "network"... Apr 14 15:11:34 volumio volumio[13424]: info: Refreshing Cached IP Addresses Apr 14 15:11:34 volumio sudo[13459]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 14 15:11:34 volumio sudo[13459]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:34 volumio sudo[13459]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:34 volumio sudo[13461]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 14 15:11:34 volumio sudo[13461]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:34 volumio volumio[13424]: info: Loading plugin "services"... Apr 14 15:11:34 volumio volumio[13424]: info: Loading plugin "alsa_controller"... Apr 14 15:11:34 volumio sudo[13461]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:34 volumio sudo[13465]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 14 15:11:34 volumio sudo[13465]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:35 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "wizard"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "networkfs"... Apr 14 15:11:35 volumio volumio[13424]: info: Starting Udev Watcher for removable devices Apr 14 15:11:35 volumio volumio[13424]: info: Ignoring mount for partition: boot Apr 14 15:11:35 volumio volumio[13424]: info: Ignoring mount for partition: volumio Apr 14 15:11:35 volumio volumio[13424]: info: Ignoring mount for partition: volumio_data Apr 14 15:11:35 volumio volumio[13424]: info: Mounting Device A27B-C06F Apr 14 15:11:35 volumio sudo[13473]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/A27B-C06F -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 14 15:11:35 volumio sudo[13473]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:35 volumio sudo[13473]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:35 volumio volumio[13424]: mount: /media/A27B-C06F: /dev/sda1 already mounted on /media/A27B-C06F. Apr 14 15:11:35 volumio volumio[13424]: error: Failed to mount A27B-C06F: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/A27B-C06F" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 14 15:11:35 volumio volumio[13424]: mount: /media/A27B-C06F: /dev/sda1 already mounted on /media/A27B-C06F. Apr 14 15:11:35 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "volumio_command_line_client"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "upnp"... Apr 14 15:11:35 volumio volumio[13424]: info: [1713078695196] Starting Upmpd Daemon Apr 14 15:11:35 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "my_music"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "mpd"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "upnp_browser"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "alarm-clock"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "airplay_emulation"... Apr 14 15:11:35 volumio volumio[13424]: info: Starting Shairport Sync Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "last_100"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "webradio"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "i2s_dacs"... Apr 14 15:11:35 volumio volumio[13424]: info: Loading plugin "volumiodiscovery"... Apr 14 15:11:36 volumio volumio[13424]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 14 15:11:36 volumio volumio[13424]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:11:36 volumio volumio[13424]: *** WARNING *** For more information see Apr 14 15:11:36 volumio node[13424]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 14 15:11:36 volumio volumio[13424]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 14 15:11:36 volumio volumio[13424]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:11:36 volumio volumio[13424]: *** WARNING *** For more information see Apr 14 15:11:36 volumio node[13424]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:11:36 volumio node[13424]: *** WARNING *** For more information see Apr 14 15:11:36 volumio node[13424]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 14 15:11:36 volumio node[13424]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:11:36 volumio node[13424]: *** WARNING *** For more information see Apr 14 15:11:36 volumio volumio[13424]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 14 15:11:36 volumio volumio[13424]: info: Discovery: Started advertising with name: Volumio Apr 14 15:11:36 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 14 15:11:36 volumio volumio[13424]: info: Loading plugin "spop"... Apr 14 15:11:36 volumio sudo[13465]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:36 volumio volumio-remote-updater[517]: [2024-04-14 15:11:36] [connect] Successful connection Apr 14 15:11:37 volumio volumio[13424]: info: Plugin youtube2 is not enabled Apr 14 15:11:37 volumio volumio[13424]: info: Loading plugin "ytcr"... Apr 14 15:11:37 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 73. Apr 14 15:11:37 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:37 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:37 volumio go-librespot[13477]: Librespot-go daemon starting... Apr 14 15:11:37 volumio go-librespot[13477]: time="2024-04-14T15:11:37+08:00" level=info msg="generated new device id: 05e19d563c9f2788cba40c9de55b26ff5fc53ec1" Apr 14 15:11:37 volumio go-librespot[13477]: time="2024-04-14T15:11:37+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:38 volumio go-librespot[13477]: time="2024-04-14T15:11:38+08:00" level=debug msg="obtained new client token: AABFMN+nx3RAH5mXuaJgKOf+n6b/WPkm/uUbSIzhidVMELqcApvkDaep7m3Jg2OLKjRvlOvXZ/mZvB7TD6YN9f/ebN7TMCUcOJkDRUEsNMTpfdwC+kbh1gJvGIXCwQVX0ArbPqrKerbuW6x1hNyFKGMwn6Skp0RY5rQRCVA7ndNbj8tj3molSIsxi1rcq7mL9VBCj3hInJbR6JdA7KtCU1Re3mfKTw+ttGOjAotv9O2gyIFe5/dwh1eDg0f9Gjmb" Apr 14 15:11:38 volumio volumio[13424]: info: Plugin ytmusic is not enabled Apr 14 15:11:38 volumio volumio[13424]: info: Loading plugin "autostart"... Apr 14 15:11:38 volumio volumio[13424]: info: Applying required configuration parameters for plugin autostart Apr 14 15:11:38 volumio volumio[13424]: info: AutoStart - onVolumioStart - read config.json Apr 14 15:11:38 volumio volumio[13424]: info: Loading plugin "now_playing"... Apr 14 15:11:39 volumio go-librespot[13477]: time="2024-04-14T15:11:39+08: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:11:39 volumio go-librespot[13477]: time="2024-04-14T15:11:39+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:39 volumio go-librespot[13477]: time="2024-04-14T15:11:39+08:00" level=debug msg="completed challenge" Apr 14 15:11:39 volumio go-librespot[13477]: time="2024-04-14T15:11:39+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:39 volumio volumio[13424]: info: Loading plugin "peppy_screensaver"... Apr 14 15:11:40 volumio volumio[13424]: info: Applying required configuration parameters for plugin peppy_screensaver Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "outputs"... Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "albumart"... Apr 14 15:11:40 volumio volumio[13424]: info: Plugin example_plugin is not enabled Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "inputs"... Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "updater_comm"... Apr 14 15:11:40 volumio volumio[13424]: info: Plugin mpdemulation is not enabled Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "rest_api"... Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "websocket"... Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "80s80s"... Apr 14 15:11:40 volumio volumio[13424]: Forking 3 albumart workers Apr 14 15:11:40 volumio volumio[13424]: info: Applying required configuration parameters for plugin 80s80s Apr 14 15:11:40 volumio volumio[13424]: info: [1713078700792] [80s80s] API delay: 30 Apr 14 15:11:40 volumio volumio[13424]: info: Loading plugin "RoonBridge"... Apr 14 15:11:41 volumio volumio[13424]: info: Applying required configuration parameters for plugin RoonBridge Apr 14 15:11:41 volumio volumio[13424]: info: Loading plugin "lms"... Apr 14 15:11:41 volumio volumio[13424]: info: Loading plugin "podcast"... Apr 14 15:11:41 volumio volumio[13424]: info: ControllerPodcast::constructor Apr 14 15:11:41 volumio volumio[13424]: Starting albumart workers Apr 14 15:11:41 volumio volumio[13424]: info: Plugin ir_controller is not enabled Apr 14 15:11:41 volumio volumio[13424]: info: Loading plugin "Systeminfo"... Apr 14 15:11:41 volumio volumio[13424]: Starting albumart workers Apr 14 15:11:41 volumio volumio[13424]: Starting albumart workers Apr 14 15:11:42 volumio volumio[13424]: info: Loading plugin "touch_display"... Apr 14 15:11:42 volumio volumio[13424]: info: Applying required configuration parameters for plugin touch_display Apr 14 15:11:42 volumio volumio[13424]: info: Loading i18n strings for locale zh Apr 14 15:11:42 volumio volumio[13424]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Apr 14 15:11:42 volumio volumio[13424]: Updating browse sources language Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::initPlayerControls Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 15:11:42 volumio volumio[13424]: Express server listening on port 3000 Apr 14 15:11:42 volumio volumio[13424]: [Metrics] WebUI: 9s 897.54ms Apr 14 15:11:42 volumio volumio[13424]: info: CoreStateMachine::resetVolumioState Apr 14 15:11:42 volumio volumio[13424]: info: CoreStateMachine::getcurrentVolume Apr 14 15:11:42 volumio volumio[13424]: info: CoreCommandRouter::volumioRetrievevolume Apr 14 15:11:43 volumio volumio[13424]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 1 Apr 14 15:11:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:43 volumio volumio[13424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Total Clients: 2 Apr 14 15:11:43 volumio volumio[13424]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 3 Apr 14 15:11:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 74. Apr 14 15:11:43 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:43 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:43 volumio go-librespot[13546]: Librespot-go daemon starting... Apr 14 15:11:43 volumio go-librespot[13546]: time="2024-04-14T15:11:43+08:00" level=info msg="generated new device id: c695f54059fe6a7b86f3a06160ba65ffe7b4d8e4" Apr 14 15:11:43 volumio volumio[13424]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 4 Apr 14 15:11:43 volumio go-librespot[13546]: time="2024-04-14T15:11:43+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::updateTrackBlock Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrackBlock Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioRetrievevolume Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Apr 14 15:11:43 volumio volumio[13424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 6 Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:11:43 volumio volumio[13424]: info: Cannot read play queue from file Apr 14 15:11:43 volumio volumio[13424]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Apr 14 15:11:43 volumio volumio[13424]: error: Failed callmethod call: TypeError: Cannot read property 'has' of undefined Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::setRepeat true single undefined Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::setRandom false Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:11:43 volumio volumio[13424]: info: Setting Device type: Raspberry PI Apr 14 15:11:43 volumio volumio[13424]: info: Listing playlists Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::getQueue Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getQueue Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Apr 14 15:11:43 volumio volumio[13424]: error: Failed callmethod call: TypeError: Cannot read property 'has' of undefined Apr 14 15:11:43 volumio volumio[13424]: info: Listing playlists Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:11:43 volumio volumio[13424]: info: CoreStateMachine::getQueue Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getQueue Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio volumio[13424]: info: Discovery: adding eaa2afdc-3fa0-4a8a-925d-a9b0c99b88c0 Apr 14 15:11:43 volumio volumio[13424]: info: Discovery: Found device Volumio Apr 14 15:11:43 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:43 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:43 volumio go-librespot[13546]: time="2024-04-14T15:11:43+08:00" level=debug msg="obtained new client token: AADGV5foCTVv7g6XY392ADziNDyqjkLcX7IE2/Yljk/KpoA4QopuqT3OpfVgUArWUv1+bajYSw/dm0z0W/Qml7ASDCO9ekaUe1pz/a01Y79Czx8GlhdqIS/mQ6dNSLgwl0whV4YpyhFyk9ilkQf0O8krknfj3FDEthPfYJWCHjWGqoQOclnRv7+IRoyc5mHqrt628YwUC6tJxyzxDoYD4A+uVYifLczoL78RDJBi1valeJYW5EVvJnyqWOMVknYF" Apr 14 15:11:44 volumio go-librespot[13546]: time="2024-04-14T15:11:44+08: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]" Apr 14 15:11:44 volumio go-librespot[13546]: time="2024-04-14T15:11:44+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:45 volumio go-librespot[13546]: time="2024-04-14T15:11:45+08:00" level=debug msg="completed challenge" Apr 14 15:11:45 volumio go-librespot[13546]: time="2024-04-14T15:11:45+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:45 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:45 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:45 volumio sudo[13607]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 14 15:11:45 volumio sudo[13607]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:45 volumio sudo[13607]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:45 volumio sudo[13610]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 14 15:11:45 volumio sudo[13610]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:45 volumio sudo[13610]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:45 volumio sudo[13613]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 14 15:11:45 volumio sudo[13613]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:11:45 volumio sudo[13613]: pam_unix(sudo:session): session closed for user root Apr 14 15:11:45 volumio volumio[13424]: info: Upmpdcli Daemon Started Apr 14 15:11:46 volumio volumio[13424]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 7 Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:46 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 14 15:11:46 volumio volumio[13424]: info: Received Get System Info Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 14 15:11:46 volumio volumio[13424]: info: Discovery: Getting this device information Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:46 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:11:46 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:11:46 volumio volumio[13424]: info: Listing playlists Apr 14 15:11:46 volumio volumio[13424]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:11:46 volumio volumio[13424]: info: CoreStateMachine::getQueue Apr 14 15:11:46 volumio volumio[13424]: info: CorePlayQueue::getQueue Apr 14 15:11:48 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:48 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 75. Apr 14 15:11:48 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:48 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:48 volumio go-librespot[13619]: Librespot-go daemon starting... Apr 14 15:11:48 volumio go-librespot[13619]: time="2024-04-14T15:11:48+08:00" level=info msg="generated new device id: 5ff7914547b725e8ea586480fbdac4f394e1434e" Apr 14 15:11:48 volumio go-librespot[13619]: time="2024-04-14T15:11:48+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:48 volumio go-librespot[13619]: time="2024-04-14T15:11:48+08:00" level=debug msg="obtained new client token: AADQwld+iX3IvJ92MNJG1TG+vMPv3dxieL96NYFCPf83wLqzvGWMymc+YO1oqlBc4TnHYLqVpQ2xmaEr41W5vbfbbIJTXjF1skb9eTPD38Bc9INbQGZcLMOQrbpoIYpfMWB1LqD/qD4uvOAeB80Tycwbmk/RJ6UvjhzPJMQTkWQC4ZQ3FPXkwf5YIIJf0MEXQ4ZAHO9e1BfxOFHVWIRjOIL5soQ18sYjxY/MwE5Nd3ULEUoTjVTAIIZ7WGUS9wGj" Apr 14 15:11:49 volumio volumio-remote-updater[517]: [2024-04-14 15:11:49] [connect] Successful connection Apr 14 15:11:49 volumio volumio-remote-updater[517]: [2024-04-14 15:11:49] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1713078709 101 Apr 14 15:11:49 volumio volumio[13424]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 8 Apr 14 15:11:49 volumio go-librespot[13619]: time="2024-04-14T15:11:49+08: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:11:49 volumio go-librespot[13619]: time="2024-04-14T15:11:49+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:50 volumio go-librespot[13619]: time="2024-04-14T15:11:50+08:00" level=debug msg="completed challenge" Apr 14 15:11:50 volumio go-librespot[13619]: time="2024-04-14T15:11:50+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:50 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:50 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:53 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:53 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 76. Apr 14 15:11:53 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:53 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:53 volumio go-librespot[13628]: Librespot-go daemon starting... Apr 14 15:11:53 volumio go-librespot[13628]: time="2024-04-14T15:11:53+08:00" level=info msg="generated new device id: cb8ea37661402fa20e34ea0dc36f08f9c6c88c5f" Apr 14 15:11:53 volumio go-librespot[13628]: time="2024-04-14T15:11:53+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:54 volumio go-librespot[13628]: time="2024-04-14T15:11:54+08:00" level=debug msg="obtained new client token: AACBtczVDp7Veu7mNeYQcAOhnNty/+1h8d/yHqChgUWJn0PkzQLThLzzxvCQSGuW1tZ4Dt4y3p4P62q9q10PL7V1tyUcbepCMtOo8KOafbtIeortssxZUfNzCsQ1U9tIpNU2mOXjyt9NcHmi3ep+Bz8wqO52ehDkewL1E2NJORZl9icK8hjJDc9MRk3xwKY+Cka5GmjhwlB9iQpp5dVC8j/zl1qgbVPdH1dQnB2hYTpbKMxtoSqCty3qhz4GQw==" Apr 14 15:11:54 volumio go-librespot[13628]: time="2024-04-14T15:11:54+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:11:54 volumio go-librespot[13628]: time="2024-04-14T15:11:54+08:00" level=debug msg="completed keyexchange" Apr 14 15:11:55 volumio go-librespot[13628]: time="2024-04-14T15:11:55+08:00" level=debug msg="completed challenge" Apr 14 15:11:55 volumio go-librespot[13628]: time="2024-04-14T15:11:55+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:11:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:11:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:11:56 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:11:56 volumio volumio[13424]: info: CURURI: music-library/USB/A27B-C06F/王杰 Apr 14 15:11:56 volumio volumio[13424]: error: Failed to execute browseSource, failure: TypeError: Cannot read property 'then' of undefined Apr 14 15:11:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:11:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 77. Apr 14 15:11:58 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:11:58 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:11:58 volumio go-librespot[13636]: Librespot-go daemon starting... Apr 14 15:11:58 volumio go-librespot[13636]: time="2024-04-14T15:11:58+08:00" level=info msg="generated new device id: 8c1e5cd37ed57fe8ddcd059a2a7efa004289f587" Apr 14 15:11:58 volumio go-librespot[13636]: time="2024-04-14T15:11:58+08:00" level=debug msg="stored credentials not found" Apr 14 15:11:59 volumio go-librespot[13636]: time="2024-04-14T15:11:59+08:00" level=debug msg="obtained new client token: AADgJWCZYDRTjAFq1xoGb5NZ9AchmskG9pnOoxhnLSPGs26Ms23flsQe9v/YWghdTAPMBfv1WxInVK6w0or3hTGmWWZsi4U9klH0ekIPJWbuCQprjSMAtKyUDnxxMY0sB00coGMwFaUetWxsQ7KzAApo5U7B7Dn54YwsWqamZE6Udjwyxt/dI52q18g/HX2MI5NqvKK4UkWKUFKnswnhfluERQu0z2ilQyZGvwZs0lRUumbTKCErEY197YBpM0CP" Apr 14 15:12:00 volumio go-librespot[13636]: time="2024-04-14T15:12:00+08: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]" Apr 14 15:12:00 volumio go-librespot[13636]: time="2024-04-14T15:12:00+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:00 volumio go-librespot[13636]: time="2024-04-14T15:12:00+08:00" level=debug msg="completed challenge" Apr 14 15:12:00 volumio go-librespot[13636]: time="2024-04-14T15:12:00+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:04 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:04 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 78. Apr 14 15:12:04 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:04 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:04 volumio go-librespot[13644]: Librespot-go daemon starting... Apr 14 15:12:04 volumio go-librespot[13644]: time="2024-04-14T15:12:04+08:00" level=info msg="generated new device id: 84a8e388c26c86b36f44449814cfc17be56a4a87" Apr 14 15:12:04 volumio go-librespot[13644]: time="2024-04-14T15:12:04+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:04 volumio go-librespot[13644]: time="2024-04-14T15:12:04+08:00" level=debug msg="obtained new client token: AAANgi1BZue8DguX5TuI4HfBNGejSj8LUUo6tKiPe1rDf4UKmSpL29cu60QIky0wPxq1O4QUhJFrWOQEvvIKhJKSPdE/mLo4KW+QsegyUzv0NhZwfQyqHBaKR/z9nzqvZ9oO5TW1XGe5znErsk/bea8jWWPF+ckLQMM2//k2Btx4HzXMPJrUmrSMGjiCO6nK4DjmQ6uY78Wzdwpt5zQudZMogsGkPR1OibWAy5Do3EaPZdg9N0T9SR/qGqGaO6zi" Apr 14 15:12:05 volumio go-librespot[13644]: time="2024-04-14T15:12:05+08: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]" Apr 14 15:12:05 volumio go-librespot[13644]: time="2024-04-14T15:12:05+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:05 volumio go-librespot[13644]: time="2024-04-14T15:12:05+08:00" level=debug msg="completed challenge" Apr 14 15:12:06 volumio go-librespot[13644]: time="2024-04-14T15:12:06+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:06 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:06 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:07 volumio kernel: usb 1-1.2: USB disconnect, device number 4 Apr 14 15:12:07 volumio volumio[13424]: info: Partition removed: {"syspath":"/sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.2/1-1.2:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","ACTION":"remove","DEVLINKS":"/dev/disk/by-partuuid/0403c116-01 /dev/disk/by-uuid/A27B-C06F /dev/disk/by-id/usb-Generic-_SD_MMC_20090815198100000-0:0-part1 /dev/disk/by-path/platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1.2:1.0-scsi-0:0:0:0-part1","DEVNAME":"/dev/sda1","DEVPATH":"/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.2/1-1.2:1.0/host0/target0:0:0/0:0:0:0/block/sda/sda1","DEVTYPE":"partition","DISKSEQ":"28","ID_BUS":"usb","ID_FS_TYPE":"vfat","ID_FS_USAGE":"filesystem","ID_FS_UUID":"A27B-C06F","ID_FS_UUID_ENC":"A27B-C06F","ID_FS_VERSION":"FAT16","ID_INSTANCE":"0:0","ID_MODEL":"SD_MMC","ID_MODEL_ENC":"SD\\x2fMMC\\x20\\x20\\x20\\x20\\x20\\x20\\x20\\x20\\x20\\x20","ID_MODEL_ID":"0119","ID_PART_ENTRY_DISK":"8:0","ID_PART_ENTRY_NUMBER":"1","ID_PART_ENTRY_OFFSET":"135","ID_PART_ENTRY_SCHEME":"dos","ID_PART_ENTRY_SIZE":"3858489","ID_PART_ENTRY_TYPE":"0xe","ID_PART_ENTRY_UUID":"0403c116-01","ID_PART_TABLE_TYPE":"dos","ID_PART_TABLE_UUID":"0403c116","ID_PATH":"platform-fd500000.pcie-pci-0000:01:00.0-usb-0:1.2:1.0-scsi-0:0:0:0","ID_PATH_TAG":"platform-fd500000_pcie-pci-0000_01_00_0-usb-0_1_2_1_0-scsi-0_0_0_0","ID_REVISION":"1.00","ID_SERIAL":"Generic-_SD_MMC_20090815198100000-0:0","ID_SERIAL_SHORT":"20090815198100000","ID_TYPE":"disk","ID_USB_DRIVER":"usb-storage","ID_USB_INTERFACES":":080650:","ID_USB_INTERFACE_NUM":"00","ID_VENDOR":"Generic-","ID_VENDOR_ENC":"Generic-","ID_VENDOR_ID":"0bda","MAJOR":"8","MINOR":"1","PARTN":"1","SEQNUM":"1801","SUBSYSTEM":"block","TAGS":":systemd:","USEC_INITIALIZED":"1568426614"} Apr 14 15:12:07 volumio sudo[13657]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/umount -f /dev/sda1 Apr 14 15:12:07 volumio sudo[13657]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:07 volumio sudo[13657]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:07 volumio systemd[1]: media-A27B\x2dC06F.mount: Succeeded. Apr 14 15:12:09 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:09 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 79. Apr 14 15:12:09 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:09 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:09 volumio go-librespot[13659]: Librespot-go daemon starting... Apr 14 15:12:09 volumio go-librespot[13659]: time="2024-04-14T15:12:09+08:00" level=info msg="generated new device id: a2666a0942b8a690c255b22816d7dce880c8767a" Apr 14 15:12:09 volumio go-librespot[13659]: time="2024-04-14T15:12:09+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:09 volumio go-librespot[13659]: time="2024-04-14T15:12:09+08:00" level=debug msg="obtained new client token: AACOfVlObkl/cCSEtvIq4cCsDQWqhUpcH7zyGUnhOS0400TH9uNFL8ZiSmjGMmcbhxluf8WqnsBn7/YtEOf5w/hKfvAY1imp8NvjZgYbcZrFjWnJ2rPddiThuvg0LT4ZGBWPIHYHVzt/htypIqDae/nkaSkhx8LVYI63ixWymB1eMxQw6cKQ5FX+Xidf2qr3PQQ0HrSHKasHFV2VGgMkRA7FM7VHwzBUnySk/kkE0o1jjq5LpzP3z0knd58SHWqL" Apr 14 15:12:10 volumio go-librespot[13659]: time="2024-04-14T15:12:10+08: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]" Apr 14 15:12:10 volumio go-librespot[13659]: time="2024-04-14T15:12:10+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:11 volumio go-librespot[13659]: time="2024-04-14T15:12:11+08:00" level=debug msg="completed challenge" Apr 14 15:12:11 volumio volumio[13424]: info: TEST: Here we shall have deleted mounted folder: /mnt/USB/A27B-C06F Apr 14 15:12:11 volumio go-librespot[13659]: time="2024-04-14T15:12:11+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:12 volumio volumio[13424]: info: Scanning removed location : "USB/A27B-C06F" Apr 14 15:12:12 volumio volumio[13424]: error: Plugin system_controller system failed to complete 'onVolumioStart' in a timely fashion Apr 14 15:12:12 volumio volumio[13424]: info: Preparing to generate the ALSA configuration file Apr 14 15:12:12 volumio volumio[13424]: info: The plugin alsa_controller has an ALSA contribution file softvolume.postVolume.conf Apr 14 15:12:12 volumio volumio[13424]: info: The plugin peppy_screensaver has an ALSA contribution file Peppyalsa.postPeppyalsa.5.conf Apr 14 15:12:12 volumio volumio[13424]: info: Reading ALSA contributions from plugins. Apr 14 15:12:12 volumio volumio[13424]: info: Asound.conf file unchanged, so no further update is needed Apr 14 15:12:12 volumio volumio[13424]: info: Output device has changed, restarting MPD Apr 14 15:12:12 volumio sudo[13672]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 14 15:12:12 volumio sudo[13672]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:12 volumio sudo[13672]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:12 volumio volumio[13424]: info: Output device has changed, restarting Shairport Sync Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:12 volumio sudo[13676]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 14 15:12:12 volumio sudo[13676]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:12 volumio systemd[1]: Stopping Music Player Daemon... Apr 14 15:12:12 volumio systemd[1]: mpd.service: Succeeded. Apr 14 15:12:12 volumio systemd[1]: Stopped Music Player Daemon. Apr 14 15:12:12 volumio volumio[13424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:12:12 volumio volumio[13424]: info: ___________ START PLUGINS ___________ Apr 14 15:12:12 volumio volumio[13424]: info: ControllerMpd::onStart: Initializing MPD Apr 14 15:12:12 volumio volumio[13424]: info: Creating MPD Configuration file Apr 14 15:12:12 volumio systemd[1]: Starting Music Player Daemon... Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:12:12 volumio volumio[13424]: info: [1713078732832] CoreMusicLibrary::Adding element 媒体服务器 Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:12 volumio sudo[13685]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Apr 14 15:12:12 volumio sudo[13685]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:12 volumio sudo[13683]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:12 volumio sudo[13683]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:12 volumio sudo[13683]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:12 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Apr 14 15:12:12 volumio systemd[1]: mpd.service: Succeeded. Apr 14 15:12:12 volumio systemd[1]: Stopped Music Player Daemon. Apr 14 15:12:12 volumio volumio[13424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:12 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:12 volumio systemd[1]: Starting Music Player Daemon... Apr 14 15:12:13 volumio volumio[13424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:12:13 volumio volumio[13424]: info: [1713078733013] CoreMusicLibrary::Adding element Last_100 Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:12:13 volumio volumio[13424]: info: [1713078733017] CoreMusicLibrary::Adding element Webradio Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:12:13 volumio volumio[13424]: info: Creating Spotify config file Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: AutoStart - onStart Apr 14 15:12:13 volumio volumio[13424]: info: [now-playing] ConfigUpdater: config is up to date. Apr 14 15:12:13 volumio volumio[13424]: info: Loading i18n strings for locale zh Apr 14 15:12:13 volumio volumio[13424]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Apr 14 15:12:13 volumio volumio[13424]: info: /tmp/myfifo created Apr 14 15:12:13 volumio sudo[13699]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/modprobe snd-dummy index=7 pcm_substreams=1 Apr 14 15:12:13 volumio sudo[13699]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:13 volumio sudo[13699]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:13 volumio volumio[13424]: info: snd-dummy loaded Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: airplay_emulation , startShairportSync Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:12:13 volumio volumio[13424]: info: [1713078733412] CoreMusicLibrary::Adding element 80s80s Radio Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:13 volumio volumio[13424]: Cannot find translation for source 80s80s Radio Apr 14 15:12:13 volumio sudo[13705]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start roonbridge.service Apr 14 15:12:13 volumio sudo[13705]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:12:13 volumio volumio[13424]: info: [1713078733513] CoreMusicLibrary::Adding element Podcast Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:13 volumio sudo[13705]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:13 volumio volumio[13424]: Cannot find translation for source 80s80s Radio Apr 14 15:12:13 volumio volumio[13424]: Cannot find translation for source Podcast Apr 14 15:12:13 volumio volumio[13424]: info: Loading i18n strings for locale zh Apr 14 15:12:13 volumio volumio[13424]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:12:13 volumio sudo[13708]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart logitechmediaserver Apr 14 15:12:13 volumio sudo[13708]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:13 volumio volumio[13424]: info: Volumio Calling Home Apr 14 15:12:13 volumio systemd[1]: Starting Logitech Media Server Daemon... Apr 14 15:12:13 volumio systemd[1]: Started Logitech Media Server Daemon. Apr 14 15:12:13 volumio systemd[13714]: logitechmediaserver.service: Failed to execute command: No such file or directory Apr 14 15:12:13 volumio systemd[13714]: logitechmediaserver.service: Failed at step EXEC spawning /usr/sbin/squeezeboxserver: No such file or directory Apr 14 15:12:13 volumio systemd[1]: logitechmediaserver.service: Main process exited, code=exited, status=203/EXEC Apr 14 15:12:13 volumio systemd[1]: logitechmediaserver.service: Failed with result 'exit-code'. Apr 14 15:12:13 volumio sudo[13708]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:13 volumio sudo[13717]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl daemon-reload Apr 14 15:12:13 volumio sudo[13717]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:13 volumio systemd[1]: Reloading. Apr 14 15:12:13 volumio volumio[13424]: info: [now-playing] App is listening on port 4004. Apr 14 15:12:13 volumio volumio[13424]: warn: [now-playing] MyBackgroundMonitor is now watching /data/INTERNAL/NowPlayingPlugin/My Backgrounds Apr 14 15:12:13 volumio mpd[13691]: Apr 14 15:12 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:13 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:13 volumio volumio[13424]: info: logitechmediaserver started Apr 14 15:12:13 volumio volumio[13424]: info: MPD Permissions set Apr 14 15:12:13 volumio volumio[13424]: info: MPD Permissions set Apr 14 15:12:13 volumio volumio[13424]: info: Spotify config file written Apr 14 15:12:13 volumio volumio[13424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:13 volumio sudo[13722]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Apr 14 15:12:13 volumio sudo[13722]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:14 volumio volumio[13424]: info: touch_display: No Raspberry Pi Foundation touch screen detected. Apr 14 15:12:14 volumio volumio[13424]: info: Starting Shairport Sync Apr 14 15:12:14 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. Apr 14 15:12:14 volumio volumio[13424]: info: Starting Shairport Sync Apr 14 15:12:14 volumio sudo[13746]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:12:14 volumio sudo[13746]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:14 volumio volumio[13424]: info: Starting Shairport Sync Apr 14 15:12:14 volumio sudo[13749]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:12:14 volumio sudo[13749]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:14 volumio volumio[13424]: info: Starting Shairport Sync Apr 14 15:12:14 volumio sudo[13752]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:12:14 volumio sudo[13752]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:14 volumio sudo[13755]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Apr 14 15:12:14 volumio sudo[13755]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:14 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:14 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. Apr 14 15:12:14 volumio systemd[1]: Started Music Player Daemon. Apr 14 15:12:14 volumio sudo[13717]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio sudo[13676]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:14 volumio volumio[13424]: info: touch_display: systemctl daemon-reload succeeded. Apr 14 15:12:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 80. Apr 14 15:12:14 volumio sudo[13685]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Apr 14 15:12:14 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:14 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:14 volumio sudo[13722]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio go-librespot[13759]: Librespot-go daemon starting... Apr 14 15:12:14 volumio systemd[1]: shairport-sync.service: Succeeded. Apr 14 15:12:14 volumio sudo[13758]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumio-kiosk.service Apr 14 15:12:14 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Apr 14 15:12:14 volumio sudo[13758]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:14 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Apr 14 15:12:14 volumio sudo[13752]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio sudo[13755]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio sudo[13746]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio go-librespot[13759]: time="2024-04-14T15:12:14+08:00" level=info msg="generated new device id: 4707de9982e9b504c9947aa8743685db9827bd72" Apr 14 15:12:14 volumio go-librespot[13759]: time="2024-04-14T15:12:14+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:14 volumio sudo[13749]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio sudo[13758]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:14 volumio volumio[13424]: error: MPD error: The expression evaluated to a falsy value: Apr 14 15:12:14 volumio volumio[13424]: assert.ok(self.idling) Apr 14 15:12:14 volumio volumio[13424]: error: The expression evaluated to a falsy value: Apr 14 15:12:14 volumio volumio[13424]: assert.ok(self.idling) Apr 14 15:12:14 volumio volumio[13424]: info: Shairport-Sync Started Apr 14 15:12:14 volumio volumio[13424]: Error adding Membership: Error: addMembership EINVAL Apr 14 15:12:14 volumio volumio[13424]: info: Shairport-Sync Started Apr 14 15:12:14 volumio volumio[13424]: info: Shairport-Sync Started Apr 14 15:12:14 volumio volumio[13424]: info: Shairport-Sync Started Apr 14 15:12:14 volumio volumio[13424]: info: MPD running with PID13691 Apr 14 15:12:14 volumio volumio[13424]: ,establishing connection Apr 14 15:12:14 volumio volumio[13424]: info: touch_display: systemctl start volumio-kiosk.service succeeded. Apr 14 15:12:14 volumio volumio[13424]: info: touch_display: Volumio Kiosk started Apr 14 15:12:14 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:14 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:15 volumio volumio[13424]: error: updateQueue error: null Apr 14 15:12:15 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:15 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:15 volumio volumio[13424]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 14 15:12:15 volumio volumio[13424]: error: updateQueue error: null Apr 14 15:12:15 volumio volumio[13424]: info: touch_display: Using Xserver unix domain socket /tmp/.X11-unix/X0 Apr 14 15:12:15 volumio volumio[13424]: info: touch_display: Setting screensaver timeout to 15 seconds. Apr 14 15:12:15 volumio go-librespot[13759]: time="2024-04-14T15:12:15+08:00" level=debug msg="obtained new client token: AACv0cv8j2B3aOqLO/uJieWSHo0dS6qLsdiAI71oSXEL2ndccOfGwccUDBsa37+cVguGj/3qTRKtY14A3bspQjVpxuVA6NV0Ggl1bpJTbNauJAji4rMJyce0I+J/R8VIvkiRE3faMhuU9mSkSO0fXBVjbsQQYXLRBctsCJewyJS8aPTtPOEPGtSZgf7o5z3xzkBt0e8TPA5L86h83x54RcA/4RML6HUnfORiZuKIs42qeWFl3S9atAt718iffbq5" Apr 14 15:12:15 volumio volumio[13424]: info: Volumio called home Apr 14 15:12:15 volumio volumio[13424]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 14 15:12:15 volumio volumio[13424]: SPOTIFY: BQCQv3chaqb2VygbSh48V8F_fZ-l0HopDkPRyInhaQ5oYqxBxFBSLZb1mbXZqBXfLoZ3yRsHg6JdJIyuzerW9esox-DdblcdvT6Lftkp7afhXJCKGP0M82QgIYbCm0DxsqKkpliSkAg9n3iUzqdx6bdxuTN9aCLGnrTfhtduvM6-G4I9JBLLR7UGbQBbqqKGu3ffmufkzAJVTsrZ3N-A9LETdkGkrhY1OKLVcg3vVKOS42fnoI4BNjThFzSv2oRdizKxLwY Apr 14 15:12:15 volumio volumio[13424]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Apr 14 15:12:15 volumio volumio[13424]: info: New Spotify access token = BQCQv3chaqb2VygbSh48V8F_fZ-l0HopDkPRyInhaQ5oYqxBxFBSLZb1mbXZqBXfLoZ3yRsHg6JdJIyuzerW9esox-DdblcdvT6Lftkp7afhXJCKGP0M82QgIYbCm0DxsqKkpliSkAg9n3iUzqdx6bdxuTN9aCLGnrTfhtduvM6-G4I9JBLLR7UGbQBbqqKGu3ffmufkzAJVTsrZ3N-A9LETdkGkrhY1OKLVcg3vVKOS42fnoI4BNjThFzSv2oRdizKxLwY Apr 14 15:12:15 volumio volumio[13424]: info: Spotify credentials grant success - running version from March 24, 2019 Apr 14 15:12:16 volumio go-librespot[13759]: time="2024-04-14T15:12:16+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:12:16 volumio go-librespot[13759]: time="2024-04-14T15:12:16+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:16 volumio volumio[13424]: SPOTIFY: User informations: {"display_name":"邱瑞华","external_urls":{"spotify":"https://open.spotify.com/user/31dd2kulom3iljqxj6iee4jqblee"},"href":"https://api.spotify.com/v1/users/31dd2kulom3iljqxj6iee4jqblee","id":"31dd2kulom3iljqxj6iee4jqblee","images":[],"type":"user","uri":"spotify:user:31dd2kulom3iljqxj6iee4jqblee","followers":{"href":null,"total":0},"country":"US","product":"free","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"466223606@qq.com"} Apr 14 15:12:16 volumio volumio[13424]: info: Spotify Successfully logged in Apr 14 15:12:16 volumio volumio[13424]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Apr 14 15:12:16 volumio volumio[13424]: info: [1713078736496] CoreMusicLibrary::Adding element Spotify Apr 14 15:12:16 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:16 volumio volumio[13424]: Cannot find translation for source 80s80s Radio Apr 14 15:12:16 volumio volumio[13424]: Cannot find translation for source Podcast Apr 14 15:12:16 volumio volumio[13424]: Cannot find translation for source Spotify Apr 14 15:12:16 volumio go-librespot[13759]: time="2024-04-14T15:12:16+08:00" level=debug msg="completed challenge" Apr 14 15:12:16 volumio go-librespot[13759]: time="2024-04-14T15:12:16+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:16 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:16 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:17 volumio volumio[13424]: info: go-librespot daemon successfully initialized Apr 14 15:12:19 volumio volumio[13424]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Apr 14 15:12:20 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:20 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 81. Apr 14 15:12:20 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:20 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:20 volumio go-librespot[13780]: Librespot-go daemon starting... Apr 14 15:12:20 volumio go-librespot[13780]: time="2024-04-14T15:12:20+08:00" level=info msg="generated new device id: 38c7ef89932245d0f01ee20dd8e3ddc7e2d3785d" Apr 14 15:12:20 volumio go-librespot[13780]: time="2024-04-14T15:12:20+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:20 volumio kernel: usb 1-1.3: new high-speed USB device number 5 using xhci_hcd Apr 14 15:12:20 volumio kernel: usb 1-1.3: New USB device found, idVendor=0bda, idProduct=0119, bcdDevice=19.81 Apr 14 15:12:20 volumio kernel: usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Apr 14 15:12:20 volumio kernel: usb 1-1.3: Product: USB2.0-CRW Apr 14 15:12:20 volumio kernel: usb 1-1.3: Manufacturer: Generic Apr 14 15:12:20 volumio kernel: usb 1-1.3: SerialNumber: 20090815198100000 Apr 14 15:12:20 volumio kernel: usb-storage 1-1.3:1.0: USB Mass Storage device detected Apr 14 15:12:20 volumio kernel: scsi host0: usb-storage 1-1.3:1.0 Apr 14 15:12:20 volumio go-librespot[13780]: time="2024-04-14T15:12:20+08:00" level=debug msg="obtained new client token: AAC+h/9Ty+RREEFbpVGambpb2kitirSdogjinL+LMAc6uSmRTbByZ0XJVbNOA+qpg0hlsYFxNf/1iPK9tt1Y8QGeJjxbsC7O5UT+dt+vPtY8DD+AB1nXEuov4a1JlzIfSHelcwQrSpZYBcvq06GPBMVLAL7vXKyj55zfTWvmY4P5Zc0rqjmUiYj9xi5uAb1K252fdNQTEe2Y45vN1t8NvYmqEVma8PuimwKXjr4bGb//xUF9OnTtYVpgkhUdOAd9" Apr 14 15:12:20 volumio volumio[13424]: info: Initializing connection to go-librespot Websocket Apr 14 15:12:20 volumio go-librespot[13780]: time="2024-04-14T15:12:20+08:00" level=debug msg="new websocket client" Apr 14 15:12:21 volumio volumio[13424]: info: Connection to go-librespot Websocket established Apr 14 15:12:21 volumio go-librespot[13780]: time="2024-04-14T15:12:21+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:12:21 volumio go-librespot[13780]: time="2024-04-14T15:12:21+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:21 volumio kernel: scsi 0:0:0:0: Direct-Access Generic- SD/MMC 1.00 PQ: 0 ANSI: 0 CCS Apr 14 15:12:21 volumio kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0 Apr 14 15:12:21 volumio go-librespot[13780]: time="2024-04-14T15:12:21+08:00" level=debug msg="completed challenge" Apr 14 15:12:22 volumio go-librespot[13780]: time="2024-04-14T15:12:22+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:22 volumio volumio[13424]: info: Connection to go-librespot Websocket closed Apr 14 15:12:22 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:22 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:22 volumio kernel: sd 0:0:0:0: [sda] 3911680 512-byte logical blocks: (2.00 GB/1.87 GiB) Apr 14 15:12:22 volumio kernel: sd 0:0:0:0: [sda] Write Protect is off Apr 14 15:12:22 volumio kernel: sd 0:0:0:0: [sda] Mode Sense: 03 00 00 00 Apr 14 15:12:22 volumio kernel: sd 0:0:0:0: [sda] No Caching mode page found Apr 14 15:12:22 volumio kernel: sd 0:0:0:0: [sda] Assuming drive cache: write through Apr 14 15:12:22 volumio kernel: sda: sda1 Apr 14 15:12:22 volumio kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk Apr 14 15:12:22 volumio volumio[13424]: info: Mounting Device A27B-C06F Apr 14 15:12:22 volumio sudo[13799]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/A27B-C06F -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 14 15:12:22 volumio sudo[13799]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. Apr 14 15:12:23 volumio sudo[13799]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:23 volumio volumio[13424]: info: Scanning new location : "USB/A27B-C06F" Apr 14 15:12:23 volumio volumio[13424]: info: AutoStart - Plugin is starting Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::getQueue Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getQueue Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: update Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: update Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: update Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 29 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 20 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 19 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 17 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 15 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 9 milliseconds Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): Filesystem has been set read-only Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7695) Apr 14 15:12:23 volumio volumio[13424]: info: Command Router : Notfying DB Updatetrue Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio kernel: FAT-fs (sda1): error, fat_bmap_cluster: request beyond EOF (i_pos 7701) Apr 14 15:12:23 volumio volumio[13424]: info: Command Router : Notfying DB Updatetrue Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:23 volumio volumio[13424]: info: Command Router : Notfying DB Updatetrue Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:23 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: No code Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:23 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: No code Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:23 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: No code Apr 14 15:12:23 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:23 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:23 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:23 volumio volumio[13424]: info: ------------------------------ 362ms Apr 14 15:12:23 volumio volumio[13424]: info: ------------------------------ 352ms Apr 14 15:12:23 volumio volumio[13424]: info: ------------------------------ 348ms Apr 14 15:12:23 volumio volumio[13424]: info: MPD Database updated - AlbumList cache refreshed Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: database Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: update Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: MPD Database updated - AlbumList cache refreshed Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: database Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: update Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: MPD Database updated - AlbumList cache refreshed Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: database Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: Apr 14 15:12:23 volumio volumio[13424]: ---------------------------- MPD announces state update: update Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: ControllerMpd::getState Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::sendMpdCommand status Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 38 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 36 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 36 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 34 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 33 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 33 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 29 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 26 milliseconds Apr 14 15:12:23 volumio volumio[13424]: info: sendMpdCommand status took 25 milliseconds Apr 14 15:12:23 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: info: Command Router : Notfying DB Updatefalse Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: info: Command Router : Notfying DB Updatefalse Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: info: Command Router : Notfying DB Updatefalse Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::Close All Modals sent Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: verbose: ControllerMpd::parseState Apr 14 15:12:24 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:24 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: No code Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:24 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: No code Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:24 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: No code Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:24 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: No code Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:24 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: No code Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: ControllerMpd::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::servicePushState Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Apr 14 15:12:24 volumio volumio[13424]: verbose: CURRENT POSITION 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState stateService stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::syncState currentStatus stop Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: No code Apr 14 15:12:24 volumio volumio[13424]: info: CoreStateMachine::pushState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:24 volumio volumio[13424]: info: ------------------------------ 447ms Apr 14 15:12:24 volumio volumio[13424]: info: ------------------------------ 450ms Apr 14 15:12:24 volumio volumio[13424]: info: ------------------------------ 447ms Apr 14 15:12:24 volumio volumio[13424]: info: ------------------------------ 447ms Apr 14 15:12:24 volumio volumio[13424]: info: ------------------------------ 444ms Apr 14 15:12:24 volumio volumio[13424]: info: ------------------------------ 445ms Apr 14 15:12:24 volumio volumio[13424]: info: Getting Spotify volume Apr 14 15:12:24 volumio volumio[13424]: (node:13424) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:12:24 volumio volumio[13424]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:12:24 volumio volumio[13424]: (Use `node --trace-warnings ...` to show where the warning was created) Apr 14 15:12:24 volumio volumio[13424]: (node:13424) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1) Apr 14 15:12:24 volumio volumio[13424]: (node:13424) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code. Apr 14 15:12:24 volumio volumio[13424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:12:24 volumio volumio[13424]: SPOTIFY: SPOTIFY VOLUME undefined Apr 14 15:12:24 volumio volumio[13424]: SPOTIFY: VOLUMIO VOLUME 69 Apr 14 15:12:24 volumio volumio[13424]: info: Aligning Spotify Volume to Volumio Volume Apr 14 15:12:24 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:24 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:24 volumio volumio[13424]: info: Setting Spotify Volume from Volumio: 69 Apr 14 15:12:25 volumio volumio[13424]: info: Initializing connection to go-librespot Websocket Apr 14 15:12:25 volumio volumio[13424]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:12:25 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:25 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 82. Apr 14 15:12:25 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:25 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:25 volumio go-librespot[13816]: Librespot-go daemon starting... Apr 14 15:12:25 volumio go-librespot[13816]: time="2024-04-14T15:12:25+08:00" level=info msg="generated new device id: e0e6886b289659f022e47e4b75813bd9dd1c3602" Apr 14 15:12:25 volumio go-librespot[13816]: time="2024-04-14T15:12:25+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:26 volumio go-librespot[13816]: time="2024-04-14T15:12:26+08:00" level=debug msg="obtained new client token: AABrL19G/46JAKFX4ucSaMPi5DjFSY7mOE4O3fwe6vOfG1khJKnJRxUhn7f/w729T/ck8O7yxsC+RPKc3e5pRyvnl9zwmNwxpCAWbyEmuQpP1U0wI/Pyh9lmAPKAxTsRCcUxOjhkZ8Mo+vClu1y3cJ5xkw3SoEcWifZ5l8CDYB72VvQPe9K6rnSdON/UygkTpG75Jdk3DQliEKDsqXJ87uIPAY6b4FTBk9Q+ghecvR9Tq+mQJzuAGvJYeEqkHU7I" Apr 14 15:12:26 volumio volumio[13424]: SPOTIFY: SETTING SPOTIFY VOLUME 69 Apr 14 15:12:26 volumio volumio[13424]: info: Sending Spotify command with payload to local API: /player/volume Apr 14 15:12:26 volumio volumio[13424]: error: Failed to send command to Spotify local API: /player/volume: Error: Internal Server Error Apr 14 15:12:26 volumio go-librespot[13816]: time="2024-04-14T15:12:26+08: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:12:26 volumio go-librespot[13816]: time="2024-04-14T15:12:26+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:27 volumio go-librespot[13816]: time="2024-04-14T15:12:27+08:00" level=debug msg="completed challenge" Apr 14 15:12:27 volumio go-librespot[13816]: time="2024-04-14T15:12:27+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:28 volumio volumio[13424]: info: Initializing connection to go-librespot Websocket Apr 14 15:12:28 volumio volumio[13424]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:12:30 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:12:30 volumio volumio[13424]: info: CURURI: music-library/USB/A27B-C06F/王杰 Apr 14 15:12:30 volumio volumio[13424]: info: Preload queue cleared Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-一场游戏一场梦.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-为了爱梦一生.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-你是我胸口永远的痛.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-回家.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-她的背影.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-忘了你忘了我.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-忘记你不如忘记自己.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-故事的角色.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-是你是你是你.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-是否我真的一无所有.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Preloading song: music-library/USB/A27B-C06F/王杰/王杰-英雄泪.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-一场游戏一场梦.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E4%B8%80%E5%9C%BA%E6%B8%B8%E6%88%8F%E4%B8%80%E5%9C%BA%E6%A2%A6.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-一场游戏一场梦.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-为了爱梦一生.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E4%B8%BA%E4%BA%86%E7%88%B1%E6%A2%A6%E4%B8%80%E7%94%9F.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-为了爱梦一生.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-你是我胸口永远的痛.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E4%BD%A0%E6%98%AF%E6%88%91%E8%83%B8%E5%8F%A3%E6%B0%B8%E8%BF%9C%E7%9A%84%E7%97%9B.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-你是我胸口永远的痛.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-回家.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E5%9B%9E%E5%AE%B6.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-回家.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-她的背影.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E5%A5%B9%E7%9A%84%E8%83%8C%E5%BD%B1.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-她的背影.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-忘了你忘了我.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E5%BF%98%E4%BA%86%E4%BD%A0%E5%BF%98%E4%BA%86%E6%88%91.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-忘了你忘了我.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-忘记你不如忘记自己.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E5%BF%98%E8%AE%B0%E4%BD%A0%E4%B8%8D%E5%A6%82%E5%BF%98%E8%AE%B0%E8%87%AA%E5%B7%B1.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-忘记你不如忘记自己.mp3 Apr 14 15:12:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 83. Apr 14 15:12:30 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-故事的角色.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E6%95%85%E4%BA%8B%E7%9A%84%E8%A7%92%E8%89%B2.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-故事的角色.mp3 Apr 14 15:12:30 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:30 volumio go-librespot[13824]: Librespot-go daemon starting... Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-是你是你是你.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E6%98%AF%E4%BD%A0%E6%98%AF%E4%BD%A0%E6%98%AF%E4%BD%A0.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-是你是你是你.mp3 Apr 14 15:12:30 volumio go-librespot[13824]: time="2024-04-14T15:12:30+08:00" level=info msg="generated new device id: de9ec24ca9e6b0aa8bb069057f46df27b2b209b9" Apr 14 15:12:30 volumio go-librespot[13824]: time="2024-04-14T15:12:30+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-是否我真的一无所有.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E6%98%AF%E5%90%A6%E6%88%91%E7%9C%9F%E7%9A%84%E4%B8%80%E6%97%A0%E6%89%80%E6%9C%89.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-是否我真的一无所有.mp3 Apr 14 15:12:30 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/王杰/王杰-英雄泪.mp3 in service mpd Apr 14 15:12:30 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2F%E7%8E%8B%E6%9D%B0%2F%E7%8E%8B%E6%9D%B0-%E8%8B%B1%E9%9B%84%E6%B3%AA.mp3&metadata=false Apr 14 15:12:30 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/王杰/王杰-英雄泪.mp3 Apr 14 15:12:31 volumio volumio[13424]: info: Initializing connection to go-librespot Websocket Apr 14 15:12:31 volumio go-librespot[13824]: time="2024-04-14T15:12:31+08:00" level=debug msg="new websocket client" Apr 14 15:12:31 volumio volumio[13424]: info: Connection to go-librespot Websocket established Apr 14 15:12:31 volumio go-librespot[13824]: time="2024-04-14T15:12:31+08:00" level=debug msg="obtained new client token: AADaAaqSgpgChM7DCllffeQ35nrGHrDQEiL/uVHNVj/plgpoMyFi6SkPkRz63lumJBDJzRcCkcSTTjGE6UUL6krvt8yOYsRHeK2bVMNC71F5ocSkUj1sw3K3P5wztGdz7A/DXkZw/hTHqFR74P2TVFp9/4mEVgVh4Jj0S2cRYLHwP51ZIEGnHLKiQQvdT1kNMAisNR6qC0/P1NhesYJNAYOrS1mylDk78cPPqtcEtjFibcbtN+a6y5d6Pv5kyg==" Apr 14 15:12:31 volumio go-librespot[13824]: time="2024-04-14T15:12:31+08: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]" Apr 14 15:12:31 volumio go-librespot[13824]: time="2024-04-14T15:12:31+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:32 volumio go-librespot[13824]: time="2024-04-14T15:12:32+08:00" level=debug msg="completed challenge" Apr 14 15:12:32 volumio go-librespot[13824]: time="2024-04-14T15:12:32+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:32 volumio volumio[13424]: info: Connection to go-librespot Websocket closed Apr 14 15:12:32 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:32 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:34 volumio volumio[13424]: info: Getting Spotify volume Apr 14 15:12:34 volumio volumio[13424]: (node:13424) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:12:34 volumio volumio[13424]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Apr 14 15:12:34 volumio volumio[13424]: (node:13424) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2) Apr 14 15:12:34 volumio volumio[13424]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 11 Apr 14 15:12:34 volumio volumio[13424]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:34 volumio volumio[13424]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:34 volumio volumio[13424]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Apr 14 15:12:34 volumio volumio[13424]: info: CoreCommandRouter::executeOnPlugin: mpd , handleBrowseUri Apr 14 15:12:34 volumio volumio[13424]: info: CURURI: music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01] Apr 14 15:12:34 volumio volumio[13424]: info: Preload queue cleared Apr 14 15:12:35 volumio volumio[13424]: info: Initializing connection to go-librespot Websocket Apr 14 15:12:35 volumio volumio[13424]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Apr 14 15:12:35 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:35 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 84. Apr 14 15:12:35 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:35 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:35 volumio go-librespot[13836]: Librespot-go daemon starting... Apr 14 15:12:35 volumio go-librespot[13836]: time="2024-04-14T15:12:35+08:00" level=info msg="generated new device id: 34981ceb6546dd7075f420f76dd5948fc68b536d" Apr 14 15:12:35 volumio go-librespot[13836]: time="2024-04-14T15:12:35+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:36 volumio go-librespot[13836]: time="2024-04-14T15:12:36+08:00" level=debug msg="obtained new client token: AAAsoH7X7qS6JsTwVcZkDt6/1rqWKRtJ5HtSCwg+3ImplRX4It5DQsBJjBi5oc0StZax0TYFIVV6CVjNPifL+pWtHhw1S87iNDHSM4f6I4WYFgj2W8Q4RJz9CTj0//ZS7g5VLOzTGptUTK8/+wfJncd3VQ2T+uxjjoSR6x1kaBqrmkI5sDSsZGEnnasnSpkouGgzNnq5HAUKh7Es8uwPZVjJG0XWl4ghtPcWz+VIKuHvNrhbwdbf27n6aYaF58J8" Apr 14 15:12:37 volumio go-librespot[13836]: time="2024-04-14T15:12:37+08: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-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Apr 14 15:12:37 volumio go-librespot[13836]: time="2024-04-14T15:12:37+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:37 volumio volumio[13424]: info: Preload queue cleared Apr 14 15:12:37 volumio volumio[13424]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 14 15:12:37 volumio volumio[13424]: info: CoreStateMachine::ClearQueue Apr 14 15:12:37 volumio volumio[13424]: info: CoreStateMachine::stop Apr 14 15:12:37 volumio volumio[13424]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:12:37 volumio volumio[13424]: info: CorePlayQueue::clearPlayQueue Apr 14 15:12:37 volumio volumio[13424]: info: CorePlayQueue::saveQueue Apr 14 15:12:37 volumio volumio[13424]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:12:37 volumio go-librespot[13836]: time="2024-04-14T15:12:37+08:00" level=debug msg="completed challenge" Apr 14 15:12:37 volumio volumio[13424]: info: CoreStateMachine::addQueueItems Apr 14 15:12:37 volumio volumio[13424]: info: CorePlayQueue::addQueueItems Apr 14 15:12:37 volumio volumio[13424]: info: Preload queue cleared Apr 14 15:12:37 volumio volumio[13424]: info: Adding Item to queue: music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01] Apr 14 15:12:37 volumio volumio[13424]: info: Exploding uri music-library/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01] in service mpd Apr 14 15:12:37 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=//extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.ape&metadata=false Apr 14 15:12:37 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.ape Apr 14 15:12:37 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=%3F%3F%3F%3F/%3F%3F%3F%3F%3F%3F%3F%D5%B5%3F01/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.cue&metadata=false Apr 14 15:12:37 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.cue Apr 14 15:12:37 volumio volumio[13424]: info: ALBUMART /albumart?cacheid=378&web=%3F%3F%3F%3F/%3F%3F%3F%3F%3F%3F%3F%D5%B5%3F01/extralarge&path=%2Fmnt%2FUSB%2FA27B-C06F%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FHRP754-2%5B%E9%9B%A8%E6%9E%9C%E5%8F%91%E7%83%A7%E7%A2%9F01%5D%2FCDImage.cue&metadata=false Apr 14 15:12:37 volumio volumio[13424]: info: URI /mnt/USB/A27B-C06F/HRP754-2[雨果发烧碟01]/HRP754-2[雨果发烧碟01]/CDImage.cue Apr 14 15:12:37 volumio volumio[13424]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:12:37 volumio volumio[13424]: Error: Unable to resolve or reject the same promise twice Apr 14 15:12:37 volumio volumio[13424]: at Promise.resolve (/volumio/node_modules/kew/kew.js:140:43) Apr 14 15:12:37 volumio volumio[13424]: at /volumio/app/plugins/music_service/mpd/index.js:2568:21 Apr 14 15:12:37 volumio volumio[13424]: at MpdClient.handleMessage (/volumio/app/plugins/music_service/mpd/lib/mpd.js:77:3) Apr 14 15:12:37 volumio volumio[13424]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:68:12) Apr 14 15:12:37 volumio volumio[13424]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:12) Apr 14 15:12:37 volumio volumio[13424]: at Socket.emit (events.js:315:20) Apr 14 15:12:37 volumio volumio[13424]: at addChunk (internal/streams/readable.js:309:12) Apr 14 15:12:37 volumio volumio[13424]: at readableAddChunk (internal/streams/readable.js:280:11) Apr 14 15:12:37 volumio volumio[13424]: at Socket.Readable.push (internal/streams/readable.js:223:10) Apr 14 15:12:37 volumio volumio[13424]: at Pipe.onStreamRead (internal/stream_base_commons.js:188:23) Apr 14 15:12:37 volumio volumio[13424]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:12:37 volumio go-librespot[13836]: time="2024-04-14T15:12:37+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:37 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:37 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:38 volumio sudo[13853]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-14 15:11 Apr 14 15:12:38 volumio sudo[13853]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:38 volumio sudo[13853]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:38 volumio volumio-remote-updater[517]: [2024-04-14 15:12:38] [error] handle_read_frame error: websocketpp.transport:7 (End of File) Apr 14 15:12:38 volumio volumio-remote-updater[517]: [2024-04-14 15:12:38] [disconnect] Disconnect close local:[1006,End of File] remote:[1006] Apr 14 15:12:38 volumio systemd[1]: volumio.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:38 volumio systemd[1]: volumio.service: Failed with result 'exit-code'. Apr 14 15:12:38 volumio systemd[1]: Started dynamicswap service. Apr 14 15:12:38 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 14 15:12:38 volumio systemd[1]: volumio.service: Service RestartSec=100ms expired, scheduling restart. Apr 14 15:12:38 volumio systemd[1]: volumio.service: Scheduled restart job, restart counter is at 22. Apr 14 15:12:38 volumio systemd[1]: Stopped Volumio Backend Module. Apr 14 15:12:38 volumio systemd[1]: Started Volumio Backend Module. Apr 14 15:12:38 volumio systemd[1]: Started dynamicswap service. Apr 14 15:12:38 volumio systemd[1]: dynamicswap.service: Succeeded. Apr 14 15:12:40 volumio volumio[13863]: info: ------------------------------------------- Apr 14 15:12:40 volumio volumio[13863]: info: ----- Volumio3 ---- Apr 14 15:12:40 volumio volumio[13863]: info: ------------------------------------------- Apr 14 15:12:40 volumio volumio[13863]: info: ----- System startup ---- Apr 14 15:12:40 volumio volumio[13863]: info: ------------------------------------------- Apr 14 15:12:40 volumio volumio[13863]: info: MYVOLUMIO Environment detected Apr 14 15:12:40 volumio volumio[13863]: info: Plugin folders cleanup Apr 14 15:12:40 volumio volumio[13863]: info: Scanning into folder /volumio/app/plugins/ Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category audio_interface Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category miscellanea Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category music_service Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category plugins.json Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category system_controller Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category user_interface Apr 14 15:12:40 volumio volumio[13863]: info: Scanning into folder /data/plugins/ Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category music_service Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category system_controller Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category system_hardware Apr 14 15:12:40 volumio volumio[13863]: info: Scanning category user_interface Apr 14 15:12:40 volumio volumio[13863]: info: Plugin folders cleanup completed Apr 14 15:12:40 volumio volumio[13863]: info: ------------------------------------------- Apr 14 15:12:40 volumio volumio[13863]: info: ----- Core plugins startup ---- Apr 14 15:12:40 volumio volumio[13863]: info: ------------------------------------------- Apr 14 15:12:40 volumio volumio[13863]: info: Loading plugins from folder /volumio/app/plugins/ Apr 14 15:12:40 volumio volumio[13863]: info: Adding plugin upnp to MyMusic Plugins Apr 14 15:12:40 volumio volumio[13863]: info: Adding plugin airplay_emulation to MyMusic Plugins Apr 14 15:12:40 volumio volumio[13863]: info: Adding plugin upnp_browser to MyMusic Plugins Apr 14 15:12:40 volumio volumio[13863]: info: Loading plugins from folder /data/plugins/ Apr 14 15:12:40 volumio volumio[13863]: info: Loading plugin "system"... Apr 14 15:12:40 volumio volumio[13863]: info: Loading plugin "appearance"... Apr 14 15:12:41 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:41 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 85. Apr 14 15:12:41 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:41 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:41 volumio go-librespot[13889]: Librespot-go daemon starting... Apr 14 15:12:41 volumio go-librespot[13889]: time="2024-04-14T15:12:41+08:00" level=info msg="generated new device id: 27d52856c7aa4d61b0ecd80f46be51e7bad3be80" Apr 14 15:12:41 volumio go-librespot[13889]: time="2024-04-14T15:12:41+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:41 volumio volumio[13863]: info: Loading plugin "network"... Apr 14 15:12:41 volumio volumio[13863]: info: Refreshing Cached IP Addresses Apr 14 15:12:41 volumio sudo[13899]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 14 15:12:41 volumio sudo[13899]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:41 volumio sudo[13899]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:41 volumio volumio[13863]: info: Loading plugin "services"... Apr 14 15:12:41 volumio sudo[13901]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 14 15:12:41 volumio sudo[13901]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:41 volumio volumio[13863]: info: Loading plugin "alsa_controller"... Apr 14 15:12:41 volumio sudo[13901]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:41 volumio sudo[13904]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan Apr 14 15:12:41 volumio sudo[13904]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:41 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Apr 14 15:12:41 volumio volumio[13863]: info: Loading plugin "wizard"... Apr 14 15:12:41 volumio volumio[13863]: info: Loading plugin "networkfs"... Apr 14 15:12:41 volumio volumio[13863]: info: Starting Udev Watcher for removable devices Apr 14 15:12:41 volumio volumio[13863]: info: Ignoring mount for partition: boot Apr 14 15:12:41 volumio volumio[13863]: info: Ignoring mount for partition: volumio Apr 14 15:12:41 volumio volumio[13863]: info: Ignoring mount for partition: volumio_data Apr 14 15:12:41 volumio go-librespot[13889]: time="2024-04-14T15:12:41+08:00" level=debug msg="obtained new client token: AACagQ+Nl0x8956CkiEQbT0j5lTUtqefqTrqT2hnuH+Pb5xaJ7n0fW3Gg5z06hAkBfTUK8BbzeCJNE6boi503EodXHDi47XSkECsOapVKJlKfa+dH1QDNv/IVc00PQsnahE/SdiyFoffV9MSs4S0ZDau0dTfRLpMEaj3J7eR+SkxK5/er7WLQSSYRLWLzCRmdn8NvVv5Kj0pWrSTnuckIcPif7ttsYCD75P4/pUPOTw2QVFVcqzYDAuyOW0XpdSW" Apr 14 15:12:41 volumio volumio[13863]: info: Mounting Device A27B-C06F Apr 14 15:12:41 volumio sudo[13913]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount /dev/sda1 /mnt/USB/A27B-C06F -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 14 15:12:41 volumio sudo[13913]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:42 volumio sudo[13913]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:42 volumio volumio[13863]: mount: /media/A27B-C06F: /dev/sda1 already mounted on /media/A27B-C06F. Apr 14 15:12:42 volumio volumio[13863]: error: Failed to mount A27B-C06F: Error: Command failed: /usr/bin/sudo /bin/mount "/dev/sda1" "/mnt/USB/A27B-C06F" -o noatime,dmask=0000,fmask=0000,iocharset=utf8 Apr 14 15:12:42 volumio volumio[13863]: mount: /media/A27B-C06F: /dev/sda1 already mounted on /media/A27B-C06F. Apr 14 15:12:42 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "volumio_command_line_client"... Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "upnp"... Apr 14 15:12:42 volumio volumio[13863]: info: [1713078762058] Starting Upmpd Daemon Apr 14 15:12:42 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "my_music"... Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "mpd"... Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "upnp_browser"... Apr 14 15:12:42 volumio go-librespot[13889]: time="2024-04-14T15:12:42+08: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]" Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "alarm-clock"... Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "airplay_emulation"... Apr 14 15:12:42 volumio volumio[13863]: info: Starting Shairport Sync Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "last_100"... Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "webradio"... Apr 14 15:12:42 volumio go-librespot[13889]: time="2024-04-14T15:12:42+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "i2s_dacs"... Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "volumiodiscovery"... Apr 14 15:12:42 volumio volumio[13863]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 14 15:12:42 volumio volumio[13863]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:12:42 volumio volumio[13863]: *** WARNING *** For more information see Apr 14 15:12:42 volumio volumio[13863]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 14 15:12:42 volumio node[13863]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi. Apr 14 15:12:42 volumio volumio[13863]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:12:42 volumio volumio[13863]: *** WARNING *** For more information see Apr 14 15:12:42 volumio node[13863]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:12:42 volumio node[13863]: *** WARNING *** For more information see Apr 14 15:12:42 volumio node[13863]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi. Apr 14 15:12:42 volumio node[13863]: *** WARNING *** Please fix your application to use the native API of Avahi! Apr 14 15:12:42 volumio node[13863]: *** WARNING *** For more information see Apr 14 15:12:42 volumio volumio[13863]: info: Applying required configuration parameters for plugin volumiodiscovery Apr 14 15:12:42 volumio volumio[13863]: info: Discovery: Started advertising with name: Volumio Apr 14 15:12:42 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Apr 14 15:12:42 volumio volumio[13863]: info: Loading plugin "spop"... Apr 14 15:12:43 volumio sudo[13904]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:43 volumio go-librespot[13889]: time="2024-04-14T15:12:43+08:00" level=debug msg="completed challenge" Apr 14 15:12:43 volumio volumio-remote-updater[517]: [2024-04-14 15:12:43] [connect] Successful connection Apr 14 15:12:43 volumio go-librespot[13889]: time="2024-04-14T15:12:43+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:43 volumio volumio[13863]: info: Plugin youtube2 is not enabled Apr 14 15:12:43 volumio volumio[13863]: info: Loading plugin "ytcr"... Apr 14 15:12:45 volumio volumio[13863]: info: Plugin ytmusic is not enabled Apr 14 15:12:45 volumio volumio[13863]: info: Loading plugin "autostart"... Apr 14 15:12:45 volumio volumio[13863]: info: Applying required configuration parameters for plugin autostart Apr 14 15:12:45 volumio volumio[13863]: info: AutoStart - onVolumioStart - read config.json Apr 14 15:12:45 volumio volumio[13863]: info: Loading plugin "now_playing"... Apr 14 15:12:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 86. Apr 14 15:12:46 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:46 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:46 volumio go-librespot[13958]: Librespot-go daemon starting... Apr 14 15:12:46 volumio go-librespot[13958]: time="2024-04-14T15:12:46+08:00" level=info msg="generated new device id: f2cbc9e2f56b1abfac9550217e7f1e291a465715" Apr 14 15:12:46 volumio go-librespot[13958]: time="2024-04-14T15:12:46+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:46 volumio volumio[13863]: info: Loading plugin "peppy_screensaver"... Apr 14 15:12:47 volumio volumio[13863]: info: Applying required configuration parameters for plugin peppy_screensaver Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "outputs"... Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "albumart"... Apr 14 15:12:47 volumio volumio[13863]: info: Plugin example_plugin is not enabled Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "inputs"... Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "updater_comm"... Apr 14 15:12:47 volumio go-librespot[13958]: time="2024-04-14T15:12:47+08:00" level=debug msg="obtained new client token: AAAJS167oJK2JluHfuhAOIGRt7Dn1Cf66esygrQC4Bb7vdaKLr5msF7IsUqSkGJP2pIMWrjvmJE7ze1akNzz1OT+V0JcGr7bS4s5qknAVLIIYlB+8GnYKdba9qF3aN9ExMq0xwkXj9JNUGp2uF44rDy4HxyEwgS6WZ1neOfnPiGvMSoftBmcOaLTQZ8PQNxDOij0AuPEXjcsoaKCu8OvM376MjMTdF6wpTlTSB4lxA1pFAIJjC7izEfMztntJA==" Apr 14 15:12:47 volumio volumio[13863]: info: Plugin mpdemulation is not enabled Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "rest_api"... Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "websocket"... Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "80s80s"... Apr 14 15:12:47 volumio volumio[13863]: Forking 3 albumart workers Apr 14 15:12:47 volumio volumio[13863]: info: Applying required configuration parameters for plugin 80s80s Apr 14 15:12:47 volumio volumio[13863]: info: [1713078767603] [80s80s] API delay: 30 Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "RoonBridge"... Apr 14 15:12:47 volumio go-librespot[13958]: time="2024-04-14T15:12:47+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:12:47 volumio volumio[13863]: info: Applying required configuration parameters for plugin RoonBridge Apr 14 15:12:47 volumio volumio[13863]: info: Loading plugin "lms"... Apr 14 15:12:47 volumio go-librespot[13958]: time="2024-04-14T15:12:47+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:48 volumio volumio[13863]: info: Loading plugin "podcast"... Apr 14 15:12:48 volumio volumio[13863]: Starting albumart workers Apr 14 15:12:48 volumio go-librespot[13958]: time="2024-04-14T15:12:48+08:00" level=debug msg="completed challenge" Apr 14 15:12:48 volumio volumio[13863]: info: ControllerPodcast::constructor Apr 14 15:12:48 volumio go-librespot[13958]: time="2024-04-14T15:12:48+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:48 volumio volumio[13863]: info: Plugin ir_controller is not enabled Apr 14 15:12:48 volumio volumio[13863]: info: Loading plugin "Systeminfo"... Apr 14 15:12:48 volumio volumio[13863]: Starting albumart workers Apr 14 15:12:48 volumio volumio[13863]: Starting albumart workers Apr 14 15:12:49 volumio volumio[13863]: info: Loading plugin "touch_display"... Apr 14 15:12:49 volumio volumio[13863]: info: Applying required configuration parameters for plugin touch_display Apr 14 15:12:49 volumio volumio[13863]: info: Loading i18n strings for locale zh Apr 14 15:12:49 volumio volumio[13863]: error: touch_display: Fetching language file: Error: i18n file complementing the system language not found. Apr 14 15:12:49 volumio volumio[13863]: Updating browse sources language Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::initPlayerControls Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Apr 14 15:12:49 volumio volumio[13863]: Express server listening on port 3000 Apr 14 15:12:49 volumio volumio[13863]: [Metrics] WebUI: 10s 0.84ms Apr 14 15:12:49 volumio volumio[13863]: info: CoreStateMachine::resetVolumioState Apr 14 15:12:49 volumio volumio[13863]: info: CoreStateMachine::getcurrentVolume Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::volumioRetrievevolume Apr 14 15:12:49 volumio volumio[13863]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS armv7l 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Total Clients: 1 Apr 14 15:12:49 volumio volumio[13863]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 2 Apr 14 15:12:49 volumio volumio[13863]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 3 Apr 14 15:12:49 volumio volumio[13863]: info: CoreStateMachine::pushState Apr 14 15:12:49 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:49 volumio volumio[13863]: info: CoreStateMachine::updateTrackBlock Apr 14 15:12:49 volumio volumio[13863]: info: CorePlayQueue::getTrackBlock Apr 14 15:12:49 volumio volumio[13863]: info: CoreCommandRouter::volumioRetrievevolume Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:50 volumio volumio[13863]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 4 Apr 14 15:12:50 volumio volumio[13863]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 5 Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Apr 14 15:12:50 volumio volumio[13863]: info: Cannot read play queue from file Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::pushState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::setRepeat true single undefined Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::pushState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::setRandom false Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::pushState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioPushState Apr 14 15:12:50 volumio volumio[13863]: info: Setting Device type: Raspberry PI Apr 14 15:12:50 volumio volumio[13863]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Apr 14 15:12:50 volumio volumio[13863]: error: Failed callmethod call: TypeError: Cannot read property 'has' of undefined Apr 14 15:12:50 volumio volumio[13863]: info: Listing playlists Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::getQueue Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getQueue Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:50 volumio volumio[13863]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo Apr 14 15:12:50 volumio volumio[13863]: error: Failed callmethod call: TypeError: Cannot read property 'has' of undefined Apr 14 15:12:50 volumio volumio[13863]: info: Listing playlists Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:12:50 volumio volumio[13863]: info: CoreStateMachine::getQueue Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getQueue Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:50 volumio volumio[13863]: info: Discovery: adding eaa2afdc-3fa0-4a8a-925d-a9b0c99b88c0 Apr 14 15:12:50 volumio volumio[13863]: info: Discovery: Found device Volumio Apr 14 15:12:50 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:50 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 87. Apr 14 15:12:51 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:51 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:51 volumio go-librespot[14039]: Librespot-go daemon starting... Apr 14 15:12:51 volumio go-librespot[14039]: time="2024-04-14T15:12:51+08:00" level=info msg="generated new device id: cf0bf76f5c4a8871c9fc5b854ff86bd71c328d6b" Apr 14 15:12:51 volumio go-librespot[14039]: time="2024-04-14T15:12:51+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:52 volumio sudo[14047]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Apr 14 15:12:52 volumio sudo[14047]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:52 volumio sudo[14047]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:52 volumio volumio[13863]: verbose: New Socket.io Connection to 192.168.2.3 from 192.168.2.5 UA: Mozilla/5.0 (Linux; Android 14; 23127PN0CC Build/UKQ1.230804.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/117.0.0.0 Mobile Safari/537.36 Total Clients: 6 Apr 14 15:12:52 volumio sudo[14050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Apr 14 15:12:52 volumio sudo[14050]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:52 volumio sudo[14050]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:52 volumio sudo[14053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Apr 14 15:12:52 volumio sudo[14053]: pam_unix(sudo:session): session opened for user root by (uid=0) Apr 14 15:12:52 volumio sudo[14053]: pam_unix(sudo:session): session closed for user root Apr 14 15:12:52 volumio volumio[13863]: info: Upmpdcli Daemon Started Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::volumioGetVisibleSources Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:52 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Apr 14 15:12:52 volumio volumio[13863]: info: Received Get System Info Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Apr 14 15:12:52 volumio volumio[13863]: info: Discovery: Getting this device information Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:52 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::volumioGetState Apr 14 15:12:52 volumio volumio[13863]: info: CorePlayQueue::getTrack 0 Apr 14 15:12:52 volumio volumio[13863]: info: Listing playlists Apr 14 15:12:52 volumio volumio[13863]: info: CoreCommandRouter::volumioGetQueue Apr 14 15:12:52 volumio volumio[13863]: info: CoreStateMachine::getQueue Apr 14 15:12:52 volumio volumio[13863]: info: CorePlayQueue::getQueue Apr 14 15:12:52 volumio go-librespot[14039]: time="2024-04-14T15:12:52+08:00" level=debug msg="obtained new client token: AADm525PNOeaE5x3Iz455FadrKCXPOJYl3Od3QcXHlbvy8KVCtfB80FcPjNxYNE81i9joC8MjthZJAWeUH+aiscffeRgkYq+rns+n/0wLwjAVzgN2+z1zgDlISDiYZrl3lj6iVCzmOPVxTt22utz8zvNhT0afVWoSPCG0wkZyHCflbf96cV2CsN6IcGvzm3emd5TH88B0QHZIXqfg2lBNQKjF4YnlxmHHflXafqnMY6T12mjQ847IdUfhCxovwYh" Apr 14 15:12:53 volumio go-librespot[14039]: time="2024-04-14T15:12:53+08: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]" Apr 14 15:12:53 volumio go-librespot[14039]: time="2024-04-14T15:12:53+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:53 volumio go-librespot[14039]: time="2024-04-14T15:12:53+08:00" level=debug msg="completed challenge" Apr 14 15:12:53 volumio go-librespot[14039]: time="2024-04-14T15:12:53+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:53 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:55 volumio volumio-remote-updater[517]: [2024-04-14 15:12:55] [connect] Successful connection Apr 14 15:12:55 volumio volumio-remote-updater[517]: [2024-04-14 15:12:55] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1713078775 101 Apr 14 15:12:55 volumio volumio[13863]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 7 Apr 14 15:12:57 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Apr 14 15:12:57 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 88. Apr 14 15:12:57 volumio systemd[1]: Stopped go-librespot Daemon. Apr 14 15:12:57 volumio systemd[1]: Started go-librespot Daemon. Apr 14 15:12:57 volumio go-librespot[14056]: Librespot-go daemon starting... Apr 14 15:12:57 volumio go-librespot[14056]: time="2024-04-14T15:12:57+08:00" level=info msg="generated new device id: ea87cef0b72c0f63e1fef37360d2a9234c496598" Apr 14 15:12:57 volumio go-librespot[14056]: time="2024-04-14T15:12:57+08:00" level=debug msg="stored credentials not found" Apr 14 15:12:57 volumio go-librespot[14056]: time="2024-04-14T15:12:57+08:00" level=debug msg="obtained new client token: AABq2aDii1rcYvzoDUTvyL7DMvOVPVQM//3etMPTKL7v+eKSeMMJmKHbKUns6/g3mWP0nXKhmmTf5QG95eIyZVl3dKE5FA3WfYXfypngzZf9p2f+6c70UkUO2TAcRu12V9OxvtnqtuquQ10fzLzdNXIdFBiOc/buHpSJ5v/vevboSSicf6aG5GSaHqPkdzFG036wl+kYRdrHgNe0C3nSzJ8ul5pmUWcPSeAQM4pkTxPTDxPJr61N1m8lGwTpOrcq" Apr 14 15:12:58 volumio go-librespot[14056]: time="2024-04-14T15:12:58+08: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Apr 14 15:12:58 volumio go-librespot[14056]: time="2024-04-14T15:12:58+08:00" level=debug msg="completed keyexchange" Apr 14 15:12:58 volumio go-librespot[14056]: time="2024-04-14T15:12:58+08:00" level=debug msg="completed challenge" Apr 14 15:12:59 volumio volumio[13863]: info: Preload queue cleared Apr 14 15:12:59 volumio volumio[13863]: info: CoreCommandRouter::volumioReplaceandPlayItems Apr 14 15:12:59 volumio go-librespot[14056]: time="2024-04-14T15:12:59+08:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with username and spotify token: failed authenticating: failed login: TravelRestriction" Apr 14 15:12:59 volumio volumio[13863]: info: CoreStateMachine::ClearQueue Apr 14 15:12:59 volumio volumio[13863]: info: CoreStateMachine::stop Apr 14 15:12:59 volumio volumio[13863]: info: CoreStateMachine::setConsumeUpdateService undefined Apr 14 15:12:59 volumio volumio[13863]: info: CorePlayQueue::clearPlayQueue Apr 14 15:12:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Apr 14 15:12:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Apr 14 15:12:59 volumio volumio[13863]: info: CorePlayQueue::saveQueue Apr 14 15:12:59 volumio volumio[13863]: info: CoreCommandRouter::volumioPushQueue Apr 14 15:12:59 volumio volumio[13863]: info: CoreStateMachine::addQueueItems Apr 14 15:12:59 volumio volumio[13863]: info: CorePlayQueue::addQueueItems Apr 14 15:12:59 volumio volumio[13863]: info: Preload queue cleared Apr 14 15:12:59 volumio volumio[13863]: info: Adding Item to queue: music-library/USB/A27B-C06F/c8，大峡谷..mp3 Apr 14 15:12:59 volumio volumio[13863]: info: Exploding uri music-library/USB/A27B-C06F/c8，大峡谷..mp3 in service mpd Apr 14 15:12:59 volumio volumio[13863]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:12:59 volumio volumio[13863]: TypeError: Cannot read property 'then' of undefined Apr 14 15:12:59 volumio volumio[13863]: at ControllerMpd.scanFolder (/volumio/app/plugins/music_service/mpd/index.js:2527:19) Apr 14 15:12:59 volumio volumio[13863]: at ControllerMpd.explodeUri (/volumio/app/plugins/music_service/mpd/index.js:2325:21) Apr 14 15:12:59 volumio volumio[13863]: at CoreCommandRouter.explodeUriFromService (/volumio/app/index.js:1359:16) Apr 14 15:12:59 volumio volumio[13863]: at CorePlayQueue.explodeUriFromCache (/volumio/app/playqueue.js:123:24) Apr 14 15:12:59 volumio volumio[13863]: at CorePlayQueue.explodeUri (/volumio/app/playqueue.js:181:19) Apr 14 15:12:59 volumio volumio[13863]: at CorePlayQueue.addQueueItems (/volumio/app/playqueue.js:223:30) Apr 14 15:12:59 volumio volumio[13863]: at CoreStateMachine.addQueueItems (/volumio/app/statemachine.js:247:25) Apr 14 15:12:59 volumio volumio[13863]: at CoreCommandRouter.replaceAndPlay (/volumio/app/index.js:501:23) Apr 14 15:12:59 volumio volumio[13863]: at CoreCommandRouter.playItemsList (/volumio/app/index.js:477:17) Apr 14 15:12:59 volumio volumio[13863]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:118:33) Apr 14 15:12:59 volumio volumio[13863]: at Socket.emit (events.js:315:20) Apr 14 15:12:59 volumio volumio[13863]: at /volumio/node_modules/socket.io/lib/socket.js:503:12 Apr 14 15:12:59 volumio volumio[13863]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Apr 14 15:12:59 volumio volumio[13863]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Apr 14 15:12:59 volumio sudo[14073]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-04-14 15:11 Apr 14 15:12:59 volumio sudo[14073]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"