-- Logs begin at Tue 2024-11-26 08:53:22 CET, end at Tue 2024-11-26 10:57:16 CET. -- Nov 26 10:56:01 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:01 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1722. Nov 26 10:56:01 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:01 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:01 player-number-one go-librespot[15476]: Librespot-go daemon starting... Nov 26 10:56:01 player-number-one go-librespot[15476]: time="2024-11-26T10:56:01+01:00" level=info msg="generated new device id: fe93b11c6908b7e30ad08b8f8a6cdce047834121" Nov 26 10:56:01 player-number-one go-librespot[15476]: time="2024-11-26T10:56:01+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:01 player-number-one go-librespot[15476]: time="2024-11-26T10:56:01+01:00" level=debug msg="obtained new client token: AAC3vK61Qb0Q7uiaeLHqQJJZxHKWV6AbAL0CGzUxP0sHJgjFi3bbizj28vjey8okEyBs5eArUlkYpg63sYmWwOwprBzNa0ZjA0fmlm2fuCm5QAhuLdW9HzWP2U+hVkUVhQV7oxzVT9062D81T3PQ1ydcwaYpI6T2YQUOBweW1TDhBQc1BJi7lqL6eyeW+iKMi9/TxSr35/PqsLfITOx8aAAL1GWIKgpNujK6FzIVe9mfU8UmaJWZi/1bPGSqihiy" Nov 26 10:56:01 player-number-one go-librespot[15476]: time="2024-11-26T10:56:01+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:01 player-number-one go-librespot[15476]: time="2024-11-26T10:56:01+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:02 player-number-one go-librespot[15476]: time="2024-11-26T10:56:02+01:00" level=debug msg="completed challenge" Nov 26 10:56:02 player-number-one go-librespot[15476]: time="2024-11-26T10:56:02+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:02 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:02 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:02 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:02 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:04 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:05 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:05 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:05 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:05 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1723. Nov 26 10:56:05 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:05 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:05 player-number-one go-librespot[15509]: Librespot-go daemon starting... Nov 26 10:56:05 player-number-one go-librespot[15509]: time="2024-11-26T10:56:05+01:00" level=info msg="generated new device id: bc7453d98699ee2f62b174d5bd3125d60dcc45a5" Nov 26 10:56:05 player-number-one go-librespot[15509]: time="2024-11-26T10:56:05+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:06 player-number-one go-librespot[15509]: time="2024-11-26T10:56:06+01:00" level=debug msg="obtained new client token: AAAeTfBXEznjaQfOV7MDcr9aDMBjnLNX5wrC7BaP76uxOJh8IG4CBDW0CMPpR2mdVrNicICYN2oahl0B6fRlzgLlIbxjHFsr8NHdwHgc95EBQb1JFJCQ8gguCQEwrNrf+kIv8CxiK/I0yz8rlQeO6PzpDwLtbDqv1OYKEd38dYQfElF+8JRXtnAUfFTaqkb5J8mB4vj6KwCUBPpol3WKspbw+jY8UD6ZiU7FKtK9iFY0DtH2mVDnALm6xGBTGw==" Nov 26 10:56:06 player-number-one go-librespot[15509]: time="2024-11-26T10:56:06+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:06 player-number-one go-librespot[15509]: time="2024-11-26T10:56:06+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:06 player-number-one go-librespot[15509]: time="2024-11-26T10:56:06+01:00" level=debug msg="completed challenge" Nov 26 10:56:06 player-number-one go-librespot[15509]: time="2024-11-26T10:56:06+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:06 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:06 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:08 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:08 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:10 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:10 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1724. Nov 26 10:56:10 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:10 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:10 player-number-one go-librespot[15520]: Librespot-go daemon starting... Nov 26 10:56:10 player-number-one go-librespot[15520]: time="2024-11-26T10:56:10+01:00" level=info msg="generated new device id: 021d0e5c861a04c6d868b6eef6ec32ad1436d78e" Nov 26 10:56:10 player-number-one go-librespot[15520]: time="2024-11-26T10:56:10+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:10 player-number-one go-librespot[15520]: time="2024-11-26T10:56:10+01:00" level=debug msg="obtained new client token: AAA8WKb8z6+jsCDMTW0uHnrnS6C9/v8Qc1+igHaa5eazan7bR/nUBCz/ils/UwWO3YRqqWDjkpbTeuSCuFGVojAODbmmDlKmLZdOyYL+ATwkNJJUaQQs4LVSI9ar57OZuvJG3kKIl6Dgaeup7ve0Ky+6qmgU3ZfhGQgk//RaRFFoqQqgDJHNJkI8c4DdIeOZ/dh0XaBlchsRbF4dcsbCYmDwrtXO7HVj8y36a0DCrMrvTA5wunW8ltZnIuf82qTD" Nov 26 10:56:10 player-number-one go-librespot[15520]: time="2024-11-26T10:56:10+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:11 player-number-one go-librespot[15520]: time="2024-11-26T10:56:11+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:11 player-number-one go-librespot[15520]: time="2024-11-26T10:56:11+01:00" level=debug msg="completed challenge" Nov 26 10:56:11 player-number-one go-librespot[15520]: time="2024-11-26T10:56:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:11 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:11 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:11 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:11 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:14 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:14 player-number-one volumio[851]: info: Listing playlists Nov 26 10:56:14 player-number-one volumio[851]: info: Listing playlists Nov 26 10:56:14 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:14 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:14 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:14 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1725. Nov 26 10:56:14 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:14 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:14 player-number-one go-librespot[15556]: Librespot-go daemon starting... Nov 26 10:56:14 player-number-one go-librespot[15556]: time="2024-11-26T10:56:14+01:00" level=info msg="generated new device id: 29f5c89e0fc2caeacf50fb5ffd9ea4390ce92884" Nov 26 10:56:14 player-number-one go-librespot[15556]: time="2024-11-26T10:56:14+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:15 player-number-one go-librespot[15556]: time="2024-11-26T10:56:15+01:00" level=debug msg="obtained new client token: AADYbbOtbdtc/uSh4PieCq9zhlJMDBYv/CI8EAHOsOhu40wPn8loZHn8CgxfhSiAJ7PLpsz0W8eyPl8Ki58NyzL2zX7xgln+uYUjRgGV/OxXJBp/Hpt/ysxTE0X76lOyFbygTyqMf1ozAbpJu7vXgxqa3lOL0VBBFfKsvhVenjw99eLW2aPQmtILym7V+C1DDIBOtkZ84ex0B7bKllVovZuvO3BPBhKdANV+KUKzLza4HTzWoqSJJwPqYRWx9A==" Nov 26 10:56:15 player-number-one go-librespot[15556]: time="2024-11-26T10:56:15+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:15 player-number-one go-librespot[15556]: time="2024-11-26T10:56:15+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:15 player-number-one go-librespot[15556]: time="2024-11-26T10:56:15+01:00" level=debug msg="completed challenge" Nov 26 10:56:16 player-number-one go-librespot[15556]: time="2024-11-26T10:56:16+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:16 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:16 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:17 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:17 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:18 player-number-one volumio[851]: info: Nov 26 10:56:18 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:18 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:18 player-number-one volumio[851]: info: Nov 26 10:56:18 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:18 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:18 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:18 player-number-one volumio[851]: info: ------------------------------ 7ms Nov 26 10:56:18 player-number-one volumio[851]: info: sendMpdCommand status took 5 milliseconds Nov 26 10:56:18 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:18 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:18 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 1 milliseconds Nov 26 10:56:18 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:18 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:18 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:18 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:18 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":1,"seek":96235,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"128 Kbps","isStreaming":false,"title":"T?rez Montcalm - Sweet Dreams","artist":"FluffyPinkUnicorns","album":null,"uri":"http://192.168.10.105:8001/stream","trackType":""} Nov 26 10:56:18 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:18 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:18 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus play Nov 26 10:56:18 player-number-one volumio[851]: info: Received an update from plugin. extracting info from payload Nov 26 10:56:18 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 26 10:56:18 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:18 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 10:56:18 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:18 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:18 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:18 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:18 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:18 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:18 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:18 player-number-one volumio[851]: info: ------------------------------ 26ms Nov 26 10:56:18 player-number-one volumio[851]: info: [LastFM] Split composite title into artist: T?rez Montcalm and title: Sweet Dreams Nov 26 10:56:18 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:18 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:18 player-number-one volumio[851]: info: [LastFM] track info: {"success":true,"trackInfo":{"name":"Sweet Dreams","url":"https://www.last.fm/music/T%3Frez+Montcalm/_/Sweet+Dreams","duration":"0","streamable":{"#":"0","@":{"fulltrack":"0"}},"listeners":"2","playcount":"3","artist":{"name":"T?rez Montcalm","url":"https://www.last.fm/music/T%3Frez+Montcalm"},"userplaycount":"0","userloved":"0","toptags":""}} Nov 26 10:56:18 player-number-one volumio[851]: info: [LastFM] Updated missing track duration: 0 Nov 26 10:56:19 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:19 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1726. Nov 26 10:56:19 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:19 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:19 player-number-one go-librespot[15567]: Librespot-go daemon starting... Nov 26 10:56:19 player-number-one go-librespot[15567]: time="2024-11-26T10:56:19+01:00" level=info msg="generated new device id: c079ace78f2292b4b71d382aed0da79ca9fe9f55" Nov 26 10:56:19 player-number-one go-librespot[15567]: time="2024-11-26T10:56:19+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:19 player-number-one go-librespot[15567]: time="2024-11-26T10:56:19+01:00" level=debug msg="obtained new client token: AABfiWXAy4v+Qu1v+cSPsYWJqb7oW7ifqd+Z7ZxIEMXKWTjMsMbPLfHIN6G72ymV7gNOHqaqSEcsxstrZL5ZFmVxk6Vr4cn3f6MIp/gG9R4OyfuTcHUkS63aIGRnmF8tchxqblEMqfnzE36uP0nXzio2CuPjHq2TMPMxCtUxYQNB2fN7/yOG2laQ2Qmf/T2qGeDGcHnviKnWeD4oq+Pd4khFWIXuRbMpI8aH/hD8mVXtx7g3py6lZIeaT32iMhCT" Nov 26 10:56:19 player-number-one go-librespot[15567]: time="2024-11-26T10:56:19+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 26 10:56:19 player-number-one go-librespot[15567]: time="2024-11-26T10:56:19+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:20 player-number-one go-librespot[15567]: time="2024-11-26T10:56:20+01:00" level=debug msg="completed challenge" Nov 26 10:56:20 player-number-one go-librespot[15567]: time="2024-11-26T10:56:20+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:20 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:20 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:20 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:20 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:23 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:23 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1727. Nov 26 10:56:23 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:23 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:23 player-number-one go-librespot[15589]: Librespot-go daemon starting... Nov 26 10:56:23 player-number-one go-librespot[15589]: time="2024-11-26T10:56:23+01:00" level=info msg="generated new device id: f0f93ba44683f9733c9154b3fd2da6739c19983b" Nov 26 10:56:23 player-number-one go-librespot[15589]: time="2024-11-26T10:56:23+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:23 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:23 player-number-one go-librespot[15589]: time="2024-11-26T10:56:23+01:00" level=debug msg="new websocket client" Nov 26 10:56:23 player-number-one volumio[851]: info: Connection to go-librespot Websocket established Nov 26 10:56:23 player-number-one go-librespot[15589]: time="2024-11-26T10:56:23+01:00" level=debug msg="obtained new client token: AAAUMD370PX9gEcsR43zZCz1JLzuv0Bhx9Qacrh/BQRC1/yUP1jhx+rr8n4ftnsTzdwJAc97Lzubtz753GWQ4oChxSTOu9r5fDvDTC0yqgVGLSWNELffuAmgFztkqru00dSgSB3+aznUJ27SjU+MwkdppLarCfRHdLFebem1U1IpfUYdYiP2LlLcsFpGqdeP3+56Ob5Xvu4LLqNVzHrzeBohcpn2CoqlgTOKjcZ4/MJVzQCMtxkW0ONET+viw1iZ" Nov 26 10:56:24 player-number-one go-librespot[15589]: time="2024-11-26T10:56:24+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:24 player-number-one go-librespot[15589]: time="2024-11-26T10:56:24+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:24 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:24 player-number-one go-librespot[15589]: time="2024-11-26T10:56:24+01:00" level=debug msg="completed challenge" Nov 26 10:56:24 player-number-one go-librespot[15589]: time="2024-11-26T10:56:24+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:24 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:24 player-number-one volumio[851]: info: Connection to go-librespot Websocket closed Nov 26 10:56:24 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:26 player-number-one volumio[851]: info: Getting Spotify volume Nov 26 10:56:26 player-number-one volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:26 player-number-one volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 26 10:56:26 player-number-one volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 269) Nov 26 10:56:26 player-number-one volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 26 10:56:26 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:26 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:27 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:27 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:27 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:27 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1728. Nov 26 10:56:27 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:27 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:27 player-number-one go-librespot[15608]: Librespot-go daemon starting... Nov 26 10:56:28 player-number-one go-librespot[15608]: time="2024-11-26T10:56:28+01:00" level=info msg="generated new device id: 0a0c0b6adf4afe083639186cba4e4b55cbb77719" Nov 26 10:56:28 player-number-one go-librespot[15608]: time="2024-11-26T10:56:28+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:28 player-number-one go-librespot[15608]: time="2024-11-26T10:56:28+01:00" level=debug msg="obtained new client token: AABrFLbRaVCP5F01y8Dspnmv0cYpvxvUICBOxuZs9xH/yXpHFTBpS5nzIsAbD6oPsv2G/iF9k1yWji7aMTsg9+dfUUd7+fWdYpSYE9y4h742VmseFWkzNHD+b/K6ydV/a3OdQmcuWYxN6iodKz655qELBYVwE64wCMzyH9inyN8vIzpOwCKHywXrqQwrsZMBFSI7ULOZ5JvnwVu2RhSdmulzKp9JBkkDWBpjAqukjjPDC2s2b03NXVO4FygiQ/wP" Nov 26 10:56:28 player-number-one go-librespot[15608]: time="2024-11-26T10:56:28+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:28 player-number-one go-librespot[15608]: time="2024-11-26T10:56:28+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:29 player-number-one go-librespot[15608]: time="2024-11-26T10:56:29+01:00" level=debug msg="completed challenge" Nov 26 10:56:29 player-number-one go-librespot[15608]: time="2024-11-26T10:56:29+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:29 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:29 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:30 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:30 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:32 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:32 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1729. Nov 26 10:56:32 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:32 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:32 player-number-one go-librespot[15634]: Librespot-go daemon starting... Nov 26 10:56:32 player-number-one go-librespot[15634]: time="2024-11-26T10:56:32+01:00" level=info msg="generated new device id: af0c58180d371b68d0c9d88d9e7a47685dfb2e64" Nov 26 10:56:32 player-number-one go-librespot[15634]: time="2024-11-26T10:56:32+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:32 player-number-one go-librespot[15634]: time="2024-11-26T10:56:32+01:00" level=debug msg="obtained new client token: AAAZlnmxtd2gMDWNsqRl4vluORUSCvxHtdcEgOUPpHHKv9FcFIbX/Rx8GL0X2xB9s0tKYzdh2bKQxnlYQQLSwHchkerMsxrWPFvANjWc7xoRva+yrGjEeurCf6PjZsAjBmyowNVs04oGhoPVCXfauBS0rF51Bd7MJZdf6g3O7aOq3d1DJYsBuCCE/qQJPwzCqj+ImcS+45jz4x+Av3dQ6gA2Up0rc0JHvbOsj3icgKAp74z42hL6zpgWb1Q5Q0K0" Nov 26 10:56:33 player-number-one go-librespot[15634]: time="2024-11-26T10:56:33+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:33 player-number-one go-librespot[15634]: time="2024-11-26T10:56:33+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:33 player-number-one go-librespot[15634]: time="2024-11-26T10:56:33+01:00" level=debug msg="completed challenge" Nov 26 10:56:33 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:33 player-number-one go-librespot[15634]: time="2024-11-26T10:56:33+01:00" level=debug msg="new websocket client" Nov 26 10:56:33 player-number-one volumio[851]: info: Connection to go-librespot Websocket established Nov 26 10:56:33 player-number-one go-librespot[15634]: time="2024-11-26T10:56:33+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:33 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:33 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:33 player-number-one volumio[851]: info: Connection to go-librespot Websocket closed Nov 26 10:56:34 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:34 player-number-one volumio[851]: info: Listing playlists Nov 26 10:56:34 player-number-one volumio[851]: info: Listing playlists Nov 26 10:56:36 player-number-one volumio[851]: info: Getting Spotify volume Nov 26 10:56:36 player-number-one volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:36 player-number-one volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 26 10:56:36 player-number-one volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 270) Nov 26 10:56:36 player-number-one volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 26 10:56:36 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:36 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:36 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:36 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:36 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:36 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1730. Nov 26 10:56:36 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:37 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:37 player-number-one go-librespot[15653]: Librespot-go daemon starting... Nov 26 10:56:37 player-number-one go-librespot[15653]: time="2024-11-26T10:56:37+01:00" level=info msg="generated new device id: 9ddcd8ec588eb0f94aa6072725e56782c4df5a38" Nov 26 10:56:37 player-number-one go-librespot[15653]: time="2024-11-26T10:56:37+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:37 player-number-one go-librespot[15653]: time="2024-11-26T10:56:37+01:00" level=debug msg="obtained new client token: AACSjO9IeqA45cztKdNSr0LOkZKsXfQHNlgof4AKF0X0ygPbzG7tXs9buhYy85bMqikJG+/ysYaZsAIBMnhe6ArqdTqxw3GiN8FIgEo8KGfSxN2MTQAOnEzdO0om11tukSRoZPD/u8zyv4KKgzV0dI9PHle3UhcdVmlZDav1xObqd1uV0j1zck5NC1xWTGSS/eAFg8SkRelrOhr9h7JJqbIXb2lrm4D/tVmhqJWHD5obP1HR2WR0ZjbWyc4LiLzv" Nov 26 10:56:37 player-number-one go-librespot[15653]: time="2024-11-26T10:56:37+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:37 player-number-one go-librespot[15653]: time="2024-11-26T10:56:37+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:38 player-number-one go-librespot[15653]: time="2024-11-26T10:56:38+01:00" level=debug msg="completed challenge" Nov 26 10:56:38 player-number-one go-librespot[15653]: time="2024-11-26T10:56:38+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:38 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:38 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:39 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:39 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:41 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:41 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1731. Nov 26 10:56:41 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:41 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:41 player-number-one go-librespot[15665]: Librespot-go daemon starting... Nov 26 10:56:41 player-number-one go-librespot[15665]: time="2024-11-26T10:56:41+01:00" level=info msg="generated new device id: 61d927050007350d8b7c61506520e5fc37b0778f" Nov 26 10:56:41 player-number-one go-librespot[15665]: time="2024-11-26T10:56:41+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:41 player-number-one go-librespot[15665]: time="2024-11-26T10:56:41+01:00" level=debug msg="obtained new client token: AACKYKiLgIwHUsLU8LUcD9fjise4dY3BXXuROYYfAcYh+TR594huq5/2ZmCiZbD4046fSomcJavkbFQLM2ui5jJSU6QAs5iWrdytnVssD3OWRcwGXgbv2G/4mQkZO7Bc5lzSHZjEynnL5mBFhl7qPMOnUK+Qrk+e8oyJqOSyzvpOiht1LHY3L+ovLTNf2Y8SZBQJiP5IkPo9uk40yzvI/5CNNn/jMU7EQ8IHTSfWGpjk2YjHC3Jz747zR4a3FRse" Nov 26 10:56:42 player-number-one go-librespot[15665]: time="2024-11-26T10:56:42+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:42 player-number-one go-librespot[15665]: time="2024-11-26T10:56:42+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:42 player-number-one go-librespot[15665]: time="2024-11-26T10:56:42+01:00" level=debug msg="completed challenge" Nov 26 10:56:42 player-number-one go-librespot[15665]: time="2024-11-26T10:56:42+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:42 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:42 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:42 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:42 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:44 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:45 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:45 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:45 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:45 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1732. Nov 26 10:56:45 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:45 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:45 player-number-one go-librespot[15698]: Librespot-go daemon starting... Nov 26 10:56:46 player-number-one go-librespot[15698]: time="2024-11-26T10:56:46+01:00" level=info msg="generated new device id: 6771dc9a091c4a8716c572a314e24af8d0b5396e" Nov 26 10:56:46 player-number-one go-librespot[15698]: time="2024-11-26T10:56:46+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:46 player-number-one go-librespot[15698]: time="2024-11-26T10:56:46+01:00" level=debug msg="obtained new client token: AAD466Q54zIEytLGB/vwGO/efR3g7a83LUE8L7x4pir9VMa88je5v0Q1FoUToqA6H552UudFbWxE/663AUJRIN21r2RYMbmi8+6nuI+KM7VAHWEwAn2UeudiMINEdnZArtTUJ8O1BMp4DskMxPziRJE4+eSywAKZ9HH7o7DshMZle0hoVJP1/Qh2jT7HT8mc5fO2wqPSDaJP8oGjDvebtXX2x87iAtvJ1dHZPjDGK6gJ6SMBqLWqiou2LDHEbEBs" Nov 26 10:56:46 player-number-one volumio[851]: error: Upnp client error: Error: This socket has been ended by the other party Nov 26 10:56:46 player-number-one go-librespot[15698]: time="2024-11-26T10:56:46+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:46 player-number-one go-librespot[15698]: time="2024-11-26T10:56:46+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:47 player-number-one go-librespot[15698]: time="2024-11-26T10:56:47+01:00" level=debug msg="completed challenge" Nov 26 10:56:47 player-number-one go-librespot[15698]: time="2024-11-26T10:56:47+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:47 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:47 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:48 player-number-one volumio[851]: info: Nov 26 10:56:48 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:48 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:48 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:48 player-number-one volumio[851]: info: sendMpdCommand status took 3 milliseconds Nov 26 10:56:48 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:48 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:48 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 3 milliseconds Nov 26 10:56:48 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:48 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:48 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:48 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:48 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:48 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:48 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:48 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:48 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"stop","position":1,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"T?rez Montcalm - Sweet Dreams","artist":"FluffyPinkUnicorns","album":null,"uri":"http://192.168.10.105:8001/stream","trackType":""} Nov 26 10:56:48 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:48 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService stop Nov 26 10:56:48 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus play Nov 26 10:56:48 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:48 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:48 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:48 player-number-one volumio[851]: info: CoreStateMachine::stPlaybackTimer Nov 26 10:56:48 player-number-one volumio[851]: info: ------------------------------ 41ms Nov 26 10:56:48 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:48 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:48 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:48 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:50 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:50 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1733. Nov 26 10:56:50 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:50 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:50 player-number-one go-librespot[15732]: Librespot-go daemon starting... Nov 26 10:56:50 player-number-one go-librespot[15732]: time="2024-11-26T10:56:50+01:00" level=info msg="generated new device id: e8bd0b6e325a562a05d744487779c97a1e141bf2" Nov 26 10:56:50 player-number-one go-librespot[15732]: time="2024-11-26T10:56:50+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:50 player-number-one volumio[851]: info: Clearing queue after UPNP request Nov 26 10:56:50 player-number-one volumio[851]: info: CoreStateMachine::ClearQueue Nov 26 10:56:50 player-number-one volumio[851]: info: CoreStateMachine::stop Nov 26 10:56:50 player-number-one volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 26 10:56:50 player-number-one volumio[851]: info: CorePlayQueue::clearPlayQueue Nov 26 10:56:50 player-number-one volumio[851]: info: CorePlayQueue::saveQueue Nov 26 10:56:50 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:50 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:50 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:50 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushQueue Nov 26 10:56:50 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:50 player-number-one volumio[851]: info: Nov 26 10:56:50 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:50 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:50 player-number-one volumio[851]: error: updateQueue error: null Nov 26 10:56:50 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:56:50 player-number-one volumio[851]: info: Starting UPNP Playback Nov 26 10:56:50 player-number-one volumio[851]: info: Preparing playback through UPNP Nov 26 10:56:50 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:50 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:50 player-number-one volumio[851]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 26 10:56:50 player-number-one go-librespot[15732]: time="2024-11-26T10:56:50+01:00" level=debug msg="obtained new client token: AAD6PVIJbljwbFGabT6Frht8iRsE/Xtf4kyvYYPEK4gH8l5MGZvNp9uSrBB/qm/z82f1cjSEk+JdbfJ3Wv5DXngpSMLYhwRiCI5kaBtsDdGHfmlQ/aKNhS++ik1G8ukbTQtWDuuOc2TG2LXB1z8bKPuSEPgBiCQpK4WjV3X4sfr31etHbQgXUqzhF//hxeR4l6VJqG8iRtiXxcw+cr7iEEZMiZfs8kZHg+jTHQ0U7dDd0VgOLIA6+x6AS0lIL3yr" Nov 26 10:56:51 player-number-one go-librespot[15732]: time="2024-11-26T10:56:51+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:51 player-number-one go-librespot[15732]: time="2024-11-26T10:56:51+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:51 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:51 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:51 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:51 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 4ms Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:51 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:51 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 4ms Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:56:51 player-number-one volumio[851]: info: Nov 26 10:56:51 player-number-one volumio[851]: ---------------------------- MPD announces state update: options Nov 26 10:56:51 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:51 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:51 player-number-one volumio[851]: info: sendMpdCommand status took 2 milliseconds Nov 26 10:56:51 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:51 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:51 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:51 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:51 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 10:56:51 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:51 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:51 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:51 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:51 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"stop","position":null,"seek":null,"duration":null,"samplerate":null,"bitdepth":null,"channels":null,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":null,"artist":null,"album":null,"uri":null} Nov 26 10:56:51 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:51 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService stop Nov 26 10:56:51 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus stop Nov 26 10:56:51 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:51 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:51 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:51 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:51 player-number-one volumio[851]: info: No code Nov 26 10:56:51 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:51 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:51 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:51 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:51 player-number-one volumio[851]: info: ------------------------------ 44ms Nov 26 10:56:51 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:51 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:51 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:51 player-number-one go-librespot[15732]: time="2024-11-26T10:56:51+01:00" level=debug msg="completed challenge" Nov 26 10:56:51 player-number-one go-librespot[15732]: time="2024-11-26T10:56:51+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:51 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:51 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:51 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:51 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:52 player-number-one volumio[851]: info: Nov 26 10:56:52 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:52 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:52 player-number-one volumio[851]: info: Nov 26 10:56:52 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:52 player-number-one volumio[851]: info: sendMpdCommand status took 7 milliseconds Nov 26 10:56:52 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:52 player-number-one volumio[851]: info: sendMpdCommand status took 3 milliseconds Nov 26 10:56:52 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 3 milliseconds Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:52 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:52 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:52 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:52 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"321099e2ac2d41ecbad2c9cd366ba66f.mp3?ts=1732615006","artist":null,"album":" Home Assistant","uri":"http://192.168.10.146:8097/flow/media_player.openhome_uuid_1d96b190_8115_a528_329f_b827ebac4151/321099e2ac2d41ecbad2c9cd366ba66f.mp3?ts=1732615006","trackType":""} Nov 26 10:56:52 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus stop Nov 26 10:56:52 player-number-one volumio[851]: info: ------------------------------ 18ms Nov 26 10:56:52 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 5 milliseconds Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:52 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:52 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:52 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:52 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"321099e2ac2d41ecbad2c9cd366ba66f.mp3?ts=1732615006","artist":null,"album":" Home Assistant","uri":"http://192.168.10.146:8097/flow/media_player.openhome_uuid_1d96b190_8115_a528_329f_b827ebac4151/321099e2ac2d41ecbad2c9cd366ba66f.mp3?ts=1732615006","trackType":""} Nov 26 10:56:52 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus play Nov 26 10:56:52 player-number-one volumio[851]: info: Received an update from plugin. extracting info from payload Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:52 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:52 player-number-one volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 26 10:56:52 player-number-one volumio[851]: info: ------------------------------ 20ms Nov 26 10:56:52 player-number-one volumio[851]: info: Nov 26 10:56:52 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:52 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:52 player-number-one volumio[851]: info: Nov 26 10:56:52 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:52 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:52 player-number-one volumio[851]: info: ------------------------------ 5ms Nov 26 10:56:52 player-number-one volumio[851]: info: sendMpdCommand status took 3 milliseconds Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:52 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 2 milliseconds Nov 26 10:56:52 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:52 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:52 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:52 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:52 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":262,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"321099e2ac2d41ecbad2c9cd366ba66f.mp3?ts=1732615006","artist":"Music Assistant","album":null,"uri":"http://192.168.10.146:8097/flow/media_player.openhome_uuid_1d96b190_8115_a528_329f_b827ebac4151/321099e2ac2d41ecbad2c9cd366ba66f.mp3?ts=1732615006","trackType":""} Nov 26 10:56:52 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus play Nov 26 10:56:52 player-number-one volumio[851]: info: Received an update from plugin. extracting info from payload Nov 26 10:56:52 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 26 10:56:52 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:52 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:52 player-number-one volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 26 10:56:52 player-number-one volumio[851]: info: ------------------------------ 17ms Nov 26 10:56:53 player-number-one volumio[851]: info: Executing endpoint metavolumio Nov 26 10:56:53 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 26 10:56:53 player-number-one volumio[851]: info: Executing endpoint metavolumio Nov 26 10:56:53 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: metavolumio , requestToMetaVolumio Nov 26 10:56:54 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:54 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:54 player-number-one volumio[851]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Nov 26 10:56:54 player-number-one volumio[851]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 26 10:56:54 player-number-one volumio[851]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 26 10:56:54 player-number-one volumio[851]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Nov 26 10:56:54 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:56:54 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Nov 26 10:56:54 player-number-one volumio[851]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Nov 26 10:56:54 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:56:54 player-number-one volumio[851]: at /volumio/node_modules/express/lib/router/index.js:281:22 Nov 26 10:56:54 player-number-one volumio[851]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 26 10:56:54 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 26 10:56:54 player-number-one volumio[851]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Nov 26 10:56:54 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:56:54 player-number-one volumio[851]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Nov 26 10:56:54 player-number-one volumio[851]: at /volumio/node_modules/express/lib/router/index.js:284:7 Nov 26 10:56:54 player-number-one volumio[851]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 26 10:56:54 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 26 10:56:54 player-number-one volumio[851]: info: Listing playlists Nov 26 10:56:54 player-number-one volumio[851]: info: Listing playlists Nov 26 10:56:54 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:54 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:54 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:54 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1734. Nov 26 10:56:54 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:55 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:55 player-number-one go-librespot[15780]: Librespot-go daemon starting... Nov 26 10:56:55 player-number-one go-librespot[15780]: time="2024-11-26T10:56:55+01:00" level=info msg="generated new device id: 4ac5a5ac9bb3371795ae5fed40b5eec67c27ff84" Nov 26 10:56:55 player-number-one go-librespot[15780]: time="2024-11-26T10:56:55+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:55 player-number-one go-librespot[15780]: time="2024-11-26T10:56:55+01:00" level=debug msg="obtained new client token: AADpWfrj98OTfoEHEQrZcwc7izw9F8G6BD0TGTGdZyZgP3nsgBfZImlR31G2Kl+67kbvSAQHHLsIK5MVjKpr3Onp19QKqjDS1TdlxH/5cGsLbMaW5khuzaBxcsogOvzZbJb7TYSVfauVFkQQpGTsYphf0p82mQUU3dgX2fAO9MAki1dzSLCoRo+keW6gKWK5XlnxlLpyAeZKHiSi3ErRrnVShshgWVCGhBEu1GEJyFuzxFND83SVF0LinZ6iPnlR" Nov 26 10:56:55 player-number-one go-librespot[15780]: time="2024-11-26T10:56:55+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:56:55 player-number-one go-librespot[15780]: time="2024-11-26T10:56:55+01:00" level=debug msg="completed keyexchange" Nov 26 10:56:56 player-number-one go-librespot[15780]: time="2024-11-26T10:56:56+01:00" level=debug msg="completed challenge" Nov 26 10:56:56 player-number-one go-librespot[15780]: time="2024-11-26T10:56:56+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:56:56 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:56:56 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:56:56 player-number-one volumio[851]: info: Nov 26 10:56:56 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:56 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:56 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:56 player-number-one volumio[851]: info: sendMpdCommand status took 2 milliseconds Nov 26 10:56:56 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:56 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:56 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 2 milliseconds Nov 26 10:56:56 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:56 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:56 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:56 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:56 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:56 player-number-one volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 26 10:56:56 player-number-one volumio[851]: info: ------------------------------ 12ms Nov 26 10:56:56 player-number-one volumiologrotate[602]: ls: cannot access '/var/log/samba/log.wb-PLAYER': No such file or directory Nov 26 10:56:56 player-number-one volumiologrotate[602]: ls: cannot access 'NUMBER': No such file or directory Nov 26 10:56:56 player-number-one volumiologrotate[602]: ls: cannot access 'ONE': No such file or directory Nov 26 10:56:57 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:56:57 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:56:58 player-number-one volumio[851]: info: Clearing queue after UPNP request Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::ClearQueue Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::stop Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::stPlaybackTimer Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::updateTrackBlock Nov 26 10:56:58 player-number-one volumio[851]: info: CorePlayQueue::getTrackBlock Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:58 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:58 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Nov 26 10:56:58 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:58 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:58 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::serviceStop Nov 26 10:56:58 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:58 player-number-one volumio[851]: info: ControllerMpd::stop Nov 26 10:56:58 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand stop Nov 26 10:56:58 player-number-one volumio[851]: info: CorePlayQueue::clearPlayQueue Nov 26 10:56:58 player-number-one volumio[851]: info: CorePlayQueue::saveQueue Nov 26 10:56:58 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:56:58 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:56:58 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:56:58 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushQueue Nov 26 10:56:58 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:58 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:56:58 player-number-one volumio[851]: info: Nov 26 10:56:58 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:58 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:58 player-number-one volumio[851]: info: sendMpdCommand stop took 32 milliseconds Nov 26 10:56:58 player-number-one volumio[851]: error: updateQueue error: null Nov 26 10:56:58 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:56:58 player-number-one volumio[851]: info: Starting UPNP Playback Nov 26 10:56:58 player-number-one volumio[851]: info: Preparing playback through UPNP Nov 26 10:56:58 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:56:58 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:58 player-number-one volumio[851]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 26 10:56:58 player-number-one volumio[851]: error: Failed request for metavolumio API Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 1ms Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 1ms Nov 26 10:56:59 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:56:59 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1735. Nov 26 10:56:59 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:56:59 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:56:59 player-number-one go-librespot[15870]: Librespot-go daemon starting... Nov 26 10:56:59 player-number-one go-librespot[15870]: time="2024-11-26T10:56:59+01:00" level=info msg="generated new device id: f3004afa1609b4ecfcfe61868075ddc4073ff0a2" Nov 26 10:56:59 player-number-one go-librespot[15870]: time="2024-11-26T10:56:59+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:59 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:59 player-number-one volumio[851]: info: sendMpdCommand status took 4 milliseconds Nov 26 10:56:59 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:59 player-number-one volumio[851]: info: sendMpdCommand status took 3 milliseconds Nov 26 10:56:59 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 3 milliseconds Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:59 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:59 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:59 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:59 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"6c0229d427444b3fb5428e163efba513.mp3?ts=1732615016","artist":null,"album":" Home Assistant","uri":"http://192.168.10.146:8097/flow/media_player.openhome_uuid_1d96b190_8115_a528_329f_b827ebac4151/6c0229d427444b3fb5428e163efba513.mp3?ts=1732615016","trackType":""} Nov 26 10:56:59 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus stop Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 18ms Nov 26 10:56:59 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 5 milliseconds Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:59 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:59 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:59 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:59 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"6c0229d427444b3fb5428e163efba513.mp3?ts=1732615016","artist":null,"album":" Home Assistant","uri":"http://192.168.10.146:8097/flow/media_player.openhome_uuid_1d96b190_8115_a528_329f_b827ebac4151/6c0229d427444b3fb5428e163efba513.mp3?ts=1732615016","trackType":""} Nov 26 10:56:59 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus play Nov 26 10:56:59 player-number-one volumio[851]: info: Received an update from plugin. extracting info from payload Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:59 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:59 player-number-one volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 19ms Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:56:59 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:56:59 player-number-one volumio[851]: info: Nov 26 10:56:59 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:56:59 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 4ms Nov 26 10:56:59 player-number-one volumio[851]: info: sendMpdCommand status took 4 milliseconds Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:56:59 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 1 milliseconds Nov 26 10:56:59 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:56:59 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:56:59 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:56:59 player-number-one volumio[851]: verbose: In UPNP mode Nov 26 10:56:59 player-number-one volumio[851]: verbose: STATE SERVICE {"status":"play","position":0,"seek":1112,"duration":0,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"320 Kbps","isStreaming":false,"title":"6c0229d427444b3fb5428e163efba513.mp3?ts=1732615016","artist":"Music Assistant","album":null,"uri":"http://192.168.10.146:8097/flow/media_player.openhome_uuid_1d96b190_8115_a528_329f_b827ebac4151/6c0229d427444b3fb5428e163efba513.mp3?ts=1732615016","trackType":""} Nov 26 10:56:59 player-number-one volumio[851]: verbose: CURRENT POSITION 0 Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::syncState stateService play Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::syncState currentStatus play Nov 26 10:56:59 player-number-one volumio[851]: info: Received an update from plugin. extracting info from payload Nov 26 10:56:59 player-number-one volumio[851]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Nov 26 10:56:59 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:56:59 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:56:59 player-number-one volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 26 10:56:59 player-number-one volumio[851]: info: ------------------------------ 14ms Nov 26 10:56:59 player-number-one go-librespot[15870]: time="2024-11-26T10:56:59+01:00" level=debug msg="obtained new client token: AABotaiYJzKhXl3bWZZtK4DJOHIavxMAn5h/4R0RHG/vsiJ/N57p3P2myERHidEuzoozQ8eOAbrc17Tj0/gKeraP3jYJbZbtcj4FWRTFJ/tHuBC/xr1M02BjBZ9VxpZI0O34y8A1U9lBIu0gQJp1KmPFJPDbpZK0Vv+kHbWsPjdXs1l1UtEpbFVXVVfg0plX2sLws6/qPI0bk66T+RFscmIXtCBRst/A5PkrGs7C/ENQJ2RF0mcth6gIOdrBz4ni" Nov 26 10:57:00 player-number-one go-librespot[15870]: time="2024-11-26T10:57:00+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:57:00 player-number-one go-librespot[15870]: time="2024-11-26T10:57:00+01:00" level=debug msg="completed keyexchange" Nov 26 10:57:00 player-number-one go-librespot[15870]: time="2024-11-26T10:57:00+01:00" level=debug msg="completed challenge" Nov 26 10:57:00 player-number-one go-librespot[15870]: time="2024-11-26T10:57:00+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:57:00 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:57:00 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:57:00 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:57:00 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:57:03 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:57:03 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:57:03 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:57:03 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1736. Nov 26 10:57:03 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:57:03 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:57:03 player-number-one go-librespot[15892]: Librespot-go daemon starting... Nov 26 10:57:04 player-number-one go-librespot[15892]: time="2024-11-26T10:57:04+01:00" level=info msg="generated new device id: 1993369a5ad6fdf705b73e082a3cbdaf527bde69" Nov 26 10:57:04 player-number-one go-librespot[15892]: time="2024-11-26T10:57:04+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:57:04 player-number-one go-librespot[15892]: time="2024-11-26T10:57:04+01:00" level=debug msg="obtained new client token: AABAbWyvg90dKJ2buPJX8FeB/4k0DX9jI1EdBBgnLnwyhjA35ZPqJ2JEqF43rv8OYbUnnZ+PsTaH5a7iYosHWKoCX62DtRHU6cqLvjQKGRp9XWDza4T6b/KUr70OdhKhSYkYcmVJVlfZmo9v82/Ry/poBxxP/D5LehYYqt3Ouxl55LfvpzNiEAyjfD9E1W4oh/eTJuIL6jbSA0YFLozue5zHYmUzPekaet01Hqm/gjj4Q1Qn2sAJxVl+UAx6XNM7" Nov 26 10:57:04 player-number-one volumio[851]: info: Nov 26 10:57:04 player-number-one volumio[851]: ---------------------------- MPD announces state update: player Nov 26 10:57:04 player-number-one volumio[851]: info: ControllerMpd::getState Nov 26 10:57:04 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand status Nov 26 10:57:04 player-number-one volumio[851]: info: sendMpdCommand status took 3 milliseconds Nov 26 10:57:04 player-number-one volumio[851]: verbose: ControllerMpd::parseState Nov 26 10:57:04 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand playlistinfo Nov 26 10:57:04 player-number-one volumio[851]: info: sendMpdCommand playlistinfo took 2 milliseconds Nov 26 10:57:04 player-number-one volumio[851]: verbose: ControllerMpd::parseTrackInfo Nov 26 10:57:04 player-number-one volumio[851]: info: ControllerMpd::pushState Nov 26 10:57:04 player-number-one volumio[851]: info: CoreCommandRouter::servicePushState Nov 26 10:57:04 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:57:04 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:04 player-number-one volumio[851]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Nov 26 10:57:04 player-number-one volumio[851]: info: ------------------------------ 16ms Nov 26 10:57:04 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:57:04 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:04 player-number-one volumio[851]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Nov 26 10:57:04 player-number-one volumio[851]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 26 10:57:04 player-number-one volumio[851]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 26 10:57:04 player-number-one volumio[851]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Nov 26 10:57:04 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:57:04 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Nov 26 10:57:04 player-number-one volumio[851]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Nov 26 10:57:04 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:57:04 player-number-one volumio[851]: at /volumio/node_modules/express/lib/router/index.js:281:22 Nov 26 10:57:04 player-number-one volumio[851]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 26 10:57:04 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 26 10:57:04 player-number-one volumio[851]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Nov 26 10:57:04 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:57:04 player-number-one volumio[851]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Nov 26 10:57:04 player-number-one volumio[851]: at /volumio/node_modules/express/lib/router/index.js:284:7 Nov 26 10:57:04 player-number-one volumio[851]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 26 10:57:04 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 26 10:57:04 player-number-one go-librespot[15892]: time="2024-11-26T10:57:04+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:57:04 player-number-one go-librespot[15892]: time="2024-11-26T10:57:04+01:00" level=debug msg="completed keyexchange" Nov 26 10:57:05 player-number-one go-librespot[15892]: time="2024-11-26T10:57:05+01:00" level=debug msg="completed challenge" Nov 26 10:57:05 player-number-one go-librespot[15892]: time="2024-11-26T10:57:05+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:57:05 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:57:05 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:57:06 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:57:06 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:57:08 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:57:08 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1737. Nov 26 10:57:08 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:57:08 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:57:08 player-number-one go-librespot[15931]: Librespot-go daemon starting... Nov 26 10:57:08 player-number-one go-librespot[15931]: time="2024-11-26T10:57:08+01:00" level=info msg="generated new device id: 8188bac0044b7b32cf337823a238bf261853fb27" Nov 26 10:57:08 player-number-one go-librespot[15931]: time="2024-11-26T10:57:08+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:57:08 player-number-one go-librespot[15931]: time="2024-11-26T10:57:08+01:00" level=debug msg="obtained new client token: AAAEqP9idhrQfreJvqTrFKtW5ouhsNb23F8KoNLStl8nfY6W2EzmtsGFUJJY0EB+A8o9LXFJ1zN6xNFIWSRpYZh/3xkw4J+fDl1Vt+f+YkQm7wZE0JqWq6tmD+9+zwX4i7YXfu8lI/zk9qrRXxWp3tAWXW+A0WclHfmo1MYOH7mbb3i2yqV/xLLHqwWP+cO8VLoAc+zV09EQ5xap8w2vuyGa4mzGxJn2J2iQX5u2FZgNWpAFbbsnUPxMn6mlnZxb" Nov 26 10:57:09 player-number-one go-librespot[15931]: time="2024-11-26T10:57:09+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Nov 26 10:57:09 player-number-one go-librespot[15931]: time="2024-11-26T10:57:09+01:00" level=fatal msg="failed running with username and spotify token" error="failed initializing accesspoint: failed dialing accesspoint: dial tcp 34.158.1.133:4070: connect: connection refused" Nov 26 10:57:09 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:57:09 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:57:09 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:57:09 player-number-one volumio[851]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:57:10 player-number-one volumio[851]: info: Clearing queue after UPNP request Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::ClearQueue Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::stop Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::setConsumeUpdateService undefined Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::stPlaybackTimer Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::updateTrackBlock Nov 26 10:57:11 player-number-one volumio[851]: info: CorePlayQueue::getTrackBlock Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::pushState Nov 26 10:57:11 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:11 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:57:11 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:57:11 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::serviceStop Nov 26 10:57:11 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:11 player-number-one volumio[851]: info: ControllerMpd::stop Nov 26 10:57:11 player-number-one volumio[851]: verbose: ControllerMpd::sendMpdCommand stop Nov 26 10:57:11 player-number-one volumio[851]: info: CorePlayQueue::clearPlayQueue Nov 26 10:57:11 player-number-one volumio[851]: info: CorePlayQueue::saveQueue Nov 26 10:57:11 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushState Nov 26 10:57:11 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output update for this device Nov 26 10:57:11 player-number-one volumio[851]: info: MRS: Pushing multiroomSync output Nov 26 10:57:11 player-number-one volumio[851]: info: CoreCommandRouter::volumioPushQueue Nov 26 10:57:11 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:57:11 player-number-one volumio[851]: SPOTIFY: RECEIVED VOLUMIO VOLUME 47 Nov 26 10:57:11 player-number-one volumio[851]: info: sendMpdCommand stop took 46 milliseconds Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: error: updateQueue error: null Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:57:11 player-number-one volumio[851]: info: Starting UPNP Playback Nov 26 10:57:11 player-number-one volumio[851]: info: Preparing playback through UPNP Nov 26 10:57:11 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:57:11 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:11 player-number-one volumio[851]: info: CoreStateMachine::setConsumeUpdateService mpd Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 3ms Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:57:11 player-number-one volumio[851]: info: Nov 26 10:57:11 player-number-one volumio[851]: ---------------------------- MPD announces system playlist update Nov 26 10:57:11 player-number-one volumio[851]: info: Ignoring MPD Status Update Nov 26 10:57:11 player-number-one volumio[851]: info: ------------------------------ 2ms Nov 26 10:57:12 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:57:12 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1738. Nov 26 10:57:12 player-number-one systemd[1]: Stopped go-librespot Daemon. Nov 26 10:57:12 player-number-one systemd[1]: Started go-librespot Daemon. Nov 26 10:57:12 player-number-one go-librespot[15973]: Librespot-go daemon starting... Nov 26 10:57:12 player-number-one go-librespot[15973]: time="2024-11-26T10:57:12+01:00" level=info msg="generated new device id: 57cbb6534eaad77707aa970d3e65fbc59072260e" Nov 26 10:57:12 player-number-one go-librespot[15973]: time="2024-11-26T10:57:12+01:00" level=debug msg="stored credentials found for olterman" Nov 26 10:57:12 player-number-one go-librespot[15973]: time="2024-11-26T10:57:12+01:00" level=debug msg="obtained new client token: AAD4Ae4KRI7Ayopd5ohuaug2V2IgZWhpERGASpg65mnTd7dggSca36fo27E6EBH6rhFYgWKPMF7Ejc8DtMB8ZMvlTHDbNHFvNVaUxf9QQmOLFWv7Ilf7zdzqXb5U8uYYKL0hY8+M+OiKHDTS5Lobjf6RHd+X2SrDTHE5lDiTZt7TYreS0mBTUTOUySRAr1kmNVZYs0DKfiwlgBRLc6MmgKMyKin5XnuLjokRtx6FiEF87PSgL0ewiuOVMHTe8V5G" Nov 26 10:57:12 player-number-one go-librespot[15973]: time="2024-11-26T10:57:12+01:00" level=debug msg="fetched new accesspoints: [ap-gew4.spotify.com:4070 ap-gew4.spotify.com:443 ap-gew4.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Nov 26 10:57:12 player-number-one volumio[851]: info: Initializing connection to go-librespot Websocket Nov 26 10:57:12 player-number-one go-librespot[15973]: time="2024-11-26T10:57:12+01:00" level=debug msg="new websocket client" Nov 26 10:57:12 player-number-one volumio[851]: info: Connection to go-librespot Websocket established Nov 26 10:57:13 player-number-one go-librespot[15973]: time="2024-11-26T10:57:13+01:00" level=debug msg="completed keyexchange" Nov 26 10:57:13 player-number-one go-librespot[15973]: time="2024-11-26T10:57:13+01:00" level=debug msg="completed challenge" Nov 26 10:57:13 player-number-one go-librespot[15973]: time="2024-11-26T10:57:13+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Nov 26 10:57:13 player-number-one systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Nov 26 10:57:13 player-number-one systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Nov 26 10:57:13 player-number-one volumio[851]: info: Connection to go-librespot Websocket closed Nov 26 10:57:14 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:57:14 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:14 player-number-one volumio[851]: An internal error occurred while serving an albumart. Details: TypeError: Cannot read property 'name' of undefined Nov 26 10:57:14 player-number-one volumio[851]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 26 10:57:14 player-number-one volumio[851]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 26 10:57:14 player-number-one volumio[851]: at RESTApiPlayback.playbackGetState (/volumio/app/plugins/user_interface/rest_api/playback.js:262:37) Nov 26 10:57:14 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:57:14 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/route.js:137:13) Nov 26 10:57:14 player-number-one volumio[851]: at Route.dispatch (/volumio/node_modules/express/lib/router/route.js:112:3) Nov 26 10:57:14 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:57:14 player-number-one volumio[851]: at /volumio/node_modules/express/lib/router/index.js:281:22 Nov 26 10:57:14 player-number-one volumio[851]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 26 10:57:14 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 26 10:57:14 player-number-one volumio[851]: at jsonParser (/volumio/node_modules/body-parser/lib/types/json.js:110:7) Nov 26 10:57:14 player-number-one volumio[851]: at Layer.handle [as handle_request] (/volumio/node_modules/express/lib/router/layer.js:95:5) Nov 26 10:57:14 player-number-one volumio[851]: at trim_prefix (/volumio/node_modules/express/lib/router/index.js:317:13) Nov 26 10:57:14 player-number-one volumio[851]: at /volumio/node_modules/express/lib/router/index.js:284:7 Nov 26 10:57:14 player-number-one volumio[851]: at Function.process_params (/volumio/node_modules/express/lib/router/index.js:335:12) Nov 26 10:57:14 player-number-one volumio[851]: at next (/volumio/node_modules/express/lib/router/index.js:275:10) Nov 26 10:57:14 player-number-one volumio[851]: info: Listing playlists Nov 26 10:57:14 player-number-one volumio[851]: info: Listing playlists Nov 26 10:57:15 player-number-one volumio[851]: info: Getting Spotify volume Nov 26 10:57:15 player-number-one volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Nov 26 10:57:15 player-number-one volumio[851]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Nov 26 10:57:15 player-number-one volumio[851]: (node:851) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 271) Nov 26 10:57:15 player-number-one volumio[851]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9 Nov 26 10:57:15 player-number-one volumio[851]: info: CoreCommandRouter::volumioGetState Nov 26 10:57:15 player-number-one volumio[851]: info: CorePlayQueue::getTrack 0 Nov 26 10:57:15 player-number-one volumio[851]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 26 10:57:15 player-number-one volumio[851]: TypeError: Cannot read property 'name' of undefined Nov 26 10:57:15 player-number-one volumio[851]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Nov 26 10:57:15 player-number-one volumio[851]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:109:28) Nov 26 10:57:15 player-number-one volumio[851]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Nov 26 10:57:15 player-number-one volumio[851]: at Socket.emit (events.js:315:20) Nov 26 10:57:15 player-number-one volumio[851]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Nov 26 10:57:15 player-number-one volumio[851]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Nov 26 10:57:15 player-number-one volumio[851]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Nov 26 10:57:16 player-number-one sudo[16002]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-26 10:56 Nov 26 10:57:16 player-number-one sudo[16002]: pam_unix(sudo:session): session opened for user root by (uid=0) Nov 26 10:57:16 player-number-one systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Nov 26 10:57:16 player-number-one systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1739. Nov 26 10:57:16 player-number-one systemd[1]: Stopped go-librespot Daemon. 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"