Feb 06 21:07:04 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:04 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:09 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:09 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:12 volumiopc volumio[1317]: info: VolumeController::SetAlsaVolume1 Feb 06 21:07:12 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:12 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:12 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:12 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:12 volumiopc volumio[1317]: info: Aligning Spotify Volume to Volumio Volume Feb 06 21:07:12 volumiopc volumio[1317]: info: CoreCommandRouter::volumioGetState Feb 06 21:07:12 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:12 volumiopc volumio[1317]: info: Setting Spotify Volume from Volumio: 1 Feb 06 21:07:14 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:14 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:14 volumiopc volumio[1317]: info: Sending Spotify command with payload to local API: /player/volume Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPrevious Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::previous Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: ControllerMpd::seek Feb 06 21:07:15 volumiopc volumio[1317]: error: null Feb 06 21:07:15 volumiopc volumio[1317]: info: Feb 06 21:07:15 volumiopc volumio[1317]: ---------------------------- MPD announces state update: player Feb 06 21:07:15 volumiopc volumio[1317]: info: ControllerMpd::getState Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand status Feb 06 21:07:15 volumiopc volumio[1317]: info: sendMpdCommand status took 0 milliseconds Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::parseState Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 06 21:07:15 volumiopc volumio[1317]: info: sendMpdCommand playlistinfo took 0 milliseconds Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::parseTrackInfo Feb 06 21:07:15 volumiopc volumio[1317]: info: ControllerMpd::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":69,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"711 Kbps","isStreaming":false,"title":"Dear Friends","artist":"Queen","album":"Sheer Heart Attack (2004, TOCP-67343)","uri":"USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/09. Dear Friends.flac","trackType":"flac"} Feb 06 21:07:15 volumiopc volumio[1317]: verbose: CURRENT POSITION 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::syncState stateService play Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::syncState currentStatus play Feb 06 21:07:15 volumiopc volumio[1317]: info: Received an update from plugin. extracting info from payload Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:15 volumiopc volumio[1317]: info: ------------------------------ 11ms Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPrevious Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::previous Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::stop Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::stPlaybackTimer Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::updateTrackBlock Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrackBlock Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::serviceStop Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::serviceStop Feb 06 21:07:15 volumiopc volumio[1317]: info: ControllerMpd::stop Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand stop Feb 06 21:07:15 volumiopc volumio[1317]: info: Feb 06 21:07:15 volumiopc volumio[1317]: ---------------------------- MPD announces state update: player Feb 06 21:07:15 volumiopc volumio[1317]: info: sendMpdCommand stop took 16 milliseconds Feb 06 21:07:15 volumiopc volumio[1317]: info: ControllerMpd::getState Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand status Feb 06 21:07:15 volumiopc volumio[1317]: info: sendMpdCommand status took 1 milliseconds Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::parseState Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 06 21:07:15 volumiopc volumio[1317]: info: sendMpdCommand playlistinfo took 3 milliseconds Feb 06 21:07:15 volumiopc volumio[1317]: verbose: ControllerMpd::parseTrackInfo Feb 06 21:07:15 volumiopc volumio[1317]: info: ControllerMpd::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: verbose: STATE SERVICE {"status":"stop","position":0,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Dear Friends","artist":"Queen","album":"Sheer Heart Attack (2004, TOCP-67343)","uri":"USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/09. Dear Friends.flac","trackType":"flac"} Feb 06 21:07:15 volumiopc volumio[1317]: verbose: CURRENT POSITION 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::syncState stateService stop Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::syncState currentStatus stop Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:15 volumiopc volumio[1317]: info: No code Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:15 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 8 Feb 06 21:07:15 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:15 volumiopc volumio[1317]: info: ------------------------------ 16ms Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::play index undefined Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 21:07:16 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::startPlaybackTimer Feb 06 21:07:16 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::clearAddPlayTracks USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/08. Stone Cold Crazy.flac Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand stop Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand stop took 1 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand clear Feb 06 21:07:16 volumiopc volumio[1317]: info: Feb 06 21:07:16 volumiopc volumio[1317]: ---------------------------- MPD announces system playlist update Feb 06 21:07:16 volumiopc volumio[1317]: info: Ignoring MPD Status Update Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand clear took 1 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand add "USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/08. Stone Cold Crazy.flac" Feb 06 21:07:16 volumiopc volumio[1317]: error: updateQueue error: null Feb 06 21:07:16 volumiopc volumio[1317]: info: ------------------------------ 1ms Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand add "USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/08. Stone Cold Crazy.flac" took 1 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand play Feb 06 21:07:16 volumiopc volumio[1317]: info: Feb 06 21:07:16 volumiopc volumio[1317]: ---------------------------- MPD announces system playlist update Feb 06 21:07:16 volumiopc volumio[1317]: info: Ignoring MPD Status Update Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand play took 0 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: info: ------------------------------ 1ms Feb 06 21:07:16 volumiopc volumio[1317]: info: Feb 06 21:07:16 volumiopc volumio[1317]: ---------------------------- MPD announces state update: player Feb 06 21:07:16 volumiopc volumio[1317]: info: ControllerMpd::getState Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand status Feb 06 21:07:16 volumiopc volumio[1317]: info: Feb 06 21:07:16 volumiopc volumio[1317]: ---------------------------- MPD announces state update: player Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand status took 33 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: info: ControllerMpd::getState Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand status Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::parseState Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand status took 1 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand playlistinfo took 0 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::parseState Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::parseTrackInfo Feb 06 21:07:16 volumiopc volumio[1317]: info: ControllerMpd::pushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:16 volumiopc volumio[1317]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":136,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"743 Kbps","isStreaming":false,"title":"Stone Cold Crazy","artist":"Queen","album":"Sheer Heart Attack (2004, TOCP-67343)","uri":"USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/08. Stone Cold Crazy.flac","trackType":"flac"} Feb 06 21:07:16 volumiopc volumio[1317]: verbose: CURRENT POSITION 7 Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::syncState stateService play Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::syncState currentStatus stop Feb 06 21:07:16 volumiopc volumio[1317]: info: ------------------------------ 36ms Feb 06 21:07:16 volumiopc volumio[1317]: info: sendMpdCommand playlistinfo took 1 milliseconds Feb 06 21:07:16 volumiopc volumio[1317]: verbose: ControllerMpd::parseTrackInfo Feb 06 21:07:16 volumiopc volumio[1317]: info: ControllerMpd::pushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:16 volumiopc volumio[1317]: verbose: STATE SERVICE {"status":"play","position":0,"seek":855,"duration":136,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"854 Kbps","isStreaming":false,"title":"Stone Cold Crazy","artist":"Queen","album":"Sheer Heart Attack (2004, TOCP-67343)","uri":"USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/08. Stone Cold Crazy.flac","trackType":"flac"} Feb 06 21:07:16 volumiopc volumio[1317]: verbose: CURRENT POSITION 7 Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::syncState stateService play Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::syncState currentStatus play Feb 06 21:07:16 volumiopc volumio[1317]: info: Received an update from plugin. extracting info from payload Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:16 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:16 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:16 volumiopc volumio[1317]: info: ------------------------------ 9ms Feb 06 21:07:19 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:19 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:24 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:24 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::getUIConfigOnPlugin Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sOptions Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: mpd , getPlaybackMode Feb 06 21:07:24 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus Feb 06 21:07:29 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:29 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:34 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:34 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPause Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::pause Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::stPlaybackTimer Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::servicePause Feb 06 21:07:35 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreCommandRouter::servicePause Feb 06 21:07:35 volumiopc volumio[1317]: info: ControllerMpd::pause Feb 06 21:07:35 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand pause Feb 06 21:07:35 volumiopc volumio[1317]: info: Feb 06 21:07:35 volumiopc volumio[1317]: ---------------------------- MPD announces state update: player Feb 06 21:07:35 volumiopc volumio[1317]: info: sendMpdCommand pause took 1 milliseconds Feb 06 21:07:35 volumiopc volumio[1317]: info: ControllerMpd::getState Feb 06 21:07:35 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand status Feb 06 21:07:35 volumiopc volumio[1317]: info: sendMpdCommand status took 0 milliseconds Feb 06 21:07:35 volumiopc volumio[1317]: verbose: ControllerMpd::parseState Feb 06 21:07:35 volumiopc volumio[1317]: verbose: ControllerMpd::sendMpdCommand playlistinfo Feb 06 21:07:35 volumiopc volumio[1317]: info: sendMpdCommand playlistinfo took 0 milliseconds Feb 06 21:07:35 volumiopc volumio[1317]: verbose: ControllerMpd::parseTrackInfo Feb 06 21:07:35 volumiopc volumio[1317]: info: ControllerMpd::pushState Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:35 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:35 volumiopc volumio[1317]: verbose: STATE SERVICE {"status":"pause","position":0,"seek":19732,"duration":136,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"968 Kbps","isStreaming":false,"title":"Stone Cold Crazy","artist":"Queen","album":"Sheer Heart Attack (2004, TOCP-67343)","uri":"USB/Smartbuy/Queen/1974. Sheer Heart Attack/1974. Queen - Sheer Heart Attack (2004, Toshiba-EMI, Japan, TOCP-67343)/08. Stone Cold Crazy.flac","trackType":"flac"} Feb 06 21:07:35 volumiopc volumio[1317]: verbose: CURRENT POSITION 7 Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::syncState stateService pause Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::syncState currentStatus pause Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:35 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:35 volumiopc volumio[1317]: info: CoreStateMachine::stPlaybackTimer Feb 06 21:07:35 volumiopc volumio[1317]: info: ------------------------------ 6ms Feb 06 21:07:39 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:39 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:43 volumiopc go-librespot[7569]: time="2026-02-06T21:07:43+03:00" level=debug msg="obtained new client token: AAAU05qrnn4WGskoZKJcaacDQzSo2GqWY0NGI8OoVkZ2jOSTzjJZhaDdh51e/Bb4AL0bbIcCeq39NHTqr7ALEmjXtUL7VUbRd1gDwB8KxY3EIesO7tCQNuWpgUqqK2zNtf7RD7ZYA7niZJb3sC3o9VP+nRJGbsxil33i64acC7EouZr2g3M62sgpM3OZbnxKIubP+jcU4ya8EJsz7X0s9H5wN9E9iBBqDk8Vw86I+8uVZWguyzAO" Feb 06 21:07:43 volumiopc go-librespot[7569]: time="2026-02-06T21:07:43+03: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]" Feb 06 21:07:43 volumiopc go-librespot[7569]: time="2026-02-06T21:07:43+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 06 21:07:43 volumiopc go-librespot[7569]: time="2026-02-06T21:07:43+03:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 06 21:07:44 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:44 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=debug msg="completed keyexchange" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=debug msg="completed challenge" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=info msg="authenticated AP" username="31************************ta" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=info msg="authenticated Login5" username="31************************ta" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03: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]" Feb 06 21:07:44 volumiopc go-librespot[7569]: time="2026-02-06T21:07:44+03:00" level=info msg="accepted zeroconf from Pixel 7 Pro" username="31************************ta" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="dealer connection opened" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=trace msg="starting accesspoint recv loop" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=trace msg="starting dealer recv loop" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=trace msg="received accesspoint ping" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=debug msg="received connection id: NzgxMWQ1ODEtNWNk...Rjk2RDQ0Q0UyRg==" Feb 06 21:07:45 volumiopc go-librespot[7569]: time="2026-02-06T21:07:45+03:00" level=trace msg="received accesspoint pong ack" Feb 06 21:07:46 volumiopc go-librespot[7569]: time="2026-02-06T21:07:46+03:00" level=debug msg="put connect state because NEW_DEVICE" Feb 06 21:07:47 volumiopc go-librespot[7569]: time="2026-02-06T21:07:47+03:00" level=debug msg="handling transfer player command from 980084dc7c17f3896e34f2fb30f8ce74bf3cc151" Feb 06 21:07:47 volumiopc go-librespot[7569]: time="2026-02-06T21:07:47+03:00" level=debug msg="resolved context of track" uri="spotify:station:track:4OMu5a8sFpcRCPCcsoEaov" Feb 06 21:07:47 volumiopc go-librespot[7569]: time="2026-02-06T21:07:47+03:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:4OMu5a8sFpcRCPCcsoEaov" Feb 06 21:07:47 volumiopc go-librespot[7569]: time="2026-02-06T21:07:47+03:00" level=debug msg="loading track (paused: true, position: 98615ms)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:47 volumiopc go-librespot[7569]: time="2026-02-06T21:07:47+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1133" Feb 06 21:07:47 volumiopc go-librespot[7569]: time="2026-02-06T21:07:47+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Feb 06 21:07:48 volumiopc go-librespot[7569]: time="2026-02-06T21:07:48+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:48 volumiopc go-librespot[7569]: time="2026-02-06T21:07:48+03:00" level=trace msg="emitting websocket event: will_play" Feb 06 21:07:48 volumiopc go-librespot[7569]: time="2026-02-06T21:07:48+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 167" Feb 06 21:07:48 volumiopc go-librespot[7569]: time="2026-02-06T21:07:48+03:00" level=debug msg="selected format OGG_VORBIS_320 (d699d6017e0e0055625f988923e763ac63de0557)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:48 volumiopc go-librespot[7569]: time="2026-02-06T21:07:48+03:00" level=debug msg="requested aes key for file d699d6017e0e0055625f988923e763ac63de0557, gid: 5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:48 volumiopc go-librespot[7569]: time="2026-02-06T21:07:48+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:49 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched first chunk of 23, total size is 11965500 bytes" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 7/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=trace msg="seek to 98615ms (diff: 151ms, samples: 4348921, bytes: 3945921)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="created new output device" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=info msg="loaded track \"Your Time Is Gonna Come - Remaster\" (paused: true, position: 98615ms, duration: 274693ms, prefetched: false)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 10/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 9/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:49 volumiopc go-librespot[7569]: time="2026-02-06T21:07:49+03:00" level=debug msg="fetched chunk 8/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=trace msg="emitting websocket event: metadata" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=trace msg="emitting websocket event: active" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="sending successful reply for dealer request" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=playback-settings/content-settings-update Feb 06 21:07:50 volumiopc volumio[1317]: info: Aligning Spotify Volume to Volumio Volume Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::volumioGetState Feb 06 21:07:50 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:50 volumiopc volumio[1317]: info: Setting Spotify Volume from Volumio: 1 Feb 06 21:07:50 volumiopc volumio[1317]: info: Aligning Spotify Volume to Volumio Volume Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::volumioGetState Feb 06 21:07:50 volumiopc volumio[1317]: info: CorePlayQueue::getTrack 7 Feb 06 21:07:50 volumiopc volumio[1317]: info: Setting Spotify Volume from Volumio: 1 Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 461" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1196" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1133" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 411" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=trace msg="emitting websocket event: paused" Feb 06 21:07:50 volumiopc volumio[1317]: info: Spotify is playing in volatile mode Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 21:07:50 volumiopc volumio[1317]: info: Setting Spotify stop after unset volatile call Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=info msg="playback was transferred to Pixel 7 Pro" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=trace msg="closed output device because of stop command" Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:50 volumiopc volumio[1317]: info: Spotify is playing in volatile mode Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreStateMachine::setConsumeUpdateService undefined Feb 06 21:07:50 volumiopc volumio[1317]: info: Setting Spotify stop after unset volatile call Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:50 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=debug msg="put connect state inactive" Feb 06 21:07:50 volumiopc go-librespot[7569]: time="2026-02-06T21:07:50+03:00" level=trace msg="emitting websocket event: inactive" Feb 06 21:07:50 volumiopc volumio[1317]: error: Failed to decode event: inactive Feb 06 21:07:50 volumiopc volumio[1317]: error: Failed to decode event: inactive Feb 06 21:07:50 volumiopc volumio[1317]: info: Spotify Stop Feb 06 21:07:50 volumiopc volumio[1317]: info: Spotify Stop Feb 06 21:07:51 volumiopc volumio[1317]: info: Sending Spotify command with payload to local API: /player/volume Feb 06 21:07:54 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:54 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:54 volumiopc go-librespot[7569]: time="2026-02-06T21:07:54+03:00" level=debug msg="obtained new client token: AADcyZhutq/NAjlj+TrWAGzsY6EgTZn5zYdPXE3XYZDlz+DjLtoHYDdUhYM8ITWW9X+zPvKvYXBZFHM90868MOni41MjM9FKcpSHz46YERArPzmt4uFLc873YfClt0cGKjzqkyE5X5ZXuRL5NdyC+hREkYxXmP0TZ6ncTBA3mZRT/nJj/lTjOqXXeKg5mDR9aA4YHCUp0/t/v8BFZYyl1KH9FfDxyxP+rVyZxFMn+mGoZlE7A7rD0Bs=" Feb 06 21:07:54 volumiopc go-librespot[7569]: time="2026-02-06T21:07:54+03:00" level=debug msg="connected to ap-gew1.spotify.com:4070" Feb 06 21:07:54 volumiopc go-librespot[7569]: time="2026-02-06T21:07:54+03:00" level=warning msg="failed connecting to accesspoint, retrying" error="failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: EOF" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="connected to ap-gew1.spotify.com:443" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="completed keyexchange" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="completed challenge" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=info msg="authenticated AP" username="31************************ta" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=info msg="authenticated Login5" username="31************************ta" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=info msg="accepted zeroconf from Pixel 7 Pro" username="31************************ta" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="dealer connection opened" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=trace msg="starting accesspoint recv loop" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=trace msg="starting dealer recv loop" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=trace msg="received accesspoint ping" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 481" Feb 06 21:07:55 volumiopc go-librespot[7569]: time="2026-02-06T21:07:55+03:00" level=debug msg="received connection id: ZWQ1MjYzMDAtNTNm...NzkzNkE0RDE4MA==" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=trace msg="received accesspoint pong ack" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=debug msg="put connect state because NEW_DEVICE" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=debug msg="handling transfer player command from 980084dc7c17f3896e34f2fb30f8ce74bf3cc151" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=debug msg="resolved context of track" uri="spotify:station:track:4OMu5a8sFpcRCPCcsoEaov" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:station:track:4OMu5a8sFpcRCPCcsoEaov" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=debug msg="loading track (paused: true, position: 98615ms)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:56 volumiopc go-librespot[7569]: time="2026-02-06T21:07:56+03:00" level=trace msg="emitting websocket event: will_play" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="selected format OGG_VORBIS_320 (d699d6017e0e0055625f988923e763ac63de0557)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="requested aes key for file d699d6017e0e0055625f988923e763ac63de0557, gid: 5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=trace msg="found 2 cdn urls" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched first chunk of 23, total size is 11965500 bytes" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched chunk 1/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched chunk 3/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched chunk 8/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched chunk 10/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched chunk 7/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=trace msg="seek to 98615ms (diff: 151ms, samples: 4348921, bytes: 3945921)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="created new output device" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=info msg="loaded track \"Your Time Is Gonna Come - Remaster\" (paused: true, position: 98615ms, duration: 274693ms, prefetched: false)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:57 volumiopc go-librespot[7569]: time="2026-02-06T21:07:57+03:00" level=debug msg="fetched chunk 9/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=debug msg="fetched chunk 2/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=trace msg="emitting websocket event: metadata" Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=trace msg="emitting websocket event: active" Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=debug msg="sending successful reply for dealer request" Feb 06 21:07:58 volumiopc volumio[1317]: info: Aligning Spotify Volume to Volumio Volume Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreCommandRouter::volumioGetState Feb 06 21:07:58 volumiopc volumio[1317]: info: Setting Spotify Volume from Volumio: 1 Feb 06 21:07:58 volumiopc volumio[1317]: info: Aligning Spotify Volume to Volumio Volume Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreCommandRouter::volumioGetState Feb 06 21:07:58 volumiopc volumio[1317]: info: Setting Spotify Volume from Volumio: 1 Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:58 volumiopc go-librespot[7569]: time="2026-02-06T21:07:58+03:00" level=trace msg="emitting websocket event: paused" Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:58 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="handling resume player command from 980084dc7c17f3896e34f2fb30f8ce74bf3cc151" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=trace msg="seek to 98615ms (diff: 151ms, samples: 4348921, bytes: 3945921)" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 124988 us, period size = 5512 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 4 frames, PCM format = FLOAT_LE" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="resume track at 98464ms" Feb 06 21:07:59 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:07:59 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=trace msg="scheduling prefetch in 146s" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="sending successful reply for dealer request" Feb 06 21:07:59 volumiopc volumio[1317]: info: Sending Spotify command with payload to local API: /player/volume Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=trace msg="emitting websocket event: playing" Feb 06 21:07:59 volumiopc go-librespot[7569]: time="2026-02-06T21:07:59+03:00" level=debug msg="update volume requested to 655/65535" Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:07:59 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:08:00 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:08:00 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:08:00 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:08:00 volumiopc volumio[1317]: info: CoreCommandRouter::servicePushState Feb 06 21:08:00 volumiopc volumio[1317]: info: CoreStateMachine::pushState Feb 06 21:08:00 volumiopc volumio[1317]: info: CoreCommandRouter::volumioPushState Feb 06 21:08:00 volumiopc go-librespot[7569]: time="2026-02-06T21:08:00+03:00" level=debug msg="put connect state because VOLUME_CHANGED" Feb 06 21:08:00 volumiopc go-librespot[7569]: time="2026-02-06T21:08:00+03:00" level=trace msg="emitting websocket event: volume" Feb 06 21:08:04 volumiopc dbus-daemon[907]: [system] The maximum number of active connections for UID 1000 has been reached (max_connections_per_user=256) Feb 06 21:08:04 volumiopc volumio[1317]: info: Discovery: Restarting Browsing Feb 06 21:08:04 volumiopc go-librespot[7569]: time="2026-02-06T21:08:04+03:00" level=debug msg="fetched chunk 11/22, size: 524288" uri="spotify:track:5RPiBNQVmuEm7YlVVotrLa" Feb 06 21:08:06 volumiopc volumio[1317]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 06 21:08:06 volumiopc volumio[1317]: AggregateError Feb 06 21:08:06 volumiopc volumio[1317]: at internalConnectMultiple (node:net:1114:18) Feb 06 21:08:06 volumiopc volumio[1317]: at afterConnectMultiple (node:net:1667:5) { Feb 06 21:08:06 volumiopc volumio[1317]: code: 'ETIMEDOUT', Feb 06 21:08:06 volumiopc volumio[1317]: [errors]: [ Feb 06 21:08:06 volumiopc volumio[1317]: Error: connect ETIMEDOUT 23.73.2.88:443 Feb 06 21:08:06 volumiopc volumio[1317]: at createConnectionError (node:net:1634:14) Feb 06 21:08:06 volumiopc volumio[1317]: at Timeout.internalConnectMultipleTimeout (node:net:1685:38) Feb 06 21:08:06 volumiopc volumio[1317]: at listOnTimeout (node:internal/timers:575:11) Feb 06 21:08:06 volumiopc volumio[1317]: at process.processTimers (node:internal/timers:514:7) { Feb 06 21:08:06 volumiopc volumio[1317]: errno: -110, Feb 06 21:08:06 volumiopc volumio[1317]: code: 'ETIMEDOUT', Feb 06 21:08:06 volumiopc volumio[1317]: syscall: 'connect', Feb 06 21:08:06 volumiopc volumio[1317]: address: '23.73.2.88', Feb 06 21:08:06 volumiopc volumio[1317]: port: 443 Feb 06 21:08:06 volumiopc volumio[1317]: }, Feb 06 21:08:06 volumiopc volumio[1317]: Error: connect ETIMEDOUT 23.73.2.84:443 Feb 06 21:08:06 volumiopc volumio[1317]: at createConnectionError (node:net:1634:14) Feb 06 21:08:06 volumiopc volumio[1317]: at afterConnectMultiple (node:net:1664:40) { Feb 06 21:08:06 volumiopc volumio[1317]: errno: -110, Feb 06 21:08:06 volumiopc volumio[1317]: code: 'ETIMEDOUT', Feb 06 21:08:06 volumiopc volumio[1317]: syscall: 'connect', Feb 06 21:08:06 volumiopc volumio[1317]: address: '23.73.2.84', Feb 06 21:08:06 volumiopc volumio[1317]: port: 443 Feb 06 21:08:06 volumiopc volumio[1317]: } Feb 06 21:08:06 volumiopc volumio[1317]: ] Feb 06 21:08:06 volumiopc volumio[1317]: } Feb 06 21:08:06 volumiopc volumio[1317]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Feb 06 21:08:06 volumiopc sudo[60437]: volumio : PWD=/ ; USER=root ; COMMAND=/bin/journalctl '--since=2026-02-06 21:07' Feb 06 21:08:06 volumiopc sudo[60437]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=1000) PRETTY_NAME="Debian GNU/Linux 12 (bookworm)" NAME="Debian GNU/Linux" VERSION_ID="12" VERSION="12 (bookworm)" VERSION_CODENAME=bookworm 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="b05a530ca81d05eb9a84d0acf82089f0a60b8ee6" VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd" VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2" VOLUMIO_BE_VERSION="4ad85e2147d972f0b838d33c21382d2d813b2ae8" VOLUMIO_ARCH="x64" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Thu Dec 25 09:38:19 UTC 2025" VOLUMIO_VERSION="4.084" VOLUMIO_HARDWARE="x86_amd64" VOLUMIO_DEVICENAME="x86_64" VOLUMIO_HASH="00e933ebe3692ad8aea9910d2289bf23"