-- Logs begin at Thu 2019-02-14 10:11:59 UTC, end at Thu 2024-10-31 03:03:38 UTC. -- Oct 31 03:03:25 volumio ntpd[851]: receive: Unexpected origin timestamp 0xeac82efa.bc95e58a does not match aorg 0000000000.00000000 from server@39.118.108.191 xmt 0xeacd71fd.7a2eac4a Oct 31 03:03:25 volumio ntpd[851]: receive: Unexpected origin timestamp 0xeac82efa.bc8c8276 does not match aorg 0000000000.00000000 from server@106.247.248.106 xmt 0xeacd71fd.7a4e5fda Oct 31 03:03:25 volumio ntpd[851]: receive: Unexpected origin timestamp 0xeac82efa.bc993116 does not match aorg 0000000000.00000000 from server@3.39.176.65 xmt 0xeacd71fd.7a4948a4 Oct 31 03:03:25 volumio ntpd[851]: receive: Unexpected origin timestamp 0xeac82efa.bc979411 does not match aorg 0000000000.00000000 from server@175.193.3.234 xmt 0xeacd71fd.79f69b6c Oct 31 03:03:25 volumio systemd[1]: Starting Daily apt download activities... Oct 31 03:03:25 volumio dnsmasq[964]: exiting on receipt of SIGTERM Oct 31 03:03:25 volumio systemd[1]: dnsmasq.service: Succeeded. Oct 31 03:03:25 volumio systemd[1]: Stopped dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:25 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:25 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 03:03:25 volumio hostapd[981]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 03:03:25 volumio hostapd[981]: Could not read interface wlan0 flags: No such device Oct 31 03:03:25 volumio hostapd[981]: nl80211: Driver does not support authentication/association or connect commands Oct 31 03:03:25 volumio hostapd[981]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 03:03:25 volumio hostapd[981]: Could not read interface wlan0 flags: No such device Oct 31 03:03:25 volumio hostapd[981]: nl80211 driver initialization failed. Oct 31 03:03:25 volumio hostapd[981]: wlan0: interface state UNINITIALIZED->DISABLED Oct 31 03:03:25 volumio hostapd[981]: wlan0: AP-DISABLED Oct 31 03:03:25 volumio hostapd[981]: wlan0: CTRL-EVENT-TERMINATING Oct 31 03:03:25 volumio hostapd[981]: hostapd_free_hapd_data: Interface wlan0 wasn't started Oct 31 03:03:25 volumio systemd[1]: hostapd.service: Control process exited, code=exited, status=1/FAILURE Oct 31 03:03:25 volumio systemd[1]: hostapd.service: Failed with result 'exit-code'. Oct 31 03:03:25 volumio systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:25 volumio systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:25 volumio dnsmasq[988]: dnsmasq: syntax check OK. Oct 31 03:03:25 volumio dnsmasq[997]: started, version 2.80 cachesize 150 Oct 31 03:03:25 volumio dnsmasq[997]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 03:03:25 volumio dnsmasq[997]: warning: interface wlan0 does not currently exist Oct 31 03:03:25 volumio dnsmasq-dhcp[997]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 03:03:25 volumio dnsmasq[997]: reading /etc/resolv.conf Oct 31 03:03:25 volumio dnsmasq[997]: using nameserver 210.220.163.82#53 Oct 31 03:03:25 volumio dnsmasq[997]: using nameserver 219.250.36.130#53 Oct 31 03:03:25 volumio dnsmasq[997]: using nameserver 208.67.222.222#53 Oct 31 03:03:25 volumio dnsmasq[997]: using nameserver 208.67.220.220#53 Oct 31 03:03:25 volumio dnsmasq[997]: read /etc/hosts - 5 addresses Oct 31 03:03:25 volumio systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:26 volumio systemd[1]: apt-daily.service: Succeeded. Oct 31 03:03:26 volumio systemd[1]: Started Daily apt download activities. Oct 31 03:03:26 volumio systemd[1]: Starting Daily apt upgrade and clean activities... Oct 31 03:03:26 volumio volumio[754]: info: Loading plugin "outputs"... Oct 31 03:03:26 volumio volumio[754]: info: Loading plugin "albumart"... Oct 31 03:03:26 volumio volumio[754]: info: Plugin example_plugin is not enabled Oct 31 03:03:26 volumio volumio[754]: info: Loading plugin "inputs"... Oct 31 03:03:26 volumio volumio[754]: info: Loading plugin "updater_comm"... Oct 31 03:03:27 volumio volumio[754]: info: Plugin mpdemulation is not enabled Oct 31 03:03:27 volumio volumio[754]: info: Loading plugin "rest_api"... Oct 31 03:03:27 volumio volumio[754]: info: Loading plugin "websocket"... Oct 31 03:03:27 volumio volumio[754]: info: Loading i18n strings for locale ko Oct 31 03:03:27 volumio volumio[754]: Updating browse sources language Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 03:03:27 volumio systemd[1]: apt-daily-upgrade.service: Succeeded. Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::initPlayerControls Oct 31 03:03:27 volumio systemd[1]: Started Daily apt upgrade and clean activities. Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 03:03:27 volumio volumio[754]: Express server listening on port 3000 Oct 31 03:03:27 volumio volumio[754]: [Metrics] WebUI: 10s 909.65ms Oct 31 03:03:27 volumio volumio[754]: info: CoreStateMachine::resetVolumioState Oct 31 03:03:27 volumio volumio[754]: info: CoreStateMachine::getcurrentVolume Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 03:03:27 volumio volumio[754]: error: Cannot read config.txt file: Error: ENOENT: no such file or directory, open '/boot/config.txt' Oct 31 03:03:27 volumio volumio[754]: info: Completed loading Core Plugins Oct 31 03:03:27 volumio volumio[754]: info: Preparing to generate the ALSA configuration file Oct 31 03:03:27 volumio volumio[754]: Forking 3 albumart workers Oct 31 03:03:27 volumio volumio[754]: info: Cannot read proc/cpuinfo: Error: Command failed: cat /proc/cpuinfo | grep Hardware Oct 31 03:03:27 volumio volumio[754]: info: MPD Permissions set Oct 31 03:03:27 volumio volumio[754]: error: An error occurred while scanning: Error: Command failed: sudo /sbin/iwlist wlan0 scan Oct 31 03:03:27 volumio volumio[754]: wlan0 Interface doesn't support scanning. Oct 31 03:03:27 volumio volumio[754]: info: Cannot use regular scanning, forcing with ap-force Oct 31 03:03:27 volumio sudo[1127]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw dev wlan0 scan ap-force Oct 31 03:03:27 volumio sudo[1127]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:27 volumio sudo[1127]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:27 volumio volumio[754]: command failed: No such device (-19) Oct 31 03:03:27 volumio volumio[754]: error: Cannot use fallback scanning method: Error: Command failed: /usr/bin/sudo /sbin/iw dev wlan0 scan ap-force Oct 31 03:03:27 volumio volumio[754]: command failed: No such device (-19) Oct 31 03:03:27 volumio volumio-remote-updater[486]: [2024-10-31 03:03:27] [connect] WebSocket Connection 127.0.0.1:3000 v-2 "WebSocket++/0.8.2" /socket.io/?EIO=4&transport=websocket&t=1729998969 101 Oct 31 03:03:27 volumio systemd[1]: hostapd.service: Service RestartSec=2s expired, scheduling restart. Oct 31 03:03:27 volumio systemd[1]: hostapd.service: Scheduled restart job, restart counter is at 6. Oct 31 03:03:27 volumio systemd[1]: Stopping dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:27 volumio volumio[754]: verbose: New Socket.io Connection to 127.0.0.1:3000 from 127.0.0.1 UA: WebSocket++/0.8.2 Total Clients: 1 Oct 31 03:03:27 volumio volumio[754]: info: MPD running with PID938 Oct 31 03:03:27 volumio volumio[754]: ,establishing connection Oct 31 03:03:27 volumio dnsmasq[997]: exiting on receipt of SIGTERM Oct 31 03:03:27 volumio systemd[1]: dnsmasq.service: Succeeded. Oct 31 03:03:27 volumio systemd[1]: Stopped dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:27 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:27 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 03:03:27 volumio hostapd[1140]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 03:03:27 volumio volumio[754]: error: MPD error: The expression evaluated to a falsy value: Oct 31 03:03:27 volumio volumio[754]: assert.ok(self.idling) Oct 31 03:03:27 volumio volumio[754]: error: MPD error: The expression evaluated to a falsy value: Oct 31 03:03:27 volumio volumio[754]: assert.ok(self.idling) Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:27 volumio hostapd[1140]: Could not read interface wlan0 flags: No such device Oct 31 03:03:27 volumio hostapd[1140]: nl80211: Driver does not support authentication/association or connect commands Oct 31 03:03:27 volumio hostapd[1140]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 31 03:03:28 volumio hostapd[1140]: Could not read interface wlan0 flags: No such device Oct 31 03:03:28 volumio hostapd[1140]: nl80211 driver initialization failed. Oct 31 03:03:28 volumio hostapd[1140]: wlan0: interface state UNINITIALIZED->DISABLED Oct 31 03:03:28 volumio hostapd[1140]: wlan0: AP-DISABLED Oct 31 03:03:28 volumio hostapd[1140]: wlan0: CTRL-EVENT-TERMINATING Oct 31 03:03:28 volumio hostapd[1140]: hostapd_free_hapd_data: Interface wlan0 wasn't started Oct 31 03:03:28 volumio systemd[1]: hostapd.service: Control process exited, code=exited, status=1/FAILURE Oct 31 03:03:28 volumio systemd[1]: hostapd.service: Failed with result 'exit-code'. Oct 31 03:03:28 volumio systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: Reloading queue from file Oct 31 03:03:28 volumio systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:28 volumio dnsmasq[1157]: dnsmasq: syntax check OK. Oct 31 03:03:28 volumio volumio[754]: info: VolumeController:: Volume=96 Mute =false Oct 31 03:03:28 volumio volumio[754]: info: CoreStateMachine::pushState Oct 31 03:03:28 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::volumioPushState Oct 31 03:03:28 volumio volumio[754]: info: CoreStateMachine::updateTrackBlock Oct 31 03:03:28 volumio volumio[754]: info: CorePlayQueue::getTrackBlock Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::volumioRetrievevolume Oct 31 03:03:28 volumio volumio[754]: info: Asound.conf file unchanged, so no further update is needed Oct 31 03:03:28 volumio volumio[754]: info: Output device has changed, restarting MPD Oct 31 03:03:28 volumio volumio[754]: info: Output device has changed, restarting Shairport Sync Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 03:03:28 volumio sudo[1167]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/mpd.conf Oct 31 03:03:28 volumio sudo[1167]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:28 volumio dnsmasq[1171]: started, version 2.80 cachesize 150 Oct 31 03:03:28 volumio dnsmasq[1171]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 03:03:28 volumio dnsmasq[1171]: warning: interface wlan0 does not currently exist Oct 31 03:03:28 volumio dnsmasq-dhcp[1171]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 03:03:28 volumio dnsmasq[1171]: reading /etc/resolv.conf Oct 31 03:03:28 volumio dnsmasq[1171]: using nameserver 210.220.163.82#53 Oct 31 03:03:28 volumio dnsmasq[1171]: using nameserver 219.250.36.130#53 Oct 31 03:03:28 volumio dnsmasq[1171]: using nameserver 208.67.222.222#53 Oct 31 03:03:28 volumio dnsmasq[1171]: using nameserver 208.67.220.220#53 Oct 31 03:03:28 volumio dnsmasq[1171]: read /etc/hosts - 5 addresses Oct 31 03:03:28 volumio sudo[1167]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:28 volumio sudo[1168]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart mpd.service Oct 31 03:03:28 volumio sudo[1168]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:28 volumio volumio[754]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 03:03:28 volumio volumio[754]: info: ___________ START PLUGINS ___________ Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: mpd , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 03:03:28 volumio volumio[754]: info: [1730343808381] CoreMusicLibrary::Adding element Media Servers Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 03:03:28 volumio volumio[754]: Cannot find translation for sourceMedia Servers Oct 31 03:03:28 volumio systemd[1]: Stopping Music Player Daemon... Oct 31 03:03:28 volumio systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:28 volumio systemd[1]: mpd.service: Succeeded. Oct 31 03:03:28 volumio systemd[1]: Stopped Music Player Daemon. Oct 31 03:03:28 volumio systemd[1]: Starting Music Player Daemon... Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 03:03:28 volumio volumio[754]: info: Could not detect Primo: Error: Command failed: aplay -l | grep es90x8q2m-dac-dai-0 Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 03:03:28 volumio volumio[754]: info: [1730343808735] CoreMusicLibrary::Adding element Last_100 Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 03:03:28 volumio volumio[754]: Cannot find translation for sourceMedia Servers Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 03:03:28 volumio volumio[754]: info: [1730343808744] CoreMusicLibrary::Adding element Webradio Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 03:03:28 volumio volumio[754]: Cannot find translation for sourceMedia Servers Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion Oct 31 03:03:28 volumio volumio[754]: Starting albumart workers Oct 31 03:03:28 volumio volumio[754]: info: Creating Spotify config file Oct 31 03:03:28 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:28 volumio volumio[754]: Starting albumart workers Oct 31 03:03:28 volumio volumio[754]: info: Volumio Calling Home Oct 31 03:03:29 volumio volumio[754]: info: Completed starting Core Plugins Oct 31 03:03:29 volumio volumio[754]: info: ------------------------------------------- Oct 31 03:03:29 volumio volumio[754]: info: ----- MyVolumio plugins startup ---- Oct 31 03:03:29 volumio volumio[754]: info: ------------------------------------------- Oct 31 03:03:29 volumio volumio[754]: info: [MyVolumio PluginManager] Fetching plans data.... Oct 31 03:03:29 volumio volumio[754]: Starting albumart workers Oct 31 03:03:29 volumio volumio[754]: info: CoreStateMachine::setRepeat null single undefined Oct 31 03:03:29 volumio volumio[754]: info: CoreStateMachine::pushState Oct 31 03:03:29 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::volumioPushState Oct 31 03:03:29 volumio volumio[754]: info: CoreStateMachine::setRandom null Oct 31 03:03:29 volumio volumio[754]: info: CoreStateMachine::pushState Oct 31 03:03:29 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::volumioPushState Oct 31 03:03:29 volumio volumio[754]: error: updateQueue error: null Oct 31 03:03:29 volumio volumio[754]: info: mDNS: A device disapperared from network Oct 31 03:03:29 volumio volumio[754]: info: mDNS Browse raised the following error TypeError: Cannot read property 'toLowerCase' of undefined Oct 31 03:03:29 volumio volumio[754]: info: MPD Permissions set Oct 31 03:03:29 volumio volumio[754]: info: Discovery: adding c8b2c3da-4740-40ed-a510-6b4ce54d20ab Oct 31 03:03:29 volumio volumio[754]: info: mDNS: Found device Volumio Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::volumioGetState Oct 31 03:03:29 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:29 volumio volumio[754]: info: Spotify config file written Oct 31 03:03:29 volumio sudo[1196]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart go-librespot-daemon.service Oct 31 03:03:29 volumio sudo[1196]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:29 volumio volumio[754]: verbose: New Socket.io Connection to localhost:3000 from 127.0.0.1 UA: node-XMLHttpRequest Total Clients: 2 Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio systemd[1]: Started go-librespot Daemon. Oct 31 03:03:29 volumio sudo[1196]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:29 volumio go-librespot[1199]: Librespot-go daemon starting... Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: system , getCPUCoresNumber Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: alsa_controller , getConfigParam Oct 31 03:03:29 volumio volumio[754]: info: No need to fix Spotify hosts Oct 31 03:03:29 volumio volumio[754]: info: VolumeController:: Volume=96 Mute =false Oct 31 03:03:29 volumio volumio[754]: info: CoreStateMachine::pushState Oct 31 03:03:29 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::volumioPushState Oct 31 03:03:29 volumio volumio[754]: info: Volumio called home Oct 31 03:03:29 volumio volumio[754]: info: Discovery: this is already registered, c8b2c3da-4740-40ed-a510-6b4ce54d20ab Oct 31 03:03:29 volumio volumio[754]: info: mDNS: Found device Volumio Oct 31 03:03:29 volumio volumio[754]: info: CoreCommandRouter::volumioGetState Oct 31 03:03:29 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:29 volumio volumio[754]: info: Starting Shairport Sync Oct 31 03:03:29 volumio volumio[754]: info: Starting Shairport Sync Oct 31 03:03:29 volumio volumio[754]: info: Starting Shairport Sync Oct 31 03:03:29 volumio sudo[1224]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 03:03:29 volumio sudo[1224]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:29 volumio sudo[1226]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 03:03:29 volumio sudo[1230]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart shairport-sync Oct 31 03:03:29 volumio sudo[1226]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:29 volumio sudo[1230]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:30 volumio systemd[1]: Stopping Shairport Sync - AirPlay Audio Receiver... Oct 31 03:03:30 volumio systemd[1]: shairport-sync.service: Succeeded. Oct 31 03:03:30 volumio systemd[1]: Stopped Shairport Sync - AirPlay Audio Receiver. Oct 31 03:03:30 volumio systemd[1]: hostapd.service: Service RestartSec=2s expired, scheduling restart. Oct 31 03:03:30 volumio systemd[1]: hostapd.service: Scheduled restart job, restart counter is at 7. Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" level=info msg="generated new device id: 7b8fb5e91378c43e95d602bddb8a75c504279565" Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" level=debug msg="stored credentials found for 31db3h6yf2eetf7h3oythh24xpvm" Oct 31 03:03:30 volumio systemd[1]: Stopping dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:30 volumio systemd[1]: Started Shairport Sync - AirPlay Audio Receiver. Oct 31 03:03:30 volumio sudo[1224]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:30 volumio sudo[1226]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:30 volumio sudo[1230]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:30 volumio dnsmasq[1171]: exiting on receipt of SIGTERM Oct 31 03:03:30 volumio systemd[1]: dnsmasq.service: Succeeded. Oct 31 03:03:30 volumio systemd[1]: Stopped dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:30 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:30 volumio volumio[754]: info: Shairport-Sync Started Oct 31 03:03:30 volumio volumio[754]: Error adding Membership: Error: addMembership EINVAL Oct 31 03:03:30 volumio volumio[754]: info: Shairport-Sync Started Oct 31 03:03:30 volumio volumio[754]: info: Shairport-Sync Started Oct 31 03:03:30 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 03:03:30 volumio volumio[754]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 31 03:03:30 volumio volumio[754]: SPOTIFY: BQCaZ0H8ynVD4pyQuET8tpgOGJNRYe_dB0DYD1llPx_rxfADmE1J3HpHAbbmVRF6Unv-5yDt1CpO2i_dnkToRojPZzQMrqCDLJdz6jzoaoyHV8WsBVvmRjYIgUnJYhymCF9o2TpJkHgNriqemJnOCOW5qaKbbmHc6nowjs7KSCswMSYKNYElBL2zYRb9YNp5oVIEOj0iDKBxnweD719SL96iT18rp8TlIRApyNzdsa4282Ozk4GMzDapPfzjH4ldHfr_lpsE0jc6On11O-8 Oct 31 03:03:30 volumio volumio[754]: SPOTIFY: ------------------------------------------------------ ACCESS TOKEN ------------------------------------------------------ Oct 31 03:03:30 volumio volumio[754]: info: New Spotify access token = BQCaZ0H8ynVD4pyQuET8tpgOGJNRYe_dB0DYD1llPx_rxfADmE1J3HpHAbbmVRF6Unv-5yDt1CpO2i_dnkToRojPZzQMrqCDLJdz6jzoaoyHV8WsBVvmRjYIgUnJYhymCF9o2TpJkHgNriqemJnOCOW5qaKbbmHc6nowjs7KSCswMSYKNYElBL2zYRb9YNp5oVIEOj0iDKBxnweD719SL96iT18rp8TlIRApyNzdsa4282Ozk4GMzDapPfzjH4ldHfr_lpsE0jc6On11O-8 Oct 31 03:03:30 volumio volumio[754]: info: Spotify credentials grant success - running version from March 24, 2019 Oct 31 03:03:30 volumio hostapd[1251]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 03:03:30 volumio hostapd[1251]: Could not read interface wlan0 flags: No such device Oct 31 03:03:30 volumio hostapd[1251]: nl80211: Driver does not support authentication/association or connect commands Oct 31 03:03:30 volumio hostapd[1251]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 03:03:30 volumio volumio[754]: info: CoreCommandRouter::volumioGetState Oct 31 03:03:30 volumio volumio[754]: info: CorePlayQueue::getTrack 0 Oct 31 03:03:30 volumio hostapd[1251]: Could not read interface wlan0 flags: No such device Oct 31 03:03:30 volumio hostapd[1251]: nl80211 driver initialization failed. Oct 31 03:03:30 volumio hostapd[1251]: wlan0: interface state UNINITIALIZED->DISABLED Oct 31 03:03:30 volumio hostapd[1251]: wlan0: AP-DISABLED Oct 31 03:03:30 volumio hostapd[1251]: wlan0: CTRL-EVENT-TERMINATING Oct 31 03:03:30 volumio hostapd[1251]: hostapd_free_hapd_data: Interface wlan0 wasn't started Oct 31 03:03:30 volumio systemd[1]: hostapd.service: Control process exited, code=exited, status=1/FAILURE Oct 31 03:03:30 volumio systemd[1]: hostapd.service: Failed with result 'exit-code'. Oct 31 03:03:30 volumio systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:30 volumio systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:30 volumio dnsmasq[1258]: dnsmasq: syntax check OK. Oct 31 03:03:30 volumio dnsmasq[1265]: started, version 2.80 cachesize 150 Oct 31 03:03:30 volumio dnsmasq[1265]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 03:03:30 volumio dnsmasq[1265]: warning: interface wlan0 does not currently exist Oct 31 03:03:30 volumio dnsmasq-dhcp[1265]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 03:03:30 volumio dnsmasq[1265]: reading /etc/resolv.conf Oct 31 03:03:30 volumio dnsmasq[1265]: using nameserver 210.220.163.82#53 Oct 31 03:03:30 volumio dnsmasq[1265]: using nameserver 219.250.36.130#53 Oct 31 03:03:30 volumio dnsmasq[1265]: using nameserver 208.67.222.222#53 Oct 31 03:03:30 volumio dnsmasq[1265]: using nameserver 208.67.220.220#53 Oct 31 03:03:30 volumio dnsmasq[1265]: read /etc/hosts - 5 addresses Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" 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]" Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" 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]" Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" 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]" Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" level=debug msg="zeroconf server listening on port 33961" Oct 31 03:03:30 volumio volumio[754]: SPOTIFY: User informations: {"country":"KR","display_name":"고경웅","email":"1270536@gmail.com","explicit_content":{"filter_enabled":false,"filter_locked":false},"external_urls":{"spotify":"https://open.spotify.com/user/31db3h6yf2eetf7h3oythh24xpvm"},"followers":{"href":null,"total":0},"href":"https://api.spotify.com/v1/users/31db3h6yf2eetf7h3oythh24xpvm","id":"31db3h6yf2eetf7h3oythh24xpvm","images":[],"product":"premium","type":"user","uri":"spotify:user:31db3h6yf2eetf7h3oythh24xpvm"} Oct 31 03:03:30 volumio volumio[754]: info: Spotify Successfully logged in Oct 31 03:03:30 volumio volumio[754]: info: CoreCommandRouter::volumioAddToBrowseSources[object Object] Oct 31 03:03:30 volumio volumio[754]: info: [1730343810701] CoreMusicLibrary::Adding element Spotify Oct 31 03:03:30 volumio volumio[754]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources Oct 31 03:03:30 volumio volumio[754]: Cannot find translation for sourceMedia Servers Oct 31 03:03:30 volumio volumio[754]: Cannot find translation for sourceSpotify Oct 31 03:03:30 volumio systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" level=debug msg="obtained new client token: AABSPfcTwswu/gimUN0E3VAqTtAeGcF+YGmrtrNhmcmiBI33RpXxQCoayIPeD8zpHgw02O1WPi10UlEmmq49AFJyZxNsiiNqRfQlOI2JeJnoeWf2+y61GKn4cPs7CeLoSOknnNjFlhYDfyGgWdfbF6Avk0sGVvaQuv5drgW+urXIh1XU7bHn04cFmTVmRLZwvl65Ew6IKtiXro1fQ+MbWdHZC279bJmyz21Oz8wxv2gu2sXq+Y5jFaAyBi4nzEg=" Oct 31 03:03:30 volumio go-librespot[1199]: time="2024-10-31T03:03:30Z" level=info msg="connected to ap-gae2.spotify.com:4070" Oct 31 03:03:30 volumio mpd[1189]: Oct 31 03:03 : exception: Decoder plugin 'wildmidi' is unavailable: configuration file does not exist: /etc/timidity/timidity.cfg Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="completed keyexchange" Oct 31 03:03:31 volumio mpd[1189]: Oct 31 03:03 : exception: Input plugin 'tidal' is unavailable: No Tidal application token configured Oct 31 03:03:31 volumio mpd[1189]: Oct 31 03:03 : exception: Input plugin 'qobuz' is unavailable: No Qobuz app_id configured Oct 31 03:03:31 volumio systemd[1]: Started Music Player Daemon. Oct 31 03:03:31 volumio sudo[1168]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:31 volumio volumio[754]: error: updateQueue error: null Oct 31 03:03:31 volumio sudo[1274]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0 Oct 31 03:03:31 volumio sudo[1274]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:31 volumio sudo[1274]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:31 volumio sudo[1276]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 Oct 31 03:03:31 volumio sudo[1276]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:31 volumio sudo[1280]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service Oct 31 03:03:31 volumio sudo[1276]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:31 volumio sudo[1280]: pam_unix(sudo:session): session opened for user root by (uid=0) Oct 31 03:03:31 volumio systemd[1]: Started UPnP Renderer front-end to MPD. Oct 31 03:03:31 volumio sudo[1280]: pam_unix(sudo:session): session closed for user root Oct 31 03:03:31 volumio volumio[754]: info: Upmpdcli Daemon Started Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="completed challenge" Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="authenticated as 31db3h6yf2eetf7h3oythh24xpvm" Oct 31 03:03:31 volumio volumio[1284]: Generating RSA private key, 4096 bit long modulus (2 primes) Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="authenticated as 31db3h6yf2eetf7h3oythh24xpvm" Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="dealer connection opened" Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="initializing zeroconf session, username: 31db3h6yf2eetf7h3oythh24xpvm" Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="skipping packet PacketTypeSecretBlock, len: 336" Oct 31 03:03:31 volumio go-librespot[1199]: time="2024-10-31T03:03:31Z" level=debug msg="skipping packet PacketTypeLicenseVersion, len: 2" Oct 31 03:03:32 volumio go-librespot[1199]: time="2024-10-31T03:03:32Z" level=debug msg="skipping packet PacketTypeUnknown1f, len: 17" Oct 31 03:03:32 volumio go-librespot[1199]: time="2024-10-31T03:03:32Z" level=debug msg="skipping packet PacketTypeLegacyWelcome, len: 0" Oct 31 03:03:32 volumio go-librespot[1199]: time="2024-10-31T03:03:32Z" level=debug msg="autoplay enabled: false" Oct 31 03:03:32 volumio go-librespot[1199]: time="2024-10-31T03:03:32Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 505" Oct 31 03:03:32 volumio go-librespot[1199]: time="2024-10-31T03:03:32Z" level=debug msg="received connection id: ZWM1ZjA5OTYtMTM2ZC00ZjgzLWFkMWQtYTAwNWI4NDhlMmUwK2RlYWxlcit0Y3A6Ly8wYWM5NDg1YS5pcC5nYWUyLnNwb3RpZnkubmV0OjU3MDArQTJDRDc0QjA5RTkyMzI1QTZFNzdGNjU3RTg5RkYzOThDQTU3RDE3QTM4QkYyRkE0Nzg5OTE0RDQwMEVFQkZFMQ==" Oct 31 03:03:32 volumio volumio[1284]: .......++++ Oct 31 03:03:32 volumio systemd[1]: hostapd.service: Service RestartSec=2s expired, scheduling restart. Oct 31 03:03:32 volumio systemd[1]: hostapd.service: Scheduled restart job, restart counter is at 8. Oct 31 03:03:32 volumio systemd[1]: Stopping dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:32 volumio dnsmasq[1265]: exiting on receipt of SIGTERM Oct 31 03:03:32 volumio systemd[1]: dnsmasq.service: Succeeded. Oct 31 03:03:32 volumio systemd[1]: Stopped dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:32 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:32 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 03:03:32 volumio hostapd[1304]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 03:03:32 volumio hostapd[1304]: Could not read interface wlan0 flags: No such device Oct 31 03:03:32 volumio hostapd[1304]: nl80211: Driver does not support authentication/association or connect commands Oct 31 03:03:32 volumio hostapd[1304]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 03:03:32 volumio hostapd[1304]: Could not read interface wlan0 flags: No such device Oct 31 03:03:32 volumio hostapd[1304]: nl80211 driver initialization failed. Oct 31 03:03:32 volumio hostapd[1304]: wlan0: interface state UNINITIALIZED->DISABLED Oct 31 03:03:32 volumio hostapd[1304]: wlan0: AP-DISABLED Oct 31 03:03:32 volumio hostapd[1304]: wlan0: CTRL-EVENT-TERMINATING Oct 31 03:03:32 volumio hostapd[1304]: hostapd_free_hapd_data: Interface wlan0 wasn't started Oct 31 03:03:32 volumio systemd[1]: hostapd.service: Control process exited, code=exited, status=1/FAILURE Oct 31 03:03:32 volumio systemd[1]: hostapd.service: Failed with result 'exit-code'. Oct 31 03:03:32 volumio systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:32 volumio volumio[754]: info: go-librespot daemon successfully initialized Oct 31 03:03:32 volumio systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:32 volumio dnsmasq[1311]: dnsmasq: syntax check OK. Oct 31 03:03:32 volumio volumio[754]: error: updateQueue error: null Oct 31 03:03:32 volumio dnsmasq[1317]: started, version 2.80 cachesize 150 Oct 31 03:03:32 volumio dnsmasq[1317]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 03:03:32 volumio dnsmasq[1317]: warning: interface wlan0 does not currently exist Oct 31 03:03:32 volumio dnsmasq-dhcp[1317]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 03:03:32 volumio dnsmasq[1317]: reading /etc/resolv.conf Oct 31 03:03:32 volumio dnsmasq[1317]: using nameserver 210.220.163.82#53 Oct 31 03:03:32 volumio dnsmasq[1317]: using nameserver 219.250.36.130#53 Oct 31 03:03:32 volumio dnsmasq[1317]: using nameserver 208.67.222.222#53 Oct 31 03:03:32 volumio dnsmasq[1317]: using nameserver 208.67.220.220#53 Oct 31 03:03:32 volumio dnsmasq[1317]: read /etc/hosts - 5 addresses Oct 31 03:03:32 volumio systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="put connect state because NEW_DEVICE" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="handling transfer player command from efb89d497c58670e119ce84c11e0137c0304befc" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="resolved context of track" uri="spotify:playlist:3SOGiCbmWV0WingzbBQBwX" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=trace msg="fetched new page 0 with 25 items (list: 25)" uri="spotify:playlist:3SOGiCbmWV0WingzbBQBwX" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="loading track (paused: true, position: 99622ms)" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=trace msg="emitting websocket event: will_play" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 241" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="selected format OGG_VORBIS_320 (e5dfa3630e4dda36c7a81714f836c988933ed912)" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="requested aes key for file e5dfa3630e4dda36c7a81714f836c988933ed912, gid: 75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:33 volumio go-librespot[1199]: time="2024-10-31T03:03:33Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1394" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="skipping packet PacketTypeMercuryEvent, len: 1151" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched first chunk of 14, total size is 6906680 bytes" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched chunk 2/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched chunk 3/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched chunk 1/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched chunk 9/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=trace msg="seek to 99622ms (diff: 79ms, samples: 4393330, bytes: 4890708)" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="created new output device" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=info msg="loaded track \"Station\" (paused: true, position: 99622ms, duration: 148466ms, prefetched: false)" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=trace msg="emitting websocket event: metadata" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=trace msg="emitting websocket event: active" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="sending successful reply for dealer request" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched chunk 10/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="skipping dealer message" uri=social-connect/v2/broadcast_status_update Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="skipping dealer message" uri=social-connect/v2/session_update Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=trace msg="emitting websocket event: paused" Oct 31 03:03:34 volumio go-librespot[1199]: time="2024-10-31T03:03:34Z" level=debug msg="fetched chunk 12/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:34 volumio systemd[1]: hostapd.service: Service RestartSec=2s expired, scheduling restart. Oct 31 03:03:34 volumio systemd[1]: hostapd.service: Scheduled restart job, restart counter is at 9. Oct 31 03:03:34 volumio systemd[1]: Stopping dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:35 volumio go-librespot[1199]: time="2024-10-31T03:03:35Z" level=debug msg="fetched chunk 11/13, size: 524288" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:35 volumio dnsmasq[1317]: exiting on receipt of SIGTERM Oct 31 03:03:35 volumio systemd[1]: dnsmasq.service: Succeeded. Oct 31 03:03:35 volumio systemd[1]: Stopped dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:35 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:35 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 03:03:35 volumio hostapd[1329]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 03:03:35 volumio hostapd[1329]: Could not read interface wlan0 flags: No such device Oct 31 03:03:35 volumio hostapd[1329]: nl80211: Driver does not support authentication/association or connect commands Oct 31 03:03:35 volumio hostapd[1329]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 03:03:35 volumio hostapd[1329]: Could not read interface wlan0 flags: No such device Oct 31 03:03:35 volumio hostapd[1329]: nl80211 driver initialization failed. Oct 31 03:03:35 volumio hostapd[1329]: wlan0: interface state UNINITIALIZED->DISABLED Oct 31 03:03:35 volumio hostapd[1329]: wlan0: AP-DISABLED Oct 31 03:03:35 volumio hostapd[1329]: wlan0: CTRL-EVENT-TERMINATING Oct 31 03:03:35 volumio hostapd[1329]: hostapd_free_hapd_data: Interface wlan0 wasn't started Oct 31 03:03:35 volumio systemd[1]: hostapd.service: Control process exited, code=exited, status=1/FAILURE Oct 31 03:03:35 volumio systemd[1]: hostapd.service: Failed with result 'exit-code'. Oct 31 03:03:35 volumio systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:35 volumio systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:35 volumio dnsmasq[1336]: dnsmasq: syntax check OK. Oct 31 03:03:35 volumio dnsmasq[1342]: started, version 2.80 cachesize 150 Oct 31 03:03:35 volumio dnsmasq[1342]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 03:03:35 volumio dnsmasq[1342]: warning: interface wlan0 does not currently exist Oct 31 03:03:35 volumio dnsmasq-dhcp[1342]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 03:03:35 volumio dnsmasq[1342]: reading /etc/resolv.conf Oct 31 03:03:35 volumio dnsmasq[1342]: using nameserver 210.220.163.82#53 Oct 31 03:03:35 volumio dnsmasq[1342]: using nameserver 219.250.36.130#53 Oct 31 03:03:35 volumio dnsmasq[1342]: using nameserver 208.67.222.222#53 Oct 31 03:03:35 volumio dnsmasq[1342]: using nameserver 208.67.220.220#53 Oct 31 03:03:35 volumio dnsmasq[1342]: read /etc/hosts - 5 addresses Oct 31 03:03:35 volumio systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:35 volumio volumio[754]: info: Initializing connection to go-librespot Websocket Oct 31 03:03:35 volumio go-librespot[1199]: time="2024-10-31T03:03:35Z" level=debug msg="new websocket client" Oct 31 03:03:35 volumio volumio[754]: info: Connection to go-librespot Websocket established Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=debug msg="handling resume player command from efb89d497c58670e119ce84c11e0137c0304befc" Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=trace msg="seek to 99622ms (diff: 79ms, samples: 4393330, bytes: 4890708)" uri="spotify:track:75dtb9xsI7h0iDnh2GdNaX" Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=debug msg="alsa driver configured, rate = 44100 bps, period time = 5102 us, period size = 225 frames, buffer time = 500000 us, buffer size = 22050 frames, periods per buffer = 98 frames" Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=debug msg="resume track at 99543ms" Oct 31 03:03:37 volumio systemd[1]: hostapd.service: Service RestartSec=2s expired, scheduling restart. Oct 31 03:03:37 volumio systemd[1]: hostapd.service: Scheduled restart job, restart counter is at 10. Oct 31 03:03:37 volumio systemd[1]: Stopping dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=trace msg="scheduling prefetch in 19s" Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=debug msg="sending successful reply for dealer request" Oct 31 03:03:37 volumio dnsmasq[1342]: exiting on receipt of SIGTERM Oct 31 03:03:37 volumio systemd[1]: dnsmasq.service: Succeeded. Oct 31 03:03:37 volumio systemd[1]: Stopped dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:37 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:37 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator... Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=debug msg="put connect state because PLAYER_STATE_CHANGED" Oct 31 03:03:37 volumio go-librespot[1199]: time="2024-10-31T03:03:37Z" level=trace msg="emitting websocket event: playing" Oct 31 03:03:37 volumio volumio[754]: SPOTIFY: received: {"type":"playing","data":{"uri":"spotify:track:75dtb9xsI7h0iDnh2GdNaX","play_origin":"playlist"}} Oct 31 03:03:37 volumio volumio[754]: |||||||||||||||||||||||| WARNING: FATAL ERROR ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 03:03:37 volumio volumio[754]: TypeError: Cannot read property 'service' of undefined Oct 31 03:03:37 volumio volumio[754]: at ControllerSpotify.identifyPlaybackMode (/data/plugins/music_service/spop/index.js:337:50) Oct 31 03:03:37 volumio volumio[754]: at ControllerSpotify.parseEventState (/data/plugins/music_service/spop/index.js:263:18) Oct 31 03:03:37 volumio volumio[754]: at WebSocket.message (/data/plugins/music_service/spop/index.js:190:14) Oct 31 03:03:37 volumio volumio[754]: at WebSocket.emit (events.js:400:28) Oct 31 03:03:37 volumio volumio[754]: at Receiver.receiverOnMessage (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1220:20) Oct 31 03:03:37 volumio volumio[754]: at Receiver.emit (events.js:400:28) Oct 31 03:03:37 volumio volumio[754]: at Receiver.dataMessage (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:596:14) Oct 31 03:03:37 volumio volumio[754]: at Receiver.getData (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:496:10) Oct 31 03:03:37 volumio volumio[754]: at Receiver.startLoop (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:167:16) Oct 31 03:03:37 volumio volumio[754]: at Receiver._write (/data/plugins/music_service/spop/node_modules/ws/lib/receiver.js:94:10) Oct 31 03:03:37 volumio volumio[754]: at writeOrBuffer (internal/streams/writable.js:358:12) Oct 31 03:03:37 volumio volumio[754]: at Receiver.Writable.write (internal/streams/writable.js:303:10) Oct 31 03:03:37 volumio volumio[754]: at Socket.socketOnData (/data/plugins/music_service/spop/node_modules/ws/lib/websocket.js:1355:35) Oct 31 03:03:37 volumio volumio[754]: at Socket.emit (events.js:400:28) Oct 31 03:03:37 volumio volumio[754]: at addChunk (internal/streams/readable.js:293:12) Oct 31 03:03:37 volumio volumio[754]: at readableAddChunk (internal/streams/readable.js:267:9) Oct 31 03:03:37 volumio volumio[754]: ||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| Oct 31 03:03:37 volumio hostapd[1352]: Configuration file: /etc/hostapd/hostapd.conf Oct 31 03:03:37 volumio hostapd[1352]: Could not read interface wlan0 flags: No such device Oct 31 03:03:37 volumio hostapd[1352]: nl80211: Driver does not support authentication/association or connect commands Oct 31 03:03:37 volumio hostapd[1352]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0 Oct 31 03:03:37 volumio hostapd[1352]: Could not read interface wlan0 flags: No such device Oct 31 03:03:37 volumio hostapd[1352]: nl80211 driver initialization failed. Oct 31 03:03:37 volumio hostapd[1352]: wlan0: interface state UNINITIALIZED->DISABLED Oct 31 03:03:37 volumio hostapd[1352]: wlan0: AP-DISABLED Oct 31 03:03:37 volumio hostapd[1352]: wlan0: CTRL-EVENT-TERMINATING Oct 31 03:03:37 volumio hostapd[1352]: hostapd_free_hapd_data: Interface wlan0 wasn't started Oct 31 03:03:37 volumio systemd[1]: hostapd.service: Control process exited, code=exited, status=1/FAILURE Oct 31 03:03:37 volumio systemd[1]: hostapd.service: Failed with result 'exit-code'. Oct 31 03:03:37 volumio systemd[1]: Failed to start Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator. Oct 31 03:03:37 volumio systemd[1]: Starting dnsmasq - A lightweight DHCP and caching DNS server... Oct 31 03:03:37 volumio dnsmasq[1366]: dnsmasq: syntax check OK. Oct 31 03:03:37 volumio dnsmasq[1373]: started, version 2.80 cachesize 150 Oct 31 03:03:37 volumio dnsmasq[1373]: compile time options: IPv6 GNU-getopt DBus i18n IDN DHCP DHCPv6 no-Lua TFTP conntrack ipset auth DNSSEC loop-detect inotify dumpfile Oct 31 03:03:37 volumio dnsmasq[1373]: warning: interface wlan0 does not currently exist Oct 31 03:03:37 volumio dnsmasq-dhcp[1373]: DHCP, IP range 192.168.211.100 -- 192.168.211.200, lease time 1d Oct 31 03:03:37 volumio dnsmasq[1373]: reading /etc/resolv.conf Oct 31 03:03:37 volumio dnsmasq[1373]: using nameserver 210.220.163.82#53 Oct 31 03:03:37 volumio dnsmasq[1373]: using nameserver 219.250.36.130#53 Oct 31 03:03:37 volumio dnsmasq[1373]: using nameserver 208.67.222.222#53 Oct 31 03:03:37 volumio dnsmasq[1373]: using nameserver 208.67.220.220#53 Oct 31 03:03:37 volumio dnsmasq[1373]: read /etc/hosts - 5 addresses Oct 31 03:03:37 volumio systemd[1]: Started dnsmasq - A lightweight DHCP and caching DNS server. Oct 31 03:03:38 volumio sudo[1380]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2024-10-31 03:02 Oct 31 03:03:38 volumio sudo[1380]: pam_unix(sudo:session): session opened for user root by (uid=0) PRETTY_NAME="Debian GNU/Linux 10 (buster)" NAME="Debian GNU/Linux" VERSION_ID="10" VERSION="10 (buster)" VERSION_CODENAME=buster ID=debian HOME_URL="https://www.debian.org/" SUPPORT_URL="https://www.debian.org/support" BUG_REPORT_URL="https://bugs.debian.org/" VOLUMIO_BUILD_VERSION="613d705c083fd29de3027cf6e63a923a6020da8e" VOLUMIO_FE_VERSION="575f38b17bfc836dbd47f560a440d36ecd98d5af" VOLUMIO_FE3_VERSION="af818e7eb038d49989134ddd7bf2b2ffaa8cf083" VOLUMIO_BE_VERSION="5936439c04ed803864b9ef314729c659b841752e" VOLUMIO_ARCH="armv7" VOLUMIO_VARIANT="volumio" VOLUMIO_TEST="FALSE" VOLUMIO_BUILD_DATE="Fri 28 Jan 2022 11:25:52 PM CET" VOLUMIO_VERSION="3.212" VOLUMIO_HARDWARE="pine64plus" VOLUMIO_DEVICENAME="Pine64+" VOLUMIO_HASH="5e57f9318a5cef553cc02a37eb89e34c"