-- Logs begin at Thu 2019-02-14 12:11:59 EET, end at Sun 2024-08-18 15:38:25 EEST. -- Aug 18 15:37:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 2930, instance 1, run: true Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="new websocket client" Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="zeroconf server listening on port 38269" Aug 18 15:37:00 volumio-77 volumio[881]: info: Connection to go-librespot Websocket established Aug 18 15:37:00 volumio-77 volumio[881]: info: Starting Shairport Sync Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="obtained new client token: AABCx2OvN3WqyWv/Zd2KQzZTovicOubY0eb7a5nHzifSKSKq+eEFPs/ZAQ/56tKMwUOfgEp2Ft7qbGb8P0gjMlEj81zi+c3pOCY1coZJS1yCRY4/UQRvb7XVZ61HRS1x+YNDgEx1yywRdHfW453HaAUuX57BjfJNBS2idbzs+LHPNyQFTVyn3RQd6SCWphtUf2gsRiQZCOgoYRQ7v8NuTUUC50cvIFSQhepq1dGHnLyXTS06T/BUM0/TIuk=" Aug 18 15:37:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 2943, instance 1, run: true Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam Aug 18 15:37:00 volumio-77 sudo[2942]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetBrowseSources Aug 18 15:37:00 volumio-77 sudo[2942]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 18 15:37:00 volumio-77 systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Aug 18 15:37:00 volumio-77 systemd[1]: shairport-sync.service: Succeeded. Aug 18 15:37:00 volumio-77 systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Aug 18 15:37:00 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:00+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:00 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:00 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:00 volumio-77 systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Aug 18 15:37:00 volumio-77 sudo[2942]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:00 volumio-77 volumio[881]: info: Shairport-Sync Started Aug 18 15:37:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 2956, instance 1, run: true Aug 18 15:37:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 2963, instance 1, run: true Aug 18 15:37:01 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:01+03:00" level=debug msg="completed challenge" Aug 18 15:37:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 2970, instance 1, run: true Aug 18 15:37:01 volumio-77 go-librespot[2911]: time="2024-08-18T15:37:01+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:01 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:01 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:01 volumio-77 volumio[881]: info: Connection to go-librespot Websocket closed Aug 18 15:37:01 volumio-77 volumiologrotate[541]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Aug 18 15:37:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 2993, instance 1, run: true Aug 18 15:37:01 volumio-77 volumiologrotate[541]: ls: cannot access '77': No such file or directory Aug 18 15:37:01 volumio-77 mpd[2907]: Aug 18 15:37 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Aug 18 15:37:01 volumio-77 sudo[3025]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start volumiobt.service Aug 18 15:37:01 volumio-77 sudo[3025]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3027, instance 1, run: true Aug 18 15:37:01 volumio-77 systemd[1]: Started Volumio Bluetooth Module. Aug 18 15:37:01 volumio-77 volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 8 Aug 18 15:37:01 volumio-77 sudo[3025]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:01 volumio-77 sudo[3036]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod -R 777 /var/lib/bluetooth/* Aug 18 15:37:01 volumio-77 sudo[3036]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:01 volumio-77 volumiobt[3035]: /bin/chmod: cannot access '/var/lib/bluetooth/*': No such file or directory Aug 18 15:37:02 volumio-77 sudo[3036]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:02 volumio-77 volumio[881]: info: Volumio BT Module successfully started Aug 18 15:37:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3039, instance 1, run: true Aug 18 15:37:02 volumio-77 systemd[1]: Started Music Player Daemon. Aug 18 15:37:02 volumio-77 sudo[2893]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3061, instance 1, run: true Aug 18 15:37:02 volumio-77 volumio[881]: error: updateQueue error: null Aug 18 15:37:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3078, instance 1, run: true Aug 18 15:37:02 volumio-77 volumio[881]: info: TidalConnect service stoped! Aug 18 15:37:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3099, instance 1, run: true Aug 18 15:37:02 volumio-77 volumio[881]: info: Adding tc_getconfig REST Endpoint for plugin: music_service/tidalconnect Aug 18 15:37:02 volumio-77 volumio[881]: info: Adding tc_connect REST Endpoint for plugin: music_service/tidalconnect Aug 18 15:37:02 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:02 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:02 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetQueue Aug 18 15:37:02 volumio-77 volumio[881]: info: CoreStateMachine::getQueue Aug 18 15:37:02 volumio-77 volumio[881]: info: CorePlayQueue::getQueue Aug 18 15:37:02 volumio-77 volumio[2898]: register 5 Aug 18 15:37:02 volumio-77 volumio[2898]: success Aug 18 15:37:02 volumio-77 volumio[2898]: register 6 Aug 18 15:37:02 volumio-77 volumio[2898]: success Aug 18 15:37:02 volumio-77 volumio[2898]: register 16 Aug 18 15:37:02 volumio-77 volumio[2898]: success Aug 18 15:37:02 volumio-77 volumio[2898]: register 20 Aug 18 15:37:02 volumio-77 volumio[2898]: success Aug 18 15:37:02 volumio-77 sudo[3122]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start vtcs.service Aug 18 15:37:02 volumio-77 sudo[3122]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:02 volumio-77 volumio[2898]: Traceback (most recent call last): Aug 18 15:37:02 volumio-77 volumio[2898]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 721, in Aug 18 15:37:02 volumio-77 volumio[2898]: main() Aug 18 15:37:02 volumio-77 volumio[2898]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 697, in main Aug 18 15:37:02 volumio-77 volumio[2898]: SOCKETIO.wait() Aug 18 15:37:02 volumio-77 volumio[2898]: File "/usr/local/lib/python3.7/dist-packages/socketIO_client/__init__.py", line 251, in wait Aug 18 15:37:02 volumio-77 volumio[2898]: self._process_packets() Aug 18 15:37:02 volumio-77 volumio[2898]: File "/usr/local/lib/python3.7/dist-packages/socketIO_client/__init__.py", line 278, in _process_packets Aug 18 15:37:02 volumio-77 volumio[2898]: self._process_packet(engineIO_packet) Aug 18 15:37:02 volumio-77 volumio[2898]: File "/usr/local/lib/python3.7/dist-packages/socketIO_client/__init__.py", line 491, in _process_packet Aug 18 15:37:02 volumio-77 volumio[2898]: delegate(parse_socketIO_packet_data(socketIO_packet_data), namespace) Aug 18 15:37:02 volumio-77 volumio[2898]: File "/usr/local/lib/python3.7/dist-packages/socketIO_client/__init__.py", line 513, in _on_event Aug 18 15:37:02 volumio-77 volumio[2898]: namespace._find_packet_callback(event)(*args) Aug 18 15:37:02 volumio-77 volumio[2898]: File "/data/plugins/system_hardware/pirateaudio/display.py", line 497, in on_push_state Aug 18 15:37:02 volumio-77 volumio[2898]: VOLUMIO_DICT['VOLUME'] = int(args[0]['volume']) Aug 18 15:37:02 volumio-77 volumio[2898]: ValueError: invalid literal for int() with base 10: '' Aug 18 15:37:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3123, instance 1, run: true Aug 18 15:37:02 volumio-77 systemd[1]: Started Volumio Tidal Connect Service. Aug 18 15:37:02 volumio-77 sudo[3122]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3134, instance 1, run: true Aug 18 15:37:02 volumio-77 systemd[1]: pirateaudio.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:02 volumio-77 systemd[1]: pirateaudio.service: Failed with result 'exit-code'. Aug 18 15:37:03 volumio-77 sudo[3143]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall pulseaudio Aug 18 15:37:03 volumio-77 sudo[3143]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:03 volumio-77 systemd[1]: pirateaudio.service: Service RestartSec=100ms expired, scheduling restart. Aug 18 15:37:03 volumio-77 systemd[1]: pirateaudio.service: Scheduled restart job, restart counter is at 16. Aug 18 15:37:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3145, instance 1, run: true Aug 18 15:37:03 volumio-77 systemd[1]: Stopped Service for using pirate audio display in volumio. Aug 18 15:37:03 volumio-77 volumiobt[3035]: pulseaudio: no process found Aug 18 15:37:03 volumio-77 sudo[3143]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:03 volumio-77 systemd[1]: Started Service for using pirate audio display in volumio. Aug 18 15:37:03 volumio-77 dbus-daemon[534]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.20' (uid=1000 pid=3155 comm="/usr/bin/pulseaudio --high-priority=true ") Aug 18 15:37:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3156, instance 1, run: true Aug 18 15:37:03 volumio-77 systemd[1]: Starting RealtimeKit Scheduling Policy Service... Aug 18 15:37:03 volumio-77 volumio[881]: info: Getting Spotify volume Aug 18 15:37:03 volumio-77 volumio[881]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 18 15:37:03 volumio-77 volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:03 volumio-77 volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 18 15:37:03 volumio-77 volumio[881]: (node:881) 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: 3) Aug 18 15:37:03 volumio-77 dbus-daemon[534]: [system] Successfully activated service 'org.freedesktop.RealtimeKit1' Aug 18 15:37:03 volumio-77 systemd[1]: Started RealtimeKit Scheduling Policy Service. Aug 18 15:37:03 volumio-77 rtkit-daemon[3157]: Successfully called chroot. Aug 18 15:37:03 volumio-77 rtkit-daemon[3157]: Successfully dropped privileges. Aug 18 15:37:03 volumio-77 rtkit-daemon[3157]: Successfully limited resources. Aug 18 15:37:03 volumio-77 rtkit-daemon[3157]: Running. Aug 18 15:37:03 volumio-77 rtkit-daemon[3157]: Watchdog thread running. Aug 18 15:37:03 volumio-77 rtkit-daemon[3157]: Canary thread running. Aug 18 15:37:03 volumio-77 dbus-daemon[534]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.21' (uid=0 pid=3157 comm="/usr/lib/rtkit/rtkit-daemon ") Aug 18 15:37:03 volumio-77 volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 8 Aug 18 15:37:03 volumio-77 systemd[1]: Starting Authorization Manager... Aug 18 15:37:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3167, instance 1, run: true Aug 18 15:37:03 volumio-77 volumio[881]: ------------------------------------ BT MESSAGE: BT STATUS: running Aug 18 15:37:03 volumio-77 volumio[881]: info: MRS: Getting audio outputs on start Aug 18 15:37:03 volumio-77 volumio[881]: info: MRS: Requesting all other devices output Aug 18 15:37:03 volumio-77 polkitd[3166]: started daemon version 0.105 using authority implementation `local' version `0.105' Aug 18 15:37:03 volumio-77 dbus-daemon[534]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Aug 18 15:37:03 volumio-77 systemd[1]: Started Authorization Manager. Aug 18 15:37:03 volumio-77 volumio[1072]: ............++++ Aug 18 15:37:03 volumio-77 volumio[1072]: e is 65537 (0x010001) Aug 18 15:37:03 volumio-77 volumio[881]: info: Executing endpoint tc_getconfig Aug 18 15:37:03 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onGetConfig Aug 18 15:37:04 volumio-77 vtcs[3126]: STARTING TidalConnect services, version: 1.3.0.19 Aug 18 15:37:04 volumio-77 volumio[1072]: writing RSA key Aug 18 15:37:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3184, instance 1, run: true Aug 18 15:37:04 volumio-77 vtcs[3126]: STARTED TidalConnect services. Aug 18 15:37:04 volumio-77 volumio[881]: info: Executing endpoint tc_connect Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: tidalconnect , onConnect Aug 18 15:37:04 volumio-77 volumio[881]: info: Connecting to TidalConnect Aug 18 15:37:04 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:04 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9. Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:04 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:04 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:04 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreCommandRouter::servicePushState Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreStateMachine::pushState Aug 18 15:37:04 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreCommandRouter::volumioPushState Aug 18 15:37:04 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:04 volumio-77 go-librespot[3205]: Librespot-go daemon starting... Aug 18 15:37:04 volumio-77 volumio[881]: info: MRS: Pushing multiroomSync output update for this device Aug 18 15:37:04 volumio-77 volumio[881]: info: MRS: Pushing multiroomSync output Aug 18 15:37:04 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:04 volumio-77 volumio[881]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreCommandRouter::servicePushState Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreStateMachine::pushState Aug 18 15:37:04 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:04 volumio-77 volumio[881]: info: CoreCommandRouter::volumioPushState Aug 18 15:37:04 volumio-77 volumio[881]: info: MRS: Pushing multiroomSync output update for this device Aug 18 15:37:04 volumio-77 volumio[881]: info: MRS: Pushing multiroomSync output Aug 18 15:37:04 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:04 volumio-77 volumio[881]: info: Received update from a service different from the one supposed to be playing music. Skipping notification.Current mpd Received tidalconnect Aug 18 15:37:04 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:04+03:00" level=info msg="generated new device id: ecf28a313320107de8b4b8ddad7717e2ce20b4b0" Aug 18 15:37:04 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:04+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3224, instance 1, run: true Aug 18 15:37:04 volumio-77 pulseaudio[3155]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Aug 18 15:37:04 volumio-77 pulseaudio[3155]: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11 Aug 18 15:37:04 volumio-77 bluetoothd[689]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource Aug 18 15:37:04 volumio-77 bluetoothd[689]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink Aug 18 15:37:04 volumio-77 volumiobt[3035]: Applying permissions Aug 18 15:37:04 volumio-77 volumiobt[3035]: Setting BT discoverable and pairable Aug 18 15:37:04 volumio-77 pulseaudio[3155]: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files Aug 18 15:37:04 volumio-77 kernel: Bluetooth: RFCOMM TTY layer initialized Aug 18 15:37:04 volumio-77 kernel: Bluetooth: RFCOMM socket layer initialized Aug 18 15:37:04 volumio-77 kernel: Bluetooth: RFCOMM ver 1.11 Aug 18 15:37:05 volumio-77 volumiobt[3035]: Agent registered Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# -e power on Aug 18 15:37:05 volumio-77 volumiobt[3035]: Invalid command in menu main: -e Aug 18 15:37:05 volumio-77 volumiobt[3035]: Aug 18 15:37:05 volumio-77 volumiobt[3035]: Use "help" for a list of available commands in a menu. Aug 18 15:37:05 volumio-77 volumiobt[3035]: Use "menu " if you want to enter any submenu. Aug 18 15:37:05 volumio-77 volumiobt[3035]: Use "back" if you want to return to menu main. Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# agent on Aug 18 15:37:05 volumio-77 volumiobt[3035]: Agent is already registered Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# discoverable on Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# pairable on Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="new websocket client" Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# agent NoInputNoOutput Aug 18 15:37:05 volumio-77 volumiobt[3035]: Agent is already registered Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# default-agent Aug 18 15:37:05 volumio-77 volumiobt[3035]: [bluetooth]# quit Aug 18 15:37:05 volumio-77 volumio[881]: info: Connection to go-librespot Websocket established Aug 18 15:37:05 volumio-77 volumiobt[3035]: [59B blob data] Aug 18 15:37:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3242, instance 1, run: true Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="zeroconf server listening on port 45667" Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="obtained new client token: AADKY18ziU/XlDQJySo4QpejU6xVkr+utD/pry0szMYmOCBOy0Z8O798mRbWjVggq2F5NsRO6ZaI/BnueXHtb671gDU0Wv+MbGct2Bq0iMapZLuL5rJibZr1OIvKc/a/j1a8YtZXcaFzgYZnGexpyD6nVWhPQVywUG3gqGv5NuKHc8sMx9mUBDCI5g1+O4Y6HRDNlUFvgX6Pyp8ToRM/G4r0BicyTv0YQq1tfs+VjcqJO4YTPwAPJF8YqVQ=" Aug 18 15:37:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3252, instance 1, run: true Aug 18 15:37:05 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:05+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3259, instance 1, run: true Aug 18 15:37:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3267, instance 1, run: true Aug 18 15:37:05 volumio-77 volumio[881]: info: TidalConnect service started! Aug 18 15:37:05 volumio-77 volumio[881]: info: BOOT COMPLETED Aug 18 15:37:05 volumio-77 volumio[881]: [Metrics] CommandRouter: 96s 747.43ms Aug 18 15:37:05 volumio-77 volumio[881]: info: CoreCommandRouter::volumiosetStartupVolume Aug 18 15:37:05 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Aug 18 15:37:05 volumio-77 volumio[881]: info: VolumeController:: Setting startup Volume 90 Aug 18 15:37:05 volumio-77 volumio[881]: info: VolumeController::SetAlsaVolume90 Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreCommandRouter::Close All Modals sent Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreCommandRouter::Close All Modals sent Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreStateMachine::pushState Aug 18 15:37:06 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreCommandRouter::volumioPushState Aug 18 15:37:06 volumio-77 volumio[881]: info: MRS: Pushing multiroomSync output update for this device Aug 18 15:37:06 volumio-77 volumio[881]: info: MRS: Pushing multiroomSync output Aug 18 15:37:06 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:06+03:00" level=debug msg="completed challenge" Aug 18 15:37:06 volumio-77 go-librespot[3205]: time="2024-08-18T15:37:06+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:06 volumio-77 volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 18 15:37:06 volumio-77 volumio[881]: SPOTIFY: SPOTIFY VOLUME undefined Aug 18 15:37:06 volumio-77 volumio[881]: SPOTIFY: VOLUMIO VOLUME 90 Aug 18 15:37:06 volumio-77 volumio[881]: info: Aligning Spotify Volume to Volumio Volume Aug 18 15:37:06 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:06 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:06 volumio-77 volumio[881]: info: Setting Spotify Volume from Volumio: 90 Aug 18 15:37:06 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:06 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:06 volumio-77 volumio[881]: error: Cannot set ALSA Volume: Error: Alsa Mixer Error: Invalid card number. Aug 18 15:37:06 volumio-77 volumio[881]: info: FusionDsp - ---- read samplerate, raw: 44100,S32_LE,2,32 Aug 18 15:37:06 volumio-77 volumio[881]: info: FusionDsp - ---- read samplerate from file: 44100 Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp service terminated, instance 1 Aug 18 15:37:06 volumio-77 volumio[881]: info: FusionDsp - If filter freq >samplerate/2 then disable it Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3282, instance 1, run: true Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp service started and running in background, instance 1 Aug 18 15:37:06 volumio-77 volumio[881]: info: Connection to go-librespot Websocket closed Aug 18 15:37:06 volumio-77 volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: python-requests/2.21.0 Total Clients: 8 Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3297, instance 1, run: true Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3318, instance 1, run: true Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3335, instance 1, run: true Aug 18 15:37:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3352, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:07 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetQueue Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreStateMachine::getQueue Aug 18 15:37:07 volumio-77 volumio[881]: info: CorePlayQueue::getQueue Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3365, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus Aug 18 15:37:07 volumio-77 volumio[881]: xcb_connection_has_error() returned true Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: raat , onStop Aug 18 15:37:07 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3374, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3381, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3388, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3395, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: SPOTIFY: SETTING SPOTIFY VOLUME 90 Aug 18 15:37:07 volumio-77 volumio[881]: info: Sending Spotify command with payload to local API: /player/volume Aug 18 15:37:07 volumio-77 volumio[881]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3402, instance 1, run: true Aug 18 15:37:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3409, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3416, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: Getting Spotify volume Aug 18 15:37:08 volumio-77 volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:08 volumio-77 volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 18 15:37:08 volumio-77 volumio[881]: (node:881) 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: 4) Aug 18 15:37:08 volumio-77 volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 9 Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3423, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:08 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:08 volumio-77 volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3430, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3437, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3444, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3451, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3458, instance 1, run: true Aug 18 15:37:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3465, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3472, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3479, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3486, instance 1, run: true Aug 18 15:37:09 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:09 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10. Aug 18 15:37:09 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3493, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:09 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:09 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:09 volumio-77 go-librespot[3494]: Librespot-go daemon starting... Aug 18 15:37:09 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:09+03:00" level=info msg="generated new device id: b7915777a14ce008f6b72cb215d30c2f870f625d" Aug 18 15:37:09 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:09+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3507, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3514, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3521, instance 1, run: true Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3529, instance 1, run: true Aug 18 15:37:09 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:09+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:09 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:09+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:09 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:09+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:09 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:09+03:00" level=debug msg="zeroconf server listening on port 44107" Aug 18 15:37:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3536, instance 1, run: true Aug 18 15:37:10 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:10+03:00" level=debug msg="obtained new client token: AACV+yVR0du0z8oFBm1D7QKzpH/TKvLAUm0FR2docPZ+jZ9meDvNtpZD+7Dl0HHY/MPdAyfG9QEIL9qnbRueVH/EgIRUa9H1KXD2fVaKp5AcPixVgHxTatCGcSbasRT2fGnA/DqrU54m/LMfUm4MxvjCJXjfp2Vv4OT49oCM7LsIDTPm1E78TIioJ32iCE+GgFgTXqRMPe4BIRMt9ewSsL/1Cr/FXGYD9lfme+yB8LniksrLKupeYmNT" Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3543, instance 1, run: true Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3550, instance 1, run: true Aug 18 15:37:10 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:10+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3557, instance 1, run: true Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3564, instance 1, run: true Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3571, instance 1, run: true Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3578, instance 1, run: true Aug 18 15:37:10 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:10+03:00" level=debug msg="completed challenge" Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3585, instance 1, run: true Aug 18 15:37:10 volumio-77 go-librespot[3494]: time="2024-08-18T15:37:10+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:10 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:10 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3592, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3599, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3606, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3613, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3620, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3627, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3634, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3641, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3648, instance 1, run: true Aug 18 15:37:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3655, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3662, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3669, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3676, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3683, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:12 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3690, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3697, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3704, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3711, instance 1, run: true Aug 18 15:37:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3718, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3725, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3732, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3739, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3746, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3753, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3760, instance 1, run: true Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3767, instance 1, run: true Aug 18 15:37:13 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:13 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11. Aug 18 15:37:13 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3774, instance 1, run: true Aug 18 15:37:13 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:13 volumio-77 go-librespot[3775]: Librespot-go daemon starting... Aug 18 15:37:13 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:13+03:00" level=info msg="generated new device id: bc767815b09b1d3ad034e70502596980069cf2cb" Aug 18 15:37:13 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:13+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3789, instance 1, run: true Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3796, instance 1, run: true Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3803, instance 1, run: true Aug 18 15:37:14 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:14+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:14 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:14+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:14 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:14+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3810, instance 1, run: true Aug 18 15:37:14 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:14+03:00" level=debug msg="zeroconf server listening on port 46513" Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3817, instance 1, run: true Aug 18 15:37:14 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:14+03:00" level=debug msg="obtained new client token: AAD/hRL1k+dgQYGhu7X9nHaDztoUH9p3CBbB5hg+EhnjIx4XKyznXU5AtpoJoNGYncpMkD0ROHDj+n0GR2cpaHmwyCEOTuv0aiDHOsj0vegZqivoxZ4tALdaU2pEXA9jMBNnIRmi5sUbmMwhoTTTD8cZAgAUtPU4f+q2vAcNJCuQZE6BGNiE97XttpHJzRBzSmCWB9XCXQ3YCcBClhBDQhRG8v26OfKHjnfdtNL8RXgFR4/LFgMPUewNCCI=" Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3824, instance 1, run: true Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3831, instance 1, run: true Aug 18 15:37:14 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:14+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3838, instance 1, run: true Aug 18 15:37:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3845, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3852, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3859, instance 1, run: true Aug 18 15:37:15 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:15+03:00" level=debug msg="completed challenge" Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3866, instance 1, run: true Aug 18 15:37:15 volumio-77 go-librespot[3775]: time="2024-08-18T15:37:15+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:15 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:15 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3873, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:15 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3880, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3887, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3894, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3901, instance 1, run: true Aug 18 15:37:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3908, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3915, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3922, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3929, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3936, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3943, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3950, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3957, instance 1, run: true Aug 18 15:37:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3964, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3971, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3978, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3985, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3992, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 3999, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4006, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4013, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4020, instance 1, run: true Aug 18 15:37:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4027, instance 1, run: true Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4034, instance 1, run: true Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4041, instance 1, run: true Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4048, instance 1, run: true Aug 18 15:37:18 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:18 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12. Aug 18 15:37:18 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4055, instance 1, run: true Aug 18 15:37:18 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:18 volumio-77 go-librespot[4056]: Librespot-go daemon starting... Aug 18 15:37:18 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:18 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:18+03:00" level=info msg="generated new device id: 7a92e6b7d3427cebf632209be3d1a8226b14c031" Aug 18 15:37:18 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:18+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4069, instance 1, run: true Aug 18 15:37:18 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4076, instance 1, run: true Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4083, instance 1, run: true Aug 18 15:37:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4091, instance 1, run: true Aug 18 15:37:18 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:18+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:18 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:18+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:18 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:18+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:18 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:18+03:00" level=debug msg="zeroconf server listening on port 40813" Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4098, instance 1, run: true Aug 18 15:37:19 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:19+03:00" level=debug msg="obtained new client token: AABUR8cSGbCMxbJMh+SE0jXtPirb0RLN2hp5+rNpiNbfGIFVmnO4N1KVQi4/AR1Sb/WsvFPEapRjQhqxxAXIZyCu6xLB8l85vQh5dxu7sZjqIP+7QhiVEc6QKVw06tnRIEmeY9EsWc98NI3BKi6Xm4oHi8ObvZglQc/IU2S/CyxEWP3GYMEeYRL8JqdXJqxC8FELtkdUPLTLJxGHtNwtiI/J4ciUE8t6W14BHM5pxKx+J1pOk5dyYbIg" Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4105, instance 1, run: true Aug 18 15:37:19 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:19+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4112, instance 1, run: true Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4119, instance 1, run: true Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4126, instance 1, run: true Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4133, instance 1, run: true Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4140, instance 1, run: true Aug 18 15:37:19 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:19+03:00" level=debug msg="completed challenge" Aug 18 15:37:19 volumio-77 go-librespot[4056]: time="2024-08-18T15:37:19+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:19 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:19 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4147, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4154, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4162, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4169, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4176, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4183, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4190, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4197, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4204, instance 1, run: true Aug 18 15:37:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4211, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4218, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4225, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4232, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4239, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4246, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:21 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4253, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4260, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4267, instance 1, run: true Aug 18 15:37:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4274, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4281, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4288, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4295, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4302, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4309, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4316, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4323, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4330, instance 1, run: true Aug 18 15:37:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4337, instance 1, run: true Aug 18 15:37:23 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:23 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13. Aug 18 15:37:23 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4344, instance 1, run: true Aug 18 15:37:23 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:23 volumio-77 go-librespot[4345]: Librespot-go daemon starting... Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=info msg="generated new device id: aa4439e8bd0a8f06f721e4dab91028e2ff8c07b0" Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4358, instance 1, run: true Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4365, instance 1, run: true Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4372, instance 1, run: true Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4380, instance 1, run: true Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=debug msg="zeroconf server listening on port 33647" Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4387, instance 1, run: true Aug 18 15:37:23 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:23+03:00" level=debug msg="obtained new client token: AAAbYesC9Zr9ZbI3IWqOL0B5kEdqpP9d6Tkrlz9Y5a6Fbnvun35fAINTjgqPxW6Tx1hqYLHbV0zmWFEGdNgcX0yalikThnbiZghPzIBsKH7iJOXjVHP7p0sqsQ+r9I5Es/1HlxoE3jqJw5tACMBpLxWe0dKzeF1AKB+VOVwMIedInpvq8HSQ4pUpTGSOxgMaJxu0IsI3JXvNwHYKbQgEH6s4JA6hh8c6+HYS6a14MqcplLObnPyoK80ckps=" Aug 18 15:37:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4394, instance 1, run: true Aug 18 15:37:24 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:24+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4401, instance 1, run: true Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4408, instance 1, run: true Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4415, instance 1, run: true Aug 18 15:37:24 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:24+03:00" level=debug msg="completed challenge" Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4422, instance 1, run: true Aug 18 15:37:24 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:24 volumio-77 go-librespot[4345]: time="2024-08-18T15:37:24+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:24 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:24 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:24 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: read ECONNRESET Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4429, instance 1, run: true Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4436, instance 1, run: true Aug 18 15:37:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4443, instance 1, run: true Aug 18 15:37:25 volumio-77 sudo[4451]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Aug 18 15:37:25 volumio-77 sudo[4451]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:25 volumio-77 sudo[4451]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:25 volumio-77 sudo[4454]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Aug 18 15:37:25 volumio-77 sudo[4454]: pam_unix(sudo:session): session opened for user root by (uid=0) Aug 18 15:37:25 volumio-77 sudo[4454]: pam_unix(sudo:session): session closed for user root Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4456, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4463, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4470, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4477, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4484, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: verbose: New Socket.io Connection to 192.168.0.196 from 192.168.0.123 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/127.0.0.0 Safari/537.36 Total Clients: 9 Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4491, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4498, instance 1, run: true Aug 18 15:37:25 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4505, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4512, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetVisibleSources Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:26 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetQueue Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreStateMachine::getQueue Aug 18 15:37:26 volumio-77 volumio[881]: info: CorePlayQueue::getQueue Aug 18 15:37:26 volumio-77 volumio[881]: info: Listing playlists Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4519, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom Aug 18 15:37:26 volumio-77 volumio[881]: info: Error : CoreCommandRouter::executeOnPlugin: No method [getMultiroom] in plugin multiroom Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4526, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: wizard , getShowWizard Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getShowWizard Aug 18 15:37:26 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4533, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4540, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4547, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4554, instance 1, run: true Aug 18 15:37:26 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4561, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4568, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4575, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4582, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4589, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4596, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:27 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:27 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:27 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14. Aug 18 15:37:27 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4604, instance 1, run: true Aug 18 15:37:27 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:27 volumio-77 go-librespot[4603]: Librespot-go daemon starting... Aug 18 15:37:27 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:27+03:00" level=info msg="generated new device id: 3258878cc00edd3f07ccb9411a616931a4c0e21b" Aug 18 15:37:27 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:27+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4617, instance 1, run: true Aug 18 15:37:27 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4624, instance 1, run: true Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4631, instance 1, run: true Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4639, instance 1, run: true Aug 18 15:37:28 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:28+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:28 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:28+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:28 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:28+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:28 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:28+03:00" level=debug msg="zeroconf server listening on port 34617" Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4646, instance 1, run: true Aug 18 15:37:28 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:28+03:00" level=debug msg="obtained new client token: AAAanqwkvQa4sv7YmItv5QLxlUhkmWc2nE89ewuPp+LKrZY6XqYpDnY9Hr0nfS+M1vjr6sJIx1nqAPJ8RpSFkXpdhzTWQiQMbLjwCjTngiUZ3rQwLtp8e/6E2jgCZiqNs1RnDy14G1ALz/jL3O0ow3ddg/IU9tgJly5ICd1mNVzBicEoqgcyMgkEI7raUicYnDUy0eNqSS/z1JEnmv9QSuEB/FbFXo/DZMVautMJgJLi70eTtA/Iq5gLDHU=" Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4653, instance 1, run: true Aug 18 15:37:28 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:28+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4660, instance 1, run: true Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4667, instance 1, run: true Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4674, instance 1, run: true Aug 18 15:37:28 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4681, instance 1, run: true Aug 18 15:37:29 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:29+03:00" level=debug msg="completed challenge" Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4688, instance 1, run: true Aug 18 15:37:29 volumio-77 go-librespot[4603]: time="2024-08-18T15:37:29+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:29 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:29 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4695, instance 1, run: true Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4702, instance 1, run: true Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4709, instance 1, run: true Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4716, instance 1, run: true Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4723, instance 1, run: true Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4730, instance 1, run: true Aug 18 15:37:29 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4737, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4744, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4751, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4758, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4765, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4772, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4779, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:30 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4786, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4793, instance 1, run: true Aug 18 15:37:30 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4800, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4807, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4814, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4821, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4828, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 18 15:37:31 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4835, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4842, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4849, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4856, instance 1, run: true Aug 18 15:37:31 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4863, instance 1, run: true Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4870, instance 1, run: true Aug 18 15:37:32 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:32 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15. Aug 18 15:37:32 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:32 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:32 volumio-77 go-librespot[4877]: Librespot-go daemon starting... Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=info msg="generated new device id: 70b45f334eed57438a9cd6103236773e6a2cb8d1" Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4884, instance 1, run: true Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4891, instance 1, run: true Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4899, instance 1, run: true Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4906, instance 1, run: true Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="zeroconf server listening on port 38013" Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4913, instance 1, run: true Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="obtained new client token: AACQsZj5lzRpfmq046QEJbZ+omYlFaO9LI7Dbqfpg2knyg5jRS3wqzgBy1IN0muSQSOIdR6428ogxbitA2Yhj9qUN6yY5MIviy0aV23NIMR0odHOe1yByU6zZ4nqCniTIBwjRVfCSipmtV8ta4YU6eTpPfHQxAvDaQn5midIp0LcTlnzdpPK8YBopWsKxro98Chm76ei4VZawnhl8q9pa+wFv3bGDgYf7V0a2KS8YAxZgVq3xnMXaPsKRHk=" Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4920, instance 1, run: true Aug 18 15:37:32 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4927, instance 1, run: true Aug 18 15:37:32 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:32+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4934, instance 1, run: true Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4941, instance 1, run: true Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4948, instance 1, run: true Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4955, instance 1, run: true Aug 18 15:37:33 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:33+03:00" level=debug msg="completed challenge" Aug 18 15:37:33 volumio-77 go-librespot[4877]: time="2024-08-18T15:37:33+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4962, instance 1, run: true Aug 18 15:37:33 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:33 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:33 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:33 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4969, instance 1, run: true Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4976, instance 1, run: true Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4983, instance 1, run: true Aug 18 15:37:33 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4990, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 4997, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5005, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5012, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5019, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5026, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5033, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5040, instance 1, run: true Aug 18 15:37:34 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5047, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5054, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5061, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5068, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5075, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5082, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5089, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5096, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5103, instance 1, run: true Aug 18 15:37:35 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5110, instance 1, run: true Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5117, instance 1, run: true Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5124, instance 1, run: true Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5131, instance 1, run: true Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5138, instance 1, run: true Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5145, instance 1, run: true Aug 18 15:37:36 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:36 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16. Aug 18 15:37:36 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5153, instance 1, run: true Aug 18 15:37:36 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:36 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:36 volumio-77 go-librespot[5152]: Librespot-go daemon starting... Aug 18 15:37:36 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:36 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:36+03:00" level=info msg="generated new device id: ac437c542b20e1daa79f97501c024650eb3b4948" Aug 18 15:37:36 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:36+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5166, instance 1, run: true Aug 18 15:37:36 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5173, instance 1, run: true Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5181, instance 1, run: true Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="zeroconf server listening on port 43831" Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5188, instance 1, run: true Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5195, instance 1, run: true Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="obtained new client token: AACItA1mz3L5Qzvq36RxUz5fG5c1Mv4lMzOMMLCRImV/nyfEYbySaMEOt/u7RVIjjVDrBNl5oMLJudrzSHF33ce8KqehcgvjJr+uXgrMP/+Ebo9VF4JOzomMCP+fgwzpSDhxqHtKC/ce8W6+hfsvjpGfJOTS5B/+vQ929pGJrwPTq+X6KsaFcWeO4ubMzauP6UA/hRU4oV+wN7nFGnGM2RX8e4USlYNGLOKkc7hES17ke3V35SZkxZRIMxo=" Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5202, instance 1, run: true Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5209, instance 1, run: true Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5216, instance 1, run: true Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5223, instance 1, run: true Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5230, instance 1, run: true Aug 18 15:37:37 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:37+03:00" level=debug msg="completed challenge" Aug 18 15:37:37 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5237, instance 1, run: true Aug 18 15:37:38 volumio-77 go-librespot[5152]: time="2024-08-18T15:37:38+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:38 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:38 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5244, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5251, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5258, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5265, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5272, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5279, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5286, instance 1, run: true Aug 18 15:37:38 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5293, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5300, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5307, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5314, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5321, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5328, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5335, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5342, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:39 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5349, instance 1, run: true Aug 18 15:37:39 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5356, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5363, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5370, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5377, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5384, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5391, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5398, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5405, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5412, instance 1, run: true Aug 18 15:37:40 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5419, instance 1, run: true Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5426, instance 1, run: true Aug 18 15:37:41 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:41 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17. Aug 18 15:37:41 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:41 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:41 volumio-77 go-librespot[5433]: Librespot-go daemon starting... Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5435, instance 1, run: true Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=info msg="generated new device id: aceb6f053fb0042e0de51df095a5da227710a421" Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5447, instance 1, run: true Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5454, instance 1, run: true Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5462, instance 1, run: true Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="zeroconf server listening on port 40837" Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5469, instance 1, run: true Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5476, instance 1, run: true Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="obtained new client token: AADV4mzFh+LDBP21J06BY2Ic8h1nzu251lNpjTKeYfz1LuL8doyltARkkVVJ39lgzDMBKxA9a1gG2iS5CzOUttr6j7xD1n5gjE+mmCq3FR/tTbBfMawVsI569jH1qI+xzfCPZCS8+rxFCXvPrpjcvr0PMgr2hZ8qnhfronFuq1hEfq7o9c9KmOEavl9aDHlPLZuM/bcWVGuZU3pOrSDuKxr+JO8RL0DyawcWK3BItg+LV0+1zH+usNOf6xQ=" Aug 18 15:37:41 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5483, instance 1, run: true Aug 18 15:37:41 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:41+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5490, instance 1, run: true Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5497, instance 1, run: true Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5504, instance 1, run: true Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5511, instance 1, run: true Aug 18 15:37:42 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:42+03:00" level=debug msg="completed challenge" Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5518, instance 1, run: true Aug 18 15:37:42 volumio-77 go-librespot[5433]: time="2024-08-18T15:37:42+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:42 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:42 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5525, instance 1, run: true Aug 18 15:37:42 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:42 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5532, instance 1, run: true Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5539, instance 1, run: true Aug 18 15:37:42 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5546, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5553, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5560, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5567, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5574, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5581, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5588, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5595, instance 1, run: true Aug 18 15:37:43 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5602, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5609, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5616, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5623, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5630, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings Aug 18 15:37:44 volumio-77 volumio[881]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates Aug 18 15:37:44 volumio-77 volumio[881]: info: Received Get System Version Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Aug 18 15:37:44 volumio-77 volumio[881]: info: Received Get System Info Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice Aug 18 15:37:44 volumio-77 volumio[881]: info: Discovery: Getting this device information Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:44 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:44 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5637, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5644, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5651, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5658, instance 1, run: true Aug 18 15:37:44 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5665, instance 1, run: true Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5672, instance 1, run: true Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5679, instance 1, run: true Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5686, instance 1, run: true Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5693, instance 1, run: true Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5700, instance 1, run: true Aug 18 15:37:45 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:45 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18. Aug 18 15:37:45 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:45 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:45 volumio-77 go-librespot[5707]: Librespot-go daemon starting... Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5708, instance 1, run: true Aug 18 15:37:45 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:45+03:00" level=info msg="generated new device id: babcd203546c33119ce8d723ee5caf3ad92ea81c" Aug 18 15:37:45 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:45+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:45 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:45 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:45+03:00" level=debug msg="new websocket client" Aug 18 15:37:45 volumio-77 volumio[881]: info: Connection to go-librespot Websocket established Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5721, instance 1, run: true Aug 18 15:37:45 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5728, instance 1, run: true Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5736, instance 1, run: true Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="zeroconf server listening on port 41617" Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5744, instance 1, run: true Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5751, instance 1, run: true Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="obtained new client token: AABaKGksVGLXbN03jfu8D6qPVRA8lzM3ujEgv07rUbZAwM1+KNDKkPs7y7ZQHXa9RGDRI+lDfIt2S9rCTe/stZWAyvyc1Fv2+CFmaprH2zgphV+ZhUuDRxl4Zn4PaImCf+BV36/6VTinK0lPPxrWjB0+Dy0maOpYAJDzpkdE01Ectkc2KhBn5Ha78eEyPePzwFAutEaV+qWZwWPqTPNvcA/vhzzQfLYUItu+UqY6nxiXoJiJztl4uqAXDW0=" Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5758, instance 1, run: true Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5765, instance 1, run: true Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5772, instance 1, run: true Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5779, instance 1, run: true Aug 18 15:37:46 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5786, instance 1, run: true Aug 18 15:37:46 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:46+03:00" level=debug msg="completed challenge" Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5793, instance 1, run: true Aug 18 15:37:47 volumio-77 go-librespot[5707]: time="2024-08-18T15:37:47+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:47 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:47 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:47 volumio-77 volumio[881]: info: Connection to go-librespot Websocket closed Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5800, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5807, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5814, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5821, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5828, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5835, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5842, instance 1, run: true Aug 18 15:37:47 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5849, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5856, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5863, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5870, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5877, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5884, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5891, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5898, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: Getting Spotify volume Aug 18 15:37:48 volumio-77 volumio[881]: (node:881) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:48 volumio-77 volumio[881]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) Aug 18 15:37:48 volumio-77 volumio[881]: (node:881) 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: 5) Aug 18 15:37:48 volumio-77 volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Aug 18 15:37:48 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5905, instance 1, run: true Aug 18 15:37:48 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:37:48 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:37:49 volumio-77 volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5912, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5919, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5926, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5933, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5940, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5947, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5954, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5961, instance 1, run: true Aug 18 15:37:49 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5968, instance 1, run: true Aug 18 15:37:50 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:50 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:50 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:50 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19. Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5975, instance 1, run: true Aug 18 15:37:50 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:50 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:50 volumio-77 go-librespot[5976]: Librespot-go daemon starting... Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=info msg="generated new device id: e1401c99297aa867296fc67f7cee1bf5928c1b45" Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5989, instance 1, run: true Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 5996, instance 1, run: true Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6003, instance 1, run: true Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6012, instance 1, run: true Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=debug msg="zeroconf server listening on port 41111" Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6019, instance 1, run: true Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6026, instance 1, run: true Aug 18 15:37:50 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:50+03:00" level=debug msg="obtained new client token: AAAFO3/J1IBH9w36HnRokEe6/hyYUbH80HF2fs8057Mmt9KxHX3Bw1hH2cndU90J+sfOb1XOQ0uLR0ahZRdEgowGIWcDP/CWoANCseI+lpvL9vlTOe84DoxnAldlqlTvvf0DEC9fkGPTlcnkMx9HaKOqwXG62MeohANcyZw0Dr+8u7jGiRvWaZZB4mnUglovO7qku/xFEoxB7Rwp5WITXWaswi9Ql5TlexnSpDW280zouEx7j3KaU2GP9rk=" Aug 18 15:37:50 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6033, instance 1, run: true Aug 18 15:37:51 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:51+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6040, instance 1, run: true Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6047, instance 1, run: true Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6054, instance 1, run: true Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6061, instance 1, run: true Aug 18 15:37:51 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:51+03:00" level=debug msg="completed challenge" Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6068, instance 1, run: true Aug 18 15:37:51 volumio-77 go-librespot[5976]: time="2024-08-18T15:37:51+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:51 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:51 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6075, instance 1, run: true Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6082, instance 1, run: true Aug 18 15:37:51 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6089, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6097, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6104, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6111, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6118, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6125, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6132, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6139, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6146, instance 1, run: true Aug 18 15:37:52 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6153, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6160, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:53 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6167, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6174, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6181, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6188, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6195, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6202, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6209, instance 1, run: true Aug 18 15:37:53 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6216, instance 1, run: true Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6223, instance 1, run: true Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6230, instance 1, run: true Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6237, instance 1, run: true Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6244, instance 1, run: true Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6251, instance 1, run: true Aug 18 15:37:54 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:54 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20. Aug 18 15:37:54 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:54 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:54 volumio-77 go-librespot[6258]: Librespot-go daemon starting... Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6259, instance 1, run: true Aug 18 15:37:54 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:54+03:00" level=info msg="generated new device id: ea82234ac12a52df6a4a5ced9cb597e36ea0cb95" Aug 18 15:37:54 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:54+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6272, instance 1, run: true Aug 18 15:37:54 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6279, instance 1, run: true Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6287, instance 1, run: true Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6294, instance 1, run: true Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="zeroconf server listening on port 40597" Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6301, instance 1, run: true Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="obtained new client token: AADiZmecEUzRETyGw2xvmnxD3fp5UlMempUwDsNzDgVjFTMIm0afagbMjV7yduN7o53HhY5I+4NOyInEL0iFf9/jPUaoIbouujcno3JY5+2RINgwdkdViHrtYLTnC0fddIMovONlUO3NTJSp0dV7BWqFvOiwBMWy7qfOrRXhsF8nrzvs2v7QmcMa/FW3AYZE3AUroCt38KphZD2hfy2DFzYg9zxF42yOGvvjwjw1OozYxb2Thhb7IhFfpvU=" Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6308, instance 1, run: true Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="completed keyexchange" Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6315, instance 1, run: true Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6322, instance 1, run: true Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6329, instance 1, run: true Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6336, instance 1, run: true Aug 18 15:37:55 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6343, instance 1, run: true Aug 18 15:37:55 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:55+03:00" level=debug msg="completed challenge" Aug 18 15:37:56 volumio-77 go-librespot[6258]: time="2024-08-18T15:37:56+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:37:56 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:37:56 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6350, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:56 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6357, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6364, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6371, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6378, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6385, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6392, instance 1, run: true Aug 18 15:37:56 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6399, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6406, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6413, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6420, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6427, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6434, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6441, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6448, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6455, instance 1, run: true Aug 18 15:37:57 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6462, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6469, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6476, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6483, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6490, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6497, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6504, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6511, instance 1, run: true Aug 18 15:37:58 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6518, instance 1, run: true Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6525, instance 1, run: true Aug 18 15:37:59 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:37:59 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 21. Aug 18 15:37:59 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:37:59 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:37:59 volumio-77 go-librespot[6533]: Librespot-go daemon starting... Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6534, instance 1, run: true Aug 18 15:37:59 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:37:59 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=info msg="generated new device id: 4f290389b1429977e2e3a29cadba8eb77a74576c" Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6547, instance 1, run: true Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6554, instance 1, run: true Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6562, instance 1, run: true Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="zeroconf server listening on port 34449" Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6569, instance 1, run: true Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6576, instance 1, run: true Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="obtained new client token: AAD9Wttg7le1vSuOG9EiJeK8oGzncDp61vSgHxaiSdR6Y/Z9/JcQv1A3+plxXUnaMaiutxyYAJKE1ZJajeZ4Ad7tu85O9WAkUnOirT9QIPID2zsgltI5u6O73ossjCDkOID4nPqEiQSyBM+zF3/1YcrxX8KL8xzUqa/lHQFm1l5i6mOBK3/d/CaC4Fr9qiUMCkcSSeKmywHiBwGAtYLGcIu8H9o8L5+5Nd+vmrPS0o2aYmZ9b25NHo8agkY=" Aug 18 15:37:59 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6583, instance 1, run: true Aug 18 15:37:59 volumio-77 go-librespot[6533]: time="2024-08-18T15:37:59+03:00" level=debug msg="completed keyexchange" Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6590, instance 1, run: true Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6597, instance 1, run: true Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6604, instance 1, run: true Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6611, instance 1, run: true Aug 18 15:38:00 volumio-77 go-librespot[6533]: time="2024-08-18T15:38:00+03:00" level=debug msg="completed challenge" Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6618, instance 1, run: true Aug 18 15:38:00 volumio-77 go-librespot[6533]: time="2024-08-18T15:38:00+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:38:00 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:38:00 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6625, instance 1, run: true Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6632, instance 1, run: true Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6639, instance 1, run: true Aug 18 15:38:00 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6646, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6653, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6660, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6667, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6674, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6681, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6688, instance 1, run: true Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6699, instance 1, run: true Aug 18 15:38:01 volumio-77 volumiologrotate[541]: ls: cannot access '/var/log/samba/log.wb-VOLUMIO': No such file or directory Aug 18 15:38:01 volumio-77 volumiologrotate[541]: ls: cannot access '77': No such file or directory Aug 18 15:38:01 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6727, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6750, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6757, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:38:02 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6764, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6771, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6778, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6785, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6792, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6799, instance 1, run: true Aug 18 15:38:02 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6806, instance 1, run: true Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6813, instance 1, run: true Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6820, instance 1, run: true Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6827, instance 1, run: true Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6834, instance 1, run: true Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6841, instance 1, run: true Aug 18 15:38:03 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:38:03 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 22. Aug 18 15:38:03 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6849, instance 1, run: true Aug 18 15:38:03 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:38:03 volumio-77 go-librespot[6848]: Librespot-go daemon starting... Aug 18 15:38:03 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:03+03:00" level=info msg="generated new device id: 07f0d1f5d460836dcb9677557e9d1f8b191d358c" Aug 18 15:38:03 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:03+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6862, instance 1, run: true Aug 18 15:38:03 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6869, instance 1, run: true Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6876, instance 1, run: true Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6884, instance 1, run: true Aug 18 15:38:04 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:04+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew4.spotify.com:443 ap-gae2.spotify.com:80]" Aug 18 15:38:04 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:04+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443 gae2-dealer.spotify.com:443]" Aug 18 15:38:04 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:04+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443 gae2-spclient.spotify.com:443]" Aug 18 15:38:04 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:04+03:00" level=debug msg="zeroconf server listening on port 36997" Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6892, instance 1, run: true Aug 18 15:38:04 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:04+03:00" level=debug msg="obtained new client token: AAAQK7pka0pBC1vfx6LfMWTvJiZdPBM+f4v/zf2HtvvRIAUQQK08gKnMNb1UHNyVgwzuUV3KxLzkrl/LqJJyUnsP15xOFlMAgGOiGTOEDMUunbLuiMEj2nilt/YGkUFEUlot/JFGPZ7/mirfoctamK7febu/6YT/We498moRg7vSRLuH1FvwsAuUonzG0HtOXTCiljYuar8ONmu1xxhUHagnegviBfgXeZZP2KsbBFWwb2T6niIPfebjwOM=" Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6899, instance 1, run: true Aug 18 15:38:04 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:04+03:00" level=debug msg="completed keyexchange" Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6906, instance 1, run: true Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6913, instance 1, run: true Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6920, instance 1, run: true Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6927, instance 1, run: true Aug 18 15:38:04 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6934, instance 1, run: true Aug 18 15:38:05 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:05+03:00" level=debug msg="completed challenge" Aug 18 15:38:05 volumio-77 go-librespot[6848]: time="2024-08-18T15:38:05+03:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials" Aug 18 15:38:05 volumio-77 systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE Aug 18 15:38:05 volumio-77 systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'. Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6941, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:38:05 volumio-77 volumio[881]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879 Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6948, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6955, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6962, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6969, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6976, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6983, instance 1, run: true Aug 18 15:38:05 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6990, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 6997, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7004, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7011, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7018, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7025, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7032, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7039, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7046, instance 1, run: true Aug 18 15:38:06 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7053, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7060, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7067, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7074, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7081, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7088, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7095, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7102, instance 1, run: true Aug 18 15:38:07 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7109, instance 1, run: true Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7116, instance 1, run: true Aug 18 15:38:08 volumio-77 systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart. Aug 18 15:38:08 volumio-77 systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 23. Aug 18 15:38:08 volumio-77 systemd[1]: Stopped go-librespot Daemon. Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7124, instance 1, run: true Aug 18 15:38:08 volumio-77 systemd[1]: Started go-librespot Daemon. Aug 18 15:38:08 volumio-77 go-librespot[7123]: Librespot-go daemon starting... Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=info msg="generated new device id: a35a159b7bc8d25c2baa9688eb4bb8c4215eb7e8" Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="stored credentials found for qsnt4btw9g0tgff8k57r1n75x" Aug 18 15:38:08 volumio-77 volumio[881]: info: Initializing connection to go-librespot Websocket Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="new websocket client" Aug 18 15:38:08 volumio-77 volumio[881]: info: Connection to go-librespot Websocket established Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7137, instance 1, run: true Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7144, instance 1, run: true Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7152, instance 1, run: true Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="fetched new accesspoints: [ap-gew1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew1.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]" Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="fetched new dealers: [gew1-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]" Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="fetched new spclients: [gew1-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]" Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7159, instance 1, run: true Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="zeroconf server listening on port 38289" Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7166, instance 1, run: true Aug 18 15:38:08 volumio-77 go-librespot[7123]: time="2024-08-18T15:38:08+03:00" level=debug msg="obtained new client token: AACyRlKIIO3MlZxseXIzPvd3mCKJXhLl25357WhdzlcASCABBsCgiyBrGLEYd+HzEJmsklYYHr6vdOCVZnzVuskqSwfhG16WfYpoBHYykQ4jbA4MwJCvnuDxAsakYS5xOTjbTT1WOya8ltDL5UyoMqI2cjV2kUZqd5f2/rzN4nZkg1WQ+U+GLHl45d/Cu6iC/bdr5YquTwMfBjoiltRzCNtEiGos3oS9gijqmo0N0A9tvt5hrA1IGnq3qUY=" Aug 18 15:38:08 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7173, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7180, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7187, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7194, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7201, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7208, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7215, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7222, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7229, instance 1, run: true Aug 18 15:38:09 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7236, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7243, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7250, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7257, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7264, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7271, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7278, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7285, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7292, instance 1, run: true Aug 18 15:38:10 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7299, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7306, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7313, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: Getting Spotify volume Aug 18 15:38:11 volumio-77 volumio[881]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 10 Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7320, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: CoreCommandRouter::volumioGetState Aug 18 15:38:11 volumio-77 volumio[881]: info: CorePlayQueue::getTrack 0 Aug 18 15:38:11 volumio-77 volumio[881]: SPOTIFY: RECEIVED VOLUMIO VOLUME 90 Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7327, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7334, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7341, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7348, instance 1, run: true Aug 18 15:38:11 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7355, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7362, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7369, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7376, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7383, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7390, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7397, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7404, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7411, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7418, instance 1, run: true Aug 18 15:38:12 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7425, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7432, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7439, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7446, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7453, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7460, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7467, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7474, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7481, instance 1, run: true Aug 18 15:38:13 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7488, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7495, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7502, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: Preload queue cleared Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7509, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7516, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7523, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7530, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7537, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7544, instance 1, run: true Aug 18 15:38:14 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7551, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7558, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7565, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7572, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7579, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7586, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7593, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7600, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7607, instance 1, run: true Aug 18 15:38:15 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7614, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7621, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7628, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7635, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7642, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7649, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7656, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7663, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7670, instance 1, run: true Aug 18 15:38:16 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7677, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7684, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7691, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7698, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7705, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7712, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7719, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7726, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7733, instance 1, run: true Aug 18 15:38:17 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7740, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7747, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7754, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7761, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7768, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7775, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7782, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7789, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7796, instance 1, run: true Aug 18 15:38:18 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 18 15:38:18 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7803, instance 1, run: true Aug 18 15:38:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7810, instance 1, run: true Aug 18 15:38:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7817, instance 1, run: true Aug 18 15:38:19 volumio-77 volumio[881]: info: Preload queue cleared Aug 18 15:38:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7824, instance 1, run: true Aug 18 15:38:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7831, instance 1, run: true Aug 18 15:38:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7838, instance 1, run: true Aug 18 15:38:19 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7845, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7852, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7859, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7866, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7873, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7880, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7887, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7894, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7901, instance 1, run: true Aug 18 15:38:20 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7908, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: Preload queue cleared Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7915, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: Preload queue cleared Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7922, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7929, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7936, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7943, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7950, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7957, instance 1, run: true Aug 18 15:38:21 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7964, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7971, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7978, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7985, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7992, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 7999, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8006, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8013, instance 1, run: true Aug 18 15:38:22 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8020, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8027, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8034, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8041, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8048, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8055, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8062, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: CoreCommandRouter::executeOnPlugin: upnp_browser , handleBrowseUri Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8069, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8076, instance 1, run: true Aug 18 15:38:23 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8083, instance 1, run: true Aug 18 15:38:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8090, instance 1, run: true Aug 18 15:38:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8097, instance 1, run: true Aug 18 15:38:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8105, instance 1, run: true Aug 18 15:38:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8112, instance 1, run: true Aug 18 15:38:24 volumio-77 volumio[881]: info: camilladsp spawned new process with pid 8119, instance 1, run: true Aug 18 15:38:24 volumio-77 volumio[881]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 18 15:38:24 volumio-77 volumio[881]: TypeError: Cannot read property 'length' of undefined Aug 18 15:38:24 volumio-77 volumio[881]: at /volumio/app/plugins/music_service/upnp_browser/index.js:341:25 Aug 18 15:38:24 volumio-77 volumio[881]: at /volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:131:13 Aug 18 15:38:24 volumio-77 volumio[881]: at Parser. (/volumio/node_modules/xml2js/lib/parser.js:304:18) Aug 18 15:38:24 volumio-77 volumio[881]: at Parser.emit (events.js:315:20) Aug 18 15:38:24 volumio-77 volumio[881]: at SAXParser.onclosetag (/volumio/node_modules/xml2js/lib/parser.js:262:26) Aug 18 15:38:24 volumio-77 volumio[881]: at emit (/volumio/node_modules/sax/lib/sax.js:624:35) Aug 18 15:38:24 volumio-77 volumio[881]: at emitNode (/volumio/node_modules/sax/lib/sax.js:629:5) Aug 18 15:38:24 volumio-77 volumio[881]: at closeTag (/volumio/node_modules/sax/lib/sax.js:889:7) Aug 18 15:38:24 volumio-77 volumio[881]: at SAXParser.write (/volumio/node_modules/sax/lib/sax.js:1436:13) Aug 18 15:38:24 volumio-77 volumio[881]: at Parser.exports.Parser.Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:323:31) Aug 18 15:38:24 volumio-77 volumio[881]: at Parser.parseString (/volumio/node_modules/xml2js/lib/parser.js:5:59) Aug 18 15:38:24 volumio-77 volumio[881]: at Object.exports.parseString (/volumio/node_modules/xml2js/lib/parser.js:369:19) Aug 18 15:38:24 volumio-77 volumio[881]: at IncomingMessage. (/volumio/app/plugins/music_service/upnp_browser/dlna-browser.js:92:15) Aug 18 15:38:24 volumio-77 volumio[881]: at IncomingMessage.emit (events.js:327:22) Aug 18 15:38:24 volumio-77 volumio[881]: at endReadableNT (internal/streams/readable.js:1327:12) Aug 18 15:38:24 volumio-77 volumio[881]: at processTicksAndRejections (internal/process/task_queues.js:80:21) Aug 18 15:38:24 volumio-77 volumio[881]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Aug 18 15:38:25 volumio-77 sudo[8135]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-08-18 15:37 Aug 18 15:38:25 volumio-77 sudo[8135]: 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="7f9f1bf001add7a8b19a4516e3c74ef598b2730d" VOLUMIO_FE_VERSION="614d7b13ffdcb0cc5a6072e7d06f59d52e323e71" VOLUMIO_FE3_VERSION="570aaed971c1346d45d1172dc445b086b258c6d1" VOLUMIO_BE_VERSION="512433c3e91cdaed7ecd2808b21adeffc2137d7f" VOLUMIO_ARCH="arm" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Wed 21 Feb 2024 09:37:22 PM CET" VOLUMIO_VERSION="3.631" VOLUMIO_HARDWARE="pi" VOLUMIO_DEVICENAME="Raspberry Pi" VOLUMIO_HASH="fdd9dd1169c06c1ad0a30ddd24c91b6b"