-- Logs begin at Fri 2025-12-05 16:57:36 EET, end at Tue 2025-12-09 15:54:37 EET. --
Dec 09 15:53:07 volumio go-librespot[5034]: time="2025-12-09T15:53:07+02:00" level=trace msg="sent dealer ping"
Dec 09 15:53:07 volumio go-librespot[5034]: time="2025-12-09T15:53:07+02:00" level=trace msg="received dealer pong"
Dec 09 15:53:13 volumio volumio[4833]: info: CALLMETHOD: system_controller network saveHotspotSettings [object Object]
Dec 09 15:53:13 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , saveHotspotSettings
Dec 09 15:53:14 volumio sudo[5596]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/chmod 777 /etc/hostapd/hostapd.conf
Dec 09 15:53:14 volumio sudo[5596]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:14 volumio sudo[5596]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:14 volumio volumio[4833]: info: Permissions for /etc/hostapd/hostapd.conf
Dec 09 15:53:14 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , onNetworkingRestart
Dec 09 15:53:14 volumio volumio[4833]: info: Discovery: Restarting Advertising due to device name change
Dec 09 15:53:14 volumio sudo[5599]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl restart wireless.service
Dec 09 15:53:14 volumio sudo[5599]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:14 volumio systemd[1]: Starting Wireless Services...
Dec 09 15:53:15 volumio volumio[4833]: info: Discovery: A device disappeared from network
Dec 09 15:53:15 volumio volumio[4833]: info: Discovery: Device volumio disappeared from network
Dec 09 15:53:15 volumio volumio[4833]: info: Discovery: A device disappeared from network
Dec 09 15:53:15 volumio wireless.js[5601]: Cleaning previous...
Dec 09 15:53:15 volumio systemd[1]: Stopping Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator...
Dec 09 15:53:16 volumio kernel: ieee80211 phy0: brcmf_cfg80211_reg_notifier: Firmware rejected country setting
Dec 09 15:53:16 volumio systemd[1]: hostapd.service: Succeeded.
Dec 09 15:53:16 volumio systemd[1]: Stopped Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator.
Dec 09 15:53:16 volumio sudo[5617]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0
Dec 09 15:53:16 volumio sudo[5617]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:16 volumio avahi-daemon[570]: Withdrawing address record for 192.168.211.1 on wlan0.
Dec 09 15:53:16 volumio avahi-daemon[570]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1.
Dec 09 15:53:16 volumio avahi-daemon[570]: Interface wlan0.IPv4 no longer relevant for mDNS.
Dec 09 15:53:16 volumio sudo[5617]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:16 volumio sudo[5619]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down
Dec 09 15:53:16 volumio sudo[5619]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:16 volumio sudo[5619]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:16 volumio wireless.js[5601]: Stopped aP
Dec 09 15:53:16 volumio sudo[5627]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up
Dec 09 15:53:16 volumio sudo[5627]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:16 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
Dec 09 15:53:16 volumio sudo[5627]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:16 volumio sudo[5629]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg get
Dec 09 15:53:16 volumio sudo[5629]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:17 volumio sudo[5629]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:17 volumio sudo[5636]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up
Dec 09 15:53:17 volumio sudo[5636]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:17 volumio sudo[5636]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:17 volumio sudo[5638]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw wlan0 scan
Dec 09 15:53:17 volumio sudo[5638]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:18 volumio ntpd[727]: Deleting interface #4 wlan0, 192.168.211.1#123, interface stats: received=0, sent=0, dropped=0, active_time=1162 secs
Dec 09 15:53:19 volumio volumio[4833]: info: Discovery: Started advertising with name: Volumio
Dec 09 15:53:19 volumio sudo[5638]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:19 volumio wireless.js[5601]: SETTING APPROPRIATE REG DOMAIN: US
Dec 09 15:53:19 volumio sudo[5658]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 up
Dec 09 15:53:19 volumio sudo[5658]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:19 volumio sudo[5658]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:20 volumio sudo[5660]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iw reg set US
Dec 09 15:53:20 volumio sudo[5660]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:20 volumio sudo[5660]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:20 volumio wireless.js[5601]: SUCCESSFULLY SET NEW REGDOMAIN: US
Dec 09 15:53:20 volumio sudo[5667]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ip addr flush dev wlan0
Dec 09 15:53:20 volumio sudo[5667]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:20 volumio sudo[5667]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:20 volumio volumio[4833]: info: Discovery: adding 63583262-5657-4448-890c-7eeda49ca4d2
Dec 09 15:53:20 volumio volumio[4833]: info: Discovery: Found device Volumio
Dec 09 15:53:20 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:20 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:20 volumio sudo[5670]: root : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0 down
Dec 09 15:53:20 volumio sudo[5670]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:20 volumio sudo[5670]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:20 volumio avahi-daemon[570]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.211.1.
Dec 09 15:53:20 volumio avahi-daemon[570]: New relevant interface wlan0.IPv4 for mDNS.
Dec 09 15:53:20 volumio avahi-daemon[570]: Registering new address record for 192.168.211.1 on wlan0.IPv4.
Dec 09 15:53:20 volumio kernel: brcmfmac: brcmf_cfg80211_set_power_mgmt: power save disabled
Dec 09 15:53:20 volumio systemd[1]: Starting Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator...
Dec 09 15:53:20 volumio hostapd[5677]: Configuration file: /etc/hostapd/hostapd.conf
Dec 09 15:53:20 volumio hostapd[5677]: wlan0: Could not connect to kernel driver
Dec 09 15:53:20 volumio hostapd[5677]: Using interface wlan0 with hwaddr b8:27:eb:6f:be:14 and ssid "Volumio-A73E8"
Dec 09 15:53:21 volumio hostapd[5677]: wlan0: interface state UNINITIALIZED->ENABLED
Dec 09 15:53:21 volumio hostapd[5677]: wlan0: AP-ENABLED
Dec 09 15:53:21 volumio systemd[1]: Started Advanced IEEE 802.11 AP and IEEE 802.1X/WPA/WPA2/EAP Authenticator.
Dec 09 15:53:21 volumio iwconfig[5680]: Error for wireless request "Set Power Management" (8B2C) :
Dec 09 15:53:21 volumio iwconfig[5680]: SET failed on device wlan0 ; Invalid argument.
Dec 09 15:53:21 volumio systemd[1]: wireless.service: Succeeded.
Dec 09 15:53:21 volumio systemd[1]: Started Wireless Services.
Dec 09 15:53:21 volumio sudo[5599]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:21 volumio volumio[4833]: info: Discovery: this is already registered, 63583262-5657-4448-890c-7eeda49ca4d2
Dec 09 15:53:21 volumio volumio[4833]: info: Discovery: Found device Volumio
Dec 09 15:53:21 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:21 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:22 volumio ntpd[727]: Listen normally on 5 wlan0 192.168.211.1:123
Dec 09 15:53:22 volumio ntpd[727]: new interface(s) found: waking up resolver
Dec 09 15:53:25 volumio ntpd[727]: 212.1.104.9 local addr 192.168.2.236 ->
Dec 09 15:53:26 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: wizard , reportWirelessConnection
Dec 09 15:53:26 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessInfo
Dec 09 15:53:26 volumio sudo[5686]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 15:53:26 volumio sudo[5686]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:26 volumio sudo[5686]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: upnp , onRestart
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , onNetworkingRestart
Dec 09 15:53:31 volumio volumio[4833]: info: Refreshing Cached IP Addresses
Dec 09 15:53:31 volumio sudo[5703]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/usr/bin/killall upmpdcli
Dec 09 15:53:31 volumio sudo[5703]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:31 volumio sudo[5703]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:31 volumio systemd[1]: upmpdcli.service: Succeeded.
Dec 09 15:53:31 volumio sudo[5706]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 15:53:31 volumio sudo[5706]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:31 volumio sudo[5706]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:31 volumio sudo[5709]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 15:53:31 volumio sudo[5709]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:31 volumio sudo[5709]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:31 volumio sudo[5713]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 15:53:31 volumio sudo[5713]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:31 volumio sudo[5713]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:31 volumio sudo[5716]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 15:53:31 volumio sudo[5716]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:31 volumio sudo[5716]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:31 volumio volumio[4833]: verbose: New Socket.io Connection to 192.168.2.236 from 192.168.2.122 UA: Mozilla/5.0 (X11; Linux x86_64; rv:140.0) Gecko/20100101 Firefox/140.0 Engine version: 3 Transport: polling Total Clients: 6
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getAutoUpdateCheckEnabled
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::volumioGetVisibleSources
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: my_music , getDisabledSources
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:31 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: metavolumio , getInfinityPlayback
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::getUIConfigOnPlugin
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: multiroom , getMultiroom
Dec 09 15:53:31 volumio volumio[4833]: info: Received Get System Info
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 09 15:53:31 volumio volumio[4833]: info: Discovery: Getting this device information
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:31 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 09 15:53:31 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:31 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:32 volumio volumio[4833]: info: Listing playlists
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: appearance , getUiSettings
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 09 15:53:32 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:32 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:32 volumio volumio[4833]: info: Prefetching next song
Dec 09 15:53:32 volumio volumio[4833]: info: [1765288412050] ControllerSpotify::prefetch
Dec 09 15:53:32 volumio volumio[4833]: info: Sending Spotify command with payload to local API: /player/add_to_queue
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getAdvancedSettingsStatus
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: updater_comm , getUpdateMessageCache
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getInfoNetwork
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=debug msg="prefetching next track" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=warning msg="original track has no formats, alternatives have a total of 4" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=debug msg="selected format OGG_VORBIS_320 (972fee72bdbb820dbb5f36b0f23441b4b1547fa6)" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=debug msg="requested aes key for file 972fee72bdbb820dbb5f36b0f23441b4b1547fa6, gid: 0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio sudo[5721]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ethtool eth0
Dec 09 15:53:32 volumio sudo[5721]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio sudo[5721]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:32 volumio sudo[5727]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
Dec 09 15:53:32 volumio sudo[5727]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio sudo[5727]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio sudo[5735]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
Dec 09 15:53:32 volumio sudo[5735]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio sudo[5735]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:32 volumio sudo[5741]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwconfig wlan0
Dec 09 15:53:32 volumio sudo[5741]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio sudo[5741]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:32 volumio sudo[5747]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 15:53:32 volumio sudo[5747]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio sudo[5747]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworksScanCache
Dec 09 15:53:32 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getWirelessNetworks
Dec 09 15:53:32 volumio sudo[5750]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 15:53:32 volumio sudo[5750]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio sudo[5750]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=debug msg="fetched first chunk of 16, total size is 8354363 bytes" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio sudo[5753]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/iwlist wlan0 scan
Dec 09 15:53:32 volumio sudo[5753]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=info msg="prefetched track \"Supergirl\" (duration: 197189ms)" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:32 volumio go-librespot[5034]: time="2025-12-09T15:53:32+02:00" level=debug msg="fetched chunk 1/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:33 volumio go-librespot[5034]: time="2025-12-09T15:53:33+02:00" level=debug msg="fetched chunk 3/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:33 volumio go-librespot[5034]: time="2025-12-09T15:53:33+02:00" level=debug msg="fetched chunk 2/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:33 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: wizard , getOnboardingWizard
Dec 09 15:53:33 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Dec 09 15:53:33 volumio volumio[4833]: info: Received Get System Info
Dec 09 15:53:33 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 09 15:53:33 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 09 15:53:33 volumio volumio[4833]: info: Discovery: Getting this device information
Dec 09 15:53:33 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:33 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:33 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 09 15:53:34 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: my_volumio , getMyVolumioStatus
Dec 09 15:53:34 volumio volumio[4833]: info: Received Get System Info
Dec 09 15:53:34 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 09 15:53:34 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 09 15:53:34 volumio volumio[4833]: info: Discovery: Getting this device information
Dec 09 15:53:34 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:34 volumio volumio[4833]: info: CorePlayQueue::getTrack 2
Dec 09 15:53:34 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=trace msg="emitting websocket event: not_playing"
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: received: {"type":"not_playing","data":{"context_uri":"spotify:track:3v6kacXzl2N3nNG5LVBxwG","uri":"spotify:track:3v6kacXzl2N3nNG5LVBxwG","play_origin":"go-librespot"}}
Dec 09 15:53:36 volumio volumio[4833]: error: Failed to decode event: not_playing
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=trace msg="emitting websocket event: will_play"
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=info msg="loaded track \"Supergirl\" (paused: false, position: 0ms, duration: 197189ms, prefetched: true)" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: received: {"type":"will_play","data":{"context_uri":"spotify:track:3v6kacXzl2N3nNG5LVBxwG","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","play_origin":"go-librespot"}}
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::startPlaybackTimer
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=trace msg="scheduling prefetch in 167s"
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=trace msg="emitting websocket event: metadata"
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: received: {"type":"metadata","data":{"uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","name":"Supergirl","artist_names":["Dream Chaos","Della"],"album_name":"Supergirl","album_cover_url":"https://i.scdn.co/image/ab67616d00001e02aee6794052cef589cf7cee92","position":0,"duration":197189,"release_date":"year:2023 month:1 day:4","track_number":1,"disc_number":1}}
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:53:36 volumio go-librespot[5034]: time="2025-12-09T15:53:36+02:00" level=trace msg="emitting websocket event: playing"
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: received: {"type":"playing","data":{"context_uri":"spotify:track:3v6kacXzl2N3nNG5LVBxwG","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","resume":false,"play_origin":"go-librespot"}}
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: PUSH STATE SPOTIFY
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: {"status":"play","service":"spop","title":"Supergirl","artist":"Dream Chaos, Della","album":"Supergirl","albumart":"https://i.scdn.co/image/ab67616d00001e02aee6794052cef589cf7cee92","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","trackType":"spotify","seek":0,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::servicePushState
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Supergirl","artist":"Dream Chaos, Della","album":"Supergirl","albumart":"https://i.scdn.co/image/ab67616d00001e02aee6794052cef589cf7cee92","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","trackType":"spotify","seek":0,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Dec 09 15:53:36 volumio volumio[4833]: verbose: CURRENT POSITION 3
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::syncState stateService play
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::syncState currentStatus play
Dec 09 15:53:36 volumio volumio[4833]: info: Received an update from plugin. extracting info from payload
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::pushState
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::volumioPushState
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::pushState
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::volumioPushState
Dec 09 15:53:36 volumio volumio[4833]: info: [ASDebug] CurState: play PrevState: play
Dec 09 15:53:36 volumio volumio[4833]: info: [ASDebug] CurState: play PrevState: play
Dec 09 15:53:36 volumio sudo[5753]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: PUSH STATE SPOTIFY
Dec 09 15:53:36 volumio volumio[4833]: SPOTIFY: {"status":"play","service":"spop","title":"Supergirl","artist":"Dream Chaos, Della","album":"Supergirl","albumart":"https://i.scdn.co/image/ab67616d00001e02aee6794052cef589cf7cee92","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","trackType":"spotify","seek":1000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::servicePushState
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: verbose: STATE SERVICE {"status":"play","service":"spop","title":"Supergirl","artist":"Dream Chaos, Della","album":"Supergirl","albumart":"https://i.scdn.co/image/ab67616d00001e02aee6794052cef589cf7cee92","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","trackType":"spotify","seek":1000,"duration":197,"samplerate":"44.1 KHz","bitdepth":"16 bit","bitrate":"320 kbps","codec":"ogg","channels":2,"random":null,"repeat":null,"repeatSingle":null}
Dec 09 15:53:36 volumio volumio[4833]: verbose: CURRENT POSITION 3
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::syncState stateService play
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::syncState currentStatus play
Dec 09 15:53:36 volumio volumio[4833]: info: Received an update from plugin. extracting info from payload
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::pushState
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::volumioPushState
Dec 09 15:53:36 volumio volumio[4833]: info: CoreStateMachine::pushState
Dec 09 15:53:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:36 volumio volumio[4833]: info: CoreCommandRouter::volumioPushState
Dec 09 15:53:37 volumio volumio[4833]: info: [ASDebug] CurState: play PrevState: play
Dec 09 15:53:37 volumio volumio[4833]: info: [ASDebug] CurState: play PrevState: play
Dec 09 15:53:37 volumio volumio[4833]: info: CoreStateMachine::pushState
Dec 09 15:53:37 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:37 volumio volumio[4833]: info: CoreCommandRouter::volumioPushState
Dec 09 15:53:37 volumio volumio[4833]: info: [ASDebug] CurState: play PrevState: play
Dec 09 15:53:37 volumio go-librespot[5034]: time="2025-12-09T15:53:37+02:00" level=trace msg="sent dealer ping"
Dec 09 15:53:37 volumio go-librespot[5034]: time="2025-12-09T15:53:37+02:00" level=trace msg="received dealer pong"
Dec 09 15:53:41 volumio sudo[5771]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig eth0
Dec 09 15:53:41 volumio sudo[5771]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:41 volumio sudo[5771]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:41 volumio sudo[5774]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/sbin/ifconfig wlan0
Dec 09 15:53:41 volumio sudo[5774]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:41 volumio sudo[5774]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:41 volumio sudo[5777]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/systemctl start upmpdcli.service
Dec 09 15:53:41 volumio sudo[5777]: pam_unix(sudo:session): session opened for user root by (uid=0)
Dec 09 15:53:41 volumio systemd[1]: Started UPnP Renderer front-end to MPD.
Dec 09 15:53:41 volumio sudo[5777]: pam_unix(sudo:session): session closed for user root
Dec 09 15:53:41 volumio volumio[4833]: info: Upmpdcli Daemon Started
Dec 09 15:53:41 volumio volumio[5779]: writing RSA key
Dec 09 15:53:42 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: appearance , isLatestTOSAccepted
Dec 09 15:53:47 volumio go-librespot[5034]: time="2025-12-09T15:53:47+02:00" level=debug msg="fetched chunk 4/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:53:51 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getPrivacySettings
Dec 09 15:53:52 volumio volumio[4833]: info: CALLMETHOD: system_controller my_volumio retreiveBackendEventStates undefined
Dec 09 15:53:52 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: my_volumio , retreiveBackendEventStates
Dec 09 15:53:52 volumio volumio[4833]: info: Received Get System Version
Dec 09 15:53:52 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getSystemVersion
Dec 09 15:53:52 volumio volumio[4833]: info: Received Get System Info
Dec 09 15:53:52 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: system , getSystemInfo
Dec 09 15:53:52 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , getThisDevice
Dec 09 15:53:52 volumio volumio[4833]: info: Discovery: Getting this device information
Dec 09 15:53:52 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:53:52 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:53:52 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: network , getCachedIPAddresses
Dec 09 15:53:59 volumio go-librespot[5034]: time="2025-12-09T15:53:59+02:00" level=debug msg="fetched chunk 5/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:54:07 volumio go-librespot[5034]: time="2025-12-09T15:54:07+02:00" level=trace msg="sent dealer ping"
Dec 09 15:54:07 volumio go-librespot[5034]: time="2025-12-09T15:54:07+02:00" level=trace msg="received dealer pong"
Dec 09 15:54:07 volumio ntpd[727]: 91.236.251.234 local addr 192.168.2.236 ->
Dec 09 15:54:11 volumio go-librespot[5034]: time="2025-12-09T15:54:11+02:00" level=debug msg="fetched chunk 6/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:54:24 volumio go-librespot[5034]: time="2025-12-09T15:54:24+02:00" level=debug msg="fetched chunk 7/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:54:33 volumio volumio[4833]: info: CoreCommandRouter::volumioGetState
Dec 09 15:54:33 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=debug msg="fetched chunk 8/15, size: 524288" uri="spotify:track:0lI2P9LXHly1ZszJYc7dsf"
Dec 09 15:54:36 volumio volumio[4833]: info: CoreCommandRouter::volumioNext
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::next
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::stop
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::setConsumeUpdateService undefined
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::stPlaybackTimer
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::updateTrackBlock
Dec 09 15:54:36 volumio volumio[4833]: info: CorePlayQueue::getTrackBlock
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::pushState
Dec 09 15:54:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:54:36 volumio volumio[4833]: info: CoreCommandRouter::executeOnPlugin: volumiodiscovery , saveDeviceInfo
Dec 09 15:54:36 volumio volumio[4833]: info: CoreCommandRouter::volumioPushState
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::serviceStop
Dec 09 15:54:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 3
Dec 09 15:54:36 volumio volumio[4833]: info: CoreCommandRouter::serviceStop
Dec 09 15:54:36 volumio volumio[4833]: info: Spotify Stop
Dec 09 15:54:36 volumio volumio[4833]: SPOTIFY: SPOTIFY STOP
Dec 09 15:54:36 volumio volumio[4833]: SPOTIFY: {"status":"play","position":3,"title":"Supergirl","artist":"Dream Chaos","album":"Supergirl","albumart":"https://i.scdn.co/image/ab67616d0000b273aee6794052cef589cf7cee92","uri":"spotify:track:0lI2P9LXHly1ZszJYc7dsf","trackType":"spotify","codec":"ogg","seek":1000,"duration":197,"samplerate":"320 kbps","bitdepth":"16 bit","channels":2,"random":null,"repeat":null,"repeatSingle":false,"consume":false,"volume":0,"dbVolume":null,"disableVolumeControl":false,"mute":false,"stream":"spotify","volatile":false,"service":"spop"}
Dec 09 15:54:36 volumio volumio[4833]: info: Sending Spotify command to local API: /player/pause
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::play index undefined
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::setConsumeUpdateService undefined
Dec 09 15:54:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 4
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::startPlaybackTimer
Dec 09 15:54:36 volumio volumio[4833]: info: CorePlayQueue::getTrack 4
Dec 09 15:54:36 volumio volumio[4833]: info: [1765288476453] ControllerSpotify::clearAddPlayTrack
Dec 09 15:54:36 volumio volumio[4833]: info: Sending Spotify command with payload to local API: /player/play
Dec 09 15:54:36 volumio volumio[4833]: info: CoreStateMachine::updateTrackBlock
Dec 09 15:54:36 volumio volumio[4833]: info: CorePlayQueue::getTrackBlock
Dec 09 15:54:36 volumio volumio[4833]: info: [ASDebug] CurState: stop PrevState: play
Dec 09 15:54:36 volumio volumio[4833]: info: [ASDebug] InitTimeout - Amp off in: 30 ms
Dec 09 15:54:36 volumio volumio[4833]: info: [ASDebug] Togle GPIO: OFF
Dec 09 15:54:36 volumio volumio[4833]: |||||||||||||||||||||||| WARNING: FATAL ERROR |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 15:54:36 volumio volumio[4833]: Error: ESPIPE: invalid seek, write
Dec 09 15:54:36 volumio volumio[4833]: at Object.writeSync (fs.js:711:3)
Dec 09 15:54:36 volumio volumio[4833]: at Gpio.writeSync (/data/plugins/system_controller/ampswitch/node_modules/onoff/onoff.js:243:8)
Dec 09 15:54:36 volumio volumio[4833]: at AmpSwitchController.off (/data/plugins/system_controller/ampswitch/index.js:221:23)
Dec 09 15:54:36 volumio volumio[4833]: at Timeout._onTimeout (/data/plugins/system_controller/ampswitch/index.js:195:88)
Dec 09 15:54:36 volumio volumio[4833]: at listOnTimeout (internal/timers.js:554:17)
Dec 09 15:54:36 volumio volumio[4833]: at processTimers (internal/timers.js:497:7) {
Dec 09 15:54:36 volumio volumio[4833]: errno: -29,
Dec 09 15:54:36 volumio volumio[4833]: syscall: 'write',
Dec 09 15:54:36 volumio volumio[4833]: code: 'ESPIPE'
Dec 09 15:54:36 volumio volumio[4833]: }
Dec 09 15:54:36 volumio volumio[4833]: |||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=debug msg="resolved context of track" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=trace msg="fetched new page 0 with 1 items (list: 1)" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=debug msg="loading track (paused: false, position: 0ms)" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=trace msg="emitting websocket event: will_play"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=debug msg="selected format OGG_VORBIS_320 (0f4c56bb070188e756686fbf5c4efce2fafa862b)" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=debug msg="requested aes key for file 0f4c56bb070188e756686fbf5c4efce2fafa862b, gid: 3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:36 volumio go-librespot[5034]: time="2025-12-09T15:54:36+02:00" level=trace msg="found 2 cdn urls" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="fetched first chunk of 18, total size is 9087348 bytes" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=info msg="loaded track \"Show Me\" (paused: false, position: 0ms, duration: 208760ms, prefetched: false)" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="scheduling prefetch in 179s"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="emitting websocket event: metadata"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="emitting websocket event: playing"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="pause track at 98ms"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="received accesspoint ping"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="fetched chunk 3/17, size: 524288" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="fetched chunk 2/17, size: 524288" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="received accesspoint pong ack"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="put connect state because PLAYER_STATE_CHANGED"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="emitting websocket event: paused"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=debug msg="fetched chunk 1/17, size: 524288" uri="spotify:track:3S39WrSibxAEW7TRDFneg0"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="sent dealer ping"
Dec 09 15:54:37 volumio go-librespot[5034]: time="2025-12-09T15:54:37+02:00" level=trace msg="received dealer pong"
Dec 09 15:54:37 volumio sudo[5937]: volumio : TTY=unknown ; PWD=/ ; USER=root ; COMMAND=/bin/journalctl --since=2025-12-09 15:53
Dec 09 15:54:37 volumio sudo[5937]: 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="cc50ad4a2058d01de272214eb33827883bd2b7d8"
VOLUMIO_FE_VERSION="35f8f4439f0076a62fefa72fd80b70701b3d6cbd"
VOLUMIO_FE3_VERSION="bcca17b6b6b26edfb999e6fd7da1b222a88a61d2"
VOLUMIO_BE_VERSION="502750e5d54ecf269d25125b622bfabc030fb553"
VOLUMIO_ARCH="arm"
VOLUMIO_VARIANT="volumio"
VOLUMIO_TEST="FALSE"
VOLUMIO_BUILD_DATE="Wed 12 Nov 2025 06:58:02 PM CET"
VOLUMIO_VERSION="3.874"
VOLUMIO_HARDWARE="pi"
VOLUMIO_DEVICENAME="Raspberry Pi"
VOLUMIO_HASH="4ae6504ed6f22e44c01a6e93b16badbd"