-- Logs begin at Fri 2024-10-04 17:28:28 CEST, end at Sat 2024-10-05 00:52:11 CEST. -- Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1141" Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="fetched first chunk of 28, total size is 14259504 bytes" uri="spotify:track:6uQBb8fNu4u71e3jfANaaQ" Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:6uQBb8fNu4u71e3jfANaaQ" Oct 05 00:51:00 volumio go-librespot[24391]: ALSA lib /home/volumio-alsa-plugin/src/pcm_volumioswitch.c:143:(_snd_pcm_volumioswitch_open_target_pcm) PCM Volumio ALSA Switch Plugin failed to open the switcher target pcm volumioLocalPlayback Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (transfer): failed setting stream for spotify:track:6uQBb8fNu4u71e3jfANaaQ: ALSA error at snd_pcm_open: Device or resource busy" Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="fetched chunk 1/27, size: 524288" uri="spotify:track:6uQBb8fNu4u71e3jfANaaQ" Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="fetched chunk 2/27, size: 524288" uri="spotify:track:6uQBb8fNu4u71e3jfANaaQ" Oct 05 00:51:00 volumio go-librespot[24391]: time="2024-10-05T00:51:00+02:00" level=debug msg="fetched chunk 3/27, size: 524288" uri="spotify:track:6uQBb8fNu4u71e3jfANaaQ" Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Oct 05 00:51:01 volumio volumio[902]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Oct 05 00:51:01 volumio volumio[902]: info: Received Get System Version Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 05 00:51:01 volumio volumio[902]: info: Received Get System Info Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 00:51:01 volumio volumio[902]: info: Discovery: Getting this device information Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:51:01 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 00:51:02 volumio volumio[902]: info: Discovery: Getting this device information Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=debug msg="handling resume player command from 51c819875d0010c112d05cc2fec9e46981b3aa40" Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=debug msg="resume track at 0ms" Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=trace msg="scheduling prefetch in 342s" Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=debug msg="sending successful reply for dealer request" Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 00:51:02 volumio go-librespot[24391]: time="2024-10-05T00:51:02+02:00" level=trace msg="emitting websocket event: playing" Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6uQBb8fNu4u71e3jfANaaQ","play_origin":"collection-songs"}} Oct 05 00:51:02 volumio volumio[902]: info: Spotify is playing in volatile mode Oct 05 00:51:02 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: UNSET VOLATILE Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"pause","title":"Bright And Early","artist":"Snorre Kirk, Stephen Riley","album":"Going Up","albumart":"https://resources.tidal.com/images/4fe86f0f/d4cd/4e38/b678/a100c4e2460f/1280x1280.jpg","uri":"","trackType":"tidal","codec":"flac","seek":47240,"duration":182,"samplerate":"96 KHz","bitdepth":"24 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":79,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"tidalconnect"} Oct 05 00:51:02 volumio volumio[902]: info: Setting Spotify stop after unset volatile call Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::servicePushState Oct 05 00:51:02 volumio volumio[902]: info: CoreStateMachine::pushState Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output update for this device Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:6uQBb8fNu4u71e3jfANaaQ","play_origin":"collection-songs"}} Oct 05 00:51:02 volumio volumio[902]: info: Spotify is playing in volatile mode Oct 05 00:51:02 volumio volumio[902]: info: CoreStateMachine::setConsumeUpdateService undefined Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: UNSET VOLATILE Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"pause","title":"Bright And Early","artist":"Snorre Kirk, Stephen Riley","album":"Going Up","albumart":"https://resources.tidal.com/images/4fe86f0f/d4cd/4e38/b678/a100c4e2460f/1280x1280.jpg","uri":"","trackType":"tidal","codec":"flac","seek":47240,"duration":182,"samplerate":"96 KHz","bitdepth":"24 bit","channels":2,"random":false,"repeat":false,"repeatSingle":false,"consume":false,"volume":79,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"tidalconnect"} Oct 05 00:51:02 volumio volumio[902]: info: Setting Spotify stop after unset volatile call Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::servicePushState Oct 05 00:51:02 volumio volumio[902]: info: CoreStateMachine::pushState Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output update for this device Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::servicePushState Oct 05 00:51:02 volumio volumio[902]: info: CoreStateMachine::pushState Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output update for this device Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: PUSH STATE SPOTIFY Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"play","service":"spop","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::servicePushState Oct 05 00:51:02 volumio volumio[902]: info: CoreStateMachine::pushState Oct 05 00:51:02 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output update for this device Oct 05 00:51:02 volumio volumio[902]: info: MRS: Pushing multiroomSync output Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:02 volumio volumio[902]: info: Spotify Stop Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: SPOTIFY STOP Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"play","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","codec":"ogg","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":79,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Oct 05 00:51:02 volumio volumio[902]: info: Spotify Stop Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: SPOTIFY STOP Oct 05 00:51:02 volumio volumio[902]: SPOTIFY: {"status":"play","title":"","artist":"","album":"","albumart":"/albumart","uri":"","trackType":"spotify","codec":"ogg","seek":0,"duration":0,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":79,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"updatedb":false,"volatile":true,"service":"spop"} Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="handling skip_next player command from 51c819875d0010c112d05cc2fec9e46981b3aa40" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=trace msg="emitting websocket event: will_play" Oct 05 00:51:08 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:72cC7aXgTx3us9bTOBbLUF","play_origin":"collection-songs"}} Oct 05 00:51:08 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:72cC7aXgTx3us9bTOBbLUF","play_origin":"collection-songs"}} Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="selected format OGG_VORBIS_320 (cc7248f29e3d5176a58b4f3f4c00c41c03333d0a)" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="requested aes key for file cc7248f29e3d5176a58b4f3f4c00c41c03333d0a, gid: 72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="fetched first chunk of 24, total size is 12304836 bytes" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=trace msg="seek to 0ms (diff: 0ms, samples: 0, bytes: 0)" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:08 volumio go-librespot[24391]: ALSA lib /home/volumio-alsa-plugin/src/pcm_volumioswitch.c:143:(_snd_pcm_volumioswitch_open_target_pcm) PCM Volumio ALSA Switch Plugin failed to open the switcher target pcm volumioLocalPlayback Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:72cC7aXgTx3us9bTOBbLUF): failed setting stream for spotify:track:72cC7aXgTx3us9bTOBbLUF: ALSA error at snd_pcm_open: Device or resource busy" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="fetched chunk 1/23, size: 524288" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:08 volumio go-librespot[24391]: time="2024-10-05T00:51:08+02:00" level=debug msg="fetched chunk 2/23, size: 524288" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:09 volumio go-librespot[24391]: time="2024-10-05T00:51:09+02:00" level=debug msg="fetched chunk 3/23, size: 524288" uri="spotify:track:72cC7aXgTx3us9bTOBbLUF" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="handling skip_next player command from 51c819875d0010c112d05cc2fec9e46981b3aa40" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=trace msg="emitting websocket event: will_play" Oct 05 00:51:12 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0vFNmvc8EAX9zliW480ol0","play_origin":"collection-songs"}} Oct 05 00:51:12 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:0vFNmvc8EAX9zliW480ol0","play_origin":"collection-songs"}} Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="selected format OGG_VORBIS_320 (4c1fddf76f2cf0d390c8e2e8ca2a796e7df03e77)" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="requested aes key for file 4c1fddf76f2cf0d390c8e2e8ca2a796e7df03e77, gid: 0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="fetched first chunk of 50, total size is 25767200 bytes" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=trace msg="seek to 0ms (diff: -1616ms, samples: 0, bytes: 94726)" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: ALSA lib /home/volumio-alsa-plugin/src/pcm_volumioswitch.c:143:(_snd_pcm_volumioswitch_open_target_pcm) PCM Volumio ALSA Switch Plugin failed to open the switcher target pcm volumioLocalPlayback Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=warning msg="failed handling dealer request" error="failed skipping to next track: failed loading current track (advance to spotify:track:0vFNmvc8EAX9zliW480ol0): failed setting stream for spotify:track:0vFNmvc8EAX9zliW480ol0: ALSA error at snd_pcm_open: Device or resource busy" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="fetched chunk 2/49, size: 524288" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="fetched chunk 1/49, size: 524288" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:12 volumio go-librespot[24391]: time="2024-10-05T00:51:12+02:00" level=debug msg="fetched chunk 3/49, size: 524288" uri="spotify:track:0vFNmvc8EAX9zliW480ol0" Oct 05 00:51:18 volumio go-librespot[24391]: time="2024-10-05T00:51:18+02:00" level=debug msg="handling play player command from 51c819875d0010c112d05cc2fec9e46981b3aa40" Oct 05 00:51:18 volumio go-librespot[24391]: time="2024-10-05T00:51:18+02:00" level=debug msg="resolved context of track" uri="spotify:user:sloam8:collection" Oct 05 00:51:18 volumio go-librespot[24391]: time="2024-10-05T00:51:18+02:00" level=trace msg="fetched new page 0 with 722 items (list: 722)" uri="spotify:user:sloam8:collection" Oct 05 00:51:18 volumio go-librespot[24391]: time="2024-10-05T00:51:18+02:00" level=debug msg="loading track (paused: false, position: 1ms)" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:18 volumio go-librespot[24391]: time="2024-10-05T00:51:18+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 05 00:51:18 volumio go-librespot[24391]: time="2024-10-05T00:51:18+02:00" level=trace msg="emitting websocket event: will_play" Oct 05 00:51:18 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6JyqiSSwsg3hNuglSiKYuc","play_origin":"collection-songs"}} Oct 05 00:51:18 volumio volumio[902]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:6JyqiSSwsg3hNuglSiKYuc","play_origin":"collection-songs"}} Oct 05 00:51:19 volumio go-librespot[24391]: time="2024-10-05T00:51:19+02:00" level=debug msg="selected format OGG_VORBIS_320 (7becbc0dc9508a6d894fb751e88f6bd9d15969ad)" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:19 volumio go-librespot[24391]: time="2024-10-05T00:51:19+02:00" level=debug msg="requested aes key for file 7becbc0dc9508a6d894fb751e88f6bd9d15969ad, gid: 6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=debug msg="fetched first chunk of 16, total size is 8290852 bytes" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=warning msg="reducing track normalisation factor to prevent clipping, please add negative pregain to avoid" Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=trace msg="seek to 1ms (diff: 1ms, samples: 44, bytes: 0)" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:20 volumio go-librespot[24391]: ALSA lib /home/volumio-alsa-plugin/src/pcm_volumioswitch.c:143:(_snd_pcm_volumioswitch_open_target_pcm) PCM Volumio ALSA Switch Plugin failed to open the switcher target pcm volumioLocalPlayback Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=warning msg="failed handling dealer request" error="failed loading current track (load context): failed setting stream for spotify:track:6JyqiSSwsg3hNuglSiKYuc: ALSA error at snd_pcm_open: Device or resource busy" Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:20 volumio go-librespot[24391]: time="2024-10-05T00:51:20+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:6JyqiSSwsg3hNuglSiKYuc" Oct 05 00:51:32 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 00:51:32 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 00:51:32 volumio volumio[902]: info: Discovery: Getting this device information Oct 05 00:51:32 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:51:32 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 00:51:47 volumio volumio[902]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 05 00:51:47 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 05 00:51:47 volumio volumio[902]: info: Creating Spotify config file Oct 05 00:51:47 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 00:51:47 volumio volumio[902]: info: Spotify config file written Oct 05 00:51:47 volumio sudo[24451]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 05 00:51:47 volumio sudo[24451]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 00:51:47 volumio systemd[1]: Stopping go-librespot Daemon... Oct 05 00:51:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 05 00:51:47 volumio volumio[902]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 00:51:47 volumio volumio[902]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 05 00:51:47 volumio volumio[902]: info: Connection to go-librespot Websocket closed Oct 05 00:51:47 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 05 00:51:47 volumio systemd[1]: Stopped go-librespot Daemon. Oct 05 00:51:47 volumio systemd[1]: Started go-librespot Daemon. Oct 05 00:51:47 volumio go-librespot[24453]: Librespot-go daemon starting... Oct 05 00:51:47 volumio sudo[24451]: pam_unix(sudo:session): session closed for user root Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=info msg="generated new device id: 9b20abadcc886d3073184b0863d84e22741857ae" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="stored credentials found for sloam8" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="zeroconf server listening on port 42729" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="obtained new client token: AADp5XMX/gF43+XxjtIcAIVQC722BUx8080BRONbi2qZ5PMIY5AbVadGoGk6RvXJHUPZsWe0G/sTPucmSHfoslhGdlFWHlgJMw036eJCpoxkrMV+tB/5Rjx/SbeM6QCOKOQfgcOooGQWSUbxmdEoTNFTh4yx2+nRHQVVwGCwHla5uaQJftK+wwm5m4oN0ADLihs4LiVsYVmLaegD4rikthm3scfcqDVZ/Nxe9mCohjYQjV2kU5fDOQBaL7hm" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=info msg="connected to ap-gew1.spotify.com:4070" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="completed keyexchange" Oct 05 00:51:47 volumio go-librespot[24453]: time="2024-10-05T00:51:47+02:00" level=debug msg="completed challenge" Oct 05 00:51:48 volumio go-librespot[24453]: time="2024-10-05T00:51:48+02:00" level=debug msg="authenticated as sloam8" Oct 05 00:51:48 volumio vtcs[23560]: [2024-10-05 00:51:48] [warning] got non-close frame in state closing Oct 05 00:51:48 volumio vtcs[23560]: [2024-10-05 00:51:48] [info] asio async_shutdown error: asio.misc:2 (End of file) Oct 05 00:51:48 volumio go-librespot[24453]: time="2024-10-05T00:51:48+02:00" level=debug msg="authenticated as sloam8" Oct 05 00:51:48 volumio volumio[902]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Oct 05 00:51:48 volumio volumio[902]: info: Creating Spotify config file Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 05 00:51:48 volumio volumio[902]: info: Spotify config file written Oct 05 00:51:48 volumio sudo[24462]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 05 00:51:48 volumio sudo[24462]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 00:51:48 volumio systemd[1]: Stopping go-librespot Daemon... Oct 05 00:51:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Oct 05 00:51:48 volumio systemd[1]: go-librespot-daemon.service: Succeeded. Oct 05 00:51:48 volumio systemd[1]: Stopped go-librespot Daemon. Oct 05 00:51:48 volumio volumio[902]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 00:51:48 volumio volumio[902]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Oct 05 00:51:48 volumio systemd[1]: Started go-librespot Daemon. Oct 05 00:51:48 volumio go-librespot[24464]: Librespot-go daemon starting... Oct 05 00:51:48 volumio sudo[24462]: pam_unix(sudo:session): session closed for user root Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=info msg="generated new device id: 8fe9d191f15d0514142888cac15a942ad66ba57d" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="stored credentials found for sloam8" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="zeroconf server listening on port 35663" Oct 05 00:51:48 volumio volumio[902]: info: Pushing metadata Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::servicePushState Oct 05 00:51:48 volumio volumio[902]: info: CoreStateMachine::pushState Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Oct 05 00:51:48 volumio volumio[902]: info: MRS: Pushing multiroomSync output update for this device Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="obtained new client token: AABls2X9VJ6BAFI35NXiWiIXRc8itKe5yCFXIjEZisF4cFvQsh+FDemJCo6sjSx+qC34fBZxp8IIynQZA9ZjAsm8eLVIca8U276ftf6bmwZjmygx2MHV9N6vJrLO8ldaQlpQJH7O9DUnU6yXVQ5WwjiCMSy0wdHsHnT0lPWSgtGkqu1qCkbcyVOKzJf26gAJU6H3u2S7Rfr0JRLNQQK7zCOAvlqxLlw5+C2Bde7MTEdVn91SMOF5pnkdZm72" Oct 05 00:51:48 volumio volumio[902]: info: MRS: Pushing multiroomSync output Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::servicePushState Oct 05 00:51:48 volumio volumio[902]: info: CoreStateMachine::pushState Oct 05 00:51:48 volumio volumio[902]: info: CoreCommandRouter::volumioPushState Oct 05 00:51:48 volumio volumio[902]: info: MRS: Pushing multiroomSync output update for this device Oct 05 00:51:48 volumio volumio[902]: info: MRS: Pushing multiroomSync output Oct 05 00:51:48 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:48 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=info msg="connected to ap-gew1.spotify.com:4070" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="completed keyexchange" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="completed challenge" Oct 05 00:51:48 volumio go-librespot[24464]: time="2024-10-05T00:51:48+02:00" level=debug msg="authenticated as sloam8" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="authenticated as sloam8" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="dealer connection opened" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="initializing zeroconf session, username: sloam8" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="autoplay enabled: false" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="received connection id: OWNiMzY0MzgtMTU4Yy00ZTJkLWEzZGYtNjcyM2QyYWYwMjg3K2RlYWxlcit0Y3A6Ly8wYWNhNDIwZS5pcC5nZXcxLnNwb3RpZnkubmV0OjU3MDArRUFGODY2MUVCMzZCQjgyMzJGRDdEQzc5OTdCNEU2RDc2MkY1RTdDODA0OUMxNDNFNDI1QTEyMjY3Q0YwOTVDNg==" Oct 05 00:51:49 volumio go-librespot[24464]: time="2024-10-05T00:51:49+02:00" level=debug msg="put connect state because NEW_DEVICE" Oct 05 00:51:50 volumio volumio[902]: info: Initializing connection to go-librespot Websocket Oct 05 00:51:50 volumio go-librespot[24464]: time="2024-10-05T00:51:50+02:00" level=debug msg="new websocket client" Oct 05 00:51:50 volumio volumio[902]: info: Connection to go-librespot Websocket established Oct 05 00:51:50 volumio volumio[902]: info: go-librespot daemon successfully initialized Oct 05 00:51:50 volumio volumio[902]: info: Executing endpoint metavolumio Oct 05 00:51:50 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 05 00:51:50 volumio volumio[902]: info: Executing endpoint metavolumio Oct 05 00:51:50 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 05 00:51:50 volumio volumio[902]: info: Executing endpoint metavolumio Oct 05 00:51:50 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Oct 05 00:51:51 volumio volumio[902]: info: go-librespot daemon successfully initialized Oct 05 00:51:53 volumio volumio[902]: info: Getting Spotify volume Oct 05 00:51:53 volumio volumio[902]: info: Spotify volume: 100 Oct 05 00:51:53 volumio volumio[902]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 05 00:51:53 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:51:53 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:53 volumio volumio[902]: SPOTIFY: SPOTIFY VOLUME 100 Oct 05 00:51:53 volumio volumio[902]: SPOTIFY: VOLUMIO VOLUME 79 Oct 05 00:51:53 volumio volumio[902]: SPOTIFY: DELTA VOLUME ENOUGH: true Oct 05 00:51:53 volumio volumio[902]: info: Setting Spotify Volume from Volumio: 79 Oct 05 00:51:53 volumio volumio[902]: info: Initializing connection to go-librespot Websocket Oct 05 00:51:53 volumio go-librespot[24464]: time="2024-10-05T00:51:53+02:00" level=debug msg="new websocket client" Oct 05 00:51:53 volumio volumio[902]: info: Connection to go-librespot Websocket established Oct 05 00:51:54 volumio volumio[902]: info: Initializing connection to go-librespot Websocket Oct 05 00:51:54 volumio go-librespot[24464]: time="2024-10-05T00:51:54+02:00" level=debug msg="new websocket client" Oct 05 00:51:54 volumio volumio[902]: info: Connection to go-librespot Websocket established Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: SETTING SPOTIFY VOLUME 79 Oct 05 00:51:54 volumio volumio[902]: info: Sending Spotify command with payload to local API: /player/volume Oct 05 00:51:54 volumio go-librespot[24464]: time="2024-10-05T00:51:54+02:00" level=debug msg="update volume to 51772/65535" Oct 05 00:51:54 volumio go-librespot[24464]: time="2024-10-05T00:51:54+02:00" level=debug msg="put connect state because VOLUME_CHANGED" Oct 05 00:51:54 volumio go-librespot[24464]: time="2024-10-05T00:51:54+02:00" level=trace msg="emitting websocket event: volume" Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: received: {"type":"volume","data":{"value":79,"max":100}} Oct 05 00:51:54 volumio volumio[902]: SPOTIFY: RECEIVED SPOTIFY VOLUME 79 Oct 05 00:51:56 volumio volumio[902]: info: Getting Spotify volume Oct 05 00:51:56 volumio volumio[902]: info: Spotify volume: 79 Oct 05 00:51:56 volumio volumio[902]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 05 00:51:56 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:51:56 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:51:57 volumio volumio[902]: info: Getting Spotify volume Oct 05 00:51:57 volumio volumio[902]: info: Spotify volume: 79 Oct 05 00:51:57 volumio volumio[902]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Oct 05 00:51:57 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:51:57 volumio volumio[902]: SPOTIFY: RECEIVED VOLUMIO VOLUME 79 Oct 05 00:52:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Oct 05 00:52:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Oct 05 00:52:02 volumio volumio[902]: info: Discovery: Getting this device information Oct 05 00:52:02 volumio volumio[902]: info: CoreCommandRouter::volumioGetState Oct 05 00:52:02 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 00:52:05 volumio volumio[902]: info: Retrieving Cloud Streaming UI Oct 05 00:52:05 volumio volumio[902]: info: Getting Tidal Cloud Configuration Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 00:52:05 volumio volumio[902]: info: Getting Qobuz Cloud Configuration Oct 05 00:52:05 volumio volumio[902]: info: Asking plugin for UI Config Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 00:52:05 volumio volumio[902]: info: Getting Spotify Cloud Configuration Oct 05 00:52:05 volumio volumio[902]: info: Asking plugin for UI Config Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 00:52:05 volumio volumio[902]: info: Saving Spotify Acccount Oct 05 00:52:05 volumio volumio[902]: info: Got it Oct 05 00:52:05 volumio volumio[902]: error: Could not retrieve Spotify Config from plugin Spotify: no section found Oct 05 00:52:05 volumio volumio[902]: info: Got Tidal Cloud Configuration Oct 05 00:52:05 volumio volumio[902]: info: Got it Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::getUIConfigOnPlugin Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::volumioGetBrowseSources Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::volumioGetBrowseSources Oct 05 00:52:05 volumio volumio[902]: info: CoreCommandRouter::volumioGetBrowseSources Oct 05 00:52:06 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 05 00:52:06 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares Oct 05 00:52:09 volumio volumio[902]: info: Disabling MyMusic plugin upnp Oct 05 00:52:09 volumio sudo[24476]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop upmpdcli.service Oct 05 00:52:09 volumio sudo[24476]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 05 00:52:09 volumio systemd[1]: Stopping UPnP Renderer front-end to MPD... Oct 05 00:52:09 volumio volumio[902]: error: Upnp client error: Error: This socket has been ended by the other party Oct 05 00:52:09 volumio volumio[902]: ------------------------------------ BT MESSAGE: BT STATUS: running Oct 05 00:52:10 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats Oct 05 00:52:11 volumio volumio[902]: info: Enabling MyMusic plugin upnp Oct 05 00:52:11 volumio volumio[902]: info: Enabling plugin upnp Oct 05 00:52:11 volumio volumio[902]: info: Loading plugin "upnp"... Oct 05 00:52:11 volumio volumio[902]: info: [1728082331501] Starting Upmpd Daemon Oct 05 00:52:11 volumio volumio[902]: info: CoreCommandRouter::executeOnPlugin: system , registerCallback Oct 05 00:52:11 volumio volumio[902]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 05 00:52:11 volumio volumio[902]: Error: listen EADDRINUSE: address already in use :::6599 Oct 05 00:52:11 volumio volumio[902]: at Server.setupListenHandle [as _listen2] (net.js:1331:16) Oct 05 00:52:11 volumio volumio[902]: at listenInCluster (net.js:1379:12) Oct 05 00:52:11 volumio volumio[902]: at Server.listen (net.js:1465:7) Oct 05 00:52:11 volumio volumio[902]: at UpnpInterface.onVolumioStart (/volumio/app/plugins/audio_interface/upnp/index.js:78:17) Oct 05 00:52:11 volumio volumio[902]: at PluginManager.loadCorePlugin (/volumio/app/pluginmanager.js:255:38) Oct 05 00:52:11 volumio volumio[902]: at Promise._successFn (/volumio/app/pluginmanager.js:1855:19) Oct 05 00:52:11 volumio volumio[902]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28) Oct 05 00:52:11 volumio volumio[902]: at processTicksAndRejections (internal/process/task_queues.js:77:11) { Oct 05 00:52:11 volumio volumio[902]: code: 'EADDRINUSE', Oct 05 00:52:11 volumio volumio[902]: errno: -98, Oct 05 00:52:11 volumio volumio[902]: syscall: 'listen', Oct 05 00:52:11 volumio volumio[902]: address: '::', Oct 05 00:52:11 volumio volumio[902]: port: 6599 Oct 05 00:52:11 volumio volumio[902]: } Oct 05 00:52:11 volumio volumio[902]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 05 00:52:11 volumio sudo[24487]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-05 00:51 Oct 05 00:52:11 volumio sudo[24487]: 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"