-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Fri 2024-08-23 15:01:04 CEST. -- Aug 23 15:00:25 volumio volumio[861]: info: Aug 23 15:00:25 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:25 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:25 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:25 volumio volumio[861]: info: Aug 23 15:00:25 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:25 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:25 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:25 volumio volumio[861]: info: Aug 23 15:00:25 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:25 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:25 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:25 volumio volumio[861]: info: sendMpdCommand status took 7 milliseconds Aug 23 15:00:25 volumio volumio[861]: info: sendMpdCommand status took 5 milliseconds Aug 23 15:00:25 volumio volumio[861]: info: sendMpdCommand status took 3 milliseconds Aug 23 15:00:25 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:25 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:25 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:25 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:25 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:25 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:25 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:25 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:25 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:25 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:25 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:25 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:25 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:25 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:25 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:25 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:25 volumio volumio[861]: info: ------------------------------ 26ms Aug 23 15:00:25 volumio volumio[861]: info: ------------------------------ 22ms Aug 23 15:00:25 volumio volumio[861]: info: ------------------------------ 19ms Aug 23 15:00:30 volumio go-librespot[2314]: time="2024-08-23T15:00:30+02:00" level=error msg="did not receive last pong ack from accesspoint, 120s passed" Aug 23 15:00:30 volumio go-librespot[2314]: time="2024-08-23T15:00:30+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed performing keyexchange: failed reading APResponseMessage message: failed reading message length: read tcp 192.168.178.43:34274->34.158.0.131:4070: use of closed network connection" Aug 23 15:00:30 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:30 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:30 volumio volumio[861]: (node:861) UnhandledPromiseRejectionWarning: Error: socket hang up Aug 23 15:00:30 volumio volumio[861]: at connResetException (internal/errors.js:607:14) Aug 23 15:00:30 volumio volumio[861]: at Socket.socketOnEnd (_http_client.js:493:23) Aug 23 15:00:30 volumio volumio[861]: at Socket.emit (events.js:327:22) Aug 23 15:00:30 volumio volumio[861]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 23 15:00:30 volumio volumio[861]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 23 15:00:30 volumio volumio[861]: (node:861) 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: 33) Aug 23 15:00:30 volumio volumio[861]: info: Connection to go-librespot Websocket closed Aug 23 15:00:33 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:33 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:33 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:00:33 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 98. Aug 23 15:00:33 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:00:33 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:00:33 volumio go-librespot[2952]: Librespot-go daemon starting... Aug 23 15:00:33 volumio go-librespot[2952]: time="2024-08-23T15:00:33+02:00" level=info msg="generated new device id: 222d92e342b7e774a3daf3e1ea1752ee772be1e9" Aug 23 15:00:33 volumio go-librespot[2952]: time="2024-08-23T15:00:33+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:00:33 volumio go-librespot[2952]: time="2024-08-23T15:00:33+02:00" level=debug msg="obtained new client token: AAAGpGEnw2vG83kdXnvmvo/BUxFAh7N+Ul5z5uqo9C+6yGzlvIC3DgEmWq/coLukfViJZ+w4S9VFzIM1gSJt/ngVDBO2a8quuzHpquVr3RFg+Uq7o3/8ttXWfjCu0+bQRCw5ZIAn0/+acGqns5KuIxL+PCROw+yBAsBcme7VGKb9qODBAXqUs2Fvn/rRBIuHbu8KT8VIljODW0A/4TPrAae992IEnE1srPw25lZiP/5+jX+2xW4JmFi+rUCYtS4=" Aug 23 15:00:34 volumio go-librespot[2952]: time="2024-08-23T15:00:34+02: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]" Aug 23 15:00:34 volumio go-librespot[2952]: time="2024-08-23T15:00:34+02:00" level=debug msg="completed keyexchange" Aug 23 15:00:34 volumio go-librespot[2952]: time="2024-08-23T15:00:34+02:00" level=debug msg="completed challenge" Aug 23 15:00:34 volumio go-librespot[2952]: time="2024-08-23T15:00:34+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:00:34 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:34 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:36 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:36 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:37 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:00:37 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 99. Aug 23 15:00:37 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:00:37 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:00:37 volumio go-librespot[2960]: Librespot-go daemon starting... Aug 23 15:00:37 volumio go-librespot[2960]: time="2024-08-23T15:00:37+02:00" level=info msg="generated new device id: 934e9a46ce693a03d294bb64c27a3d47b85c0e52" Aug 23 15:00:37 volumio go-librespot[2960]: time="2024-08-23T15:00:37+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:00:38 volumio go-librespot[2960]: time="2024-08-23T15:00:38+02:00" level=debug msg="obtained new client token: AABWc9ghiN6g75TyEe2O7j9pErGso4+KQv79jOk3PGsChAWY9Sbvkv8UZGOr4DU248qDiPxKUvBdPup5fBHtY35lFr5ZSaOMpChbxC7Rvt50TBFr0u4YSH5lrlmrA8TLnkQnzuzu79+67T1LWQiIBy4MtkqqxeGX7mOgDPhWUPGXjl8p4noUo62GccrrHY72/slHoZYR8Dd8OLg9RzZvWKZ8Z/PgtQXVm7iE51aohPq0XFk/IG/shFSd/dWEbBY=" Aug 23 15:00:38 volumio go-librespot[2960]: time="2024-08-23T15:00:38+02: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]" Aug 23 15:00:38 volumio go-librespot[2960]: time="2024-08-23T15:00:38+02:00" level=debug msg="completed keyexchange" Aug 23 15:00:39 volumio go-librespot[2960]: time="2024-08-23T15:00:39+02:00" level=debug msg="completed challenge" Aug 23 15:00:39 volumio go-librespot[2960]: time="2024-08-23T15:00:39+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:00:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:39 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:39 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:42 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:42 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:00:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 100. Aug 23 15:00:42 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:00:42 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:00:42 volumio go-librespot[2969]: Librespot-go daemon starting... Aug 23 15:00:42 volumio go-librespot[2969]: time="2024-08-23T15:00:42+02:00" level=info msg="generated new device id: d973bf33a1e801d2e300e7811b426b424092b480" Aug 23 15:00:42 volumio go-librespot[2969]: time="2024-08-23T15:00:42+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:00:42 volumio go-librespot[2969]: time="2024-08-23T15:00:42+02:00" level=debug msg="obtained new client token: AAB0GpyE0EpdTF9M0RDHYM8j62ptz4xYSAeGvzcIwSKLJB3YWj3tgQLSmrTOO4XOBpPWonDR9G7RKvW7nTUBJPVX7gl9zdnq2XyZ4c0gZvCkXLnfnM8+JCX4XNqkBnot6Ej8CkLIQ84Rq2nWvTXXrWDZD+6PT49cZ2QSRaLUjC/Rq3hzdsdM0cM1g8pcQ+GRxRFBXRkrmCyoRY797MSPqgmOEkxzYhrFQu3sxKTLGblSTO69NtS/W0FnFaxS/SA=" Aug 23 15:00:42 volumio go-librespot[2969]: time="2024-08-23T15:00:42+02: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]" Aug 23 15:00:43 volumio go-librespot[2969]: time="2024-08-23T15:00:43+02:00" level=debug msg="completed keyexchange" Aug 23 15:00:43 volumio go-librespot[2969]: time="2024-08-23T15:00:43+02:00" level=debug msg="completed challenge" Aug 23 15:00:43 volumio go-librespot[2969]: time="2024-08-23T15:00:43+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:00:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:45 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:45 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:00:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 101. Aug 23 15:00:46 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:00:46 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:00:46 volumio go-librespot[2977]: Librespot-go daemon starting... Aug 23 15:00:47 volumio go-librespot[2977]: time="2024-08-23T15:00:47+02:00" level=info msg="generated new device id: a0a0c5a6031e94ca56175fcfecd603087a1d9f35" Aug 23 15:00:47 volumio go-librespot[2977]: time="2024-08-23T15:00:47+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:00:47 volumio go-librespot[2977]: time="2024-08-23T15:00:47+02:00" level=debug msg="obtained new client token: AAACwfsQ+ZO8Iq6rmPRzBSGM+2nSV2yY/cfpyalLBVIQ/J7avNI+71dH7NpTGPm9M7mQJCbFkjpU2chMW9phGRjy6+M2bvpl5zT2stO0kdz62jAUqeJNGBfLugw/m7Ws7Et9S0O6sIxizMpbb+phOIcrB7Ldopu/ZlvMyxSX+pxHNAUL3fs93PnTW5GY+lIWlr71oWB4NJSUGncbD8AE9v35TqmABWHbb69lPZM906+H/memeko4IdguPzBH+c0=" Aug 23 15:00:47 volumio go-librespot[2977]: time="2024-08-23T15:00:47+02: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]" Aug 23 15:00:47 volumio go-librespot[2977]: time="2024-08-23T15:00:47+02:00" level=debug msg="completed keyexchange" Aug 23 15:00:48 volumio go-librespot[2977]: time="2024-08-23T15:00:48+02:00" level=debug msg="completed challenge" Aug 23 15:00:48 volumio go-librespot[2977]: time="2024-08-23T15:00:48+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:00:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:48 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:48 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:51 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:51 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:00:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 102. Aug 23 15:00:51 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:00:51 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:00:51 volumio go-librespot[2986]: Librespot-go daemon starting... Aug 23 15:00:51 volumio go-librespot[2986]: time="2024-08-23T15:00:51+02:00" level=info msg="generated new device id: 176fb0ca4a68b3c970beb9f8d1425e846e714fd3" Aug 23 15:00:51 volumio go-librespot[2986]: time="2024-08-23T15:00:51+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:00:51 volumio go-librespot[2986]: time="2024-08-23T15:00:51+02:00" level=debug msg="obtained new client token: AABzbYtX9fNUld5UXnDrucyITMVCio+mjK3zMKmp7qXyKUwtPbyfspYySQZXnU+Q8Qvx6fXYir8x2/8b++0s+of5R6jcs9frvJLHDc+VPwvi0AY8lNGAqmsRLbys5Cmh6UmUnUmACzyO9kIVHp7aT/he+YtD3NJCNN++UeUv1e97n53V9sXmS1jUpMeJf5D5SKd1bNodvXxgLLpUv0rWnYpubVHXXcRXuaNgo/7KgIOcrnWLxz0Q6TNIbZCoNtI=" Aug 23 15:00:51 volumio go-librespot[2986]: time="2024-08-23T15:00:51+02: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]" Aug 23 15:00:52 volumio go-librespot[2986]: time="2024-08-23T15:00:52+02:00" level=debug msg="completed keyexchange" Aug 23 15:00:52 volumio go-librespot[2986]: time="2024-08-23T15:00:52+02:00" level=debug msg="completed challenge" Aug 23 15:00:52 volumio go-librespot[2986]: time="2024-08-23T15:00:52+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:00:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:53 volumio volumio[861]: info: Clearing queue after UPNP request Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::ClearQueue Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::stop Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::setConsumeUpdateService undefined Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::stPlaybackTimer Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::updateTrackBlock Aug 23 15:00:53 volumio volumio[861]: info: CorePlayQueue::getTrackBlock Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:53 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:53 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 23 15:00:53 volumio volumio[861]: info: CoreCommandRouter::volumioPushState Aug 23 15:00:53 volumio volumio[861]: info: CoreStateMachine::serviceStop Aug 23 15:00:53 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:53 volumio volumio[861]: info: ControllerMpd::stop Aug 23 15:00:53 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand stop Aug 23 15:00:53 volumio volumio[861]: info: CorePlayQueue::clearPlayQueue Aug 23 15:00:53 volumio volumio[861]: info: CorePlayQueue::saveQueue Aug 23 15:00:53 volumio volumio[861]: info: CoreCommandRouter::volumioPushState Aug 23 15:00:53 volumio volumio[861]: info: CoreCommandRouter::volumioPushQueue Aug 23 15:00:54 volumio volumio[861]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Aug 23 15:00:54 volumio volumio[861]: SPOTIFY: SPOTIFY VOLUME 25 Aug 23 15:00:54 volumio volumio[861]: SPOTIFY: VOLUMIO VOLUME 38 Aug 23 15:00:54 volumio volumio[861]: SPOTIFY: DELTA VOLUME ENOUGH: true Aug 23 15:00:54 volumio volumio[861]: info: Setting Spotify Volume from Volumio: 38 Aug 23 15:00:54 volumio volumio[861]: SPOTIFY: RECEIVED VOLUMIO VOLUME 38 Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: sendMpdCommand stop took 56 milliseconds Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: error: updateQueue error: null Aug 23 15:00:54 volumio volumio[861]: error: updateQueue error: null Aug 23 15:00:54 volumio volumio[861]: error: updateQueue error: null Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 9ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 7ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 6ms Aug 23 15:00:54 volumio volumio[861]: info: Starting UPNP Playback Aug 23 15:00:54 volumio volumio[861]: info: Preparing playback through UPNP Aug 23 15:00:54 volumio volumio[861]: info: CoreCommandRouter::volumioGetState Aug 23 15:00:54 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:54 volumio volumio[861]: info: CoreStateMachine::setConsumeUpdateService mpd Aug 23 15:00:54 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:54 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 12ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 12ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 7ms Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 14ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 11ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 7ms Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 8ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 6ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 5ms Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 2ms Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 5ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 3ms Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 7ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 7ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 6ms Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: Aug 23 15:00:54 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:54 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 9ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 5ms Aug 23 15:00:54 volumio volumio[861]: info: ------------------------------ 4ms Aug 23 15:00:55 volumio volumio[861]: SPOTIFY: SETTING SPOTIFY VOLUME 38 Aug 23 15:00:55 volumio volumio[861]: info: Sending Spotify command with payload to local API: /player/volume Aug 23 15:00:55 volumio volumio[861]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:00:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:00:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 103. Aug 23 15:00:55 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio kernel: pcm512x 1-004d: No SCLK, using BCLK: -2 Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 17 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 18 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 22 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 10 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 11 milliseconds Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"Home","artist":"Good Neighbours","album":"Home","uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus stop Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 43ms Aug 23 15:00:55 volumio go-librespot[3004]: Librespot-go daemon starting... Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:55 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 27 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 25 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 25 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 12 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 10 milliseconds Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio go-librespot[3004]: time="2024-08-23T15:00:55+02:00" level=info msg="generated new device id: b3055658de701ee8efa61a31ec77d70485f5ee36" Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio go-librespot[3004]: time="2024-08-23T15:00:55+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":null,"isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 95ms Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 92ms Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 81ms Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:55 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces system playlist update Aug 23 15:00:55 volumio volumio[861]: info: Ignoring MPD Status Update Aug 23 15:00:55 volumio volumio[861]: info: Aug 23 15:00:55 volumio volumio[861]: ---------------------------- MPD announces state update: player Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::getState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand status Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 62ms Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 57 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 48 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 48 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 17ms Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 15 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 14ms Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand status took 13 milliseconds Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseState Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::sendMpdCommand playlistinfo Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":869,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"601 Kbps","isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":869,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"605 Kbps","isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 88ms Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 85ms Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 16 milliseconds Aug 23 15:00:55 volumio volumio[861]: info: sendMpdCommand playlistinfo took 16 milliseconds Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: verbose: ControllerMpd::parseTrackInfo Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":869,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"616 Kbps","isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":869,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"485 Kbps","isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: info: ControllerMpd::pushState Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::servicePushState Aug 23 15:00:55 volumio volumio[861]: verbose: In UPNP mode Aug 23 15:00:55 volumio volumio[861]: verbose: STATE SERVICE {"status":"play","position":0,"seek":869,"duration":0,"samplerate":"44.1 kHz","bitdepth":"16 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"485 Kbps","isStreaming":false,"title":"66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","artist":"Music Assistant","album":null,"uri":"http://192.168.178.47:8097/single/uuid:548a2cb5-2925-37ea-1818-d83addd4d894/66c13f2e6c334dbb8b5888d56760b9a4.flac?ts=1724418053","trackType":""} Aug 23 15:00:55 volumio volumio[861]: verbose: CURRENT POSITION 0 Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState stateService play Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::syncState currentStatus play Aug 23 15:00:55 volumio volumio[861]: info: Received an update from plugin. extracting info from payload Aug 23 15:00:55 volumio volumio[861]: info: CoreCommandRouter::executeOnPlugin: albumart , getAlbumArt Aug 23 15:00:55 volumio volumio[861]: info: CoreStateMachine::pushState Aug 23 15:00:55 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: error: ControllerMpd::pushError: TypeError: Cannot read property 'name' of undefined Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 102ms Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 58ms Aug 23 15:00:55 volumio volumio[861]: info: ------------------------------ 54ms Aug 23 15:00:56 volumio go-librespot[3004]: time="2024-08-23T15:00:56+02:00" level=debug msg="obtained new client token: AAD3v5PZiivhqSMbCNbqIHeFnU/17jTo3g4YLxz2Rm1CHxxSpnFhTQsJc5yPWw8q8gA/4CPy1t15nApYCrFfHpgVtKydySMSqm8t2/2LRiX8oHv0Nbze3al10mNGCtFkYJPvF+KuEbj7QquRc/owNV706RjKwgzNVp/yJGtLimYiNsktpBCaBawm+Kvl/bWnQi5sFwdJJp/6gJCg1y97HD7vC++ffVXeHYEZBxEjWAD71YsBhScmyknDgkVt" Aug 23 15:00:56 volumio go-librespot[3004]: time="2024-08-23T15:00:56+02: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]" Aug 23 15:00:56 volumio go-librespot[3004]: time="2024-08-23T15:00:56+02:00" level=debug msg="completed keyexchange" Aug 23 15:00:57 volumio go-librespot[3004]: time="2024-08-23T15:00:57+02:00" level=debug msg="completed challenge" Aug 23 15:00:57 volumio go-librespot[3004]: time="2024-08-23T15:00:57+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:00:57 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:00:57 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:00:57 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:00:57 volumio volumio[861]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:01:00 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 23 15:01:00 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 104. Aug 23 15:01:00 volumio systemd[1]: Stopped go-librespot Daemon. Aug 23 15:01:00 volumio systemd[1]: Started go-librespot Daemon. Aug 23 15:01:00 volumio go-librespot[3027]: Librespot-go daemon starting... Aug 23 15:01:00 volumio go-librespot[3027]: time="2024-08-23T15:01:00+02:00" level=info msg="generated new device id: 5c52059532b8c59c6da04e62ce75ff869aa6fd7d" Aug 23 15:01:00 volumio go-librespot[3027]: time="2024-08-23T15:01:00+02:00" level=debug msg="stored credentials found for 6wnwbcx8fzn7amyf8ck51bjmi" Aug 23 15:01:00 volumio volumio[861]: info: Initializing connection to go-librespot Websocket Aug 23 15:01:00 volumio go-librespot[3027]: time="2024-08-23T15:01:00+02:00" level=debug msg="new websocket client" Aug 23 15:01:00 volumio volumio[861]: info: Connection to go-librespot Websocket established Aug 23 15:01:00 volumio go-librespot[3027]: time="2024-08-23T15:01:00+02:00" level=debug msg="obtained new client token: AAAs/tWy4nRu/5h5TOfHLoMdV3bL7mkQzOy97JejAyszEC/TiTmP50OSVyfuSTbKixj7R/ucE2/x7u0Z3zWRaFV4R5JF2QYy3eoDfUazsJJzheB/E6Hx8v4WvPi4x3/WhrgicyYrgG7tx7O1Rn/SHgUQRstOHW5L8snBVW5zdnoOdV5Ljx0fjJOAWsDShsbuZXDgPElh+6pwS4PzJCchc8yjEonrmJ1nlTz8NICVpqvqObv5hxVIHQrNPDzrvrk=" Aug 23 15:01:00 volumio go-librespot[3027]: time="2024-08-23T15:01:00+02: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]" Aug 23 15:01:00 volumio go-librespot[3027]: time="2024-08-23T15:01:00+02:00" level=debug msg="completed keyexchange" Aug 23 15:01:01 volumio go-librespot[3027]: time="2024-08-23T15:01:01+02:00" level=debug msg="completed challenge" Aug 23 15:01:01 volumio go-librespot[3027]: time="2024-08-23T15:01:01+02:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 23 15:01:01 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 23 15:01:01 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 23 15:01:01 volumio volumio[861]: info: Connection to go-librespot Websocket closed Aug 23 15:01:03 volumio volumio[861]: info: Getting Spotify volume Aug 23 15:01:03 volumio volumio[861]: (node:861) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 23 15:01:03 volumio volumio[861]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 23 15:01:03 volumio volumio[861]: (node:861) 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: 34) Aug 23 15:01:03 volumio volumio[861]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 8 Aug 23 15:01:03 volumio volumio[861]: info: CoreCommandRouter::volumioGetState Aug 23 15:01:03 volumio volumio[861]: info: CorePlayQueue::getTrack 0 Aug 23 15:01:03 volumio volumio[861]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 23 15:01:03 volumio volumio[861]: TypeError: Cannot read property 'name' of undefined Aug 23 15:01:03 volumio volumio[861]: at CoreStateMachine.getState (/volumio/app/statemachine.js:126:48) Aug 23 15:01:03 volumio volumio[861]: at CoreCommandRouter.volumioGetState (/volumio/app/index.js:107:28) Aug 23 15:01:03 volumio volumio[861]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:58:38) Aug 23 15:01:03 volumio volumio[861]: at Socket.emit (events.js:315:20) Aug 23 15:01:03 volumio volumio[861]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Aug 23 15:01:03 volumio volumio[861]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Aug 23 15:01:03 volumio volumio[861]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 23 15:01:04 volumio sudo[3050]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-23 15:00 Aug 23 15:01:04 volumio sudo[3050]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Raspbian GNU/Linux 10 (buster)" NAME="Raspbian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=raspbian ID_LIKE=debian HOME_URL="http://www.raspbian.org/" SUPPORT_URL="http://www.raspbian.org/RaspbianForums" BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs" VOLUMIO_BUILD_VERSION="5fd3886148e72a9cecd88a772d1f6079fb64d11a" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="8bb23b009e91ae4c7ecd678f193e7d3b281fca0c" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 22 Jul 2024 07:17:01 PM CEST" VOLUMIO_VERSION="3.742" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="2782e52360f70dfab079c82951ebbbb1"