-- Logs begin at Thu 2019-02-14 11:11:58 CET, end at Tue 2024-11-26 00:00:41 CET. --
Nov 25 23:59:07 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:08 volumio volumio[1205]: error: Failed LSINFO: Error: [50@0] {lsinfo} No such directory
Nov 25 23:59:08 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 25 23:59:08 volumio volumio-remote-updater[671]: [2024-11-25 23:59:08] [connect] Successful connection
Nov 25 23:59:08 volumio volumio-remote-updater[671]: [2024-11-25 23:59:08] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1732575548 101
Nov 25 23:59:08 volumio volumio[1205]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Engine version: 4 Transport: websocket Total Clients: 66
Nov 25 23:59:08 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:08 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:08 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:08 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:09 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:09 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:10 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:10 volumio sudo[1384]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Nov 25 23:59:10 volumio sudo[1384]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:10 volumio sudo[1384]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:10 volumio sudo[1386]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Nov 25 23:59:10 volumio sudo[1386]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:10 volumio sudo[1386]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:10 volumio sudo[1390]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Nov 25 23:59:10 volumio sudo[1390]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2.
Nov 25 23:59:10 volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Nov 25 23:59:10 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:10 volumio sudo[1390]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:10 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:10 volumio volumio[1205]: info: Upmpdcli Daemon Started
Nov 25 23:59:10 volumio go-librespot[1393]: Librespot-go daemon starting...
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01:00" level=info msg="generated new device id: 8b302d7114ea74a09859f4af6f2dd758b0de5114"
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:10 volumio volumio[1392]: Generating RSA private key, 4096 bit long modulus (2 primes)
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01: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]"
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01: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]"
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01: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]"
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01:00" level=debug msg="zeroconf server listening on port 46149"
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01:00" level=debug msg="obtained new client token: AACKp7xA7kErgG5icGQFGuziXlYltBH8DnPWIfLfxkfF0Z/wCHmFguaeI+KRLyx2y5+JLM9sP84ztMf8ZzcuhL1pDVuqIkO1Ukatn+s8TEaU1GhTJaCdyhw1nWwKUrqaGd/deKv6oIDMG9POF+GzDi0LMYLJwd3aRv2O2lB/VbSqe4k7qy4ctOh1U1yDAWBSoqWooV8JpykxfwWT3v9K3yn0BN4vHSQ43YM4dI+1NwbIqc7N0CTD8HPGEZ9Oew=="
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:10 volumio go-librespot[1393]: time="2024-11-25T23:59:10+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:10 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:10 volumio sudo[1417]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Nov 25 23:59:10 volumio sudo[1417]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:10 volumio sudo[1417]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:10 volumio sudo[1419]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Nov 25 23:59:10 volumio sudo[1419]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:10 volumio sudo[1419]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:11 volumio volumio[1205]: verbose: New Socket.io Connection to 10.0.10.20 from 10.0.100.9 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 67
Nov 25 23:59:11 volumio sudo[1423]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Nov 25 23:59:11 volumio sudo[1423]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:11 volumio sudo[1423]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio sudo[1425]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Nov 25 23:59:11 volumio sudo[1425]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:11 volumio sudo[1425]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetVisibleSources
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: Listing playlists
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: verbose: New Socket.io Connection to 10.0.10.20 from 10.0.100.9 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 67
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetVisibleSources
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: Listing playlists
Nov 25 23:59:11 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:11 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:11 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:11 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:11 volumio go-librespot[1393]: time="2024-11-25T23:59:11+01:00" level=debug msg="new websocket client"
Nov 25 23:59:11 volumio volumio[1205]: info: Connection to go-librespot Websocket established
Nov 25 23:59:11 volumio go-librespot[1393]: time="2024-11-25T23:59:11+01:00" level=debug msg="completed challenge"
Nov 25 23:59:11 volumio go-librespot[1393]: time="2024-11-25T23:59:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:11 volumio volumio[1205]: info: Connection to go-librespot Websocket closed
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Nov 25 23:59:11 volumio volumio[1205]: info: Adding plugin bluetooth to MyMusic Plugins
Nov 25 23:59:11 volumio volumio[1205]: info: Adding plugin multiroom to MyMusic Plugins
Nov 25 23:59:11 volumio volumio[1205]: info: Adding plugin metavolumio to MyMusic Plugins
Nov 25 23:59:11 volumio volumio[1205]: info: Adding plugin cd_controller to MyMusic Plugins
Nov 25 23:59:11 volumio volumio[1205]: info: Adding plugin smart_inputs to MyMusic Plugins
Nov 25 23:59:11 volumio volumio[1205]: info: Adding plugin tidalconnect to MyMusic Plugins
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:11 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:11 volumio volumio[1205]: info: Starting MyVolumio Remote Streaming Endpoints
Nov 25 23:59:11 volumio volumio[1205]: info: MyVolumio login type: Token
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Nov 25 23:59:11 volumio volumio[1205]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Nov 25 23:59:12 volumio volumio[1205]: info: Starting Streaming Service Transparent Proxy
Nov 25 23:59:12 volumio volumio[1205]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Nov 25 23:59:12 volumio volumio[1205]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Nov 25 23:59:12 volumio volumio[1205]: info: Streaming services startup
Nov 25 23:59:12 volumio volumio[1205]: info: Starting Streaming Daemon
Nov 25 23:59:12 volumio sudo[1435]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Nov 25 23:59:12 volumio sudo[1435]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:12 volumio sudo[1435]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:12 volumio volumio[1205]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Nov 25 23:59:12 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:12 volumio volumio[1205]: error: Cannot start Volumio Streaming Daemon
Nov 25 23:59:12 volumio volumio[1205]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Nov 25 23:59:12 volumio volumio[1205]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Nov 25 23:59:12 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:12 volumio volumio[1205]: STREAMING PROXY: Starting server on port 3245
Nov 25 23:59:12 volumio volumio[1205]: Node JS runtime: 14
Nov 25 23:59:12 volumio volumio[1205]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 25 23:59:13 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:13 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:13 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:13 volumio volumio[1205]: info: MyVolumio token set successfully
Nov 25 23:59:13 volumio volumio[1205]: info: MYVOLUMIO: Adding device
Nov 25 23:59:13 volumio volumio[1205]: info: MYVOLUMIO: Evaluating Server
Nov 25 23:59:13 volumio volumio[1205]: info: MyVolumio status changed
Nov 25 23:59:13 volumio volumio[1205]: info: Streaming services startup
Nov 25 23:59:13 volumio volumio[1205]: info: Starting Streaming Daemon
Nov 25 23:59:13 volumio volumio[1205]: info: Removing browser output: myVolumio user plan is not superstar
Nov 25 23:59:13 volumio volumio[1205]: info: Removing audio output:
Nov 25 23:59:13 volumio volumio[1205]: info: Stoppping Tunnel 1
Nov 25 23:59:13 volumio sudo[1460]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Nov 25 23:59:13 volumio sudo[1460]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:13 volumio sudo[1463]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Nov 25 23:59:13 volumio sudo[1463]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:13 volumio sudo[1460]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:13 volumio volumio[1205]: error: Cannot start Volumio Streaming Daemon
Nov 25 23:59:13 volumio volumio[1205]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Nov 25 23:59:13 volumio volumio[1205]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Nov 25 23:59:13 volumio sudo[1463]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:13 volumio volumio[1205]: info: Remote SSH Stopped
Nov 25 23:59:13 volumio volumio[1392]: .............................................................++++
Nov 25 23:59:13 volumio volumio[1205]: info: Setting Geolocation for MyVolumio to eu7
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:13 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:14 volumio volumio[1205]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Nov 25 23:59:14 volumio volumio[1205]: info: Getting Spotify volume
Nov 25 23:59:14 volumio volumio[1205]: (node:1205) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:14 volumio volumio[1205]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16)
Nov 25 23:59:14 volumio volumio[1205]: (Use `node --trace-warnings ...` to show where the warning was created)
Nov 25 23:59:14 volumio volumio[1205]: (node:1205) 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: 1)
Nov 25 23:59:14 volumio volumio[1205]: (node:1205) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
Nov 25 23:59:14 volumio volumio[1205]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 67
Nov 25 23:59:14 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:14 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:14 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:14 volumio volumio[1205]: SPOTIFY: SPOTIFY VOLUME undefined
Nov 25 23:59:14 volumio volumio[1205]: SPOTIFY: VOLUMIO VOLUME 68
Nov 25 23:59:14 volumio volumio[1205]: info: Aligning Spotify Volume to Volumio Volume
Nov 25 23:59:14 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:14 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:14 volumio volumio[1205]: info: Setting Spotify Volume from Volumio: 68
Nov 25 23:59:14 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:14 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3.
Nov 25 23:59:14 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:14 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:14 volumio go-librespot[1465]: Librespot-go daemon starting...
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01:00" level=info msg="generated new device id: eb9c710fbf487a3bc7f8a1459dad4ed82ad8f854"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01: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]"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01: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]"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01: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]"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01:00" level=debug msg="zeroconf server listening on port 36549"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01:00" level=debug msg="obtained new client token: AAAnO7FBLZuNrdzXvOm7NIZfurpZy69vFUe2aXVi+u7NQW2pDqNAVCQF+rx4gKq4tMDG9BTfGEdA0/s5jVljiLAp7L07yWrWzoiXTZ3xeJMyyYeLa/I1rob5/148I3MrLckB6TwovX7kJv8d7+v0q3qMaPrStZmVZNQCFxshdyEEU9dL/RGzx4gQwLZQrX4KTGECVDh8m0FwtXCwtcfG5elGi6B1dcsrFdSdWHW3JUp9i4kaVBGTWGgi/1tFpw=="
Nov 25 23:59:14 volumio volumio[1205]: info: Updating MyVolumio device info
Nov 25 23:59:14 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:14 volumio go-librespot[1465]: time="2024-11-25T23:59:14+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:15 volumio go-librespot[1465]: time="2024-11-25T23:59:15+01:00" level=debug msg="completed challenge"
Nov 25 23:59:15 volumio go-librespot[1465]: time="2024-11-25T23:59:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:15 volumio volumio[1205]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Nov 25 23:59:15 volumio volumio[1392]: ........................................++++
Nov 25 23:59:15 volumio volumio[1392]: e is 65537 (0x010001)
Nov 25 23:59:15 volumio volumio[1392]: writing RSA key
Nov 25 23:59:15 volumio volumio[1205]: SPOTIFY: SETTING SPOTIFY VOLUME 68
Nov 25 23:59:15 volumio volumio[1205]: info: Sending Spotify command with payload to local API: /player/volume
Nov 25 23:59:15 volumio volumio[1205]: error: Failed to send command to Spotify local API: /player/volume: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:17 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 25 23:59:17 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:17 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:17 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:17 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:17 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:17 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:17 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:17 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:17 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:18 volumio volumio[1205]: info: MYVOLUMIO: Adding device
Nov 25 23:59:18 volumio volumio[1205]: info: MYVOLUMIO: Evaluating Server
Nov 25 23:59:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4.
Nov 25 23:59:18 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:18 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:18 volumio go-librespot[1503]: Librespot-go daemon starting...
Nov 25 23:59:18 volumio volumio[1205]: info: Setting Geolocation for MyVolumio to eu4
Nov 25 23:59:18 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01:00" level=info msg="generated new device id: f6b67ab969eefc754e4826b92f10b4d7a98674ea"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01: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]"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01: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]"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01: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]"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01:00" level=debug msg="zeroconf server listening on port 43453"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01:00" level=debug msg="obtained new client token: AADsyP+9OqCsySr46Ss8vh/YViQPdrlEyBMV5UlX2B7p0iotZmUhmiUBIeyj59ERJl06jY1fp5WYBRmBetEiMZca3wPzg9Dp1f3kgM6p70s8/sBcAkmWrWW2t+IvZaMqb2nDnp19xoIkRQpVje2DQrJlfOqWQTkMm/7cRkZtFGFtl10dHGth+rkbqHMoNTmiu4UqNAYia0bF5zC89uvwL1GrArMjKA3F2fPO2s+HhtrK+SIJ9pZpmiQDkWbw4A=="
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:18 volumio go-librespot[1503]: time="2024-11-25T23:59:18+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:19 volumio volumio[1205]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Nov 25 23:59:19 volumio go-librespot[1503]: time="2024-11-25T23:59:19+01:00" level=debug msg="completed challenge"
Nov 25 23:59:19 volumio go-librespot[1503]: time="2024-11-25T23:59:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:19 volumio volumio[1205]: info: Updating MyVolumio device info
Nov 25 23:59:19 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:20 volumio volumio[1205]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Nov 25 23:59:20 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:20 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:21 volumio sudo[1512]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Nov 25 23:59:21 volumio sudo[1512]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:21 volumio sudo[1512]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:21 volumio sudo[1514]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Nov 25 23:59:21 volumio sudo[1514]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 25 23:59:21 volumio sudo[1514]: pam_unix(sudo:session): session closed for user root
Nov 25 23:59:21 volumio volumio[1205]: verbose: New Socket.io Connection to 10.0.10.20 from 10.0.100.9 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 68
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:21 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:21 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetVisibleSources
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Nov 25 23:59:21 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:21 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: Listing playlists
Nov 25 23:59:21 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:21 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: Received Get System Info
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 25 23:59:21 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 25 23:59:21 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:21 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: AutoStart - Plugin is starting
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioGetQueue
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::getQueue
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getQueue
Nov 25 23:59:22 volumio volumio[1205]: info: AutoStart - start playing
Nov 25 23:59:22 volumio volumio[1205]: info: AutoStart - start playing with no specific position
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPlay
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::play index 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::setConsumeUpdateService undefined
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::stop
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::setConsumeUpdateService undefined
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::play index undefined
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::setConsumeUpdateService undefined
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::startPlaybackTimer
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::clearAddPlayTracks INTERNAL/music/guitar-lounge.mp3
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand stop
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand stop took 3 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand clear
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces system playlist update
Nov 25 23:59:22 volumio volumio[1205]: info: Ignoring MPD Status Update
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand clear took 1 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand add "INTERNAL/music/guitar-lounge.mp3"
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces system playlist update
Nov 25 23:59:22 volumio volumio[1205]: info: Ignoring MPD Status Update
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces system playlist update
Nov 25 23:59:22 volumio volumio[1205]: info: Ignoring MPD Status Update
Nov 25 23:59:22 volumio volumio[1205]: error: updateQueue error: null
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces system playlist update
Nov 25 23:59:22 volumio volumio[1205]: info: Ignoring MPD Status Update
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 3ms
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand add "INTERNAL/music/guitar-lounge.mp3" took 2 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 2ms
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 1ms
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand play
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces system playlist update
Nov 25 23:59:22 volumio volumio[1205]: info: Ignoring MPD Status Update
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces system playlist update
Nov 25 23:59:22 volumio volumio[1205]: info: Ignoring MPD Status Update
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 3ms
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand play took 2 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 1ms
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 1ms
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces state update: player
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::getState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand status
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces state update: player
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::getState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand status
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces state update: player
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::getState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand status
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand status took 60 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand status took 60 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand status took 58 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces state update: player
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::getState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand status
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand playlistinfo took 1 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand playlistinfo took 1 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand playlistinfo took 1 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseTrackInfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseTrackInfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseTrackInfo
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::servicePushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: STATE SERVICE {"status":"play","position":0,"seek":0,"duration":130,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"guitar-lounge.mp3","artist":null,"album":null,"uri":"INTERNAL/music/guitar-lounge.mp3","trackType":"mp3"}
Nov 25 23:59:22 volumio volumio[1205]: verbose: CURRENT POSITION 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState stateService play
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState currentStatus stop
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::servicePushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: STATE SERVICE {"status":"play","position":0,"seek":483,"duration":130,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"guitar-lounge.mp3","artist":null,"album":null,"uri":"INTERNAL/music/guitar-lounge.mp3","trackType":"mp3"}
Nov 25 23:59:22 volumio volumio[1205]: verbose: CURRENT POSITION 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState stateService play
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState currentStatus play
Nov 25 23:59:22 volumio volumio[1205]: info: Received an update from plugin. extracting info from payload
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::servicePushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: STATE SERVICE {"status":"play","position":0,"seek":483,"duration":130,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"guitar-lounge.mp3","artist":null,"album":null,"uri":"INTERNAL/music/guitar-lounge.mp3","trackType":"mp3"}
Nov 25 23:59:22 volumio volumio[1205]: verbose: CURRENT POSITION 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState stateService play
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState currentStatus play
Nov 25 23:59:22 volumio volumio[1205]: info: Received an update from plugin. extracting info from payload
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 72ms
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 75ms
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 75ms
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces state update: player
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::getState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand status
Nov 25 23:59:22 volumio volumio[1205]: info:
Nov 25 23:59:22 volumio volumio[1205]: ---------------------------- MPD announces state update: player
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::getState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand status
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand status took 15 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand status took 1 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand status took 0 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseState
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::sendMpdCommand playlistinfo
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand playlistinfo took 3 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand playlistinfo took 3 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: info: sendMpdCommand playlistinfo took 3 milliseconds
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseTrackInfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseTrackInfo
Nov 25 23:59:22 volumio volumio[1205]: verbose: ControllerMpd::parseTrackInfo
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::servicePushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: STATE SERVICE {"status":"play","position":0,"seek":986,"duration":130,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"guitar-lounge.mp3","artist":null,"album":null,"uri":"INTERNAL/music/guitar-lounge.mp3","trackType":"mp3"}
Nov 25 23:59:22 volumio volumio[1205]: verbose: CURRENT POSITION 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState stateService play
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState currentStatus play
Nov 25 23:59:22 volumio volumio[1205]: info: Received an update from plugin. extracting info from payload
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::servicePushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: STATE SERVICE {"status":"play","position":0,"seek":986,"duration":130,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"guitar-lounge.mp3","artist":null,"album":null,"uri":"INTERNAL/music/guitar-lounge.mp3","trackType":"mp3"}
Nov 25 23:59:22 volumio volumio[1205]: verbose: CURRENT POSITION 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState stateService play
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState currentStatus play
Nov 25 23:59:22 volumio volumio[1205]: info: Received an update from plugin. extracting info from payload
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: ControllerMpd::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::servicePushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: verbose: STATE SERVICE {"status":"play","position":0,"seek":986,"duration":130,"samplerate":"48 kHz","bitdepth":"24 bit","channels":2,"random":false,"updatedb":false,"repeat":false,"bitrate":"256 Kbps","isStreaming":false,"title":"guitar-lounge.mp3","artist":null,"album":null,"uri":"INTERNAL/music/guitar-lounge.mp3","trackType":"mp3"}
Nov 25 23:59:22 volumio volumio[1205]: verbose: CURRENT POSITION 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState stateService play
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::syncState currentStatus play
Nov 25 23:59:22 volumio volumio[1205]: info: Received an update from plugin. extracting info from payload
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: CoreStateMachine::pushState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioPushState
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 32ms
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 17ms
Nov 25 23:59:22 volumio volumio[1205]: info: ------------------------------ 18ms
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Nov 25 23:59:22 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:22 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:22 volumio go-librespot[1525]: Librespot-go daemon starting...
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01:00" level=info msg="generated new device id: f5a8e28862557d968c998637ad88ca1b1079aabe"
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01: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]"
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01: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]"
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01: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]"
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01:00" level=debug msg="zeroconf server listening on port 33285"
Nov 25 23:59:22 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:22 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01:00" level=debug msg="obtained new client token: AADhXla8IJycgQVHIYvgk1hmdKCKBe7Yeh+u5FFWe0mG2I4nyWZXVzzICOR8FSHfVjEWI8S+A8KfAeKF29h5Z7/Cb61twLLlw1gpZh0Dx+Of6JGqwRGKC/7Ns4gBqzNpF9aub/kmEnmt2zzO990MF5+vZooIXVS6a76PeSPZIySwmWgr4+SAWjk+rOfEcdq5caLbAtgQfQbMDl6G63fWyOXBPZmlVj9PynZwMm/4azfN/pV98e1Pj5mQYnFIpQ=="
Nov 25 23:59:22 volumio go-librespot[1525]: time="2024-11-25T23:59:22+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:23 volumio go-librespot[1525]: time="2024-11-25T23:59:23+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:23 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:23 volumio go-librespot[1525]: time="2024-11-25T23:59:23+01:00" level=debug msg="new websocket client"
Nov 25 23:59:23 volumio volumio[1205]: info: Connection to go-librespot Websocket established
Nov 25 23:59:23 volumio go-librespot[1525]: time="2024-11-25T23:59:23+01:00" level=debug msg="completed challenge"
Nov 25 23:59:23 volumio go-librespot[1525]: time="2024-11-25T23:59:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:23 volumio volumio[1205]: info: Connection to go-librespot Websocket closed
Nov 25 23:59:26 volumio volumio[1205]: info: Getting Spotify volume
Nov 25 23:59:26 volumio volumio[1205]: (node:1205) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:26 volumio volumio[1205]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16)
Nov 25 23:59:26 volumio volumio[1205]: (node:1205) 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: 2)
Nov 25 23:59:26 volumio volumio[1205]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 68
Nov 25 23:59:26 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:26 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:26 volumio volumio[1205]: SPOTIFY: RECEIVED VOLUMIO VOLUME 68
Nov 25 23:59:26 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:26 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:26 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:26 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Nov 25 23:59:26 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:26 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:26 volumio go-librespot[1543]: Librespot-go daemon starting...
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01:00" level=info msg="generated new device id: 8570902da6e8d418adf7086d2c5042ccdad53085"
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01: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]"
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01: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]"
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01: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]"
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01:00" level=debug msg="zeroconf server listening on port 40219"
Nov 25 23:59:26 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Nov 25 23:59:26 volumio volumio[1205]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 68
Nov 25 23:59:26 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 25 23:59:26 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01:00" level=debug msg="obtained new client token: AAB2x7HhtRPaHALjHlTvcd/+m+4fvcG2hmxTTESEtC0cv0dZUfVr9Gtjw0WGq+SCKhgrcjwJH7enHqiugwsHAQq2kGsFRjho/K9yGxrCGWUf+8HFyXmwcDUIxNurwtcGRcgRs/NNERBwuDjPBoiqc/qmilm2340c4vRL+jA39EaJTDrEqZRu/+WcUq8z6kXC8xOabjbQhQ3g49RlxWOlpPWI4Sy/GJkl4PlfMQboJKoGm0C9biMkQxmU+532eg=="
Nov 25 23:59:26 volumio go-librespot[1543]: time="2024-11-25T23:59:26+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:27 volumio go-librespot[1543]: time="2024-11-25T23:59:27+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:27 volumio go-librespot[1543]: time="2024-11-25T23:59:27+01:00" level=debug msg="completed challenge"
Nov 25 23:59:27 volumio go-librespot[1543]: time="2024-11-25T23:59:27+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:27 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:27 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:27 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 25 23:59:27 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken
Nov 25 23:59:29 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:29 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:30 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:30 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Nov 25 23:59:30 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:30 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:30 volumio go-librespot[1559]: Librespot-go daemon starting...
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01:00" level=info msg="generated new device id: 912b8a4ad7b9d602786ed1c666f16a91f1af06cb"
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01: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]"
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01: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]"
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01: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]"
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01:00" level=debug msg="zeroconf server listening on port 41495"
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01:00" level=debug msg="obtained new client token: AAAamEPWdvAk8r/MyJQAp+d8vmdxRSTwAnTjLoLOMuAvJf/APOEm8x1UCJ7qCvudxIHd2PjJvgZojbdKezyGK0R7fufkelpYou5scpeOVXN1TLikDWC+1LC8UJD/xxs0P+zm4/REz5rBAyMAQ7rDiCIht0SwfYOzl8A9PLJHwtqz5W+4WWlmfiiUtBFb4MSAyfoFAJ1Nm+Y2LxlFkLvpvqfIp/2U5am9epeMhPwBqR4iYIkSXyJ3zM32HRXTrw=="
Nov 25 23:59:30 volumio go-librespot[1559]: time="2024-11-25T23:59:30+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:31 volumio go-librespot[1559]: time="2024-11-25T23:59:31+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:31 volumio go-librespot[1559]: time="2024-11-25T23:59:31+01:00" level=debug msg="completed challenge"
Nov 25 23:59:31 volumio go-librespot[1559]: time="2024-11-25T23:59:31+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:31 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:31 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::volumioGetBrowseSources
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Nov 25 23:59:31 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Nov 25 23:59:32 volumio volumio-remote-updater[671]: No test mode
Nov 25 23:59:32 volumio volumio-remote-updater[671]: No alpha test mode
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Nov 25 23:59:32 volumio volumio[1205]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Nov 25 23:59:32 volumio volumio[1205]: info: Completed starting MyVolumio Plugin
Nov 25 23:59:32 volumio volumio[1205]: info: BOOT COMPLETED
Nov 25 23:59:32 volumio volumio[1205]: [Metrics] CommandRouter: 32s 459.26ms
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::volumiosetStartupVolume
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::Close All Modals sent
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::Close All Modals sent
Nov 25 23:59:32 volumio volumio[1205]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"FIXES
- Improved translations
- Fix Multiroom Buffer Sizes
- Increase results for Kana-Kanji Conversion
- Fix for streaming interruptions
NEW ADDITIONS
- Bump RPi kernel to 6.6.56, support for RPi5 2GB
- Dedicated entry for RPi5 on some I2S DACs, restored master mode for older RPi models
- Add support for HifiBerry AMP4 Pro on RPi
","title":"Update v3.779","updateavailable":true}
Nov 25 23:59:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Nov 25 23:59:32 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:32 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:33 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Nov 25 23:59:33 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Nov 25 23:59:33 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Nov 25 23:59:34 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:34 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Nov 25 23:59:34 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:34 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:34 volumio go-librespot[1580]: Librespot-go daemon starting...
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01:00" level=info msg="generated new device id: 828d066b85c9374dcd078a9cd5c34ff8e3bdcc12"
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01: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]"
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01: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]"
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01: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]"
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01:00" level=debug msg="zeroconf server listening on port 42119"
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01:00" level=debug msg="obtained new client token: AAAsI+kgOTEPwaTrTQF+cKiKdffq/SHSlg/thWGpr/YqfDW5AT7hGpDcPZiIIuuT4+m/Kp6f+VDZZiExq3TCgi5o/oXnI3ocwhwi4ru+uxOZYA+pCd2FK606b0Solj6ss/W72qL9eV+BXk0PLYPq5RL5LagIKKI/g8if8kQz6bc1fjUU1Myms2INYSAS2FUKKN79CqIKHVG4uRVpwDsg6CVsETDVSQvSAIzG3L0F/ZudyLDgyFFA/VDIU2rDcQ=="
Nov 25 23:59:34 volumio go-librespot[1580]: time="2024-11-25T23:59:34+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:35 volumio go-librespot[1580]: time="2024-11-25T23:59:35+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:35 volumio volumio[1205]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/volumio/buster/armhf
Nov 25 23:59:35 volumio go-librespot[1580]: time="2024-11-25T23:59:35+01:00" level=debug msg="completed challenge"
Nov 25 23:59:35 volumio go-librespot[1580]: time="2024-11-25T23:59:35+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:35 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:35 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:35 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:35 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:37 volumio volumio[1205]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/volumio/buster/armhf
Nov 25 23:59:37 volumio volumio[1205]: info: Folder /tmp/plugins removed
Nov 25 23:59:37 volumio volumio[1205]: info: Check plugin dependencies
Nov 25 23:59:37 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Nov 25 23:59:37 volumio volumio[1205]: info: Checking if plugin already exists
Nov 25 23:59:37 volumio volumio[1205]: info: Rename folder
Nov 25 23:59:37 volumio volumio[1205]: info: Folder /tmp/downloaded_plugin.zip removed
Nov 25 23:59:37 volumio volumio[1205]: info: Move to category
Nov 25 23:59:38 volumio volumio[1205]: info: Checking if install.sh is present
Nov 25 23:59:38 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:38 volumio volumio[1205]: info: Executing install.sh
Nov 25 23:59:38 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:38 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:38 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Nov 25 23:59:38 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:38 volumio sudo[1646]: pam_unix(sudo:auth): authentication failure; logname= uid=1000 euid=0 tty= ruser=volumio rhost= user=volumio
Nov 25 23:59:38 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:38 volumio go-librespot[1649]: Librespot-go daemon starting...
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01:00" level=info msg="generated new device id: 9df7e6b64813ec2a56fbe4205b80a7cd2b34fdd9"
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01: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]"
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01: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]"
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01: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]"
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01:00" level=debug msg="zeroconf server listening on port 39969"
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01:00" level=debug msg="obtained new client token: AADXCgj6o17mKsjbamKEcktBXeAwhePORK/JvukaSwxc8fW5LSz9bopAeB243N7LlEGrUhpr2F2s6bPrYTP7nt/GcZdxX5a8hJgS8UN/ELh5G3Ul0a/Fd8Ej5kBsUlQ26r8BDcgIDF/8fLxIEWNlzodwMug4kjYGfQu8XnVxx3CfJkQqGxugIoyfHLmTjb6qtPshsH/mve/z9HeJQ925igNs+tPo/ezIYURfg9ic+T27nFxo5b/vxKnZq5uHYA=="
Nov 25 23:59:38 volumio go-librespot[1649]: time="2024-11-25T23:59:38+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:39 volumio go-librespot[1649]: time="2024-11-25T23:59:39+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:39 volumio go-librespot[1649]: time="2024-11-25T23:59:39+01:00" level=debug msg="completed challenge"
Nov 25 23:59:39 volumio go-librespot[1649]: time="2024-11-25T23:59:39+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:39 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:39 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:41 volumio sudo[1646]: pam_unix(sudo:auth): conversation failed
Nov 25 23:59:41 volumio sudo[1646]: pam_unix(sudo:auth): auth could not identify password for [volumio]
Nov 25 23:59:41 volumio sudo[1646]: volumio : 1 incorrect password attempt ; TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/fusiondsp/install.sh
Nov 25 23:59:41 volumio volumio[1205]: info: Install script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/audio_interface/fusiondsp/install.sh > /tmp/installog
Nov 25 23:59:41 volumio volumio[1205]: [sudo] password for volumio: Sorry, try again.
Nov 25 23:59:41 volumio volumio[1205]: [sudo] password for volumio:
Nov 25 23:59:41 volumio volumio[1205]: sudo: no password was provided
Nov 25 23:59:41 volumio volumio[1205]: sudo: 1 incorrect password attempt
Nov 25 23:59:41 volumio volumio[1205]: info: An error occurred installing the plugin. Rolling back config
Nov 25 23:59:41 volumio volumio[1205]: info: Plugin folders cleanup
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning into folder /volumio/app/plugins/
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category audio_interface
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category miscellanea
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category music_service
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category plugins.json
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category system_controller
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category user_interface
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning into folder /data/plugins/
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category audio_interface
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category music_service
Nov 25 23:59:41 volumio volumio[1205]: info: Scanning category system_controller
Nov 25 23:59:41 volumio volumio[1205]: info: Plugin folders cleanup completed
Nov 25 23:59:41 volumio volumio[1205]: info: Error: Error
Nov 25 23:59:41 volumio volumio[1205]: info: Folder /tmp/plugins removed
Nov 25 23:59:41 volumio volumio[1205]: info: Folder /tmp/downloaded_plugin.zip removed
Nov 25 23:59:41 volumio volumio[1205]: info: Folder /data/temp removed
Nov 25 23:59:41 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:41 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:42 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:42 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 10.
Nov 25 23:59:42 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:42 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:42 volumio go-librespot[1664]: Librespot-go daemon starting...
Nov 25 23:59:42 volumio go-librespot[1664]: time="2024-11-25T23:59:42+01:00" level=info msg="generated new device id: 9e19c88c95ad95ec9edcdff8f0baa3a13eb3bb4f"
Nov 25 23:59:42 volumio go-librespot[1664]: time="2024-11-25T23:59:42+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:42 volumio go-librespot[1664]: time="2024-11-25T23:59:42+01: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]"
Nov 25 23:59:42 volumio go-librespot[1664]: time="2024-11-25T23:59:42+01: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]"
Nov 25 23:59:42 volumio go-librespot[1664]: time="2024-11-25T23:59:42+01: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]"
Nov 25 23:59:42 volumio go-librespot[1664]: time="2024-11-25T23:59:42+01:00" level=debug msg="zeroconf server listening on port 44809"
Nov 25 23:59:43 volumio go-librespot[1664]: time="2024-11-25T23:59:43+01:00" level=debug msg="obtained new client token: AABvNNVLaE4gl13580mKoC6iIL/JaCQpkCnt91/+o/ZLjA5bl8TKHSdaLNT8XmAev2857d7sU6e9v9Kq7E6kjI/FGiFl59HTmgPR1lRkxQw0+RmtZGYUg6VQ1ya1NEyZTZlfblUy6KDn+C5iuzEby4CxCdUIHcbWKaqlXdV1bLOvvsYhQRf8o7ZTwIvx7bwJYQY5S86Wd67MuRsOH3H/lUCqC88Ogs6tegU+xsppihndZJOTg4+jjqYbiNE="
Nov 25 23:59:43 volumio go-librespot[1664]: time="2024-11-25T23:59:43+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:43 volumio go-librespot[1664]: time="2024-11-25T23:59:43+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:43 volumio go-librespot[1664]: time="2024-11-25T23:59:43+01:00" level=debug msg="completed challenge"
Nov 25 23:59:43 volumio go-librespot[1664]: time="2024-11-25T23:59:43+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:43 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:43 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:44 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:44 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:46 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:46 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 11.
Nov 25 23:59:46 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:46 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:46 volumio go-librespot[1680]: Librespot-go daemon starting...
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01:00" level=info msg="generated new device id: e13a54e744055db95955275dfa076eeb82cae0e2"
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01: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]"
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01: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]"
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01: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]"
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01:00" level=debug msg="zeroconf server listening on port 36951"
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01:00" level=debug msg="obtained new client token: AAAQEODUlp86CyUuBy47v0cqtJ97AQih2HU0ORTJAFpQYEOKhhTNUz1On4ENNVG2mkf2yCnwetpGRKO/QeK/4K7VI+QMJm5bsfeynllg84Fes8BuJyNAnfkSILSOC4Chm/kYQ4jTorNl0VCBh8WxvgYFPeHLkkkoskqHu+NPWUWAkufA75CU9xDI6j9+wGzY4lvIyt5CkzDQPnJ+RFG/22LFnpy3WX/lITj1CGSIdKfQ1U+V7YMKhiej01tzRA=="
Nov 25 23:59:46 volumio go-librespot[1680]: time="2024-11-25T23:59:46+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:47 volumio go-librespot[1680]: time="2024-11-25T23:59:47+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:47 volumio go-librespot[1680]: time="2024-11-25T23:59:47+01:00" level=debug msg="completed challenge"
Nov 25 23:59:47 volumio go-librespot[1680]: time="2024-11-25T23:59:47+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:47 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:47 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:47 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:47 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:50 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:50 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 12.
Nov 25 23:59:50 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:50 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:50 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:50 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:50 volumio go-librespot[1696]: Librespot-go daemon starting...
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01:00" level=info msg="generated new device id: c6aa6998af1f25a754a72319a4c2a23488044994"
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01: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]"
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01: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]"
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01: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]"
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01:00" level=debug msg="zeroconf server listening on port 35899"
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01:00" level=debug msg="obtained new client token: AACiuqaunxlB4tbWphU03QZ7FtyZRdkaHXm6zLiW25UJSTpxAIoUyjQ43o+ELd8lq4EZQzbkYwRosRzEbIUxlrKsOxGPEajFrY5dWj9wOQLeeIqSODCZkSpdBMvmBbaL4muqEfEdesEAu/rXgT/+wPnOHl8VHbBsVu8mZ7aWyCrEuw20/vYKt/NW1PTB6nGlaKjl3HdKZPFWpBkEWOyMGf0zy1pn2ReZNTwdLS/qa568LE37riPJIqfYn2mMMQ=="
Nov 25 23:59:50 volumio go-librespot[1696]: time="2024-11-25T23:59:50+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:51 volumio go-librespot[1696]: time="2024-11-25T23:59:51+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:51 volumio go-librespot[1696]: time="2024-11-25T23:59:51+01:00" level=debug msg="completed challenge"
Nov 25 23:59:51 volumio go-librespot[1696]: time="2024-11-25T23:59:51+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:51 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:51 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:53 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:53 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:54 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:54 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 13.
Nov 25 23:59:54 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:54 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:54 volumio go-librespot[1712]: Librespot-go daemon starting...
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01:00" level=info msg="generated new device id: a7c86a5ec1fd8dc3799a2a497ccadfc39158515a"
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01: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]"
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01: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]"
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01: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]"
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01:00" level=debug msg="zeroconf server listening on port 38595"
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01:00" level=debug msg="obtained new client token: AABCPia5AbnliIBDHqq6Gr9HHWeECdfUwXM3x7nrAE3VPvfWiGoi6VJOmiC9Jx4oej6He8aw+jbp9gdfV9iT28U78WHXu1a+qQczun9yBTYhTDBpriS8uavhomsKE+rIXzA775CFVvNlNI6XNIfjoLW2AVvpqsEP1PBR6+V41lRVsWiqL27aHPwmiC9Xy6m/KlBVQcftx4mLdOwBzr+PsnJGbPi/tKDXb53LC0CXyqGydS0OE4uBG209POroLg=="
Nov 25 23:59:54 volumio go-librespot[1712]: time="2024-11-25T23:59:54+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:55 volumio go-librespot[1712]: time="2024-11-25T23:59:55+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:55 volumio go-librespot[1712]: time="2024-11-25T23:59:55+01:00" level=debug msg="completed challenge"
Nov 25 23:59:55 volumio go-librespot[1712]: time="2024-11-25T23:59:55+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:56 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:56 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 25 23:59:58 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 25 23:59:58 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 14.
Nov 25 23:59:58 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 25 23:59:58 volumio systemd[1]: Started go-librespot Daemon.
Nov 25 23:59:58 volumio go-librespot[1728]: Librespot-go daemon starting...
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01:00" level=info msg="generated new device id: f655df6544fa0500583802fc0bfecee50b64400b"
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01: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]"
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01: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]"
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01: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]"
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01:00" level=debug msg="zeroconf server listening on port 33407"
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01:00" level=debug msg="obtained new client token: AAC7UEVHjlag3gpyUXup/pKYMAu8YMAw2/5hcAq1PiqeqVMwJZ21+UW+RSB1OCgpv0OMFBsu0KdEvWdo1GopjEuYiZrdqYXtFAuO/cWOylL9hWgvJK/sMzqB7pezfqlKE4Jc4ttbAPE5I/ck1yj/mA5eS8Ww8T18klJlzQu8PhgQ1+4v/WSoAoV4LxzgCCwY4drTNB3GtgtM8s/EGCxO9HAYXclD6T4gyRFs3b9HeiTidU5k5CAJsAs7JcuJcg=="
Nov 25 23:59:58 volumio go-librespot[1728]: time="2024-11-25T23:59:58+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 25 23:59:59 volumio go-librespot[1728]: time="2024-11-25T23:59:59+01:00" level=debug msg="completed keyexchange"
Nov 25 23:59:59 volumio go-librespot[1728]: time="2024-11-25T23:59:59+01:00" level=debug msg="completed challenge"
Nov 25 23:59:59 volumio go-librespot[1728]: time="2024-11-25T23:59:59+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 25 23:59:59 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 25 23:59:59 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 25 23:59:59 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 25 23:59:59 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:02 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 26 00:00:02 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 15.
Nov 26 00:00:02 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:02 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:02 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:02 volumio systemd[1]: Started go-librespot Daemon.
Nov 26 00:00:02 volumio go-librespot[1744]: Librespot-go daemon starting...
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01:00" level=info msg="generated new device id: e7442168769a057137a9f96a3dd4b98e5304109f"
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01: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]"
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01: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]"
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01: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]"
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01:00" level=debug msg="zeroconf server listening on port 42169"
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01:00" level=debug msg="obtained new client token: AACEZVwhQADQnX8is8JTnL+mkfiyXhtkDwQtMSpNC/qNuLmlDvvW/0iZbDsSX51xhnQBUpHvPOc6TKc9aKAU+w1GHL2sNS6rnJj8WwoB44AS+bNIlxHctdFJE4vvXoeqLgDmc1mOJQBjLzJv0ZZ5wQRXHzsMQTt4WeRsTimpjpKwZvl+t1mL3sVu7vuc6fr/i906868ypDlZwbSPBfBNk71Z2srM7Q1x7R2XSj4zn4PRoIYo5v3SX5dziGTi8Q=="
Nov 26 00:00:02 volumio go-librespot[1744]: time="2024-11-26T00:00:02+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 26 00:00:03 volumio go-librespot[1744]: time="2024-11-26T00:00:03+01:00" level=debug msg="completed keyexchange"
Nov 26 00:00:03 volumio go-librespot[1744]: time="2024-11-26T00:00:03+01:00" level=debug msg="completed challenge"
Nov 26 00:00:03 volumio go-librespot[1744]: time="2024-11-26T00:00:03+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 26 00:00:03 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 26 00:00:03 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 26 00:00:05 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:05 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:06 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 26 00:00:06 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 16.
Nov 26 00:00:06 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:06 volumio systemd[1]: Started go-librespot Daemon.
Nov 26 00:00:06 volumio go-librespot[1760]: Librespot-go daemon starting...
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01:00" level=info msg="generated new device id: f03dfb25c3e801d89dc9c45a03ee5d4b278dfcdf"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01: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]"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01: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]"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01: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]"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01:00" level=debug msg="zeroconf server listening on port 43891"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01:00" level=debug msg="obtained new client token: AAAR3SV+MWW84M3U8ZZkNtbtgQcSXUhWHaa2K+3TeGtH/BTlmUu8EiuUCoKIwkZNDPk8d/qMKTfH3T3ZlLfyOvtuuBhT4P/7ANCIIng9SOqX4VrhsuLSvNREwR6lIKnL5zgYAhx5bHNBCE8zy6AEBJt+o3f2D/Vssu96HGBDtj6/SLj5b1zWpUt+dWC6Vr9wQ4BWvDhAEg7iM+YbWx3JXe+6XpUZrXR4MNIi0ywXjyFlSdCDpves1l0comDBVg=="
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01:00" level=warning msg="failed to connect to AP ap-gew1.spotify.com:4070 (error: dial tcp 104.199.65.9:4070: connect: connection refused), retrying with a different AP"
Nov 26 00:00:06 volumio go-librespot[1760]: time="2024-11-26T00:00:06+01:00" level=info msg="connected to ap-gew1.spotify.com:443"
Nov 26 00:00:07 volumio volumio[1205]: info: Downloading plugin at https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/volumio/buster/armhf
Nov 26 00:00:07 volumio go-librespot[1760]: time="2024-11-26T00:00:07+01:00" level=debug msg="completed keyexchange"
Nov 26 00:00:07 volumio go-librespot[1760]: time="2024-11-26T00:00:07+01:00" level=debug msg="completed challenge"
Nov 26 00:00:07 volumio go-librespot[1760]: time="2024-11-26T00:00:07+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 26 00:00:07 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 26 00:00:07 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 26 00:00:08 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:08 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:08 volumio volumio[1205]: info: END DOWNLOAD: https://plugins.volumio.workers.dev/pluginsv2/downloadLatestStable/fusiondsp/volumio/buster/armhf
Nov 26 00:00:08 volumio volumio[1205]: info: Folder /tmp/plugins removed
Nov 26 00:00:09 volumio volumio[1205]: info: Check plugin dependencies
Nov 26 00:00:09 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Nov 26 00:00:09 volumio volumio[1205]: info: Checking if plugin already exists
Nov 26 00:00:09 volumio volumio[1205]: info: Rename folder
Nov 26 00:00:09 volumio volumio[1205]: info: Folder /tmp/downloaded_plugin.zip removed
Nov 26 00:00:09 volumio volumio[1205]: info: Move to category
Nov 26 00:00:10 volumio volumio[1205]: info: Checking if install.sh is present
Nov 26 00:00:10 volumio volumio[1205]: info: Executing install.sh
Nov 26 00:00:10 volumio sudo[1788]: pam_unix(sudo:auth): authentication failure; logname= uid=1000 euid=0 tty= ruser=volumio rhost= user=volumio
Nov 26 00:00:10 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 26 00:00:10 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 17.
Nov 26 00:00:10 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:10 volumio systemd[1]: Started go-librespot Daemon.
Nov 26 00:00:10 volumio go-librespot[1791]: Librespot-go daemon starting...
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01:00" level=info msg="generated new device id: 451040fe557f6ae9793f84e534cb1ba9d53cf382"
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01: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]"
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01: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]"
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01: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]"
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01:00" level=debug msg="zeroconf server listening on port 37843"
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01:00" level=debug msg="obtained new client token: AAAhHlbcPbDtFgmiy/xE/b4XAYhKcVIXS/ovxUjR7U2behic0YgCxj4xHTgFSAkfOCM7xTF24zM2O23UHaNXje9usmL0/ngZfRJ65xsFCYGSIWZZQW51/8zPlxNq8vfdphpwk3rsWIYBMc+v+E+ikgNwsXxPJKm1mDDQfs+34bpJKIM9V8kVwBKrCTR2Dgdi4EUAnXvKv1LR629AcpIcXC0KZPD+Vt2mOApeGxsr911YfB8DVVUPhj0PhcoTew=="
Nov 26 00:00:10 volumio go-librespot[1791]: time="2024-11-26T00:00:10+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 26 00:00:11 volumio go-librespot[1791]: time="2024-11-26T00:00:11+01:00" level=debug msg="completed keyexchange"
Nov 26 00:00:11 volumio go-librespot[1791]: time="2024-11-26T00:00:11+01:00" level=debug msg="completed challenge"
Nov 26 00:00:11 volumio go-librespot[1791]: time="2024-11-26T00:00:11+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 26 00:00:11 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 26 00:00:11 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 26 00:00:11 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:11 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:12 volumio sudo[1788]: pam_unix(sudo:auth): conversation failed
Nov 26 00:00:12 volumio sudo[1788]: pam_unix(sudo:auth): auth could not identify password for [volumio]
Nov 26 00:00:12 volumio sudo[1788]: volumio : 1 incorrect password attempt ; TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/audio_interface/fusiondsp/install.sh
Nov 26 00:00:12 volumio volumio[1205]: info: Install script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/audio_interface/fusiondsp/install.sh > /tmp/installog
Nov 26 00:00:12 volumio volumio[1205]: [sudo] password for volumio: Sorry, try again.
Nov 26 00:00:12 volumio volumio[1205]: [sudo] password for volumio:
Nov 26 00:00:12 volumio volumio[1205]: sudo: no password was provided
Nov 26 00:00:12 volumio volumio[1205]: sudo: 1 incorrect password attempt
Nov 26 00:00:12 volumio volumio[1205]: info: An error occurred installing the plugin. Rolling back config
Nov 26 00:00:12 volumio volumio[1205]: info: Plugin folders cleanup
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning into folder /volumio/app/plugins/
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category audio_interface
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category miscellanea
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category music_service
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category plugins.json
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category system_controller
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category user_interface
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning into folder /data/plugins/
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category audio_interface
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category music_service
Nov 26 00:00:12 volumio volumio[1205]: info: Scanning category system_controller
Nov 26 00:00:12 volumio volumio[1205]: info: Plugin folders cleanup completed
Nov 26 00:00:12 volumio volumio[1205]: info: Error: Error
Nov 26 00:00:12 volumio volumio[1205]: info: Folder /tmp/plugins removed
Nov 26 00:00:12 volumio volumio[1205]: info: Folder /tmp/downloaded_plugin.zip removed
Nov 26 00:00:12 volumio volumio[1205]: info: Folder /data/temp removed
Nov 26 00:00:14 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 26 00:00:14 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 18.
Nov 26 00:00:14 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:14 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:14 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:14 volumio systemd[1]: Started go-librespot Daemon.
Nov 26 00:00:14 volumio go-librespot[1807]: Librespot-go daemon starting...
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01:00" level=info msg="generated new device id: 655ff8c97c4d78de8612e234154242b4b7c7f225"
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01: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]"
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01: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]"
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01: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]"
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01:00" level=debug msg="zeroconf server listening on port 46793"
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01:00" level=debug msg="obtained new client token: AAABN4XqtGaNRqf3y8DlPlEe3qFDIEHPLfRQDz0VMwLBpHQuAxvyAFWJTZHeL+C5q73p95VDHTJRUnjkXFnwq3DyKE5Xz8rPrnSNbUnEI9HahnX117WtlWmi13MvUenOTbtO7pNOzkH22CgsruVNVPBflEwLeVoKzKVVe6ErXDOIEUPTqCTikusz9nhj9KZXj2sXGb0IxilhspER8kwIfaddtCeKDpRXh8hJ0WiMxNT2SRoMI+kScSQPAg9p1w=="
Nov 26 00:00:14 volumio go-librespot[1807]: time="2024-11-26T00:00:14+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 26 00:00:15 volumio go-librespot[1807]: time="2024-11-26T00:00:15+01:00" level=debug msg="completed keyexchange"
Nov 26 00:00:15 volumio go-librespot[1807]: time="2024-11-26T00:00:15+01:00" level=debug msg="completed challenge"
Nov 26 00:00:15 volumio go-librespot[1807]: time="2024-11-26T00:00:15+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 26 00:00:15 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 26 00:00:15 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 26 00:00:17 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:17 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:18 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 26 00:00:18 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 19.
Nov 26 00:00:18 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:18 volumio systemd[1]: Started go-librespot Daemon.
Nov 26 00:00:18 volumio go-librespot[1823]: Librespot-go daemon starting...
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01:00" level=info msg="generated new device id: b98d53171aec4735fa2533748c119bb9574384ec"
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01: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]"
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01: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]"
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01: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]"
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01:00" level=debug msg="zeroconf server listening on port 45603"
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01:00" level=debug msg="obtained new client token: AADGuIy7us7olSUmK1wNybevZyVeCU4+g9MBrLnXnFdWZeK2wBdSXQ5nvDZsznIMQLrIvcvTbMODV2IIfFAS55V0ipLIwYhdU7U1fcev00w9WdNhXAUHyGk26xwD3roNMFgJzwnEnjZGu0ZovEpBMX7NIQE18wXqHuyfHCvRb+WgWk42sJER2tS69LhfD6Rf+nhNdutQ3jEYh7W3wWwHzxPC1CE8c5yuEVa45VAZyUtBG2f76ijl0DN5QdkDjA=="
Nov 26 00:00:18 volumio go-librespot[1823]: time="2024-11-26T00:00:18+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 26 00:00:19 volumio go-librespot[1823]: time="2024-11-26T00:00:19+01:00" level=debug msg="completed keyexchange"
Nov 26 00:00:19 volumio go-librespot[1823]: time="2024-11-26T00:00:19+01:00" level=debug msg="completed challenge"
Nov 26 00:00:19 volumio go-librespot[1823]: time="2024-11-26T00:00:19+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 26 00:00:19 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 26 00:00:19 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 26 00:00:20 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:20 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:22 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Nov 26 00:00:22 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 20.
Nov 26 00:00:22 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:22 volumio systemd[1]: Started go-librespot Daemon.
Nov 26 00:00:22 volumio go-librespot[1839]: Librespot-go daemon starting...
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01:00" level=info msg="generated new device id: 096cd2f9beb1396168272f8a3852db64954b8574"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01:00" level=debug msg="stored credentials found for mstvqowa77asg52kq94w9ua9e"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01: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]"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01: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]"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01: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]"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01:00" level=debug msg="zeroconf server listening on port 43781"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01:00" level=debug msg="obtained new client token: AAAj60iwR+I0R1lItTx3FqPvd5fkrXHjrKDyVfwlFHLExBUmDMqmIzRniDbnEw4KxuancIAnGsvwo8AIhLMaq9AYf1fNu9aZIvIDI+1301qSgjjh6i6+msGRZaPOqyhBojbtO4ECfMWGRp041VE/7nOsittSYz4a+e1W1eKaEWTN9lkgIHMEdqlJ6nm/G8qoU/PzUPetqIhJQaprK/D/9yHbjstw35rfqp/ZKSIljl3LYON+xAICsXXcgRx+lw=="
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01:00" level=info msg="connected to ap-gew1.spotify.com:4070"
Nov 26 00:00:22 volumio go-librespot[1839]: time="2024-11-26T00:00:22+01:00" level=debug msg="completed keyexchange"
Nov 26 00:00:23 volumio go-librespot[1839]: time="2024-11-26T00:00:23+01:00" level=debug msg="completed challenge"
Nov 26 00:00:23 volumio go-librespot[1839]: time="2024-11-26T00:00:23+01:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Nov 26 00:00:23 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Nov 26 00:00:23 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Nov 26 00:00:23 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:23 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:25 volumio volumio[1205]: info: Starting Uninstall of plugin music_service - spop
Nov 26 00:00:25 volumio volumio[1205]: info: Uninstalling plugin spop
Nov 26 00:00:25 volumio volumio[1205]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify
Nov 26 00:00:25 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Nov 26 00:00:25 volumio sudo[1852]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service
Nov 26 00:00:25 volumio sudo[1852]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:25 volumio volumio[1205]: info: Disabling plugin spop
Nov 26 00:00:25 volumio volumio[1205]: info: Checking if uninstall.sh is present
Nov 26 00:00:25 volumio volumio[1205]: info: Executing uninstall.sh
Nov 26 00:00:25 volumio systemd[1]: Stopped go-librespot Daemon.
Nov 26 00:00:25 volumio sudo[1852]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:25 volumio sudo[1856]: pam_unix(sudo:auth): authentication failure; logname= uid=1000 euid=0 tty= ruser=volumio rhost= user=volumio
Nov 26 00:00:26 volumio volumio[1205]: info: Initializing connection to go-librespot Websocket
Nov 26 00:00:26 volumio volumio[1205]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Nov 26 00:00:27 volumio sudo[1856]: pam_unix(sudo:auth): conversation failed
Nov 26 00:00:27 volumio sudo[1856]: pam_unix(sudo:auth): auth could not identify password for [volumio]
Nov 26 00:00:27 volumio sudo[1856]: volumio : 1 incorrect password attempt ; TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/sh /data/plugins/music_service/spop/uninstall.sh
Nov 26 00:00:27 volumio volumio[1205]: info: Uninstall script return the error Error: Command failed: echo volumio | sudo -S sh /data/plugins/music_service/spop/uninstall.sh > /tmp/installog
Nov 26 00:00:27 volumio volumio[1205]: [sudo] password for volumio: Sorry, try again.
Nov 26 00:00:27 volumio volumio[1205]: [sudo] password for volumio:
Nov 26 00:00:27 volumio volumio[1205]: sudo: no password was provided
Nov 26 00:00:27 volumio volumio[1205]: sudo: 1 incorrect password attempt
Nov 26 00:00:32 volumio volumio[1205]: info: CoreCommandRouter::volumioRemoveToBrowseSourcesSpotify
Nov 26 00:00:32 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Nov 26 00:00:32 volumio volumio[1205]: info: Disabling plugin spop
Nov 26 00:00:32 volumio volumio[1205]: info: Done.
Nov 26 00:00:32 volumio sudo[1872]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop go-librespot-daemon.service
Nov 26 00:00:32 volumio sudo[1872]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:32 volumio sudo[1872]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:36 volumio sudo[1921]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Nov 26 00:00:36 volumio sudo[1921]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:36 volumio sudo[1921]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:36 volumio sudo[1923]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Nov 26 00:00:36 volumio sudo[1923]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:36 volumio sudo[1923]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:36 volumio volumio[1205]: verbose: New Socket.io Connection to 10.0.10.20 from 10.0.100.9 UA: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36 Edg/131.0.0.0 Engine version: 3 Transport: polling Total Clients: 4
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::volumioGetVisibleSources
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 26 00:00:36 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Nov 26 00:00:36 volumio volumio[1205]: info: Received Get System Info
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 26 00:00:36 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 26 00:00:36 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 26 00:00:36 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 26 00:00:36 volumio volumio[1205]: info: Listing playlists
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioToken
Nov 26 00:00:36 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Nov 26 00:00:38 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard
Nov 26 00:00:38 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 26 00:00:38 volumio volumio[1205]: info: Received Get System Info
Nov 26 00:00:38 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 26 00:00:38 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 26 00:00:38 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 26 00:00:38 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 26 00:00:38 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 26 00:00:38 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Nov 26 00:00:39 volumio volumio[1205]: info: Received Get System Info
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Nov 26 00:00:39 volumio volumio[1205]: info: Discovery: Getting this device information
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::volumioGetState
Nov 26 00:00:39 volumio volumio[1205]: info: CorePlayQueue::getTrack 0
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 26 00:00:39 volumio volumio[1205]: info: Enabling plugin fusiondsp
Nov 26 00:00:39 volumio volumio[1205]: info: Loading plugin "fusiondsp"...
Nov 26 00:00:39 volumio volumio[1205]: info: Preparing to generate the ALSA configuration file
Nov 26 00:00:39 volumio volumio[1205]: info: Asound.conf file unchanged, so no further update is needed
Nov 26 00:00:39 volumio volumio[1205]: info: Output device has changed, restarting MPD
Nov 26 00:00:39 volumio sudo[1935]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Nov 26 00:00:39 volumio sudo[1935]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:39 volumio volumio[1205]: info: PLUGIN START: fusiondsp
Nov 26 00:00:39 volumio sudo[1935]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:39 volumio volumio[1205]: info: Loading i18n strings for locale hu
Nov 26 00:00:39 volumio sudo[1938]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Nov 26 00:00:39 volumio sudo[1938]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , updateALSAConfigFile
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: FusionDsp - mixtype--------------------- Hardware
Nov 26 00:00:39 volumio volumio[1205]: info: Preparing to generate the ALSA configuration file
Nov 26 00:00:39 volumio systemd[1]: Stopping Music Player Daemon...
Nov 26 00:00:39 volumio volumio[1205]: info: Done.
Nov 26 00:00:39 volumio volumio[1205]: info: MPD Permissions set
Nov 26 00:00:39 volumio volumio[1205]: info: Asound.conf file unchanged, so no further update is needed
Nov 26 00:00:39 volumio volumio[1205]: info: Output device has changed, restarting MPD
Nov 26 00:00:39 volumio sudo[1941]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf
Nov 26 00:00:39 volumio sudo[1941]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio sudo[1941]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:39 volumio sudo[1943]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service
Nov 26 00:00:39 volumio sudo[1943]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::getUIConfigOnPlugin
Nov 26 00:00:39 volumio volumio[1205]: info: MPD Permissions set
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Nov 26 00:00:39 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:39 volumio systemd[1]: mpd.service: Succeeded.
Nov 26 00:00:39 volumio systemd[1]: Stopped Music Player Daemon.
Nov 26 00:00:39 volumio systemd[1]: Starting Music Player Daemon...
Nov 26 00:00:39 volumio sudo[1954]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chown mpd:audio /var/log/mpd.log
Nov 26 00:00:39 volumio sudo[1954]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:39 volumio sudo[1954]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:40 volumio mpd[1956]: Nov 26 00:00 : decoder: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg
Nov 26 00:00:40 volumio systemd[1]: Started Music Player Daemon.
Nov 26 00:00:40 volumio sudo[1943]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:40 volumio sudo[1938]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:40 volumio volumio[1205]: error: MPD error: The expression evaluated to a falsy value:
Nov 26 00:00:40 volumio volumio[1205]: assert.ok(self.idling)
Nov 26 00:00:40 volumio volumio[1205]: error: The expression evaluated to a falsy value:
Nov 26 00:00:40 volumio volumio[1205]: assert.ok(self.idling)
Nov 26 00:00:40 volumio volumio[1205]: error: updateQueue error: null
Nov 26 00:00:40 volumio volumio[1205]: error: Upnp client error: Error: This socket has been ended by the other party
Nov 26 00:00:41 volumio volumio[1205]: info: camilladsp spawned new process with pid undefined, instance 1, run: true
Nov 26 00:00:41 volumio volumio[1205]: info: camilladsp service started and running in background, instance 1
Nov 26 00:00:41 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Nov 26 00:00:41 volumio volumio[1205]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found
Nov 26 00:00:41 volumio volumio[1205]: error: FusionDsp - ----Hw detection failed :Error: Command failed: /data/plugins/audio_interface/fusiondsp/hw_params volumioHw >/data/configuration/audio_interface/fusiondsp/hwinfo.json
Nov 26 00:00:41 volumio volumio[1205]: /bin/sh: 1: /data/plugins/audio_interface/fusiondsp/hw_params: not found
Nov 26 00:00:41 volumio volumio[1205]: info: FusionDsp loaded
Nov 26 00:00:41 volumio volumio[1205]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Nov 26 00:00:41 volumio sudo[1969]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start fusiondsp.service
Nov 26 00:00:41 volumio sudo[1969]: pam_unix(sudo:session): session opened for user root by (uid=0)
Nov 26 00:00:41 volumio volumio[1205]: info: FusionDsp - Reporting Fusion DSP Enabled
Nov 26 00:00:41 volumio volumio[1205]: info: Adding Signal Path Element [object Object]
Nov 26 00:00:41 volumio volumio[1205]: info: Adding fusiondspeq DSP Signal Path Element
Nov 26 00:00:41 volumio volumio[1205]: info: FusionDsp - ---- installed callbackRead
Nov 26 00:00:41 volumio volumio[1205]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Nov 26 00:00:41 volumio sudo[1969]: pam_unix(sudo:session): session closed for user root
Nov 26 00:00:41 volumio volumio[1205]: Error: spawn /data/plugins/audio_interface/fusiondsp/camilladsp ENOENT
Nov 26 00:00:41 volumio volumio[1205]: at Process.ChildProcess._handle.onexit (internal/child_process.js:269:19)
Nov 26 00:00:41 volumio volumio[1205]: at onErrorNT (internal/child_process.js:465:16)
Nov 26 00:00:41 volumio volumio[1205]: at processTicksAndRejections (internal/process/task_queues.js:80:21)
Nov 26 00:00:41 volumio volumio[1205]: at runNextTicks (internal/process/task_queues.js:62:3)
Nov 26 00:00:41 volumio volumio[1205]: at listOnTimeout (internal/timers.js:523:9)
Nov 26 00:00:41 volumio volumio[1205]: at processTimers (internal/timers.js:497:7) {
Nov 26 00:00:41 volumio volumio[1205]: errno: -2,
Nov 26 00:00:41 volumio volumio[1205]: code: 'ENOENT',
Nov 26 00:00:41 volumio volumio[1205]: syscall: 'spawn /data/plugins/audio_interface/fusiondsp/camilladsp',
Nov 26 00:00:41 volumio volumio[1205]: path: '/data/plugins/audio_interface/fusiondsp/camilladsp',
Nov 26 00:00:41 volumio volumio[1205]: spawnargs: [
Nov 26 00:00:41 volumio volumio[1205]: '-p',
Nov 26 00:00:41 volumio volumio[1205]: 9876,
Nov 26 00:00:41 volumio volumio[1205]: '-o',
Nov 26 00:00:41 volumio volumio[1205]: '/tmp/camilladsp.log',
Nov 26 00:00:41 volumio volumio[1205]: '-l',
Nov 26 00:00:41 volumio volumio[1205]: 'warn',
Nov 26 00:00:41 volumio volumio[1205]: '/data/configuration/audio_interface/fusiondsp/camilladsp.yml'
Nov 26 00:00:41 volumio volumio[1205]: ]
Nov 26 00:00:41 volumio volumio[1205]: }
Nov 26 00:00:41 volumio volumio[1205]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Nov 26 00:00:41 volumio sudo[1980]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-11-25 23:59
Nov 26 00:00:41 volumio sudo[1980]: 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="8b17c2f054b42f7617d19172c51eb8801fef450d"
VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6"
VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a"
VOLUMIO_BE_VERSION="5ed89c6e5067f886280d87d6c1a3f9930df14028"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Wed 16 Oct 2024 03:57:06 PM CEST"
VOLUMIO_VERSION="3.765"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="0d32cf437531a99146c655ee44a741a6"