-- Logs begin at Sat 2024-11-30 12:54:36 CET, end at Sun 2024-12-01 09:40:04 CET. -- Dec 01 09:39:03 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:39:03 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Dec 01 09:39:03 volumio volumio[981]: info: Listing playlists Dec 01 09:39:03 volumio volumio[981]: info: Listing playlists Dec 01 09:39:05 volumio go-librespot[1226]: time="2024-12-01T09:39:05+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 01 09:39:05 volumio go-librespot[1226]: time="2024-12-01T09:39:05+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 250" Dec 01 09:39:09 volumio go-librespot[1226]: time="2024-12-01T09:39:09+01:00" level=debug msg="handling transfer player command from 7c1fe991c614e789740e98d00e17eaffba5f0ed9" Dec 01 09:39:09 volumio go-librespot[1226]: time="2024-12-01T09:39:09+01:00" level=debug msg="renewing login5 access token" Dec 01 09:39:09 volumio go-librespot[1226]: time="2024-12-01T09:39:09+01:00" level=debug msg="authenticated as 1112663367" Dec 01 09:39:09 volumio go-librespot[1226]: time="2024-12-01T09:39:09+01:00" level=debug msg="resolved context of track" uri="spotify:playlist:37i9dQZF1EVHGWrwldPRtj" Dec 01 09:39:09 volumio go-librespot[1226]: time="2024-12-01T09:39:09+01:00" level=trace msg="fetched new page 0 with 50 items (list: 50)" uri="spotify:playlist:37i9dQZF1EVHGWrwldPRtj" Dec 01 09:39:09 volumio go-librespot[1226]: time="2024-12-01T09:39:09+01:00" level=debug msg="loading track (paused: false, position: 4112ms)" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=trace msg="emitting websocket event: will_play" Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: received: {"type":"will_play","data":{"uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","play_origin":"playlist/ondemand"}} Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="selected format OGG_VORBIS_320 (8b7e746a299c453aef1aabb275dfd57dfb89643a)" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="requested aes key for file 8b7e746a299c453aef1aabb275dfd57dfb89643a, gid: 19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 2794" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1841" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="fetched first chunk of 16, total size is 7972388 bytes" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=trace msg="seek to 4112ms (diff: 207ms, samples: 181339, bytes: 163745)" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="created new output device" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=info msg="loaded track \"Back On 74\" (paused: false, position: 4112ms, duration: 209482ms, prefetched: false)" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=trace msg="scheduling prefetch in 175s" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=trace msg="emitting websocket event: metadata" Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","name":"Back On 74","artist_names":["Jungle"],"album_name":"Volcano","album_cover_url":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","position":4112,"duration":209482,"release_date":"year:2023 month:8 day:11","track_number":6,"disc_number":1}} Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=trace msg="emitting websocket event: active" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="sending successful reply for dealer request" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: received: {"type":"active","data":null} Dec 01 09:39:10 volumio volumio[981]: info: Aligning Spotify Volume to Volumio Volume Dec 01 09:39:10 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:39:10 volumio volumio[981]: info: CorePlayQueue::getTrack 0 Dec 01 09:39:10 volumio volumio[981]: info: Setting Spotify Volume from Volumio: 52 Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:10 volumio go-librespot[1226]: time="2024-12-01T09:39:10+01:00" level=trace msg="emitting websocket event: playing" Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","play_origin":"playlist/ondemand"}} Dec 01 09:39:10 volumio volumio[981]: info: Spotify is playing in volatile mode Dec 01 09:39:10 volumio volumio[981]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: UNSET VOLATILE Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: {"status":"play","position":0,"title":"Naked Eyes - Always Something There to Remind Me","artist":"80s80s Wave","album":"","albumart":"https://is5-ssl.mzstatic.com/image/thumb/Music112/v4/4a/8a/3c/4a8a3c90-e939-0f66-34ce-58ead22e914e/5060516092673.png/600x600bb.jpg","uri":"http://streams.80s80s.de/wave/mp3-192/volumio","trackType":"80s80s Radio","seek":0,"duration":"211","samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":52,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"80s80s Radio","volatile":false,"service":"80s80s"} Dec 01 09:39:10 volumio volumio[981]: info: Setting Spotify stop after unset volatile call Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: PUSH STATE SPOTIFY Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: {"status":"play","service":"spop","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","seek":4112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null} Dec 01 09:39:10 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:10 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:10 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 09:39:10 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:10 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:11 volumio go-librespot[1226]: time="2024-12-01T09:39:11+01:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:11 volumio go-librespot[1226]: time="2024-12-01T09:39:11+01:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:11 volumio volumio[981]: SPOTIFY: PUSH STATE SPOTIFY Dec 01 09:39:11 volumio volumio[981]: SPOTIFY: {"status":"play","service":"spop","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","seek":4112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 01 09:39:11 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:11 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:11 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:11 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:11 volumio volumio[981]: info: Spotify Stop Dec 01 09:39:11 volumio volumio[981]: SPOTIFY: SPOTIFY STOP Dec 01 09:39:11 volumio volumio[981]: SPOTIFY: {"status":"play","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","codec":"ogg","seek":4112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":52,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 01 09:39:12 volumio volumio[981]: SPOTIFY: SETTING SPOTIFY VOLUME 52 Dec 01 09:39:12 volumio volumio[981]: info: Sending Spotify command with payload to local API: /player/volume Dec 01 09:39:13 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:39:17 volumio volumio[981]: info: CoreCommandRouter::volumioPause Dec 01 09:39:17 volumio volumio[981]: info: CoreStateMachine::pause Dec 01 09:39:17 volumio volumio[981]: info: CoreStateMachine::stPlaybackTimer Dec 01 09:39:17 volumio volumio[981]: info: CoreStateMachine::servicePause Dec 01 09:39:17 volumio volumio[981]: info: CoreCommandRouter::servicePause Dec 01 09:39:17 volumio volumio[981]: info: Spotify Received pause Dec 01 09:39:17 volumio volumio[981]: SPOTIFY: SPOTIFY PAUSE Dec 01 09:39:17 volumio volumio[981]: SPOTIFY: {"status":"play","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","codec":"ogg","seek":4112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":52,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 01 09:39:17 volumio volumio[981]: info: Sending Spotify command to local API: /player/pause Dec 01 09:39:17 volumio go-librespot[1226]: time="2024-12-01T09:39:17+01:00" level=debug msg="pause track at 10828ms" Dec 01 09:39:17 volumio go-librespot[1226]: time="2024-12-01T09:39:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:17 volumio go-librespot[1226]: time="2024-12-01T09:39:17+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:17 volumio go-librespot[1226]: time="2024-12-01T09:39:17+01:00" level=trace msg="emitting websocket event: paused" Dec 01 09:39:17 volumio volumio[981]: SPOTIFY: received: {"type":"paused","data":{"uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","play_origin":"playlist/ondemand"}} Dec 01 09:39:17 volumio volumio[981]: SPOTIFY: PUSH STATE SPOTIFY Dec 01 09:39:17 volumio volumio[981]: SPOTIFY: {"status":"pause","service":"spop","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","seek":10112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 01 09:39:17 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:17 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:17 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 09:39:17 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:17 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces system playlist update Dec 01 09:39:18 volumio volumio[981]: info: Ignoring MPD Status Update Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces system playlist update Dec 01 09:39:18 volumio volumio[981]: info: Ignoring MPD Status Update Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces system playlist update Dec 01 09:39:18 volumio volumio[981]: info: Ignoring MPD Status Update Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces system playlist update Dec 01 09:39:18 volumio volumio[981]: info: Ignoring MPD Status Update Dec 01 09:39:18 volumio volumio[981]: info: Dec 01 09:39:18 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 17ms Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand status took 15 milliseconds Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 14ms Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand status took 12 milliseconds Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 10ms Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand status took 9 milliseconds Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 8ms Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand status took 7 milliseconds Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand playlistinfo took 5 milliseconds Dec 01 09:39:18 volumio volumio[981]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:18 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:18 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:18 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:18 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:18 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:18 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:18 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 65ms Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 61ms Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 58ms Dec 01 09:39:18 volumio volumio[981]: info: ------------------------------ 57ms Dec 01 09:39:18 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:18 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:18 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:18 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::volumioPause Dec 01 09:39:21 volumio volumio[981]: info: CoreStateMachine::pause Dec 01 09:39:21 volumio volumio[981]: info: CoreStateMachine::stPlaybackTimer Dec 01 09:39:21 volumio volumio[981]: info: CoreStateMachine::servicePause Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::servicePause Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::pause Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand pause Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand pause took 4 milliseconds Dec 01 09:39:21 volumio volumio[981]: info: Dec 01 09:39:21 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:21 volumio volumio[981]: info: Dec 01 09:39:21 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:21 volumio volumio[981]: info: Dec 01 09:39:21 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:21 volumio volumio[981]: info: Dec 01 09:39:21 volumio volumio[981]: ---------------------------- MPD announces state update: player Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::getState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand status Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand status took 8 milliseconds Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand status took 7 milliseconds Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand status took 5 milliseconds Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand status took 7 milliseconds Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand playlistinfo took 4 milliseconds Dec 01 09:39:21 volumio volumio[981]: info: sendMpdCommand playlistinfo took 3 milliseconds Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseState Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::sendMpdCommand playlistinfo Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:21 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:21 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:21 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:21 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:21 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:21 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:22 volumio volumio[981]: info: ------------------------------ 40ms Dec 01 09:39:22 volumio volumio[981]: info: ------------------------------ 39ms Dec 01 09:39:22 volumio volumio[981]: info: ------------------------------ 38ms Dec 01 09:39:22 volumio volumio[981]: info: sendMpdCommand playlistinfo took 27 milliseconds Dec 01 09:39:22 volumio volumio[981]: verbose: ControllerMpd::parseTrackInfo Dec 01 09:39:22 volumio volumio[981]: info: ControllerMpd::pushState Dec 01 09:39:22 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:22 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:22 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:22 volumio volumio[981]: info: ------------------------------ 46ms Dec 01 09:39:22 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:22 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:22 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:22 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:23 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:39:23 volumio volumio[981]: info: Listing playlists Dec 01 09:39:23 volumio volumio[981]: info: Listing playlists Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=debug msg="handling resume player command from 7c1fe991c614e789740e98d00e17eaffba5f0ed9" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=trace msg="seek to 10828ms (diff: 41ms, samples: 477514, bytes: 443427)" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 10068 us, period size = 444 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 49 frames" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=debug msg="resume track at 10787ms" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=trace msg="scheduling prefetch in 169s" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=debug msg="sending successful reply for dealer request" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Dec 01 09:39:25 volumio go-librespot[1226]: time="2024-12-01T09:39:25+01:00" level=trace msg="emitting websocket event: playing" Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","play_origin":"playlist/ondemand"}} Dec 01 09:39:25 volumio volumio[981]: info: Spotify is playing in volatile mode Dec 01 09:39:25 volumio volumio[981]: info: CoreStateMachine::setConsumeUpdateService undefined Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: UNSET VOLATILE Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: {"status":"pause","title":"Yello - Desire","artist":"80s80s Wave","album":null,"albumart":"/albumart","uri":"http://streams.80s80s.de/wave/mp3-192/volumio","trackType":"","codec":"","seek":888525,"duration":0,"samplerate":"44.1 kHz","bitdepth":"24 bit","channels":2,"random":false,"repeat":false,"consume":false,"volume":52,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true} Dec 01 09:39:25 volumio volumio[981]: info: Setting Spotify stop after unset volatile call Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: PUSH STATE SPOTIFY Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: {"status":"play","service":"spop","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","seek":10112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 01 09:39:25 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:25 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:25 volumio volumio[981]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Dec 01 09:39:25 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: PUSH STATE SPOTIFY Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: {"status":"play","service":"spop","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","seek":10112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null,"stream":false,"repeatMode":"all"} Dec 01 09:39:25 volumio volumio[981]: info: CoreCommandRouter::servicePushState Dec 01 09:39:25 volumio volumio[981]: info: CoreStateMachine::pushState Dec 01 09:39:25 volumio volumio[981]: info: CoreCommandRouter::volumioPushState Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: RECEIVED VOLUMIO VOLUME 52 Dec 01 09:39:25 volumio volumio[981]: info: Spotify Stop Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: SPOTIFY STOP Dec 01 09:39:25 volumio volumio[981]: SPOTIFY: {"status":"play","title":"Back On 74","artist":"Jungle","album":"Volcano","albumart":"https://i.scdn.co/image/ab67616d00001e0277619f14cb03e11baf5761d1","uri":"spotify:track:19kHhX6f6EfLU7rcO3RqjO","trackType":"spotify","codec":"ogg","seek":10112,"duration":209,"samplerate":"44.1 KHz","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":null,"consume":false,"volume":52,"dbVolume":null,"mute":false,"disableVolumeControl":false,"stream":false,"volatile":true,"service":"spop"} Dec 01 09:39:26 volumio go-librespot[1226]: time="2024-12-01T09:39:26+01:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:33 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:39:39 volumio go-librespot[1226]: time="2024-12-01T09:39:39+01:00" level=debug msg="fetched chunk 5/15, size: 524288" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:44 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:39:44 volumio volumio[981]: info: Listing playlists Dec 01 09:39:52 volumio go-librespot[1226]: time="2024-12-01T09:39:52+01:00" level=debug msg="fetched chunk 6/15, size: 524288" uri="spotify:track:19kHhX6f6EfLU7rcO3RqjO" Dec 01 09:39:53 volumio volumio[981]: info: CoreCommandRouter::volumioGetState Dec 01 09:40:03 volumio volumio[981]: info: [1733042403036] [80s80s] Pushing the next song state Heaven 17 - Let Me Go and getting next track. Dec 01 09:40:03 volumio volumio[981]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 01 09:40:03 volumio volumio[981]: TypeError: Cannot set property 'name' of undefined Dec 01 09:40:03 volumio volumio[981]: at Controller80s80s.pushSongState (/data/plugins/music_service/80s80s/index.js:565:20) Dec 01 09:40:03 volumio volumio[981]: at Controller80s80s.playNextTrack (/data/plugins/music_service/80s80s/index.js:665:34) Dec 01 09:40:03 volumio volumio[981]: at NanoTimer.setTimeout (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:343:9) Dec 01 09:40:03 volumio volumio[981]: at Immediate. (/data/plugins/music_service/80s80s/node_modules/nanotimer/lib/nanotimer.js:327:66) Dec 01 09:40:03 volumio volumio[981]: at processImmediate (internal/timers.js:461:21) Dec 01 09:40:03 volumio volumio[981]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Dec 01 09:40:04 volumio sudo[3761]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-12-01 09:39 Dec 01 09:40:04 volumio sudo[3761]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="70bcab5180cf11352f5a5197ade215ea8ee93db0" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="678d37490b3eb2102ce7c6d7a6dc3cf042ff2347" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 08 Nov 2024 06:51:56 PM CET" VOLUMIO_VERSION="3.779" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="b9009e0280f50389e80a537357ff3961"