-- Logs begin at Mon 2025-02-24 21:07:09 CET, end at Wed 2025-03-05 14:20:02 CET. -- Mar 05 14:19:01 volumio volumio[21022]: info: Loading plugin "outputs"... Mar 05 14:19:01 volumio volumio[21022]: info: Loading plugin "albumart"... Mar 05 14:19:01 volumio volumio[21022]: info: Plugin example_plugin is not enabled Mar 05 14:19:01 volumio volumio[21022]: info: Loading plugin "inputs"... Mar 05 14:19:01 volumio volumio[21022]: info: Loading plugin "updater_comm"... Mar 05 14:19:04 volumio volumio[21022]: info: Plugin mpdemulation is not enabled Mar 05 14:19:04 volumio volumio[21022]: info: Loading plugin "rest_api"... Mar 05 14:19:04 volumio volumio[21022]: info: Loading plugin "websocket"... Mar 05 14:19:05 volumio volumio[21022]: info: Starting Socket.io Server version 2.3.0 Mar 05 14:19:05 volumio volumio[21022]: info: Loading i18n strings for locale it Mar 05 14:19:05 volumio volumio[21022]: Updating browse sources language Mar 05 14:19:05 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:19:06 volumio volumio-remote-updater[415]: [2025-03-05 14:19:06] [connect] Successful connection Mar 05 14:19:06 volumio volumio[21022]: Forking 1 albumart workers Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::initPlayerControls Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Mar 05 14:19:08 volumio volumio[21022]: Express server listening on port 3000 Mar 05 14:19:08 volumio volumio[21022]: [Metrics] WebUI: 40s 565.92ms Mar 05 14:19:08 volumio volumio[21022]: info: CoreStateMachine::resetVolumioState Mar 05 14:19:08 volumio volumio[21022]: info: CoreStateMachine::getcurrentVolume Mar 05 14:19:08 volumio volumio[21022]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 14:19:08 volumio volumio[21022]: info: Cannot mount NAS lorraine at system boot, trial number 2 ,retrying in 5 seconds Mar 05 14:19:09 volumio volumio[21022]: info: Cannot mount NAS lorraine at system boot, trial number 2 ,retrying in 5 seconds Mar 05 14:19:09 volumio volumio[21022]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Mar 05 14:19:09 volumio volumio[21022]: wlan0 Interface doesn't support scanning. Mar 05 14:19:09 volumio volumio[21022]: info: Cannot use regular scanning, forcing with ap-force Mar 05 14:19:09 volumio sudo[21126]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Mar 05 14:19:09 volumio sudo[21126]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:10 volumio sudo[21126]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:10 volumio volumio[21022]: command failed: No such device (-19) Mar 05 14:19:10 volumio volumio[21022]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Mar 05 14:19:10 volumio volumio[21022]: command failed: No such device (-19) Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 1 Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 2 Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 3 Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 4 Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5 Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6 Mar 05 14:19:11 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Mar 05 14:19:12 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Mar 05 14:19:12 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Mar 05 14:19:12 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Mar 05 14:19:12 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Mar 05 14:19:12 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Mar 05 14:19:12 volumio volumio[21022]: Unable to parse: Mar 05 14:19:12 volumio volumio[21022]: Simple mixer control 'Master',0 Mar 05 14:19:12 volumio volumio[21022]: Capabilities: volume volume-joined Mar 05 14:19:12 volumio volumio[21022]: Playback channels: Mono Mar 05 14:19:12 volumio volumio[21022]: Capture channels: Mono Mar 05 14:19:12 volumio volumio[21022]: Limits: 0 - 248 Mar 05 14:19:12 volumio volumio[21022]: Mono: 136 [55%] Mar 05 14:19:12 volumio volumio[21022]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Mar 05 14:19:13 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 14:19:13 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 14:19:13 volumio volumio[21022]: info: Discovery: Getting this device information Mar 05 14:19:13 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:13 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:13 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 14:19:13 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 13 Mar 05 14:19:13 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 14 Mar 05 14:19:13 volumio volumio[21022]: info: Reloading queue from file Mar 05 14:19:13 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:19:14 volumio volumio[21022]: Unable to parse: Mar 05 14:19:14 volumio volumio[21022]: Simple mixer control 'Master',0 Mar 05 14:19:14 volumio volumio[21022]: Capabilities: volume volume-joined Mar 05 14:19:14 volumio volumio[21022]: Playback channels: Mono Mar 05 14:19:14 volumio volumio[21022]: Capture channels: Mono Mar 05 14:19:14 volumio volumio[21022]: Limits: 0 - 248 Mar 05 14:19:14 volumio volumio[21022]: Mono: 136 [55%] Mar 05 14:19:14 volumio volumio[21022]: info: VolumeController:: Volume=undefined Mute =false Mar 05 14:19:14 volumio volumio[21022]: info: CoreStateMachine::pushState Mar 05 14:19:14 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:14 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 14:19:14 volumio volumio[21022]: info: CoreCommandRouter::volumioPushState Mar 05 14:19:14 volumio volumio[21022]: info: CoreStateMachine::updateTrackBlock Mar 05 14:19:14 volumio volumio[21022]: info: CorePlayQueue::getTrackBlock Mar 05 14:19:14 volumio volumio[21022]: info: CoreCommandRouter::volumioRetrievevolume Mar 05 14:19:14 volumio volumio[21022]: info: Cannot mount NAS lorraine at system boot, trial number 3 ,retrying in 5 seconds Mar 05 14:19:14 volumio volumio[21022]: info: Cannot mount NAS lorraine at system boot, trial number 3 ,retrying in 5 seconds Mar 05 14:19:14 volumio volumio[21022]: info: CoreStateMachine::setRepeat null single undefined Mar 05 14:19:14 volumio volumio[21022]: info: CoreStateMachine::pushState Mar 05 14:19:14 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:14 volumio volumio[21022]: info: CoreCommandRouter::volumioPushState Mar 05 14:19:14 volumio volumio[21022]: info: CoreStateMachine::setRandom false Mar 05 14:19:14 volumio volumio[21022]: info: CoreStateMachine::pushState Mar 05 14:19:14 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:14 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 14:19:14 volumio volumio[21022]: info: CoreCommandRouter::volumioPushState Mar 05 14:19:14 volumio volumio[21022]: info: Setting Device type: Raspberry PI Mar 05 14:19:14 volumio volumio[21022]: info: Completed loading Core Plugins Mar 05 14:19:14 volumio volumio[21022]: info: Preparing to generate the ALSA configuration file Mar 05 14:19:15 volumio volumio[21022]: Unable to parse: Mar 05 14:19:15 volumio volumio[21022]: Simple mixer control 'Master',0 Mar 05 14:19:15 volumio volumio[21022]: Capabilities: volume volume-joined Mar 05 14:19:15 volumio volumio[21022]: Playback channels: Mono Mar 05 14:19:15 volumio volumio[21022]: Capture channels: Mono Mar 05 14:19:15 volumio volumio[21022]: Limits: 0 - 248 Mar 05 14:19:15 volumio volumio[21022]: Mono: 136 [55%] Mar 05 14:19:15 volumio volumio[21022]: error: Cannot get ALSA Volume: Error: Alsa Mixer Error: failed to parse output Mar 05 14:19:15 volumio volumio[21022]: info: Asound.conf file unchanged, so no further update is needed Mar 05 14:19:15 volumio volumio[21022]: info: Output device has changed, restarting MPD Mar 05 14:19:15 volumio volumio[21022]: info: ___________ START PLUGINS ___________ Mar 05 14:19:16 volumio sudo[21140]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 14:19:16 volumio sudo[21140]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:16 volumio go-librespot[20918]: time="2025-03-05T14:19:16+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Mar 05 14:19:16 volumio go-librespot[20918]: time="2025-03-05T14:19:16+01:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.65.42:50362->34.158.1.133:4070: use of closed network connection" Mar 05 14:19:16 volumio volumio[21022]: info: ControllerMpd::onStart: Initializing MPD Mar 05 14:19:16 volumio volumio[21022]: info: Creating MPD Configuration file Mar 05 14:19:16 volumio sudo[21140]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:16 volumio go-librespot[20918]: time="2025-03-05T14:19:16+01:00" level=debug msg="obtained new client token: AACCDYzRzdcxSIJ3EgDLRagF3yvPU137mb9cff9L96Tse+JccyqdJ3n4jFA9gGc8EN207uSJkP+Hcp6i5kh3BTeYP0OBQrBv0926VqSQNcs6+BM/s6DXNmJQlz2hUqR1wj8wuXdPxu+LFc3CIOJTB5qyY7i9F0vLMueNxaSyGGdHR9WFjdkn9wQdcReT1SJtfMihRrBSBBkLZenNrLAcY+9PjD0wM4nqwzrG9gvQmgbr4q6+HgMdjKIeBOU=" Mar 05 14:19:16 volumio sudo[21142]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 14:19:16 volumio sudo[21142]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:16 volumio go-librespot[20918]: time="2025-03-05T14:19:16+01:00" level=debug msg="completed keyexchange" Mar 05 14:19:16 volumio volumio[21022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:19:16 volumio volumio[21022]: info: [1741180756816] CoreMusicLibrary::Adding element Last_100 Mar 05 14:19:16 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:19:16 volumio volumio[21022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:19:16 volumio volumio[21022]: info: [1741180756987] CoreMusicLibrary::Adding element Webradio Mar 05 14:19:17 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:19:17 volumio systemd[1]: Stopping Music Player Daemon... Mar 05 14:19:17 volumio sudo[21146]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Mar 05 14:19:17 volumio go-librespot[20918]: time="2025-03-05T14:19:17+01:00" level=debug msg="completed challenge" Mar 05 14:19:17 volumio go-librespot[20918]: time="2025-03-05T14:19:17+01:00" level=debug msg="authenticated as emma.falco" Mar 05 14:19:17 volumio sudo[21146]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:17 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 14:19:17 volumio sudo[21146]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:17 volumio volumio[21022]: info: Initializing BBC Radios Mar 05 14:19:17 volumio go-librespot[20918]: time="2025-03-05T14:19:17+01:00" level=debug msg="authenticated as emma.falco" Mar 05 14:19:17 volumio sudo[21148]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Mar 05 14:19:17 volumio systemd[1]: mpd.service: Succeeded. Mar 05 14:19:17 volumio sudo[21148]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:17 volumio systemd[1]: Stopped Music Player Daemon. Mar 05 14:19:17 volumio systemd[1]: Starting Music Player Daemon... Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="dealer connection opened" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=info msg="accepted zeroconf user emma.falco from IV2201" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="received connection id: MmE0YjliYTktYThjYi00NjI4LThiMjAtMDgxZTVkZmM1MmFlK2RlYWxlcit0Y3A6Ly8wYWNhNWExMi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArODM5NEQ5MkI0QUFGMTM3RjFEODk3RjAyOUUzNzNGOURBMUZGQjAxM0YwQkYyOTIzNDMzNjkyMTk1QkExM0U0Mw==" Mar 05 14:19:18 volumio systemd[1]: mpd.service: Control process exited, code=killed, status=15/TERM Mar 05 14:19:18 volumio systemd[1]: mpd.service: Succeeded. Mar 05 14:19:18 volumio systemd[1]: Stopped Music Player Daemon. Mar 05 14:19:18 volumio systemd[1]: Starting Music Player Daemon... Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="autoplay enabled: false" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="handling transfer player command from f350f1650d9f5b768ad558f2a6396fdd1598a4bc" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="resolved context of track" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:18 volumio go-librespot[20918]: time="2025-03-05T14:19:18+01:00" level=debug msg="loading track (paused: true, position: 271ms)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=trace msg="emitting websocket event: will_play" Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1658" Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=debug msg="selected format OGG_VORBIS_320 (17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=debug msg="requested aes key for file 17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634, gid: 0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:19 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 05 14:19:19 volumio go-librespot[20918]: time="2025-03-05T14:19:19+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1273" Mar 05 14:19:19 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:19:19 volumio sudo[21154]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Mar 05 14:19:19 volumio sudo[21154]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:19 volumio sudo[21154]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:20 volumio volumio[21022]: info: Creating Spotify config file Mar 05 14:19:20 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:21 volumio go-librespot[20918]: time="2025-03-05T14:19:21+01:00" level=debug msg="fetched first chunk of 16, total size is 8349532 bytes" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:21 volumio go-librespot[20918]: time="2025-03-05T14:19:21+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 05 14:19:21 volumio go-librespot[20918]: time="2025-03-05T14:19:21+01:00" level=trace msg="seek to 271ms (diff: 129ms, samples: 11951, bytes: 8631)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:21 volumio volumio-remote-updater[415]: [2025-03-05 14:19:21] [connect] Successful connection Mar 05 14:19:21 volumio volumio[21022]: Starting albumart workers Mar 05 14:19:22 volumio go-librespot[20918]: time="2025-03-05T14:19:22+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Mar 05 14:19:22 volumio go-librespot[20918]: time="2025-03-05T14:19:22+01:00" level=debug msg="created new output device" Mar 05 14:19:22 volumio go-librespot[20918]: time="2025-03-05T14:19:22+01:00" level=info msg="loaded track \"Searching for Lambs - Live in Goderich, Ontario / 2023\" (paused: true, position: 271ms, duration: 212359ms, prefetched: false)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=trace msg="emitting websocket event: metadata" Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=trace msg="emitting websocket event: active" Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:23 volumio volumio[21022]: info: Volumio Calling Home Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=trace msg="emitting websocket event: paused" Mar 05 14:19:23 volumio go-librespot[20918]: time="2025-03-05T14:19:23+01:00" level=debug msg="handling resume player command from f350f1650d9f5b768ad558f2a6396fdd1598a4bc" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=trace msg="seek to 271ms (diff: 129ms, samples: 11951, bytes: 8631)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=debug msg="resume track at 142ms" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=trace msg="scheduling prefetch in 182s" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:19:24 volumio go-librespot[20918]: time="2025-03-05T14:19:24+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=trace msg="emitting websocket event: playing" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=debug msg="handling play player command from f350f1650d9f5b768ad558f2a6396fdd1598a4bc" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=debug msg="resolved context of track" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=debug msg="loading track (paused: false, position: 170ms)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:25 volumio go-librespot[20918]: time="2025-03-05T14:19:25+01:00" level=trace msg="emitting websocket event: will_play" Mar 05 14:19:26 volumio go-librespot[20918]: time="2025-03-05T14:19:26+01:00" level=debug msg="selected format OGG_VORBIS_320 (17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:26 volumio go-librespot[20918]: time="2025-03-05T14:19:26+01:00" level=debug msg="requested aes key for file 17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634, gid: 0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:26 volumio go-librespot[20918]: time="2025-03-05T14:19:26+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:27 volumio go-librespot[20918]: time="2025-03-05T14:19:27+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:28 volumio go-librespot[20918]: time="2025-03-05T14:19:28+01:00" level=debug msg="fetched first chunk of 16, total size is 8349532 bytes" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:28 volumio go-librespot[20918]: time="2025-03-05T14:19:28+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 05 14:19:29 volumio go-librespot[20918]: time="2025-03-05T14:19:29+01:00" level=trace msg="seek to 170ms (diff: 141ms, samples: 7497, bytes: 2472)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:29 volumio go-librespot[20918]: time="2025-03-05T14:19:29+01:00" level=info msg="loaded track \"Searching for Lambs - Live in Goderich, Ontario / 2023\" (paused: false, position: 170ms, duration: 212359ms, prefetched: false)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:30 volumio go-librespot[20918]: time="2025-03-05T14:19:30+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:30 volumio volumio[21022]: info: Cannot mount NAS lorraine at system boot, trial number 4 ,retrying in 5 seconds Mar 05 14:19:30 volumio volumio[21022]: info: Cannot mount NAS lorraine at system boot, trial number 4 ,retrying in 5 seconds Mar 05 14:19:30 volumio volumio[21022]: info: Discovery: adding 75d53a79-d0fe-478a-b412-1f68d00b2179 Mar 05 14:19:30 volumio volumio[21022]: info: Discovery: Found device Volumio Mar 05 14:19:30 volumio go-librespot[20918]: time="2025-03-05T14:19:30+01:00" level=trace msg="scheduling prefetch in 182s" Mar 05 14:19:30 volumio go-librespot[20918]: time="2025-03-05T14:19:30+01:00" level=trace msg="emitting websocket event: metadata" Mar 05 14:19:30 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:30 volumio go-librespot[20918]: time="2025-03-05T14:19:30+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:19:30 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:31 volumio go-librespot[20918]: time="2025-03-05T14:19:31+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:31 volumio go-librespot[20918]: time="2025-03-05T14:19:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:31 volumio go-librespot[20918]: time="2025-03-05T14:19:31+01:00" level=trace msg="emitting websocket event: playing" Mar 05 14:19:31 volumio go-librespot[20918]: time="2025-03-05T14:19:31+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:31 volumio volumio[21022]: info: MPD Permissions set Mar 05 14:19:31 volumio volumio[21022]: info: MPD Permissions set Mar 05 14:19:31 volumio volumio[21022]: Unable to parse: Mar 05 14:19:31 volumio volumio[21022]: Simple mixer control 'Master',0 Mar 05 14:19:31 volumio volumio[21022]: Capabilities: volume volume-joined Mar 05 14:19:31 volumio volumio[21022]: Playback channels: Mono Mar 05 14:19:31 volumio volumio[21022]: Capture channels: Mono Mar 05 14:19:31 volumio volumio[21022]: Limits: 0 - 248 Mar 05 14:19:31 volumio volumio[21022]: Mono: 136 [55%] Mar 05 14:19:31 volumio volumio[21022]: info: VolumeController:: Volume=undefined Mute =false Mar 05 14:19:31 volumio volumio[21022]: info: CoreStateMachine::pushState Mar 05 14:19:31 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:31 volumio volumio[21022]: info: CoreCommandRouter::volumioPushState Mar 05 14:19:32 volumio go-librespot[20918]: time="2025-03-05T14:19:32+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:32 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 15 Mar 05 14:19:33 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 16 Mar 05 14:19:33 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 17 Mar 05 14:19:33 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 12; CPH2135 Build/RKQ1.211119.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.122 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 18 Mar 05 14:19:33 volumio volumio[21022]: info: Volumio called home Mar 05 14:19:33 volumio volumio[21022]: info: Spotify config file written Mar 05 14:19:34 volumio sudo[21231]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 05 14:19:34 volumio sudo[21231]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 05 14:19:35 volumio systemd[1]: Stopping go-librespot Daemon... Mar 05 14:19:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Mar 05 14:19:35 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Mar 05 14:19:35 volumio systemd[1]: Stopped go-librespot Daemon. Mar 05 14:19:35 volumio systemd[1]: Started go-librespot Daemon. Mar 05 14:19:35 volumio go-librespot[21233]: Librespot-go daemon starting... Mar 05 14:19:36 volumio sudo[21231]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:36 volumio go-librespot[21233]: time="2025-03-05T14:19:36+01:00" level=info msg="generated new device id: 931d3cdcf35f85c21f70dcb7f80faf9888516dfb" Mar 05 14:19:36 volumio go-librespot[21233]: time="2025-03-05T14:19:36+01:00" level=debug msg="stored credentials found for 31waql2gw4ltfg7ggpwaor5hv4ri" Mar 05 14:19:36 volumio volumio[21022]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 19 Mar 05 14:19:36 volumio volumio[21022]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Mar 05 14:19:36 volumio volumio[21022]: info: Cannot mount NAS at system boot, trial number 4 ,stopping Mar 05 14:19:36 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:36 volumio volumio-remote-updater[415]: [2025-03-05 14:19:36] [connect] Successful connection Mar 05 14:19:36 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:36 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:36 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:37 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:38 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:38 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:38 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Mar 05 14:19:38 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 05 14:19:41 volumio go-librespot[21233]: time="2025-03-05T14:19:41+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 05 14:19:41 volumio go-librespot[21233]: time="2025-03-05T14:19:41+01: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]" Mar 05 14:19:41 volumio go-librespot[21233]: time="2025-03-05T14:19:41+01: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]" Mar 05 14:19:41 volumio go-librespot[21233]: time="2025-03-05T14:19:41+01:00" level=debug msg="zeroconf server listening on port 34781" Mar 05 14:19:41 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 05 14:19:41 volumio go-librespot[21233]: time="2025-03-05T14:19:41+01:00" level=debug msg="obtained new client token: AACJC7O+Sus56Du8eZV4o+gHiSsy2SQhy4hhd02LqLME+ByqZgpkQru4/5i8IAJSHciAULP4oo2975FM7XMwYa7nwHCDblWA5DVZ9UFzy4grpf0cXU7o6dE644+d/yKbvBtp9Ivpxm9Xyxw+QwYi5qyodmmRUXWEC5AGK4FLtCXNs8Ox+8hi42MEKCh1UIqtrTHpTb002DXkEj3NtON35hojbepgDMlal/QvHijMXUmO9vLhv8r1sKYTGec=" Mar 05 14:19:42 volumio go-librespot[21233]: time="2025-03-05T14:19:42+01:00" level=debug msg="completed keyexchange" Mar 05 14:19:42 volumio go-librespot[21233]: time="2025-03-05T14:19:42+01:00" level=debug msg="completed challenge" Mar 05 14:19:42 volumio go-librespot[21233]: time="2025-03-05T14:19:42+01:00" level=debug msg="authenticated as 31waql2gw4ltfg7ggpwaor5hv4ri" Mar 05 14:19:43 volumio volumio[21022]: verbose: New Socket.io Connection to 192.168.65.42 from 192.168.65.120 UA: Mozilla/5.0 (Linux; Android 10; K) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 20 Mar 05 14:19:43 volumio go-librespot[21233]: time="2025-03-05T14:19:43+01:00" level=debug msg="authenticated as 31waql2gw4ltfg7ggpwaor5hv4ri" Mar 05 14:19:43 volumio go-librespot[21233]: time="2025-03-05T14:19:43+01:00" level=debug msg="dealer connection opened" Mar 05 14:19:43 volumio go-librespot[21233]: time="2025-03-05T14:19:43+01:00" level=debug msg="initializing zeroconf session, username: 31waql2gw4ltfg7ggpwaor5hv4ri" Mar 05 14:19:43 volumio go-librespot[21233]: time="2025-03-05T14:19:43+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 05 14:19:43 volumio go-librespot[21233]: time="2025-03-05T14:19:43+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 05 14:19:43 volumio go-librespot[21233]: time="2025-03-05T14:19:43+01:00" level=debug msg="received connection id: YWUyNGIzYWEtMWJiOC00ZjA3LTlmYmQtM2Q2NDY0ODlkZGZkK2RlYWxlcit0Y3A6Ly8wYWNhNTliOS5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArMkY1OURGNUFGNDZDNEY4MUFCOUI3MjgxMjUyMUNBODY0REJCQTI1RTNBMDhCODgzRTAzOTgxQkRCREI5NjVFOA==" Mar 05 14:19:44 volumio go-librespot[21233]: time="2025-03-05T14:19:44+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 05 14:19:44 volumio go-librespot[21233]: time="2025-03-05T14:19:44+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 05 14:19:44 volumio go-librespot[21233]: time="2025-03-05T14:19:44+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 05 14:19:44 volumio go-librespot[21233]: time="2025-03-05T14:19:44+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 05 14:19:44 volumio go-librespot[21233]: time="2025-03-05T14:19:44+01:00" level=debug msg="autoplay enabled: false" Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::volumioGetVisibleSources Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:44 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 05 14:19:44 volumio volumio[21022]: info: Received Get System Info Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 05 14:19:44 volumio volumio[21022]: info: Discovery: Getting this device information Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:44 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 05 14:19:44 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:44 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:45 volumio volumio[21022]: info: Listing playlists Mar 05 14:19:45 volumio volumio[21022]: info: CoreCommandRouter::volumioGetQueue Mar 05 14:19:45 volumio volumio[21022]: info: CoreStateMachine::getQueue Mar 05 14:19:45 volumio volumio[21022]: info: CorePlayQueue::getQueue Mar 05 14:19:45 volumio volumio[21022]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 05 14:19:45 volumio volumio[21022]: SPOTIFY: BQCpW2l1vaL76dqieirrJs7CuiIAo1Kt7tqx8Kkpvgk1XDlkATNZ3DyXKepGnfmeUnHvnCi4OadgFEl8tPW9famAWskPadvfH83tFqsAiC7-Vw5nNwL6JULYLBNC_XEL84BfmWP6xnz7Mor86LnCCFBDf2PR5ylwyutmVZQMBnX8AMwvcA9UuuYerLSKeIXTxkvsMkVhyo8u-GTpfPZWmfGA3YgpO7jUQW1ZBHnuKq-K6mOs8BMoBE-VRUd4dtMVu0mM5lVKkjWGtdMgft9KrBKqXhH0AsepTgHILhOUoNM Mar 05 14:19:45 volumio volumio[21022]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Mar 05 14:19:45 volumio volumio[21022]: info: New Spotify access token = BQCpW2l1vaL76dqieirrJs7CuiIAo1Kt7tqx8Kkpvgk1XDlkATNZ3DyXKepGnfmeUnHvnCi4OadgFEl8tPW9famAWskPadvfH83tFqsAiC7-Vw5nNwL6JULYLBNC_XEL84BfmWP6xnz7Mor86LnCCFBDf2PR5ylwyutmVZQMBnX8AMwvcA9UuuYerLSKeIXTxkvsMkVhyo8u-GTpfPZWmfGA3YgpO7jUQW1ZBHnuKq-K6mOs8BMoBE-VRUd4dtMVu0mM5lVKkjWGtdMgft9KrBKqXhH0AsepTgHILhOUoNM Mar 05 14:19:45 volumio volumio[21022]: info: Spotify credentials grant success - running version from March 24, 2019 Mar 05 14:19:46 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:46 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:46 volumio go-librespot[21233]: time="2025-03-05T14:19:46+01:00" level=error msg="failed receiving dealer message" error="failed to get reader: received close frame: status = StatusGoingAway and reason = \"\"" Mar 05 14:19:46 volumio go-librespot[21233]: time="2025-03-05T14:19:46+01:00" level=error msg="failed receiving packet" error="failed reading packet header: read tcp 192.168.65.42:33798->34.158.1.133:4070: use of closed network connection" Mar 05 14:19:46 volumio go-librespot[21233]: time="2025-03-05T14:19:46+01:00" level=debug msg="obtained new client token: AABBDPo6Yra7dAHboSyT+2v4BaXW5u2c2ePi8QPQVXKygfsywSmvWE+NEhErDXNjX5UEToJGif/eNKRdDcjpZTxnC35fTBAnvv3HZhhGcap1pA73PX+H/2PQ6iQ9BFxgVt5kqXin0U1b63rGJpUJy9OTvY5gzK+mUYJ7Abs0C4FSXzhfVq0qw+8kN4kLxJ/JcPPHsYNomGYmA01SQscI5i2RJIxjJzPm901RTJuPqZ25h7V9eNUTypvgaaQ=" Mar 05 14:19:46 volumio volumio[21022]: info: go-librespot daemon successfully initialized Mar 05 14:19:46 volumio go-librespot[21233]: time="2025-03-05T14:19:46+01:00" level=debug msg="completed keyexchange" Mar 05 14:19:47 volumio volumio[21022]: info: VolumeController::SetAlsaVolume- Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="completed challenge" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="authenticated as emma.falco" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="authenticated as emma.falco" Mar 05 14:19:47 volumio volumio[21022]: info: CoreStateMachine::pushState Mar 05 14:19:47 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:47 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Mar 05 14:19:47 volumio volumio[21022]: info: CoreCommandRouter::volumioPushState Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="dealer connection opened" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=info msg="accepted zeroconf user emma.falco from IV2201" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="received connection id: MzQzMmJhYjktY2MzOS00NGM1LWE2ZDAtNGQwNzY0MmFiYTk0K2RlYWxlcit0Y3A6Ly8wYWNhNTk3Mi5pcC5nZXc0LnNwb3RpZnkubmV0OjU3MDArQUQxMkJDNDg0REQwMTZDNTBGNkE1RTEwQ0E3MEU4MEI3OTdCMTg2NUIxNTBERjE4MURFRTMwM0Q0Qjk1MDIwQw==" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="put connect state because NEW_DEVICE" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Mar 05 14:19:47 volumio volumio[21022]: info: VolumeController::SetAlsaVolume- Mar 05 14:19:47 volumio go-librespot[21233]: time="2025-03-05T14:19:47+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="autoplay enabled: false" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="handling transfer player command from f350f1650d9f5b768ad558f2a6396fdd1598a4bc" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="resolved context of track" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="loading track (paused: true, position: 770ms)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:48 volumio volumio[21022]: info: CoreStateMachine::pushState Mar 05 14:19:48 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:48 volumio volumio[21022]: info: CoreCommandRouter::volumioPushState Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=trace msg="emitting websocket event: will_play" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1658" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="selected format OGG_VORBIS_320 (17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="requested aes key for file 17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634, gid: 0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:48 volumio go-librespot[21233]: time="2025-03-05T14:19:48+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1273" Mar 05 14:19:49 volumio volumio[21022]: SPOTIFY: User informations: {"country":"IT","display_name":"ilnidodeifalco","email":"wallyweek@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31waql2gw4ltfg7ggpwaor5hv4ri"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31waql2gw4ltfg7ggpwaor5hv4ri","id":"31waql2gw4ltfg7ggpwaor5hv4ri","images":[{"height":300,"url":"https://i.scdn.co/image/ab6775700000ee8551d61f446d48345d1bc201c4","width":300},{"height":64,"url":"https://i.scdn.co/image/ab67757000003b8251d61f446d48345d1bc201c4","width":64}],"product":"premium","type":"user","uri":"spotify:user:31waql2gw4ltfg7ggpwaor5hv4ri"} Mar 05 14:19:49 volumio volumio[21022]: info: Spotify Successfully logged in Mar 05 14:19:49 volumio volumio[21022]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Mar 05 14:19:49 volumio volumio[21022]: info: [1741180789628] CoreMusicLibrary::Adding element Spotify Mar 05 14:19:49 volumio volumio[21022]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 05 14:19:49 volumio volumio[21022]: Cannot find translation for source Spotify Mar 05 14:19:50 volumio volumio[21022]: info: Initializing connection to go-librespot Websocket Mar 05 14:19:50 volumio go-librespot[21233]: time="2025-03-05T14:19:50+01:00" level=debug msg="fetched first chunk of 16, total size is 8349532 bytes" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:50 volumio go-librespot[21233]: time="2025-03-05T14:19:50+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 05 14:19:50 volumio go-librespot[21233]: time="2025-03-05T14:19:50+01:00" level=debug msg="new websocket client" Mar 05 14:19:50 volumio go-librespot[21233]: time="2025-03-05T14:19:50+01:00" level=trace msg="seek to 770ms (diff: 62ms, samples: 33957, bytes: 39062)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:51 volumio mpd[21164]: Mar 05 14:19 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Mar 05 14:19:51 volumio volumio[21022]: info: Connection to go-librespot Websocket established Mar 05 14:19:51 volumio go-librespot[21233]: time="2025-03-05T14:19:51+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Mar 05 14:19:51 volumio go-librespot[21233]: time="2025-03-05T14:19:51+01:00" level=debug msg="created new output device" Mar 05 14:19:51 volumio volumio-remote-updater[415]: [2025-03-05 14:19:51] [connect] Successful connection Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=info msg="loaded track \"Searching for Lambs - Live in Goderich, Ontario / 2023\" (paused: true, position: 770ms, duration: 212359ms, prefetched: false)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=trace msg="emitting websocket event: metadata" Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=trace msg="emitting websocket event: active" Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Mar 05 14:19:52 volumio go-librespot[21233]: time="2025-03-05T14:19:52+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:52 volumio volumio-remote-updater[415]: [2025-03-05 14:19:52] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1741180791 101 Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:19:53 volumio volumio[21022]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 7 Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=trace msg="emitting websocket event: paused" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="handling play player command from f350f1650d9f5b768ad558f2a6396fdd1598a4bc" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="resolved context of track" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=trace msg="fetched new page 0 with 10 items (list: 10)" uri="spotify:album:0nVnqt5MCNd6RZv7biBwdZ" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="loading track (paused: false, position: 3ms)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:53 volumio volumio[21022]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0leEISE2mQGOnzd2SBO7lV","name":"Searching for Lambs - Live in Goderich, Ontario / 2023","artist_names":["Loreena McKennitt"],"album_name":"The Road Back Home","album_cover_url":"https://i.scdn.co/image/ab67616d00001e022e4b6430b8b39480cffeb957","position":770,"duration":212359,"release_date":"year:2024 month:3 day:8","track_number":1,"disc_number":1}} Mar 05 14:19:53 volumio volumio[21022]: SPOTIFY: received: {"type":"active","data":null} Mar 05 14:19:53 volumio volumio[21022]: info: Aligning Spotify Volume to Volumio Volume Mar 05 14:19:53 volumio volumio[21022]: info: CoreCommandRouter::volumioGetState Mar 05 14:19:53 volumio volumio[21022]: info: CorePlayQueue::getTrack 0 Mar 05 14:19:53 volumio volumio[21022]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:0leEISE2mQGOnzd2SBO7lV","play_origin":"playlist"}} Mar 05 14:19:53 volumio volumio[21022]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 14:19:53 volumio volumio[21022]: TypeError: Cannot read property 'service' of undefined Mar 05 14:19:53 volumio volumio[21022]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:336:50) Mar 05 14:19:53 volumio volumio[21022]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:270:18) Mar 05 14:19:53 volumio volumio[21022]: at WebSocket.message (/data/plugins/music_service/spop/index.js:189:14) Mar 05 14:19:53 volumio volumio[21022]: at WebSocket.emit (events.js:315:20) Mar 05 14:19:53 volumio volumio[21022]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Mar 05 14:19:53 volumio volumio[21022]: at Receiver.emit (events.js:315:20) Mar 05 14:19:53 volumio volumio[21022]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Mar 05 14:19:53 volumio volumio[21022]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Mar 05 14:19:53 volumio volumio[21022]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Mar 05 14:19:53 volumio volumio[21022]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Mar 05 14:19:53 volumio volumio[21022]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=trace msg="emitting websocket event: will_play" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:53 volumio go-librespot[21233]: time="2025-03-05T14:19:53+01:00" level=debug msg="selected format OGG_VORBIS_320 (17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:54 volumio go-librespot[21233]: time="2025-03-05T14:19:54+01:00" level=debug msg="requested aes key for file 17eb4cf820fdc8fb1a6f09b45adbe5d68cff6634, gid: 0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:54 volumio go-librespot[21233]: time="2025-03-05T14:19:54+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:54 volumio go-librespot[21233]: time="2025-03-05T14:19:54+01:00" level=debug msg="fetched first chunk of 16, total size is 8349532 bytes" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:54 volumio go-librespot[21233]: time="2025-03-05T14:19:54+01:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Mar 05 14:19:55 volumio go-librespot[21233]: time="2025-03-05T14:19:55+01:00" level=trace msg="seek to 3ms (diff: 3ms, samples: 132, bytes: 0)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:55 volumio go-librespot[21233]: time="2025-03-05T14:19:55+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Mar 05 14:19:55 volumio go-librespot[21233]: time="2025-03-05T14:19:55+01:00" level=info msg="loaded track \"Searching for Lambs - Live in Goderich, Ontario / 2023\" (paused: false, position: 3ms, duration: 212359ms, prefetched: false)" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:56 volumio go-librespot[21233]: time="2025-03-05T14:19:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:56 volumio go-librespot[21233]: time="2025-03-05T14:19:56+01:00" level=trace msg="scheduling prefetch in 182s" Mar 05 14:19:56 volumio go-librespot[21233]: time="2025-03-05T14:19:56+01:00" level=trace msg="emitting websocket event: metadata" Mar 05 14:19:56 volumio go-librespot[21233]: time="2025-03-05T14:19:56+01:00" level=debug msg="sending successful reply for dealer request" Mar 05 14:19:56 volumio go-librespot[21233]: time="2025-03-05T14:19:56+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Mar 05 14:19:56 volumio go-librespot[21233]: time="2025-03-05T14:19:56+01:00" level=trace msg="emitting websocket event: playing" Mar 05 14:19:56 volumio systemd[1]: Started Music Player Daemon. Mar 05 14:19:56 volumio sudo[21148]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:56 volumio sudo[21142]: pam_unix(sudo:session): session closed for user root Mar 05 14:19:57 volumio go-librespot[21233]: time="2025-03-05T14:19:57+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:57 volumio go-librespot[21233]: time="2025-03-05T14:19:57+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:19:58 volumio go-librespot[21233]: time="2025-03-05T14:19:58+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0leEISE2mQGOnzd2SBO7lV" Mar 05 14:20:02 volumio sudo[21272]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-05 14:19 Mar 05 14:20:02 volumio sudo[21272]: 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"