-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Thu 2025-07-10 13:06:22 CEST. -- Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=trace msg="sent dealer ping" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=trace msg="received dealer pong" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=debug msg="handling transfer player command from 60dccc44e42b509838cbd709847ae46a22a55047" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=debug msg="resolved context of track" uri="spotify:album:02ZecgD4McNRUyXtXzjtYk" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:album:02ZecgD4McNRUyXtXzjtYk" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=debug msg="loading track (paused: true, position: 53397ms)" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=trace msg="emitting websocket event: will_play" Jul 10 13:05:00 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","play_origin":"album"}} Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=debug msg="selected format OGG_VORBIS_320 (c6aa6dc1c0d1e65b432956e3e35fd3ce61e46d86)" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:00+02:00" level=debug msg="requested aes key for file c6aa6dc1c0d1e65b432956e3e35fd3ce61e46d86, gid: 6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched first chunk of 11, total size is 5717274 bytes" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 3/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 1/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 4/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=trace msg="seek to 53397ms (diff: 37ms, samples: 2354807, bytes: 2256029)" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="created new output device" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=info msg="loaded track \"Rotonde (we draaien rond)\" (paused: true, position: 53397ms, duration: 139034ms, prefetched: false)" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 2/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 7/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 5/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="fetched chunk 6/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=trace msg="emitting websocket event: metadata" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=trace msg="emitting websocket event: active" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="sending successful reply for dealer request" Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","name":"Rotonde (we draaien rond)","artist_names":["LUBACH"],"album_name":"Rotonde (we draaien rond)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","position":53397,"duration":139034,"release_date":"year:2025 month:6 day:10","track_number":1,"disc_number":1}} Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"active","data":null} Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: Aligning Spotify Volume to Volumio Volume Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioGetState Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CorePlayQueue::getTrack 0 Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: Setting Spotify Volume from Volumio: 46 Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:01 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:01+02:00" level=trace msg="emitting websocket event: paused" Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","play_origin":"album"}} Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: Spotify is playing in volatile mode Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CoreStateMachine::setConsumeUpdateService undefined Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: UNSET VOLATILE Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"stop","position":0,"title":"SLAM! Mixmarathon","albumart":"http://cdn-profiles.tunein.com/s296300/images/logoq.jpg?t=162428","uri":"https://stream.slam.nl/web13_mp3?dist=tunein","trackType":"webradio","seek":0,"samplerate":"","bitdepth":"","channels":0,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":46,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"webradio","updatedb":false,"volatile":false,"service":"webradio"} Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: PUSH STATE SPOTIFY Jul 10 13:05:01 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"pause","service":"spop","title":"Rotonde (we draaien rond)","artist":"LUBACH","album":"Rotonde (we draaien rond)","albumart":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","trackType":"spotify","seek":53397,"duration":139,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::servicePushState Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:01 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=debug msg="handling resume player command from 60dccc44e42b509838cbd709847ae46a22a55047" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=trace msg="seek to 53397ms (diff: 37ms, samples: 2354807, bytes: 2256029)" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=debug msg="resume track at 53360ms" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=trace msg="scheduling prefetch in 56s" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=debug msg="sending successful reply for dealer request" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:02 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:02+02:00" level=trace msg="emitting websocket event: playing" Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","play_origin":"album"}} Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: PUSH STATE SPOTIFY Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"play","service":"spop","title":"Rotonde (we draaien rond)","artist":"LUBACH","album":"Rotonde (we draaien rond)","albumart":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","trackType":"spotify","seek":53397,"duration":139,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::servicePushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: PUSH STATE SPOTIFY Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"play","service":"spop","title":"Rotonde (we draaien rond)","artist":"LUBACH","album":"Rotonde (we draaien rond)","albumart":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","trackType":"spotify","seek":53397,"duration":139,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::servicePushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:02 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioGetBrowseSources Jul 10 13:05:02 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 10 13:05:03 rpi-audio-merijn volumio[660]: SPOTIFY: SETTING SPOTIFY VOLUME 46 Jul 10 13:05:03 rpi-audio-merijn volumio[660]: info: Sending Spotify command with payload to local API: /player/volume Jul 10 13:05:03 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:03+02:00" level=debug msg="update volume to 30146/65535" Jul 10 13:05:04 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:04+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 10 13:05:04 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:04+02:00" level=trace msg="emitting websocket event: volume" Jul 10 13:05:04 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Jul 10 13:05:04 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: Received Get System Version Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: Received Get System Info Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: Discovery: Getting this device information Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioGetState Jul 10 13:05:05 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Jul 10 13:05:06 rpi-audio-merijn volumio[660]: error: MyVolumio Plugin failed to authenticate in a timely fashion Jul 10 13:05:06 rpi-audio-merijn volumio[660]: info: Completed starting MyVolumio Plugin Jul 10 13:05:06 rpi-audio-merijn volumio[660]: [Metrics] CommandRouter: 86s 879.62ms Jul 10 13:05:06 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumiosetStartupVolume Jul 10 13:05:06 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Jul 10 13:05:06 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 10 13:05:06 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::Close All Modals sent Jul 10 13:05:06 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::Close All Modals sent Jul 10 13:05:07 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Jul 10 13:05:07 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jul 10 13:05:07 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Jul 10 13:05:10 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:10+02:00" level=debug msg="fetched chunk 8/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:13 rpi-audio-merijn volumio[660]: info: BOOT COMPLETED Jul 10 13:05:16 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:16+02:00" level=debug msg="update volume to 32767/65535" Jul 10 13:05:16 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:16+02:00" level=debug msg="update volume to 49806/65535" Jul 10 13:05:16 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:16+02:00" level=debug msg="update volume to 50461/65535" Jul 10 13:05:17 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:17+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 10 13:05:17 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:17+02:00" level=trace msg="emitting websocket event: volume" Jul 10 13:05:17 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"volume","data":{"value":77,"max":100}} Jul 10 13:05:17 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED SPOTIFY VOLUME 77 Jul 10 13:05:17 rpi-audio-merijn volumio[660]: info: Setting Volumio Volume from Spotify: 77 Jul 10 13:05:17 rpi-audio-merijn volumio[660]: info: VolumeController::SetAlsaVolume77 Jul 10 13:05:17 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:17 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:17 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:17 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Jul 10 13:05:23 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:23+02:00" level=debug msg="fetched chunk 9/10, size: 524288" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:23 rpi-audio-merijn sudo[1255]: pam_unix(sudo:session): session closed for user root Jul 10 13:05:23 rpi-audio-merijn volumio[660]: info: Cannot mount NAS Synology at system boot, trial number 2 ,retrying in 5 seconds Jul 10 13:05:24 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:24+02:00" level=debug msg="update volume to 52428/65535" Jul 10 13:05:24 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:24+02:00" level=debug msg="update volume to 65535/65535" Jul 10 13:05:25 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:25+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 10 13:05:25 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:25+02:00" level=trace msg="emitting websocket event: volume" Jul 10 13:05:25 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Jul 10 13:05:25 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Jul 10 13:05:25 rpi-audio-merijn volumio[660]: info: Setting Volumio Volume from Spotify: 100 Jul 10 13:05:25 rpi-audio-merijn volumio[660]: info: VolumeController::SetAlsaVolume100 Jul 10 13:05:25 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:25 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:25 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:25 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 10 13:05:28 rpi-audio-merijn sudo[1477]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t nfs -o ro,soft,noauto 192.168.1.225:media /mnt/NAS/Synology Jul 10 13:05:28 rpi-audio-merijn sudo[1477]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 10 13:05:29 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:29+02:00" level=debug msg="handling pause player command from 60dccc44e42b509838cbd709847ae46a22a55047" Jul 10 13:05:29 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:29+02:00" level=debug msg="pause track at 80533ms" Jul 10 13:05:29 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:29 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:29+02:00" level=debug msg="sending successful reply for dealer request" Jul 10 13:05:29 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:29+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:29 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:29+02:00" level=trace msg="emitting websocket event: paused" Jul 10 13:05:29 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","play_origin":"album"}} Jul 10 13:05:29 rpi-audio-merijn volumio[660]: SPOTIFY: PUSH STATE SPOTIFY Jul 10 13:05:29 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"pause","service":"spop","title":"Rotonde (we draaien rond)","artist":"LUBACH","album":"Rotonde (we draaien rond)","albumart":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","trackType":"spotify","seek":80397,"duration":139,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 10 13:05:29 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::servicePushState Jul 10 13:05:29 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:29 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:29 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:29 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Jul 10 13:05:30 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:30+02:00" level=trace msg="sent dealer ping" Jul 10 13:05:30 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:30+02:00" level=trace msg="received dealer pong" Jul 10 13:05:35 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:35+02:00" level=debug msg="update volume to 60947/65535" Jul 10 13:05:35 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:35+02:00" level=debug msg="update volume to 15728/65535" Jul 10 13:05:36 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:36+02:00" level=debug msg="update volume to 15073/65535" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=trace msg="emitting websocket event: volume" Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"volume","data":{"value":23,"max":100}} Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED SPOTIFY VOLUME 23 Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: Setting Volumio Volume from Spotify: 23 Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: VolumeController::SetAlsaVolume23 Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="handling resume player command from 60dccc44e42b509838cbd709847ae46a22a55047" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=trace msg="seek to 80533ms (diff: 50ms, samples: 3551505, bytes: 3382818)" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="resume track at 80483ms" Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=trace msg="scheduling prefetch in 29s" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="sending successful reply for dealer request" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Jul 10 13:05:37 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:37+02:00" level=trace msg="emitting websocket event: playing" Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","play_origin":"album"}} Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: PUSH STATE SPOTIFY Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"play","service":"spop","title":"Rotonde (we draaien rond)","artist":"LUBACH","album":"Rotonde (we draaien rond)","albumart":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","trackType":"spotify","seek":80397,"duration":139,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::servicePushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: PUSH STATE SPOTIFY Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: {"status":"play","service":"spop","title":"Rotonde (we draaien rond)","artist":"LUBACH","album":"Rotonde (we draaien rond)","albumart":"https://i.scdn.co/image/ab67616d00001e029a1a57bbad1b5c87199f47b6","uri":"spotify:track:6couS5Po5EvlBqYyDgZ98E","trackType":"spotify","seek":80397,"duration":139,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::servicePushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:37 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 23 Jul 10 13:05:43 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:43+02:00" level=debug msg="fetched chunk 10/10, size: 474394" uri="spotify:track:6couS5Po5EvlBqYyDgZ98E" Jul 10 13:05:47 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:47+02:00" level=debug msg="update volume to 17694/65535" Jul 10 13:05:47 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:47+02:00" level=debug msg="update volume to 28835/65535" Jul 10 13:05:47 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:47+02:00" level=debug msg="update volume to 28180/65535" Jul 10 13:05:48 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:48+02:00" level=debug msg="update volume to 24903/65535" Jul 10 13:05:48 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:48+02:00" level=debug msg="update volume to 17694/65535" Jul 10 13:05:48 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:48+02:00" level=debug msg="update volume to 20971/65535" Jul 10 13:05:48 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:48+02:00" level=debug msg="update volume to 20315/65535" Jul 10 13:05:49 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:49+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Jul 10 13:05:49 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:05:49+02:00" level=trace msg="emitting websocket event: volume" Jul 10 13:05:49 rpi-audio-merijn volumio[660]: SPOTIFY: received: {"type":"volume","data":{"value":31,"max":100}} Jul 10 13:05:49 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED SPOTIFY VOLUME 31 Jul 10 13:05:49 rpi-audio-merijn volumio[660]: info: Setting Volumio Volume from Spotify: 31 Jul 10 13:05:49 rpi-audio-merijn volumio[660]: info: VolumeController::SetAlsaVolume31 Jul 10 13:05:50 rpi-audio-merijn volumio[660]: info: CoreStateMachine::pushState Jul 10 13:05:50 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Jul 10 13:05:50 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioPushState Jul 10 13:05:50 rpi-audio-merijn volumio[660]: SPOTIFY: RECEIVED VOLUMIO VOLUME 31 Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::getUIConfigOnPlugin Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Jul 10 13:05:55 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Jul 10 13:06:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:06:00+02:00" level=trace msg="sent dealer ping" Jul 10 13:06:00 rpi-audio-merijn go-librespot[1198]: time="2025-07-10T13:06:00+02:00" level=trace msg="received dealer pong" Jul 10 13:06:07 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::volumioGetState Jul 10 13:06:15 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 10 13:06:15 rpi-audio-merijn sudo[1477]: pam_unix(sudo:session): session closed for user root Jul 10 13:06:15 rpi-audio-merijn volumio[660]: info: Cannot mount NAS Synology at system boot, trial number 3 ,retrying in 5 seconds Jul 10 13:06:15 rpi-audio-merijn volumio[660]: info: Preload queue cleared Jul 10 13:06:16 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 10 13:06:16 rpi-audio-merijn volumio[660]: info: Preload queue cleared Jul 10 13:06:17 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 10 13:06:17 rpi-audio-merijn volumio[660]: info: Preload queue cleared Jul 10 13:06:20 rpi-audio-merijn volumio[660]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Jul 10 13:06:20 rpi-audio-merijn sudo[1604]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t nfs -o ro,soft,noauto 192.168.1.225:media /mnt/NAS/Synology Jul 10 13:06:20 rpi-audio-merijn sudo[1604]: pam_unix(sudo:session): session opened for user root by (uid=0) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 10 13:06:20 rpi-audio-merijn volumio[660]: TypeError: Cannot read property 'length' of undefined Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at Parser.emit (events.js:315:20) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at IncomingMessage.emit (events.js:327:22) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at endReadableNT (internal/streams/readable.js:1327:12) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Jul 10 13:06:20 rpi-audio-merijn volumio[660]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Jul 10 13:06:22 rpi-audio-merijn sudo[1619]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-07-10 13:05 Jul 10 13:06:22 rpi-audio-merijn sudo[1619]: 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="a142ed2648fb91920de0dde3a60cd39b5d0ba4f6" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="811ff8312d42f9da0260be1d353081a805678820" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 02 Jul 2025 04:07:25 PM CEST" VOLUMIO_VERSION="3.819" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="3b9115b1943141a9d7186aa434f8f3c2"