-- Logs begin at Mon 2024-07-22 19:22:29 CEST, end at Thu 2024-09-05 10:10:52 CEST. -- Sep 05 10:09:03 volumio volumio[810]: info: Setting up bzip2 (1.0.6-9.2~deb10u2) ... Sep 05 10:09:03 volumio volumio[810]: info: Setting up python3-wheel (0.32.3-2) ... Sep 05 10:09:03 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:07 volumio volumio[810]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Sep 05 10:09:07 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Sep 05 10:09:07 volumio volumio[810]: info: Creating Spotify config file Sep 05 10:09:07 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 05 10:09:07 volumio volumio[810]: info: Spotify config file written Sep 05 10:09:07 volumio sudo[7173]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 05 10:09:07 volumio sudo[7173]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:09:07 volumio systemd[1]: Stopping go-librespot Daemon... Sep 05 10:09:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Sep 05 10:09:07 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Sep 05 10:09:07 volumio systemd[1]: Stopped go-librespot Daemon. Sep 05 10:09:07 volumio volumio[810]: info: Connection to go-librespot Websocket closed Sep 05 10:09:07 volumio volumio[810]: info: Connection to go-librespot Websocket closed Sep 05 10:09:07 volumio systemd[1]: Started go-librespot Daemon. Sep 05 10:09:07 volumio sudo[7173]: pam_unix(sudo:session): session closed for user root Sep 05 10:09:07 volumio go-librespot[7177]: Librespot-go daemon starting... Sep 05 10:09:08 volumio go-librespot[7177]: time="2024-09-05T10:09:08+02:00" level=info msg="generated new device id: 99569e9ca26fb993dc8c0cc771c683843ccca018" Sep 05 10:09:08 volumio volumio[810]: info: Setting up python3-multidict (4.5.2-1) ... Sep 05 10:09:10 volumio go-librespot[7177]: time="2024-09-05T10:09:10+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-guc3.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 05 10:09:10 volumio go-librespot[7177]: time="2024-09-05T10:09:10+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]" Sep 05 10:09:10 volumio go-librespot[7177]: time="2024-09-05T10:09:10+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]" Sep 05 10:09:10 volumio go-librespot[7177]: time="2024-09-05T10:09:10+02:00" level=debug msg="zeroconf server listening on port 34075" Sep 05 10:09:10 volumio volumio[810]: info: Initializing connection to go-librespot Websocket Sep 05 10:09:10 volumio go-librespot[7177]: time="2024-09-05T10:09:10+02:00" level=debug msg="new websocket client" Sep 05 10:09:10 volumio volumio[810]: info: Connection to go-librespot Websocket established Sep 05 10:09:10 volumio volumio[810]: info: go-librespot daemon successfully initialized Sep 05 10:09:13 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:13 volumio volumio[810]: info: Listing playlists Sep 05 10:09:13 volumio volumio[810]: info: Listing playlists Sep 05 10:09:13 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:13 volumio volumio[810]: info: Getting Spotify volume Sep 05 10:09:13 volumio volumio[810]: info: Initializing connection to go-librespot Websocket Sep 05 10:09:14 volumio go-librespot[7177]: time="2024-09-05T10:09:14+02:00" level=debug msg="new websocket client" Sep 05 10:09:14 volumio volumio[810]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 05 10:09:14 volumio volumio[810]: info: Connection to go-librespot Websocket established Sep 05 10:09:14 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:14 volumio volumio[810]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 05 10:09:14 volumio volumio[810]: info: Setting up libfakeroot:armhf (1.23-1) ... Sep 05 10:09:14 volumio volumio[810]: info: Setting up python3-async-timeout (3.0.1-1) ... Sep 05 10:09:17 volumio volumio[810]: info: Getting Spotify volume Sep 05 10:09:17 volumio volumio[810]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 6 Sep 05 10:09:17 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:17 volumio volumio[810]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 05 10:09:19 volumio volumio[810]: info: Setting up fakeroot (1.23-1) ... Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: using /usr/bin/fakeroot-sysv to provide /usr/bin/fakeroot (fakeroot) in auto mode Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: warning: skip creation of /usr/share/man/es/man1/fakeroot.1.gz because associated file /usr/share/man/es/man1/fakeroot-sysv.1.gz (of link group fakeroot) doesn't exist Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: warning: skip creation of /usr/share/man/es/man1/faked.1.gz because associated file /usr/share/man/es/man1/faked-sysv.1.gz (of link group fakeroot) doesn't exist Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: warning: skip creation of /usr/share/man/fr/man1/fakeroot.1.gz because associated file /usr/share/man/fr/man1/fakeroot-sysv.1.gz (of link group fakeroot) doesn't exist Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: warning: skip creation of /usr/share/man/fr/man1/faked.1.gz because associated file /usr/share/man/fr/man1/faked-sysv.1.gz (of link group fakeroot) doesn't exist Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: warning: skip creation of /usr/share/man/sv/man1/fakeroot.1.gz because associated file /usr/share/man/sv/man1/fakeroot-sysv.1.gz (of link group fakeroot) doesn't exist Sep 05 10:09:19 volumio volumio[810]: info: update-alternatives: warning: skip creation of /usr/share/man/sv/man1/faked.1.gz because associated file /usr/share/man/sv/man1/faked-sysv.1.gz (of link group fakeroot) doesn't exist Sep 05 10:09:20 volumio volumio[810]: info: Setting up libasan5:armhf (8.3.0-6+rpi1) ... Sep 05 10:09:20 volumio volumio[810]: info: Setting up libexpat1-dev:armhf (2.2.6-2+deb10u7) ... Sep 05 10:09:20 volumio volumio[810]: info: Setting up make (4.2.1-1.2) ... Sep 05 10:09:20 volumio volumio[810]: info: Setting up libmpfr6:armhf (4.0.2-1) ... Sep 05 10:09:20 volumio volumio[810]: info: Setting up python3-gi (3.30.4-1) ... Sep 05 10:09:23 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:25 volumio volumio[810]: info: Setting up libmpc3:armhf (1.1.0-1) ... Sep 05 10:09:25 volumio volumio[810]: info: Setting up patch (2.7.6-3+deb10u1) ... Sep 05 10:09:26 volumio volumio[810]: info: Setting up libubsan1:armhf (8.3.0-6+rpi1) ... Sep 05 10:09:26 volumio volumio[810]: info: Setting up libisl19:armhf (0.20-2) ... Sep 05 10:09:26 volumio volumio[810]: info: Setting up python3-crypto (2.6.1-9+b1) ... Sep 05 10:09:27 volumio go-librespot[7177]: time="2024-09-05T10:09:27+02:00" level=debug msg="obtained new client token: AACdXHiq9sImBy0/PbGPII/P9PeaH7y+AtsyT/oB7pdneaBUNC5Ea9ZlWqBObXO3HseIYsMOgqn5CdHRa195dbyp3FnPqoJjK5bN4RZFP5U1dBpp3cipGtm0jO5NFSiti4ZHjGO4zSgtIx0PNwRAWizCLVyJslfm8sJdEx1BcZYf+CutJnfP5/sFAvxXxgsMgcwdvvDBZ8YuWZucKiVVXdBnhqilpAcGZtPx68hJr2xuiFOLpzqrWBZcWwKl" Sep 05 10:09:27 volumio go-librespot[7177]: time="2024-09-05T10:09:27+02:00" level=debug msg="completed keyexchange" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="completed challenge" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="authenticated as jrsikken" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="authenticated as jrsikken" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="dealer connection opened" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=info msg="accepted zeroconf user jrsikken from Jaspers Awephone" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="received connection id: MjJlOWVhM2YtMDE5Ny00MzhiLTg0ZWYtMmNkMjc2MTE2OTE1K2RlYWxlcit0Y3A6Ly8wYWNhNTg2Zi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArRDE0NUQ1QjZBMjY5MjVGQURDNDEzNkQ3QzIwOENEQUYxNUYxOTlDNDY4NjBCMzFCMTlBMEZCRjdCQTZDOTI3RQ==" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 05 10:09:28 volumio go-librespot[7177]: time="2024-09-05T10:09:28+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 493" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="autoplay enabled: false" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="handling transfer player command from 5a615842da9ede0dffa75229236da48aeaa88174" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DXdKMCnEhDnDL" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=trace msg="fetched new page 0 with 100 items (list: 100)" uri="spotify:playlist:37i9dQZF1DXdKMCnEhDnDL" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="loading track (paused: false, position: 19877ms)" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=trace msg="emitting websocket event: will_play" Sep 05 10:09:29 volumio volumio[810]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0Uy5VFlvsosR3YZbpsxYFh","play_origin":"playlist"}} Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Sep 05 10:09:29 volumio volumio[810]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0Uy5VFlvsosR3YZbpsxYFh","play_origin":"playlist"}} Sep 05 10:09:29 volumio go-librespot[7177]: time="2024-09-05T10:09:29+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1680" Sep 05 10:09:30 volumio go-librespot[7177]: time="2024-09-05T10:09:30+02:00" level=debug msg="selected format OGG_VORBIS_96 (d313345989e7f34e35f9934cf34d78efdda26373)" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:30 volumio go-librespot[7177]: time="2024-09-05T10:09:30+02:00" level=debug msg="requested aes key for file d313345989e7f34e35f9934cf34d78efdda26373, gid: 0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:30 volumio go-librespot[7177]: time="2024-09-05T10:09:30+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1294" Sep 05 10:09:31 volumio go-librespot[7177]: time="2024-09-05T10:09:31+02:00" level=debug msg="fetched first chunk of 3, total size is 1450388 bytes" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:31 volumio go-librespot[7177]: time="2024-09-05T10:09:31+02:00" level=trace msg="seek to 19877ms (diff: 339ms, samples: 876575, bytes: 228834)" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:32 volumio go-librespot[7177]: time="2024-09-05T10:09:32+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:0Uy5VFlvsosR3YZbpsxYFh: ALSA error at snd_pcm_open: Device or resource busy" Sep 05 10:09:32 volumio go-librespot[7177]: time="2024-09-05T10:09:32+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 05 10:09:32 volumio go-librespot[7177]: time="2024-09-05T10:09:32+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 05 10:09:32 volumio go-librespot[7177]: time="2024-09-05T10:09:32+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 05 10:09:32 volumio go-librespot[7177]: time="2024-09-05T10:09:32+02:00" level=debug msg="fetched chunk 2/2, size: 401812" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:32 volumio go-librespot[7177]: time="2024-09-05T10:09:32+02:00" level=debug msg="fetched chunk 1/2, size: 524288" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:09:33 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:33 volumio volumio[810]: info: Listing playlists Sep 05 10:09:33 volumio volumio[810]: info: Listing playlists Sep 05 10:09:37 volumio volumio[810]: info: Setting up python-pip-whl (18.1-5+rpt1) ... Sep 05 10:09:37 volumio volumio[810]: info: Setting up cpp-8 (8.3.0-6+rpi1) ... Sep 05 10:09:37 volumio volumio[810]: info: Setting up python3-yarl (1.3.0-1) ... Sep 05 10:09:41 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 05 10:09:41 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 05 10:09:41 volumio volumio[810]: info: Setting up libalgorithm-diff-xs-perl (0.04-5+b1) ... Sep 05 10:09:42 volumio volumio[810]: info: Setting up python3-asn1crypto (0.24.0-1) ... Sep 05 10:09:43 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:45 volumio volumio[810]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 05 10:09:48 volumio volumio[810]: info: Setting up libcc1-0:armhf (8.3.0-6+rpi1) ... Sep 05 10:09:48 volumio volumio[810]: info: Setting up python3-cffi-backend (1.12.2-1) ... Sep 05 10:09:48 volumio volumio[810]: info: Setting up libalgorithm-merge-perl (0.08-3) ... Sep 05 10:09:48 volumio volumio[810]: info: Setting up libpython3.7-dev:armhf (3.7.3-2+deb10u7) ... Sep 05 10:09:48 volumio volumio[810]: info: Setting up python3-aiohttp (3.5.1-1+deb10u1) ... Sep 05 10:09:49 volumio volumio[810]: info: Received OAUTH Data Sep 05 10:09:49 volumio volumio[810]: info: Executing Spotify Oauth Login Sep 05 10:09:49 volumio volumio[810]: info: Saving Spotify Refresh Token Sep 05 10:09:50 volumio volumio[810]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 05 10:09:50 volumio volumio[810]: SPOTIFY: BQCIN0eblrM_foBhXLSn2Jv7MUo9yZ0IQEKU1eCrh54Md44ao2t5jRRQyUZX5bHYpneUX9L0ygLygAsw923dsapvU5Edg5I8sMNnI6BGq_X0_-jpKbB1JB8tg1pl0dBwR_mHtpgCaunjrX2raPhENd6DpbQKfBrEzPwux2Mv3FHBwllR_DP6cBFtsw8mF9i7Fl-VqjUR67cozY4LzPrN2atOhujzWHDLEWasE70WWJzpxlz7GVK8HBYN Sep 05 10:09:50 volumio volumio[810]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 05 10:09:50 volumio volumio[810]: info: New Spotify access token = BQCIN0eblrM_foBhXLSn2Jv7MUo9yZ0IQEKU1eCrh54Md44ao2t5jRRQyUZX5bHYpneUX9L0ygLygAsw923dsapvU5Edg5I8sMNnI6BGq_X0_-jpKbB1JB8tg1pl0dBwR_mHtpgCaunjrX2raPhENd6DpbQKfBrEzPwux2Mv3FHBwllR_DP6cBFtsw8mF9i7Fl-VqjUR67cozY4LzPrN2atOhujzWHDLEWasE70WWJzpxlz7GVK8HBYN Sep 05 10:09:50 volumio volumio[810]: info: Spotify credentials grant success - running version from March 24, 2019 Sep 05 10:09:51 volumio sudo[7393]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Sep 05 10:09:51 volumio sudo[7393]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:09:51 volumio volumio[810]: SPOTIFY: User informations: {"display_name":"jrsikken","external_urls":{"spotify":"https://open.spotify.com/user/jrsikken"},"href":"https://api.spotify.com/v1/users/jrsikken","id":"jrsikken","images":[{"url":"https://i.scdn.co/image/ab67757000003b826ab7d1aabd7754aa7f010bd2","height":64,"width":64},{"url":"https://i.scdn.co/image/ab6775700000ee856ab7d1aabd7754aa7f010bd2","height":300,"width":300}],"type":"user","uri":"spotify:user:jrsikken","followers":{"href":null,"total":0},"country":"NL","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"jrsikken@gmail.com"} Sep 05 10:09:51 volumio volumio[810]: info: Creating Spotify config file Sep 05 10:09:51 volumio sudo[7395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Sep 05 10:09:51 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 05 10:09:51 volumio sudo[7393]: pam_unix(sudo:session): session closed for user root Sep 05 10:09:51 volumio sudo[7395]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:09:52 volumio sudo[7395]: pam_unix(sudo:session): session closed for user root Sep 05 10:09:52 volumio volumio[810]: info: Spotify config file written Sep 05 10:09:52 volumio sudo[7403]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Sep 05 10:09:52 volumio sudo[7403]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:09:52 volumio systemd[1]: Stopping go-librespot Daemon... Sep 05 10:09:53 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Sep 05 10:09:53 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Sep 05 10:09:53 volumio systemd[1]: Stopped go-librespot Daemon. Sep 05 10:09:53 volumio systemd[1]: Started go-librespot Daemon. Sep 05 10:09:53 volumio volumio[810]: verbose: New Socket.io Connection to 192.168.2.86 from 192.168.2.126 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Sep 05 10:09:53 volumio go-librespot[7407]: Librespot-go daemon starting... Sep 05 10:09:53 volumio sudo[7403]: pam_unix(sudo:session): session closed for user root Sep 05 10:09:53 volumio go-librespot[7407]: time="2024-09-05T10:09:53+02:00" level=info msg="generated new device id: 23ec70ca849b4c2915e3786f0986f0a364b2cf32" Sep 05 10:09:53 volumio go-librespot[7407]: time="2024-09-05T10:09:53+02:00" level=debug msg="stored credentials not found" Sep 05 10:09:54 volumio volumio[810]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 05 10:09:54 volumio volumio[810]: SPOTIFY: BQBOs6SCgi3PCX3HPRy3XxI0kh8U9ejyKgAnNlfAHKf4RE0azmc7Fu-8_BT6TYYwOAYutymkGMjhMHnJJM5uF6YqdklXZ7RhspMxuXKu2IJhMgufve_SRlYgHcUZW96u6US97JyUkyN8j5dIfHCT_HOsED-B3qyEGw3goRtEhcBF_HbcxpradvhYQROhWzmvXZlx6D_pVnyo769mFv5phYGhIA-brr6eE1hNevgZQIpBEf_BO2a81H_s Sep 05 10:09:54 volumio volumio[810]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Sep 05 10:09:54 volumio volumio[810]: info: New Spotify access token = BQBOs6SCgi3PCX3HPRy3XxI0kh8U9ejyKgAnNlfAHKf4RE0azmc7Fu-8_BT6TYYwOAYutymkGMjhMHnJJM5uF6YqdklXZ7RhspMxuXKu2IJhMgufve_SRlYgHcUZW96u6US97JyUkyN8j5dIfHCT_HOsED-B3qyEGw3goRtEhcBF_HbcxpradvhYQROhWzmvXZlx6D_pVnyo769mFv5phYGhIA-brr6eE1hNevgZQIpBEf_BO2a81H_s Sep 05 10:09:54 volumio volumio[810]: info: Spotify credentials grant success - running version from March 24, 2019 Sep 05 10:09:54 volumio volumio[810]: verbose: New Socket.io Connection to 192.168.2.86 from 192.168.2.126 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Sep 05 10:09:54 volumio volumio[810]: info: Connection to go-librespot Websocket closed Sep 05 10:09:55 volumio volumio[810]: info: Connection to go-librespot Websocket closed Sep 05 10:09:55 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:56 volumio go-librespot[7407]: time="2024-09-05T10:09:56+02:00" level=debug msg="fetched new accesspoints: [ap2-gew4.spotify.com:4070 ap2-gew4.spotify.com:443 ap2-gew4.spotify.com:80 ap2-gue1.spotify.com:4070 ap2-gew1.spotify.com:443 ap2-gae2.spotify.com:80]" Sep 05 10:09:56 volumio go-librespot[7407]: time="2024-09-05T10:09:56+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]" Sep 05 10:09:56 volumio go-librespot[7407]: time="2024-09-05T10:09:56+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]" Sep 05 10:09:56 volumio volumio[810]: info: Listing playlists Sep 05 10:09:56 volumio volumio[810]: info: Listing playlists Sep 05 10:09:56 volumio go-librespot[7407]: time="2024-09-05T10:09:56+02:00" level=debug msg="zeroconf server listening on port 34993" Sep 05 10:09:56 volumio go-librespot[7407]: time="2024-09-05T10:09:56+02:00" level=debug msg="obtained new client token: AADV00iL8L7dKY5VtVzXA7syuhb/wJxrMT3hQsaoSjIZcyCEKceQSMQpNNn0Ajnemi/eLfpXD4ccDeIRfgi9TtKWL2secBpzHuukS2uWzE5OL6r/D9p3LW4AJKhjTjOg+xEmLShoyZbn71z2pWbC2JcpZh5BU1v6uE6QFpbg0T9VX5w0pvsAA14syFDwiN8vSiWt1/ovxgE2XJuoXbsEX8OLk/7v4adiJpOL0N2Qpke9pjhSuSpr9weGV4/n" Sep 05 10:09:57 volumio go-librespot[7407]: time="2024-09-05T10:09:57+02:00" level=debug msg="completed keyexchange" Sep 05 10:09:57 volumio volumio[810]: verbose: New Socket.io Connection to 192.168.2.86 from 192.168.2.126 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Sep 05 10:09:57 volumio volumio[810]: info: go-librespot daemon successfully initialized Sep 05 10:09:57 volumio go-librespot[7407]: time="2024-09-05T10:09:57+02:00" level=debug msg="completed challenge" Sep 05 10:09:57 volumio volumio[810]: SPOTIFY: User informations: {"display_name":"jrsikken","external_urls":{"spotify":"https://open.spotify.com/user/jrsikken"},"href":"https://api.spotify.com/v1/users/jrsikken","id":"jrsikken","images":[{"url":"https://i.scdn.co/image/ab67757000003b826ab7d1aabd7754aa7f010bd2","height":64,"width":64},{"url":"https://i.scdn.co/image/ab6775700000ee856ab7d1aabd7754aa7f010bd2","height":300,"width":300}],"type":"user","uri":"spotify:user:jrsikken","followers":{"href":null,"total":0},"country":"NL","product":"premium","explicit_content":{"filter_enabled":false,"filter_locked":false},"email":"jrsikken@gmail.com"} Sep 05 10:09:57 volumio go-librespot[7407]: time="2024-09-05T10:09:57+02:00" level=debug msg="authenticated as jrsikken" Sep 05 10:09:57 volumio volumio[810]: info: Spotify Successfully logged in Sep 05 10:09:58 volumio volumio[810]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Sep 05 10:09:58 volumio volumio[810]: info: [1725523798116] CoreMusicLibrary::Adding element Spotify Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="authenticated as jrsikken" Sep 05 10:09:58 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 05 10:09:58 volumio volumio[810]: Cannot find translation for source Spotify Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="dealer connection opened" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="stored credentials for jrsikken" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="initializing zeroconf session, username: jrsikken" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Sep 05 10:09:58 volumio volumio[810]: info: Initializing connection to go-librespot Websocket Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="autoplay enabled: false" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="received connection id: MGU3ODJjMWMtZGQyNi00NjQ1LThlYjctNWFlNWI1NTc4Yzk2K2RlYWxlcit0Y3A6Ly8wYWNhNTk4YS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMzYzQ0M2MjRDRTM2NzE0NUE2MjlGRkMxN0JGQ0E1QUY2MDZERUMwODk3QTZCNkU2RUIyRjc4NTJDQkNGOUEwQg==" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="new websocket client" Sep 05 10:09:58 volumio volumio[810]: info: Connection to go-librespot Websocket established Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1720" Sep 05 10:09:58 volumio go-librespot[7407]: time="2024-09-05T10:09:58+02:00" level=debug msg="put connect state because NEW_DEVICE" Sep 05 10:09:59 volumio go-librespot[7407]: time="2024-09-05T10:09:59+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 05 10:09:59 volumio go-librespot[7407]: time="2024-09-05T10:09:59+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 05 10:09:59 volumio volumio[810]: verbose: New Socket.io Connection to 192.168.2.86 from 192.168.2.126 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/128.0.0.0 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetVisibleSources Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 05 10:09:59 volumio volumio[810]: info: Received Get System Info Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 05 10:09:59 volumio volumio[810]: info: Discovery: Getting this device information Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: Listing playlists Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 05 10:09:59 volumio volumio[810]: info: Received Get System Info Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 05 10:09:59 volumio volumio[810]: info: Discovery: Getting this device information Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 05 10:09:59 volumio volumio[810]: info: Received Get System Info Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 05 10:09:59 volumio volumio[810]: info: Discovery: Getting this device information Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetVisibleSources Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Sep 05 10:09:59 volumio volumio[810]: info: Received Get System Info Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 05 10:09:59 volumio volumio[810]: info: Discovery: Getting this device information Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 05 10:09:59 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:09:59 volumio volumio[810]: info: Listing playlists Sep 05 10:10:00 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 05 10:10:00 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Sep 05 10:10:00 volumio volumio[810]: info: Initializing connection to go-librespot Websocket Sep 05 10:10:00 volumio volumio[810]: info: Connection to go-librespot Websocket established Sep 05 10:10:00 volumio go-librespot[7407]: time="2024-09-05T10:10:00+02:00" level=debug msg="new websocket client" Sep 05 10:10:00 volumio go-librespot[7407]: time="2024-09-05T10:10:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 346" Sep 05 10:10:00 volumio go-librespot[7407]: time="2024-09-05T10:10:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 05 10:10:01 volumio volumio[810]: info: Setting up python3.7-dev (3.7.3-2+deb10u7) ... Sep 05 10:10:01 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Sep 05 10:10:01 volumio volumio[810]: info: Setting up dpkg-dev (1.19.8) ... Sep 05 10:10:01 volumio volumio[810]: info: Setting up python3-cryptography (2.6.1-3+deb10u4) ... Sep 05 10:10:02 volumio volumio[810]: info: Getting Spotify volume Sep 05 10:10:02 volumio volumio[810]: info: Spotify volume: 100 Sep 05 10:10:02 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Sep 05 10:10:02 volumio volumio[810]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Sep 05 10:10:02 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:02 volumio volumio[810]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 05 10:10:02 volumio volumio[810]: SPOTIFY: SPOTIFY VOLUME 100 Sep 05 10:10:02 volumio volumio[810]: SPOTIFY: VOLUMIO VOLUME 33 Sep 05 10:10:02 volumio volumio[810]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 05 10:10:02 volumio volumio[810]: info: Setting Spotify Volume from Volumio: 33 Sep 05 10:10:03 volumio volumio[810]: info: Getting Spotify volume Sep 05 10:10:03 volumio volumio[810]: info: Spotify volume: 100 Sep 05 10:10:03 volumio volumio[810]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Sep 05 10:10:03 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:04 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:04 volumio volumio[810]: SPOTIFY: RECEIVED VOLUMIO VOLUME 33 Sep 05 10:10:04 volumio volumio[810]: SPOTIFY: SPOTIFY VOLUME 100 Sep 05 10:10:04 volumio volumio[810]: SPOTIFY: VOLUMIO VOLUME 33 Sep 05 10:10:04 volumio volumio[810]: SPOTIFY: DELTA VOLUME ENOUGH: true Sep 05 10:10:04 volumio volumio[810]: info: Setting Spotify Volume from Volumio: 33 Sep 05 10:10:05 volumio volumio[810]: SPOTIFY: SETTING SPOTIFY VOLUME 33 Sep 05 10:10:05 volumio volumio[810]: info: Sending Spotify command with payload to local API: /player/volume Sep 05 10:10:05 volumio go-librespot[7407]: time="2024-09-05T10:10:05+02:00" level=debug msg="update volume to 21626/65535" Sep 05 10:10:05 volumio go-librespot[7407]: time="2024-09-05T10:10:05+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Sep 05 10:10:05 volumio go-librespot[7407]: time="2024-09-05T10:10:05+02:00" level=trace msg="emitting websocket event: volume" Sep 05 10:10:05 volumio volumio[810]: SPOTIFY: received: {"type":"volume","data":{"value":33,"max":100}} Sep 05 10:10:05 volumio volumio[810]: SPOTIFY: RECEIVED SPOTIFY VOLUME 33 Sep 05 10:10:05 volumio volumio[810]: SPOTIFY: received: {"type":"volume","data":{"value":33,"max":100}} Sep 05 10:10:05 volumio volumio[810]: SPOTIFY: RECEIVED SPOTIFY VOLUME 33 Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="handling transfer player command from 5a615842da9ede0dffa75229236da48aeaa88174" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DXdKMCnEhDnDL" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=trace msg="fetched new page 0 with 100 items (list: 100)" uri="spotify:playlist:37i9dQZF1DXdKMCnEhDnDL" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="loading track (paused: false, position: 51503ms)" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=trace msg="emitting websocket event: will_play" Sep 05 10:10:06 volumio volumio[810]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0Uy5VFlvsosR3YZbpsxYFh","play_origin":"playlist"}} Sep 05 10:10:06 volumio volumio[810]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0Uy5VFlvsosR3YZbpsxYFh","play_origin":"playlist"}} Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1680" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="selected format OGG_VORBIS_96 (d313345989e7f34e35f9934cf34d78efdda26373)" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="requested aes key for file d313345989e7f34e35f9934cf34d78efdda26373, gid: 0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:06 volumio go-librespot[7407]: time="2024-09-05T10:10:06+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1294" Sep 05 10:10:07 volumio go-librespot[7407]: time="2024-09-05T10:10:07+02:00" level=debug msg="fetched first chunk of 3, total size is 1450388 bytes" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:08 volumio go-librespot[7407]: time="2024-09-05T10:10:08+02:00" level=debug msg="fetched chunk 1/2, size: 524288" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:08 volumio go-librespot[7407]: time="2024-09-05T10:10:08+02:00" level=trace msg="seek to 51503ms (diff: 264ms, samples: 2271282, bytes: 615983)" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:08 volumio go-librespot[7407]: time="2024-09-05T10:10:08+02:00" level=debug msg="fetched chunk 2/2, size: 401812" uri="spotify:track:0Uy5VFlvsosR3YZbpsxYFh" Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Sep 05 10:10:09 volumio volumio[810]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Sep 05 10:10:09 volumio go-librespot[7407]: time="2024-09-05T10:10:09+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:0Uy5VFlvsosR3YZbpsxYFh: ALSA error at snd_pcm_open: Device or resource busy" Sep 05 10:10:09 volumio go-librespot[7407]: time="2024-09-05T10:10:09+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Sep 05 10:10:09 volumio go-librespot[7407]: time="2024-09-05T10:10:09+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 05 10:10:09 volumio go-librespot[7407]: time="2024-09-05T10:10:09+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Sep 05 10:10:09 volumio volumio[810]: info: Received Get System Version Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Sep 05 10:10:09 volumio volumio[810]: info: Received Get System Info Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Sep 05 10:10:09 volumio volumio[810]: info: Discovery: Getting this device information Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:09 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 05 10:10:11 volumio volumio[810]: info: Setting up python3-pip (18.1-5+rpt1) ... Sep 05 10:10:13 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:13 volumio volumio[810]: info: Listing playlists Sep 05 10:10:13 volumio volumio[810]: info: Listing playlists Sep 05 10:10:14 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:15 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Sep 05 10:10:15 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Sep 05 10:10:20 volumio volumio[810]: info: Setting up libgcc-8-dev:armhf (8.3.0-6+rpi1) ... Sep 05 10:10:20 volumio volumio[810]: info: Setting up cpp (4:8.3.0-1+rpi2) ... Sep 05 10:10:20 volumio volumio[810]: info: Setting up python3-keyrings.alt (3.1.1-1) ... Sep 05 10:10:22 volumio volumio[810]: info: Enabling plugin fusiondsp Sep 05 10:10:22 volumio volumio[810]: info: Loading plugin "fusiondsp"... Sep 05 10:10:26 volumio volumio[810]: info: Preparing to generate the ALSA configuration file Sep 05 10:10:26 volumio volumio[810]: info: CoreCommandRouter::getUIConfigOnPlugin Sep 05 10:10:27 volumio volumio[810]: Upnp client error: Error: This socket has been ended by the other party Sep 05 10:10:27 volumio volumio[810]: info: Setting up libstdc++-8-dev:armhf (8.3.0-6+rpi1) ... Sep 05 10:10:27 volumio volumio[810]: info: Setting up gcc-8 (8.3.0-6+rpi1) ... Sep 05 10:10:27 volumio volumio[810]: info: Setting up libpython3-dev:armhf (3.7.3-1) ... Sep 05 10:10:27 volumio volumio[810]: info: Setting up gcc (4:8.3.0-1+rpi2) ... Sep 05 10:10:27 volumio volumio[810]: info: Setting up python3-secretstorage (2.3.1-2) ... Sep 05 10:10:27 volumio volumio[810]: info: CoreCommandRouter::volumioGetState Sep 05 10:10:27 volumio volumio[810]: info: Asound.conf file unchanged, so no further update is needed Sep 05 10:10:27 volumio volumio[810]: info: Output device has changed, restarting MPD Sep 05 10:10:28 volumio volumio[810]: info: Output device has changed, restarting Shairport Sync Sep 05 10:10:28 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 05 10:10:28 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Sep 05 10:10:28 volumio sudo[7506]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Sep 05 10:10:28 volumio sudo[7506]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:10:28 volumio sudo[7506]: pam_unix(sudo:session): session closed for user root Sep 05 10:10:28 volumio sudo[7508]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Sep 05 10:10:28 volumio sudo[7508]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:10:28 volumio systemd[1]: Stopping Music Player Daemon... Sep 05 10:10:29 volumio volumio[810]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Sep 05 10:10:29 volumio volumio[810]: info: PLUGIN START: fusiondsp Sep 05 10:10:29 volumio volumio[810]: info: Loading i18n strings for locale en Sep 05 10:10:29 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Sep 05 10:10:29 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 05 10:10:29 volumio volumio[810]: info: FusionDsp - mixtype--------------------- Hardware Sep 05 10:10:29 volumio volumio[810]: info: Preparing to generate the ALSA configuration file Sep 05 10:10:29 volumio volumio[810]: info: Done. Sep 05 10:10:33 volumio go-librespot[7407]: time="2024-09-05T10:10:33+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 340" Sep 05 10:10:33 volumio go-librespot[7407]: time="2024-09-05T10:10:33+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1720" Sep 05 10:10:34 volumio systemd[1]: mpd.service: Succeeded. Sep 05 10:10:34 volumio systemd[1]: Stopped Music Player Daemon. Sep 05 10:10:35 volumio systemd[1]: Starting Music Player Daemon... Sep 05 10:10:35 volumio go-librespot[7407]: time="2024-09-05T10:10:35+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 346" Sep 05 10:10:35 volumio volumio[810]: info: camilladsp spawned new process with pid undefined, instance 1, run: true Sep 05 10:10:35 volumio volumio[810]: info: camilladsp service started and running in background, instance 1 Sep 05 10:10:35 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Sep 05 10:10:35 volumio volumio[810]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Sep 05 10:10:35 volumio volumio[810]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Sep 05 10:10:35 volumio volumio[810]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Sep 05 10:10:35 volumio volumio[810]: info: FusionDsp loaded Sep 05 10:10:35 volumio volumio[810]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Sep 05 10:10:36 volumio sudo[7528]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Sep 05 10:10:36 volumio sudo[7544]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Sep 05 10:10:36 volumio sudo[7528]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:10:36 volumio sudo[7544]: pam_unix(sudo:session): session opened for user root by (uid=0) Sep 05 10:10:36 volumio sudo[7528]: pam_unix(sudo:session): session closed for user root Sep 05 10:10:36 volumio volumio[810]: info: FusionDsp - Reporting Fusion DSP Enabled Sep 05 10:10:36 volumio volumio[810]: info: Adding Signal Path Element [object Object] Sep 05 10:10:36 volumio volumio[810]: info: Adding fusiondspeq DSP Signal Path Element Sep 05 10:10:36 volumio volumio[810]: info: FusionDsp - ---- installed callbackRead Sep 05 10:10:37 volumio sudo[7544]: pam_unix(sudo:session): session closed for user root Sep 05 10:10:37 volumio volumio[810]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 05 10:10:37 volumio volumio[810]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Sep 05 10:10:37 volumio volumio[810]: at Process.ChildProcess._handle.onexit (internal/child_process.js:269:19) Sep 05 10:10:37 volumio volumio[810]: at onErrorNT (internal/child_process.js:465:16) Sep 05 10:10:37 volumio volumio[810]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Sep 05 10:10:37 volumio volumio[810]: at runNextTicks (internal/process/task_queues.js:62:3) Sep 05 10:10:37 volumio volumio[810]: at listOnTimeout (internal/timers.js:523:9) Sep 05 10:10:37 volumio volumio[810]: at processTimers (internal/timers.js:497:7) { Sep 05 10:10:37 volumio volumio[810]: errno: -2, Sep 05 10:10:37 volumio volumio[810]: code: 'ENOENT', Sep 05 10:10:37 volumio volumio[810]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Sep 05 10:10:37 volumio volumio[810]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Sep 05 10:10:37 volumio volumio[810]: spawnargs: [ Sep 05 10:10:37 volumio volumio[810]: '-p', Sep 05 10:10:37 volumio volumio[810]: 9876, Sep 05 10:10:37 volumio volumio[810]: '-o', Sep 05 10:10:37 volumio volumio[810]: '/tmp/camilladsp.log', Sep 05 10:10:37 volumio volumio[810]: '-l', Sep 05 10:10:37 volumio volumio[810]: 'warn', Sep 05 10:10:37 volumio volumio[810]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Sep 05 10:10:37 volumio volumio[810]: ] Sep 05 10:10:37 volumio volumio[810]: } Sep 05 10:10:37 volumio volumio[810]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Sep 05 10:10:39 volumio volumio-remote-updater[544]: [2024-09-05 10:10:39] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] Sep 05 10:10:44 volumio volumio-remote-updater[544]: [2024-09-05 10:10:44] [connect] Successful connection Sep 05 10:10:52 volumio sudo[7616]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-09-05 10:09 Sep 05 10:10:52 volumio sudo[7616]: 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="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"