-- Logs begin at Thu 2019-02-14 10:11:58 GMT, end at Sat 2025-05-10 09:23:51 BST. -- May 10 09:22:03 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings May 10 09:22:03 rhodesrpi volumio[1358]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 May 10 09:22:03 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioGetState May 10 09:22:03 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:22:04 rhodesrpi ntpd[796]: Soliciting pool server 162.159.200.123 May 10 09:22:04 rhodesrpi ntpd[796]: Soliciting pool server 162.159.200.1 May 10 09:22:05 rhodesrpi ntpd[796]: Soliciting pool server 178.79.143.32 May 10 09:22:05 rhodesrpi ntpd[796]: Soliciting pool server 109.74.206.120 May 10 09:22:05 rhodesrpi ntpd[796]: Soliciting pool server 213.5.132.231 May 10 09:22:06 rhodesrpi ntpd[796]: Soliciting pool server 145.40.176.243 May 10 09:22:06 rhodesrpi ntpd[796]: Soliciting pool server 82.219.4.30 May 10 09:22:06 rhodesrpi ntpd[796]: Soliciting pool server 91.109.118.94 May 10 09:22:06 rhodesrpi ntpd[796]: Soliciting pool server 178.62.18.76 May 10 09:22:07 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 10 09:22:07 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:22:07 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled May 10 09:22:07 rhodesrpi volumio-remote-updater[652]: No test mode May 10 09:22:07 rhodesrpi volumio-remote-updater[652]: No alpha test mode May 10 09:22:07 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled May 10 09:22:07 rhodesrpi volumio[1358]: info: Update Ready: {"changeLogLink":"","description":"You're already on the latest version","title":"No Updates Available","updateavailable":false} May 10 09:22:07 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache May 10 09:22:07 rhodesrpi ntpd[796]: Soliciting pool server 80.87.128.222 May 10 09:22:07 rhodesrpi ntpd[796]: Soliciting pool server 77.74.199.184 May 10 09:22:07 rhodesrpi ntpd[796]: Soliciting pool server 80.87.128.222 May 10 09:22:07 rhodesrpi ntpd[796]: Soliciting pool server 77.104.162.218 May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioGetBrowseSources May 10 09:22:08 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion May 10 09:22:08 rhodesrpi ntpd[796]: Soliciting pool server 63.135.73.82 May 10 09:22:08 rhodesrpi ntpd[796]: Soliciting pool server 2a11:29c0:11::31 May 10 09:22:09 rhodesrpi volumio[1358]: error: MyVolumio Plugin failed to authenticate in a timely fashion May 10 09:22:09 rhodesrpi volumio[1358]: info: Completed starting MyVolumio Plugin May 10 09:22:09 rhodesrpi volumio[1358]: [Metrics] CommandRouter: 35s 525.89ms May 10 09:22:09 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumiosetStartupVolume May 10 09:22:09 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:22:09 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:22:09 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:22:09 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:22:09 rhodesrpi volumio[1358]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 10 09:22:09 rhodesrpi volumio[1358]: info: FusionDsp - ---- read samplerate from file: 44100 May 10 09:22:09 rhodesrpi volumio[1358]: info: camilladsp stopping service pid 1597... May 10 09:22:09 rhodesrpi volumio[1358]: info: camilladsp service terminated, instance 1 May 10 09:22:09 rhodesrpi volumio[1358]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 10 09:22:09 rhodesrpi volumio[1358]: info: camilladsp service started and running in background, instance 1 May 10 09:22:09 rhodesrpi volumio[1358]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 10 09:22:09 rhodesrpi volumio[1358]: info: FusionDsp - ---- read samplerate from file: 44100 May 10 09:22:09 rhodesrpi volumio[1358]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 10 09:22:09 rhodesrpi volumio[1358]: error: FusionDsp - WebSocket error: [object Object] May 10 09:22:10 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable May 10 09:22:10 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus May 10 09:22:10 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect May 10 09:22:14 rhodesrpi ntpd[796]: receive: Unexpected origin timestamp 0xebc98b34.ec24db49 does not match aorg 0000000000.00000000 from server@178.62.18.76 xmt 0xebc98b36.270284c1 May 10 09:22:14 rhodesrpi ntpd[796]: receive: Unexpected origin timestamp 0xebc98b34.ec23d3bb does not match aorg 0000000000.00000000 from server@77.74.199.184 xmt 0xebc98b36.2780d9e0 May 10 09:22:14 rhodesrpi ntpd[796]: receive: Unexpected origin timestamp 0xebc98b34.ec26da9d does not match aorg 0000000000.00000000 from server@213.5.132.231 xmt 0xebc98b36.26d13f86 May 10 09:22:14 rhodesrpi ntpd[796]: receive: Unexpected origin timestamp 0xebc98b34.ec1f14bf does not match aorg 0000000000.00000000 from server@63.135.73.82 xmt 0xebc98b36.279002f2 May 10 09:22:17 rhodesrpi volumio[1358]: info: BOOT COMPLETED May 10 09:22:24 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:24+01:00" level=debug msg="obtained new client token: AADhsmtLByXo+GcFtwPGFJyJSuCLoo3NGrDtYoKXwstAh+DmhbI+8v+mHHUnqMGJFD75ILwGbZn9fSMIoHhMfKufSbE5LSowLQnP4QmMSu1pmOMF52KyfFbx/fTcLj0B3DDvqhEsN92aEbPb9zwdzm8aIx8AgKsmkit7mgBXUJ0DDrblBitcGrVwahT95Gqm+mQJkbNaeKAoQv/KBOYM1ea+G/GLTRCWnkqzj0q+RM0AhnAmVIY4fZ5r" May 10 09:22:25 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:25+01:00" level=debug msg="connected to ap-gew1.spotify.com:4070" May 10 09:22:25 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:25+01:00" level=debug msg="completed keyexchange" May 10 09:22:25 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:25+01:00" level=debug msg="completed challenge" May 10 09:22:25 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:25+01:00" level=info msg="authenticated AP as 31qiqd7unifdykc235cnrod7cj4u" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=info msg="authenticated Login5 as 31qiqd7unifdykc235cnrod7cj4u" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=info msg="accepted zeroconf user 31qiqd7unifdykc235cnrod7cj4u from V60" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="dealer connection opened" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=trace msg="starting accesspoint recv loop" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=trace msg="starting dealer recv loop" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=trace msg="received accesspoint ping" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="received connection id: ZjczZDBlMjgtMmRkNy00YzM1LWE3OTItMGVhMDFlNTU5MzExK2RlYWxlcit0Y3A6Ly8wYWNhNDBiZS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArMjNFMTRCRThFNTVGNEVBRkVCNzZCNjg1QzI3NTYyOTA5NUU3MTU5MTE2NkY3QjgwRDVGNTlENzdDQjkyQTc5Ng==" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=trace msg="received accesspoint pong ack" May 10 09:22:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:26+01:00" level=debug msg="put connect state because NEW_DEVICE" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="handling transfer player command from adf3715eb6ce97868bd44f2c968be87466ba9615" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1DX3fRquEp6m8D" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=trace msg="fetched new page 0 with 55 items (list: 55)" uri="spotify:playlist:37i9dQZF1DX3fRquEp6m8D" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="loading track (paused: false, position: 6107ms)" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=trace msg="emitting websocket event: will_play" May 10 09:22:27 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:1vYXt7VSjH9JIM5oRRo7vA","play_origin":"playlist"}} May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 345" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="selected format OGG_VORBIS_320 (3a2ba40c5d44327c2742d07f292af8317953df08)" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="requested aes key for file 3a2ba40c5d44327c2742d07f292af8317953df08, gid: 1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:27 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:27+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1370" May 10 09:22:28 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:28+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1130" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="fetched first chunk of 16, total size is 7930568 bytes" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=trace msg="seek to 6107ms (diff: 123ms, samples: 269318, bytes: 252851)" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="created new output device" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01: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" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=info msg="loaded track \"Dance The Night - From Barbie The Album\" (paused: false, position: 6107ms, duration: 176579ms, prefetched: false)" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:29 rhodesrpi volumio[1358]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 May 10 09:22:29 rhodesrpi volumio[1358]: info: FusionDsp - ---- read samplerate from file: 44100 May 10 09:22:29 rhodesrpi volumio[1358]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 10 09:22:29 rhodesrpi volumio[1358]: info: FusionDsp - {"Reload":{"result":"Ok"}} May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=trace msg="scheduling prefetch in 139s" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=trace msg="emitting websocket event: metadata" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=trace msg="emitting websocket event: active" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="sending successful reply for dealer request" May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:1vYXt7VSjH9JIM5oRRo7vA","name":"Dance The Night - From Barbie The Album","artist_names":["Dua Lipa"],"album_name":"Dance The Night (From Barbie The Album)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e027dd3ba455ee3390cb55b0192","position":6107,"duration":176579,"release_date":"year:2023 month:5 day:25","track_number":1,"disc_number":1}} May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"active","data":null} May 10 09:22:29 rhodesrpi volumio[1358]: info: Aligning Spotify Volume to Volumio Volume May 10 09:22:29 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioGetState May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 10 09:22:29 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:22:29 rhodesrpi volumio[1358]: info: Setting Spotify Volume from Volumio: 100 May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:29 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:29+01:00" level=trace msg="emitting websocket event: playing" May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:1vYXt7VSjH9JIM5oRRo7vA","play_origin":"playlist"}} May 10 09:22:29 rhodesrpi volumio[1358]: info: Spotify is playing in volatile mode May 10 09:22:29 rhodesrpi volumio[1358]: info: CoreStateMachine::setConsumeUpdateService undefined May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: UNSET VOLATILE May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":100,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: PUSH STATE SPOTIFY May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: {"status":"play","service":"spop","title":"Dance The Night - From Barbie The Album","artist":"Dua Lipa","album":"Dance The Night (From Barbie The Album)","albumart":"https://i.scdn.co/image/ab67616d00001e027dd3ba455ee3390cb55b0192","uri":"spotify:track:1vYXt7VSjH9JIM5oRRo7vA","trackType":"spotify","seek":6107,"duration":176,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} May 10 09:22:29 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:22:29 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:22:29 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 09:22:29 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:22:29 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:22:30 rhodesrpi volumio[1358]: SPOTIFY: PUSH STATE SPOTIFY May 10 09:22:30 rhodesrpi volumio[1358]: SPOTIFY: {"status":"play","service":"spop","title":"Dance The Night - From Barbie The Album","artist":"Dua Lipa","album":"Dance The Night (From Barbie The Album)","albumart":"https://i.scdn.co/image/ab67616d00001e027dd3ba455ee3390cb55b0192","uri":"spotify:track:1vYXt7VSjH9JIM5oRRo7vA","trackType":"spotify","seek":6107,"duration":176,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 10 09:22:30 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:22:30 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:22:30 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:22:30 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:31 rhodesrpi volumio[1358]: SPOTIFY: SETTING SPOTIFY VOLUME 100 May 10 09:22:31 rhodesrpi volumio[1358]: info: Sending Spotify command with payload to local API: /player/volume May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="update volume to 65535/65535" May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="handling skip_next player command from adf3715eb6ce97868bd44f2c968be87466ba9615" May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=trace msg="emitting websocket event: will_play" May 10 09:22:31 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","play_origin":"playlist"}} May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:1vYXt7VSjH9JIM5oRRo7vA" May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="selected format OGG_VORBIS_320 (89cd611be35913e4b617df8d08621c2c6d806dd8)" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:31 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:31+01:00" level=debug msg="requested aes key for file 89cd611be35913e4b617df8d08621c2c6d806dd8, gid: 4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=debug msg="fetched first chunk of 18, total size is 9209928 bytes" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=info msg="loaded track \"New Rules\" (paused: false, position: 0ms, duration: 212000ms, prefetched: false)" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=trace msg="scheduling prefetch in 182s" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=trace msg="emitting websocket event: metadata" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=debug msg="sending successful reply for dealer request" May 10 09:22:32 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","name":"New Rules","artist_names":["Dua Lipa"],"album_name":"Dua Lipa (Deluxe)","album_cover_url":"https://i.scdn.co/image/ab67616d00001e025576b115926aa2069bcf0c7f","position":0,"duration":212000,"release_date":"year:2017 month:6 day:2","track_number":10,"disc_number":1}} May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=debug msg="put connect state because VOLUME_CHANGED" May 10 09:22:32 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:32+01:00" level=trace msg="emitting websocket event: volume" May 10 09:22:32 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} May 10 09:22:32 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 May 10 09:22:33 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:33+01:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:33 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:33+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:33 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:33+01:00" level=trace msg="emitting websocket event: playing" May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","play_origin":"playlist"}} May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: PUSH STATE SPOTIFY May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: {"status":"play","service":"spop","title":"New Rules","artist":"Dua Lipa","album":"Dua Lipa (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e025576b115926aa2069bcf0c7f","uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","trackType":"spotify","seek":1000,"duration":212,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: PUSH STATE SPOTIFY May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: {"status":"play","service":"spop","title":"New Rules","artist":"Dua Lipa","album":"Dua Lipa (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e025576b115926aa2069bcf0c7f","uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","trackType":"spotify","seek":1000,"duration":212,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:22:33 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:22:33 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:22:34 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:34+01:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:34 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:34+01:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:4LihUZcWy0B6lGLqcJ8u9B" May 10 09:22:34 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:34+01:00" level=debug msg="handling pause player command from adf3715eb6ce97868bd44f2c968be87466ba9615" May 10 09:22:34 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:34+01:00" level=debug msg="pause track at 2617ms" May 10 09:22:35 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:35+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:35 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:35+01:00" level=debug msg="sending successful reply for dealer request" May 10 09:22:35 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:35+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" May 10 09:22:35 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:35+01:00" level=trace msg="emitting websocket event: paused" May 10 09:22:35 rhodesrpi volumio[1358]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","play_origin":"playlist"}} May 10 09:22:35 rhodesrpi volumio[1358]: SPOTIFY: PUSH STATE SPOTIFY May 10 09:22:35 rhodesrpi volumio[1358]: SPOTIFY: {"status":"pause","service":"spop","title":"New Rules","artist":"Dua Lipa","album":"Dua Lipa (Deluxe)","albumart":"https://i.scdn.co/image/ab67616d00001e025576b115926aa2069bcf0c7f","uri":"spotify:track:4LihUZcWy0B6lGLqcJ8u9B","trackType":"spotify","seek":3000,"duration":212,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} May 10 09:22:35 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:22:35 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:22:35 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 09:22:35 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:22:35 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:22:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 10 09:22:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 10 09:22:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:22:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:22:36 rhodesrpi volumio[1358]: info: FusionDsp - May 10 09:22:37 rhodesrpi volumio[1358]: info: FusionDsp - May 10 09:22:37 rhodesrpi volumio[1358]: info: FusionDsp - undefined May 10 09:22:37 rhodesrpi volumio[1358]: info: FusionDsp - undefined May 10 09:22:40 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:22:40 rhodesrpi volumio[1358]: info: FusionDsp - May 10 09:22:40 rhodesrpi volumio[1358]: info: FusionDsp - undefined May 10 09:22:48 rhodesrpi volumio[1358]: info: CALLMETHOD: audio_interface fusiondsp choosedsp [object Object] May 10 09:22:48 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , choosedsp May 10 09:22:48 rhodesrpi volumio[1358]: error: FusionDsp - File size not found in array! May 10 09:22:48 rhodesrpi volumio[1358]: info: FusionDsp - Nulleq applied May 10 09:22:48 rhodesrpi volumio[1358]: info: FusionDsp - {"Reload":{"result":"Ok"}} May 10 09:22:48 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:22:48 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:22:48 rhodesrpi volumio[1358]: info: FusionDsp - Choose a preset May 10 09:22:48 rhodesrpi volumio[1358]: info: FusionDsp - kef.json,test.json May 10 09:22:55 rhodesrpi volumio[1358]: info: CALLMETHOD: audio_interface fusiondsp choosedsp [object Object] May 10 09:22:55 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , choosedsp May 10 09:22:55 rhodesrpi volumio[1358]: info: FusionDsp - If filter freq >samplerate/2 then disable it May 10 09:22:55 rhodesrpi volumio[1358]: info: FusionDsp - Nulleq applied May 10 09:22:55 rhodesrpi volumio[1358]: info: FusionDsp - {"Reload":{"result":"Ok"}} May 10 09:22:55 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:22:55 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:22:55 rhodesrpi volumio[1358]: info: FusionDsp - Choose a preset May 10 09:22:55 rhodesrpi volumio[1358]: info: FusionDsp - May 10 09:22:56 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:56+01:00" level=trace msg="sent dealer ping" May 10 09:22:56 rhodesrpi go-librespot[1537]: time="2025-05-10T09:22:56+01:00" level=trace msg="received dealer pong" May 10 09:23:12 rhodesrpi volumio[1358]: info: CALLMETHOD: audio_interface fusiondsp installtools May 10 09:23:12 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: fusiondsp , installtools May 10 09:23:21 rhodesrpi volumio[1358]: --2025-05-10 09:23:12-- https://github.com/balbuze/volumio-plugins/raw/alsa_modular/plugins/audio_interface/FusionDsp/tools/tools.tar.xz May 10 09:23:21 rhodesrpi volumio[1358]: Resolving github.com (github.com)... 20.26.156.215 May 10 09:23:21 rhodesrpi volumio[1358]: Connecting to github.com (github.com)|20.26.156.215|:443... connected. May 10 09:23:21 rhodesrpi volumio[1358]: HTTP request sent, awaiting response... 302 Found May 10 09:23:21 rhodesrpi volumio[1358]: Location: https://raw.githubusercontent.com/balbuze/volumio-plugins/alsa_modular/plugins/audio_interface/FusionDsp/tools/tools.tar.xz [following] May 10 09:23:21 rhodesrpi volumio[1358]: --2025-05-10 09:23:12-- https://raw.githubusercontent.com/balbuze/volumio-plugins/alsa_modular/plugins/audio_interface/FusionDsp/tools/tools.tar.xz May 10 09:23:21 rhodesrpi volumio[1358]: Resolving raw.githubusercontent.com (raw.githubusercontent.com)... 185.199.110.133, 185.199.111.133, 185.199.108.133, ... May 10 09:23:21 rhodesrpi volumio[1358]: Connecting to raw.githubusercontent.com (raw.githubusercontent.com)|185.199.110.133|:443... connected. May 10 09:23:21 rhodesrpi volumio[1358]: HTTP request sent, awaiting response... 200 OK May 10 09:23:21 rhodesrpi volumio[1358]: Length: 23035700 (22M) [application/octet-stream] May 10 09:23:21 rhodesrpi volumio[1358]: Saving to: ‘/tmp/tools.tar.xz’ May 10 09:23:21 rhodesrpi volumio[1358]: 0K .......... .......... .......... .......... .......... 0% 736K 30s May 10 09:23:21 rhodesrpi volumio[1358]: 50K .......... .......... .......... .......... .......... 0% 3.23M 19s May 10 09:23:21 rhodesrpi volumio[1358]: 100K .......... .......... .......... .......... .......... 0% 5.29M 14s May 10 09:23:21 rhodesrpi volumio[1358]: 150K .......... .......... .......... .......... .......... 0% 1.50M 14s May 10 09:23:21 rhodesrpi volumio[1358]: 200K .......... .......... .......... .......... .......... 1% 1.05M 15s May 10 09:23:21 rhodesrpi volumio[1358]: 250K .......... .......... .......... .......... .......... 1% 3.74M 14s May 10 09:23:21 rhodesrpi volumio[1358]: 300K .......... .......... .......... .......... .......... 1% 3.74M 13s May 10 09:23:21 rhodesrpi volumio[1358]: 350K .......... .......... .......... .......... .......... 1% 4.15M 12s May 10 09:23:21 rhodesrpi volumio[1358]: 400K .......... .......... .......... .......... .......... 2% 2.80M 11s May 10 09:23:21 rhodesrpi volumio[1358]: 450K .......... .......... .......... .......... .......... 2% 5.56M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 500K .......... .......... .......... .......... .......... 2% 1.85M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 550K .......... .......... .......... .......... .......... 2% 5.50M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 600K .......... .......... .......... .......... .......... 2% 1.63M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 650K .......... .......... .......... .......... .......... 3% 3.72M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 700K .......... .......... .......... .......... .......... 3% 1.32M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 750K .......... .......... .......... .......... .......... 3% 3.71M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 800K .......... .......... .......... .......... .......... 3% 2.91M 10s May 10 09:23:21 rhodesrpi volumio[1358]: 850K .......... .......... .......... .......... .......... 4% 6.84M 9s May 10 09:23:21 rhodesrpi volumio[1358]: 900K .......... .......... .......... .......... .......... 4% 3.58M 9s May 10 09:23:21 rhodesrpi volumio[1358]: 950K .......... .......... .......... .......... .......... 4% 3.84M 9s May 10 09:23:21 rhodesrpi volumio[1358]: 1000K .......... .......... .......... .......... .......... 4% 3.48M 9s May 10 09:23:21 rhodesrpi volumio[1358]: 1050K .......... .......... .......... .......... .......... 4% 5.30M 9s May 10 09:23:21 rhodesrpi volumio[1358]: 1100K .......... .......... .......... .......... .......... 5% 2.42M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1150K .......... .......... .......... .......... .......... 5% 4.94M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1200K .......... .......... .......... .......... .......... 5% 2.72M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1250K .......... .......... .......... .......... .......... 5% 2.76M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1300K .......... .......... .......... .......... .......... 6% 2.73M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1350K .......... .......... .......... .......... .......... 6% 4.36M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1400K .......... .......... .......... .......... .......... 6% 909K 9s May 10 09:23:21 rhodesrpi volumio[1358]: 1450K .......... .......... .......... .......... .......... 6% 2.92M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1500K .......... .......... .......... .......... .......... 6% 1.88M 9s May 10 09:23:21 rhodesrpi volumio[1358]: 1550K .......... .......... .......... .......... .......... 7% 3.02M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1600K .......... .......... .......... .......... .......... 7% 2.45M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1650K .......... .......... .......... .......... .......... 7% 9.10M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1700K .......... .......... .......... .......... .......... 7% 2.10M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1750K .......... .......... .......... .......... .......... 8% 8.78M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1800K .......... .......... .......... .......... .......... 8% 2.59M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1850K .......... .......... .......... .......... .......... 8% 4.94M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1900K .......... .......... .......... .......... .......... 8% 3.03M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 1950K .......... .......... .......... .......... .......... 8% 3.66M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2000K .......... .......... .......... .......... .......... 9% 4.43M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2050K .......... .......... .......... .......... .......... 9% 2.32M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2100K .......... .......... .......... .......... .......... 9% 4.35M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2150K .......... .......... .......... .......... .......... 9% 3.73M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2200K .......... .......... .......... .......... .......... 10% 3.18M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2250K .......... .......... .......... .......... .......... 10% 3.08M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2300K .......... .......... .......... .......... .......... 10% 10.7M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2350K .......... .......... .......... .......... .......... 10% 867K 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2400K .......... .......... .......... .......... .......... 10% 1.98M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2450K .......... .......... .......... .......... .......... 11% 2.71M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2500K .......... .......... .......... .......... .......... 11% 2.47M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2550K .......... .......... .......... .......... .......... 11% 4.02M 8s May 10 09:23:21 rhodesrpi volumio[1358]: 2600K .......... .......... .......... .......... .......... 11% 3.25M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2650K .......... .......... .......... .......... .......... 12% 3.50M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2700K .......... .......... .......... .......... .......... 12% 3.10M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2750K .......... .......... .......... .......... .......... 12% 3.17M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2800K .......... .......... .......... .......... .......... 12% 4.31M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2850K .......... .......... .......... .......... .......... 12% 2.46M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2900K .......... .......... .......... .......... .......... 13% 5.36M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 2950K .......... .......... .......... .......... .......... 13% 1.03M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3000K .......... .......... .......... .......... .......... 13% 11.8M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3050K .......... .......... .......... .......... .......... 13% 6.31M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3100K .......... .......... .......... .......... .......... 14% 7.00M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3150K .......... .......... .......... .......... .......... 14% 1.50M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3200K .......... .......... .......... .......... .......... 14% 4.26M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3250K .......... .......... .......... .......... .......... 14% 3.62M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3300K .......... .......... .......... .......... .......... 14% 2.43M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3350K .......... .......... .......... .......... .......... 15% 2.31M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3400K .......... .......... .......... .......... .......... 15% 2.35M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3450K .......... .......... .......... .......... .......... 15% 4.07M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3500K .......... .......... .......... .......... .......... 15% 4.07M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3550K .......... .......... .......... .......... .......... 16% 3.02M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3600K .......... .......... .......... .......... .......... 16% 2.71M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3650K .......... .......... .......... .......... .......... 16% 4.15M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3700K .......... .......... .......... .......... .......... 16% 6.03M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3750K .......... .......... .......... .......... .......... 16% 2.39M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3800K .......... .......... .......... .......... .......... 17% 4.00M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3850K .......... .......... .......... .......... .......... 17% 3.20M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3900K .......... .......... .......... .......... .......... 17% 15.1M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 3950K .......... .......... .......... .......... .......... 17% 953K 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4000K .......... .......... .......... .......... .......... 18% 1.08M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4050K .......... .......... .......... .......... .......... 18% 3.15M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4100K .......... .......... .......... .......... .......... 18% 2.46M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4150K .......... .......... .......... .......... .......... 18% 3.14M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4200K .......... .......... .......... .......... .......... 18% 4.78M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4250K .......... .......... .......... .......... .......... 19% 729K 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4300K .......... .......... .......... .......... .......... 19% 4.25M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4350K .......... .......... .......... .......... .......... 19% 4.60M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4400K .......... .......... .......... .......... .......... 19% 3.06M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4450K .......... .......... .......... .......... .......... 20% 7.63M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4500K .......... .......... .......... .......... .......... 20% 2.59M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4550K .......... .......... .......... .......... .......... 20% 5.69M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4600K .......... .......... .......... .......... .......... 20% 2.21M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4650K .......... .......... .......... .......... .......... 20% 4.06M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4700K .......... .......... .......... .......... .......... 21% 3.71M 7s May 10 09:23:21 rhodesrpi volumio[1358]: 4750K .......... .......... .......... .......... .......... 21% 6.58M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 4800K .......... .......... .......... .......... .......... 21% 4.02M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 4850K .......... .......... .......... .......... .......... 21% 2.58M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 4900K .......... .......... .......... .......... .......... 22% 3.30M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 4950K .......... .......... .......... .......... .......... 22% 2.91M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5000K .......... .......... .......... .......... .......... 22% 4.19M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5050K .......... .......... .......... .......... .......... 22% 5.97M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5100K .......... .......... .......... .......... .......... 22% 4.67M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5150K .......... .......... .......... .......... .......... 23% 2.73M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5200K .......... .......... .......... .......... .......... 23% 4.36M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5250K .......... .......... .......... .......... .......... 23% 2.28M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5300K .......... .......... .......... .......... .......... 23% 2.35M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5350K .......... .......... .......... .......... .......... 24% 4.99M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5400K .......... .......... .......... .......... .......... 24% 6.31M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5450K .......... .......... .......... .......... .......... 24% 3.16M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5500K .......... .......... .......... .......... .......... 24% 5.36M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5550K .......... .......... .......... .......... .......... 24% 5.59M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5600K .......... .......... .......... .......... .......... 25% 4.49M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5650K .......... .......... .......... .......... .......... 25% 2.90M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5700K .......... .......... .......... .......... .......... 25% 8.51M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5750K .......... .......... .......... .......... .......... 25% 2.50M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5800K .......... .......... .......... .......... .......... 26% 2.71M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5850K .......... .......... .......... .......... .......... 26% 4.05M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5900K .......... .......... .......... .......... .......... 26% 3.19M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 5950K .......... .......... .......... .......... .......... 26% 4.47M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6000K .......... .......... .......... .......... .......... 26% 1.91M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6050K .......... .......... .......... .......... .......... 27% 3.96M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6100K .......... .......... .......... .......... .......... 27% 2.99M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6150K .......... .......... .......... .......... .......... 27% 4.48M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6200K .......... .......... .......... .......... .......... 27% 4.03M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6250K .......... .......... .......... .......... .......... 28% 3.19M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6300K .......... .......... .......... .......... .......... 28% 4.58M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6350K .......... .......... .......... .......... .......... 28% 1.68M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6400K .......... .......... .......... .......... .......... 28% 7.63M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6450K .......... .......... .......... .......... .......... 28% 1.79M 6s May 10 09:23:21 rhodesrpi volumio[1358]: 6500K .......... .......... .......... .......... .......... 29% 5.55M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6550K .......... .......... .......... .......... .......... 29% 4.68M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6600K .......... .......... .......... .......... .......... 29% 5.48M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6650K .......... .......... .......... .......... .......... 29% 4.33M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6700K .......... .......... .......... .......... .......... 30% 1.96M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6750K .......... .......... .......... .......... .......... 30% 8.04M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6800K .......... .......... .......... .......... .......... 30% 5.14M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6850K .......... .......... .......... .......... .......... 30% 1.96M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6900K .......... .......... .......... .......... .......... 30% 4.48M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 6950K .......... .......... .......... .......... .......... 31% 5.52M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7000K .......... .......... .......... .......... .......... 31% 4.04M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7050K .......... .......... .......... .......... .......... 31% 5.48M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7100K .......... .......... .......... .......... .......... 31% 2.34M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7150K .......... .......... .......... .......... .......... 32% 4.92M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7200K .......... .......... .......... .......... .......... 32% 2.79M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7250K .......... .......... .......... .......... .......... 32% 2.30M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7300K .......... .......... .......... .......... .......... 32% 8.19M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7350K .......... .......... .......... .......... .......... 32% 3.13M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7400K .......... .......... .......... .......... .......... 33% 12.0M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7450K .......... .......... .......... .......... .......... 33% 2.73M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7500K .......... .......... .......... .......... .......... 33% 4.14M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7550K .......... .......... .......... .......... .......... 33% 6.92M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7600K .......... .......... .......... .......... .......... 34% 1.53M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7650K .......... .......... .......... .......... .......... 34% 3.56M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7700K .......... .......... .......... .......... .......... 34% 2.96M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7750K .......... .......... .......... .......... .......... 34% 5.42M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7800K .......... .......... .......... .......... .......... 34% 2.70M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7850K .......... .......... .......... .......... .......... 35% 5.24M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7900K .......... .......... .......... .......... .......... 35% 2.88M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 7950K .......... .......... .......... .......... .......... 35% 4.37M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8000K .......... .......... .......... .......... .......... 35% 1.99M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8050K .......... .......... .......... .......... .......... 36% 5.46M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8100K .......... .......... .......... .......... .......... 36% 4.17M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8150K .......... .......... .......... .......... .......... 36% 2.82M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8200K .......... .......... .......... .......... .......... 36% 5.04M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8250K .......... .......... .......... .......... .......... 36% 2.79M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8300K .......... .......... .......... .......... .......... 37% 3.03M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8350K .......... .......... .......... .......... .......... 37% 2.81M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8400K .......... .......... .......... .......... .......... 37% 4.39M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8450K .......... .......... .......... .......... .......... 37% 6.02M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8500K .......... .......... .......... .......... .......... 38% 3.21M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8550K .......... .......... .......... .......... .......... 38% 3.20M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8600K .......... .......... .......... .......... .......... 38% 4.78M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8650K .......... .......... .......... .......... .......... 38% 2.80M 5s May 10 09:23:21 rhodesrpi volumio[1358]: 8700K .......... .......... .......... .......... .......... 38% 5.55M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 8750K .......... .......... .......... .......... .......... 39% 4.07M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 8800K .......... .......... .......... .......... .......... 39% 3.53M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 8850K .......... .......... .......... .......... .......... 39% 3.82M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 8900K .......... .......... .......... .......... .......... 39% 820K 4s May 10 09:23:21 rhodesrpi volumio[1358]: 8950K .......... .......... .......... .......... .......... 40% 3.74M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9000K .......... .......... .......... .......... .......... 40% 4.56M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9050K .......... .......... .......... .......... .......... 40% 3.09M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9100K .......... .......... .......... .......... .......... 40% 1.19M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9150K .......... .......... .......... .......... .......... 40% 1.00M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9200K .......... .......... .......... .......... .......... 41% 3.18M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9250K .......... .......... .......... .......... .......... 41% 2.97M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9300K .......... .......... .......... .......... .......... 41% 3.26M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9350K .......... .......... .......... .......... .......... 41% 8.41M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9400K .......... .......... .......... .......... .......... 42% 3.01M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9450K .......... .......... .......... .......... .......... 42% 2.20M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9500K .......... .......... .......... .......... .......... 42% 2.41M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9550K .......... .......... .......... .......... .......... 42% 2.73M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9600K .......... .......... .......... .......... .......... 42% 3.35M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9650K .......... .......... .......... .......... .......... 43% 4.47M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9700K .......... .......... .......... .......... .......... 43% 5.15M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9750K .......... .......... .......... .......... .......... 43% 1.62M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9800K .......... .......... .......... .......... .......... 43% 9.42M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9850K .......... .......... .......... .......... .......... 44% 3.68M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9900K .......... .......... .......... .......... .......... 44% 1.64M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 9950K .......... .......... .......... .......... .......... 44% 9.12M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10000K .......... .......... .......... .......... .......... 44% 1.53M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10050K .......... .......... .......... .......... .......... 44% 1.08M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10100K .......... .......... .......... .......... .......... 45% 2.91M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10150K .......... .......... .......... .......... .......... 45% 5.27M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10200K .......... .......... .......... .......... .......... 45% 2.53M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10250K .......... .......... .......... .......... .......... 45% 3.76M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10300K .......... .......... .......... .......... .......... 46% 2.89M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10350K .......... .......... .......... .......... .......... 46% 3.90M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10400K .......... .......... .......... .......... .......... 46% 6.12M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10450K .......... .......... .......... .......... .......... 46% 2.50M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10500K .......... .......... .......... .......... .......... 46% 3.93M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10550K .......... .......... .......... .......... .......... 47% 4.06M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10600K .......... .......... .......... .......... .......... 47% 3.68M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10650K .......... .......... .......... .......... .......... 47% 2.81M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10700K .......... .......... .......... .......... .......... 47% 3.86M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10750K .......... .......... .......... .......... .......... 48% 4.49M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10800K .......... .......... .......... .......... .......... 48% 4.59M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10850K .......... .......... .......... .......... .......... 48% 1.53M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10900K .......... .......... .......... .......... .......... 48% 18.6M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 10950K .......... .......... .......... .......... .......... 48% 1.83M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11000K .......... .......... .......... .......... .......... 49% 4.26M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11050K .......... .......... .......... .......... .......... 49% 3.22M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11100K .......... .......... .......... .......... .......... 49% 3.29M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11150K .......... .......... .......... .......... .......... 49% 2.68M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11200K .......... .......... .......... .......... .......... 50% 3.88M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11250K .......... .......... .......... .......... .......... 50% 3.52M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11300K .......... .......... .......... .......... .......... 50% 2.29M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11350K .......... .......... .......... .......... .......... 50% 3.36M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11400K .......... .......... .......... .......... .......... 50% 8.22M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11450K .......... .......... .......... .......... .......... 51% 3.01M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11500K .......... .......... .......... .......... .......... 51% 1.94M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11550K .......... .......... .......... .......... .......... 51% 6.56M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11600K .......... .......... .......... .......... .......... 51% 2.09M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11650K .......... .......... .......... .......... .......... 52% 3.14M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11700K .......... .......... .......... .......... .......... 52% 5.08M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11750K .......... .......... .......... .......... .......... 52% 4.07M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11800K .......... .......... .......... .......... .......... 52% 1.84M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11850K .......... .......... .......... .......... .......... 52% 3.45M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11900K .......... .......... .......... .......... .......... 53% 2.24M 4s May 10 09:23:21 rhodesrpi volumio[1358]: 11950K .......... .......... .......... .......... .......... 53% 5.51M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12000K .......... .......... .......... .......... .......... 53% 3.54M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12050K .......... .......... .......... .......... .......... 53% 4.39M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12100K .......... .......... .......... .......... .......... 54% 5.41M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12150K .......... .......... .......... .......... .......... 54% 1.89M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12200K .......... .......... .......... .......... .......... 54% 4.49M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12250K .......... .......... .......... .......... .......... 54% 2.44M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12300K .......... .......... .......... .......... .......... 54% 5.21M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12350K .......... .......... .......... .......... .......... 55% 3.43M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12400K .......... .......... .......... .......... .......... 55% 923K 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12450K .......... .......... .......... .......... .......... 55% 3.07M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12500K .......... .......... .......... .......... .......... 55% 5.20M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12550K .......... .......... .......... .......... .......... 56% 1.83M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12600K .......... .......... .......... .......... .......... 56% 1.19M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12650K .......... .......... .......... .......... .......... 56% 1.72M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12700K .......... .......... .......... .......... .......... 56% 927K 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12750K .......... .......... .......... .......... .......... 56% 708K 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12800K .......... .......... .......... .......... .......... 57% 15.4M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12850K .......... .......... .......... .......... .......... 57% 4.87M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12900K .......... .......... .......... .......... .......... 57% 5.05M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 12950K .......... .......... .......... .......... .......... 57% 1.26M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13000K .......... .......... .......... .......... .......... 58% 2.10M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13050K .......... .......... .......... .......... .......... 58% 3.53M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13100K .......... .......... .......... .......... .......... 58% 1.16M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13150K .......... .......... .......... .......... .......... 58% 941K 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13200K .......... .......... .......... .......... .......... 58% 2.27M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13250K .......... .......... .......... .......... .......... 59% 6.65M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13300K .......... .......... .......... .......... .......... 59% 3.39M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13350K .......... .......... .......... .......... .......... 59% 1.84M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13400K .......... .......... .......... .......... .......... 59% 2.93M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13450K .......... .......... .......... .......... .......... 60% 3.33M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13500K .......... .......... .......... .......... .......... 60% 3.37M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13550K .......... .......... .......... .......... .......... 60% 5.08M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13600K .......... .......... .......... .......... .......... 60% 4.26M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13650K .......... .......... .......... .......... .......... 60% 5.23M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13700K .......... .......... .......... .......... .......... 61% 1.79M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13750K .......... .......... .......... .......... .......... 61% 4.66M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13800K .......... .......... .......... .......... .......... 61% 3.48M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13850K .......... .......... .......... .......... .......... 61% 3.46M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13900K .......... .......... .......... .......... .......... 62% 3.83M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 13950K .......... .......... .......... .......... .......... 62% 4.22M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14000K .......... .......... .......... .......... .......... 62% 2.72M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14050K .......... .......... .......... .......... .......... 62% 2.34M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14100K .......... .......... .......... .......... .......... 62% 2.36M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14150K .......... .......... .......... .......... .......... 63% 4.25M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14200K .......... .......... .......... .......... .......... 63% 3.13M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14250K .......... .......... .......... .......... .......... 63% 8.03M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14300K .......... .......... .......... .......... .......... 63% 5.04M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14350K .......... .......... .......... .......... .......... 64% 3.64M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14400K .......... .......... .......... .......... .......... 64% 4.56M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14450K .......... .......... .......... .......... .......... 64% 2.33M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14500K .......... .......... .......... .......... .......... 64% 2.45M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14550K .......... .......... .......... .......... .......... 64% 2.74M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14600K .......... .......... .......... .......... .......... 65% 9.42M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14650K .......... .......... .......... .......... .......... 65% 3.32M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14700K .......... .......... .......... .......... .......... 65% 4.79M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14750K .......... .......... .......... .......... .......... 65% 3.70M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14800K .......... .......... .......... .......... .......... 66% 3.65M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14850K .......... .......... .......... .......... .......... 66% 4.28M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14900K .......... .......... .......... .......... .......... 66% 2.86M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 14950K .......... .......... .......... .......... .......... 66% 3.32M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 15000K .......... .......... .......... .......... .......... 66% 6.11M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 15050K .......... .......... .......... .......... .......... 67% 4.17M 3s May 10 09:23:21 rhodesrpi volumio[1358]: 15100K .......... .......... .......... .......... .......... 67% 4.76M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15150K .......... .......... .......... .......... .......... 67% 4.67M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15200K .......... .......... .......... .......... .......... 67% 1.74M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15250K .......... .......... .......... .......... .......... 68% 2.94M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15300K .......... .......... .......... .......... .......... 68% 3.36M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15350K .......... .......... .......... .......... .......... 68% 3.15M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15400K .......... .......... .......... .......... .......... 68% 6.95M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15450K .......... .......... .......... .......... .......... 68% 3.79M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15500K .......... .......... .......... .......... .......... 69% 3.27M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15550K .......... .......... .......... .......... .......... 69% 2.90M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15600K .......... .......... .......... .......... .......... 69% 2.79M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15650K .......... .......... .......... .......... .......... 69% 2.40M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15700K .......... .......... .......... .......... .......... 70% 3.33M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15750K .......... .......... .......... .......... .......... 70% 3.68M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15800K .......... .......... .......... .......... .......... 70% 2.62M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15850K .......... .......... .......... .......... .......... 70% 3.21M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15900K .......... .......... .......... .......... .......... 70% 15.2M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 15950K .......... .......... .......... .......... .......... 71% 4.07M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16000K .......... .......... .......... .......... .......... 71% 2.13M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16050K .......... .......... .......... .......... .......... 71% 3.01M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16100K .......... .......... .......... .......... .......... 71% 3.27M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16150K .......... .......... .......... .......... .......... 72% 2.23M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16200K .......... .......... .......... .......... .......... 72% 4.26M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16250K .......... .......... .......... .......... .......... 72% 3.42M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16300K .......... .......... .......... .......... .......... 72% 3.98M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16350K .......... .......... .......... .......... .......... 72% 2.10M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16400K .......... .......... .......... .......... .......... 73% 3.70M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16450K .......... .......... .......... .......... .......... 73% 3.09M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16500K .......... .......... .......... .......... .......... 73% 1.80M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16550K .......... .......... .......... .......... .......... 73% 2.04M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16600K .......... .......... .......... .......... .......... 74% 2.43M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16650K .......... .......... .......... .......... .......... 74% 13.9M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16700K .......... .......... .......... .......... .......... 74% 4.89M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16750K .......... .......... .......... .......... .......... 74% 3.46M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16800K .......... .......... .......... .......... .......... 74% 2.67M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16850K .......... .......... .......... .......... .......... 75% 4.91M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16900K .......... .......... .......... .......... .......... 75% 1.96M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 16950K .......... .......... .......... .......... .......... 75% 383K 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17000K .......... .......... .......... .......... .......... 75% 5.50M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17050K .......... .......... .......... .......... .......... 76% 3.80M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17100K .......... .......... .......... .......... .......... 76% 1.89M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17150K .......... .......... .......... .......... .......... 76% 5.54M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17200K .......... .......... .......... .......... .......... 76% 1.99M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17250K .......... .......... .......... .......... .......... 76% 465K 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17300K .......... .......... .......... .......... .......... 77% 550K 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17350K .......... .......... .......... .......... .......... 77% 1.12M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17400K .......... .......... .......... .......... .......... 77% 1.43M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17450K .......... .......... .......... .......... .......... 77% 743K 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17500K .......... .......... .......... .......... .......... 78% 1.36M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17550K .......... .......... .......... .......... .......... 78% 2.11M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17600K .......... .......... .......... .......... .......... 78% 1.75M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17650K .......... .......... .......... .......... .......... 78% 4.49M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17700K .......... .......... .......... .......... .......... 78% 1.09M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17750K .......... .......... .......... .......... .......... 79% 1.40M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17800K .......... .......... .......... .......... .......... 79% 3.43M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17850K .......... .......... .......... .......... .......... 79% 4.97M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17900K .......... .......... .......... .......... .......... 79% 2.33M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 17950K .......... .......... .......... .......... .......... 80% 1.62M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18000K .......... .......... .......... .......... .......... 80% 9.56M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18050K .......... .......... .......... .......... .......... 80% 3.73M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18100K .......... .......... .......... .......... .......... 80% 1.67M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18150K .......... .......... .......... .......... .......... 80% 3.74M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18200K .......... .......... .......... .......... .......... 81% 2.25M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18250K .......... .......... .......... .......... .......... 81% 4.50M 2s May 10 09:23:21 rhodesrpi volumio[1358]: 18300K .......... .......... .......... .......... .......... 81% 3.27M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18350K .......... .......... .......... .......... .......... 81% 5.30M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18400K .......... .......... .......... .......... .......... 82% 4.27M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18450K .......... .......... .......... .......... .......... 82% 3.65M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18500K .......... .......... .......... .......... .......... 82% 2.94M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18550K .......... .......... .......... .......... .......... 82% 1.69M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18600K .......... .......... .......... .......... .......... 82% 4.71M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18650K .......... .......... .......... .......... .......... 83% 2.64M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18700K .......... .......... .......... .......... .......... 83% 4.44M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18750K .......... .......... .......... .......... .......... 83% 3.16M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18800K .......... .......... .......... .......... .......... 83% 4.04M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18850K .......... .......... .......... .......... .......... 84% 4.26M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18900K .......... .......... .......... .......... .......... 84% 2.17M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 18950K .......... .......... .......... .......... .......... 84% 4.60M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19000K .......... .......... .......... .......... .......... 84% 3.13M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19050K .......... .......... .......... .......... .......... 84% 4.63M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19100K .......... .......... .......... .......... .......... 85% 2.41M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19150K .......... .......... .......... .......... .......... 85% 2.94M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19200K .......... .......... .......... .......... .......... 85% 1.64M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19250K .......... .......... .......... .......... .......... 85% 14.6M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19300K .......... .......... .......... .......... .......... 86% 3.08M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19350K .......... .......... .......... .......... .......... 86% 3.65M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19400K .......... .......... .......... .......... .......... 86% 5.58M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19450K .......... .......... .......... .......... .......... 86% 1.83M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19500K .......... .......... .......... .......... .......... 86% 4.88M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19550K .......... .......... .......... .......... .......... 87% 3.84M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19600K .......... .......... .......... .......... .......... 87% 1.70M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19650K .......... .......... .......... .......... .......... 87% 3.60M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19700K .......... .......... .......... .......... .......... 87% 1.48M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19750K .......... .......... .......... .......... .......... 88% 3.06M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19800K .......... .......... .......... .......... .......... 88% 1.49M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19850K .......... .......... .......... .......... .......... 88% 2.80M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19900K .......... .......... .......... .......... .......... 88% 5.30M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 19950K .......... .......... .......... .......... .......... 88% 3.43M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20000K .......... .......... .......... .......... .......... 89% 3.92M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20050K .......... .......... .......... .......... .......... 89% 3.41M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20100K .......... .......... .......... .......... .......... 89% 5.16M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20150K .......... .......... .......... .......... .......... 89% 2.51M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20200K .......... .......... .......... .......... .......... 90% 5.78M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20250K .......... .......... .......... .......... .......... 90% 541K 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20300K .......... .......... .......... .......... .......... 90% 1.92M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20350K .......... .......... .......... .......... .......... 90% 606K 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20400K .......... .......... .......... .......... .......... 90% 3.26M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20450K .......... .......... .......... .......... .......... 91% 4.81M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20500K .......... .......... .......... .......... .......... 91% 1.65M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20550K .......... .......... .......... .......... .......... 91% 2.85M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20600K .......... .......... .......... .......... .......... 91% 1.59M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20650K .......... .......... .......... .......... .......... 92% 1.75M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20700K .......... .......... .......... .......... .......... 92% 4.34M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20750K .......... .......... .......... .......... .......... 92% 2.73M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20800K .......... .......... .......... .......... .......... 92% 5.29M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20850K .......... .......... .......... .......... .......... 92% 1.45M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20900K .......... .......... .......... .......... .......... 93% 1.78M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 20950K .......... .......... .......... .......... .......... 93% 10.1M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 21000K .......... .......... .......... .......... .......... 93% 3.75M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 21050K .......... .......... .......... .......... .......... 93% 1.86M 1s May 10 09:23:21 rhodesrpi volumio[1358]: 21100K .......... .......... .......... .......... .......... 94% 3.95M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21150K .......... .......... .......... .......... .......... 94% 2.47M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21200K .......... .......... .......... .......... .......... 94% 2.29M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21250K .......... .......... .......... .......... .......... 94% 4.21M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21300K .......... .......... .......... .......... .......... 94% 3.60M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21350K .......... .......... .......... .......... .......... 95% 3.62M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21400K .......... .......... .......... .......... .......... 95% 1.55M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21450K .......... .......... .......... .......... .......... 95% 3.65M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21500K .......... .......... .......... .......... .......... 95% 3.80M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21550K .......... .......... .......... .......... .......... 96% 3.42M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21600K .......... .......... .......... .......... .......... 96% 3.38M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21650K .......... .......... .......... .......... .......... 96% 3.68M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21700K .......... .......... .......... .......... .......... 96% 3.07M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21750K .......... .......... .......... .......... .......... 96% 997K 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21800K .......... .......... .......... .......... .......... 97% 2.78M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21850K .......... .......... .......... .......... .......... 97% 3.91M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21900K .......... .......... .......... .......... .......... 97% 3.51M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 21950K .......... .......... .......... .......... .......... 97% 2.29M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22000K .......... .......... .......... .......... .......... 98% 3.89M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22050K .......... .......... .......... .......... .......... 98% 1.18M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22100K .......... .......... .......... .......... .......... 98% 5.45M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22150K .......... .......... .......... .......... .......... 98% 2.84M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22200K .......... .......... .......... .......... .......... 98% 1.61M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22250K .......... .......... .......... .......... .......... 99% 4.07M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22300K .......... .......... .......... .......... .......... 99% 2.57M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22350K .......... .......... .......... .......... .......... 99% 3.68M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22400K .......... .......... .......... .......... .......... 99% 3.99M 0s May 10 09:23:21 rhodesrpi volumio[1358]: 22450K .......... .......... .......... .......... ..... 100% 3.53M=8.2s May 10 09:23:21 rhodesrpi volumio[1358]: 2025-05-10 09:23:21 (2.68 MB/s) - ‘/tmp/tools.tar.xz’ saved [23035700/23035700] May 10 09:23:24 rhodesrpi volumio-remote-updater[652]: [2025-05-10 09:23:24] [disconnect] Disconnect close local:[1008,Pong timeout] remote:[1006] May 10 09:23:25 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:23:25 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:25 rhodesrpi volumio[1358]: info: FusionDsp - Choose a preset May 10 09:23:25 rhodesrpi volumio[1358]: info: FusionDsp - May 10 09:23:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:23:26+01:00" level=trace msg="sent dealer ping" May 10 09:23:26 rhodesrpi go-librespot[1537]: time="2025-05-10T09:23:26+01:00" level=trace msg="received dealer pong" May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: mpd , updateDb May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand update May 10 09:23:27 rhodesrpi volumio[1358]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 4 May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand update took 23 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 28 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 25 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 24 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 24 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 24 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 22 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 21 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 21 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatetrue May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatetrue May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatetrue May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatetrue May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:27 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:27 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:27 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:27 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:27 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:27 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:27 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":true,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:27 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:27 rhodesrpi volumio[1358]: info: ------------------------------ 744ms May 10 09:23:27 rhodesrpi volumio[1358]: info: ------------------------------ 741ms May 10 09:23:27 rhodesrpi volumio[1358]: info: ------------------------------ 741ms May 10 09:23:27 rhodesrpi volumio[1358]: info: ------------------------------ 738ms May 10 09:23:27 rhodesrpi volumio[1358]: info: MPD Database updated - AlbumList cache refreshed May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: database May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:27 rhodesrpi volumio[1358]: info: MPD Database updated - AlbumList cache refreshed May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: database May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: MPD Database updated - AlbumList cache refreshed May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: database May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: MPD Database updated - AlbumList cache refreshed May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: database May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: May 10 09:23:27 rhodesrpi volumio[1358]: ---------------------------- MPD announces state update: update May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: ControllerMpd::getState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::sendMpdCommand status May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 34 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 34 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 34 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 24 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 23 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 22 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 19 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 18 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 17 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 16 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 14 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: info: sendMpdCommand status took 14 milliseconds May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatefalse May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatefalse May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatefalse May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: info: Command Router : Notfying DB Updatefalse May 10 09:23:27 rhodesrpi volumio[1358]: info: CoreCommandRouter::Close All Modals sent May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:27 rhodesrpi volumio[1358]: verbose: ControllerMpd::parseState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ControllerMpd::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::servicePushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CorePlayQueue::getTrack 0 May 10 09:23:28 rhodesrpi volumio[1358]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} May 10 09:23:28 rhodesrpi volumio[1358]: verbose: CURRENT POSITION 0 May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState stateService stop May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::syncState currentStatus pause May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreStateMachine::pushState May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioPushState May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 187ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 187ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 177ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 178ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 173ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 174ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 171ms May 10 09:23:28 rhodesrpi volumio[1358]: info: ------------------------------ 171ms May 10 09:23:28 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioGetState May 10 09:23:28 rhodesrpi volumio[1358]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 5 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:28 rhodesrpi volumio[1358]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 May 10 09:23:29 rhodesrpi volumio-remote-updater[652]: [2025-05-10 09:23:29] [connect] Successful connection May 10 09:23:29 rhodesrpi volumio-remote-updater[652]: [2025-05-10 09:23:29] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1746865409 101 May 10 09:23:29 rhodesrpi volumio[1358]: 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: 6 May 10 09:23:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 10 09:23:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 10 09:23:36 rhodesrpi volumio[1358]: info: CoreCommandRouter::getUIConfigOnPlugin May 10 09:23:36 rhodesrpi volumio[1358]: info: FusionDsp - Choose a preset May 10 09:23:37 rhodesrpi volumio[1358]: info: FusionDsp - May 10 09:23:39 rhodesrpi volumio[1358]: info: CoreCommandRouter::volumioGetState May 10 09:23:42 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus May 10 09:23:42 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken May 10 09:23:45 rhodesrpi volumio[1358]: info: FusionDsp - Stopping FusionDsp service May 10 09:23:45 rhodesrpi volumio[1358]: info: camilladsp stopping service pid 1815... May 10 09:23:45 rhodesrpi volumio[1358]: info: camilladsp service terminated, instance 1 May 10 09:23:45 rhodesrpi volumio[1358]: info: Disabling plugin fusiondsp May 10 09:23:45 rhodesrpi volumio[1358]: info: Preparing to generate the ALSA configuration file May 10 09:23:45 rhodesrpi sudo[1999]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop fusiondsp.service May 10 09:23:45 rhodesrpi sudo[1999]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:45 rhodesrpi volumio[1358]: info: Asound.conf file written May 10 09:23:45 rhodesrpi systemd[1]: Stopping FusionDsp Daemon... May 10 09:23:45 rhodesrpi volumio[1274]: Backend configuration: May 10 09:23:45 rhodesrpi volumio[1274]: active_config: /data/configuration/audio_interface/fusiondsp/camilladsp.yml May 10 09:23:45 rhodesrpi volumio[1274]: active_config_txt: null May 10 09:23:45 rhodesrpi volumio[1274]: camilla_host: 127.0.0.1 May 10 09:23:45 rhodesrpi volumio[1274]: camilla_port: 9876 May 10 09:23:45 rhodesrpi volumio[1274]: coeff_dir: /data/INTERNAL/FusionDsp/filters May 10 09:23:45 rhodesrpi volumio[1274]: config_dir: /data/configuration/audio_interface/fusiondsp May 10 09:23:45 rhodesrpi volumio[1274]: default_config: /data/configuration/audio_interface/fusiondsp/camilladsp.yml May 10 09:23:45 rhodesrpi volumio[1274]: log_file: /tmp/camilladsp.log May 10 09:23:45 rhodesrpi volumio[1274]: on_get_active_config: null May 10 09:23:45 rhodesrpi volumio[1274]: on_set_active_config: null May 10 09:23:45 rhodesrpi volumio[1274]: port: 5011 May 10 09:23:45 rhodesrpi volumio[1274]: supported_capture_types: null May 10 09:23:45 rhodesrpi volumio[1274]: supported_playback_types: null May 10 09:23:45 rhodesrpi volumio[1274]: update_config_symlink: false May 10 09:23:45 rhodesrpi volumio[1274]: update_config_txt: false May 10 09:23:45 rhodesrpi volumio[1274]: ======== Running on http://0.0.0.0:5011 ======== May 10 09:23:45 rhodesrpi volumio[1274]: (Press CTRL+C to quit) May 10 09:23:45 rhodesrpi sudo[2002]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf May 10 09:23:45 rhodesrpi sudo[2002]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:45 rhodesrpi sudo[2002]: pam_unix(sudo:session): session closed for user root May 10 09:23:45 rhodesrpi volumio[1358]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy May 10 09:23:45 rhodesrpi volumio[1358]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy May 10 09:23:45 rhodesrpi volumio[1358]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy May 10 09:23:45 rhodesrpi volumio[1358]: info: Output device has changed, restarting MPD May 10 09:23:45 rhodesrpi systemd[1]: fusiondsp.service: Succeeded. May 10 09:23:45 rhodesrpi systemd[1]: Stopped FusionDsp Daemon. May 10 09:23:45 rhodesrpi sudo[1999]: pam_unix(sudo:session): session closed for user root May 10 09:23:45 rhodesrpi sudo[2007]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 10 09:23:45 rhodesrpi sudo[2007]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:45 rhodesrpi volumio[1358]: info: Output device has changed, restarting Shairport Sync May 10 09:23:45 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:45 rhodesrpi sudo[2007]: pam_unix(sudo:session): session closed for user root May 10 09:23:45 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:23:45 rhodesrpi sudo[2010]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 10 09:23:45 rhodesrpi sudo[2010]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:46 rhodesrpi systemd[1]: Stopping Music Player Daemon... May 10 09:23:46 rhodesrpi volumio[1358]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 10 09:23:46 rhodesrpi systemd[1]: mpd.service: Succeeded. May 10 09:23:46 rhodesrpi volumio[1358]: info: Done. May 10 09:23:46 rhodesrpi systemd[1]: Stopped Music Player Daemon. May 10 09:23:46 rhodesrpi volumio[1358]: info: MPD Permissions set May 10 09:23:46 rhodesrpi volumio[1358]: info: FusionDsp - Reporting Fusion DSP Disabled May 10 09:23:46 rhodesrpi volumio[1358]: info: Removing fusiondspeq DSP Signal Path Element May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:23:46 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:46 rhodesrpi systemd[1]: Starting Music Player Daemon... May 10 09:23:46 rhodesrpi volumio[1358]: info: Starting Shairport Sync May 10 09:23:46 rhodesrpi sudo[2021]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 10 09:23:46 rhodesrpi sudo[2021]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:46 rhodesrpi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 10 09:23:46 rhodesrpi systemd[1]: shairport-sync.service: Succeeded. May 10 09:23:46 rhodesrpi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 10 09:23:46 rhodesrpi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 10 09:23:46 rhodesrpi sudo[2021]: pam_unix(sudo:session): session closed for user root May 10 09:23:46 rhodesrpi volumio[1358]: info: Shairport-Sync Started May 10 09:23:46 rhodesrpi sudo[2015]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 10 09:23:46 rhodesrpi sudo[2015]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:46 rhodesrpi sudo[2015]: pam_unix(sudo:session): session closed for user root May 10 09:23:46 rhodesrpi mpd[2025]: May 10 09:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 10 09:23:46 rhodesrpi systemd[1]: Started Music Player Daemon. May 10 09:23:46 rhodesrpi sudo[2010]: pam_unix(sudo:session): session closed for user root May 10 09:23:46 rhodesrpi volumio[1358]: error: updateQueue error: null May 10 09:23:49 rhodesrpi volumio[1358]: info: Enabling plugin fusiondsp May 10 09:23:49 rhodesrpi volumio[1358]: info: Loading plugin "fusiondsp"... May 10 09:23:49 rhodesrpi volumio[1358]: info: Applying required configuration parameters for plugin fusiondsp May 10 09:23:49 rhodesrpi volumio[1358]: info: Preparing to generate the ALSA configuration file May 10 09:23:49 rhodesrpi volumio[1358]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 10 09:23:49 rhodesrpi volumio[1358]: info: Reading ALSA contributions from plugins. May 10 09:23:49 rhodesrpi volumio[1358]: info: Asound.conf file written May 10 09:23:49 rhodesrpi sudo[2045]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mv /home/volumio/.asoundrc /etc/asound.conf May 10 09:23:49 rhodesrpi sudo[2045]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:49 rhodesrpi sudo[2045]: pam_unix(sudo:session): session closed for user root May 10 09:23:49 rhodesrpi volumio[1358]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock PLL:0' : Device or resource busy May 10 09:23:49 rhodesrpi volumio[1358]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DSP:0' : Device or resource busy May 10 09:23:49 rhodesrpi volumio[1358]: /usr/sbin/alsactl: set_control:1461: Cannot write control '2:0:0:Max Overclock DAC:0' : Device or resource busy May 10 09:23:49 rhodesrpi volumio[1358]: info: Output device has changed, restarting MPD May 10 09:23:49 rhodesrpi sudo[2050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 10 09:23:49 rhodesrpi sudo[2050]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:49 rhodesrpi volumio[1358]: info: Output device has changed, restarting Shairport Sync May 10 09:23:49 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:49 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:23:49 rhodesrpi sudo[2050]: pam_unix(sudo:session): session closed for user root May 10 09:23:49 rhodesrpi sudo[2053]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 10 09:23:49 rhodesrpi sudo[2053]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:49 rhodesrpi systemd[1]: Stopping Music Player Daemon... May 10 09:23:49 rhodesrpi volumio[1358]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 10 09:23:49 rhodesrpi systemd[1]: mpd.service: Succeeded. May 10 09:23:49 rhodesrpi systemd[1]: Stopped Music Player Daemon. May 10 09:23:49 rhodesrpi volumio[1358]: info: PLUGIN START: fusiondsp May 10 09:23:49 rhodesrpi volumio[1358]: info: Loading i18n strings for locale en May 10 09:23:49 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile May 10 09:23:49 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:49 rhodesrpi volumio[1358]: info: FusionDsp - mixtype--------------------- Hardware May 10 09:23:49 rhodesrpi volumio[1358]: info: Preparing to generate the ALSA configuration file May 10 09:23:50 rhodesrpi volumio[1358]: info: Done. May 10 09:23:50 rhodesrpi volumio[1358]: info: The plugin fusiondsp has an ALSA contribution file volumioDsp.postDsp.10.conf May 10 09:23:50 rhodesrpi volumio[1358]: info: Reading ALSA contributions from plugins. May 10 09:23:50 rhodesrpi volumio[1358]: info: MPD Permissions set May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: Starting Shairport Sync May 10 09:23:50 rhodesrpi systemd[1]: Starting Music Player Daemon... May 10 09:23:50 rhodesrpi volumio[1358]: info: Asound.conf file unchanged, so no further update is needed May 10 09:23:50 rhodesrpi volumio[1358]: info: Output device has changed, restarting MPD May 10 09:23:50 rhodesrpi sudo[2064]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 10 09:23:50 rhodesrpi sudo[2064]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:50 rhodesrpi sudo[2067]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf May 10 09:23:50 rhodesrpi sudo[2067]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:50 rhodesrpi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 10 09:23:50 rhodesrpi volumio[1358]: info: Output device has changed, restarting Shairport Sync May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:23:50 rhodesrpi systemd[1]: shairport-sync.service: Succeeded. May 10 09:23:50 rhodesrpi sudo[2067]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 10 09:23:50 rhodesrpi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 10 09:23:50 rhodesrpi sudo[2064]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi sudo[2070]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service May 10 09:23:50 rhodesrpi sudo[2070]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:50 rhodesrpi sudo[2058]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 10 09:23:50 rhodesrpi sudo[2058]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:50 rhodesrpi sudo[2058]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM May 10 09:23:50 rhodesrpi systemd[1]: mpd.service: Succeeded. May 10 09:23:50 rhodesrpi systemd[1]: Stopped Music Player Daemon. May 10 09:23:50 rhodesrpi volumio[1358]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 May 10 09:23:50 rhodesrpi systemd[1]: Starting Music Player Daemon... May 10 09:23:50 rhodesrpi volumio[1358]: info: MPD Permissions set May 10 09:23:50 rhodesrpi volumio[1358]: info: Shairport-Sync Started May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam May 10 09:23:50 rhodesrpi volumio[1358]: info: Starting Shairport Sync May 10 09:23:50 rhodesrpi sudo[2086]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync May 10 09:23:50 rhodesrpi sudo[2086]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:50 rhodesrpi sudo[2079]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log May 10 09:23:50 rhodesrpi sudo[2079]: pam_unix(sudo:session): session opened for user root by (uid=0) May 10 09:23:50 rhodesrpi sudo[2079]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... May 10 09:23:50 rhodesrpi systemd[1]: shairport-sync.service: Succeeded. May 10 09:23:50 rhodesrpi systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. May 10 09:23:50 rhodesrpi systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. May 10 09:23:50 rhodesrpi sudo[2086]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi volumio[1358]: info: Shairport-Sync Started May 10 09:23:50 rhodesrpi mpd[2089]: May 10 09:23 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg May 10 09:23:50 rhodesrpi systemd[1]: Started Music Player Daemon. May 10 09:23:50 rhodesrpi sudo[2070]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi sudo[2053]: pam_unix(sudo:session): session closed for user root May 10 09:23:50 rhodesrpi volumio[1358]: error: MPD error: The expression evaluated to a falsy value: May 10 09:23:50 rhodesrpi volumio[1358]: assert.ok(self.idling) May 10 09:23:50 rhodesrpi volumio[1358]: error: The expression evaluated to a falsy value: May 10 09:23:50 rhodesrpi volumio[1358]: assert.ok(self.idling) May 10 09:23:50 rhodesrpi volumio[1358]: error: updateQueue error: null May 10 09:23:51 rhodesrpi volumio[1358]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 10 09:23:51 rhodesrpi volumio[1358]: TypeError: Cannot read property 'off' of undefined May 10 09:23:51 rhodesrpi volumio[1358]: at FusionDsp.onStop (/data/plugins/audio_interface/fusiondsp/index.js:107:15) May 10 09:23:51 rhodesrpi volumio[1358]: at PluginManager.stopPlugin (/volumio/app/pluginmanager.js:460:30) May 10 09:23:51 rhodesrpi volumio[1358]: at PluginManager.disableAndStopPlugin (/volumio/app/pluginmanager.js:1883:8) May 10 09:23:51 rhodesrpi volumio[1358]: at CoreCommandRouter.disableAndStopPlugin (/volumio/app/index.js:1556:29) May 10 09:23:51 rhodesrpi volumio[1358]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:1401:47) May 10 09:23:51 rhodesrpi volumio[1358]: at Socket.emit (events.js:315:20) May 10 09:23:51 rhodesrpi volumio[1358]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 May 10 09:23:51 rhodesrpi volumio[1358]: at processTicksAndRejections (internal/process/task_queues.js:75:11) May 10 09:23:51 rhodesrpi volumio[1358]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| May 10 09:23:51 rhodesrpi sudo[2104]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-05-10 09:22 May 10 09:23:51 rhodesrpi sudo[2104]: 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="147953990fca4aa103a8f90538ef56fb0454638c" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="9ab87de061b3649c303da550e73c92d340b0f989" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 30 Apr 2025 11:47:57 AM CEST" VOLUMIO_VERSION="3.807" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fddd10196af80fdc784c726185a6abe4"