-- Logs begin at Sat 2025-03-01 06:20:00 CET, end at Sat 2025-03-01 09:18:31 CET. -- Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:17:42 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:17:42 volumio-keuken volumio[970]: verbose: New Socket.io Connection to 192.168.2.9:3000 from 192.168.2.1 UA: Dart/3.5 (dart:io) Engine version: 3 Transport: websocket Total Clients: 9 Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Mar 01 09:17:42 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Mar 01 09:17:43 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:17:43 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:17:43 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:17:43 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:43 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:17:49 volumio-keuken sudo[31733]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 01 09:17:49 volumio-keuken sudo[31733]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:17:49 volumio-keuken sudo[31733]: pam_unix(sudo:session): session closed for user root Mar 01 09:17:49 volumio-keuken sudo[31736]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 01 09:17:49 volumio-keuken sudo[31736]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:17:49 volumio-keuken sudo[31736]: pam_unix(sudo:session): session closed for user root Mar 01 09:17:49 volumio-keuken volumio[970]: verbose: New Socket.io Connection to 192.168.2.9 from 192.168.2.1 UA: Mozilla/5.0 (Linux; Android 14; SM-S911B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.121 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 10 Mar 01 09:17:49 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 01 09:17:49 volumio-keuken sudo[31739]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 01 09:17:49 volumio-keuken sudo[31739]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:17:49 volumio-keuken sudo[31739]: pam_unix(sudo:session): session closed for user root Mar 01 09:17:49 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 01 09:17:49 volumio-keuken sudo[31742]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 01 09:17:49 volumio-keuken sudo[31742]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:17:49 volumio-keuken sudo[31742]: pam_unix(sudo:session): session closed for user root Mar 01 09:17:49 volumio-keuken volumio[970]: verbose: New Socket.io Connection to 192.168.2.9 from 192.168.2.1 UA: Mozilla/5.0 (Linux; Android 14; SM-S911B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.121 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Mar 01 09:17:49 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetVisibleSources Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 01 09:17:50 volumio-keuken volumio[970]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 01 09:17:50 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:17:50 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:50 volumio-keuken volumio[970]: info: Listing playlists Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 01 09:17:50 volumio-keuken volumio[970]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 01 09:17:51 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 01 09:17:51 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:17:51 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:17:51 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:17:51 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:17:51 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:51 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:17:52 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 01 09:17:52 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 01 09:17:52 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:17:52 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:17:52 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:17:52 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:17:52 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:17:52 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:17:56 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 01 09:17:56 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Mar 01 09:17:56 volumio-keuken volumio[970]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 01 09:17:59 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted Mar 01 09:18:00 volumio-keuken volumio[970]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 01 09:18:03 volumio-keuken volumio[970]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 01 09:18:03 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 01 09:18:03 volumio-keuken volumio[970]: info: Creating Spotify config file Mar 01 09:18:03 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 01 09:18:03 volumio-keuken volumio[970]: info: Spotify config file written Mar 01 09:18:03 volumio-keuken sudo[31763]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 01 09:18:03 volumio-keuken sudo[31763]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:18:03 volumio-keuken systemd[1]: Stopping go-librespot Daemon... Mar 01 09:18:03 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=killed, status=15/TERM Mar 01 09:18:03 volumio-keuken systemd[1]: go-librespot-daemon.service: Succeeded. Mar 01 09:18:03 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:03 volumio-keuken volumio[970]: ------------------------------------ BT MESSAGE: BT STATUS: running Mar 01 09:18:03 volumio-keuken volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: socket hang up Mar 01 09:18:03 volumio-keuken volumio[970]: at connResetException (internal/errors.js:607:14) Mar 01 09:18:03 volumio-keuken volumio[970]: at Socket.socketOnEnd (_http_client.js:493:23) Mar 01 09:18:03 volumio-keuken volumio[970]: at Socket.emit (events.js:327:22) Mar 01 09:18:03 volumio-keuken volumio[970]: at endReadableNT (internal/streams/readable.js:1327:12) Mar 01 09:18:03 volumio-keuken volumio[970]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Mar 01 09:18:03 volumio-keuken volumio[970]: (node:970) 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: 657) Mar 01 09:18:03 volumio-keuken volumio[970]: ------------------------------------ BT MESSAGE: BT STATUS: waiting Mar 01 09:18:03 volumio-keuken volumio[970]: info: Connection to go-librespot Websocket closed Mar 01 09:18:03 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:03 volumio-keuken go-librespot[31766]: go-librespot daemon starting... Mar 01 09:18:03 volumio-keuken sudo[31763]: pam_unix(sudo:session): session closed for user root Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=debug msg="app state loaded" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+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]" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=info msg="zeroconf server listening on port 41533" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=debug msg="obtained new client token: AADeaCVtui9Jfeh8toY9i2nutLY1o+l99cLdHP1LKnSr2c/CgzhyM22qejeZ7Wk/HsVF6g/3rZHvn9cV00Gv1bik7Dd2E98hiO1jKpHMBX3dqXgruD3tNmnjByoL73EHmLERIwAB3YPGc472GYpNxJaDgMXZ7XZNso4Sb4oI0lWcGoM/n6vhjl6/zUnkQL5we692RJI9QB8dvWYMsR92R2WSE9GVxJ1FB5uhf+rvHKApbJDFnuzfqhYG2Q==" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:03 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:03+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:04 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:04+01:00" level=debug msg="completed challenge" Mar 01 09:18:04 volumio-keuken go-librespot[31766]: time="2025-03-01T09:18:04+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Mar 01 09:18:04 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:04 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:04 volumio-keuken volumio[970]: info: CALLMETHOD: music_service spop saveGoLibrespotSettings [object Object] Mar 01 09:18:04 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: spop , saveGoLibrespotSettings Mar 01 09:18:04 volumio-keuken volumio[970]: info: Creating Spotify config file Mar 01 09:18:04 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Mar 01 09:18:04 volumio-keuken volumio[970]: info: Spotify config file written Mar 01 09:18:04 volumio-keuken sudo[31775]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Mar 01 09:18:04 volumio-keuken sudo[31775]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:18:04 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:04 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:04 volumio-keuken go-librespot[31777]: go-librespot daemon starting... Mar 01 09:18:04 volumio-keuken sudo[31775]: pam_unix(sudo:session): session closed for user root Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=debug msg="app state loaded" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18: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-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=info msg="zeroconf server listening on port 46849" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=debug msg="obtained new client token: AAAwkY5Peao8DCcWC+Q1qvuwuqQ6dAcbOSXTn5T3zHCw+ijsg8iHAfenlVGmwzqa/yGEHi5Nt4c8jpyrA/e4aOInOKKpBbXgM8IoUn5ur6mW0NP1srpqMJVyzh1zuConh+3qWuK5BZ2idT0XYyFUsnvkNOMGnHnFSF4raJdnkbarf+ltRVv87ZOh79/hrWKh6G/4TdQbAKEHz7j8TBP4e8laUsJiJqA1iZqBzzwiwbRVQEuy/4ghjW0/Zg==" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:04 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:04+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:05 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18:05+01:00" level=debug msg="completed challenge" Mar 01 09:18:05 volumio-keuken go-librespot[31777]: time="2025-03-01T09:18: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" Mar 01 09:18:05 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:05 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:06 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:06 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:06 volumio-keuken volumio[970]: info: go-librespot daemon successfully initialized Mar 01 09:18:07 volumio-keuken volumio[970]: info: go-librespot daemon successfully initialized Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 01 09:18:08 volumio-keuken volumio[970]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Mar 01 09:18:08 volumio-keuken volumio[970]: info: Received Get System Version Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Mar 01 09:18:08 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:18:08 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:08 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:18:08 volumio-keuken systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 01 09:18:08 volumio-keuken systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1. Mar 01 09:18:08 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:08 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:08 volumio-keuken go-librespot[31804]: go-librespot daemon starting... Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=debug msg="app state loaded" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+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]" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=info msg="zeroconf server listening on port 36875" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=debug msg="obtained new client token: AACGTXw7zsY5tNshj0ENxRFVVKbI23cHiKEUqN6v/LpuEri7xGpzhI6xZjXjq3HoNjPwgOXKsarh8SixZ0SSwvywoDF/tK8ZIPwi3ShqTP8BhrZYsoF8Cq8l2WdgHz+tkeIYlFxD11IXrdDbXfyrP9EojNObxEqDqRszYZZWgWeJavOujYKXKfnkdheus0iqLZI9NdmC6PO/mFBHhzhcIDFM8/eiP675eUZ8rtB0USUPGDyINKIeeOF2Fg==" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:08 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:08+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:09 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:09+01:00" level=debug msg="completed challenge" Mar 01 09:18:09 volumio-keuken go-librespot[31804]: time="2025-03-01T09:18:09+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Mar 01 09:18:09 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:09 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:09 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:09 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:09 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:09 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:10 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:10 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:12 volumio-keuken systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 01 09:18:12 volumio-keuken systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2. Mar 01 09:18:12 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:12 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:12 volumio-keuken go-librespot[31813]: go-librespot daemon starting... Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=debug msg="app state loaded" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18: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-gew1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=info msg="zeroconf server listening on port 43453" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=debug msg="obtained new client token: AAB5MBjk43r0orxL+Xc3L+EakT/DSzbSK89Q5bqG8ZsqaJw2+ZIShDpTqruktW6S4xc+eDcpVvxqe42DQ2pGrwin7waCyi5n2jOE9ccPvfoQsnI6yf1qok+CRX9E6qdvHo5pinfSQ6owlzBVAgUsD5nEXfLxAL1UemjVobbatKvoyO/4FuxAqF2jXPko0cstq03yAcP/nu1fkSZZAoMdkxrTrZRENPTywowwojbs2jZuCNmZGS00V+YFBQ==" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:12 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:12+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:12 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:18:12 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:18:12 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:18:12 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:12 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:18:13 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18:13+01:00" level=debug msg="completed challenge" Mar 01 09:18:13 volumio-keuken go-librespot[31813]: time="2025-03-01T09:18: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" Mar 01 09:18:13 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:13 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:13 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:13 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:16 volumio-keuken systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 01 09:18:16 volumio-keuken systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3. Mar 01 09:18:16 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:16 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:16 volumio-keuken go-librespot[31821]: go-librespot daemon starting... Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="app state loaded" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+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]" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=info msg="zeroconf server listening on port 36385" Mar 01 09:18:16 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="new websocket client" Mar 01 09:18:16 volumio-keuken volumio[970]: info: Connection to go-librespot Websocket established Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="obtained new client token: AACTBqzyNOyPc7z8pFyIfcltOK5vY9VuhZEjNJ6OyuhdUejEjiIFz1xTEcHp8OMmq2nUR9mAzJK80Y/CQFwMtqCIHx3ZC2WUNDOAO7aLybxMRwPwR+sy0EBhJfQlQAHFrBIwLPsCAH+xvDZowyozZJpLTmBwWXmv9+BgL2JZXz64ghO702arINWsiiRfaZdHTBichgD5za/yDAex1O84+TkG3YtPrgCb59umj0NocrXNj6DmqNaRil7zEg==" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:16 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:16+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:17 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:17+01:00" level=debug msg="completed challenge" Mar 01 09:18:17 volumio-keuken go-librespot[31821]: time="2025-03-01T09:18:17+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Mar 01 09:18:17 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:17 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:17 volumio-keuken volumio[970]: info: Connection to go-librespot Websocket closed Mar 01 09:18:19 volumio-keuken volumio[970]: info: Getting Spotify volume Mar 01 09:18:19 volumio-keuken volumio[970]: (node:970) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:19 volumio-keuken volumio[970]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Mar 01 09:18:19 volumio-keuken volumio[970]: (node:970) 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: 658) Mar 01 09:18:19 volumio-keuken volumio[970]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12 Mar 01 09:18:19 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:19 volumio-keuken volumio[970]: SPOTIFY: RECEIVED VOLUMIO VOLUME 20 Mar 01 09:18:20 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:20 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:20 volumio-keuken systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 01 09:18:20 volumio-keuken systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4. Mar 01 09:18:20 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:20 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:20 volumio-keuken go-librespot[31846]: go-librespot daemon starting... Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=debug msg="app state loaded" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+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]" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=info msg="zeroconf server listening on port 40415" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=debug msg="obtained new client token: AABzQewFXZU/ccbHKBnuurQJB/K4VkYMrHwZYe4dryOZa2umvG7caHeBwuff2D2d9N+s52EJggpadxJtuTtKqunps2FfFO4i45mhhfWtlAhSoBKwz06rlNC5xMAagBmR7OAbSKPk1w/8qeIV68s/BfVnHRdcoCe8++SVCRugy970Glb3Qg/0VZqbViyBtuZCl0getnlcBJTuq3FiSn0HJf9XwoYUFPqfU5ZBjjYq+dLHYgrPNikEzN3BRw==" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:20 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:20+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:21 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:21+01:00" level=debug msg="completed challenge" Mar 01 09:18:21 volumio-keuken go-librespot[31846]: time="2025-03-01T09:18:21+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Mar 01 09:18:21 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:21 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:23 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:23 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:24 volumio-keuken systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 01 09:18:24 volumio-keuken systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5. Mar 01 09:18:24 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:24 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:24 volumio-keuken go-librespot[31896]: go-librespot daemon starting... Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=debug msg="app state loaded" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18: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-gue1.spotify.com:443 ap-gew1.spotify.com:80]" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443]" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443]" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=info msg="zeroconf server listening on port 45223" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=debug msg="obtained new client token: AAC/VDImCIFbQvJjhz0p7GfkE8tfYmDzaX7cIuolo5oH9LK1M0Bdn9SUpc/Z1MaTZmCR7IWQCPARazgG6iAoPOUg5phebeY1+VOnRtZSkeS6cb1zAh3HFvR3Bc4txxRarfD3PO8N0UwynHl6loy3fnc8PEEte+HepDYQwzukz4ppSp5JPlDtVK/BE7pdG4B6KcxXf3gIVKfRC1SVMbO0hzu55JqytXPlSGPlIUEKfPIrHvq15rKEFoTORQ==" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:24 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:24+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:25 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:25+01:00" level=debug msg="completed challenge" Mar 01 09:18:25 volumio-keuken go-librespot[31896]: time="2025-03-01T09:18:25+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Mar 01 09:18:25 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:25 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:26 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:26 volumio-keuken volumio[970]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Mar 01 09:18:26 volumio-keuken sudo[31919]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 01 09:18:26 volumio-keuken sudo[31919]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:18:26 volumio-keuken sudo[31919]: pam_unix(sudo:session): session closed for user root Mar 01 09:18:26 volumio-keuken sudo[31922]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 01 09:18:26 volumio-keuken sudo[31922]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:18:27 volumio-keuken sudo[31922]: pam_unix(sudo:session): session closed for user root Mar 01 09:18:27 volumio-keuken volumio[970]: verbose: New Socket.io Connection to 192.168.2.9 from 192.168.2.1 UA: Mozilla/5.0 (Linux; Android 14; SM-S911B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.121 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 11 Mar 01 09:18:27 volumio-keuken sudo[31925]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Mar 01 09:18:27 volumio-keuken sudo[31925]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:18:27 volumio-keuken sudo[31925]: pam_unix(sudo:session): session closed for user root Mar 01 09:18:27 volumio-keuken sudo[31928]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Mar 01 09:18:27 volumio-keuken sudo[31928]: pam_unix(sudo:session): session opened for user root by (uid=0) Mar 01 09:18:27 volumio-keuken sudo[31928]: pam_unix(sudo:session): session closed for user root Mar 01 09:18:27 volumio-keuken volumio[970]: verbose: New Socket.io Connection to 192.168.2.9 from 192.168.2.1 UA: Mozilla/5.0 (Linux; Android 14; SM-S911B Build/UP1A.231005.007; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/133.0.6943.121 Mobile Safari/537.36 Engine version: 3 Transport: polling Total Clients: 12 Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetVisibleSources Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Mar 01 09:18:27 volumio-keuken volumio[970]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Mar 01 09:18:27 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:18:27 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:27 volumio-keuken volumio[970]: info: Listing playlists Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache Mar 01 09:18:27 volumio-keuken volumio[970]: info: CoreCommandRouter::getUIConfigOnPlugin Mar 01 09:18:28 volumio-keuken systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Mar 01 09:18:28 volumio-keuken systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6. Mar 01 09:18:28 volumio-keuken systemd[1]: Stopped go-librespot Daemon. Mar 01 09:18:28 volumio-keuken systemd[1]: Started go-librespot Daemon. Mar 01 09:18:28 volumio-keuken go-librespot[31931]: go-librespot daemon starting... Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=info msg="running go-librespot 0.1.3" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=debug msg="app state loaded" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=info msg="api server listening on 127.0.0.1:9879" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18: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-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=debug msg="fetched new dealers: [gew4-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=debug msg="fetched new spclients: [gew4-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=info msg="zeroconf server listening on port 43477" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=debug msg="obtained new client token: AADuQgfsXGACDv6kEFgVr8ISC9IIzdLDIuPvwNzcHj6yud7VItXz6pbKx4/axOVEeQ2m5H7cKQA1nBbScrXjNR9/co/1X8R15uteEJjBrqqXjcNykAPT0U7tWNtlM63gFWufpZzq4yFZjNpFkjB1ngNnhbO7Ee3GzFjEqnnJadAfkk/wR3WETCarIXCCGU14QCEIWNUkPbN03TKwwUfu4wbqjrVLFQgkpkbIyaB9ZjlcI1YuNQqTspgYSw==" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=debug msg="connected to ap-gew4.spotify.com:4070" Mar 01 09:18:28 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:28+01:00" level=debug msg="completed keyexchange" Mar 01 09:18:28 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard Mar 01 09:18:29 volumio-keuken volumio[970]: info: Initializing connection to go-librespot Websocket Mar 01 09:18:29 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:29+01:00" level=debug msg="new websocket client" Mar 01 09:18:29 volumio-keuken volumio[970]: info: Connection to go-librespot Websocket established Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 01 09:18:29 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:18:29 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:18:29 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18:29+01:00" level=debug msg="completed challenge" Mar 01 09:18:29 volumio-keuken go-librespot[31931]: time="2025-03-01T09:18: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" Mar 01 09:18:29 volumio-keuken systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Mar 01 09:18:29 volumio-keuken systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Mar 01 09:18:29 volumio-keuken volumio[970]: info: Connection to go-librespot Websocket closed Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetQueue Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreStateMachine::getQueue Mar 01 09:18:29 volumio-keuken volumio[970]: info: CorePlayQueue::getQueue Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Mar 01 09:18:29 volumio-keuken volumio[970]: info: Received Get System Info Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Mar 01 09:18:29 volumio-keuken volumio[970]: info: Discovery: Getting this device information Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioGetState Mar 01 09:18:29 volumio-keuken volumio[970]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Mar 01 09:18:31 volumio-keuken volumio[970]: info: CoreCommandRouter::volumioRemoveQueueItem Mar 01 09:18:31 volumio-keuken volumio[970]: info: CoreStateMachine::removeQueueItem Mar 01 09:18:31 volumio-keuken volumio[970]: info: CoreStateMachine::stop Mar 01 09:18:31 volumio-keuken volumio[970]: info: CoreStateMachine::serviceStop Mar 01 09:18:31 volumio-keuken volumio[970]: info: CoreCommandRouter::serviceStop Mar 01 09:18:31 volumio-keuken volumio[970]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 01 09:18:31 volumio-keuken volumio[970]: TypeError: Cannot read property 'then' of undefined Mar 01 09:18:31 volumio-keuken volumio[970]: at CoreStateMachine.removeQueueItem (/volumio/app/statemachine.js:1368:7) Mar 01 09:18:31 volumio-keuken volumio[970]: at CoreCommandRouter.volumioRemoveQueueItem (/volumio/app/index.js:121:28) Mar 01 09:18:31 volumio-keuken volumio[970]: at Socket. (/volumio/app/plugins/user_interface/websocket/index.js:173:33) Mar 01 09:18:31 volumio-keuken volumio[970]: at Socket.emit (events.js:315:20) Mar 01 09:18:31 volumio-keuken volumio[970]: at /volumio/node_modules/socket.io/lib/socket.js:528:12 Mar 01 09:18:31 volumio-keuken volumio[970]: at processTicksAndRejections (internal/process/task_queues.js:75:11) Mar 01 09:18:31 volumio-keuken volumio[970]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Mar 01 09:18:31 volumio-keuken vtcs[1477]: [2025-03-01 09:18:31.204] [tisoc] [warning] [PlaybackControllerImpl.cpp:510] Illegal state:0 Mar 01 09:18:31 volumio-keuken sudo[31953]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-03-01 09:17 Mar 01 09:18:31 volumio-keuken sudo[31953]: 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="f6610a1100d2380eef33bd3004af43153c786f96" VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6" VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a" VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET" VOLUMIO_VERSION="3.785" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"