Dec 24 19:47:27 volumio ntpd[1012]: CLOCK: time stepped by 86628.541140 Dec 24 19:47:27 volumio ntpd[1012]: CLOCK: time changed from 2025-12-23 to 2025-12-24 Dec 24 19:47:27 volumio ntpd[1012]: INIT: MRU 13107 entries, 13 hash bits, 32768 bytes Dec 24 19:47:29 volumio volumio[1077]: info: Volumio Calling Home Dec 24 19:47:30 volumio volumio[1287]: Starting albumart workers Dec 24 19:47:30 volumio mpd[1363]: 2025-12-24T19:47:30 decoder: Decoder plugin "wildmidi" is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Dec 24 19:47:30 volumio systemd[1]: Starting dpkg-db-backup.service - Daily dpkg database backup service... Dec 24 19:47:30 volumio systemd[1]: Started ntpsec-rotate-stats.service - Rotate ntpd stats. Dec 24 19:47:30 volumio systemd[1]: Started mpd.service - Music Player Daemon. Dec 24 19:47:30 volumio sudo[1346]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:30 volumio sudo[1334]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:30 volumio systemd[1]: ntpsec-rotate-stats.service: Deactivated successfully. Dec 24 19:47:30 volumio volumio[1286]: Starting albumart workers Dec 24 19:47:30 volumio systemd[1]: dpkg-db-backup.service: Deactivated successfully. Dec 24 19:47:30 volumio systemd[1]: Finished dpkg-db-backup.service - Daily dpkg database backup service. Dec 24 19:47:31 volumio volumio[1288]: Starting albumart workers Dec 24 19:47:31 volumio volumio[1077]: info: Volumio Network Manager: Network status updated: 1 Dec 24 19:47:31 volumio sudo[1408]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Dec 24 19:47:31 volumio sudo[1408]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:31 volumio sudo[1408]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:31 volumio sudo[1410]: volumio : PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Dec 24 19:47:31 volumio sudo[1410]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:31 volumio sudo[1410]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:31 volumio volumio[1077]: info: Completed starting Core Plugins Dec 24 19:47:31 volumio volumio[1077]: info: ------------------------------------------- Dec 24 19:47:31 volumio volumio[1077]: info: ----- MyVolumio plugins startup ---- Dec 24 19:47:31 volumio volumio[1077]: info: ------------------------------------------- Dec 24 19:47:31 volumio volumio[1077]: info: [MyVolumio PluginManager] Fetching plans data.... Dec 24 19:47:31 volumio volumio[1077]: info: MPD Permissions set Dec 24 19:47:31 volumio volumio[1077]: info: MPD Permissions set Dec 24 19:47:31 volumio volumio[1077]: info: Discovery: A device disappeared from network Dec 24 19:47:31 volumio volumio[1077]: info: Discovery: Device volumio disappeared from network Dec 24 19:47:31 volumio volumio[1077]: info: MPD running with PID1363 Dec 24 19:47:31 volumio volumio[1077]: ,establishing connection Dec 24 19:47:31 volumio volumio[1077]: info: Volumio called home Dec 24 19:47:31 volumio volumio[1077]: info: Spotify config file written Dec 24 19:47:31 volumio volumio[1077]: info: Discovery: A device disappeared from network Dec 24 19:47:31 volumio sudo[1418]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Dec 24 19:47:31 volumio sudo[1418]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:31 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:9: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 24 19:47:31 volumio systemd[1]: /lib/systemd/system/go-librespot-daemon.service:10: Standard output type syslog is obsolete, automatically updating to journal. Please update your unit file, and consider removing the setting altogether. Dec 24 19:47:31 volumio systemd[1]: Started go-librespot-daemon.service - go-librespot Daemon. Dec 24 19:47:31 volumio sudo[1418]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:31 volumio go-librespot[1421]: go-librespot daemon starting... Dec 24 19:47:32 volumio volumio[1077]: error: MPD error: The expression evaluated to a falsy value: Dec 24 19:47:32 volumio volumio[1077]: assert.ok(self.idling) Dec 24 19:47:32 volumio volumio[1077]: error: The expression evaluated to a falsy value: Dec 24 19:47:32 volumio volumio[1077]: assert.ok(self.idling) Dec 24 19:47:32 volumio volumio[1077]: error: MPD error: The expression evaluated to a falsy value: Dec 24 19:47:32 volumio volumio[1077]: assert.ok(self.idling) Dec 24 19:47:32 volumio volumio[1077]: error: The expression evaluated to a falsy value: Dec 24 19:47:32 volumio volumio[1077]: assert.ok(self.idling) Dec 24 19:47:32 volumio volumio[1077]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 2 Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Dec 24 19:47:32 volumio volumio[1077]: info: No need to fix Spotify hosts Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=info msg="running go-librespot 0.4.0" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="app state loaded" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=info msg="api server listening on 127.0.0.1:9879" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=info msg="zeroconf server listening on port 35067" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="obtained new client token: AADYgeEFdQ35AtZ2DcXpT8sfAztFh7VRB14SnE7RqY2XB6ZrbXoqe8u7RJ7lPscJVjGch99UrCTQC8dRrTF2NFNceCouj5Hk9WXjETymU3Fub/7xvyZdEGFewdhD3vZaeGGOw9V1+NEIZC3QvFv+gUrYbFX/KvW7tgSNxIUzBFTSf3GLj2ZaTArefhtgaMNSn4oj7koXi+kEV+odYTlS7aUFSeppxY22syIYZ55n0Kn5vnSYmQSOSQ==" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="connected to ap-gew1.spotify.com:4070" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="completed keyexchange" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="completed challenge" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=info msg="authenticated AP" username="31************************v4" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=info msg="authenticated Login5" username="31************************v4" Dec 24 19:47:32 volumio go-librespot[1428]: time="2025-12-24T19:47:32Z" level=debug msg="initializing zeroconf session" username="31************************v4" Dec 24 19:47:33 volumio volumio[1077]: error: updateQueue error: null Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="dealer connection opened" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=trace msg="starting accesspoint recv loop" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=trace msg="starting dealer recv loop" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=trace msg="received accesspoint ping" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="received connection id: MWUzNDNkNWEtYTIw...NTBERjhCNEI0NA==" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=trace msg="received accesspoint pong ack" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="put connect state because NEW_DEVICE" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="update volume requested to 65535/65535" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=debug msg="put connect state because VOLUME_CHANGED" Dec 24 19:47:33 volumio go-librespot[1428]: time="2025-12-24T19:47:33Z" level=trace msg="emitting websocket event: volume" Dec 24 19:47:33 volumio volumio[1077]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 24 19:47:33 volumio volumio[1077]: SPOTIFY: BQBW2dKFwm3bVlOiFF4ZX1jFthQXQcXbJDq9w3h9wTqLHVsZYOnruTdaYqlObfxf-gY-v1I8C_Z6Ywwh2gIT4ZEgl44Y9vis73PGHT8IDnDvV0KA4BLMdVktOf4d0XEicHI6G9XkSMK_sGUbNkOAOWKudj4mPDLY4AWRkpBYxwjvtt0f2qPzBYynxmqbBy8KqVhxjVWlGN5-xJz0mBYysYnwORWuwHwxAghehMFGBpJMAKIF350oVkmAa7s9tyXZUZiqM7REgiTIcG9-MEw1QgrZUYlSBiIhKPi0hTn_OfXizKnXKaH2CbHmPLRD Dec 24 19:47:33 volumio volumio[1077]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Dec 24 19:47:33 volumio volumio[1077]: info: New Spotify access token = BQBW2dKFwm3bVlOiFF4ZX1jFthQXQcXbJDq9w3h9wTqLHVsZYOnruTdaYqlObfxf-gY-v1I8C_Z6Ywwh2gIT4ZEgl44Y9vis73PGHT8IDnDvV0KA4BLMdVktOf4d0XEicHI6G9XkSMK_sGUbNkOAOWKudj4mPDLY4AWRkpBYxwjvtt0f2qPzBYynxmqbBy8KqVhxjVWlGN5-xJz0mBYysYnwORWuwHwxAghehMFGBpJMAKIF350oVkmAa7s9tyXZUZiqM7REgiTIcG9-MEw1QgrZUYlSBiIhKPi0hTn_OfXizKnXKaH2CbHmPLRD Dec 24 19:47:33 volumio volumio[1077]: info: Spotify credentials grant success - running version from March 24, 2019 Dec 24 19:47:33 volumio volumio[1077]: info: Starting Shairport Sync Dec 24 19:47:33 volumio volumio[1077]: info: Starting Shairport Sync Dec 24 19:47:33 volumio volumio[1077]: info: Starting Shairport Sync Dec 24 19:47:33 volumio sudo[1456]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 24 19:47:33 volumio sudo[1456]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:33 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 24 19:47:33 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 24 19:47:33 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 24 19:47:33 volumio systemd[1]: shairport-sync.service: Consumed 1.640s CPU time. Dec 24 19:47:33 volumio volumio[1077]: info: Discovery: adding 5c5da7ea-747a-4b46-b523-5dc149572b0f Dec 24 19:47:33 volumio volumio[1077]: info: Discovery: Found device Volumio Dec 24 19:47:33 volumio volumio[1077]: info: CoreCommandRouter::volumioGetState Dec 24 19:47:33 volumio volumio[1077]: info: CorePlayQueue::getTrack 0 Dec 24 19:47:33 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 24 19:47:33 volumio sudo[1456]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:33 volumio sudo[1460]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 24 19:47:33 volumio sudo[1460]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:33 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 24 19:47:33 volumio sudo[1461]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Dec 24 19:47:33 volumio sudo[1461]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:33 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 24 19:47:33 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 24 19:47:33 volumio sudo[1479]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Dec 24 19:47:33 volumio sudo[1479]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:34 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 24 19:47:34 volumio sudo[1460]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:34 volumio systemd[1]: Stopping shairport-sync.service - Shairport Sync - AirPlay Audio Receiver... Dec 24 19:47:34 volumio systemd[1]: shairport-sync.service: Deactivated successfully. Dec 24 19:47:34 volumio systemd[1]: Stopped shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 24 19:47:34 volumio systemd[1]: Started shairport-sync.service - Shairport Sync - AirPlay Audio Receiver. Dec 24 19:47:34 volumio sudo[1461]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:34 volumio volumio[1077]: info: Shairport-Sync Started Dec 24 19:47:34 volumio volumio[1077]: Error adding Membership: Error: addMembership EINVAL Dec 24 19:47:34 volumio volumio[1077]: info: Shairport-Sync Started Dec 24 19:47:34 volumio volumio[1077]: info: Discovery: this is already registered, 5c5da7ea-747a-4b46-b523-5dc149572b0f Dec 24 19:47:34 volumio volumio[1077]: info: Discovery: Found device Volumio Dec 24 19:47:34 volumio volumio[1077]: info: CoreCommandRouter::volumioGetState Dec 24 19:47:34 volumio volumio[1077]: info: CorePlayQueue::getTrack 0 Dec 24 19:47:34 volumio volumio[1077]: info: Shairport-Sync Started Dec 24 19:47:34 volumio sudo[1507]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 24 19:47:34 volumio sudo[1507]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:34 volumio volumio[1077]: info: CoreCommandRouter::volumioGetState Dec 24 19:47:34 volumio volumio[1077]: info: CorePlayQueue::getTrack 0 Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="handling transfer player command from 568caf377f7c11ecb30ef13f3b6deb732e25f614" Dec 24 19:47:34 volumio sudo[1511]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd_monitor.service Dec 24 19:47:34 volumio sudo[1511]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:34 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 24 19:47:34 volumio mpd_monitor.sh[1509]: MPD Monitor Service: Starting MPD Monitor Service Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DWTYKFynxp6Fs" Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1DWTYKFynxp6Fs" Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="shuffled context with seed 12153217526849035319 (len: 50, keep: 29)" uri="spotify:playlist:37i9dQZF1DWTYKFynxp6Fs" Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="loading track (paused: false, position: 25926872ms)" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:34 volumio sudo[1507]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=trace msg="emitting websocket event: will_play" Dec 24 19:47:34 volumio systemd[1]: Stopping mpd_monitor.service - MPD Monitor Service... Dec 24 19:47:34 volumio systemd[1]: mpd_monitor.service: Deactivated successfully. Dec 24 19:47:34 volumio systemd[1]: Stopped mpd_monitor.service - MPD Monitor Service. Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="selected format OGG_VORBIS_320 (1153ffbe0bf5a27252936ca39dbbf92d14aebf5b)" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="requested aes key for file 1153ffbe0bf5a27252936ca39dbbf92d14aebf5b, gid: 05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:34 volumio volumio[1077]: info: Successfully started MPD Monitor Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1368" Dec 24 19:47:34 volumio systemd[1]: Started mpd_monitor.service - MPD Monitor Service. Dec 24 19:47:34 volumio mpd_monitor.sh[1516]: MPD Monitor Service: Starting MPD Monitor Service Dec 24 19:47:34 volumio sudo[1511]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:34 volumio go-librespot[1428]: time="2025-12-24T19:47:34Z" level=trace msg="found 2 cdn urls" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:34 volumio volumio[1077]: info: Successfully started MPD Monitor Dec 24 19:47:35 volumio volumio[1077]: SPOTIFY: User informations: {"country":"IN","display_name":"Jothms","email":"jothms51@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31wj27a55tbfcn6pzyo2ryt7rqv4"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31wj27a55tbfcn6pzyo2ryt7rqv4","id":"31wj27a55tbfcn6pzyo2ryt7rqv4","images":[],"product":"premium","type":"user","uri":"spotify:user:31wj27a55tbfcn6pzyo2ryt7rqv4"} Dec 24 19:47:35 volumio volumio[1077]: info: Spotify Successfully logged in Dec 24 19:47:35 volumio volumio[1077]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Dec 24 19:47:35 volumio volumio[1077]: info: [1766605655143] CoreMusicLibrary::Adding element Spotify Dec 24 19:47:35 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched first chunk of 18, total size is 9037670 bytes" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1128" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio volumio[1077]: Cannot find translation for source Spotify Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 17/17, size: 124774" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="seek to 212794ms (diff: 420ms, samples: 9384215, bytes: 9027256)" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="created new output device" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=info msg="loaded track \"Dhurooha Manthahasame - From \\\"Sookshmadarshini\\\"\" (paused: false, position: 25926872ms, duration: 212794ms, prefetched: false)" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: metadata" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: active" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="sending successful reply for dealer request" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:05EpQNTKhOlX6NBI5h8RPJ" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="prefetching next track" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="selected format OGG_VORBIS_320 (07c07d3e73c7ee0fa0f10c0dc95e2fe54175a757)" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="requested aes key for file 07c07d3e73c7ee0fa0f10c0dc95e2fe54175a757, gid: 3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: playing" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: not_playing" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: will_play" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="found 2 cdn urls" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="selected format OGG_VORBIS_320 (07c07d3e73c7ee0fa0f10c0dc95e2fe54175a757)" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="requested aes key for file 07c07d3e73c7ee0fa0f10c0dc95e2fe54175a757, gid: 3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched first chunk of 19, total size is 9541665 bytes" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=info msg="prefetched track \"SHERIYA\" (duration: 191020ms)" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="found 2 cdn urls" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched first chunk of 19, total size is 9541665 bytes" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 100000 us, period size = 4410 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 5 frames, PCM format = FLOAT_LE" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=info msg="loaded track \"SHERIYA\" (paused: false, position: 0ms, duration: 191020ms, prefetched: false)" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio volumio[1077]: info: New access token = BQAgo-2rli6dxHJA8-JYrE0ax-32ds93Uh6V9zfsxMeKKJDYDeN_oihPknJc7uXGYeqQ3-XkENQlL6X-ksn0TcUe51fkp7SphUwCPfSzV1g3v36qRHYgXzDElp-VM1iuKymLTaPUZp2xrQ7_NrjTzmpsg6vmWOWd_InsZYUKLqQ3ynjeL-SqH4umiDpP_UkBV0h6vuOHdwJWFN7RtDkjz55H6gA3hQ3SWGhAwu6jHFy3EyK7PIEXDHC4xDDarGMmnmO6dtBRIpxdXIWcVC1XVGfZXcorkm4OgHNpPKFKGvQI8KeU3a4trfwJTSkh Dec 24 19:47:35 volumio volumio[1077]: info: New access token = BQB4ecScKmhCNY18UcKnrextlANmJCkUZM-D65-5fEVx-afpabjrhtKKk2t3EWKCoom2vv-6UW4FNNgjUJlwXT416etHoMIZvyVytWCYxgqiyEeVwAYBZQCvacfM9qRQcJwOLyv4pGA7y0Vqi9nO5X4svgnva1l6lhoJMsMc8knJ-5Y_iMg34SrQ6o9HsvpjEulzEfD9SZ2mOsoj6fgRFBqvA3tgZLTDVaF-jpmCDwpFpYrgXPP252O1xmlhN_gShEsbCVsJKpEftv4YqTkl1YINyUKUz_r8L60F-FIRI7mfynp3JezFbyc8NcDT Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="scheduling prefetch in 161s" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: metadata" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 3/18, size: 524288" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 1/18, size: 524288" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio volumio[1077]: info: New access token = BQC7tpKiwYrb_eTHre14XpLi5NBAckfKWn24HZxrDQiyYQDD1WzXr2FMccNgrZ-OLIHfdjOY1QfpHoqkoMdYp19n1V5KGfXCBHvR9jKAYTdsRiMT8EFuyX-RFBPs5u1803sfDPpnk6rPVlCS3O_-PKzwWCOKXmk-LJsVgsQRBoG1RQk31TsxQKLDvmh9iWXAk64m7h_0T936JbAICyB4_gUcyEYIcJl7JQQYI9ZL93imjFW8MjXUewjLrBFtqUBRrKvJDss7YgJIk_WvQdCrNVAXr4HRC8tQk69SCNiXTXDwMlJN4pBkZU3iDI5H Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=trace msg="emitting websocket event: playing" Dec 24 19:47:35 volumio go-librespot[1428]: time="2025-12-24T19:47:35Z" level=debug msg="fetched chunk 2/18, size: 524288" uri="spotify:track:3mpHzsOufcQoVMjpZPc2Kd" Dec 24 19:47:35 volumio volumio[1077]: info: go-librespot daemon successfully initialized Dec 24 19:47:36 volumio volumio[1077]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory Dec 24 19:47:37 volumio systemd[1]: systemd-fsckd.service: Deactivated successfully. Dec 24 19:47:38 volumio volumio[1077]: info: Initializing connection to go-librespot Websocket Dec 24 19:47:38 volumio go-librespot[1428]: time="2025-12-24T19:47:38Z" level=debug msg="new websocket client" Dec 24 19:47:38 volumio volumio[1077]: info: Connection to go-librespot Websocket established Dec 24 19:47:40 volumio systemd[1]: upmpdcli.service: Scheduled restart job, restart counter is at 2. Dec 24 19:47:40 volumio systemd[1]: Stopped upmpdcli.service - UPnP Renderer front-end to MPD. Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan premium Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin qobuzconnect to plan superstar Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin bluetooth to MyMusic Plugins Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin multiroom to MyMusic Plugins Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin metavolumio to MyMusic Plugins Dec 24 19:47:40 volumio systemd[1]: Started upmpdcli.service - UPnP Renderer front-end to MPD. Dec 24 19:47:40 volumio sudo[1479]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin cd_controller to MyMusic Plugins Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin qobuzconnect to MyMusic Plugins Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin smart_inputs to MyMusic Plugins Dec 24 19:47:40 volumio volumio[1077]: info: Adding plugin tidalconnect to MyMusic Plugins Dec 24 19:47:40 volumio volumio[1077]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"... Dec 24 19:47:40 volumio systemd[1]: systemd-hostnamed.service: Deactivated successfully. Dec 24 19:47:43 volumio volumio[1077]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded Dec 24 19:47:43 volumio volumio[1077]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio Dec 24 19:47:43 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 24 19:47:43 volumio volumio[1077]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Dec 24 19:47:43 volumio volumio[1077]: info: Starting MyVolumio Remote Streaming Endpoints Dec 24 19:47:44 volumio volumio[1077]: info: MyVolumio login type: Token Dec 24 19:47:44 volumio volumio[1077]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started Dec 24 19:47:44 volumio volumio[1077]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"... Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="handling play player command from 568caf377f7c11ecb30ef13f3b6deb732e25f614" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="resolved context of track" uri="spotify:search:christmas+songs+fel" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:search:christmas+songs+fel" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=trace msg="emitting websocket event: will_play" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="selected format OGG_VORBIS_320 (e780980ca75282ea359d16fa6898cf4eeb582c41)" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="requested aes key for file e780980ca75282ea359d16fa6898cf4eeb582c41, gid: 0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=trace msg="found 2 cdn urls" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="fetched first chunk of 16, total size is 8030759 bytes" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=info msg="loaded track \"Feliz Navidad\" (paused: false, position: 0ms, duration: 181794ms, prefetched: false)" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=trace msg="scheduling prefetch in 152s" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=trace msg="emitting websocket event: metadata" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="sending successful reply for dealer request" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=trace msg="emitting websocket event: playing" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 157" Dec 24 19:47:47 volumio go-librespot[1428]: time="2025-12-24T19:47:47Z" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0oPdaY4dXtc3ZsaG17V972" Dec 24 19:47:48 volumio volumio[1077]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded Dec 24 19:47:48 volumio volumio[1077]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services Dec 24 19:47:48 volumio volumio[1077]: info: Streaming services startup Dec 24 19:47:48 volumio volumio[1077]: info: Starting Streaming Daemon Dec 24 19:47:48 volumio volumio[1077]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started Dec 24 19:47:48 volumio sudo[1551]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service Dec 24 19:47:48 volumio sudo[1551]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) Dec 24 19:47:48 volumio sudo[1551]: pam_unix(sudo:session): session closed for user root Dec 24 19:47:48 volumio volumio[1077]: info: Getting Spotify volume Dec 24 19:47:48 volumio volumio[1077]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:search:christmas+songs+fel","uri":"spotify:track:0oPdaY4dXtc3ZsaG17V972","play_origin":"search"}} Dec 24 19:47:49 volumio volumio[1077]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0oPdaY4dXtc3ZsaG17V972","name":"Feliz Navidad","artist_names":["José Feliciano"],"album_name":"Feliz Navidad","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02ddf52275ffabcc1151c65cae","position":0,"duration":181794,"release_date":"year:2002 month:9 day:24","track_number":1,"disc_number":1}} Dec 24 19:47:49 volumio volumio[1077]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:search:christmas+songs+fel","uri":"spotify:track:0oPdaY4dXtc3ZsaG17V972","resume":false,"play_origin":"search"}} Dec 24 19:47:49 volumio volumio[1077]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 24 19:47:49 volumio volumio[1077]: TypeError: Cannot read properties of undefined (reading 'service') Dec 24 19:47:49 volumio volumio[1077]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:346:50) Dec 24 19:47:49 volumio volumio[1077]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:272:18) Dec 24 19:47:49 volumio volumio[1077]: at WebSocket.message (/data/plugins/music_service/spop/index.js:199:14) Dec 24 19:47:49 volumio volumio[1077]: at WebSocket.emit (node:events:514:28) Dec 24 19:47:49 volumio volumio[1077]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Dec 24 19:47:49 volumio volumio[1077]: at Receiver.emit (node:events:514:28) Dec 24 19:47:49 volumio volumio[1077]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Dec 24 19:47:49 volumio volumio[1077]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Dec 24 19:47:49 volumio volumio[1077]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Dec 24 19:47:49 volumio volumio[1077]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Dec 24 19:47:49 volumio volumio[1077]: at writeOrBuffer (node:internal/streams/writable:399:12) Dec 24 19:47:49 volumio volumio[1077]: at _write (node:internal/streams/writable:340:10) Dec 24 19:47:49 volumio volumio[1077]: at Writable.write (node:internal/streams/writable:344:10) Dec 24 19:47:49 volumio volumio[1077]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Dec 24 19:47:49 volumio volumio[1077]: at Socket.emit (node:events:514:28) Dec 24 19:47:49 volumio volumio[1077]: at addChunk (node:internal/streams/readable:343:12) Dec 24 19:47:49 volumio volumio[1077]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 24 19:47:52 volumio sudo[1583]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2025-12-24 19:46' Dec 24 19:47:52 volumio sudo[1583]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Raspbian GNU/Linux 12 (bookworm)" NAME="Raspbian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="cfdc872d40b979cca36352a7333c940c38dc64b5" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="6cbc2303e10f00c3a01cb7f02c6d12448bd32c62" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri Dec 5 20:42:14 UTC 2025" VOLUMIO_VERSION="4.073" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="67fdc5f60f00b7a328ccd8c4ad441086"