-- Logs begin at Thu 2024-05-09 10:50:32 CEST, end at Sat 2024-05-11 11:11:46 CEST. -- May 11 11:10:04 volumio volumio-remote-updater[349]: [2024-05-11 11:10:04] [connect] Successful connection May 11 11:10:08 volumio systemd[1]: apt-daily.service: Succeeded. May 11 11:10:08 volumio systemd[1]: Started Daily apt download activities. May 11 11:10:08 volumio systemd[1]: Starting Daily apt upgrade and clean activities... May 11 11:10:14 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. May 11 11:10:14 volumio systemd[1]: Started Daily apt upgrade and clean activities. May 11 11:10:14 volumio volumio[727]: info: Loading plugin "soundcloud"... May 11 11:10:18 volumio volumio[727]: info: Loading plugin "spop"... May 11 11:10:19 volumio volumio-remote-updater[349]: [2024-05-11 11:10:19] [connect] Successful connection May 11 11:10:22 volumio wpa_supplicant[626]: wlan0: WPA: Group rekeying completed with 3c:a6:2f:60:2a:57 [GTK=CCMP] May 11 11:10:25 volumio volumio[727]: info: Loading plugin "ytcr"... May 11 11:10:34 volumio volumio-remote-updater[349]: [2024-05-11 11:10:34] [connect] Successful connection May 11 11:10:43 volumio volumio[727]: info: Loading plugin "outputs"... May 11 11:10:43 volumio volumio[727]: info: Loading plugin "albumart"... May 11 11:10:44 volumio volumio[727]: info: Plugin example_plugin is not enabled May 11 11:10:44 volumio volumio[727]: info: Loading plugin "inputs"... May 11 11:10:44 volumio volumio[727]: info: Loading plugin "updater_comm"... May 11 11:10:46 volumio volumio[727]: info: Plugin mpdemulation is not enabled May 11 11:10:46 volumio volumio[727]: info: Loading plugin "rest_api"... May 11 11:10:46 volumio volumio[727]: info: Loading plugin "websocket"... May 11 11:10:46 volumio volumio[727]: info: Loading i18n strings for locale de May 11 11:10:46 volumio volumio[727]: Updating browse sources language May 11 11:10:47 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:10:48 volumio volumio[727]: Forking 1 albumart workers May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::initPlayerControls May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:49 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 11:10:49 volumio volumio[727]: Express server listening on port 3000 May 11 11:10:49 volumio volumio-remote-updater[349]: [2024-05-11 11:10:49] [connect] Successful connection May 11 11:10:49 volumio volumio[727]: [Metrics] WebUI: 82s 686.54ms May 11 11:10:50 volumio volumio[727]: info: CoreStateMachine::resetVolumioState May 11 11:10:50 volumio volumio[727]: info: CoreStateMachine::getcurrentVolume May 11 11:10:50 volumio volumio[727]: info: CoreCommandRouter::volumioRetrievevolume May 11 11:10:50 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:10:51 volumio sudo[982]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 11 11:10:51 volumio sudo[982]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:10:51 volumio sudo[984]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 11 11:10:51 volumio sudo[984]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:10:51 volumio sudo[982]: pam_unix(sudo:session): session closed for user root May 11 11:10:51 volumio sudo[984]: pam_unix(sudo:session): session closed for user root May 11 11:10:53 volumio volumio-remote-updater[349]: [2024-05-11 11:10:53] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1715418649 101 May 11 11:10:54 volumio volumio[727]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 May 11 11:10:54 volumio volumio[727]: info: VolumeController:: Volume=98 Mute =false May 11 11:10:54 volumio volumio[727]: info: CoreStateMachine::pushState May 11 11:10:54 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:10:54 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 11:10:54 volumio volumio[727]: info: CoreCommandRouter::volumioPushState May 11 11:10:54 volumio volumio[727]: info: CoreStateMachine::updateTrackBlock May 11 11:10:54 volumio volumio[727]: info: CorePlayQueue::getTrackBlock May 11 11:10:54 volumio volumio[727]: info: CoreCommandRouter::volumioRetrievevolume May 11 11:10:54 volumio volumio[727]: info: Reloading queue from file May 11 11:10:55 volumio volumio[727]: info: Setting Device type: Raspberry PI May 11 11:10:55 volumio volumio[727]: info: CoreStateMachine::setRepeat null single undefined May 11 11:10:55 volumio volumio[727]: info: CoreStateMachine::pushState May 11 11:10:55 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:10:55 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 11 11:10:55 volumio volumio[727]: info: CoreCommandRouter::volumioPushState May 11 11:10:55 volumio volumio[727]: info: CoreStateMachine::setRandom null May 11 11:10:55 volumio volumio[727]: info: CoreStateMachine::pushState May 11 11:10:55 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:10:55 volumio volumio[727]: info: CoreCommandRouter::volumioPushState May 11 11:10:55 volumio volumio[727]: info: Discovery: A device disappeared from network May 11 11:10:55 volumio volumio[727]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined May 11 11:10:56 volumio volumio[727]: info: Discovery: adding b0468504-c7dc-41fa-ab2e-440c78cb884f May 11 11:10:56 volumio volumio[727]: info: Discovery: Found device Volumio May 11 11:10:56 volumio volumio[727]: info: CoreCommandRouter::volumioGetState May 11 11:10:56 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:10:56 volumio sudo[997]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 11 11:10:56 volumio sudo[997]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:10:56 volumio volumio[727]: info: VolumeController:: Volume=98 Mute =false May 11 11:10:56 volumio volumio[727]: info: CoreStateMachine::pushState May 11 11:10:56 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:10:56 volumio volumio[727]: info: CoreCommandRouter::volumioPushState May 11 11:10:56 volumio volumio[727]: info: Discovery: this is already registered, b0468504-c7dc-41fa-ab2e-440c78cb884f May 11 11:10:56 volumio systemd[1]: Started UPnP Renderer front-end to MPD. May 11 11:10:56 volumio sudo[997]: pam_unix(sudo:session): session closed for user root May 11 11:10:56 volumio volumio[727]: info: Discovery: Found device Volumio May 11 11:10:56 volumio volumio[727]: info: CoreCommandRouter::volumioGetState May 11 11:10:56 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:10:56 volumio volumio[727]: info: Completed loading Core Plugins May 11 11:10:57 volumio volumio[727]: info: Preparing to generate the ALSA configuration file May 11 11:10:57 volumio volumio[727]: info: Upmpdcli Daemon Started May 11 11:10:57 volumio volumio[727]: error: Upnp client error: Error: connect ECONNREFUSED 127.0.0.1:6600 May 11 11:10:57 volumio volumio[727]: info: Asound.conf file unchanged, so no further update is needed May 11 11:10:57 volumio volumio[727]: info: Output device has changed, restarting MPD May 11 11:10:57 volumio volumio[727]: info: Output device has changed, restarting Shairport Sync May 11 11:10:57 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:10:57 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:10:57 volumio sudo[1002]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 11:10:58 volumio sudo[1002]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:10:58 volumio sudo[1002]: pam_unix(sudo:session): session closed for user root May 11 11:10:58 volumio sudo[1004]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 11:10:58 volumio sudo[1004]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:10:58 volumio systemd[1]: Listening on mpd.socket. May 11 11:10:58 volumio systemd[1]: Starting Music Player Daemon... May 11 11:10:58 volumio volumio[727]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:10:59 volumio volumio[727]: info: ___________ START PLUGINS ___________ May 11 11:10:59 volumio volumio[727]: info: ControllerMpd::onStart: Initializing MPD May 11 11:10:59 volumio volumio[727]: info: Creating MPD Configuration file May 11 11:10:59 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam May 11 11:10:59 volumio volumio[727]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:10:59 volumio volumio[727]: info: [1715418659994] CoreMusicLibrary::Adding element Medienserver May 11 11:11:00 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:11:00 volumio sudo[1014]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 11 11:11:00 volumio sudo[1014]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:11:00 volumio sudo[1014]: pam_unix(sudo:session): session closed for user root May 11 11:11:00 volumio sudo[1016]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 11 11:11:00 volumio sudo[1016]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:11:01 volumio systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 11 11:11:01 volumio systemd[1]: mpd.service: Succeeded. May 11 11:11:01 volumio systemd[1]: Stopped Music Player Daemon. May 11 11:11:01 volumio systemd[1]: Starting Music Player Daemon... May 11 11:11:01 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:01 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:11:02 volumio volumio[727]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:11:02 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:02 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:11:03 volumio volumio[727]: Starting albumart workers May 11 11:11:03 volumio volumio[727]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 11 11:11:03 volumio volumio[727]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:11:03 volumio volumio[727]: info: [1715418663634] CoreMusicLibrary::Adding element Last_100 May 11 11:11:03 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:11:03 volumio volumio[727]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:11:03 volumio volumio[727]: info: [1715418663716] CoreMusicLibrary::Adding element Webradio May 11 11:11:03 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:11:03 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 11 11:11:04 volumio volumio[727]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:11:04 volumio volumio[727]: info: [1715418664189] CoreMusicLibrary::Adding element Bandcamp Discover May 11 11:11:04 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:11:04 volumio volumio[727]: Cannot find translation for source Bandcamp Discover May 11 11:11:04 volumio volumio[727]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:11:04 volumio volumio[727]: info: [1715418664457] CoreMusicLibrary::Adding element SoundCloud May 11 11:11:04 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:11:04 volumio volumio[727]: Cannot find translation for source Bandcamp Discover May 11 11:11:04 volumio volumio[727]: Cannot find translation for source SoundCloud May 11 11:11:04 volumio volumio[727]: info: Creating Spotify config file May 11 11:11:04 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:08 volumio volumio[727]: info: Volumio Calling Home May 11 11:11:13 volumio volumio[727]: info: MPD Permissions set May 11 11:11:13 volumio volumio[727]: info: MPD Permissions set May 11 11:11:13 volumio volumio[727]: info: Volumio called home May 11 11:11:13 volumio volumio[727]: info: Spotify config file written May 11 11:11:15 volumio sudo[1030]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service May 11 11:11:15 volumio sudo[1030]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:11:15 volumio systemd[1]: Started go-librespot Daemon. May 11 11:11:15 volumio go-librespot[1032]: Librespot-go daemon starting... May 11 11:11:15 volumio sudo[1030]: pam_unix(sudo:session): session closed for user root May 11 11:11:16 volumio go-librespot[1032]: time="2024-05-11T11:11:16+02:00" level=info msg="generated new device id: 45aaa9a2f6b1acc06cbe1a2211116723e658f8f8" May 11 11:11:16 volumio go-librespot[1032]: time="2024-05-11T11:11:16+02:00" level=debug msg="stored credentials found for bernie5514" May 11 11:11:17 volumio volumio[727]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:17 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:18 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:19 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 11 11:11:19 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 11 11:11:20 volumio volumio[727]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 11 11:11:20 volumio volumio[727]: SPOTIFY: BQBLiJ9P42qzwNtfH9pAGivAB7qkNWb-fsR481uQPfGF6LsrEwBsacxguAYkyVwL4sn9joGz3VKtmjxCundUs1F83H2FvIURpNxLyqkVKFAxzZaaoH5wWm-joGV3ET1ZGBTwIU716gf0_HL8d1kkPtIalCMJ7ygqTUgRRGcc1IheQe01xFizk5uFsdyvh_C-W-HHZMPoZGrmwQiQ0OUzZ0ZTErZ4W-BQPXadRYfyUIn8CidvUwM May 11 11:11:20 volumio volumio[727]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 11 11:11:20 volumio volumio[727]: info: New Spotify access token = BQBLiJ9P42qzwNtfH9pAGivAB7qkNWb-fsR481uQPfGF6LsrEwBsacxguAYkyVwL4sn9joGz3VKtmjxCundUs1F83H2FvIURpNxLyqkVKFAxzZaaoH5wWm-joGV3ET1ZGBTwIU716gf0_HL8d1kkPtIalCMJ7ygqTUgRRGcc1IheQe01xFizk5uFsdyvh_C-W-HHZMPoZGrmwQiQ0OUzZ0ZTErZ4W-BQPXadRYfyUIn8CidvUwM May 11 11:11:20 volumio volumio[727]: info: Spotify credentials grant success - running version from March 24, 2019 May 11 11:11:22 volumio volumio[727]: info: Starting Shairport Sync May 11 11:11:23 volumio volumio[727]: info: Starting Shairport Sync May 11 11:11:23 volumio go-librespot[1032]: time="2024-05-11T11:11:23+02:00" level=debug msg="obtained new client token: AACnR0k8i9sLX304NaGDgDJxTuAcIWIut3yZCjH+7h71uRiDaKIxb3X+XLjWDvVfK5QjIhzJhua+o+MmJt4O5m9Kcqq2fZgyOrvDyTUNKPT/GCPL8WXyu8AIgdIa33wSvsZFpDT6zT/XmKhv1ln+IFl0e6fu9jrgFTiVvCP8zDvyB5D/oolYtY+LEUedMeSRjao7nEzHsDFY0EsgaEIf+SFtagpDxMNzv4YB8wDbar9TRL8zStBROj7MQBrtcQ==" May 11 11:11:23 volumio volumio[727]: info: Starting Shairport Sync May 11 11:11:23 volumio sudo[1056]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:11:23 volumio sudo[1056]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:11:24 volumio go-librespot[1032]: time="2024-05-11T11:11:24+02:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" May 11 11:11:24 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 11:11:24 volumio sudo[1058]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:11:24 volumio systemd[1]: shairport-sync.service: Succeeded. May 11 11:11:24 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 11:11:24 volumio sudo[1058]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:11:24 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:11:24 volumio sudo[1056]: pam_unix(sudo:session): session closed for user root May 11 11:11:25 volumio sudo[1061]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 11 11:11:25 volumio sudo[1061]: pam_unix(sudo:session): session opened for user root by (uid=0) May 11 11:11:25 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 11:11:25 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 11 11:11:25 volumio systemd[1]: shairport-sync.service: Succeeded. May 11 11:11:25 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 11:11:25 volumio go-librespot[1032]: time="2024-05-11T11:11:25+02:00" level=debug msg="completed keyexchange" May 11 11:11:25 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:11:25 volumio sudo[1058]: pam_unix(sudo:session): session closed for user root May 11 11:11:26 volumio go-librespot[1032]: time="2024-05-11T11:11:26+02:00" level=debug msg="completed challenge" May 11 11:11:26 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 11 11:11:26 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM May 11 11:11:26 volumio systemd[1]: shairport-sync.service: Succeeded. May 11 11:11:26 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 11 11:11:26 volumio go-librespot[1032]: time="2024-05-11T11:11:26+02:00" level=debug msg="authenticated as bernie5514" May 11 11:11:26 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 11 11:11:26 volumio volumio[727]: info: Shairport-Sync Started May 11 11:11:26 volumio sudo[1061]: pam_unix(sudo:session): session closed for user root May 11 11:11:26 volumio volumio[727]: Error adding Membership: Error: addMembership EINVAL May 11 11:11:26 volumio volumio[727]: info: go-librespot daemon successfully initialized May 11 11:11:27 volumio volumio[727]: info: Shairport-Sync Started May 11 11:11:27 volumio volumio[727]: info: Shairport-Sync Started May 11 11:11:27 volumio go-librespot[1032]: time="2024-05-11T11:11:27+02:00" level=debug msg="authenticated as bernie5514" May 11 11:11:27 volumio go-librespot[1032]: time="2024-05-11T11:11:27+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 11 11:11:27 volumio go-librespot[1032]: time="2024-05-11T11:11:27+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 11 11:11:27 volumio volumio[727]: info: CoreCommandRouter::volumioGetState May 11 11:11:27 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:11:28 volumio go-librespot[1032]: time="2024-05-11T11:11:28+02:00" level=debug msg="dealer connection opened" May 11 11:11:28 volumio go-librespot[1032]: time="2024-05-11T11:11:28+02:00" level=debug msg="received connection id: OWFjMDkzMmQtZDFmYy00ZmRjLWIxOTMtNWQzNTEzNWE5Njc0K2RlYWxlcit0Y3A6Ly9nZXc0LWRlYWxlci1hLXpzemMuZ2V3NC5zcG90aWZ5Lm5ldDo1NzAwKzY3MzIyQUNCRDlEOEI0QTUxMDAxMTFEQkY4M0RDMzU2QjAwMzcyMEQ5NDRENTkyRUE3ODkzMTIyNTVEQjFFOUU=" May 11 11:11:28 volumio go-librespot[1032]: time="2024-05-11T11:11:28+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 11 11:11:28 volumio go-librespot[1032]: time="2024-05-11T11:11:28+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 11 11:11:28 volumio volumio[727]: SPOTIFY: User informations: {"display_name":"bernie5514","external_urls":{"spotify":"https://open.spotify.com/user/bernie5514"},"href":"https://api.spotify.com/v1/users/bernie5514","id":"bernie5514","images":[],"type":"user","uri":"spotify:user:bernie5514","followers":{"href":null,"total":5},"country":"DE","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"christoph.suel@web.de"} May 11 11:11:28 volumio volumio[727]: info: Spotify Successfully logged in May 11 11:11:28 volumio volumio[727]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 11 11:11:28 volumio volumio[727]: info: [1715418688673] CoreMusicLibrary::Adding element Spotify May 11 11:11:28 volumio volumio[727]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 11 11:11:28 volumio volumio[727]: Cannot find translation for source Bandcamp Discover May 11 11:11:28 volumio volumio[727]: Cannot find translation for source SoundCloud May 11 11:11:28 volumio volumio[727]: Cannot find translation for source Spotify May 11 11:11:29 volumio go-librespot[1032]: time="2024-05-11T11:11:29+02:00" level=debug msg="put connect state because NEW_DEVICE" May 11 11:11:29 volumio go-librespot[1032]: time="2024-05-11T11:11:29+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 11 11:11:29 volumio go-librespot[1032]: time="2024-05-11T11:11:29+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 11 11:11:29 volumio go-librespot[1032]: time="2024-05-11T11:11:29+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 513" May 11 11:11:29 volumio volumio[727]: info: Initializing connection to go-librespot Websocket May 11 11:11:29 volumio go-librespot[1032]: time="2024-05-11T11:11:29+02:00" level=debug msg="new websocket client" May 11 11:11:30 volumio volumio[727]: info: Connection to go-librespot Websocket established May 11 11:11:30 volumio go-librespot[1032]: time="2024-05-11T11:11:30+02:00" level=debug msg="handling transfer player command from f39c60921995127f4eb351bd972514e6c818cf7d" May 11 11:11:30 volumio go-librespot[1032]: time="2024-05-11T11:11:30+02:00" level=trace msg="fetched new page 0 with 12 items (list: 12)" May 11 11:11:30 volumio go-librespot[1032]: time="2024-05-11T11:11:30+02:00" level=debug msg="loading track spotify:track:78JPy0KV547MIfWTSJRebU (paused: false, position: 8674ms)" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=trace msg="emitting websocket event: will_play" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1557" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=debug msg="selected format OGG_VORBIS_320 for spotify:track:78JPy0KV547MIfWTSJRebU" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=debug msg="requested aes key for file ef7f9740e400f527246f3e10ede86c5e84df42b6, gid: 78JPy0KV547MIfWTSJRebU" May 11 11:11:31 volumio go-librespot[1032]: time="2024-05-11T11:11:31+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1331" May 11 11:11:31 volumio mpd[1019]: May 11 11:11 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 11 11:11:31 volumio volumio[727]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:78JPy0KV547MIfWTSJRebU","play_origin":"playlist"}} May 11 11:11:31 volumio systemd[1]: Started Music Player Daemon. May 11 11:11:31 volumio sudo[1016]: pam_unix(sudo:session): session closed for user root May 11 11:11:31 volumio sudo[1004]: pam_unix(sudo:session): session closed for user root May 11 11:11:32 volumio volumio[727]: Upnp client error: Error: This socket has been ended by the other party May 11 11:11:32 volumio volumio[727]: Upnp client error: Error: This socket has been ended by the other party May 11 11:11:32 volumio volumio[727]: Upnp client error: Error: This socket has been ended by the other party May 11 11:11:33 volumio volumio[727]: info: Getting Spotify volume May 11 11:11:33 volumio go-librespot[1032]: time="2024-05-11T11:11:33+02:00" level=debug msg="fetched first chunk of 27, total size is 13730396 bytes" May 11 11:11:33 volumio volumio[727]: info: [yt-cast-receiver] DIAL server listening on port 8098 May 11 11:11:34 volumio volumio[727]: info: CoreCommandRouter::volumioRetrievevolume May 11 11:11:34 volumio go-librespot[1032]: time="2024-05-11T11:11:34+02:00" level=trace msg="seek to 8674ms (diff: 57ms, samples: 382523, bytes: 318396)" May 11 11:11:35 volumio go-librespot[1032]: time="2024-05-11T11:11:35+02:00" level=info msg="loaded track \"Mas Que Nada - Live 1993 Version\" (uri: spotify:track:78JPy0KV547MIfWTSJRebU, paused: false, position: 8674ms, duration: 314306ms)" May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="fetched chunk 3/26, size: 524288" May 11 11:11:36 volumio volumio[727]: error: MPD error: The expression evaluated to a falsy value: May 11 11:11:36 volumio volumio[727]: assert.ok(self.idling) May 11 11:11:36 volumio volumio[727]: error: The expression evaluated to a falsy value: May 11 11:11:36 volumio volumio[727]: assert.ok(self.idling) May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=trace msg="emitting websocket event: metadata" May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=trace msg="emitting websocket event: active" May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="sending successful reply for delaer request" May 11 11:11:36 volumio volumio[727]: info: MPD running with PID1019 May 11 11:11:36 volumio volumio[727]: ,establishing connection May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 11 11:11:36 volumio volumio[727]: error: updateQueue error: null May 11 11:11:36 volumio volumio[727]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:78JPy0KV547MIfWTSJRebU","name":"Mas Que Nada - Live 1993 Version","artist_names":["Al Jarreau"],"album_name":"Tenderness","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0207bcff4375d83db49f2d9678","position":8674,"duration":314306,"release_date":"year:1994","track_number":1,"disc_number":1}} May 11 11:11:36 volumio volumio[727]: SPOTIFY: received: {"type":"active","data":null} May 11 11:11:36 volumio volumio[727]: info: Aligning Spotify Volume to Volumio Volume May 11 11:11:36 volumio volumio[727]: info: CoreCommandRouter::volumioGetState May 11 11:11:36 volumio volumio[727]: info: CorePlayQueue::getTrack 0 May 11 11:11:36 volumio volumio[727]: info: Setting Spotify Volume from Volumio: 98 May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 11 11:11:36 volumio go-librespot[1032]: time="2024-05-11T11:11:36+02:00" level=trace msg="emitting websocket event: playing" May 11 11:11:37 volumio volumio[727]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:78JPy0KV547MIfWTSJRebU","play_origin":"playlist"}} May 11 11:11:37 volumio volumio[727]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 11:11:37 volumio volumio[727]: TypeError: Cannot read property 'service' of undefined May 11 11:11:37 volumio volumio[727]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) May 11 11:11:37 volumio volumio[727]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:262:18) May 11 11:11:37 volumio volumio[727]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) May 11 11:11:37 volumio volumio[727]: at WebSocket.emit (events.js:315:20) May 11 11:11:37 volumio volumio[727]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1203:20) May 11 11:11:37 volumio volumio[727]: at Receiver.emit (events.js:315:20) May 11 11:11:37 volumio volumio[727]: at /data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:608:16 May 11 11:11:37 volumio volumio[727]: at internal/process/task_queues.js:149:7 May 11 11:11:37 volumio volumio[727]: at AsyncResource.runInAsyncScope (async_hooks.js:197:9) May 11 11:11:37 volumio volumio[727]: at AsyncResource.runMicrotask (internal/process/task_queues.js:146:8) May 11 11:11:37 volumio volumio[727]: at processTicksAndRejections (internal/process/task_queues.js:93:5) May 11 11:11:37 volumio volumio[727]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 11 11:11:38 volumio go-librespot[1032]: time="2024-05-11T11:11:38+02:00" level=debug msg="fetched chunk 2/26, size: 524288" May 11 11:11:38 volumio go-librespot[1032]: time="2024-05-11T11:11:38+02:00" level=debug msg="fetched chunk 1/26, size: 524288" May 11 11:11:42 volumio go-librespot[1032]: time="2024-05-11T11:11:42+02:00" level=debug msg="fetched chunk 4/26, size: 524288" May 11 11:11:46 volumio sudo[1125]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-05-11 11:10 May 11 11:11:46 volumio sudo[1125]: 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="e7445fab547cd22e23d9bef72406cfb610bc1d7d" VOLUMIO_FE_VERSION="5d5e99f8f803b3ec5fc5e8ca13bb4023600f3eee" VOLUMIO_FE3_VERSION="a6ae210575eae1ff43f06ab71e1cd17576840623" VOLUMIO_BE_VERSION="a9e1e1dd6072ffb15c0fcb8938d9ea0d8900c0da" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 24 Apr 2024 02:10:14 PM CEST" VOLUMIO_VERSION="3.661" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="5bdefd4af4423fd17aacb83a8538bf1f"