-- Logs begin at Thu 2019-02-14 19:11:58 KST, end at Wed 2025-04-23 16:04:16 KST. --
Apr 23 16:03:40 volumio systemd[1]: Starting Daily man-db regeneration...
Apr 23 16:03:40 volumio systemd-timedated[2959]: Changed local time to Wed Apr 23 16:03:40 2025
Apr 23 16:03:40 volumio systemd[1]: Starting Daily apt download activities...
Apr 23 16:03:40 volumio sudo[2957]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:40 volumio volumio-time-update[840]: volumio-time-update-util: System time updated successfully.
Apr 23 16:03:40 volumio systemd[1]: Started Volumio Time Update Utility.
Apr 23 16:03:40 volumio systemd[1]: Reached target Multi-User System.
Apr 23 16:03:40 volumio systemd[1]: Reached target Graphical Interface.
Apr 23 16:03:40 volumio squeezeboxserver[985]: [16:03:40.009] mDNSsearchCallback:691 [0x195a80]: changed ip:port 192.168.219.105:5000
Apr 23 16:03:40 volumio squeezeboxserver[985]: [16:03:40.009] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.17.0.1:5000
Apr 23 16:03:40 volumio squeezeboxserver[985]: [16:03:40.009] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.18.0.1:5000
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: A device disappeared from network
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: Device volumio disappeared from network
Apr 23 16:03:40 volumio systemd[1]: Starting Update UTMP about System Runlevel Changes...
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: A device disappeared from network
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: A device disappeared from network
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: adding a8f7da66-c4ee-4837-a17c-20dc85d43ef9
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: Found device Volumio
Apr 23 16:03:40 volumio systemd[1]: systemd-update-utmp-runlevel.service: Succeeded.
Apr 23 16:03:40 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:40 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:40 volumio systemd[1]: Started Update UTMP about System Runlevel Changes.
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: this is already registered, a8f7da66-c4ee-4837-a17c-20dc85d43ef9
Apr 23 16:03:40 volumio kernel: broken atomic modeset userspace detected, disabling atomic
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: Found device Volumio
Apr 23 16:03:40 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:40 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:40 volumio volumio[1065]: info: Discovery: Browse raised the following error Error: getaddrinfo -3007
Apr 23 16:03:40 volumio ntpd[1022]: Listen normally on 4 eth0 192.168.219.105:123
Apr 23 16:03:40 volumio ntpd[1022]: new interface(s) found: waking up resolver
Apr 23 16:03:40 volumio startx[2800]: (II) modeset(0): Initializing kms color map for depth 24, 8 bpc.
Apr 23 16:03:40 volumio systemd[1]: man-db.service: Succeeded.
Apr 23 16:03:40 volumio systemd[1]: Started Daily man-db regeneration.
Apr 23 16:03:41 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:41 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:41 volumio systemd[1]: apt-daily.service: Succeeded.
Apr 23 16:03:41 volumio systemd[1]: Started Daily apt download activities.
Apr 23 16:03:41 volumio volumio[1065]: info: touch_display: Setting screensaver timeout to 0 seconds.
Apr 23 16:03:41 volumio systemd[1]: Starting Daily apt upgrade and clean activities...
Apr 23 16:03:41 volumio volumio[1065]: info: go-librespot daemon successfully initialized
Apr 23 16:03:41 volumio systemd[1]: apt-daily-upgrade.service: Succeeded.
Apr 23 16:03:41 volumio systemd[1]: Started Daily apt upgrade and clean activities.
Apr 23 16:03:41 volumio systemd[1]: Startup finished in 11.816s (kernel) + 14.738s (userspace) = 26.555s.
Apr 23 16:03:41 volumio squeezeboxserver[985]: [16:03:41.802] mDNSsearchCallback:691 [0x195a80]: changed ip:port 192.168.219.105:5000
Apr 23 16:03:41 volumio squeezeboxserver[985]: [16:03:41.802] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.17.0.1:5000
Apr 23 16:03:41 volumio squeezeboxserver[985]: [16:03:41.802] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.18.0.1:5000
Apr 23 16:03:42 volumio sudo[3216]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=raspberry,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.219.109/OMV/ /mnt/NAS/hbymomv
Apr 23 16:03:42 volumio sudo[3216]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:42 volumio kernel: CIFS: Attempting to mount //192.168.219.109/OMV
Apr 23 16:03:42 volumio volumio[1065]: info: Volumio Network Manager: Network status updated: 1
Apr 23 16:03:42 volumio squeezeboxserver[985]: [16:03:42.871] mDNSsearchCallback:691 [0x195a80]: changed ip:port 192.168.219.105:5000
Apr 23 16:03:42 volumio squeezeboxserver[985]: [16:03:42.872] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.17.0.1:5000
Apr 23 16:03:42 volumio squeezeboxserver[985]: [16:03:42.872] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.18.0.1:5000
Apr 23 16:03:43 volumio sudo[3261]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Apr 23 16:03:43 volumio sudo[3261]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:43 volumio sudo[3261]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:43 volumio sudo[3265]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Apr 23 16:03:43 volumio sudo[3265]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:43 volumio sudo[3265]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:43 volumio sudo[3270]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Apr 23 16:03:43 volumio sudo[3270]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:43 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:03:43 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 1.
Apr 23 16:03:43 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:03:43 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:03:43 volumio go-librespot[3276]: go-librespot daemon starting...
Apr 23 16:03:43 volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Apr 23 16:03:43 volumio sudo[3270]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:43 volumio volumio[1065]: info: Upmpdcli Daemon Started
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="app state loaded"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:03:43 volumio volumio[3282]: Generating RSA private key, 4096 bit long modulus (2 primes)
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=info msg="zeroconf server listening on port 40299"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="obtained new client token: AAA9GVnxeKdd5psKbNZFouJ5Ot2pFjHEYGzl9vDvCOa3t9ghD9zMcJyeFCJWu3EQP+5mT04LGlUD/LUmKj1hw3yik/0ZOFmWIj5LOQnfcvnm3nhrMQiUinZpzmDYr5W4XrOrPMuLdsblSks5j+ifOADMs52PwfNfoQguybU7aliNmNWYxfr2cPtp1FTYx6wEAocabMi1/FvMzNzSnl0fv7barF28HlAOt+Y7E8JfxLnfaJ5gi7RkesbgURo="
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="completed keyexchange"
Apr 23 16:03:43 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 23 16:03:43 volumio volumio[1065]: info: Discovery: Getting this device information
Apr 23 16:03:43 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:43 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:43 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 23 16:03:43 volumio go-librespot[3276]: time="2025-04-23T16:03:43+09:00" level=debug msg="completed challenge"
Apr 23 16:03:44 volumio go-librespot[3276]: time="2025-04-23T16:03:44+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:03:44 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:03:44 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:03:44 volumio volumio[1065]: info: [now-playing] Fetching API key...
Apr 23 16:03:44 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS aarch64 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 5
Apr 23 16:03:44 volumio volumio[1065]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined
Apr 23 16:03:44 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo
Apr 23 16:03:44 volumio volumio[1065]: info: Listing playlists
Apr 23 16:03:44 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue
Apr 23 16:03:44 volumio volumio[1065]: info: CoreStateMachine::getQueue
Apr 23 16:03:44 volumio volumio[1065]: info: CorePlayQueue::getQueue
Apr 23 16:03:44 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources
Apr 23 16:03:44 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Apr 23 16:03:44 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:44 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:44 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:03:44 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:03:44 volumio squeezeboxserver[985]: [16:03:44.941] mDNSsearchCallback:691 [0x195a80]: changed ip:port 192.168.219.105:5000
Apr 23 16:03:44 volumio squeezeboxserver[985]: [16:03:44.942] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.17.0.1:5000
Apr 23 16:03:44 volumio squeezeboxserver[985]: [16:03:44.942] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.18.0.1:5000
Apr 23 16:03:45 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS aarch64 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 6
Apr 23 16:03:45 volumio volumio[1065]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo
Apr 23 16:03:45 volumio volumio[1065]: info: Listing playlists
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue
Apr 23 16:03:45 volumio volumio[1065]: info: CoreStateMachine::getQueue
Apr 23 16:03:45 volumio volumio[1065]: info: CorePlayQueue::getQueue
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:45 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:45 volumio volumio[1065]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo
Apr 23 16:03:45 volumio volumio[1065]: info: Listing playlists
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue
Apr 23 16:03:45 volumio volumio[1065]: info: CoreStateMachine::getQueue
Apr 23 16:03:45 volumio volumio[1065]: info: CorePlayQueue::getQueue
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Apr 23 16:03:45 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:45 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:46 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: Mozilla/5.0 (X11; CrOS aarch64 13597.84.0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.98 Safari/537.36 Engine version: 3 Transport: polling Total Clients: 7
Apr 23 16:03:46 volumio volumio[1065]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo
Apr 23 16:03:46 volumio volumio[1065]: info: Listing playlists
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue
Apr 23 16:03:46 volumio volumio[1065]: info: CoreStateMachine::getQueue
Apr 23 16:03:46 volumio volumio[1065]: info: CorePlayQueue::getQueue
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:46 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:46 volumio volumio[1065]: info: CALLMETHOD: user_interface now_playing getPluginInfo undefined
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: now_playing , getPluginInfo
Apr 23 16:03:46 volumio volumio[1065]: info: Listing playlists
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue
Apr 23 16:03:46 volumio volumio[1065]: info: CoreStateMachine::getQueue
Apr 23 16:03:46 volumio volumio[1065]: info: CorePlayQueue::getQueue
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Apr 23 16:03:46 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:46 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:47 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:03:47 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 2.
Apr 23 16:03:47 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:03:47 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:03:47 volumio go-librespot[3362]: go-librespot daemon starting...
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="app state loaded"
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin tidal to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan premium
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin multiroom to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin metavolumio to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin smart_inputs to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin hi_res_audio to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin tidal to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan superstar
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin bluetooth to plan virtuoso
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin manifestui to plan virtuoso
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin cd_controller to plan virtuoso
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin tidal to plan virtuoso
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin qobuz to plan virtuoso
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Adding plugin tidalconnect to plan virtuoso
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=info msg="zeroconf server listening on port 36577"
Apr 23 16:03:47 volumio volumio[1065]: info: Adding plugin bluetooth to MyMusic Plugins
Apr 23 16:03:47 volumio volumio[1065]: info: Adding plugin multiroom to MyMusic Plugins
Apr 23 16:03:47 volumio volumio[1065]: info: Adding plugin metavolumio to MyMusic Plugins
Apr 23 16:03:47 volumio volumio[1065]: info: Adding plugin cd_controller to MyMusic Plugins
Apr 23 16:03:47 volumio volumio[1065]: info: Adding plugin smart_inputs to MyMusic Plugins
Apr 23 16:03:47 volumio volumio[1065]: info: Adding plugin tidalconnect to MyMusic Plugins
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Loading plugin "my_volumio"...
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="obtained new client token: AAAYvtNen9b871CD351kENTJsZlw7+Ua+0tnbyFYQDXRzsk92Xz8+Y1By23QHtFPFJAVJ44YvYDAIhdsarzesoBg1HNEwgFf4eGPUaMsc/HDYTbuCidl5WB0YuAfC/ZrZBhKIZb+uE38z75WgFNV9SD5NMzkh6HSxS2bBWDOzynlrtqeVl9thjRfhV44IXE0QVNFj9mEtQwYab7jED3viAgFns0/1LnmsBOPJNgFla8oD7XsalzdY2X64N8="
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="completed keyexchange"
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] MyVolumio plugin successfully loaded
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Starting plugin system_controller.my_volumio
Apr 23 16:03:47 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:47 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:47 volumio volumio[1065]: info: Starting MyVolumio Remote Streaming Endpoints
Apr 23 16:03:47 volumio volumio[1065]: info: MyVolumio login type: Token
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] MyVolumio plugin successfully started
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Loading plugin "streaming_services"...
Apr 23 16:03:47 volumio volumio[1065]: info: Starting Streaming Service Transparent Proxy
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Streaming Services plugin successfully loaded
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Starting plugin music_service.streaming_services
Apr 23 16:03:47 volumio volumio[1065]: info: Streaming services startup
Apr 23 16:03:47 volumio volumio[1065]: info: Starting Streaming Daemon
Apr 23 16:03:47 volumio sudo[3547]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Apr 23 16:03:47 volumio sudo[3547]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:47 volumio go-librespot[3362]: time="2025-04-23T16:03:47+09:00" level=debug msg="completed challenge"
Apr 23 16:03:47 volumio volumio[1065]: info: [MyVolumio PluginManager] Streaming Services plugin successfully started
Apr 23 16:03:47 volumio sudo[3547]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:47 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:03:47 volumio volumio[1065]: info: [now-playing] OpenWeatherMap API key obtained.
Apr 23 16:03:47 volumio volumio[1065]: error: Cannot start Volumio Streaming Daemon
Apr 23 16:03:48 volumio volumio[1065]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Apr 23 16:03:48 volumio volumio[1065]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Apr 23 16:03:48 volumio volumio[1065]: info: Connection to go-librespot Websocket established
Apr 23 16:03:48 volumio go-librespot[3362]: time="2025-04-23T16:03:48+09:00" level=debug msg="new websocket client"
Apr 23 16:03:48 volumio volumio[1065]: info: Cannot call home: Error: Command failed: /usr/bin/curl -X POST --data-binary "device=pi&variante=volumio&version=3.785&uuid=8bb605e3ec1dd29462b3332e20266be3" http://updates.volumio.org/downloader-v1/track-device
Apr 23 16:03:48 volumio volumio[1065]: % Total % Received % Xferd Average Speed Time Time Time Current
Apr 23 16:03:48 volumio volumio[1065]: Dload Upload Total Spent Left Speed
Apr 23 16:03:48 volumio volumio[1065]: [132B blob data]
Apr 23 16:03:48 volumio volumio[1065]: retrying in 5 seconds, trial 0
Apr 23 16:03:48 volumio volumio[1065]: info: Volumio Calling Home
Apr 23 16:03:48 volumio go-librespot[3362]: time="2025-04-23T16:03:48+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:03:48 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:03:48 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:03:48 volumio volumio[1065]: info: Connection to go-librespot Websocket closed
Apr 23 16:03:48 volumio volumio[1065]: STREAMING PROXY: Starting server on port 3245
Apr 23 16:03:48 volumio volumio[1065]: Node JS runtime: 14
Apr 23 16:03:48 volumio volumio[1065]: error: MyVolumio Custom Token format not valid, refreshing it
Apr 23 16:03:48 volumio sudo[3216]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:48 volumio volumio[1065]: info: Cannot mount NAS hbymomv at system boot, trial number 2 ,retrying in 5 seconds
Apr 23 16:03:48 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation.
Apr 23 16:03:48 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113
Apr 23 16:03:48 volumio volumio[1065]: info: Volumio called home
Apr 23 16:03:48 volumio volumio[1065]: error: [now-playing] Error fetching https://openweathermap.org/data/2.5/onecall?appid=5796abbde9106b7da4febfae8c44c232&lat=37.55655&lon=127.03164: Error: Response error: 401 - Unauthorized
Apr 23 16:03:48 volumio volumio[1065]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:29:15)
Apr 23 16:03:48 volumio volumio[1065]: at runMicrotasks ()
Apr 23 16:03:48 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Apr 23 16:03:48 volumio volumio[1065]: at async Promise.all (index 0)
Apr 23 16:03:48 volumio volumio[1065]: at async fetchData (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:84:24)
Apr 23 16:03:48 volumio volumio[1065]: at async OpenWeatherMapAPI.getWeather (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:97:45)
Apr 23 16:03:48 volumio volumio[1065]: at async /data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:297:25
Apr 23 16:03:48 volumio volumio[1065]: info: [now-playing] Fetching API key...
Apr 23 16:03:48 volumio volumio[1065]: error: [now-playing] Error fetching https://openweathermap.org/data/2.5/weather?appid=5796abbde9106b7da4febfae8c44c232&lat=37.55655&lon=127.03164: Error: Response error: 401 - Unauthorized
Apr 23 16:03:48 volumio volumio[1065]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:29:15)
Apr 23 16:03:48 volumio volumio[1065]: at runMicrotasks ()
Apr 23 16:03:48 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Apr 23 16:03:48 volumio volumio[1065]: at async Promise.all (index 1)
Apr 23 16:03:49 volumio volumio[1065]: info: MyVolumio login type: Token
Apr 23 16:03:49 volumio squeezeboxserver[985]: [16:03:49.207] mDNSsearchCallback:691 [0x195a80]: changed ip:port 192.168.219.105:5000
Apr 23 16:03:49 volumio volumio[1065]: verbose: New Socket.io Connection to 192.168.219.105 from 192.168.219.100 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_4 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 8
Apr 23 16:03:49 volumio volumio[1065]: info: MYVOLUMIO SUCCESSFULLY LOGGED IN
Apr 23 16:03:50 volumio volumio[3282]: ................................................................................................................................................++++
Apr 23 16:03:51 volumio volumio[1065]: info: Getting Spotify volume
Apr 23 16:03:51 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:03:51 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16)
Apr 23 16:03:51 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 5)
Apr 23 16:03:51 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 9
Apr 23 16:03:51 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:51 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:51 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:03:51 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:03:51 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:03:51 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 3.
Apr 23 16:03:51 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:03:51 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:03:51 volumio go-librespot[3571]: go-librespot daemon starting...
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="app state loaded"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=info msg="zeroconf server listening on port 45227"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="obtained new client token: AADSA5Y7qvplol1zB2+gG3d3NisIhq5QBqMXTXFVg9euzeT27tpFgraXR02unSIkps6ahrEyXAs4Ok3w3Fr7FXPEb/DS9FR1Rx41KsGSTjCSdJnFTTP9z4dKoZMbNYYfsBtcfdUBWbP2TqWMosdO9SvQxisuKVTRWnVyIw6SKG8r/Qh/e3LCEV9vEKe49qQPy3Jkj8S1A49xT0Dgmwq/3hksftbuGAI4UEgjxmH2CCifil+amG+XbzWs7FE="
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="completed keyexchange"
Apr 23 16:03:51 volumio volumio[1065]: info: MyVolumio token set successfully
Apr 23 16:03:51 volumio volumio[1065]: info: MYVOLUMIO: Adding device
Apr 23 16:03:51 volumio volumio[1065]: info: MYVOLUMIO: Evaluating Server
Apr 23 16:03:51 volumio volumio[1065]: info: [now-playing] OpenWeatherMap API key obtained.
Apr 23 16:03:51 volumio squeezeboxserver[985]: [16:03:51.615] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.18.0.1:5000
Apr 23 16:03:51 volumio volumio[1065]: info: MyVolumio status changed
Apr 23 16:03:51 volumio volumio[1065]: info: Streaming services startup
Apr 23 16:03:51 volumio volumio[1065]: info: Starting Streaming Daemon
Apr 23 16:03:51 volumio volumio[1065]: info: Removing browser output: myVolumio user plan is not superstar
Apr 23 16:03:51 volumio volumio[1065]: info: Removing audio output:
Apr 23 16:03:51 volumio volumio[1065]: info: Stoppping Tunnel 1
Apr 23 16:03:51 volumio sudo[3595]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart volumio-streaming-daemon.service
Apr 23 16:03:51 volumio sudo[3595]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:51 volumio sudo[3595]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:51 volumio sudo[3598]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl stop sshtunnel.service
Apr 23 16:03:51 volumio sudo[3598]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:51 volumio volumio[1065]: error: Cannot start Volumio Streaming Daemon
Apr 23 16:03:51 volumio volumio[1065]: error: Failed initialization of streaming services: Error: Error: Command failed: /usr/bin/sudo systemctl restart volumio-streaming-daemon.service
Apr 23 16:03:51 volumio volumio[1065]: Failed to restart volumio-streaming-daemon.service: Unit volumio-streaming-daemon.service not found.
Apr 23 16:03:51 volumio sudo[3598]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:51 volumio volumio[1065]: info: Remote SSH Stopped
Apr 23 16:03:51 volumio go-librespot[3571]: time="2025-04-23T16:03:51+09:00" level=debug msg="completed challenge"
Apr 23 16:03:52 volumio go-librespot[3571]: time="2025-04-23T16:03:52+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:03:52 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:03:52 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:03:52 volumio volumio[1065]: error: [now-playing] Error fetching https://openweathermap.org/data/2.5/onecall?appid=5796abbde9106b7da4febfae8c44c232&lat=37.55655&lon=127.03164: Error: Response error: 401 - Unauthorized
Apr 23 16:03:52 volumio volumio[1065]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:29:15)
Apr 23 16:03:52 volumio volumio[1065]: at runMicrotasks ()
Apr 23 16:03:52 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Apr 23 16:03:52 volumio volumio[1065]: at async Promise.all (index 0)
Apr 23 16:03:52 volumio volumio[1065]: at async fetchData (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:84:24)
Apr 23 16:03:52 volumio volumio[1065]: at async OpenWeatherMapAPI.getWeather (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:97:45)
Apr 23 16:03:52 volumio volumio[1065]: at async /data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:297:25
Apr 23 16:03:52 volumio volumio[1065]: error: [now-playing] API endpoint weather/fetchInfo returned error: Error: Could not fetch weather: Response error: 401 - Unauthorized
Apr 23 16:03:52 volumio volumio[1065]: at WeatherAPI.fetchInfo (/data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:114:19)
Apr 23 16:03:52 volumio volumio[1065]: at runMicrotasks ()
Apr 23 16:03:52 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Apr 23 16:03:52 volumio volumio[1065]: at async Object.api (/data/plugins/user_interface/now_playing/dist/app/Handler.js:113:28)
Apr 23 16:03:52 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: Response error: 401 - Unauthorized
Apr 23 16:03:52 volumio volumio[1065]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:29:15)
Apr 23 16:03:52 volumio volumio[1065]: at runMicrotasks ()
Apr 23 16:03:52 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Apr 23 16:03:52 volumio volumio[1065]: at async Promise.all (index 0)
Apr 23 16:03:52 volumio volumio[1065]: at async fetchData (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:84:24)
Apr 23 16:03:52 volumio volumio[1065]: at async OpenWeatherMapAPI.getWeather (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:97:45)
Apr 23 16:03:52 volumio volumio[1065]: at async /data/plugins/user_interface/now_playing/dist/lib/api/WeatherAPI.js:297:25
Apr 23 16:03:52 volumio volumio[1065]: (node:1065) 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: 7)
Apr 23 16:03:52 volumio volumio[1065]: error: [now-playing] Error fetching https://openweathermap.org/data/2.5/weather?appid=5796abbde9106b7da4febfae8c44c232&lat=37.55655&lon=127.03164: Error: Response error: 401 - Unauthorized
Apr 23 16:03:52 volumio volumio[1065]: at fetchPage (/data/plugins/user_interface/now_playing/dist/lib/api/openweathermap/index.js:29:15)
Apr 23 16:03:52 volumio volumio[1065]: at runMicrotasks ()
Apr 23 16:03:52 volumio volumio[1065]: at processTicksAndRejections (internal/process/task_queues.js:93:5)
Apr 23 16:03:52 volumio volumio[1065]: at async Promise.all (index 1)
Apr 23 16:03:52 volumio volumio[1065]: info: Setting Geolocation for MyVolumio to as2
Apr 23 16:03:52 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:52 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:52 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:52 volumio volumio[1065]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Apr 23 16:03:53 volumio volumio[1065]: info: Updating MyVolumio device info
Apr 23 16:03:53 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:53 volumio sudo[3615]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=raspberry,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.219.109/OMV/ /mnt/NAS/hbymomv
Apr 23 16:03:53 volumio sudo[3615]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:03:53 volumio kernel: CIFS: Attempting to mount //192.168.219.109/OMV
Apr 23 16:03:53 volumio volumio[1065]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Apr 23 16:03:54 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:03:54 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:03:54 volumio volumio[1065]: verbose: New Socket.io Connection to 192.168.219.105 from 192.168.219.100 UA: Mozilla/5.0 (iPhone; CPU iPhone OS 18_4 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Mobile/15E148 Engine version: 3 Transport: polling Total Clients: 10
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Apr 23 16:03:54 volumio volumio[1065]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates
Apr 23 16:03:54 volumio volumio[1065]: info: Received Get System Version
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Apr 23 16:03:54 volumio volumio[1065]: info: Received Get System Info
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 23 16:03:54 volumio volumio[1065]: info: Discovery: Getting this device information
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:54 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::volumioGetVisibleSources
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:54 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Apr 23 16:03:54 volumio volumio[1065]: info: Received Get System Info
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Apr 23 16:03:54 volumio volumio[1065]: info: Discovery: Getting this device information
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:54 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:03:54 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:03:54 volumio volumio[1065]: info: Listing playlists
Apr 23 16:03:54 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Apr 23 16:03:55 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:03:55 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 4.
Apr 23 16:03:55 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:03:55 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:03:55 volumio go-librespot[3619]: go-librespot daemon starting...
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="app state loaded"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=info msg="zeroconf server listening on port 37851"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="obtained new client token: AAD/BK2W4Di5EVTvplMQeaz5pW7OCMNpdwPG47JDi+PBru55PFoWTE8OvT0zqmuaF6AkownKzJ+NhjXOThykHeHKSzSqXd3Z2euJzL7PXgweOvopcwQMp7AGrpR5EfPcQ2aRsE1lq0NSm4veTcX7nLjCP7Dk8P9Ga/D8a1t0t2HqsaH+voCoo+8OffTVnJsR3Vwl6K9NYw5DY4yDHo0Cu04176ZCfS7xtD3LUX1iK5D32wXpkcp4mQvUVko="
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="completed keyexchange"
Apr 23 16:03:55 volumio volumio[1065]: info: CoreCommandRouter::volumioGetQueue
Apr 23 16:03:55 volumio volumio[1065]: info: CoreStateMachine::getQueue
Apr 23 16:03:55 volumio volumio[1065]: info: CorePlayQueue::getQueue
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=debug msg="completed challenge"
Apr 23 16:03:55 volumio go-librespot[3619]: time="2025-04-23T16:03:55+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:03:55 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:03:55 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:03:56 volumio volumio[1065]: info: MYVOLUMIO: Adding device
Apr 23 16:03:56 volumio volumio[1065]: info: MYVOLUMIO: Evaluating Server
Apr 23 16:03:57 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:03:57 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:03:57 volumio volumio[1065]: info: Setting Geolocation for MyVolumio to as2
Apr 23 16:03:57 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:57 volumio systemd[1]: systemd-fsckd.service: Succeeded.
Apr 23 16:03:58 volumio volumio[1065]: error: Failed to add MyVolumio device: {"message":"USER_NOT_FOUND"}
Apr 23 16:03:58 volumio volumio[1065]: info: Updating MyVolumio device info
Apr 23 16:03:58 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:03:59 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:03:59 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 5.
Apr 23 16:03:59 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:03:59 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:03:59 volumio go-librespot[3643]: go-librespot daemon starting...
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="app state loaded"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:03:59 volumio volumio[1065]: error: Failed to update MyVolumio device: {"message":"DEVICE_NOT_FOUND"}
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=info msg="zeroconf server listening on port 42321"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="obtained new client token: AACsf/bhYBFuB3xqXwXIi9dRFuHCIQdlazP7vm8i8gTutqcqa2q7q0irthUgGtVctM8uDiFkpAjR2HQIXzLaX9pwjE3HiNXHuu8X/zDotuXcb7yUNckhzQl8cY58a6lgyqP+53MxAgem+X9SD79sl7WFNCoQvKQrsy1QLBMiJvLb8a54/JqC+LJbZRBkrd1K1fiJmuVxyv6q7SaxVDzkRXj5IUDT8D2cRpSTqEta4zq2p3WlAuXL/6lRG4g="
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused"
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="connected to ap-gae2.spotify.com:443"
Apr 23 16:03:59 volumio systemd[1]: systemd-hostnamed.service: Succeeded.
Apr 23 16:03:59 volumio go-librespot[3643]: time="2025-04-23T16:03:59+09:00" level=debug msg="completed keyexchange"
Apr 23 16:03:59 volumio sudo[3615]: pam_unix(sudo:session): session closed for user root
Apr 23 16:03:59 volumio volumio[1065]: info: Cannot mount NAS hbymomv at system boot, trial number 3 ,retrying in 5 seconds
Apr 23 16:03:59 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation.
Apr 23 16:03:59 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113
Apr 23 16:04:00 volumio go-librespot[3643]: time="2025-04-23T16:04:00+09:00" level=debug msg="completed challenge"
Apr 23 16:04:00 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:04:00 volumio go-librespot[3643]: time="2025-04-23T16:04:00+09:00" level=debug msg="new websocket client"
Apr 23 16:04:00 volumio volumio[1065]: info: Connection to go-librespot Websocket established
Apr 23 16:04:00 volumio go-librespot[3643]: time="2025-04-23T16:04:00+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:04:00 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:04:00 volumio volumio[1065]: info: Connection to go-librespot Websocket closed
Apr 23 16:04:00 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:04:00 volumio volumio[3282]: ..............................................................................................................................................................................................................++++
Apr 23 16:04:00 volumio volumio[3282]: e is 65537 (0x010001)
Apr 23 16:04:00 volumio volumio[3282]: writing RSA key
Apr 23 16:04:02 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Apr 23 16:04:02 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11
Apr 23 16:04:02 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:04:02 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:04:03 volumio volumio[1065]: info: Getting Spotify volume
Apr 23 16:04:03 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:04:03 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16)
Apr 23 16:04:03 volumio volumio[1065]: (node:1065) 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: 8)
Apr 23 16:04:03 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 12
Apr 23 16:04:03 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:04:03 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:04:03 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:04:03 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:04:03 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:04:03 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 6.
Apr 23 16:04:03 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:04:03 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:04:03 volumio go-librespot[3691]: go-librespot daemon starting...
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="app state loaded"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=info msg="zeroconf server listening on port 34393"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="obtained new client token: AABa8Qdmk7xNxw5VqHL0R94unXNvQ0qAaTs8LHRFY4pka/2DfmiZ+JGsTqIsMLkrfk5G54guyt0mk7hwVM7zpvAgkmlT0Sv5oGFY4U46/T91OsM3JSzgNbEaXSVOXbuO/SHUTyssH9RDXz0RovQ8t0RM+zK7dW0vPtLWQmkBgRJWHBBu645xUMdS8wX58uIWmvIusSK/xYv2aNYbgxLLdMZ1WoNluDgPPKFHezUwM5E48HsFf0V6i/ej"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=warning msg="failed to connect to AP ap-gae2.spotify.com:4070, retrying with a different AP" error="dial tcp 104.199.241.202:4070: connect: connection refused"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="connected to ap-gae2.spotify.com:443"
Apr 23 16:04:03 volumio go-librespot[3691]: time="2025-04-23T16:04:03+09:00" level=debug msg="completed keyexchange"
Apr 23 16:04:04 volumio go-librespot[3691]: time="2025-04-23T16:04:04+09:00" level=debug msg="completed challenge"
Apr 23 16:04:04 volumio go-librespot[3691]: time="2025-04-23T16:04:04+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:04:04 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:04:04 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:04:04 volumio sudo[3703]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/mount -t cifs -o username=pi,password=raspberry,ro,dir_mode=0777,file_mode=0666,iocharset=utf8,noauto,soft //192.168.219.109/OMV/ /mnt/NAS/hbymomv
Apr 23 16:04:04 volumio sudo[3703]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 23 16:04:04 volumio kernel: CIFS: Attempting to mount //192.168.219.109/OMV
Apr 23 16:04:06 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:04:06 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 23 16:04:07 volumio volumio[1065]: info: Retrieving Cloud Streaming UI
Apr 23 16:04:07 volumio volumio[1065]: info: Getting Tidal Cloud Configuration
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 23 16:04:07 volumio volumio[1065]: info: Getting Qobuz Cloud Configuration
Apr 23 16:04:07 volumio volumio[1065]: info: Asking plugin for UI Config
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 23 16:04:07 volumio volumio[1065]: info: Getting Spotify Cloud Configuration
Apr 23 16:04:07 volumio volumio[1065]: info: Asking plugin for UI Config
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 23 16:04:07 volumio volumio[1065]: info: Saving Spotify Acccount
Apr 23 16:04:07 volumio volumio[1065]: info: Got Tidal Cloud Configuration
Apr 23 16:04:07 volumio volumio[1065]: info: Got it
Apr 23 16:04:07 volumio volumio[1065]: info: Got it
Apr 23 16:04:07 volumio volumio[1065]: error: Could not retrieve Spotify Config from plugin Spotify: no section found
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::getUIConfigOnPlugin
Apr 23 16:04:07 volumio volumio[1065]: error: Error retrieving Highresaudio conf: TypeError: Cannot read property 'onSave' of undefined
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: albumart , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: appearance , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStatsObject
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::volumioGetBrowseSources
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Apr 23 16:04:07 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:04:07 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 7.
Apr 23 16:04:07 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:04:07 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:04:07 volumio go-librespot[3710]: go-librespot daemon starting...
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="app state loaded"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=info msg="zeroconf server listening on port 35641"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="obtained new client token: AAAP7U7qxGGQ9ekKnTkmCeZPi4ab0jc4BdYdWa02cmy0/q/JLLdg5NiTKzu5R35D1t3BBeygzfLXEi8w8qHorAfsb2yDlq3MCs9jm3A70fW/J/vZQM1AhOS/oUSQlAwXQ457lKLKN7aqcr3zmKYo3FYoNHTtQ3RwGKLGJTPFK07qbU/homFWU8+2JHBPPviJJCOkh7EWxw40Afuh+Qr6qTE47vihI7DQ0tP6MweNuvaP2jD6llCsfn24"
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Apr 23 16:04:07 volumio go-librespot[3710]: time="2025-04-23T16:04:07+09:00" level=debug msg="completed keyexchange"
Apr 23 16:04:07 volumio volumio[1065]: error: MyVolumio Plugin failed to authenticate in a timely fashion
Apr 23 16:04:07 volumio volumio[1065]: info: Completed starting MyVolumio Plugin
Apr 23 16:04:07 volumio volumio[1065]: [Metrics] CommandRouter: 36s 143.62ms
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::volumiosetStartupVolume
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::Close All Modals sent
Apr 23 16:04:07 volumio volumio[1065]: info: CoreCommandRouter::Close All Modals sent
Apr 23 16:04:08 volumio volumio-remote-updater[826]: No test mode
Apr 23 16:04:08 volumio volumio-remote-updater[826]: No alpha test mode
Apr 23 16:04:08 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateEnabled
Apr 23 16:04:08 volumio go-librespot[3710]: time="2025-04-23T16:04:08+09:00" level=debug msg="completed challenge"
Apr 23 16:04:08 volumio go-librespot[3710]: time="2025-04-23T16:04:08+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:04:08 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:04:08 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:04:08 volumio volumio[1065]: info: Update Ready: {"changeLogLink":"http://volumio.org","description":"FIXES
- Improved translations
NEW ADDITIONS
- Update to TIDAL Connect
- Add Install-to-disk option for the new RPi5 HW revisions
","title":"Update v3.799","updateavailable":true}
Apr 23 16:04:08 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: updater_comm , setUpdateMessageCache
Apr 23 16:04:08 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , checkAudioDeviceAvailable
Apr 23 16:04:08 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: i2s_dacs , getI2sStatus
Apr 23 16:04:08 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: system , versionChangeDetect
Apr 23 16:04:09 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:04:09 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:04:10 volumio systemd[1]: systemd-timedated.service: Succeeded.
Apr 23 16:04:10 volumio sudo[3703]: pam_unix(sudo:session): session closed for user root
Apr 23 16:04:10 volumio volumio[1065]: info: Cannot mount NAS hbymomv at system boot, trial number 4 ,retrying in 5 seconds
Apr 23 16:04:11 volumio kernel: CIFS: VFS: Error connecting to socket. Aborting operation.
Apr 23 16:04:11 volumio kernel: CIFS: VFS: cifs_mount failed w/return code = -113
Apr 23 16:04:11 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
Apr 23 16:04:11 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:04:11 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 8.
Apr 23 16:04:11 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:04:11 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:04:11 volumio go-librespot[3730]: go-librespot daemon starting...
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="app state loaded"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-guc3.spotify.com:4070 ap-gue1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 guc3-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 guc3-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=info msg="zeroconf server listening on port 33331"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="obtained new client token: AABrODm03H3RTltMx6h/ZRCIjDIJu+vHJ92z4pTCUTK9lLrpYgs3A0ssAUtvehyg6SRUS5Uozo8Ed4R5DkWAq/8VOguyRWWN6drvK92pDGSD4+ukLWTKhCC8cGiLnCukjtU8ED4fPIYy4gWAScacDu9GIJuBaMR0mFE0cEXR1hbCXBNSfsh2nOP6Sw9T8bBg8U8lZ1Kxh5dffLMUggu9TRrVMl9ayAUbPAaT+ndieRC3Ysoc6d83z95N"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:04:11 volumio go-librespot[3730]: time="2025-04-23T16:04:11+09:00" level=debug msg="completed keyexchange"
Apr 23 16:04:12 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:04:12 volumio go-librespot[3730]: time="2025-04-23T16:04:12+09:00" level=debug msg="new websocket client"
Apr 23 16:04:12 volumio volumio[1065]: info: Connection to go-librespot Websocket established
Apr 23 16:04:12 volumio go-librespot[3730]: time="2025-04-23T16:04:12+09:00" level=debug msg="completed challenge"
Apr 23 16:04:12 volumio go-librespot[3730]: time="2025-04-23T16:04:12+09:00" level=fatal msg="failed running with username and spotify token" error="failed authenticating accesspoint with stored credentials: failed authenticating: failed login: BadCredentials"
Apr 23 16:04:12 volumio systemd[1]: go-librespot-daemon.service: Main process exited, code=exited, status=1/FAILURE
Apr 23 16:04:12 volumio systemd[1]: go-librespot-daemon.service: Failed with result 'exit-code'.
Apr 23 16:04:12 volumio volumio[1065]: info: Connection to go-librespot Websocket closed
Apr 23 16:04:13 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , deleteShare
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.974] AddMRDevice:1455 [0x1f5290]: adding renderer (Volumio-UPnP/AV) 192.168.219.105 with mac BBBB-F0BD0DA4
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.976] MasterHandler:1077 [0x1f5290]: subscribe fail, re-trying 1
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] MasterHandler:1077 [0x1f5290]: subscribe fail, re-trying 2
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] MasterHandler:1077 [0x1f5290]: subscribe fail, re-trying 3
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] MasterHandler:1080 [0x1f5290]: subscribe fail, volume feedback will not work
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] slimproto:885 squeezelite [0x178730] <=> player [0x1f5290]
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] slimproto:886 [0x178730] connecting to 192.168.219.105:3483
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] slimproto:916 [0x178730] connected
Apr 23 16:04:13 volumio squeezeboxserver[985]: [16:04:13.977] sendHELO:131 [0x178730] cap: CanHTTPS=1,Model=squeezelite,ModelName=UPnPBridge,AccuratePlayPoints=0,HasDigitalOut=1,MaxSampleRate=384000,aac,ogg,ops,ogf,flc,alc,wav,aif,pcm,mp3
Apr 23 16:04:14 volumio squeezeboxserver[985]: [16:04:14.002] main:253 host: volumio.local
Apr 23 16:04:14 volumio squeezeboxserver[985]: identity: A9362DBC3B67@Volumio-UPnP/AV
Apr 23 16:04:14 volumio squeezeboxserver[985]: type: _raop._tcp.local
Apr 23 16:04:14 volumio squeezeboxserver[985]: ip: 192.168.219.105
Apr 23 16:04:14 volumio squeezeboxserver[985]: port: 34351
Apr 23 16:04:14 volumio squeezeboxserver[985]: with TXT:
Apr 23 16:04:14 volumio squeezeboxserver[985]: tp=UDP
Apr 23 16:04:14 volumio squeezeboxserver[985]: sm=false
Apr 23 16:04:14 volumio squeezeboxserver[985]: sv=false
Apr 23 16:04:14 volumio squeezeboxserver[985]: ek=1
Apr 23 16:04:14 volumio squeezeboxserver[985]: et=0,1
Apr 23 16:04:14 volumio squeezeboxserver[985]: md=0,1,2
Apr 23 16:04:14 volumio squeezeboxserver[985]: cn=0,1
Apr 23 16:04:14 volumio squeezeboxserver[985]: ch=2
Apr 23 16:04:14 volumio squeezeboxserver[985]: ss=16
Apr 23 16:04:14 volumio squeezeboxserver[985]: sr=44100
Apr 23 16:04:14 volumio squeezeboxserver[985]: pw=false
Apr 23 16:04:14 volumio squeezeboxserver[985]: vn=3
Apr 23 16:04:14 volumio squeezeboxserver[985]: txtvers=1
Apr 23 16:04:14 volumio squeezeboxserver[985]: am=shairtunes2
Apr 23 16:04:14 volumio squeezeboxserver[985]: [16:04:14.003] mDNSsearchCallback:691 [0x195a80]: changed ip:port 192.168.219.105:5000
Apr 23 16:04:14 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: networkfs , listShares
Apr 23 16:04:14 volumio volumio[1065]: info: BOOT COMPLETED
Apr 23 16:04:15 volumio volumio[1065]: info: Getting Spotify volume
Apr 23 16:04:15 volumio volumio[1065]: (node:1065) UnhandledPromiseRejectionWarning: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:04:15 volumio volumio[1065]: at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16)
Apr 23 16:04:15 volumio volumio[1065]: (node:1065) 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: 9)
Apr 23 16:04:15 volumio volumio[1065]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Engine version: 3 Transport: polling Total Clients: 11
Apr 23 16:04:15 volumio volumio[1065]: info: CoreCommandRouter::volumioGetState
Apr 23 16:04:15 volumio volumio[1065]: info: CorePlayQueue::getTrack 0
Apr 23 16:04:15 volumio volumio[1065]: info: CoreCommandRouter::executeOnPlugin: mpd , getMyCollectionStats
Apr 23 16:04:15 volumio volumio[1065]: info: Initializing connection to go-librespot Websocket
Apr 23 16:04:15 volumio volumio[1065]: info: Error connecting to go-librespot Websocket: Error: connect ECONNREFUSED 127.0.0.1:9879
Apr 23 16:04:15 volumio systemd[1]: go-librespot-daemon.service: Service RestartSec=3s expired, scheduling restart.
Apr 23 16:04:15 volumio systemd[1]: go-librespot-daemon.service: Scheduled restart job, restart counter is at 9.
Apr 23 16:04:15 volumio systemd[1]: Stopped go-librespot Daemon.
Apr 23 16:04:15 volumio systemd[1]: Started go-librespot Daemon.
Apr 23 16:04:15 volumio go-librespot[3777]: go-librespot daemon starting...
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=info msg="running go-librespot 0.1.3"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="app state loaded"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=info msg="api server listening on 127.0.0.1:9879"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="fetched new accesspoints: [ap-gae2.spotify.com:4070 ap-gae2.spotify.com:443 ap-gae2.spotify.com:80 ap-gue1.spotify.com:4070 ap-gew1.spotify.com:443 ap-gew4.spotify.com:80]"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="fetched new dealers: [gae2-dealer.spotify.com:443 gue1-dealer.spotify.com:443 gew1-dealer.spotify.com:443 gew4-dealer.spotify.com:443]"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="fetched new spclients: [gae2-spclient.spotify.com:443 gue1-spclient.spotify.com:443 gew1-spclient.spotify.com:443 gew4-spclient.spotify.com:443]"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=info msg="zeroconf server listening on port 33807"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="obtained new client token: AAACvnZaYPlbTTqGc40G1/DduxKt+uPtL8XG3Fp7c3QQ5byoSq7pG8XJugZaITM1qn6dNEVIIlFINj9RZeU2ghYT92ZSKpsNVaAu9drDQLC79eUz9EhwVddEDlHPPHTbAMgUit/2YZAZ8JUoH9sl5WTr3ZSt5C3+NyIJSYwOPwt9lInkCMTHIGSgp0gwBygmBCywV0/9WzVs7iF9Oh03OT8qwjijPSQI48L+5Y4LfanzC/NNgvDXVvED"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="connected to ap-gae2.spotify.com:4070"
Apr 23 16:04:15 volumio go-librespot[3777]: time="2025-04-23T16:04:15+09:00" level=debug msg="completed keyexchange"
Apr 23 16:04:16 volumio volumio[1065]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 23 16:04:16 volumio volumio[1065]: TypeError: Cannot read property 'replace' of undefined
Apr 23 16:04:16 volumio volumio[1065]: at ControllerNetworkfs.mountShare (/volumio/app/plugins/system_controller/networkfs/index.js:202:28)
Apr 23 16:04:16 volumio volumio[1065]: at Timeout._onTimeout (/volumio/app/plugins/system_controller/networkfs/index.js:255:20)
Apr 23 16:04:16 volumio volumio[1065]: at listOnTimeout (internal/timers.js:554:17)
Apr 23 16:04:16 volumio volumio[1065]: at processTimers (internal/timers.js:497:7)
Apr 23 16:04:16 volumio volumio[1065]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Apr 23 16:04:16 volumio squeezeboxserver[985]: [16:04:16.009] mDNSsearchCallback:691 [0x195a80]: changed ip:port 172.18.0.1:5000
Apr 23 16:04:16 volumio sudo[3796]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-04-23 16:03
Apr 23 16:04:16 volumio sudo[3796]: pam_unix(sudo:session): session opened for user root by (uid=0)
PRETTY_NAME="Raspbian GNU/Linux 10 (buster)"
NAME="Raspbian GNU/Linux"
VERSION_ID="10"
VERSION="10 (buster)"
VERSION_CODENAME=buster
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"
VOLUMIO_BUILD_VERSION="f6610a1100d2380eef33bd3004af43153c786f96"
VOLUMIO_FE_VERSION="e7cae168f9927391640a091813b8a9656b6909b6"
VOLUMIO_FE3_VERSION="df82a8f23c90a3617c15c55572c8aaea90d8b32a"
VOLUMIO_BE_VERSION="1c0e5daee99fe3a72cc38b0d1fe6cd78d7f001fe"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Mon 16 Dec 2024 09:30:04 AM CET"
VOLUMIO_VERSION="3.785"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="fe0ac4b79aed19ccde4b5bd83d468193"