-- Logs begin at Thu 2019-02-14 11:11:59 CET, end at Sat 2024-11-30 09:42:28 CET. -- Nov 30 09:42:19 volumio systemd-timedated[1057]: Changed local time to Sat Nov 30 09:42:19 2024 Nov 30 09:42:19 volumio sudo[1042]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio volumio-time-update[600]: volumio-time-update-util: System time updated successfully. Nov 30 09:42:19 volumio systemd[1]: Starting Daily apt download activities... Nov 30 09:42:19 volumio volumio[827]: info: Volumio Calling Home Nov 30 09:42:19 volumio systemd[1]: Started Volumio Time Update Utility. Nov 30 09:42:19 volumio volumio[827]: info: MPD Permissions set Nov 30 09:42:19 volumio volumio[827]: info: MPD Permissions set Nov 30 09:42:19 volumio volumio[827]: info: Spotify config file written Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio sudo[1084]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Nov 30 09:42:19 volumio sudo[1084]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 30 09:42:19 volumio systemd[1]: Started go-librespot Daemon. Nov 30 09:42:19 volumio go-librespot[1097]: Librespot-go daemon starting... Nov 30 09:42:19 volumio sudo[1084]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio volumio[827]: info: Volumio called home Nov 30 09:42:19 volumio volumio[827]: info: Discovery: A device disappeared from network Nov 30 09:42:19 volumio volumio[827]: info: Discovery: Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Nov 30 09:42:19 volumio volumio[827]: info: Starting Shairport Sync Nov 30 09:42:19 volumio volumio[827]: info: Starting Shairport Sync Nov 30 09:42:19 volumio sudo[1105]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 30 09:42:19 volumio sudo[1105]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:19 volumio sudo[1109]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 30 09:42:19 volumio sudo[1109]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:19 volumio volumio[827]: info: Starting Shairport Sync Nov 30 09:42:19 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 30 09:42:19 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 30 09:42:19 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 30 09:42:19 volumio sudo[1117]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 30 09:42:19 volumio sudo[1117]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:19 volumio ntpd[943]: Soliciting pool server 185.252.140.126 Nov 30 09:42:19 volumio volumio[827]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Nov 30 09:42:19 volumio ntpd[943]: Soliciting pool server 168.119.211.223 Nov 30 09:42:19 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 30 09:42:19 volumio sudo[1105]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio sudo[1109]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 30 09:42:19 volumio systemd[1]: shairport-sync.service: Main process exited, code=killed, status=15/TERM Nov 30 09:42:19 volumio systemd[1]: shairport-sync.service: Succeeded. Nov 30 09:42:19 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 30 09:42:19 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 30 09:42:19 volumio sudo[1117]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio volumio[827]: info: Shairport-Sync Started Nov 30 09:42:19 volumio volumio[827]: Error adding Membership: Error: addMembership EINVAL Nov 30 09:42:19 volumio volumio[827]: info: Shairport-Sync Started Nov 30 09:42:19 volumio volumio[827]: info: Shairport-Sync Started Nov 30 09:42:19 volumio volumio[827]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 30 09:42:19 volumio volumio[827]: SPOTIFY: BQBazI1tqb26O9yfadbV0T9RjzoMrtJA5BLvFa6p2QwQo93KP3PkgrtJaOkxgvYyjLlOAFLR3QY8WljY6vnyOwYvUKi2vRL3Iz_oUIAki_FtujkFaJqzJrZsfBmdmS-G2ZKPA4k4VCu76s5rg9gA0fMIa8xlkL9csrywN32a94TSPbWzBRn0BEgS5jNhzGkytuByxj20yMTZs-3P9MPhM9iCK2w11xJ1Nl7BxjZI2Ujzuh0r_qDPafW0eN83xTN6Nad7DugTzeVWXU8 Nov 30 09:42:19 volumio volumio[827]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Nov 30 09:42:19 volumio volumio[827]: info: New Spotify access token = BQBazI1tqb26O9yfadbV0T9RjzoMrtJA5BLvFa6p2QwQo93KP3PkgrtJaOkxgvYyjLlOAFLR3QY8WljY6vnyOwYvUKi2vRL3Iz_oUIAki_FtujkFaJqzJrZsfBmdmS-G2ZKPA4k4VCu76s5rg9gA0fMIa8xlkL9csrywN32a94TSPbWzBRn0BEgS5jNhzGkytuByxj20yMTZs-3P9MPhM9iCK2w11xJ1Nl7BxjZI2Ujzuh0r_qDPafW0eN83xTN6Nad7DugTzeVWXU8 Nov 30 09:42:19 volumio volumio[827]: info: Spotify credentials grant success - running version from March 24, 2019 Nov 30 09:42:19 volumio go-librespot[1097]: time="2024-11-30T09:42:19+01:00" level=info msg="generated new device id: dd07df877e5996e15dee1069db77c39de6f9de11" Nov 30 09:42:19 volumio go-librespot[1097]: time="2024-11-30T09:42:19+01:00" level=debug msg="stored credentials found for 0f7o3pl68dmie1lfijtzrwbyj" Nov 30 09:42:19 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Nov 30 09:42:19 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Nov 30 09:42:19 volumio mpd[1051]: Nov 30 09:42 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 30 09:42:19 volumio systemd[1]: Started Music Player Daemon. Nov 30 09:42:19 volumio sudo[1014]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio sudo[1024]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:19 volumio volumio[827]: info: Completed starting Core Plugins Nov 30 09:42:19 volumio volumio[827]: info: ------------------------------------------- Nov 30 09:42:19 volumio volumio[827]: info: ----- MyVolumio plugins startup ---- Nov 30 09:42:19 volumio volumio[827]: info: ------------------------------------------- Nov 30 09:42:19 volumio volumio[827]: info: [MyVolumio PluginManager] Fetching plans data.... Nov 30 09:42:19 volumio volumio[827]: error: MPD error: The expression evaluated to a falsy value: Nov 30 09:42:19 volumio volumio[827]: assert.ok(self.idling) Nov 30 09:42:19 volumio volumio[827]: error: The expression evaluated to a falsy value: Nov 30 09:42:19 volumio volumio[827]: assert.ok(self.idling) Nov 30 09:42:19 volumio volumio[827]: info: MPD running with PID1051 Nov 30 09:42:19 volumio volumio[827]: ,establishing connection Nov 30 09:42:19 volumio volumio[827]: error: MPD error: The expression evaluated to a falsy value: Nov 30 09:42:19 volumio volumio[827]: assert.ok(self.idling) Nov 30 09:42:19 volumio volumio[827]: error: The expression evaluated to a falsy value: Nov 30 09:42:19 volumio volumio[827]: assert.ok(self.idling) Nov 30 09:42:19 volumio volumio[827]: error: updateQueue error: null Nov 30 09:42:19 volumio systemd[1]: apt-daily.service: Succeeded. Nov 30 09:42:19 volumio systemd[1]: Started Daily apt download activities. Nov 30 09:42:19 volumio go-librespot[1097]: time="2024-11-30T09:42:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 30 09:42:19 volumio go-librespot[1097]: time="2024-11-30T09:42:19+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Nov 30 09:42:19 volumio go-librespot[1097]: time="2024-11-30T09:42:19+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Nov 30 09:42:19 volumio go-librespot[1097]: time="2024-11-30T09:42:19+01:00" level=debug msg="zeroconf server listening on port 39783" Nov 30 09:42:20 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="obtained new client token: AAAycw1A2G8PgkIrIyTTWmARbPiYGrngHYZ/DP4+LArrhyuu9rZGQSwq/0Uxz4+RC0ndVld/o2mOIH43QkWTraBtqEphpJd2HIzVaawBKWKdaDb8JfUakwa3+GgaCJI8tIRkrxH2bsdD4SViVRVzQRFaK/DVJ8IKCbGTPfkc8AVrC2WKzN/zhIYZqgJCREDIfTLJGgl+BUIzoCSIys/tlKj7YQOKGEz3NxfbTubHE1T6tSRd4Tq87VCltA==" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="completed keyexchange" Nov 30 09:42:20 volumio ntpd[943]: Soliciting pool server 128.127.67.142 Nov 30 09:42:20 volumio ntpd[943]: Soliciting pool server 85.214.133.14 Nov 30 09:42:20 volumio nmbd[761]: [2024/11/30 09:42:20.474958, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 30 09:42:20 volumio systemd[1]: Started Samba NMB Daemon. Nov 30 09:42:20 volumio nmbd[761]: daemon_ready: STATUS=daemon 'nmbd' finished starting up and ready to serve connections Nov 30 09:42:20 volumio systemd[1]: Starting Samba Winbind Daemon... Nov 30 09:42:20 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Nov 30 09:42:20 volumio systemd[1]: Started Daily apt upgrade and clean activities. Nov 30 09:42:20 volumio ntpd[943]: Soliciting pool server 185.233.107.180 Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="completed challenge" Nov 30 09:42:20 volumio winbindd[1213]: [2024/11/30 09:42:20.685096, 0] ../source3/winbindd/winbindd_cache.c:3160(initialize_winbindd_cache) Nov 30 09:42:20 volumio winbindd[1213]: initialize_winbindd_cache: clearing cache and re-creating with version number 2 Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="authenticated as 0f7o3pl68dmie1lfijtzrwbyj" Nov 30 09:42:20 volumio winbindd[1213]: [2024/11/30 09:42:20.741619, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 30 09:42:20 volumio systemd[1]: Started Samba Winbind Daemon. Nov 30 09:42:20 volumio winbindd[1213]: daemon_ready: STATUS=daemon 'winbindd' finished starting up and ready to serve connections Nov 30 09:42:20 volumio systemd[1]: Starting Samba SMB Daemon... Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="authenticated as 0f7o3pl68dmie1lfijtzrwbyj" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="dealer connection opened" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="initializing zeroconf session, username: 0f7o3pl68dmie1lfijtzrwbyj" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="autoplay enabled: false" Nov 30 09:42:20 volumio go-librespot[1097]: time="2024-11-30T09:42:20+01:00" level=debug msg="received connection id: ZjFmYzE3ODQtNGVhMi00OWViLThkZTYtMDIyMTJhMjIwM2I3K2RlYWxlcit0Y3A6Ly8wYWNhNWEwZC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArNDdBQjEyMTY0MzA3NEJEM0U5QUEyOEY2NzNENzQyMDU0RUIwNzQyREFGNzQ0QUY3ODFGODdCQTJEMkQ2MzkxMQ==" Nov 30 09:42:21 volumio go-librespot[1097]: time="2024-11-30T09:42:21+01:00" level=debug msg="put connect state because NEW_DEVICE" Nov 30 09:42:21 volumio smbd[1221]: [2024/11/30 09:42:21.107075, 0] ../lib/util/become_daemon.c:138(daemon_ready) Nov 30 09:42:21 volumio systemd[1]: Started Samba SMB Daemon. Nov 30 09:42:21 volumio smbd[1221]: daemon_ready: STATUS=daemon 'smbd' finished starting up and ready to serve connections Nov 30 09:42:21 volumio systemd[1]: Reached target Multi-User System. Nov 30 09:42:21 volumio systemd[1]: Reached target Graphical Interface. Nov 30 09:42:21 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes... Nov 30 09:42:21 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded. Nov 30 09:42:21 volumio systemd[1]: Started Update UTMP about System Runlevel Changes. Nov 30 09:42:21 volumio systemd[1]: Startup finished in 13.837s (kernel) + 19.911s (userspace) = 33.749s. Nov 30 09:42:21 volumio ntpd[943]: Soliciting pool server 141.144.230.32 Nov 30 09:42:21 volumio ntpd[943]: Soliciting pool server 79.133.44.140 Nov 30 09:42:21 volumio ntpd[943]: Soliciting pool server 80.153.195.191 Nov 30 09:42:21 volumio ntpd[943]: Soliciting pool server 194.50.19.117 Nov 30 09:42:22 volumio volumio[827]: info: go-librespot daemon successfully initialized Nov 30 09:42:22 volumio ntpd[943]: Soliciting pool server 217.144.138.234 Nov 30 09:42:22 volumio ntpd[943]: Soliciting pool server 148.251.235.164 Nov 30 09:42:22 volumio ntpd[943]: Soliciting pool server 90.187.112.137 Nov 30 09:42:23 volumio volumio[827]: info: Discovery: adding 088eb5f8-25aa-4cc7-96d1-29fb29a2ae6e Nov 30 09:42:23 volumio volumio[827]: info: Discovery: Found device Volumio Nov 30 09:42:23 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Nov 30 09:42:23 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Nov 30 09:42:23 volumio ntpd[943]: Soliciting pool server 85.10.240.253 Nov 30 09:42:23 volumio ntpd[943]: Soliciting pool server 85.215.229.230 Nov 30 09:42:23 volumio volumio[827]: SPOTIFY: User informations: {"country":"DE","display_name":"Ingo","email":"i.z@gmx.net","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/0f7o3pl68dmie1lfijtzrwbyj"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/0f7o3pl68dmie1lfijtzrwbyj","id":"0f7o3pl68dmie1lfijtzrwbyj","images":[],"product":"premium","type":"user","uri":"spotify:user:0f7o3pl68dmie1lfijtzrwbyj"} Nov 30 09:42:23 volumio volumio[827]: info: Spotify Successfully logged in Nov 30 09:42:23 volumio volumio[827]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Nov 30 09:42:23 volumio volumio[827]: info: [1732956143579] CoreMusicLibrary::Adding element Spotify Nov 30 09:42:23 volumio volumio[827]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 30 09:42:23 volumio volumio[827]: Cannot find translation for source Spotify Nov 30 09:42:23 volumio volumio[827]: info: New access token = BQD15GE7nhBc5uucLvElYv8IRqkcdoLfg-P5TFufn7GInUBhu8fBKLz1YDEA1Odo0nlI7FBezkI7aAtfoOQYY7_aRUgzsGv3Ui-ZBz4VYZNpbG7b1kRR8G286uE-FFZrWzjNZ67bYgCGzOVUP9tRs4EeHyLKXokUSauMnxMjkHNiqH9Z8JjyIGL8a8IBuRJNp7XbvtgIagUjhzEiXsFfXpN_Gncdrg7PFmfQnM_nm7fd5Wn3Ib6-4m3WurbT0NQCkS09fCuMA_DpiNs Nov 30 09:42:23 volumio volumio[827]: info: New access token = BQCPAqC_1OOr7iBfJp_R8FFWee30TwS_LawHhQ_FOoiVvKjk8f9fAMdq2L46uexisk1FPLtTVfMp7zIOPvg8WDGt7YUB761_4srvrEjp-ummYGlSuh9tpzr06gKY-S3sD3tSTgjdfLhaq8lAf4qc1NaE2UHYQUzVCeGEuumtWUgZM-yPCMTiI7uyCBqqGrgBvDSN5-JPz494pz8X5rg-r2wH5EIWw6XiOno3endViIsujEqb_hEaZ1sGuRhJRxC_3-oX3Gfnb9wPGII Nov 30 09:42:23 volumio volumio[827]: info: New access token = BQDPOLRXSDQgeeM-LyQEhtHXe0UOBW0NNxMrsuUKBrmU0UIOHBsIXGrqxaBKQBSibj0yRwQmAdxbnYA3Bc6vXANvn2E6UKFICxw3NEsbE-bCdUitw0B-qIRZ_6mLaNV58m4ydVklA4QygxTqLVJfEuSLgPZcCxghlnt98ddaYU-r7nQwTz6M1LQNO3yZjRmGFw_Tml_lRq4_PjrF6w0a9-p0GaoBFWdYX1lRwQbxbsQoriEHafehdFq7Ub1zQobRqIYvPlHwBXLxpps Nov 30 09:42:24 volumio ntpd[943]: Soliciting pool server 78.47.118.0 Nov 30 09:42:24 volumio ntpd[943]: Soliciting pool server 2001:418:3ff::1:53 Nov 30 09:42:24 volumio volumio[827]: info: Discovery: this is already registered, 088eb5f8-25aa-4cc7-96d1-29fb29a2ae6e Nov 30 09:42:24 volumio volumio[827]: info: Discovery: Found device Volumio Nov 30 09:42:24 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Nov 30 09:42:24 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Nov 30 09:42:24 volumio volumio[827]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Nov 30 09:42:25 volumio volumio[827]: info: Volumio Network Manager: Network status updated: 1 Nov 30 09:42:25 volumio volumio[827]: info: Initializing connection to go-librespot Websocket Nov 30 09:42:25 volumio go-librespot[1097]: time="2024-11-30T09:42:25+01:00" level=debug msg="new websocket client" Nov 30 09:42:25 volumio volumio[827]: info: Connection to go-librespot Websocket established Nov 30 09:42:25 volumio sudo[1248]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Nov 30 09:42:25 volumio sudo[1248]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:25 volumio sudo[1248]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:25 volumio sudo[1250]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Nov 30 09:42:25 volumio sudo[1250]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:25 volumio sudo[1250]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:25 volumio sudo[1254]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Nov 30 09:42:25 volumio sudo[1254]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 30 09:42:26 volumio ntpd[943]: receive: Unexpected origin timestamp 0xeaf54e71.79027879 does not match aorg 0000000000.00000000 from server@168.119.211.223 xmt 0xeaf54e72.8c25e6de Nov 30 09:42:26 volumio ntpd[943]: receive: Unexpected origin timestamp 0xeaf54e71.78fabe50 does not match aorg 0000000000.00000000 from server@78.47.118.0 xmt 0xeaf54e72.8c4bf9bf Nov 30 09:42:26 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Nov 30 09:42:26 volumio ntpd[943]: receive: Unexpected origin timestamp 0xeaf54e71.78fe81d1 does not match aorg 0000000000.00000000 from server@80.153.195.191 xmt 0xeaf54e72.8c855936 Nov 30 09:42:26 volumio ntpd[943]: receive: Unexpected origin timestamp 0xeaf54e71.79019df2 does not match aorg 0000000000.00000000 from server@85.214.133.14 xmt 0xeaf54e72.8c524906 Nov 30 09:42:26 volumio sudo[1254]: pam_unix(sudo:session): session closed for user root Nov 30 09:42:26 volumio volumio[827]: info: Upmpdcli Daemon Started Nov 30 09:42:26 volumio volumio[1256]: Generating RSA private key, 4096 bit long modulus (2 primes) Nov 30 09:42:26 volumio go-librespot[1097]: time="2024-11-30T09:42:26+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Nov 30 09:42:26 volumio go-librespot[1097]: time="2024-11-30T09:42:26+01:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.2.9:51782->34.158.1.133:4070: use of closed network connection" Nov 30 09:42:26 volumio go-librespot[1097]: time="2024-11-30T09:42:26+01:00" level=debug msg="obtained new client token: AAAzPwPh9Pr/+e/nZAQLppkwi4+s1Bdup3LKIAa4YrFJkgSiOf9SHKLrao9npfy7jW0i0B9GDUbmjuA9rh4QjdIKtBccfisVbjEH57b8drh9s8HysEkyr7y4qzAmsYNG2no24UfMIO6v3Fd/PG1FHl2SRPnOwR29OsIRTNnDmkEjLgA5Y/rbTxdl8h+Wz7WKlV8JRLoqtX7U+BeO1ze02M/o4tmtm40OVVQb84VQsnLr8iHJMGASlgkLlzwz" Nov 30 09:42:26 volumio go-librespot[1097]: time="2024-11-30T09:42:26+01:00" level=debug msg="completed keyexchange" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="completed challenge" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="authenticated as okkklq9j1li3lhm51pdglivgj" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="authenticated as okkklq9j1li3lhm51pdglivgj" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="dealer connection opened" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=info msg="accepted zeroconf user okkklq9j1li3lhm51pdglivgj from Lina's Handy" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="autoplay enabled: false" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="received connection id: ODk2MDQxNzgtOGFmYS00OWQ3LTg5MDUtOGQwNjljNWRiNDg1K2RlYWxlcit0Y3A6Ly8wYWNhNWEwOC5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMDhGRkFCNTgxQjRCRDc2NjdBMzc0NzVGNTcxNEUzRTVDRkE5QUQxRTFBRkI1MzkxN0Y1MjUwMENGMDU5NUE1NA==" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="put connect state because NEW_DEVICE" Nov 30 09:42:27 volumio go-librespot[1097]: time="2024-11-30T09:42:27+01:00" level=debug msg="handling transfer player command from 12c0442660a2ab9e37ce91cbdae32a5fac76c827" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="resolved context of track" uri="spotify:station:track:3dDaZtrQzWW9IPJz4Az2oY" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:3dDaZtrQzWW9IPJz4Az2oY" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=error msg="failed fetching next tracks" error="failed moving to next index 50 (page 1): failed fetching next page: invalid status code from page at radio-apollo/v3/tracks/spotify:station:track:3dDaZtrQzWW9IPJz4Az2oY?salt=722877&autoplay=false&count=50&isVideo=false&prev_tracks=3dDaZtrQzWW9IPJz4Az2oY,4xGLfAGlNJVvpC1X1lCWAf,0QdiWE0KoN1KDs8FYwtpAJ,2YgHhD3Tuifloa4ju1N0g2,1v1cijv1qjMJ5o9OvMWACS,540JMtXlUGkUn6ITsryjRM,7bkUa9kDFGxgCC7d36dzFI,5M5kGo3XKHte94y3Jf7qxi,5f036FYvbMqmiF3PJczy1y,1CfXReZpkv5l10m1Zc1mGn,4AKX4MsoqMnhrJ2qDh3tCJ,0h1d2sv6RIxB8e0xiEIJ45,4P3DSLxQLg0il3pEBKsPTJ,3F8vtandirkggs3aOXOGgX,4lnLVhGxv1YnJEJIComb9x,2XbeHu0WGHipc8BtrkLMy3,3vD832LKUskbgpZGr78EKK,2CWXVE0h91nurJi1DtO37q,1c7usoqJL4tjHyh1XwoIsD,5XjFrra3olQBIBa2gcZ4So,6tW9IfjsF6D1YdJkIE7AQl,65i0i1aixjk7GoJaMEnKqy,6KiPf8zHwaBK7VMHZZ1ReL,65caFJtNCC6xdSBUXZivw2,3Vw4SxsPsVwG4xwK3Il0mP,05jxlV1d75GkrMEZCP9qHQ,6Cy2aCQUeJy3aTAI7P9ZwJ,7x8yoh4fgdDqGWM75W4CMZ,5hYfbAxovSsKWYRSelsAhz,2NY6OwXheFjzMvdVmw69mQ,5ttt3HxKyYr8Ni9TuH4Rdd,1Yj9IP75nNp6JntNYOxrzH,277uZsTtRCyTXlGyTGXjlR,3Iq8XToI0I9KSnqovkv1AV,7Et1qLWqYwfV8MLSoLzTyo,7nrjWF8qnqT59lIFLLh1Di,7kcpqmRY795L9YgfsZWXNF,5bRqdjdVRfd1zOY1xesNgu,4Ofqdvr2QPmbbJQNfOJFwV,1iICY8qXRZKHThDyFYJql1,57SWVEd1IxRmm8gWpupukS,6j7jmp8dTzFxLPtwW58ixp,1sFB74eq5lH4ifqAfAi6kU,3VNQ3hvh3m59RKIjYD6B2U,0B4gBXd4XLXGvaBl7pI2vL,3PzNf1AAj2nK46vljp3pAx,1aZjtwIU9TmxBtzS2ZL0C9,0rt8k3nUqVpM4lc5KRdkOf,45roVuodsjHKjPeEL0Gru1,3aeRQ9xGSLAUg1R7CZ5QKv&minimal=true: 502" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="loading track (paused: true, position: 207655ms)" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=trace msg="emitting websocket event: will_play" Nov 30 09:42:28 volumio volumio[827]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6tW9IfjsF6D1YdJkIE7AQl","play_origin":""}} Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="selected format OGG_VORBIS_320 (4b5c6f074c8b3681916051852b0c6c31c805cbd8)" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="requested aes key for file 4b5c6f074c8b3681916051852b0c6c31c805cbd8, gid: 6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1686" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="fetched first chunk of 16, total size is 8032032 bytes" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1287" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="fetched chunk 15/15, size: 167712" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=trace msg="seek to 207655ms (diff: 152ms, samples: 9157585, bytes: 7992735)" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01: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" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="created new output device" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=info msg="loaded track \"Tanz für mich\" (paused: true, position: 207655ms, duration: 209986ms, prefetched: false)" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=trace msg="emitting websocket event: metadata" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=trace msg="emitting websocket event: active" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="sending successful reply for dealer request" Nov 30 09:42:28 volumio volumio[827]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6tW9IfjsF6D1YdJkIE7AQl","name":"Tanz für mich","artist_names":["Provinz"],"album_name":"Wir bauten uns Amerika","album_cover_url":"https://i.scdn.co/image/ab67616d00001e021fa7fee88f9468cceb7b48ba","position":207655,"duration":209986,"release_date":"year:2020 month:7 day:17","track_number":2,"disc_number":1}} Nov 30 09:42:28 volumio volumio[827]: SPOTIFY: received: {"type":"active","data":null} Nov 30 09:42:28 volumio volumio[827]: info: Aligning Spotify Volume to Volumio Volume Nov 30 09:42:28 volumio volumio[827]: info: CoreCommandRouter::volumioGetState Nov 30 09:42:28 volumio volumio[827]: info: CorePlayQueue::getTrack 0 Nov 30 09:42:28 volumio volumio[827]: info: Setting Spotify Volume from Volumio: 100 Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:6tW9IfjsF6D1YdJkIE7AQl" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 30 09:42:28 volumio go-librespot[1097]: time="2024-11-30T09:42:28+01:00" level=trace msg="emitting websocket event: paused" Nov 30 09:42:28 volumio volumio[827]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6tW9IfjsF6D1YdJkIE7AQl","play_origin":""}} Nov 30 09:42:28 volumio volumio[827]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 30 09:42:28 volumio volumio[827]: TypeError: Cannot read property 'service' of undefined Nov 30 09:42:28 volumio volumio[827]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Nov 30 09:42:28 volumio volumio[827]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Nov 30 09:42:28 volumio volumio[827]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Nov 30 09:42:28 volumio volumio[827]: at WebSocket.emit (events.js:315:20) Nov 30 09:42:28 volumio volumio[827]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Nov 30 09:42:28 volumio volumio[827]: at Receiver.emit (events.js:315:20) Nov 30 09:42:28 volumio volumio[827]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Nov 30 09:42:28 volumio volumio[827]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Nov 30 09:42:28 volumio volumio[827]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Nov 30 09:42:28 volumio volumio[827]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Nov 30 09:42:28 volumio volumio[827]: at writeOrBuffer (internal/streams/writable.js:358:12) Nov 30 09:42:28 volumio volumio[827]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Nov 30 09:42:28 volumio volumio[827]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Nov 30 09:42:28 volumio volumio[827]: at Socket.emit (events.js:315:20) Nov 30 09:42:28 volumio volumio[827]: at addChunk (internal/streams/readable.js:309:12) Nov 30 09:42:28 volumio volumio[827]: at readableAddChunk (internal/streams/readable.js:284:9) Nov 30 09:42:28 volumio volumio[827]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 30 09:42:28 volumio sudo[1281]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-30 09:41 Nov 30 09:42:28 volumio sudo[1281]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"