-- Logs begin at Fri 2024-11-29 15:16:59 +08, end at Fri 2024-11-29 15:26:57 +08. -- Nov 29 15:25:06 altec ntpd[1136]: Soliciting pool server 240b:400e:3b:7401:e706:8294:461f:7f12 Nov 29 15:25:22 altec volumio[984]: verbose: New Socket.io Connection to 192.168.31.80 from 192.168.31.186 UA: Mozilla/5.0 (Linux; Android 14; SM-S711B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/130.0.6723.107 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Nov 29 15:25:22 altec volumio[984]: verbose: New Socket.io Connection to 192.168.31.80 from 192.168.31.186 UA: Mozilla/5.0 (Linux; Android 14; SM-S711B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/130.0.6723.107 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 8 Nov 29 15:25:22 altec volumio[984]: verbose: New Socket.io Connection to 192.168.31.80 from 192.168.31.186 UA: Mozilla/5.0 (Linux; Android 14; SM-S711B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/130.0.6723.107 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 9 Nov 29 15:25:30 altec go-librespot[1594]: time="2024-11-29T15:25:30+08:00" level=debug msg="obtained new client token: AABSyZObtgGcDQa0lubskGkMmBrYewFggnGmHuT1NRjkeETkHHscjPh9+tNF9nx6okyFQ6doi+/2xCCol+mXZSfrqWJcnY1tB6MJ61BgWigatJ//P7mryBWsRKA+HW1ziogv8RvQ2ybX4NXy32M+33KrvhQlWY4B6uSMXQw0dsSvcoNlAYGKONFdhVOAoBhbbtSEejAu3LdGsbFWRyTMZaowHZgwH0Fgfy4pJHrW/+kPmTM/wgfy0fXPH+6o" Nov 29 15:25:30 altec go-librespot[1594]: time="2024-11-29T15:25:30+08:00" level=info msg="connected to ap-gae2.spotify.com:4070" Nov 29 15:25:30 altec go-librespot[1594]: time="2024-11-29T15:25:30+08:00" level=debug msg="completed keyexchange" Nov 29 15:25:30 altec go-librespot[1594]: time="2024-11-29T15:25:30+08:00" level=debug msg="completed challenge" Nov 29 15:25:30 altec go-librespot[1594]: time="2024-11-29T15:25:30+08:00" level=debug msg="authenticated as yapcheekhoon" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="authenticated as yapcheekhoon" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="dealer connection opened" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=info msg="accepted zeroconf user yapcheekhoon from SM-S711B" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="autoplay enabled: true" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="received connection id: Yzc1NTdjYzktZmFjMy00NTA4LWE5YzYtY2IzNmY4YTlhMjE1K2RlYWxlcit0Y3A6Ly8wYWM5NDhmMC5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQUM5Qjk4OEFGMTdENjFDQUI2MDIyMDNFRUNCQTc3Q0UzQkE3QzY5MDA4RjE4QzFCMkIwNkQ4NkVBQURFNzlDMQ==" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="put connect state because NEW_DEVICE" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="handling transfer player command from ddd6df7511211492900dbee29887f4007e61222c" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="resolved context of track" uri="spotify:album:74XLaVRIeHY51nuXcC5RuS" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=trace msg="fetched new page 0 with 11 items (list: 11)" uri="spotify:album:74XLaVRIeHY51nuXcC5RuS" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="loading track (paused: false, position: 601074ms)" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=trace msg="emitting websocket event: will_play" Nov 29 15:25:31 altec volumio[984]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:55lM3nYE02vTLl3B4PkLlc","play_origin":"playlist"}} Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1120" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="selected format OGG_VORBIS_320 (f25d06b4e923441802429cda39bb2c4ac4289f16)" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:31 altec go-librespot[1594]: time="2024-11-29T15:25:31+08:00" level=debug msg="requested aes key for file f25d06b4e923441802429cda39bb2c4ac4289f16, gid: 55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="fetched first chunk of 24, total size is 12075964 bytes" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="fetched chunk 23/23, size: 17340" uri="spotify:track:55lM3nYE02vTLl3B4PkLlc" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed creating stream for spotify:track:55lM3nYE02vTLl3B4PkLlc: failed seeking stream: failed reading page: EOF" Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Nov 29 15:25:32 altec go-librespot[1594]: time="2024-11-29T15:25:32+08:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="handling skip_next player command from ddd6df7511211492900dbee29887f4007e61222c" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=trace msg="emitting websocket event: will_play" Nov 29 15:25:43 altec volumio[984]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:38LUbz74v3nmP8x0efElw2","play_origin":"playlist"}} Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="selected format OGG_VORBIS_320 (dfed49590661d57a7bb42f659320cfc3df1c790c)" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="requested aes key for file dfed49590661d57a7bb42f659320cfc3df1c790c, gid: 38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="fetched first chunk of 24, total size is 12424600 bytes" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5011 us, period size = 221 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 99 frames" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="created new output device" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=info msg="loaded track \"Last Summer Whisper\" (paused: false, position: 0ms, duration: 299680ms, prefetched: false)" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=trace msg="scheduling prefetch in 269s" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=trace msg="emitting websocket event: metadata" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="sending successful reply for dealer request" Nov 29 15:25:43 altec volumio[984]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:38LUbz74v3nmP8x0efElw2","name":"Last Summer Whisper","artist_names":["Anri"],"album_name":"Heaven Beach","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02e5cdab693bda0ed0bcffe334","position":0,"duration":299680,"release_date":"year:1982 month:11 day:21","track_number":2,"disc_number":1}} Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Nov 29 15:25:43 altec go-librespot[1594]: time="2024-11-29T15:25:43+08:00" level=trace msg="emitting websocket event: playing" Nov 29 15:25:43 altec volumio[984]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:38LUbz74v3nmP8x0efElw2","play_origin":"playlist"}} Nov 29 15:25:43 altec volumio[984]: info: Spotify is playing in volatile mode Nov 29 15:25:43 altec volumio[984]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 29 15:25:43 altec volumio[984]: SPOTIFY: UNSET VOLATILE Nov 29 15:25:43 altec volumio[984]: SPOTIFY: {"status":"stop","position":0,"title":"","artist":"","album":"","albumart":"/albumart","duration":0,"uri":"","seek":0,"samplerate":"","channels":"","bitdepth":"","Streaming":false,"service":"mpd","volume":0,"dbVolume":null,"mute":false,"disableVolumeControl":false,"random":null,"repeat":null,"repeatSingle":false,"updatedb":false,"consume":false} Nov 29 15:25:43 altec volumio[984]: SPOTIFY: PUSH STATE SPOTIFY Nov 29 15:25:43 altec volumio[984]: SPOTIFY: {"status":"play","service":"spop","title":"Last Summer Whisper","artist":"Anri","album":"Heaven Beach","albumart":"https://i.scdn.co/image/ab67616d00001e02e5cdab693bda0ed0bcffe334","uri":"spotify:track:38LUbz74v3nmP8x0efElw2","trackType":"spotify","seek":0,"duration":299,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Nov 29 15:25:43 altec volumio[984]: info: CoreCommandRouter::servicePushState Nov 29 15:25:43 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:25:43 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:25:43 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:25:44 altec volumio[984]: SPOTIFY: PUSH STATE SPOTIFY Nov 29 15:25:44 altec volumio[984]: SPOTIFY: {"status":"play","service":"spop","title":"Last Summer Whisper","artist":"Anri","album":"Heaven Beach","albumart":"https://i.scdn.co/image/ab67616d00001e02e5cdab693bda0ed0bcffe334","uri":"spotify:track:38LUbz74v3nmP8x0efElw2","trackType":"spotify","seek":0,"duration":299,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Nov 29 15:25:44 altec volumio[984]: info: CoreCommandRouter::servicePushState Nov 29 15:25:44 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:25:44 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:25:56 altec go-librespot[1594]: time="2024-11-29T15:25:56+08:00" level=debug msg="fetched chunk 4/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:26:03 altec go-librespot[1594]: time="2024-11-29T15:26:03+08:00" level=debug msg="update volume to 64880/65535" Nov 29 15:26:03 altec go-librespot[1594]: time="2024-11-29T15:26:03+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:03 altec go-librespot[1594]: time="2024-11-29T15:26:03+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:03 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Nov 29 15:26:03 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Nov 29 15:26:03 altec volumio[984]: info: Setting Volumio Volume from Spotify: 100 Nov 29 15:26:03 altec volumio[984]: info: VolumeController::SetAlsaVolume100 Nov 29 15:26:03 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:03 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:03 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:04 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 29 15:26:04 altec go-librespot[1594]: time="2024-11-29T15:26:04+08:00" level=debug msg="update volume to 64224/65535" Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:05 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":98,"max":100}} Nov 29 15:26:05 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 98 Nov 29 15:26:05 altec volumio[984]: info: Setting Volumio Volume from Spotify: 98 Nov 29 15:26:05 altec volumio[984]: info: VolumeController::SetAlsaVolume98 Nov 29 15:26:05 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:05 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:05 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:05 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 98 Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=debug msg="update volume to 63569/65535" Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:05 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":98,"max":100}} Nov 29 15:26:05 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 98 Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=debug msg="update volume to 62914/65535" Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:05 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":97,"max":100}} Nov 29 15:26:05 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 97 Nov 29 15:26:05 altec volumio[984]: info: Setting Volumio Volume from Spotify: 97 Nov 29 15:26:05 altec volumio[984]: info: VolumeController::SetAlsaVolume97 Nov 29 15:26:05 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:05 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:05 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:05 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Nov 29 15:26:05 altec go-librespot[1594]: time="2024-11-29T15:26:05+08:00" level=debug msg="update volume to 60948/65535" Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:06 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":94,"max":100}} Nov 29 15:26:06 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 94 Nov 29 15:26:06 altec volumio[984]: info: Setting Volumio Volume from Spotify: 94 Nov 29 15:26:06 altec volumio[984]: info: VolumeController::SetAlsaVolume94 Nov 29 15:26:06 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:06 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:06 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:06 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 94 Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=debug msg="update volume to 55705/65535" Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:06 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":86,"max":100}} Nov 29 15:26:06 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 86 Nov 29 15:26:06 altec volumio[984]: info: Setting Volumio Volume from Spotify: 86 Nov 29 15:26:06 altec volumio[984]: info: VolumeController::SetAlsaVolume86 Nov 29 15:26:06 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:06 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:06 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:06 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 86 Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=debug msg="update volume to 50462/65535" Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:06 altec go-librespot[1594]: time="2024-11-29T15:26:06+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:06 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":78,"max":100}} Nov 29 15:26:06 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 78 Nov 29 15:26:06 altec volumio[984]: info: Setting Volumio Volume from Spotify: 78 Nov 29 15:26:06 altec volumio[984]: info: VolumeController::SetAlsaVolume78 Nov 29 15:26:06 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:06 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:06 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:06 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 78 Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="update volume to 45219/65535" Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:07 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":69,"max":100}} Nov 29 15:26:07 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 69 Nov 29 15:26:07 altec volumio[984]: info: Setting Volumio Volume from Spotify: 69 Nov 29 15:26:07 altec volumio[984]: info: VolumeController::SetAlsaVolume69 Nov 29 15:26:07 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:07 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:07 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:07 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="update volume to 43253/65535" Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:07 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":66,"max":100}} Nov 29 15:26:07 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 66 Nov 29 15:26:07 altec volumio[984]: info: Setting Volumio Volume from Spotify: 66 Nov 29 15:26:07 altec volumio[984]: info: VolumeController::SetAlsaVolume66 Nov 29 15:26:07 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:07 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:07 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:07 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 66 Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="update volume to 37355/65535" Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:07 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":58,"max":100}} Nov 29 15:26:07 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 58 Nov 29 15:26:07 altec volumio[984]: info: Setting Volumio Volume from Spotify: 58 Nov 29 15:26:07 altec volumio[984]: info: VolumeController::SetAlsaVolume58 Nov 29 15:26:07 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:07 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:07 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:07 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 58 Nov 29 15:26:07 altec go-librespot[1594]: time="2024-11-29T15:26:07+08:00" level=debug msg="update volume to 34734/65535" Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:08 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":54,"max":100}} Nov 29 15:26:08 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 54 Nov 29 15:26:08 altec volumio[984]: info: Setting Volumio Volume from Spotify: 54 Nov 29 15:26:08 altec volumio[984]: info: VolumeController::SetAlsaVolume54 Nov 29 15:26:08 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:08 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:08 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:08 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 54 Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=debug msg="update volume to 29491/65535" Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:08 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":46,"max":100}} Nov 29 15:26:08 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 46 Nov 29 15:26:08 altec volumio[984]: info: Setting Volumio Volume from Spotify: 46 Nov 29 15:26:08 altec volumio[984]: info: VolumeController::SetAlsaVolume46 Nov 29 15:26:08 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:08 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:08 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:08 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 46 Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=debug msg="update volume to 26869/65535" Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:08 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":41,"max":100}} Nov 29 15:26:08 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 41 Nov 29 15:26:08 altec volumio[984]: info: Setting Volumio Volume from Spotify: 41 Nov 29 15:26:08 altec volumio[984]: info: VolumeController::SetAlsaVolume41 Nov 29 15:26:08 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:08 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:08 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:08 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 41 Nov 29 15:26:08 altec go-librespot[1594]: time="2024-11-29T15:26:08+08:00" level=debug msg="fetched chunk 5/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=debug msg="update volume to 22282/65535" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:09 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":35,"max":100}} Nov 29 15:26:09 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 35 Nov 29 15:26:09 altec volumio[984]: info: Setting Volumio Volume from Spotify: 35 Nov 29 15:26:09 altec volumio[984]: info: VolumeController::SetAlsaVolume35 Nov 29 15:26:09 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:09 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:09 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:09 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 35 Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=debug msg="update volume to 17039/65535" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:09 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Nov 29 15:26:09 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Nov 29 15:26:09 altec volumio[984]: info: Setting Volumio Volume from Spotify: 26 Nov 29 15:26:09 altec volumio[984]: info: VolumeController::SetAlsaVolume26 Nov 29 15:26:09 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:09 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:09 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:09 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 26 Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=debug msg="update volume to 16384/65535" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:09 altec go-librespot[1594]: time="2024-11-29T15:26:09+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:09 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Nov 29 15:26:09 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Nov 29 15:26:12 altec go-librespot[1594]: time="2024-11-29T15:26:12+08:00" level=debug msg="update volume to 17039/65535" Nov 29 15:26:12 altec go-librespot[1594]: time="2024-11-29T15:26:12+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:12 altec go-librespot[1594]: time="2024-11-29T15:26:12+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:12 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":26,"max":100}} Nov 29 15:26:12 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 26 Nov 29 15:26:13 altec go-librespot[1594]: time="2024-11-29T15:26:13+08:00" level=debug msg="update volume to 17694/65535" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:14 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":27,"max":100}} Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 27 Nov 29 15:26:14 altec volumio[984]: info: Setting Volumio Volume from Spotify: 27 Nov 29 15:26:14 altec volumio[984]: info: VolumeController::SetAlsaVolume27 Nov 29 15:26:14 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:14 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:14 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 27 Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="update volume to 18350/65535" Nov 29 15:26:14 altec ntpd[1136]: Soliciting pool server 2001:e68:58bc:b200::123 Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:14 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Nov 29 15:26:14 altec volumio[984]: info: Setting Volumio Volume from Spotify: 29 Nov 29 15:26:14 altec volumio[984]: info: VolumeController::SetAlsaVolume29 Nov 29 15:26:14 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:14 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:14 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 29 Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="update volume to 19005/65535" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:14 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":29,"max":100}} Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 29 Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="update volume to 20971/65535" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:14 altec go-librespot[1594]: time="2024-11-29T15:26:14+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:14 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":32,"max":100}} Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 32 Nov 29 15:26:14 altec volumio[984]: info: Setting Volumio Volume from Spotify: 32 Nov 29 15:26:14 altec volumio[984]: info: VolumeController::SetAlsaVolume32 Nov 29 15:26:14 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:14 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:14 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:14 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 32 Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="update volume to 23593/65535" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:15 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":37,"max":100}} Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 37 Nov 29 15:26:15 altec volumio[984]: info: Setting Volumio Volume from Spotify: 37 Nov 29 15:26:15 altec volumio[984]: info: VolumeController::SetAlsaVolume37 Nov 29 15:26:15 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 37 Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="update volume to 28835/65535" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:15 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":44,"max":100}} Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 44 Nov 29 15:26:15 altec volumio[984]: info: Setting Volumio Volume from Spotify: 44 Nov 29 15:26:15 altec volumio[984]: info: VolumeController::SetAlsaVolume44 Nov 29 15:26:15 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 44 Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="update volume to 31457/65535" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:15 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":49,"max":100}} Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 49 Nov 29 15:26:15 altec volumio[984]: info: Setting Volumio Volume from Spotify: 49 Nov 29 15:26:15 altec volumio[984]: info: VolumeController::SetAlsaVolume49 Nov 29 15:26:15 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 49 Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="update volume to 34078/65535" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:15 altec go-librespot[1594]: time="2024-11-29T15:26:15+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:15 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":52,"max":100}} Nov 29 15:26:15 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 52 Nov 29 15:26:15 altec volumio[984]: info: Setting Volumio Volume from Spotify: 52 Nov 29 15:26:15 altec volumio[984]: info: VolumeController::SetAlsaVolume52 Nov 29 15:26:15 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:15 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:16 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=debug msg="update volume to 39321/65535" Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:16 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":60,"max":100}} Nov 29 15:26:16 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 60 Nov 29 15:26:16 altec volumio[984]: info: Setting Volumio Volume from Spotify: 60 Nov 29 15:26:16 altec volumio[984]: info: VolumeController::SetAlsaVolume60 Nov 29 15:26:16 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:16 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:16 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:16 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 60 Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=debug msg="update volume to 44564/65535" Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:16 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":69,"max":100}} Nov 29 15:26:16 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 69 Nov 29 15:26:16 altec volumio[984]: info: Setting Volumio Volume from Spotify: 69 Nov 29 15:26:16 altec volumio[984]: info: VolumeController::SetAlsaVolume69 Nov 29 15:26:16 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:16 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:16 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:16 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 69 Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=debug msg="update volume to 46530/65535" Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:16 altec go-librespot[1594]: time="2024-11-29T15:26:16+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:16 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":72,"max":100}} Nov 29 15:26:16 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 72 Nov 29 15:26:16 altec volumio[984]: info: Setting Volumio Volume from Spotify: 72 Nov 29 15:26:16 altec volumio[984]: info: VolumeController::SetAlsaVolume72 Nov 29 15:26:17 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:17 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 72 Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=debug msg="update volume to 49807/65535" Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:17 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":77,"max":100}} Nov 29 15:26:17 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 77 Nov 29 15:26:17 altec volumio[984]: info: Setting Volumio Volume from Spotify: 77 Nov 29 15:26:17 altec volumio[984]: info: VolumeController::SetAlsaVolume77 Nov 29 15:26:17 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:17 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 77 Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=debug msg="update volume to 57671/65535" Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:17 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":89,"max":100}} Nov 29 15:26:17 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 89 Nov 29 15:26:17 altec volumio[984]: info: Setting Volumio Volume from Spotify: 89 Nov 29 15:26:17 altec volumio[984]: info: VolumeController::SetAlsaVolume89 Nov 29 15:26:17 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:17 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 89 Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=debug msg="update volume to 59637/65535" Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:17 altec go-librespot[1594]: time="2024-11-29T15:26:17+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:17 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":92,"max":100}} Nov 29 15:26:17 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 92 Nov 29 15:26:17 altec volumio[984]: info: Setting Volumio Volume from Spotify: 92 Nov 29 15:26:17 altec volumio[984]: info: VolumeController::SetAlsaVolume92 Nov 29 15:26:17 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:17 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:18 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 92 Nov 29 15:26:18 altec go-librespot[1594]: time="2024-11-29T15:26:18+08:00" level=debug msg="update volume to 62914/65535" Nov 29 15:26:18 altec go-librespot[1594]: time="2024-11-29T15:26:18+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:18 altec go-librespot[1594]: time="2024-11-29T15:26:18+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:18 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":97,"max":100}} Nov 29 15:26:18 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 97 Nov 29 15:26:18 altec volumio[984]: info: Setting Volumio Volume from Spotify: 97 Nov 29 15:26:18 altec volumio[984]: info: VolumeController::SetAlsaVolume97 Nov 29 15:26:18 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:18 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:18 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:18 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 97 Nov 29 15:26:18 altec go-librespot[1594]: time="2024-11-29T15:26:18+08:00" level=debug msg="update volume to 65535/65535" Nov 29 15:26:18 altec go-librespot[1594]: time="2024-11-29T15:26:18+08:00" level=debug msg="put connect state because VOLUME_CHANGED" Nov 29 15:26:18 altec go-librespot[1594]: time="2024-11-29T15:26:18+08:00" level=trace msg="emitting websocket event: volume" Nov 29 15:26:18 altec volumio[984]: SPOTIFY: received: {"type":"volume","data":{"value":100,"max":100}} Nov 29 15:26:18 altec volumio[984]: SPOTIFY: RECEIVED SPOTIFY VOLUME 100 Nov 29 15:26:18 altec volumio[984]: info: Setting Volumio Volume from Spotify: 100 Nov 29 15:26:18 altec volumio[984]: info: VolumeController::SetAlsaVolume100 Nov 29 15:26:18 altec volumio[984]: info: CoreStateMachine::pushState Nov 29 15:26:18 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 29 15:26:18 altec volumio[984]: info: CoreCommandRouter::volumioPushState Nov 29 15:26:18 altec volumio[984]: SPOTIFY: RECEIVED VOLUMIO VOLUME 100 Nov 29 15:26:21 altec go-librespot[1594]: time="2024-11-29T15:26:21+08:00" level=debug msg="fetched chunk 6/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:26:30 altec volumio[984]: verbose: New Socket.io Connection to 192.168.31.80 from 192.168.31.186 UA: Mozilla/5.0 (Linux; Android 14; SM-S711B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/130.0.6723.107 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7 Nov 29 15:26:30 altec volumio[984]: info: Received Get System Info Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 29 15:26:30 altec volumio[984]: info: Discovery: Getting this device information Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetState Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetState Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetVisibleSources Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetState Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Nov 29 15:26:30 altec volumio[984]: info: Received Get System Info Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Nov 29 15:26:30 altec volumio[984]: info: Discovery: Getting this device information Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetState Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetState Nov 29 15:26:30 altec volumio[984]: info: Listing playlists Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::volumioGetQueue Nov 29 15:26:30 altec volumio[984]: info: CoreStateMachine::getQueue Nov 29 15:26:30 altec volumio[984]: info: CorePlayQueue::getQueue Nov 29 15:26:30 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Nov 29 15:26:33 altec volumio[984]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 15:26:33 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 29 15:26:33 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 29 15:26:33 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Nov 29 15:26:33 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: appearance , getAvailableUIs Nov 29 15:26:33 altec volumio[984]: info: Received Get System Version Nov 29 15:26:33 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Nov 29 15:26:34 altec go-librespot[1594]: time="2024-11-29T15:26:34+08:00" level=debug msg="fetched chunk 7/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:26:47 altec go-librespot[1594]: time="2024-11-29T15:26:47+08:00" level=debug msg="fetched chunk 8/23, size: 524288" uri="spotify:track:38LUbz74v3nmP8x0efElw2" Nov 29 15:26:52 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Nov 29 15:26:52 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Nov 29 15:26:54 altec volumio[984]: info: Enabling plugin fusiondsp Nov 29 15:26:54 altec volumio[984]: info: Loading plugin "fusiondsp"... Nov 29 15:26:55 altec volumio[984]: info: Preparing to generate the ALSA configuration file Nov 29 15:26:55 altec volumio[984]: info: Asound.conf file unchanged, so no further update is needed Nov 29 15:26:55 altec volumio[984]: info: Output device has changed, restarting MPD Nov 29 15:26:55 altec volumio[984]: info: Output device has changed, restarting Shairport Sync Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 15:26:55 altec sudo[2395]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 29 15:26:55 altec sudo[2395]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec sudo[2395]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:55 altec sudo[2397]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 29 15:26:55 altec sudo[2397]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec systemd[1]: Stopping Music Player Daemon... Nov 29 15:26:55 altec volumio[984]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 29 15:26:55 altec volumio[984]: info: PLUGIN START: fusiondsp Nov 29 15:26:55 altec volumio[984]: info: Loading i18n strings for locale en Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: FusionDsp - mixtype--------------------- Hardware Nov 29 15:26:55 altec volumio[984]: info: Preparing to generate the ALSA configuration file Nov 29 15:26:55 altec systemd[1]: mpd.service: Succeeded. Nov 29 15:26:55 altec systemd[1]: Stopped Music Player Daemon. Nov 29 15:26:55 altec volumio[984]: info: Done. Nov 29 15:26:55 altec volumio[984]: info: MPD Permissions set Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec systemd[1]: Starting Music Player Daemon... Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: Asound.conf file unchanged, so no further update is needed Nov 29 15:26:55 altec volumio[984]: info: Output device has changed, restarting MPD Nov 29 15:26:55 altec sudo[2412]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Nov 29 15:26:55 altec sudo[2412]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec volumio[984]: info: Output device has changed, restarting Shairport Sync Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec sudo[2412]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 15:26:55 altec sudo[2404]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 29 15:26:55 altec sudo[2404]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec sudo[2404]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:55 altec sudo[2415]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Nov 29 15:26:55 altec sudo[2415]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec volumio[984]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Nov 29 15:26:55 altec systemd[1]: mpd.service: Main process exited, code=killed, status=15/TERM Nov 29 15:26:55 altec systemd[1]: mpd.service: Succeeded. Nov 29 15:26:55 altec systemd[1]: Stopped Music Player Daemon. Nov 29 15:26:55 altec systemd[1]: Starting Music Player Daemon... Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 15:26:55 altec volumio[984]: info: MPD Permissions set Nov 29 15:26:55 altec volumio[984]: info: Starting Shairport Sync Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec sudo[2425]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 29 15:26:55 altec sudo[2425]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Nov 29 15:26:55 altec systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 29 15:26:55 altec systemd[1]: shairport-sync.service: Succeeded. Nov 29 15:26:55 altec systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 29 15:26:55 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:55 altec sudo[2422]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log Nov 29 15:26:55 altec sudo[2422]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:55 altec systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 29 15:26:55 altec sudo[2422]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:55 altec sudo[2425]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:56 altec mpd[2437]: Nov 29 15:26 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Nov 29 15:26:56 altec systemd[1]: Started Music Player Daemon. Nov 29 15:26:56 altec sudo[2415]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:56 altec sudo[2397]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:56 altec volumio[984]: info: Starting Shairport Sync Nov 29 15:26:56 altec volumio[984]: info: CoreCommandRouter::getUIConfigOnPlugin Nov 29 15:26:56 altec sudo[2443]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Nov 29 15:26:56 altec sudo[2443]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:56 altec volumio[984]: info: Shairport-Sync Started Nov 29 15:26:56 altec systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Nov 29 15:26:56 altec systemd[1]: shairport-sync.service: Succeeded. Nov 29 15:26:56 altec systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Nov 29 15:26:56 altec systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Nov 29 15:26:56 altec sudo[2443]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:56 altec volumio[984]: error: MPD error: The expression evaluated to a falsy value: Nov 29 15:26:56 altec volumio[984]: assert.ok(self.idling) Nov 29 15:26:56 altec volumio[984]: error: The expression evaluated to a falsy value: Nov 29 15:26:56 altec volumio[984]: assert.ok(self.idling) Nov 29 15:26:56 altec volumio[984]: error: updateQueue error: null Nov 29 15:26:56 altec volumio[984]: info: Shairport-Sync Started Nov 29 15:26:57 altec volumio[984]: info: camilladsp spawned new process with pid undefined, instance 1, run: true Nov 29 15:26:57 altec volumio[984]: info: camilladsp service started and running in background, instance 1 Nov 29 15:26:57 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Nov 29 15:26:57 altec volumio[984]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Nov 29 15:26:57 altec volumio[984]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json Nov 29 15:26:57 altec volumio[984]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found Nov 29 15:26:57 altec volumio[984]: info: FusionDsp loaded Nov 29 15:26:57 altec volumio[984]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Nov 29 15:26:57 altec sudo[2458]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service Nov 29 15:26:57 altec sudo[2458]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 29 15:26:57 altec volumio[984]: info: FusionDsp - Reporting Fusion DSP Enabled Nov 29 15:26:57 altec volumio[984]: info: Adding Signal Path Element [object Object] Nov 29 15:26:57 altec volumio[984]: info: Adding fusiondspeq DSP Signal Path Element Nov 29 15:26:57 altec volumio[984]: info: FusionDsp - ---- installed callbackRead Nov 29 15:26:57 altec volumio[984]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 29 15:26:57 altec sudo[2458]: pam_unix(sudo:session): session closed for user root Nov 29 15:26:57 altec volumio[984]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT Nov 29 15:26:57 altec volumio[984]: at Process.ChildProcess._handle.onexit (internal/child_process.js:277:19) Nov 29 15:26:57 altec volumio[984]: at onErrorNT (internal/child_process.js:472:16) Nov 29 15:26:57 altec volumio[984]: at processTicksAndRejections (internal/process/task_queues.js:82:21) { Nov 29 15:26:57 altec volumio[984]: errno: -2, Nov 29 15:26:57 altec volumio[984]: code: 'ENOENT', Nov 29 15:26:57 altec volumio[984]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp', Nov 29 15:26:57 altec volumio[984]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp', Nov 29 15:26:57 altec volumio[984]: spawnargs: [ Nov 29 15:26:57 altec volumio[984]: '-p', Nov 29 15:26:57 altec volumio[984]: 9876, Nov 29 15:26:57 altec volumio[984]: '-o', Nov 29 15:26:57 altec volumio[984]: '/tmp/camilladsp.log', Nov 29 15:26:57 altec volumio[984]: '-l', Nov 29 15:26:57 altec volumio[984]: 'warn', Nov 29 15:26:57 altec volumio[984]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml' Nov 29 15:26:57 altec volumio[984]: ] Nov 29 15:26:57 altec volumio[984]: } Nov 29 15:26:57 altec volumio[984]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 29 15:26:57 altec sudo[2469]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-29 15:25 Nov 29 15:26:57 altec sudo[2469]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="bba9e3185e150dd0995f9a49355b34fc6218d5a2" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8aa57e3ae5b742ea1069404608336a9884ccfb4e" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Tue 17 Sep 2024 05:33:09 PM CEST" VOLUMIO_VERSION="3.757" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="ee834e1c2a28de3c5d8c48611ecf1167"