-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Sat 2025-05-24 18:21:39 CEST. -- May 24 18:21:31 volumiorasp-wohn systemd-timedated[1105]: Changed local time to Sat May 24 18:21:31 2025 May 24 18:21:31 volumiorasp-wohn sudo[1099]: pam_unix(sudo:session): session closed for user root May 24 18:21:31 volumiorasp-wohn volumio-time-update[628]: volumio-time-update-util: System time updated successfully. May 24 18:21:31 volumiorasp-wohn systemd[1]: Starting Daily apt download activities... May 24 18:21:31 volumiorasp-wohn systemd[1]: Started Volumio Time Update Utility. May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Starting Shairport Sync May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Starting Shairport Sync May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Starting Shairport Sync May 24 18:21:31 volumiorasp-wohn volumio[829]: info: CoreCommandRouter::volumioGetState May 24 18:21:31 volumiorasp-wohn volumio[829]: info: CorePlayQueue::getTrack 0 May 24 18:21:31 volumiorasp-wohn volumio[829]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 24 18:21:31 volumiorasp-wohn volumio[829]: SPOTIFY: BQASGRG4Vr8t4jkhXyLx5qkcRL9ZtEbmQd4PYjyHl2b8O73X8lFpPCHFBMOCfnBtt3MQeguocbp1IkZYYpsa17d1HIr2-7xjHvObK9VA_If1QfduhShIIkWpaI7fv22LFVllGvrpF-E1m-EOQh11w0CoTnl_b8x_FDtvzX531VzLqQc4CHKw-KfB3ycf7EVNH9rZU26db625LdT07WBKqulCfjJM9Ay1SODpEz6RN9edoXXnU-QMZBCF9ty7cODv5YSzfCv1dXauClQhV7dM5HpY7pAkppCzJxtbVarWjUim9UI May 24 18:21:31 volumiorasp-wohn volumio[829]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ May 24 18:21:31 volumiorasp-wohn volumio[829]: info: New Spotify access token = BQASGRG4Vr8t4jkhXyLx5qkcRL9ZtEbmQd4PYjyHl2b8O73X8lFpPCHFBMOCfnBtt3MQeguocbp1IkZYYpsa17d1HIr2-7xjHvObK9VA_If1QfduhShIIkWpaI7fv22LFVllGvrpF-E1m-EOQh11w0CoTnl_b8x_FDtvzX531VzLqQc4CHKw-KfB3ycf7EVNH9rZU26db625LdT07WBKqulCfjJM9Ay1SODpEz6RN9edoXXnU-QMZBCF9ty7cODv5YSzfCv1dXauClQhV7dM5HpY7pAkppCzJxtbVarWjUim9UI May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Spotify credentials grant success - running version from March 24, 2019 May 24 18:21:31 volumiorasp-wohn sudo[1118]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 18:21:31 volumiorasp-wohn sudo[1118]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:31 volumiorasp-wohn sudo[1122]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 18:21:31 volumiorasp-wohn sudo[1122]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:31 volumiorasp-wohn sudo[1120]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 24 18:21:31 volumiorasp-wohn sudo[1120]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Discovery: Browse raised the following error Error: dns service error: unknown May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Discovery: A device disappeared from network May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined May 24 18:21:31 volumiorasp-wohn systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 24 18:21:31 volumiorasp-wohn systemd[1]: shairport-sync.service: Succeeded. May 24 18:21:31 volumiorasp-wohn systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Discovery: adding 56bfc599-e99d-45a9-8feb-2c264408da85 May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Discovery: Found device VolumioRasp-Wohn May 24 18:21:31 volumiorasp-wohn volumio[829]: info: CoreCommandRouter::volumioGetState May 24 18:21:31 volumiorasp-wohn volumio[829]: info: CorePlayQueue::getTrack 0 May 24 18:21:31 volumiorasp-wohn ntpd[1038]: Soliciting pool server 213.209.109.44 May 24 18:21:31 volumiorasp-wohn volumio[829]: SPOTIFY: User informations: {"country":"DE","display_name":"Akuhr","email":"andy.kuhr@gmx.de","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/jd7vtmcorkvamtd6lfjv9wd8s"},"followers":{"href":null,"total":1},"href":"https://api.spotify.com/v1/users/jd7vtmcorkvamtd6lfjv9wd8s","id":"jd7vtmcorkvamtd6lfjv9wd8s","images":[],"product":"premium","type":"user","uri":"spotify:user:jd7vtmcorkvamtd6lfjv9wd8s"} May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Spotify Successfully logged in May 24 18:21:31 volumiorasp-wohn volumio[829]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] May 24 18:21:31 volumiorasp-wohn volumio[829]: info: [1748103691369] CoreMusicLibrary::Adding element Spotify May 24 18:21:31 volumiorasp-wohn volumio[829]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources May 24 18:21:31 volumiorasp-wohn volumio[829]: Cannot find translation for source Podcast May 24 18:21:31 volumiorasp-wohn volumio[829]: Cannot find translation for source Spotify May 24 18:21:31 volumiorasp-wohn systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 24 18:21:31 volumiorasp-wohn sudo[1118]: pam_unix(sudo:session): session closed for user root May 24 18:21:31 volumiorasp-wohn sudo[1122]: pam_unix(sudo:session): session closed for user root May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Shairport-Sync Started May 24 18:21:31 volumiorasp-wohn sudo[1120]: pam_unix(sudo:session): session closed for user root May 24 18:21:31 volumiorasp-wohn volumio[829]: Error adding Membership: Error: addMembership EINVAL May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Shairport-Sync Started May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Shairport-Sync Started May 24 18:21:31 volumiorasp-wohn mpd[1090]: May 24 18:21 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 24 18:21:31 volumiorasp-wohn volumio[829]: info: New access token = BQBu8-xjmVvemDhsMk3Ico6Ze9RiE59I5DLkFCrZwiiJkM9lgNz0p8WsDhFRe2eb0K1-2o6v1WYNeluWRE3708eW9bAi3MHl-UVWb53358yBSIjyl9sNo-8gFtB-jooshzUQl7h5iL9goHlBNnXK-pJSv71nQx8a5Kizk42Q6oWTjVivHE0YE7QtDN7kAPPP_UfGuby46DPbhBKvoV0AT_xpligpClqXoutT5RDtu1Ki-awiwI6C68HIuPDa4HN2eSXCTMk4LB3_gP7yDFn1LQ0-iA0rEFs2lpxnTwLuCRzkKf4 May 24 18:21:31 volumiorasp-wohn volumio[829]: info: New access token = BQAL75ZbzSi5y8jaNdyZ8Y447VOv-ZPRvPSZda5YNaoP_3i9oKTd2yhTp7RB9S7bDnrealFMFL-W4AOdvTmJXSzc_0v51nFSP_hB3op8NWp3__HcQSBa3YRwvrKLVLIHq7pz7xVo-kAT5Hh23CRGnd_2A0d3bHWN-CCMVgWAA4R3yFSQrIy5r1OON78DP6-NYlKlzI3v0y_mbOyOI47zpYt_0WWjrHNAgGy1TvjUbfqvHaUWEhEtauv4QkR2h_XdBLymwCwJdUhW-BAB_wbJAlITdKTsHH0o2heoBXr-a8_dBxA May 24 18:21:31 volumiorasp-wohn volumio[829]: info: New access token = BQBOLKVm1OnuGHiLJ8ncsuJ0T4uqwNTly5MK6WH-TmcLXcojXT1opmZKVSrMBRr-IG7syPl5OwDSMWqzXEc0cqNjPwoTVehZN8dykVNnlTzaM8gGCGLf8QTWLPXtjpJyPGLyfqs7njzAFzxst4Z5FfvRdMsATL2Vyp2Bg_1HwWLZ6mj5UKA75ypkGsp-TK2dM629U_6HtooGvn9ZUHLbBA_B_djMDJ96KJ_rsfL4yJgjJGdEZnqa9Ol5hYtYY3MO5J2JBAgTFBgU1mDHGScleqBtWgkkW9IYvdtPCJpEhJ6LcLA May 24 18:21:31 volumiorasp-wohn systemd[1]: Started Music Player Daemon. May 24 18:21:31 volumiorasp-wohn sudo[1030]: pam_unix(sudo:session): session closed for user root May 24 18:21:31 volumiorasp-wohn sudo[1044]: pam_unix(sudo:session): session closed for user root May 24 18:21:31 volumiorasp-wohn volumio[829]: info: Completed starting Core Plugins May 24 18:21:31 volumiorasp-wohn volumio[829]: info: ------------------------------------------- May 24 18:21:31 volumiorasp-wohn volumio[829]: info: ----- MyVolumio plugins startup ---- May 24 18:21:31 volumiorasp-wohn volumio[829]: info: ------------------------------------------- May 24 18:21:31 volumiorasp-wohn volumio[829]: info: [MyVolumio PluginManager] Fetching plans data.... May 24 18:21:31 volumiorasp-wohn volumio[829]: error: MPD error: The expression evaluated to a falsy value: May 24 18:21:31 volumiorasp-wohn volumio[829]: assert.ok(self.idling) May 24 18:21:31 volumiorasp-wohn volumio[829]: error: The expression evaluated to a falsy value: May 24 18:21:31 volumiorasp-wohn volumio[829]: assert.ok(self.idling) May 24 18:21:31 volumiorasp-wohn volumio[829]: info: MPD running with PID1090 May 24 18:21:31 volumiorasp-wohn volumio[829]: ,establishing connection May 24 18:21:31 volumiorasp-wohn volumio[829]: error: MPD error: The expression evaluated to a falsy value: May 24 18:21:31 volumiorasp-wohn volumio[829]: assert.ok(self.idling) May 24 18:21:31 volumiorasp-wohn volumio[829]: error: The expression evaluated to a falsy value: May 24 18:21:31 volumiorasp-wohn volumio[829]: assert.ok(self.idling) May 24 18:21:31 volumiorasp-wohn volumio[829]: error: updateQueue error: null May 24 18:21:31 volumiorasp-wohn nmbd[738]: [2025/05/24 18:21:31.953964, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 24 18:21:31 volumiorasp-wohn nmbd[738]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections May 24 18:21:31 volumiorasp-wohn systemd[1]: Started Samba NMB Daemon. May 24 18:21:32 volumiorasp-wohn systemd[1]: Starting Samba Winbind Daemon... May 24 18:21:32 volumiorasp-wohn ntpd[1038]: Soliciting pool server 185.252.140.126 May 24 18:21:32 volumiorasp-wohn ntpd[1038]: Soliciting pool server 159.69.64.189 May 24 18:21:32 volumiorasp-wohn winbindd[1157]: [2025/05/24 18:21:32.399783, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) May 24 18:21:32 volumiorasp-wohn winbindd[1157]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 May 24 18:21:32 volumiorasp-wohn winbindd[1157]: [2025/05/24 18:21:32.466985, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 24 18:21:32 volumiorasp-wohn systemd[1]: Started Samba Winbind Daemon. May 24 18:21:32 volumiorasp-wohn winbindd[1157]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections May 24 18:21:32 volumiorasp-wohn systemd[1]: Starting Samba SMB Daemon... May 24 18:21:32 volumiorasp-wohn systemd[1]: apt-daily.service: Succeeded. May 24 18:21:32 volumiorasp-wohn systemd[1]: Started Daily apt download activities. May 24 18:21:32 volumiorasp-wohn systemd[1]: Starting Daily apt upgrade and clean activities... May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+02:00" level=info msg="generated new device id: f5f70e6cddab624dfd76a7f84739c96f7bd176fc" May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+02:00" level=debug msg="stored credentials found for jd7vtmcorkvamtd6lfjv9wd8s" May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+02:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+02:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+02:00" level=debug msg="zeroconf server listening on port 39703" May 24 18:21:32 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:32+02:00" level=debug msg="obtained new client token: AAAsAh7HySvt2lMAAtsfcKvJnXiN02Z18MlDOMk79c3u2tMzSvG8POT7SbKbHNsZ747eXI8g3J4hgejODje5rOiCp+tA9Kde028YVmaG23qLKymgKqsJCaZ6pldF/wqedL/4TN+DCs0Q55b8WncGine6dmDa5U3U6+1c0Jq4P7LQ+eqBHcLEbJHzR0T3dlicaJT1zV5PyA5by6rar882DJGxj7faBWWABYlsFt+YC1FC9cS6Gw5FymVMSsw=" May 24 18:21:32 volumiorasp-wohn smbd[1197]: [2025/05/24 18:21:32.988172, 0] ../lib/util/become_daemon.c:138(daemon_ready) May 24 18:21:32 volumiorasp-wohn smbd[1197]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections May 24 18:21:32 volumiorasp-wohn systemd[1]: Started Samba SMB Daemon. May 24 18:21:32 volumiorasp-wohn systemd[1]: Reached target Multi-User System. May 24 18:21:32 volumiorasp-wohn systemd[1]: Reached target Graphical Interface. May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="completed keyexchange" May 24 18:21:33 volumiorasp-wohn systemd[1]: Starting Update UTMP about System Runlevel Changes... May 24 18:21:33 volumiorasp-wohn systemd[1]: apt-daily-upgrade.service: Succeeded. May 24 18:21:33 volumiorasp-wohn systemd[1]: Started Daily apt upgrade and clean activities. May 24 18:21:33 volumiorasp-wohn systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. May 24 18:21:33 volumiorasp-wohn systemd[1]: Started Update UTMP about System Runlevel Changes. May 24 18:21:33 volumiorasp-wohn systemd[1]: Startup finished in 13.195s (kernel) + 18.102s (userspace) = 31.297s. May 24 18:21:33 volumiorasp-wohn ntpd[1038]: Soliciting pool server 162.159.200.123 May 24 18:21:33 volumiorasp-wohn ntpd[1038]: Soliciting pool server 85.220.190.246 May 24 18:21:33 volumiorasp-wohn ntpd[1038]: Soliciting pool server 193.203.3.170 May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="completed challenge" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="authenticated as jd7vtmcorkvamtd6lfjv9wd8s" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="authenticated as jd7vtmcorkvamtd6lfjv9wd8s" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="dealer connection opened" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="initializing zeroconf session, username: jd7vtmcorkvamtd6lfjv9wd8s" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="autoplay enabled: false" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="received connection id: MDQ5OWRjYmQtNDk2YS00NmMxLTk5MTgtNzQxN2I3MTM5ZjMxK2RlYWxlcit0Y3A6Ly8wYWNhNWE0Yy5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMjVGRTE1MjA4QUFDMjg4NjExRDE4RDIzRjJEQUUxNEEzQ0ZFNkU4NEZEOTc2NzcxMkM1NzRCQjVFMzBCNDNEMw==" May 24 18:21:33 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:33+02:00" level=debug msg="put connect state because NEW_DEVICE" May 24 18:21:34 volumiorasp-wohn volumio[829]: info: go-librespot daemon successfully initialized May 24 18:21:34 volumiorasp-wohn ntpd[1038]: Soliciting pool server 131.188.3.222 May 24 18:21:34 volumiorasp-wohn ntpd[1038]: Soliciting pool server 85.215.93.134 May 24 18:21:34 volumiorasp-wohn ntpd[1038]: Soliciting pool server 46.38.241.235 May 24 18:21:34 volumiorasp-wohn ntpd[1038]: Soliciting pool server 213.239.234.28 May 24 18:21:34 volumiorasp-wohn sudo[1253]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=admin,password=kmW9@4G1n1#2023,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.0.111/Multimedia\\Musik /mnt/NAS/EddyNAS May 24 18:21:34 volumiorasp-wohn sudo[1253]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:34 volumiorasp-wohn kernel: CIFS: Attempting to mount //192.168.0.111/Multimedia/Musik May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.0.66:58748->34.158.1.133:4070: use of closed network connection" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="obtained new client token: AACWkEtEVrN4kX15sTZ6Dgpr7dl0QSzWBQmC861Ua3+vVoX7mn0noWA6CqgLe59owIzpowtmDqVFt6iVpiSUXhSCUNlysyLn2Tz/Y65RrLHXgHmxOfI1bX+XWFLWb2MleGp61zqBqKJ2tqo0cPTjXrBACXxGZpkig9+HGLjP8ocENE+Gtdj/gaseeZB2FRQeJ1xAILgKyQcZT08kZZmPAcKdnsE4/6cYltos8V9faAyFQOY3gb3iylfdfjnDgw==" May 24 18:21:35 volumiorasp-wohn kernel: cryptd: max_cpu_qlen set to 1000 May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=info msg="connected to ap-gew4.spotify.com:4070" May 24 18:21:35 volumiorasp-wohn ntpd[1038]: Soliciting pool server 168.119.211.223 May 24 18:21:35 volumiorasp-wohn ntpd[1038]: Soliciting pool server 185.194.239.35 May 24 18:21:35 volumiorasp-wohn ntpd[1038]: Soliciting pool server 5.189.151.39 May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="completed keyexchange" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="completed challenge" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="authenticated as b26giigdu9qoavguijmut6q93" May 24 18:21:35 volumiorasp-wohn sudo[1253]: pam_unix(sudo:session): session closed for user root May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="authenticated as b26giigdu9qoavguijmut6q93" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="dealer connection opened" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=info msg="accepted zeroconf user b26giigdu9qoavguijmut6q93 from S21 von Linus" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="autoplay enabled: false" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="received connection id: MGZlMGI5ODctYWE3Yi00MzcxLWFkNTItZDE0ODk0ZmU4NGRiK2RlYWxlcit0Y3A6Ly8wYWNhNTkwNC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNTdENTg3NDUwQjQ0NDc3MTQ2NkNGOTgyRUEyNkE3NUNENDc2RjVEQTlGNTU4QkQ4MjcxQjRFOENGRDc3QzJGMA==" May 24 18:21:35 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:35+02:00" level=debug msg="put connect state because NEW_DEVICE" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="handling transfer player command from 5e1557a030e644b2fe0f58fd76fb6431f146acf8" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:0ej4YNptsYtdPEYN5y4bvc" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=trace msg="fetched new page 0 with 224 items (list: 224)" uri="spotify:playlist:0ej4YNptsYtdPEYN5y4bvc" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="shuffled context with seed 17547412175164467980 (len: 224, keep: 146)" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="loading track (paused: true, position: 300ms)" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=trace msg="emitting websocket event: will_play" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="selected format OGG_VORBIS_320 (7a2a58e076cb6633f364d61ba4ab57afb1debb6c)" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="requested aes key for file 7a2a58e076cb6633f364d61ba4ab57afb1debb6c, gid: 2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 24 18:21:36 volumiorasp-wohn ntpd[1038]: Soliciting pool server 130.162.220.39 May 24 18:21:36 volumiorasp-wohn ntpd[1038]: Soliciting pool server 2a01:4f8:211:2093::1 May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1697" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="fetched first chunk of 17, total size is 8586741 bytes" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=trace msg="seek to 300ms (diff: 300ms, samples: 13230, bytes: 0)" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="created new output device" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=info msg="loaded track \"Pasilda - Knee Deep Mix\" (paused: true, position: 300ms, duration: 209500ms, prefetched: false)" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="fetched chunk 2/16, size: 524288" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn volumio[829]: info: Volumio Network Manager: Network status updated: 1 May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=trace msg="emitting websocket event: metadata" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=trace msg="emitting websocket event: active" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="sending successful reply for dealer request" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="fetched chunk 3/16, size: 524288" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="fetched chunk 1/16, size: 524288" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=trace msg="emitting websocket event: paused" May 24 18:21:36 volumiorasp-wohn sudo[1297]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 May 24 18:21:36 volumiorasp-wohn sudo[1297]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:36 volumiorasp-wohn sudo[1297]: pam_unix(sudo:session): session closed for user root May 24 18:21:36 volumiorasp-wohn sudo[1299]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 May 24 18:21:36 volumiorasp-wohn sudo[1299]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:36 volumiorasp-wohn sudo[1299]: pam_unix(sudo:session): session closed for user root May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 24 18:21:36 volumiorasp-wohn sudo[1303]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service May 24 18:21:36 volumiorasp-wohn sudo[1303]: pam_unix(sudo:session): session opened for user root by (uid=0) May 24 18:21:36 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:36+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1297" May 24 18:21:36 volumiorasp-wohn systemd[1]: Started UPnP Renderer front-end to MPD. May 24 18:21:36 volumiorasp-wohn sudo[1303]: pam_unix(sudo:session): session closed for user root May 24 18:21:36 volumiorasp-wohn volumio[829]: info: Upmpdcli Daemon Started May 24 18:21:36 volumiorasp-wohn volumio[829]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory May 24 18:21:37 volumiorasp-wohn volumio[829]: info: Initializing connection to go-librespot Websocket May 24 18:21:37 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:37+02:00" level=debug msg="new websocket client" May 24 18:21:37 volumiorasp-wohn ntpd[1038]: Soliciting pool server 87.106.25.161 May 24 18:21:37 volumiorasp-wohn volumio[829]: info: Connection to go-librespot Websocket established May 24 18:21:37 volumiorasp-wohn volumio[1305]: Generating RSA private key, 4096 bit long modulus (2 primes) May 24 18:21:37 volumiorasp-wohn volumio[829]: Cannot compose Albumart path May 24 18:21:37 volumiorasp-wohn volumio[829]: Cannot compose Albumart path May 24 18:21:37 volumiorasp-wohn volumio[829]: Cannot compose Albumart path May 24 18:21:37 volumiorasp-wohn volumio[829]: Cannot compose Albumart path May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=debug msg="handling resume player command from 5e1557a030e644b2fe0f58fd76fb6431f146acf8" May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=trace msg="seek to 300ms (diff: 300ms, samples: 13230, bytes: 0)" uri="spotify:track:2BUL7sF7y5oBYUQarVCukR" May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=debug msg="resume track at 0ms" May 24 18:21:38 volumiorasp-wohn volumio[829]: Cannot compose Albumart path May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:21:38 volumiorasp-wohn volumio[829]: Cannot compose Albumart path May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=trace msg="scheduling prefetch in 179s" May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=debug msg="sending successful reply for dealer request" May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 24 18:21:38 volumiorasp-wohn go-librespot[1107]: time="2025-05-24T18:21:38+02:00" level=trace msg="emitting websocket event: playing" May 24 18:21:39 volumiorasp-wohn ntpd[1038]: receive: Unexpected origin timestamp 0xebdc7092.493704cb does not match aorg 0000000000.00000000 from server@193.203.3.170 xmt 0xebdc7093.598558ed May 24 18:21:39 volumiorasp-wohn ntpd[1038]: receive: Unexpected origin timestamp 0xebdc7092.4932f77c does not match aorg 0000000000.00000000 from server@46.38.241.235 xmt 0xebdc7093.5987996a May 24 18:21:39 volumiorasp-wohn volumio[829]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:2BUL7sF7y5oBYUQarVCukR","play_origin":"playlist"}} May 24 18:21:39 volumiorasp-wohn volumio[829]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 18:21:39 volumiorasp-wohn volumio[829]: TypeError: Cannot read property 'service' of undefined May 24 18:21:39 volumiorasp-wohn volumio[829]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) May 24 18:21:39 volumiorasp-wohn volumio[829]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) May 24 18:21:39 volumiorasp-wohn volumio[829]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) May 24 18:21:39 volumiorasp-wohn volumio[829]: at WebSocket.emit (events.js:315:20) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver.emit (events.js:315:20) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) May 24 18:21:39 volumiorasp-wohn volumio[829]: at writeOrBuffer (internal/streams/writable.js:358:12) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Receiver.Writable.write (internal/streams/writable.js:303:10) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) May 24 18:21:39 volumiorasp-wohn volumio[829]: at Socket.emit (events.js:315:20) May 24 18:21:39 volumiorasp-wohn volumio[829]: at addChunk (internal/streams/readable.js:309:12) May 24 18:21:39 volumiorasp-wohn volumio[829]: at readableAddChunk (internal/streams/readable.js:284:9) May 24 18:21:39 volumiorasp-wohn volumio[829]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 24 18:21:39 volumiorasp-wohn sudo[1330]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-24 18:20 May 24 18:21:39 volumiorasp-wohn sudo[1330]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"